CODEWITHSUNDEEP
shell
Borek Bernard
Borek Bernard

Reputation: 53231

What explains the inaccuracy of `time` on macOS?

Note: I've seen https://stackoverflow.com/a/64315882/21728 and understand that time is not necessarily that precise. However, I'm seeing a 4× difference between the reported time and time it actually took, and I'd like to understand what's causing it on macOS – that's the point of this question.

I'm trying to compare two ways to run a binary and they report very similar time info:

$ time ../../../node_modules/.bin/quicktype --version
quicktype version 15.0.214
Visit quicktype.io for more info.
../../../node_modules/.bin/quicktype --version  0.46s user 0.06s system 110% cpu 0.474 total

$ time $(yarn bin quicktype) --version
quicktype version 15.0.214
Visit quicktype.io for more info.
$(yarn bin quicktype) --version  0.44s user 0.06s system 110% cpu 0.449 total

However, the latter feels much slower. So I've added timestamps before and after:

$ date +"%T.%3N" && time $(yarn bin quicktype) --version && date +"%T.%3N"
15:11:09.667
quicktype version 15.0.214
Visit quicktype.io for more info.
$(yarn bin quicktype) --version  0.49s user 0.06s system 108% cpu 0.513 total
15:11:11.400

Indeed, the difference between 15:11:09.667 and 15:11:11.400 is almost two seconds but time is reporting about 0.5 second. What explains this rather vast difference?

Upvotes: 0

Views: 680

Answers (2)

Nate Eldredge
Nate Eldredge

Reputation: 57942

Generally speaking, for an external command cmd, it is the case that shell expansions are done by the shell before cmd is started. This includes command substitution cmd $(other_cmd), globbing cmd *.txt, variable expansion cmd $FOO, and so forth. So cmd is executed with the result of the expansion as its arguments, and never sees the original command line typed by the user.

Thus if time were an ordinary external command, as it is if you use /usr/bin/time, then the command yarn bin quicktype would be run before time even starts, and it would be just as if you had run time .../quicktype --version. It only measures the time taken to execute .../quicktype --version, and it would not (and could not) account for the time taken for the shell to generate that command line by running yarn.

Now the situation here is not quite that simple because time is actually a builtin command in many shells, and not an external command. So it doesn't necessarily have to follow the above behavior. However, in my tests, zsh's builtin time behaves the same, and does not count the time taken to run the substituted command yarn. On the other hand, in bash, the time builtin does include it.

As you saw, you can circumvent the issue by timing the running of a new shell which does both the command substitution (running yarn) and the resulting ../quicktype command itself. Then you will definitely include the time taken by both steps.

Upvotes: 1

Borek Bernard
Borek Bernard

Reputation: 53231

I was using the time wrong.

First, time is different from /usr/bin/time on my Mac:

  • time is a shell built-in (I use Zsh)
  • /usr/bin/time is BSD time

This gives the expected results:

$ /usr/bin/time bash -c '../../../node_modules/.bin/quicktype --version'
quicktype version 15.0.214
Visit quicktype.io for more info.
        0.49 real         0.47 user         0.06 sys

$ /usr/bin/time bash -c '$(yarn bin quicktype) --version'
quicktype version 15.0.214
Visit quicktype.io for more info.
        2.02 real         1.92 user         0.27 sys

Upvotes: 2

Related Questions