strace -{c,T} timing issues

[Mathis Ahrens]

Hi,

it seems like strace does timing different when doing
	strace -T
as opposed to 
	strace -c

I am wondering if this is intended, because what I would
like to have is a summary as with the -c option, but the
timings as with -T.

Actually I find -c timings rather useless (pretty random).
I tried measuring how long a simple ls call spends in 
individual system calls. 
Here is the head of `strace -T ls`:
	execve("/bin/ls", ["ls"], [/* 31 vars */]) = 0 <0.000224>
	uname({sys="Linux", node="template", ...}) = 0 <0.000009>
	brk(0)                                  = 0x805c000 <0.000007>

The timings vary within a few percent across invocations, which
is what I would expect. But the output is not summed up per syscall,
so I tried `strace -c ls`:
	% time     seconds  usecs/call     calls    errors syscall
	------ ----------- ----------- --------- --------- ----------------
	100.00    0.000215           8        28           mmap2
	  0.00    0.000000           0        10           read
	  0.00    0.000000           0         1           write
	  0.00    0.000000           0        12           open
	  0.00    0.000000           0        13           close
	  0.00    0.000000           0         1           execve
	  0.00    0.000000           0        11        11 access
	...cut...

The next time output might look completely different (timing-wise):

	% time     seconds  usecs/call     calls    errors syscall
	------ ----------- ----------- --------- --------- ----------------
	100.00    0.000027           2        11        11 access
	  0.00    0.000000           0        10           read
	  0.00    0.000000           0         1           write
	  0.00    0.000000           0        12           open
	  0.00    0.000000           0        13           close
	  0.00    0.000000           0         1           execve
	...cut...

But most of the time, measurements seem to be invalid:

	% time     seconds  usecs/call     calls    errors syscall
	------ ----------- ----------- --------- --------- ----------------
	   nan    0.000000           0        10           read
	   nan    0.000000           0         1           write
	   nan    0.000000           0        12           open
	   nan    0.000000           0        13           close
	   nan    0.000000           0         1           execve
	   nan    0.000000           0        11        11 access
	...cut...


This was all done with recent 4.5.1{2,4} strace on 2.6.1{6,8} linux 
(gentoo / debian-etch).

Is this expected?
If so, why?


Thanks,
Mathis

--