Ever wonder what happens when you save a file in vim? There's quite a lot more
happening than open, write, and close. I found this out while working on
some code to monitor changed files using the node.js fs.watch API, which abstracts
(or obscures) Mac OS X's kqueue API.
To find out exactly what vim is doing when saving a file, we'll use a tool
included with DTrace that reports on another process's system calls. We need
the process ID of vim, which is already open and editing my file:
$ ps ax | grep vim
15800 s003 R+ 0:00.00 vim short/source.html
Then we run dtruss to attach to the running process, elevating our privileges
first
$ sudo dtruss -p 15800
Once attached to the running process, dtruss starts printing out system calls invoked by vim. I'm not entirely sure what these first few signify, perhaps they're caused by DTrace attaching, but after waiting a second, the output pauses.
SYSCALL(args) = return
workq_kernreturn(0x20, 0x0, 0x1) = 0 0
kevent(0x5, 0x0, 0x0) = 1 0
thread_selfid(0x7FFF74F62278, 0x0, 0xFFFFFFFF) = 848013 0
kevent(0x5, 0x10FE8DDB8, 0x1) = 1 0
__disable_threadsignal(0x1, 0x0, 0x0) = 0 0
thread_selfid(0x10FE0D000, 0x83000, 0x17BB) = 848037 0
select(0x1, 0x7FFF50670010, 0x0, 0x7FFF5066FF90, 0x0) = 1 0
Now we're ready to start interacting with vim. With the file already open, and
the command mode active, I enter :w. You can see the first call to read fills
a buffer with the single-character string ":". Vim then draws the : character
to the screen using all sorts of escape sequences to set colors and things.
read(0x0, ":", 0x1000) = 1 0
select(0x1, 0x7FFF50670180, 0x0, 0x7FFF50670100, 0x7FFF50670208) = 0 0
write(0x1, "\033[?25l\033[58;1H\033[K\033[58;1H:", 0x18) = 24 0
ioctl(0x0, 0x80487414, 0x7FFF5066F8E8) = 0 0
select(0x1, 0x7FFF5066F790, 0x0, 0x7FFF5066F710, 0x7FFF5066F818) = 0 0
write(0x1, "\033[?12l\033[?25h", 0xC) = 12 0
select(0x1, 0x7FFF5066F620, 0x0, 0x7FFF5066F5A0, 0x7FFF5066F6A8) = 1 0
Now vim waits for more user input by calling select, which eventually signals
more input is available from the keyboard. This time it's the letter "w". How
exciting! Vim draws the "w" character to the screen and waits for more input.
select(0x1, 0x7FFF5066F620, 0x0, 0x7FFF5066F5A0, 0x0) = 1 0
read(0x0, "w", 0x1000) = 1 0
select(0x1, 0x7FFF5066F790, 0x0, 0x7FFF5066F710, 0x7FFF5066F818) = 0 0
select(0x1, 0x7FFF5066F800, 0x0, 0x7FFF5066F780, 0x7FFF5066F888) = 0 0
write(0x1, "w", 0x1) = 1 0
select(0x1, 0x7FFF5066F690, 0x0, 0x7FFF5066F610, 0x7FFF5066F718) = 0 0
select(0x1, 0x7FFF5066F790, 0x0, 0x7FFF5066F710, 0x7FFF5066F818) = 0 0
write(0x1, "\033[?25l\033[?12l\033[?25h", 0x12) = 18 0
select(0x1, 0x7FFF5066F620, 0x0, 0x7FFF5066F5A0, 0x7FFF5066F6A8) = 1 0
select(0x1, 0x7FFF5066F620, 0x0, 0x7FFF5066F5A0, 0x0) = 1 0
Yep, got it, ":w". Finally, vim reads the result of me pressing [return] on
the keyboard.
read(0x0, "\r", 0x1000) = 1 0
select(0x1, 0x7FFF5066F790, 0x0, 0x7FFF5066F710, 0x7FFF5066F818) = 0 0
write(0x1, "\r", 0x1) = 1 0
Having received the whole command, it's parsed and the code to output the
buffer contents to a file is dispatched. We can see vim getting metadata in
the stat64 call, then checking write permissions with access.
stat64("/Users/kputnam/wd/resume/short/source.html", 0x7FFF5066F6C0, 0x7FFF506702E0) = 0 0
access("/Users/kputnam/wd/resume/short/source.html", 0x2, 0x0) = 0 0
Notably, the Mac OS X man page for access states,
Access() is a potential security hole and should never be used.
Next we see vim setting the current working directory to ".". Yes, "." is
the symbol that means the current working directory. So this just tells the
current working directory, "Be yourself, current working directory."
open(".", 0x0, 0x0) = 6 0
fchdir(0x6, 0x0, 0x0) = 0 0
Then vim traverses to the subdirectory "short", relative to the current
working directory. Again we see some calls that appear redundant, like two
calls to change the current working directory to "short".
chdir("short", 0x7FE96B417065, 0x0) = 0 0
open_nocancel(".", 0x0, 0x1) = 7 0
fstat64(0x7, 0x7FFF5066EBF0, 0x0) = 0 0
fcntl_nocancel(0x7, 0x32, 0x7FE96D803200) = 0 0
close_nocancel(0x7) = 0 0
stat64("/Users/kputnam/wd/resume/short", 0x7FFF5066EB60, 0x0) = 0 0
fchdir(0x6, 0x7FFF5066EB60, 0x0) = 0 0
close(0x6) = 0 0
Now vim prints the filename to the terminal, to indicate to the user that it's beginning to write the file contents to disk. Then another few calls to test the file status.
select(0x1, 0x7FFF5066F1B0, 0x0, 0x7FFF5066F130, 0x7FFF5066F238) = 0 0
write(0x1, "\033[?25l\"short/source.html\"", 0x19) = 25 0
stat64("short/source.html", 0x7FFF5066F970, 0x7FE96D807C00) = 0 0
access("short/source.html", 0x2, 0x0) = 0 0
lstat64("short/source.html", 0x7FFF5066F7E0, 0x98880) = 0 0
This next part seems highly strange. Apparently vim creates a new file called
"short/4913", sets the ownership of it, closes it, and then deletes the file.
lstat64("short/4913", 0x7FFF5066F7E0, 0x4) = -1 Err#2
open("short/4913", 0xB01, 0x81A4) = 6 0
fchown(0x6, 0x14000001F5, 0x14) = 0 0
stat64("short/4913", 0x7FFF5066F7E0, 0x0) = 0 0
close(0x6) = 0 0
unlink("short/4913", 0x7FFF5066F7E0, 0x0) = 0 0
Having completed that inexplicable task, vim now checks for the presence of
a backup named "source.html~", twice for good measure, and despite learning that
the file doesn't exist, tells the OS to remove it.
stat64("short/source.html~", 0x7FFF5066F330, 0x98880) = -1 Err#2
stat64("short/source.html", 0x7FFF5066EEF0, 0x7FFFFFFF) = 0 0
stat64("short/source.html~", 0x7FFF5066EE60, 0x0) = -1 Err#2
unlink("short/source.html~", 0x1, 0xFFFFFFFFFFFFFFFF) = -1 Err#2
Now vim renames the original, unmodified file, to "source.html~", and then
creates a new, empty file in its place. The contents of the editor buffer are
written to this new file.
rename("short/source.html", "short/source.html~") = 0 0
open("short/source.html", 0x601, 0x1A4) = 6 0
write(0x6, "<!DOCTYPE html PUBLIC \"-//W3C//DTD XHTML 1.0 Strict//EN\"\n...", 0x2000) = 8192 0
write(0x6, "S)</a>.</p>\n\n <span class=\"date_duration\">\n ...", 0x2000) = 8192 0
write(0x6, "gration with <a\n href=\"https://github.com/kputn...", 0x2000) = 8192 0
write(0x6, "ols</span>\n <span class=\"hidden\">\n <span...", 0x1A25) = 6693 0
fsync(0x6, 0x7FE96D805C00, 0x0) = 0 0
stat64("short/source.html", 0x7FFF5066F588, 0x0) = 0 0
stat64("short/source.html", 0x7FFF5066F328, 0x0) = 0 0
close(0x6) = 0 0
We can see from the return values of the write calls that vim writes 8192 bytes
each time. Then it waits for the OS to confirm the contents were flushed to disk
by calling fsync.
Lastly, vim indicates in the UI that the file has been written, and removes the backup file.
chmod(0x7FE96B417060, 0x81A4, 0x0) = 0 0
write(0x1, " 747L, 31269C written", 0x15) = 21 0
stat64("/Users/kputnam/wd/resume/short/source.html", 0x7FFF5066F290, 0x0) = 0 0
unlink("short/source.html~", 0x7FE96B44B4A0, 0x10F6F44F8) = 0 0
Once the file's been written, some plugin (probably syntastic) is invoked to check the syntax of the newly written file. But first vim asks the OS to do a bunch of seemingly useless tasks.
Stand in the place where you are:
open(".", 0x0, 0x0) = 6 0
fchdir(0x6, 0x0, 0x0) = 0 0
Now face West:
chdir("short", 0x7FE96B417065, 0x0) = 0 0
open_nocancel(".", 0x0, 0x1) = 7 0
fstat64(0x7, 0x7FFF5066EBF0, 0x0) = 0 0
fcntl_nocancel(0x7, 0x32, 0x7FE96C00B600) = 0 0
close_nocancel(0x7) = 0 0
Think about direction. Wonder why you haven't before.
stat64("/Users/kputnam/wd/resume/short", 0x7FFF5066EB60, 0x0) = 0 0
fchdir(0x6, 0x7FFF5066EB60, 0x0) = 0 0
close(0x6) = 0 0
stat64("short/source.html", 0x7FFF5066BF38, 0x10) = 0 0
Open it! No, close it!
open("short/source.html", 0x4, 0x0) = 6 0
close(0x6) = 0 0
Delete a non-existent file whose name is incomprehensible.
unlink("/var/folders/n2/b4nj1yhx7fbc3dcvqgt_93nr0000gn/T/vEtkV5J/7", 0x7FFF5066A29B, 0x0) = -1 Err#2
Next vim forks a child process to execute Tidy HTML, which will check that the changes I saved were well-formed HTML.
write(0x1, "\033[?12l\033[?25h", 0xC) = 12 0
ioctl(0x0, 0x80487414, 0x7FFF5066A028) = 0 0
fork() = 13834 0
Then vim compulsively waits for its child to die.
__semwait_signal(0x60F, 0x0, 0x1) = -1 Err#60
wait4(0x360A, 0x7FFF5066A1AC, 0x1) = 0 0
__semwait_signal(0x60F, 0x0, 0x1) = -1 Err#60
wait4(0x360A, 0x7FFF5066A1AC, 0x1) = 0 0
__semwait_signal(0x60F, 0x0, 0x1) = -1 Err#60
wait4(0x360A, 0x7FFF5066A1AC, 0x1) = 0 0
__semwait_signal(0x60F, 0x0, 0x1) = -1 Err#60
wait4(0x360A, 0x7FFF5066A1AC, 0x1) = 0 0
__semwait_signal(0x60F, 0x0, 0x1) = -1 Err#60
wait4(0x360A, 0x7FFF5066A1AC, 0x1) = 0 0
__semwait_signal(0x60F, 0x0, 0x1) = -1 Err#60
wait4(0x360A, 0x7FFF5066A1AC, 0x1) = 0 0
__semwait_signal(0x60F, 0x0, 0x1) = -1 Err#60
wait4(0x360A, 0x7FFF5066A1AC, 0x1) = 0 0
...
Someone now installs signal handlers for several UNIX signals, like
SIGKILL, SIGHUP, etc. I'm not sure if these are calls from the
child process or why the parent (vim) would reinitialize the signal
handlers at this ponit. These all point to the same address, except
for the last one on signal 0x2 which is SIGINT.
sigaction(0x1, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0x3, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0x4, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0x5, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0x6, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0x7, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0x8, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0xA, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0xB, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0xC, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0xF, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0x1B, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0x18, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0x19, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0x1E, 0x7FFF5066A048, 0x0) = 0 0
sigaction(0x1F, 0x7FFF5066A048, 0x0) = 0 0
sigprocmask(0x0, 0x0, 0x7FFF5066A08C) = 0x0 0
sigaction(0x2, 0x7FFF5066A018, 0x7FFF5066A040) = 0 0
More compulsive checking. Hurry up, are you dead yet?
wait4(0x360A, 0x7FFF5066A1AC, 0x1) = 0 0
__semwait_signal(0x60F, 0x0, 0x1) = -1 Err#60
wait4(0x360A, 0x7FFF5066A1AC, 0x1) = 0 0
__semwait_signal(0x60F, 0x0, 0x1) = -1 Err#60
wait4(0x360A, 0x7FFF5066A1AC, 0x1) = 0 0
__semwait_signal(0x60F, 0x0, 0x1) = -1 Err#60
wait4(0x360A, 0x7FFF5066A1AC, 0x1) = 0 0
__semwait_signal(0x60F, 0x0, 0x1) = -1 Err#60
...
Signal handlers still being installed, this time replacing some of the handlers we just installed, with an address 16 bytes from the previous handler.
ioctl(0x0, 0x80487414, 0x7FFF5066A028) = 0 0
sigprocmask(0x0, 0x0, 0x7FFF5066A07C) = 0x0 0
sigaction(0x1C, 0x7FFF5066A008, 0x7FFF5066A030) = 0 0
sigprocmask(0x0, 0x0, 0x7FFF5066A07C) = 0x0 0
sigaction(0x12, 0x7FFF5066A008, 0x7FFF5066A030) = 0 0
sigprocmask(0x0, 0x0, 0x7FFF5066A07C) = 0x0 0
sigaction(0x13, 0x7FFF5066A008, 0x7FFF5066A030) = 0 0
sigprocmask(0x0, 0x0, 0x7FFF5066A07C) = 0x0 0
sigaction(0xD, 0x7FFF5066A008, 0x7FFF5066A030) = 0 0
sigprocmask(0x0, 0x0, 0x7FFF5066A07C) = 0x0 0
sigaction(0x2, 0x7FFF5066A008, 0x7FFF5066A030) = 0 0
sigprocmask(0x0, 0x0, 0x7FFF5066A07C) = 0x0 0
sigaction(0xE, 0x7FFF5066A008, 0x7FFF5066A030) = 0 0
sigaction(0x1, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0x3, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0x4, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0x5, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0x6, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0x7, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0x8, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0xA, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0xB, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0xC, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0xF, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0x1B, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0x18, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0x19, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0x1E, 0x7FFF5066A038, 0x0) = 0 0
sigaction(0x1F, 0x7FFF5066A038, 0x0) = 0 0
ioctl(0x1, 0x4004667A, 0x7FFF5066A264) = 0 0
ioctl(0x1, 0x40087468, 0x7FFF5066A288) = 0 0
Conspicuously absent from these signal handlers is SIGCHLD (0x14), which
is invoked by the OS when a child process terminates. Perhaps what's going
on is the handlers are setup one way just after spawning the child, then wait4
returns indicating the child died, then the handlers are all restored to their
original settings.
Now vim reads the output of the child process, which was stored in /var/folders,
a descriptively named folder.
open_nocancel("/var/folders/n2/b4nj1yhx7fbc3dcvqgt_93nr0000gn/T/vEtkV5J/7", 0x0, 0x1B6) = 6 0
fstat64(0x6, 0x7FFF50669FD8, 0x7FFF5066A09C) = 0 0
read_nocancel(0x6, "No warnings or errors were found.\n\n\nTo learn more about HTML Tidy see http://tidy.sourceforge.net\nPlease send bug reports to html-tidy@w3.org\nHTML and CSS specifications are available from http://www.w3.org/\nLobby your company to join W3C, see http://www.w", 0x1000) = 273 0
read_nocancel(0x6, "", 0x1000) = 0 0
close_nocancel(0x6) = 0 0
unlink("/var/folders/n2/b4nj1yhx7fbc3dcvqgt_93nr0000gn/T/vEtkV5J/7", 0x10F6F91CA, 0x10F7649F0) = 0 0
Next all kinds of escape codes are written to the terminal, probably to position the cursor, and write color-coded, syntax-highlighted HTML to the screen.
select(0x1, 0x7FFF50669700, 0x0, 0x7FFF50669680, 0x7FFF50669788) = 0 0
select(0x1, 0x7FFF50669B90, 0x0, 0x7FFF50669B10, 0x7FFF50669C18) = 0 0
select(0x1, 0x7FFF50669B90, 0x0, 0x7FFF50669B10, 0x7FFF50669C18) = 0 0
...
write(0x1, "\033[27m\033[m\033[38;5;244m\033[48;5;234m\033[H\033[2J\033[?25l...", 0x7F1) = 2033 0
__semwait_signal(0x60F, 0x0, 0x1) = -1 Err#60
wait4(0x360A, 0x7FFF5066A1AC, 0x1) = 0 0
write(0x1, "m</a>\r\n\033[38;5;239m\033[48;5;235m 54 \033[m\033[38;5;244m\03...", 0x151) = 337 0
select(0x1, 0x7FFF5066B830, 0x0, 0x7FFF5066B7B0, 0x7FFF5066B8B8) = 0 0
select(0x1, 0x7FFF5066E290, 0x0, 0x7FFF5066E210, 0x7FFF5066E318) = 0 0
Then vim tells the OS to check again that the current directory still exists, and that the directory containing our file still exists, etc, in case it changed in the intervening microseconds since we last checked. You never know.
open(".", 0x0, 0x0) = 6 0
fchdir(0x6, 0x0, 0x0) = 0 0
chdir("short", 0x7FE96CB574A5, 0x0) = 0 0
open_nocancel(".", 0x0, 0x1) = 7 0
fstat64(0x7, 0x7FFF5066C330, 0x0) = 0 0
fcntl_nocancel(0x7, 0x32, 0x7FE96D800000) = 0 0
close_nocancel(0x7) = 0 0
stat64("/Users/kputnam/wd/resume/short", 0x7FFF5066C2A0, 0x0) = 0 0
fchdir(0x6, 0x7FFF5066C2A0, 0x0) = 0 0
close(0x6) = 0 0
Next, vim looks in my $PATH for ctags, probably to rebuild the a ctags
index (if I had ctags configured).
stat64("/Users/kputnam/wd/resume/short/source.html", 0x7FFF5066C968, 0x10FC76408) = 0 0
stat64("/Users/kputnam/.rvm/gems/ruby-2.0.0-p195/bin/ctags", 0x7FFF5066CE68, 0x6) = -1 Err#2
stat64("/Users/kputnam/.rvm/gems/ruby-2.0.0-p195@global/bin/ctags", 0x7FFF5066CE68, 0x6) = -1 Err#2
stat64("/Users/kputnam/.rvm/rubies/ruby-2.0.0-p195/bin/ctags", 0x7FFF5066CE68, 0x6) = -1 Err#2
stat64("/Users/kputnam/.rvm/bin/ctags", 0x7FFF5066CE68, 0x6) = -1 Err#2
stat64("/usr/local/share/npm/bin/ctags", 0x7FFF5066CE68, 0x6) = -1 Err#2
stat64("/usr/local/sbin/ctags", 0x7FFF5066CE68, 0x6) = -1 Err#2
stat64("/usr/local/bin/ctags", 0x7FFF5066CE68, 0x6) = -1 Err#2
stat64("/Users/kputnam/.cabal/bin/ctags", 0x7FFF5066CE68, 0x6) = -1 Err#2
stat64("/Users/kputnam/bin/ctags", 0x7FFF5066CE68, 0x6) = -1 Err#2
stat64("/usr/bin/ctags", 0x7FFF5066CE68, 0x6) = 0 0
access("/usr/bin/ctags", 0x1, 0x0) = 0 0
That's pretty much it. Part of the status bar is written to the screen again, and a few lines of the file are redrawn. The revelant parts which actually deal with the filesystem are:
- Move the original file out of the way, to
source.html~. - Write the buffer contents to a new file,
source.html - Remove the
source.html~backup file after flushing output