Re: [PATCH/7.10 2/2] gdbserver: Fix non-stop / fork / step-over issues

[Pedro Alves <palves at redhat dot com>]

On 08/05/2015 11:19 PM, Don Breazeal wrote:

> Hi Pedro,
> I spent some time looking at this, and I found at least one of the
> culprits affecting performance.  Without going through the details of
> how I arrived at this conclusion, if I insert
> 
>     gdb_test_no_output "set sysroot /"
> 

Yeah, I had suspected that too, but discarded it as while it does
make the test go faster, it doesn't seem to explain the
seemingly progressively increasing slowdown.  See below.

> just before the call to runto_main, it cuts the wall clock time by at
> least half.  Running with just the 'detach-on-fork=off' case, it went
> from 41 secs to 20 secs on one system, and 1:21 to 0:27 and 1:50 to 0:41
> on another.  Successive runs without set sysroot resulted in
> successively decreasing run times, presumably due to filesystem caching.
> 
> I ran strace -cw to collect wall clock time (strace 4.9 and above
> support '-w' for wall time), and saw this:
> 
> Without set sysroot /:
> % time     seconds  usecs/call     calls    errors syscall^M
> ------ ----------- ----------- --------- --------- ----------------^M
>  25.90   14.620339           4   3666141       202 ptrace^M
>  25.21   14.229421          81    175135        57 select^M
>  14.42    8.139715          13    641874         7 write^M
>  10.65    6.012699           4   1397576    670469 read^M
>   7.52    4.245209           4   1205014       104 wait4^M
>   4.90    2.765111           3    847985           rt_sigprocmask^M
> 
> With set sysroot /:
> % time     seconds  usecs/call     calls    errors syscall^M
> ------ ----------- ----------- --------- --------- ----------------^M
>  32.91    6.885008         148     46665        43 select^M
>  21.59    4.516311           4   1158530       202 ptrace^M
>  11.15    2.332491          13    184229         2 write^M
>   9.07    1.897401           4    422122    203552 read^M
>   6.77    1.415918          42     34076        53 open^M
>   6.27    1.312490           3    378702       103 wait4^M
>   4.00    0.835731           3    262195           rt_sigprocmask^M
> 
> The # calls and times for each case varied from run to run, but the
> relative proportions stayed reasonably similar.  I'm not sure why the
> unmodified case has so many more calls to ptrace, but it was not an
> anomaly, I saw this in multiple runs.
> 

That's very interesting.  Something
around "strace gdb | grep ptrace | sort" might give an idea of what ptrace
calls those are.  Maybe there's low hanging fruit waiting to be picked,
regarding speeding up file transfers caused by
the "target:" sysroot default.

> Note that I used the original version of the test that you posted, not
> the update on your branch.  Also, I didn't make the set sysroot command
> conditional on running with a remote or gdbserver target, since it was
> just an experiment.


> 
> Do you think there is more to the slowdown than this?  As you said
> above, detach-on-fork 'off' is going to take longer than 'on'.  It may
> be a little while before I can get back to this, so I thought I'd share
> what I found. Let me know if you think this change will be sufficient.
> 

I do.  The test is now in master (note it was renamed.)

Try the patch below, and while

 $ make check RUNTESTFLAGS="--target_board=native-extended-gdbserver forking-threads-plus-breakpoint.exp"

is running on one terminal, in another do:

 $ tail -f testsuite/gdb.log

On my box, the first 50 or inferiors are created at roughly 3 inferiors per second,
but by the time you get to inferior 100 or so, GDB is taking over one second or
so to create each inferior.   Be inferior 200 it's taking around 3 seconds or so.
gdb is getting slower and slower.

>From d55465edd4ad75e963b1d2df201f2fd2950542bf Mon Sep 17 00:00:00 2001
From: Pedro Alves <palves@redhat.com>
Date: Thu, 6 Aug 2015 09:55:42 +0100
Subject: [PATCH] test slowdown

---
 gdb/testsuite/gdb.threads/forking-threads-plus-breakpoint.c   | 4 ++--
 gdb/testsuite/gdb.threads/forking-threads-plus-breakpoint.exp | 4 +++-
 2 files changed, 5 insertions(+), 3 deletions(-)

diff --git a/gdb/testsuite/gdb.threads/forking-threads-plus-breakpoint.c b/gdb/testsuite/gdb.threads/forking-threads-plus-breakpoint.c
index a6ff0fd..14b4240 100644
--- a/gdb/testsuite/gdb.threads/forking-threads-plus-breakpoint.c
+++ b/gdb/testsuite/gdb.threads/forking-threads-plus-breakpoint.c
@@ -33,7 +33,7 @@ pthread_t threads[NTHREADS];

 pthread_barrier_t barrier;

-#define NFORKS 10
+#define NFORKS 1000

 /* Used to create a conditional breakpoint that always fails.  */
 volatile int zero;
@@ -108,7 +108,7 @@ main (void)
   pthread_t bp_thread;

   /* Don't run forever.  */
-  alarm (180);
+  //  alarm (180);

   pthread_barrier_init (&barrier, NULL, NTHREADS + 1);

diff --git a/gdb/testsuite/gdb.threads/forking-threads-plus-breakpoint.exp b/gdb/testsuite/gdb.threads/forking-threads-plus-breakpoint.exp
index 448b734..b50e6ec 100644
--- a/gdb/testsuite/gdb.threads/forking-threads-plus-breakpoint.exp
+++ b/gdb/testsuite/gdb.threads/forking-threads-plus-breakpoint.exp
@@ -39,6 +39,7 @@ proc do_test { cond_bp_target detach_on_fork } {

     set saved_gdbflags $GDBFLAGS
     set GDBFLAGS [concat $GDBFLAGS " -ex \"set non-stop on\""]
+    set GDBFLAGS [concat $GDBFLAGS " -ex \"set sysroot /\""]
     clean_restart $binfile
     set GDBFLAGS $saved_gdbflags

@@ -71,6 +72,7 @@ proc do_test { cond_bp_target detach_on_fork } {
 	}
 	-re "Inferior $decimal \(\[^\r\n\]+\) exited normally" {
 	    incr fork_count
+	    exp_continue
 	    if {$fork_count <= 100} {
 		exp_continue
 	    } else {
@@ -105,7 +107,7 @@ proc foreach_with_prefix {var list body} {
 }

 foreach_with_prefix cond_bp_target {1 0} {
-    foreach_with_prefix detach_on_fork {"on" "off"} {
+    foreach_with_prefix detach_on_fork {"off" "off"} {
 	do_test $cond_bp_target $detach_on_fork

 	# Disable "off" for now.  The test does pass with
-- 
1.9.3