Some things about getting useful output from time

December 20, 2009

No version of time has ever had what you could call a genuinely useful default output format, at least not for benchmarking and testing. The POSIX (and System V) standard format has all of the information you want in the right format (the times in simple seconds), but spreads it across multiple lines; the BSD format used by csh puts the times in 'human readable' format of hours, minutes, and seconds, and includes a bunch of additional information (much of which is inaccurate, useless, or outright made up by the kernel).

Fortunately, GNU time lets you set a different format. Since I keep looking this up, here is what I want to use:

time -f '%e real %U user %S kernel' ....

I want the times in pure seconds, not in 'human readable' converted form, because I am almost invariably performing math on them in order to find out the information that I'm really interested in.

(Perhaps somewhere there is a convenient Python module for doing this with human readable numbers, but frankly bc works fine with seconds so my motivation to go looking is low.)

FreeBSD's time program has no format specifier option, but defaults to essentially this format. Solaris's time program also has no format specifier option and defaults to a 'human readable' multi-line format; the best you can do is make it use the POSIX format with 'time -p'. On basically all systems, csh and tcsh have their own time builtin which uses the BSD csh format or some variant of it (and can be customized to some extent).

Now, let's talk about why I say that time makes up some of its numbers.

time generally gets its numbers from getrusage() (okay, technically it gets them from wait4(), which returns the same information). However, various versions of getrusage() explicitly document that some information is plain not returned or is not what you think it is. The Linux manpage for getrusage() says, for example:

[...] Not all fields are meaningful under Linux. In linux 2.4 only the fields ru_utime, ru_stime, ru_minflt, and ru_majflt are maintained. Since Linux 2.6, ru_nvcsw and ru_nivcsw are also maintained.

(Note that time determines the wall clock time itself.)

This corresponds to time's user and system time, major and minor page faults, and voluntary and involuntary time switches (%w and %c, not printed by default), and it assumes that the Linux kernel does a good job of keeping track of this information, which I would be dubious of. The kernel has good intentions, but doing completely accurate accounting can be hard and is not necessarily a high priority.

(Current Linux 2.6 kernels seems to also produce numbers for IO input and output, provided that you have the right kernel configuration options turned on. Again, the trustworthiness of those numbers is unknown.)

Currently, FreeBSD 8.0 says:

The numbers ru_inblock and ru_oublock account only for real I/O; data supplied by the caching mechanism is charged only to the first process to read or write the data.

I'm not going to quote from the Solaris 10 getrusage() manpage, but it has a similar long list of caveats and cautions.

Now, it's possible that time will return real and useful information for things you are interested in (beyond the basic time information). But before you rely on its numbers for performance measurement, you certainly need to check to make sure that they are accurate and useful. This should include not just reading the getrusage() manpage for your OS, but actually constructing synthetic programs that perform known operations and making sure that time reports accurate information for what they do.

Written on 20 December 2009.
« Some thoughts on intercepting https traffic
Using OpenID for local web application authentication »

Page tools: View Source, Add Comment.
Search:
Login: Password:
Atom Syndication: Recent Comments.

Last modified: Sun Dec 20 23:07:29 2009
This dinky wiki is brought to you by the Insane Hackers Guild, Python sub-branch.