Time Utility – Why Real Time is Higher Than User and Sys Times Combined

When you run ls without arguments, it will just open a directory, read all the contents, sort them and print them out.

When you run ls *, first the shell expands *, which is effectively the same as what the simple ls did, builds an argument vector with all the files in the current directory and calls ls. ls then has to process that argument vector and for each argument, and calls access(2)¹ the file to check it's existence. Then it will print out the same output as the first (simple) ls. Both the shell's processing of the large argument vector and ls's will likely involve a lot of memory allocation of small blocks, which can take some time. However, since there was little sys and user time, but a lot of real time, most of the time would have been spent waiting for disk, rather than using CPU doing memory allocation.

Each call to access(2) will need to read the file's inode to get the permission information. That means a lot more disk reads and seeks than simply reading a directory. I do not know how expensive these operations are on your GPFS, but as the comparison you've shown to ls -l which has a similar run time to the wildcard case, the time needed to retrieve the inode information appears to dominate. If GPFS has a slightly higher latency than your local filesystem on each read operation, we would expect it to be more pronounced in these cases.

The difference between the wildcard case and ls -l of 50% could be explained by the ordering of inodes on the disk. If the inodes were laid out successively in the same order as the filenames in the directory and ls -l stat(2)ed the files in directory order before sorting, ls -l would possibly read most of the inodes in a sweep. With the wildcard, the shell will sort the filenames before passing them to ls, so ls will likely read the inodes in a different order, adding more disk head movement.

It should be noted that your time output will not include the time taken by the shell to expand the wildcard.

If you really want to see what's going on, use strace(1):

strace -o /tmp/ls-star.trace ls *
strace -o /tmp/ls-l-star.trace ls -l *

and have a look which system calls are being performed in each case.

¹ I don't know if access(2) is actually used, or something else such as stat(2). But both probably require an inode lookup (I'm not sure if access(file, 0) would bypass an inode lookup.)

The output you show is a bit odd, since real time would usually be bigger than the other two.

• Real time is wall clock time. (what we could measure with a stopwatch)
• User time is the amount of time spend in user-mode within the process
• Sys is the CPU time spend in the kernel within the process.

So I suppose if the work was done by several processors concurrently, the CPU time would be higher than the elapsed wall clock time.

Was this a concurrent/multi-threaded/parallel type of application?

Just as an example, this is what I get on my Linux system when I issue the time find . command. As expected the elapsed real time is much larger than the others on this single user/single core process.

real    0m5.231s
user    0m0.072s
sys     0m0.088s

The rule of thumb is:

• real < user: The process is CPU bound and takes advantage of parallel execution on multiple cores/CPUs.
• real ≈ user: The process is CPU bound and takes no advantage of parallel exeuction.
• real > user: The process is I/O bound. Execution on multiple cores would be of little to no advantage.