Bug report and patch for strace's -O option

[Lai JiangShan]

Hi,

I found another bug of strace's the -O option.

$ strace -V
strace -- version 4.5.15
$ strace -c -O 30 echo

Process 27534 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
-43.01    0.000123         123         1           execve
 -0.00    0.000000           0         1           write
  2.80   -1.999992          -8         1           munmap
  4.90   -1.999986         -14         1         1 access
  5.24   -1.999985         -15         1           read
  5.59   -1.999984         -16         1           arch_prctl
  6.29   -1.999982         -18         1           uname
  8.04   -1.999977          -7         3           open
 10.49   -1.999970         -14         2           mprotect
 17.13   -1.999951         -16         3           brk
 18.18   -1.999948         -17         3           close
 23.08   -1.999934         -16         4           fstat
 41.26   -1.999882         -12         9           mmap
------ ----------- ----------- --------- --------- ----------------
100.00   -1.999714                    31         1 total


The negative data of "seconds" colume is not correct.
Take munmap as an example, the result should not be

  2.80   -1.999992          -8         1           munmap
but
  2.80   -0.000008          -8         1           munmap

The bug can be fixed with the following patch:

Signed-off-by: "Lai Jiangshan" <laijs at cn.fujitsu.com>

--- count.c	2007-07-11 16:40:25.000000000 +0800
+++ count.c.new	2007-07-11 16:26:46.000000000 +0800
@@ -205,9 +205,8 @@ call_summary_pers(FILE *outf)
 				error_str[0] = '\0';
 			percent = (100.0 * tv_float(&counts[j].time)
 				   / tv_float(&tv_cum));
-			fprintf(outf, "%6.2f %4ld.%06ld %11ld %9d %9.9s %s\n",
-				percent, (long) counts[j].time.tv_sec,
-				(long) counts[j].time.tv_usec,
+			fprintf(outf, "%6.2f %11.6f %11ld %9d %9.9s %s\n",
+				percent, tv_float(&counts[j].time),
 				(long) 1000000 * dtv.tv_sec + dtv.tv_usec,
 				counts[j].calls,
 				error_str, sysent[j].sys_name);
@@ -221,8 +220,8 @@ call_summary_pers(FILE *outf)
 		sprintf(error_str, "%d", error_cum);
 	else
 		error_str[0] = '\0';
-	fprintf(outf, "%6.6s %4ld.%06ld %11.11s %9d %9.9s %s\n",
-		"100.00", (long) tv_cum.tv_sec, (long) tv_cum.tv_usec, "",
+	fprintf(outf, "%6.6s %11.6f %11.11s %9d %9.9s %s\n",
+		"100.00", tv_float(&tv_cum), "",
 		call_cum, error_str, "total");
 }

Here is the output after the fix:

$ ./strace -c -O 30 echo

Process 29766 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
-50.19    0.000134         134         1           execve
  2.25   -0.000006          -6         1           write
  3.00   -0.000008          -8         1           munmap
  4.87   -0.000013         -13         1           uname
  5.24   -0.000014         -14         1         1 access
  5.62   -0.000015         -15         1           read
  5.99   -0.000016         -16         1           arch_prctl
  8.99   -0.000024         -11         2           mprotect
 10.11   -0.000027          -8         3           open
 14.98   -0.000040         -13         3           brk
 18.73   -0.000050         -16         3           close
 25.09   -0.000067         -16         4           fstat
 45.32   -0.000121         -13         9           mmap
------ ----------- ----------- --------- --------- ----------------
100.00   -0.000267                    31         1 total

Regards