Browse Source

strace: add arguments to --syscall-times and --relative-timestamps

* defs.h (Tflag_scale, Tflag_width): New declarations.
* strace.c (Tflag_scale, Tflag_width, rflag_scale, rflag_width): New
variables.
(printleader): Parametrise relative timestamp printing with rflag_width
and rflag_scale.
(init) <longopts>: Change second field of "relative-timestamps" and
"syscall-times" from no_argument to optional_argument.
(init) <case 'r', case 'T'>: Handle optarg, fail if the scale variable
is set to -1.
(usage): Document it.
* strace.1.in (.SS Output format): Likewise.
* syscall.c (syscall_exiting_trace): Parametrise syscall time printing
* with Tflag_width and Tflag_scale.
* tests/gen_tests.in (strace--relative-timestamps-s,
strace--relative-timestamps-ms, strace--relative-timestamps-us,
strace--relative-timestamps-ns): New tests.
* tests/options-syntax.test: New checks for --relative-timestamps and
--syscall-times option syntax.
* tests/strace--relative-timestamps-ms.expected: New file.
* tests/strace--relative-timestamps-ns.expected: Likewise.
* tests/strace--relative-timestamps-s.expected: Likewise.
* tests/strace--relative-timestamps-us.expected: Likewise.
* tests/strace--syscall-times-ms.expected: Likewise.
* tests/strace--syscall-times-ns.expected: Likewise.
* tests/strace--syscall-times-s.expected: Likewise.
* tests/strace--syscall-times-us.expected: Likewise.
* tests/Makefile.am (EXTRA_DIST): Add them.
Eugene Syromyatnikov 1 month ago
parent
commit
e375a25e9e

+ 2
- 0
defs.h View File

@@ -462,6 +462,8 @@ typedef enum {
462 462
 } cflag_t;
463 463
 extern cflag_t cflag;
464 464
 extern bool Tflag;
465
+extern int Tflag_scale;
466
+extern int Tflag_width;
465 467
 extern bool iflag;
466 468
 extern bool count_wallclock;
467 469
 extern unsigned int show_fd_path;

+ 16
- 2
strace.1.in View File

@@ -880,10 +880,17 @@ and about process exit status.
880 880
 .TP
881 881
 .B \-r
882 882
 .TQ
883
-.B \-\-relative\-timestamps
883
+.BR \-\-relative\-timestamps [= \fIprecision\fR ]
884 884
 Print a relative timestamp upon entry to each system call.  This
885 885
 records the time difference between the beginning of successive
886 886
 system calls.
887
+.I precision
888
+can be one of
889
+.BR s " (for seconds), " ms " (milliseconds), " us " (microseconds), or " ns
890
+(nanoseconds), and allows setting the precision of time value being printed.
891
+Default is
892
+.B us
893
+(microseconds).
887 894
 Note that since
888 895
 .B \-r
889 896
 option uses the monotonic clock time for measuring time difference and not the
@@ -912,9 +919,16 @@ of seconds since the epoch.
912 919
 .TP
913 920
 .B \-T
914 921
 .TQ
915
-.B \-\-syscall\-times
922
+.BR \-\-syscall\-times [= \fIprecision\fR ]
916 923
 Show the time spent in system calls.  This records the time
917 924
 difference between the beginning and the end of each system call.
925
+.I precision
926
+can be one of
927
+.BR s " (for seconds), " ms " (milliseconds), " us " (microseconds), or " ns
928
+(nanoseconds), and allows setting the precision of time value being printed.
929
+Default is
930
+.B us
931
+(microseconds).
918 932
 .TP
919 933
 .B \-v
920 934
 .TQ

+ 26
- 8
strace.c View File

@@ -77,10 +77,14 @@ static struct xlat_data xflag_str[] = {
77 77
 unsigned int xflag;
78 78
 bool debug_flag;
79 79
 bool Tflag;
80
+int Tflag_scale = 1000;
81
+int Tflag_width = 6;
80 82
 bool iflag;
81 83
 bool count_wallclock;
82 84
 static unsigned int tflag;
83 85
 static bool rflag;
86
+static int rflag_scale = 1000;
87
+static int rflag_width = 6;
84 88
 static bool print_pid_pfx;
85 89
 
86 90
 /* -I n */
@@ -353,15 +357,17 @@ Output format:\n\
353 357
                  suppress messages about attaching, detaching, etc.\n\
354 358
   -qq, --quiet=attach,personality,exit\n\
355 359
                  suppress messages about process exit status as well.\n\
356
-  -r, --relative-timestamps\n\
360
+  -r, --relative-timestamps[=PRECISION]\n\
357 361
                  print relative timestamp\n\
362
+     precision:  one of s, ms, us, ns; default is microseconds\n\
358 363
   -s STRSIZE, --string-limit=STRSIZE\n\
359 364
                  limit length of print strings to STRSIZE chars (default %d)\n\
360 365
   -t             print absolute timestamp\n\
361 366
   -tt            print absolute timestamp with usecs\n\
362 367
   -ttt           print absolute UNIX time with usecs\n\
363
-  -T, --syscall-times\n\
368
+  -T, --syscall-times[=PRECISION]\n\
364 369
                  print time spent in each syscall\n\
370
+     precision:  one of s, ms, us, ns; default is microseconds\n\
365 371
   -v, --no-abbrev\n\
366 372
                  verbose mode: print entities unabbreviated\n\
367 373
   -x, --strings-in-hex=non-ascii\n\
@@ -778,10 +784,12 @@ printleader(struct tcb *tcp)
778 784
 		ts_sub(&dts, &ts, &ots);
779 785
 		ots = ts;
780 786
 
781
-		tprintf("%s%6ld.%06ld%s ",
782
-			tflag ? "(+" : "",
783
-			(long) dts.tv_sec, (long) dts.tv_nsec / 1000,
784
-			tflag ? ")" : "");
787
+		tprintf("%s%6ld", tflag ? "(+" : "", (long) dts.tv_sec);
788
+		if (rflag_width) {
789
+			tprintf(".%0*ld",
790
+				rflag_width, (long) dts.tv_nsec / rflag_scale);
791
+		}
792
+		tprints(tflag ? ") " : " ");
785 793
 	}
786 794
 
787 795
 	if (iflag)
@@ -1798,10 +1806,10 @@ init(int argc, char *argv[])
1798 1806
 		{ "summary-syscall-overhead", required_argument, 0, 'O' },
1799 1807
 		{ "attach",		required_argument, 0, 'p' },
1800 1808
 		{ "trace-path",		required_argument, 0, 'P' },
1801
-		{ "relative-timestamps", no_argument,	   0, 'r' },
1809
+		{ "relative-timestamps", optional_argument, 0, 'r' },
1802 1810
 		{ "string-limit",	required_argument, 0, 's' },
1803 1811
 		{ "summary-sort-by",	required_argument, 0, 'S' },
1804
-		{ "syscall-times",	no_argument,	   0, 'T' },
1812
+		{ "syscall-times",	optional_argument, 0, 'T' },
1805 1813
 		{ "user",		required_argument, 0, 'u' },
1806 1814
 		{ "no-abbrev",		no_argument,	   0, 'v' },
1807 1815
 		{ "version",		no_argument,	   0, 'V' },
@@ -1934,6 +1942,11 @@ init(int argc, char *argv[])
1934 1942
 			break;
1935 1943
 		case 'r':
1936 1944
 			rflag = 1;
1945
+			rflag_width = 6;
1946
+			rflag_scale = str2timescale_optarg(optarg,
1947
+							   &rflag_width);
1948
+			if (rflag_scale < 0)
1949
+				error_opt_arg(c, lopt, optarg);
1937 1950
 			break;
1938 1951
 		case 's':
1939 1952
 			i = string_to_uint(optarg);
@@ -1949,6 +1962,11 @@ init(int argc, char *argv[])
1949 1962
 			break;
1950 1963
 		case 'T':
1951 1964
 			Tflag = 1;
1965
+			Tflag_width = 6;
1966
+			Tflag_scale = str2timescale_optarg(optarg,
1967
+							   &Tflag_width);
1968
+			if (Tflag_scale < 0)
1969
+				error_opt_arg(c, lopt, optarg);
1952 1970
 			break;
1953 1971
 		case 'u':
1954 1972
 			username = optarg;

+ 6
- 2
syscall.c View File

@@ -939,8 +939,12 @@ syscall_exiting_trace(struct tcb *tcp, struct timespec *ts, int res)
939 939
 	}
940 940
 	if (Tflag) {
941 941
 		ts_sub(ts, ts, &tcp->etime);
942
-		tprintf(" <%ld.%06ld>",
943
-			(long) ts->tv_sec, (long) ts->tv_nsec / 1000);
942
+		tprintf(" <%ld", (long) ts->tv_sec);
943
+		if (Tflag_width) {
944
+			tprintf(".%0*ld",
945
+				Tflag_width, (long) ts->tv_nsec / Tflag_scale);
946
+		}
947
+		tprints(">");
944 948
 	}
945 949
 	tprints("\n");
946 950
 	dumpio(tcp);

+ 8
- 0
tests/Makefile.am View File

@@ -477,7 +477,15 @@ EXTRA_DIST = \
477 477
 	stack-fcall.h \
478 478
 	status-detached.expected \
479 479
 	strace--relative-timestamps.expected \
480
+	strace--relative-timestamps-s.expected \
481
+	strace--relative-timestamps-ms.expected \
482
+	strace--relative-timestamps-us.expected \
483
+	strace--relative-timestamps-ns.expected \
480 484
 	strace--syscall-times.expected \
485
+	strace--syscall-times-s.expected \
486
+	strace--syscall-times-ms.expected \
487
+	strace--syscall-times-us.expected \
488
+	strace--syscall-times-ns.expected \
481 489
 	strace-C.expected \
482 490
 	strace-D.expected \
483 491
 	strace-DD.expected \

+ 8
- 0
tests/gen_tests.in View File

@@ -543,7 +543,15 @@ status-successful-status	-a10 -e trace=chdir --status=successful
543 543
 status-unfinished	-a10 -e trace=all --status=unfinished
544 544
 statx	-a32 --no-abbrev --trace-path=stat.sample --trace-path=/dev/full
545 545
 strace--relative-timestamps +strace-r.test --relative-timestamps
546
+strace--relative-timestamps-s +strace-r.test --relative-timestamps=s
547
+strace--relative-timestamps-ms +strace-r.test --relative-timestamps=ms
548
+strace--relative-timestamps-us +strace-r.test --relative-timestamps=us
549
+strace--relative-timestamps-ns +strace-r.test --relative-timestamps=ns
546 550
 strace--syscall-times +strace-T.test --syscall-times
551
+strace--syscall-times-s +strace-T.test --syscall-times=s
552
+strace--syscall-times-ms +strace-T.test --syscall-times=ms
553
+strace--syscall-times-us +strace-T.test --syscall-times=us
554
+strace--syscall-times-ns +strace-T.test --syscall-times=ns
547 555
 strace--strings-in-hex	--trace=chdir --strings-in-hex --columns=18
548 556
 strace--strings-in-hex-all	--trace=chdir --strings-in-hex=all --columns=18
549 557
 strace--strings-in-hex-non-ascii	--trace=chdir --strings-in-hex=non-ascii --columns=12

+ 14
- 0
tests/options-syntax.test View File

@@ -90,6 +90,20 @@ check_h "must have PROG [ARGS] or -p PID" --interruptible=never
90 90
 check_h "must have PROG [ARGS] or -p PID" --interruptible=never_tstp
91 91
 check_h "invalid --interruptible argument: 'nevertheless'" --interruptible=nevertheless
92 92
 check_h "invalid --interruptible argument: 'nev'" --interruptible=nev
93
+check_h "must have PROG [ARGS] or -p PID" --relative-timestamps
94
+check_h "must have PROG [ARGS] or -p PID" --relative-timestamps=s
95
+check_h "must have PROG [ARGS] or -p PID" --relative-timestamps=ms
96
+check_h "must have PROG [ARGS] or -p PID" --relative-timestamps=us
97
+check_h "must have PROG [ARGS] or -p PID" --relative-timestamps=ns
98
+check_h "invalid --relative-timestamps argument: 'n'" --relative-timestamps=n
99
+check_h "invalid --relative-timestamps argument: 'ss'" --relative-timestamps=ss
100
+check_h "must have PROG [ARGS] or -p PID" --syscall-times
101
+check_h "must have PROG [ARGS] or -p PID" --syscall-times=s
102
+check_h "must have PROG [ARGS] or -p PID" --syscall-times=ms
103
+check_h "must have PROG [ARGS] or -p PID" --syscall-times=us
104
+check_h "must have PROG [ARGS] or -p PID" --syscall-times=ns
105
+check_h "invalid --syscall-times argument: 'n'" --syscall-times=n
106
+check_h "invalid --syscall-times argument: 'ss'" --syscall-times=ss
93 107
 check_h "must have PROG [ARGS] or -p PID" --strings-in-hex
94 108
 check_h "must have PROG [ARGS] or -p PID" --strings-in-hex=all
95 109
 check_h "must have PROG [ARGS] or -p PID" --strings-in-hex=non-ascii

+ 2
- 0
tests/strace--relative-timestamps-ms.expected View File

@@ -0,0 +1,2 @@
1
+[ ]{5}0\.0{3} execve\("\.\./sleep", \["\.\./sleep", "1"\], 0x[[:xdigit:]]* /\* [[:digit:]]* vars \*/\) = 0
2
+[ ]{5}(1\.[01]|0\.9)[[:digit:]]{2} \+\+\+ exited with 0 \+\+\+

+ 2
- 0
tests/strace--relative-timestamps-ns.expected View File

@@ -0,0 +1,2 @@
1
+[ ]{5}0\.0{9} execve\("\.\./sleep", \["\.\./sleep", "1"\], 0x[[:xdigit:]]* /\* [[:digit:]]* vars \*/\) = 0
2
+[ ]{5}(1\.[01]|0\.9)[[:digit:]]{8} \+\+\+ exited with 0 \+\+\+

+ 2
- 0
tests/strace--relative-timestamps-s.expected View File

@@ -0,0 +1,2 @@
1
+[ ]{5}0 execve\("\.\./sleep", \["\.\./sleep", "1"\], 0x[[:xdigit:]]* /\* [[:digit:]]* vars \*/\) = 0
2
+[ ]{5}[01] \+\+\+ exited with 0 \+\+\+

+ 2
- 0
tests/strace--relative-timestamps-us.expected View File

@@ -0,0 +1,2 @@
1
+[ ]{5}0\.0{6} execve\("\.\./sleep", \["\.\./sleep", "1"\], 0x[[:xdigit:]]* /\* [[:digit:]]* vars \*/\) = 0
2
+[ ]{5}(1\.[01]|0\.9)[[:digit:]]{5} \+\+\+ exited with 0 \+\+\+

+ 1
- 0
tests/strace--syscall-times-ms.expected View File

@@ -0,0 +1 @@
1
+nanosleep\(\{tv_sec=1, tv_nsec=0\}, NULL\) = 0 <(1\.[01]|0\.9)[[:digit:]]{2}>

+ 1
- 0
tests/strace--syscall-times-ns.expected View File

@@ -0,0 +1 @@
1
+nanosleep\(\{tv_sec=1, tv_nsec=0\}, NULL\) = 0 <(1\.[01]|0\.9)[[:digit:]]{8}>

+ 1
- 0
tests/strace--syscall-times-s.expected View File

@@ -0,0 +1 @@
1
+nanosleep\(\{tv_sec=1, tv_nsec=0\}, NULL\) = 0 <[01]>

+ 1
- 0
tests/strace--syscall-times-us.expected View File

@@ -0,0 +1 @@
1
+nanosleep\(\{tv_sec=1, tv_nsec=0\}, NULL\) = 0 <(1\.[01]|0\.9)[[:digit:]]{5}>

Loading…
Cancel
Save