Profiling terminal startup time

Source code for this document

It takes a noticeable amount of time to open a new terminal on my Mac, so I wanted to get to the bottom of it and fix the slowness.

The first step is to find out what’s slow. I adapted code from this answer on StackOverflow, and put this in my ~/.profile file, which is run each time I open a new terminal. The ~/.profile also sources ~/.bashrc.

Note: on Linux, the terminal startup behavior is a little different. ~/.profile is typically run only on login, and each new terminal only runs ~/.bashrc. It’s therefore possible to put expensive commands in ~/.profile and not pay the penalty every time you open a terminal.

I put this at the top of my ~/.profile:

PS4='.\011$(gdate "+%s.%N")\011'
exec 3>&2 2>~/bashstart.$$.log
set -x

And this at the bottom:

set +x
exec 2>&3 3>&-

This saves a startup profile to a file named ~/bashstart.XXXXX.log.

Some notes about this:

• The Mac’s included date command doesn’t have the necessary time resolution, so I needed to use the GNU version, which can be installed with brew install coreutils. When installed this way, it’s named gdate.
• It runs date for each line that is executed in the bash startup, and this can add up to a fair amount of time.
• Because each line of scripts runs date, if your .profile has many lines or if it sources a long script (like rvm), it pays a big overall penalty for running date many times, even if the script by itself would not take much time.

Analyzing startup time

library(dplyr)
#> 
#> Attaching package: 'dplyr'
#> The following objects are masked from 'package:stats':
#> 
#>     filter, lag
#> The following objects are masked from 'package:base':
#> 
#>     intersect, setdiff, setequal, union
library(readr)

# Load into data frame
dat <- read_tsv(
  "bashstart.41676.log",
  col_names = c("depth", "time", "cmd")
)
#> Parsed with column specification:
#> cols(
#>   depth = col_character(),
#>   time = col_double(),
#>   cmd = col_character()
#> )

dat <- dat %>%
  mutate(
    depth = nchar(depth),
    difftime = lead(time) - time,
    seq = row_number()
  ) %>%
  select(seq, depth, time, difftime, cmd)

# Replace trailing NA difftime with zero
dat$difftime[nrow(dat)] <- 0

library(ggplot2)
ggplot(dat, aes(seq, difftime)) + geom_bar(stat = "identity")

Most expensive commands:

dat %>%
  arrange(-difftime) %>%
  select(seq, difftime, cmd) %>%
  head(10) %>%
  kable

seq	difftime	cmd
765	0.4584610	yarn global bin
762	0.0693970	ruby -rubygems -e ‘puts Gem.user_dir’
334	0.0343859	awk -F. ‘{print $1“.”$2}’
66	0.0286920	/usr/libexec/java_home
365	0.0210812	sed -n -e ‘#^system_type=# { s#^system_type=##;; p; }’ -e ‘/^$/d’
655	0.0168929	cat /Users/winston/.rvm/VERSION
530	0.0158780	__rvm_which sudo
343	0.0137122	_system_arch=x86_64
41	0.0128431	LSCOLORS=gxfxcxdxbxegedabagacad
294	0.0127299	command which which

Notes:

• The call stack depth is encoded in the log file, but we’re not using it.