Thursday, March 20, 2014

Shell history: Set HISTTIMEFORMAT to save & see when you executed commands

this is a really useful setting that I didn't know about until a couple years ago.

HISTTIMEFORMAT='%F %T '

So used to it now, I get annoyed when I create a new account/login and don't have it.

Why:  ability to correlate system artifacts with commands.
There's a file here, when/how did I create it?
Now in the shell, 'history' will show the time of commands; which may help you track down when you created (or deleted) a file, etc.

Some issues:

  • if you start a new shell, and it ends after this one, $HISTFILE can get overwritten.
    Problem if you like to have lots of shells & windows at the same time.
  • after a while, with a lot of history, only the last $HISTSIZE (or HISTFILESIZE) commands will be saved.
  • your $HISTFILE contains unix epoch times, so not easily read or grep'd directly.
    (However, you can easily save and load with history -w / -r )
  • recorded time is not retroactive.  All previous commands prior will have the time when you first set HISTTIMEFORMAT, so start today!
I have solutions to most of these, so each of my screen windows have their own history, also emacs, xterm shells,  and a per-directory history as well.
How many commands?  121859 (just one system, my main laptop last 2.5 years usage),
this doesn't count a few other development systems.

Seems like a lot, but that's only ~133 commands per day average.


... So what is the ideal system audit trail ?

Use fs_usage to monitor file system activity on OS X


Here's 3 commands I've found useful over the past year to see:

  • how much filesystem activity is going on
    IOPS (i/o operations per second), approximately
  • which applications are causing the most activity
  • which files or paths in the filesystem are being accessed
I will assume some unix familiarity here;  if you don't know where these commands go, then you probably don't understand the output either.  Come back after you've learned more.  All command lines are a single line, and appear below in courier bold.

Also, you need to be root for this.
I like to keep past outputs, and in a separate directory to contain clutter, so if you want to use these commands without modification then first do (one time only):
mkdir fs_usage

1.  Collect output from fs_usage

[42]original-mac 10:21:56 1082 ~# fs=$[fs+1]; fsd=0216; time fs_usage -w -f filesys  | grep '/.*/'  | head -10000 > fs_usage/fs.$fsd.$fs  


real    1m18.214s
user    0m1.379s
sys     0m1.428s


Here, only looking for the fs_usage output lines with pathnames (at least 2 slashes), the first 10k instances.  You can do more or less...  This took 78 seconds, which tells me the system is "fairly idle", at least mine, with the normal set of applications that I usually have open.  I have seen it complete in as little as two or three seconds.

I set $fsd as the date, and then increment the filename each time; this is just a personal packrat preference, but you can just use a single file in /tmp if you like.

In this form, it's easy to wrap with a while or
for sample in {1..10}; do ...; doneif you want to get ten samples, and then compare/combine the outputs.  Putting output from time into a separate file left as exercise for the reader.

Note these do not directly correspond to disk accesses (reads/writes), just general i/o activity.
'Activity Monitor' provides a graph of IOPS (or so it says); there are other benchmark programs if you want to check your disk (what's your favorite?).

2.  See which applications are issuing requests.  

Note with fs_usage '-w' wide output, the application name starts in column 234.  


[37]original-mac 10:02:40 1078 ~# cat fs_usage/fs.$fsd.$fs | cut -c234- | sort | uniq -c | sort -n | tail -25
  67 fseventsd.1560736
  67 fseventsd.3241
  67 fseventsd.639202
  80 CalendarAgent.2319030
  81 mds.2317581
  96 Dropbox.6042
 114 leapd.2991
 119 mdworker.2292251
 120 fseventsd.3427
 120 fseventsd.3428
 131 Google Chrome.1506982
 132 CalendarAgent.2319032
 148 Google Chrome.1507028
 152 launchd.210
 154 opendirectoryd.2318992
 154 opendirectoryd.2318994
 156 Google Chrome.1507026
 156 opendirectoryd.2318977
 160 opendirectoryd.2318972
 202 dbfseventsd.626141
 206 mtmfs.780
 230 Google Chrome.1506961
 288 com.apple.iCloud.2319050
 376 mtmd.781
6021 Google Chrome.1506955


Google Chrome is the majority of the activity...  not particularly surprising (I currently have 30+ tabs open).

3.  See what directories and files are being accessed

[36]original-mac 10:01:26 1077 ~# cat fs_usage/fs.$fsd.$fs | cut -c57-200 | sort | cut -c1-60 | uniq -c | sort -n | tail -33

  20 /Users/todd/Library/Application%2525252520Support
  20 /private/var/folders/98/vpw5gnnx1xg_9l3vjv3cc7r00000gn/T/.co
  20 0       /dev/disk0s2
  20 private/var/folders/98/vpw5gnnx1xg_9l3vjv3cc7r00000gn/T/.com
  21 /Applications/TextEdit.app
  22 /Users/todd/Library/Application%252520Support>>>>>>>>>>>>>>>
  23 /Users/todd/Library
  23 /Users/todd/Library/Application%20Support>>>>>>>>>>>>>>>>>>>
  23 /Users/todd/Library/Application%2520Support>>>>>>>>>>>>>>>>>
  24 /Users/todd/.dropbox/PENDING_MN7VKR
  24 /Users/todd/.dropbox/UPDATED_Xp1v55
  24 /Users/todd/Library/Application Support/Google/Chrome/.com.g
  24 /Users/todd/Library/Application Support/Google/Chrome/Local
  25 private/var/folders/98/vpw5gnnx1xg_9l3vjv3cc7r00000gn/T
  29 /Users/todd/Library/Saved Application State/com.apple.Termin
  31 /Users/todd
  31 /Users/todd/Library/Calendars
  32 00      /dev/disk0s3
  36 /Users/todd/Library/Application Support/iCloud>>>>>>>>>>>>>>
  40 /Users/todd/Library/Calendars/CE0DC09B-CC04-47D0-9217-E0E295
  42 /Users/todd/Library/Preferences/com.apple.security.revocatio
  47 /Volumes/rescue          
  58 /Users/todd/Library/Preferences/VMware Fusion/preferences
  72 /System/Library/CoreServices/backupd.bundle/Contents/Resourc
  89 /Users/todd/Library/Calendars/Calendar Cache-wal
 104 /Users/todd/Library/Calendars/Calendar Cache-journal
 114 /dev/console
 115 /Users/todd/Library/Application Support/Google/Chrome
 123 /private/var/folders/98/vpw5gnnx1xg_9l3vjv3cc7r00000gn/T
 216 /System/Library/PrivateFrameworks/CalendarAgent.framework/Ex
 250 /Users/todd/Library/Application Support/Google/Chrome/Safe B
 454 0       /dev/disk0s3
6487 /Users/todd/Library/Application Support/Google/Chrome/Defaul

Again, the fs_usage output has the pathname (since we explicitly grep'd for one) starting around column 57..  then I'm only looking at the first 60 characters of that path and aggregating to get a useful summary; you can use shorter or longer, or just search the raw output for specific files.

Mostly Chrome accessing my profile here.  Not sure about the /dev/disk accesses, or why some lines have '>>>>..' in them...  in the context of the full fs_usage output it might be more apparent.  However, for my purposes of approximately finding out what is going on, these are useful.

You need to run this a few times on yoru system to determine a baseline--i.e., what normal levels of activity are, and which applications are generating them.

DISKS ARE SLOW,  limited to one head per platter, and you have to wait for it to rotate into place.. a limiting resource (if you have an SSD or hybrid disk or RAID with battery-backed write-cache memory--they are a little better).  Sometimes you can't avoid them (e.g., you have to save your work).  But if/when your system starts slowing down, this can provide a little insight into what may be the bottleneck, and what unnecessary items you can shut down.


Emacs (Aquamacs) VC (SVN) failure to authenticate

At somepoint when I upgraded my Aquamacs this stopped working:
C-x v v  within aquamacs should do an "svn commit".

svn: E215004: Authentication failed and interactive prompting is disabled; see the --force-interactive option
svn: E215004: Commit failed (details follow):
svn: E215004: Unable to connect to a repository at URL 'https://svn.foo.com/svn/myproject/etc/etc'
svn: E215004: No more credentials or we tried too many times.
Authentication failed

Aquamacs version:
GNU Emacs 23.4.1 (x86_64-apple-darwin12.3.0, NS apple-appkit-1187.37) of 2013-06-13 on acs-trailblazer.ist.psu.edu - Aquamacs Distribution 2.5

from cmd-line, same thing!  I thought that worked.
GNU Emacs 24.3.1 (x86_64-apple-darwin12.5.0) of 2013-12-22 on teneight-slave.macports.org

there is the possibility something in my .emacs
no; 'emacs -q' produces the same thing.

vc.el ?  I guess next step is to load the elisp source, and start to dig in.

For now, I've reverted to calling svn from the cmd line.
I'm trying to switch over to git anyway, and this just encourages that (because vc+git is (still) working)...