[PATCH] Tracepoint speed test

[PATCH] Tracepoint speed test

[Stan Shebs]

[-- Attachment #1: Type: text/plain, Size: 1025 bytes --]

This patch adds a test of tracepoint speed to the testsuite.  It's a 
little complicated, because it exercises both slow and fast tracepoints, 
it attempts to adjust its looping time to accommodate different kinds of 
hardware, and the test program is set up to be useful for interactive 
experimentation as well.  So I'm going to leave it up for review for a 
week or so, in case anybody has any questions or comments.

There are a couple things to note: 1) it adjusts loop iterations by 
simply doubling the number until the test loops run for at least a 
second each, with a couple checks to keep it from getting out of hand, 
and 2) it uses getrusage to compute CPU time.  While it seems 
appropriate to conditionalize this from configure, I note that our test 
cases never seem to use configury, instead just letting the compilation 
fail and the test return early.

Stan
stan@codesourcery.com

2011-09-08  Stan Shebs <stan@codesourcery.com>

     * gdb.trace/tspeed.exp: New file.
     * gdb.trace/tspeed.c: New file.


[-- Attachment #2: tspeed-patch-1 --]
[-- Type: text/plain, Size: 9744 bytes --]

Index: gdb.trace/tspeed.c
===================================================================
RCS file: gdb.trace/tspeed.c
diff -N gdb.trace/tspeed.c
*** /dev/null	1 Jan 1970 00:00:00 -0000
--- gdb.trace/tspeed.c	8 Sep 2011 22:11:35 -0000
***************
*** 0 ****
--- 1,184 ----
+ /* This testcase is part of GDB, the GNU debugger.
+ 
+    Copyright 2010, 2011
+    Free Software Foundation, Inc.
+ 
+    This program is free software; you can redistribute it and/or modify
+    it under the terms of the GNU General Public License as published by
+    the Free Software Foundation; either version 3 of the License, or
+    (at your option) any later version.
+ 
+    This program is distributed in the hope that it will be useful,
+    but WITHOUT ANY WARRANTY; without even the implied warranty of
+    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+    GNU General Public License for more details.
+ 
+    You should have received a copy of the GNU General Public License
+    along with this program.  If not, see <http://www.gnu.org/licenses/>.  */
+ 
+ /* This program tests tracepoint speed. It consists of two identical
+    loops, which in normal execution will run for exactly the same
+    amount of time. A tracepoint in the second loop will slow it down
+    by some amount, and then the program will report the slowdown
+    observed.  */
+ 
+ /* While primarily designed for the testsuite, it can also be used
+    for interactive testing.  */
+ 
+ #include <stdio.h>
+ #include <time.h>
+ #include <sys/time.h>
+ #include <sys/resource.h>
+ 
+ int trace_speed_test (void);
+ 
+ /* We mark these globals as volatile so the speed-measuring loops
+    don't get totally emptied out at high optimization levels.  */
+ 
+ volatile int globfoo, globfoo2, globfoo3;
+ 
+ volatile short globarr[80000];
+ 
+ int init_iters = 10 * 1000;
+ 
+ int iters;
+ 
+ int max_iters = 1000 * 1000 * 1000;
+ 
+ int numtps = 1;
+ 
+ unsigned long long now2, now3, now4, now5;
+ int total1, total2, idelta, mindelta, nsdelta;
+ int nspertp = 0;
+ 
+ /* Return CPU usage (both user and system - trap-based tracepoints use
+    a bunch of system time).  */
+ 
+ unsigned long long
+ myclock ()
+ {
+   struct timeval tm, tm2;
+   struct rusage ru;
+   getrusage (RUSAGE_SELF, &ru);
+   tm = ru.ru_utime;
+   tm2 = ru.ru_stime;
+   return (((unsigned long long) tm.tv_sec) * 1000000) + tm.tv_usec
+     + (((unsigned long long) tm2.tv_sec) * 1000000) + tm2.tv_usec;
+ }
+ 
+ int
+ main(int argc, char **argv)
+ {
+   int problem;
+ 
+   iters = init_iters;
+ 
+   while (1)
+     {
+       numtps = 1;  /* set pre-run breakpoint here */
+ 
+       /* Keep trying the speed test, with more iterations, until
+ 	 we get to a reasonable number.  */
+       while (problem = trace_speed_test())
+ 	{
+ 	  /* If iteration isn't working, give up.  */
+ 	  if (iters > max_iters)
+ 	    {
+ 	      printf ("Gone over %d iterations, giving up\n", max_iters);
+ 	      break;
+ 	    }
+ 	  if (problem < 0)
+ 	    {
+ 	      printf ("Negative times, giving up\n", max_iters);
+ 	      break;
+ 	    }
+ 
+ 	  iters *= 2;
+ 	  printf ("Doubled iterations to %d\n", iters);
+ 	}
+ 
+       printf ("Tracepoint time is %d ns\n", nspertp);
+ 
+       /* This is for the benefit of interactive testing and attaching,
+ 	 keeps the program from pegging the machine.  */
+       sleep (1);  /* set post-run breakpoint here */
+ 
+       /* Issue a little bit of output periodically, so we can see if
+ 	 program is alive or hung.  */
+       printf ("%s keeping busy, clock=%llu\n", argv[0], myclock ());
+     }
+   return 0;
+ }
+ 
+ int
+ trace_speed_test (void)
+ {
+   int i;
+ 
+   /* Overall loop run time deltas under 1 ms are likely noise and
+      should be ignored.  */
+   mindelta = 1000;
+ 
+   // The bodies of the two loops following must be identical.
+ 
+   now2 = myclock ();
+   globfoo2 = 1;
+   for (i = 0; i < iters; ++i)
+     {
+       globfoo2 *= 45;
+       globfoo2 += globfoo + globfoo3; 
+       globfoo2 *= globfoo + globfoo3; 
+       globfoo2 -= globarr[4] + globfoo3; 
+       globfoo2 *= globfoo + globfoo3; 
+       globfoo2 += globfoo + globfoo3; 
+     }
+   now3 = myclock ();
+   total1 = now3 - now2;
+ 
+   now4 = myclock ();
+   globfoo2 = 1;
+   for (i = 0; i < iters; ++i)
+     {
+       globfoo2 *= 45;
+       globfoo2 += globfoo + globfoo3;  /* set tracepoint here */
+       globfoo2 *= globfoo + globfoo3; 
+       globfoo2 -= globarr[4] + globfoo3; 
+       globfoo2 *= globfoo + globfoo3; 
+       globfoo2 += globfoo + globfoo3; 
+     }
+   now5 = myclock ();
+   total2 = now5 - now4;
+ 
+   /* Report on the test results.  */
+ 
+   nspertp = 0;
+ 
+   idelta = total2 - total1;
+ 
+   printf ("Loops took %d usec and %d usec, delta is %d usec, %d iterations\n",
+ 	  total1, total2, idelta, iters);
+ 
+   /* If the second loop seems to run faster, things are weird so give up.  */
+   if (idelta < 0)
+     return -1;
+ 
+   if (idelta > mindelta
+       /* Total test time should be between 2 and 5 seconds.  */
+       && (total1 + total2) > (2 * 1000000)
+       && (total1 + total2) < (5 * 1000000)) 
+     {
+       nsdelta = (((unsigned long long) idelta) * 1000) / iters;
+       printf ("Second loop took %d ns longer per iter than first\n", nsdelta);
+       nspertp = nsdelta / numtps;
+       printf ("%d ns per tracepoint\n", nspertp);
+       printf ("Base iteration time %d ns\n",
+ 	      ((int) (((unsigned long long) total1) * 1000) / iters));
+       printf ("Total test time %d secs\n", ((int) ((now5 - now2) / 1000000)));
+ 
+       /* Speed test ran with no problem.  */
+       return 0;
+     }
+ 
+   /* The test run was too brief, or otherwise not useful.  */
+   return 1;
+ }
Index: gdb.trace/tspeed.exp
===================================================================
RCS file: gdb.trace/tspeed.exp
diff -N gdb.trace/tspeed.exp
*** /dev/null	1 Jan 1970 00:00:00 -0000
--- gdb.trace/tspeed.exp	8 Sep 2011 22:11:35 -0000
***************
*** 0 ****
--- 1,140 ----
+ # Copyright 2011
+ # Free Software Foundation, Inc.
+ 
+ # This program is free software; you can redistribute it and/or modify
+ # it under the terms of the GNU General Public License as published by
+ # the Free Software Foundation; either version 3 of the License, or
+ # (at your option) any later version.
+ #
+ # This program is distributed in the hope that it will be useful,
+ # but WITHOUT ANY WARRANTY; without even the implied warranty of
+ # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ # GNU General Public License for more details.
+ #
+ # You should have received a copy of the GNU General Public License
+ # along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ 
+ load_lib "trace-support.exp"
+ 
+ set testfile "tspeed"
+ set srcfile ${testfile}.c
+ set executable $testfile
+ set binfile $objdir/$subdir/$executable
+ 
+ set ipalib $objdir/../gdbserver/libinproctrace.so
+ 
+ if { [gdb_compile "$srcdir/$subdir/$srcfile" $binfile \
+ 	  executable [concat {debug nowarnings c} libs=$ipalib]] != "" } {
+     untested tspeed.exp
+     return -1
+ }
+ 
+ # Typically we need a little extra time for this test.
+ set timeout 180
+ 
+ set ws "\[\r\n\t \]+"
+ set cr "\[\r\n\]+"
+ 
+ #
+ # Utility procs
+ #
+ 
+ proc prepare_for_trace_test {} {
+     global executable
+ 
+     clean_restart $executable
+ 
+     runto_main
+ 
+     set testline [gdb_get_line_number "set pre-run breakpoint here"]
+ 
+     gdb_test "break $testline" ".*" ""
+ 
+     set testline [gdb_get_line_number "set post-run breakpoint here"]
+ 
+     gdb_test "break $testline" ".*" ""
+ }
+ 
+ proc run_trace_experiment {} {
+ 
+     gdb_test "continue" \
+ 	".*Breakpoint \[0-9\]+, main .*" \
+ 	"advance to trace begin"
+ 
+     gdb_test_no_output "tstart" "start trace experiment"
+ 
+     gdb_test "continue" \
+ 	".*Breakpoint \[0-9\]+, main .*" \
+ 	"advance through tracing"
+ 
+     gdb_test "tstatus" ".*Trace .*" "check on trace status"
+ 
+     gdb_test "tstop" "" ""
+ }
+ 
+ proc gdb_slow_trace_speed_test { } {
+ 
+     gdb_delete_tracepoints
+ 
+     gdb_test "print iters = init_iters" ".* = .*";
+ 
+     set testline [gdb_get_line_number "set tracepoint here"]
+ 
+     gdb_test "trace $testline if (globfoo != 12 && globfoo2 == 45)" \
+ 	"Tracepoint \[0-9\]+ at .*" \
+ 	"set slow tracepoint"
+ 
+     # Begin the test.
+     run_trace_experiment
+ }
+ 
+ proc gdb_fast_trace_speed_test { } {
+ 
+     gdb_delete_tracepoints
+ 
+     gdb_test "print iters = init_iters" ".* = .*";
+ 
+     set run_ftrace 0
+ 
+     set testline [gdb_get_line_number "set tracepoint here"]
+ 
+     gdb_test_multiple "ftrace $testline if (globfoo != 12 && globfoo2 == 45)" \
+ 	"set conditional fast tracepoint" {
+ 	    -re "Fast tracepoint \[0-9\]+ at .*" {
+ 		pass "set conditional fast tracepoint, done"
+ 		set run_ftrace 1
+ 	    }
+ 	    -re "May not have a fast tracepoint at .*" {
+ 		pass "set conditional fast tracepoint, not allowed at line"
+ 	    }
+ 	}
+ 
+     # If the fast tracepoint couldn't be set, don't bother with the run.
+     if { $run_ftrace == 1 } then {
+ 
+ 	# Begin the test.
+ 	run_trace_experiment
+     }
+ }
+ 
+ proc gdb_trace_collection_test {} {
+ 
+     prepare_for_trace_test
+ 
+     gdb_slow_trace_speed_test
+ 
+     gdb_fast_trace_speed_test
+ }
+ 
+ clean_restart $executable
+ runto_main
+ 
+ # We generously give ourselves one "pass" if we successfully
+ # detect that this test cannot be run on this target!
+ if { ![gdb_target_supports_trace] } then {
+     pass "Current target does not support trace"
+     return 1;
+ }
+ 
+ # Body of test encased in a proc so we can return prematurely.
+ gdb_trace_collection_test

Re: [PATCH] Tracepoint speed test

[Stan Shebs]

On 9/8/11 3:35 PM, Stan Shebs wrote:
> This patch adds a test of tracepoint speed to the testsuite.

Oh yeah, one other thing to note: the test cases don't actually 
regression-test performance numbers, since they will vary randomly; the 
numbers are simply printed into the test log.  It's not even clear that 
we can test that "fast" tracepoints are faster than regular tracepoints, 
since a target is not even required to implement them with different 
mechanisms.

Stan
stan@codesourcery.com