Want to share your content on R-bloggers? click here if you have a blog, or here if you don't.
Why?
Since the latest Mac OS X update, 10.10 “Yosemite”, was released last Thursday, there have been complaints springing up online of the progress bar woefully underestimating the actual time to complete installation. More specifically, it appeared as if, for a certain group of people (myself included), the installer would stall out at “two minutes remaining” or “less than a minute remaining”–sometimes for hours.
In the vast majority of these cases, though, the installation process didn’t hang, it was just performing a bunch of unexpected tasks that it couldn’t predict.
During the install, striking “Command” + “L” would bring up the install logs. In my case, the logs indicated that the installer was busy right until the very last minute.
Not knowing very much about OS X’s installation process and wanting to learn more, and wanting to answer why the installation was taking longer than the progress bar expected, I saved the log to a file on my disk with the intention of analyzing it before the installer automatically restarted my computer.
Cleaning
The log file from the Yosemite installer wasn’t in a format that R (or any program) could handle natively so before we can use it, we have to clean/munge it. To do this, we’ll write a program in the queen of all text-processing languages: perl.
This script will read the log file, line-by-line from standard input (for easy shell piping), and spit out nicely formatted tab-delimited lines.
#!/usr/bin/perl
use strict;
use warnings;
# read from stdin
while(<>){
chomp;
my $line = $_;
my ($not_message, $message) = split ': ', $line, 2;
# skip lines with blank messages
next if $message =~ m/^s*$/;
my ($month, $day, $time, $machine, $service) = split " ", $not_message;
print join("t", $month, $day, $time, $machine, $service, $message) . "n";
}
We can output the cleaned log file with this shell command:
echo "MonthtDaytTimetMachinetServicetMessage" > cleaned.log grep '^Oct' ./YosemiteInstall.log | grep -v ']: ' | grep -v ': }' | ./clean-log.pl >> cleaned.log
This cleaned log contains 6 fields: ‘Month’, ‘Day’, ‘Time’, ‘Machine (host)’, ‘Service’, and ‘Message’. The installation didn’t span days (it didn’t even span an hour) so technically I didn’t need the ‘Month’ and ‘Day’ fields, but I left them in for completeness’ sake.
Analysis
Let’s set some options and load the libraries we are going to use:
# options options(echo=TRUE) options(stringsAsFactors=FALSE) # libraries library(dplyr) library(ggplot2) library(lubridate) library(reshape2)
Now we read the log file that I cleaned and add a few columns with correctly parsed timestamps using lubridate’s “parse_date_time()” function
yos.log <- read.delim("./cleaned.log", sep="t") %>%
mutate(nice.date=paste(Month, Day, "2014", Time)) %>%
mutate(lub.time=parse_date_time(nice.date,
"%b %d! %Y! %H!:%M!:%S!",
tz="EST"))
And remove the rows of dates that didn’t parse correctly
yos.log <- yos.log[!is.na(yos.log$lub.time),] head(yos.log)
## Month Day Time Machine Service ## 1 Oct 18 11:28:23 localhost opendirectoryd ## 2 Oct 18 11:28:23 localhost opendirectoryd ## 3 Oct 18 11:28:23 localhost opendirectoryd ## 4 Oct 18 11:28:23 localhost opendirectoryd ## 5 Oct 18 11:28:23 localhost opendirectoryd ## 6 Oct 18 11:28:23 localhost opendirectoryd ## Message ## 1 opendirectoryd (build 382.0) launched - installer mode ## 2 Logging level limit changed to 'notice' ## 3 Initialize trigger support ## 4 created endpoint for mach service 'com.apple.private.opendirectoryd.rpc' ## 5 set default handler for RPC 'reset_cache' ## 6 set default handler for RPC 'reset_statistics' ## nice.date lub.time ## 1 Oct 18 2014 11:28:23 2014-10-18 11:28:23 ## 2 Oct 18 2014 11:28:23 2014-10-18 11:28:23 ## 3 Oct 18 2014 11:28:23 2014-10-18 11:28:23 ## 4 Oct 18 2014 11:28:23 2014-10-18 11:28:23 ## 5 Oct 18 2014 11:28:23 2014-10-18 11:28:23 ## 6 Oct 18 2014 11:28:23 2014-10-18 11:28:23
The first question I had was how long the installation process took
install.time <- yos.log[nrow(yos.log), "lub.time"] - yos.log[1, "lub.time"] (as.duration(install.time)) ## [1] "1848s (~30.8 minutes)"
Ok, about a half-hour.
Let’s make a column for cumulative time by subtracting each row’s time by the start time
yos.log$cumulative <- yos.log$lub.time - min(yos.log$lub.time, na.rm=TRUE)
In order to see what processes were taking the longest, we have to make a column for elapsed time. To do this, we can subtract each row’s time from the time of the subsequent row.
yos.log$elapsed <- lead(yos.log$lub.time) - yos.log$lub.time # remove last row yos.log <- yos.log[-nrow(yos.log),]
Which services were responsible for the most writes to the log and what services took the longest? We can find out with the following elegant dplyr construct. While we’re at it, we should add columns for percentange of the whole for easy plotting.
counts <- yos.log %>% group_by(Service) %>% summarise(n=n(), totalTime=sum(elapsed)) %>% arrange(desc(n)) %>% top_n(8, n) %>% mutate(percent.n = n/sum(n)) %>% mutate(percent.totalTime = as.numeric(totalTime)/sum(as.numeric(totalTime))) (counts)
## Source: local data frame [8 x 5] ## ## Service n totalTime percent.n percent.totalTime ## 1 OSInstaller 42400 1586 secs 0.9197197 0.867615 ## 2 opendirectoryd 3263 43 secs 0.0707794 0.023523 ## 3 Unknown 236 157 secs 0.0051192 0.085886 ## 4 _mdnsresponder 52 17 secs 0.0011280 0.009300 ## 5 OS 49 1 secs 0.0010629 0.000547 ## 6 diskmanagementd 47 7 secs 0.0010195 0.003829 ## 7 storagekitd 29 2 secs 0.0006291 0.001094 ## 8 configd 25 15 secs 0.0005423 0.008206
Ok, the “OSInstaller” is responsible for the vast majority of the writes to the log and to the total time of the installation. “opendirectoryd” was the next most verbose process, but its processes were relatively quick compared to the “Unknown” process’ as evidenced by “Unknown” taking almost 4 times longer, in aggregate, in spite of having only 7% of “opendirectoryd”‘s log entries.
We can more intuitively view the number-of-entries/time-taken mismatch thusly:
melted <- melt(as.data.frame(counts[,c("Service",
"percent.n",
"percent.totalTime")]))
ggplot(melted, aes(x=Service, y=as.numeric(value), fill=factor(variable))) +
geom_bar(width=.8, stat="identity", position = "dodge",) +
ggtitle("Breakdown of services during installation by writes to log") +
ylab("percent") + xlab("service") +
scale_fill_discrete(name="Percent of",
breaks=c("percent.n", "percent.totalTime"),
labels=c("writes to logfile", "time elapsed"))
As you can see, the “Unknown” process took a disproportionately long time for its relatively few log entries; the opposite behavior is observed with “opendirectoryd”. The other processes contribute very little to both the number of log entries and the total time in the installation process.
What were the 5 most lengthy processes?
yos.log %>% arrange(desc(elapsed)) %>% select(Service, Message, elapsed) %>% head(n=5)
## Service ## 1 OSInstaller ## 2 OSInstaller ## 3 Unknown ## 4 OSInstaller ## 5 OSInstaller ## Message ## 1 PackageKit: Extracting file:///System/Installation/Packages/Essentials.pkg (destination=/Volumes/Macintosh HD/.OSInstallSandboxPath/Root, uid=0) ## 2 System Reaper: Archiving previous system logs to /Volumes/Macintosh HD/private/var/db/PreviousSystemLogs.cpgz ## 3 kext file:///Volumes/Macintosh%20HD/System/Library/Extensions/JMicronATA.kext/ is in hash exception list, allowing to load ## 4 Folder Manager is being asked to create a folder (down) while running as uid 0 ## 5 Checking catalog hierarchy. ## elapsed ## 1 169 secs ## 2 149 secs ## 3 70 secs ## 4 46 secs ## 5 44 secs
The top processes were:
- Unpacking and moving the contents of “Essentials.pkg” into what is to become the newsystem directory structure. This ostensibly contains items like all the updated applications (Safari, Mail, etc..). (almost three minutes)
- Archiving the old system logs (two and a half minutes)
- Loading the kernel module that allows the onboard serial ATA controller to work (a little over a minute)
Let’s view a density plot of the number of writes to the log file during installation.
ggplot(yos.log, aes(x=lub.time)) +
geom_density(adjust=3, fill="#0072B2") +
ggtitle("Density plot of number of writes to log file during installation") +
xlab("time") + ylab("")
This graph is very illuminating; the vast majority of log file writes were the result of very quick processes that took place in the last 15 minutes of the install, which is when the progress bar read that only two minutes were remaining.
In particular, there were a very large number of log file writes between 11:47 and 11:48; what was going on here?
# if the first time is in between the second two, this returns TRUE
is.in <- function(time, start, end){
if(time > start && time < end)
return(TRUE)
return(FALSE)
}
the.start <- ymd_hms("14-10-18 11:47:00", tz="EST")
the.end <- ymd_hms("14-10-18 11:48:00", tz="EST")
# logical vector containing indices of writes in time interval
is.in.interval <- sapply(yos.log$lub.time, is.in,
the.start,
the.end)
# extract only these rows
in.interval <- yos.log[is.in.interval, ]
# what do they look like?
silence <- in.interval %>%
select(Message) %>%
sample_n(7) %>%
apply(1, function (x){cat("n");cat(x);cat("n")})
##
## (NodeOp) Move /Volumes/Macintosh HD/Recovered Items/usr/local/texlive/2013/tlpkg/tlpobj/featpost.tlpobj -> /Volumes/Macintosh HD/usr/local/texlive/2013/tlpkg/tlpobj Final name: featpost.tlpobj (Flags used: kFSFileOperationDefaultOptions,kFSFileOperationSkipSourcePermissionErrors,kFSFileOperationCopyExactPermissions,kFSFileOperationSkipPreflight,k_FSFileOperationSuppressConversionCopy)
##
## (NodeOp) Move /Volumes/Macintosh HD/Recovered Items/usr/local/texlive/2013/texmf-dist/tex/generic/pst-eucl/pst-eucl.tex -> /Volumes/Macintosh HD/usr/local/texlive/2013/texmf-dist/tex/generic/pst-eucl Final name: pst-eucl.tex (Flags used: kFSFileOperationDefaultOptions,kFSFileOperationSkipSourcePermissionErrors,kFSFileOperationCopyExactPermissions,kFSFileOperationSkipPreflight,k_FSFileOperationSuppressConversionCopy)
##
## (NodeOp) Move /Volumes/Macintosh HD/Recovered Items/Library/Python/2.7/site-packages/pandas-0.12.0_943_gaef5061-py2.7-macosx-10.9-intel.egg/pandas/tests/test_groupby.py -> /Volumes/Macintosh HD/Library/Python/2.7/site-packages/pandas-0.12.0_943_gaef5061-py2.7-macosx-10.9-intel.egg/pandas/tests Final name: test_groupby.py (Flags used: kFSFileOperationDefaultOptions,kFSFileOperationSkipSourcePermissionErrors,kFSFileOperationCopyExactPermissions,kFSFileOperationSkipPreflight,k_FSFileOperationSuppressConversionCopy)
##
## (NodeOp) Move /Volumes/Macintosh HD/Recovered Items/usr/local/texlive/2013/texmf-dist/tex/latex/ucthesis/uct10.clo -> /Volumes/Macintosh HD/usr/local/texlive/2013/texmf-dist/tex/latex/ucthesis Final name: uct10.clo (Flags used: kFSFileOperationDefaultOptions,kFSFileOperationSkipSourcePermissionErrors,kFSFileOperationCopyExactPermissions,kFSFileOperationSkipPreflight,k_FSFileOperationSuppressConversionCopy)
##
## (NodeOp) Move /Volumes/Macintosh HD/Recovered Items/usr/local/texlive/2013/texmf-dist/doc/latex/przechlewski-book/wkmgr1.tex -> /Volumes/Macintosh HD/usr/local/texlive/2013/texmf-dist/doc/latex/przechlewski-book Final name: wkmgr1.tex (Flags used: kFSFileOperationDefaultOptions,kFSFileOperationSkipSourcePermissionErrors,kFSFileOperationCopyExactPermissions,kFSFileOperationSkipPreflight,k_FSFileOperationSuppressConversionCopy)
##
## WARNING : ensureParentPathExists: Created `/Volumes/Macintosh HD/usr/local/texlive/2013/texmf-dist/doc/latex/moderntimeline' w/ {
##
## (NodeOp) Move /Volumes/Macintosh HD/Recovered Items/usr/local/texlive/2013/texmf-dists/type1/wadalab/mrj/mrjkx.pfb -> /Volumes/Macintosh HD/usr/local/texlive/2013/texmf-dists/type1/wadalab/mrj Final name: mrjkx.pfb (Flags used: kFSFileOperationDefaultOptions,kFSFileOperationSkipSourcePermissionErrors,kFSFileOperationCopyExactPermissions,kFSFileOperationSkipPreflight,k_FSFileOperationSuppressConversionCopy)
Ah, so these processes are the result of the installer having to move files back into the new installation directory structure. In particular, the vast majority of these move operations are moving files related to a program called “texlive”. I’ll explain why this is to blame for the inaccurate projected time to completion in the next section.
But lastly, let’s view a faceted density plot of the number of log files writes by process. This might give us a sense of what steps go on as the installation progresses by showing us with processes are most active.
# reduce number of service to a select few of the most active
smaller <- yos.log %>%
filter(Service %in% c("OSInstaller", "opendirectoryd",
"Unknown", "OS"))
ggplot(smaller, aes(x=lub.time, color=Service)) +
geom_density(aes( y = ..scaled..)) +
ggtitle("Faceted density of log file writes by process (scaled)") +
xlab("time") + ylab("")
This shows that no one process runs consistently throughout the entire installation process, but rather that the process run in spurts.
the answer
The vast majority of Mac users don’t place strange files in certain special system-critical locations like ‘/usr/local/’ and ‘/Library/’. Among those who do, though, these directories are littered with hundreds and hundreds of custom files that the installer doesn’t and can’t have prior knowledge of.
In my case, and probably many others, the estimated time-to-completion was inaccurate because the installer couldn’t anticipate needing to copy back so many files to certain special directories after unpacking the contents of the new OS. Additionally, for each of these copied files, the installer had to make sure the subdirectories had the exact same meta-data (permissions, owner, reference count, creation date, etc…) as before the installation began. This entire process added many minutes to the procedure at a point when the installer thought it was pretty much done.
What were some of the files that the installer needed to copy back? The answer will be different for each system but, as mentioned above, anything placed ‘/usr/local’ and ‘/Library’ directories that wasn’t Apple-supplied needed to be moved and moved back.
/usr/local/
/usr/local/ is used chiefly for user-installed software that isn’t part of the OS distribution. In my case, my /usr/local contained a custom compliled Vim; ClamXAV, a lightweight virus scanner that I use only for the benefit of my Windows-using friends; and texlive, software for the TeX typesetting system. texlive was, by far, the biggest time-sink since it had over 123,491 files.
In addition to these programs, many users might find that the Homebrew package manager is to blame for their long installation process, since this software also uses the /usr/local prefix (although it probably should not).
/Library/
Among other things, this directory holds (subdirectories that hold) modules and packages that the Apple-supplied Python, Ruby, and Perl uses. If you use these Apple-supplied versions of these languages and you install your own packages/modules using super-user privileges, the new packages will go into this directory and it will appear foreign to the Yosemite installer.
To get around this issue, either install packages/modules in a local (non-system) library, or use alternate versions of these programming languages that you either download and install yourself, or use MacPorts to install.
—
You can find all the code and logs that I used for this analysis in this git repository
This post is also available as a RMarkdown report here
share this:
R-bloggers.com offers daily e-mail updates about R news and tutorials about learning R and many other topics. Click here if you're looking to post or find an R/data-science job.
Want to share your content on R-bloggers? click here if you have a blog, or here if you don't.