2

We are having latency issue with a vendor application. I ran an strace -Tttt on the process and got this:

[...]
1470166748.946144 open("/opt/app/shdbrth/X       ", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000016>
1470166800.850979 open("/opt/app/shdbrth/X38347", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 10 <0.000070>
1470166800.851139 fstat(10, {st_mode=S_IFREG|0660, st_size=0, ...}) = 0 <0.000006>
[...]

According to the manpage, the -ttt prefixes each line with the time the syscall was made. The -T option appends the time the call took to process in between < and > brackets. However, this doesn't seem to add up in the above example.

For instance, the 2nd line started at 1,470,166,800 epoch seconds and 850,979 microsecs. According to the appended timer, it took 70 microsecs to process. However, the next line starts at the same epoch seconds and 851,139 microsecs---a difference of 90 microsecs.

I was going to write that off as just overhead but perhaps there's a more accurate explanation.

  • Sorry if i am being too obvious: It looks like is trying to find that file or a file that this file depends on: /opt/app/shdbrth/X... Is this file at the folder, if it is, it probably depends on something else... – Luciano Andress Martini Aug 2 '16 at 19:53
  • The program is probably doing more than just system calls, if that's what you're wondering about. These calls could come from deep within a library doing all sorts of other things that takes time inbetween them. – Kusalananda Aug 2 '16 at 19:57
  • @LucianoAndressMartini No need to apologize for something that seems obvious. Usually, that's the right answer :-). But what I don't understand is whether or not the IO search for the file should be included in the appended time (70 microsecs). – Belmin Fernandez Aug 2 '16 at 19:58
  • @Kusalananda Hm, okay.. that makes sense. User space stuff. Should have thought of that. – Belmin Fernandez Aug 2 '16 at 19:59
  • Also, strace may not show certain calls (that ltrace might) due to things like gettimeofday that have been optimized. – thrig Aug 2 '16 at 20:41
2

The time at the beginning of the line is the time when the kernel started processing that system call. The duration at the end of the line is the interval between the time when the kernel started processing that system call and the time when the kernel replied to the system call.

The time at the beginning of the next line is the time when the kernel started processing that next system call. Between the reply to one system call and the entry into the next system call, two kinds of things happened: the process ran user code, and potentially other processes were scheduled on the same processor.

In your example, the first open call took 16µs, and the next call was issued about 12s later. During those twelve seconds, the process ran user code, and was probably preempted many times to run other processes. Between the second open call and the subsequent fstat, about 90µs elapsed; given how small this is, it suggests that the process ran only a small amount of user code and wasn't preempted.

  • This is a great explanation. Not sure where the downvote comes from. Thanks @Gilles. – Belmin Fernandez Aug 3 '16 at 1:46
  • On a side note: to decode UNIX timestamps: perl -E 'say scalar localtime $ARGV[0]' 1470166800. – Satō Katsura Aug 3 '16 at 7:04
  • 1
    @SatoKatsura Or, on Linux: date -d @1470166800 – Gilles Aug 3 '16 at 7:40

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.