unexpected slowdown and cancellation point

unexpected slowdown and cancellation point

[Mathis Ahrens]

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

Hi,

I am trying to debug a multithreaded program with gdb but get unexpected 
side effects.

Test case code is attached.
Basically, main() is an endless loop that
	- creates two threads t1 & t2
	- joins t2
	- increments an iteration counter i.
t2 shall wait until t1 exists, then cancel and join t1.
t1 does nothing, but has a cleanup handler that increments a counter c.

When running without gdb, the output is as expected:
i=1, c=1, dt=0.000848
i=1001, c=1001, dt=0.095550
i=2001, c=2001, dt=0.081302
i=3001, c=3001, dt=0.089316
i=4001, c=4001, dt=0.088792
i=5001, c=5001, dt=0.086609
i=6001, c=6001, dt=0.086388
i=7001, c=7001, dt=0.090560
...

[ i: iteration, c: cancellation handler calls, dt: time ]

When running inside gdb (4.5 and master), I get:
i=1, c=1, dt=0.005421
i=1001, c=1000, dt=2.675437
i=2001, c=2000, dt=5.822094
i=3001, c=3000, dt=9.502770
i=4001, c=4000, dt=15.998418
i=5001, c=4999, dt=30.724420
i=6001, c=5999, dt=57.917127
i=7001, c=6999, dt=109.575370
i=8001, c=7999, dt=162.559419
i=9001, c=8999, dt=187.046422
...


First, c is not incremented for every iteration.
Maybe gdb inserts a cancellation point before the cleanup handler gets 
pushed ? Is this expected behavior ?

Second, the time per 1000 iterations increases rapidly.
I cannot figure a reason for that. Do you see this too ?

I am running this on ubuntu 12.04 64bit with eglibc-2.15 and gcc-4.6.3.

Thanks,
Mathis


[-- Attachment #2: test.c --]
[-- Type: text/x-csrc, Size: 1798 bytes --]

#include <sys/types.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <errno.h>
#include <pthread.h>
#include <sys/time.h>

pthread_t t1;
pthread_t t2;
pthread_mutex_t m = PTHREAD_MUTEX_INITIALIZER;
int c;

void cancellation(void *nothing) {

  if (pthread_mutex_lock(&m)) 
  {
    printf("cancellation: lock error.\n");
    exit(1);
  }

  c++;

  if (pthread_mutex_unlock(&m)) 
  {
    printf("cancellation: unlock error.\n");
    exit(1);
  }

}

void *thread1(void *nothing) {
  pthread_cleanup_push(cancellation, NULL);

  while (1) 
  {
    usleep(10);
  }

  // never reached
  pthread_cleanup_pop(NULL);
  exit(5);
  return NULL;
}

void *thread2(void *nothing) {

  // wait until t1 is created
  pthread_mutex_lock(&m);
  pthread_mutex_unlock(&m);

  if (pthread_cancel(t1) != 0) 
  {
    printf("cancel error.\n");
    exit(1);
  }

  if (pthread_join(t1, NULL)) 
  {
    printf("join t1 error.\n");
    exit(1);
  }

  pthread_exit(NULL);
  return NULL;
}

int main(void) {

  int i = 0;
  struct timeval tv1, tv2, dt;

  printf("pid: %d\n", getpid());

  gettimeofday(&tv1, NULL);

  c=0;
  while (1) {

    if (pthread_mutex_lock(&m)) 
    {
      printf("lock error.\n");
      exit(1);
    }

    if ( pthread_create(&t1, NULL, thread1, NULL)
      || pthread_create(&t2, NULL, thread2, NULL)) 
    {
      printf("create error.\n");
      exit(1);
    }

    if (pthread_mutex_unlock(&m)) 
    {
      printf("unlock error.\n");
      exit(1);
    }

    if (pthread_join(t2, NULL)) 
    {
      printf("join t2 error.\n");
      exit(1);
    }

    if (i++ % 1000 == 0) 
    {
      gettimeofday(&tv2, NULL);
      timersub( &tv2, &tv1, &dt );
      printf("i=%d, c=%d, dt=%ld.%06ld\n", i, c, dt.tv_sec, dt.tv_usec);
      tv1 = tv2;
    }

  }

  return 0;
}

Re: unexpected slowdown and cancellation point

[Pedro Alves]

On 10/20/2012 07:00 PM, Mathis Ahrens wrote:

> I am trying to debug a multithreaded program with gdb but get unexpected side effects.
> 
> Test case code is attached.
> Basically, main() is an endless loop that
>     - creates two threads t1 & t2
>     - joins t2
>     - increments an iteration counter i.
> t2 shall wait until t1 exists, then cancel and join t1.
> t1 does nothing, but has a cleanup handler that increments a counter c.
> 
> When running without gdb, the output is as expected:
> i=1, c=1, dt=0.000848
> i=1001, c=1001, dt=0.095550
> i=2001, c=2001, dt=0.081302
> i=3001, c=3001, dt=0.089316
> i=4001, c=4001, dt=0.088792
> i=5001, c=5001, dt=0.086609
> i=6001, c=6001, dt=0.086388
> i=7001, c=7001, dt=0.090560
> ...
> 
> [ i: iteration, c: cancellation handler calls, dt: time ]
> 
> When running inside gdb (4.5 and master), I get:
> i=1, c=1, dt=0.005421
> i=1001, c=1000, dt=2.675437
> i=2001, c=2000, dt=5.822094
> i=3001, c=3000, dt=9.502770
> i=4001, c=4000, dt=15.998418
> i=5001, c=4999, dt=30.724420
> i=6001, c=5999, dt=57.917127
> i=7001, c=6999, dt=109.575370
> i=8001, c=7999, dt=162.559419
> i=9001, c=8999, dt=187.046422
> ...
> 
> 
> First, c is not incremented for every iteration.
> Maybe gdb inserts a cancellation point before the cleanup handler gets pushed ? Is this expected behavior ?
> 
> Second, the time per 1000 iterations increases rapidly.
> I cannot figure a reason for that. Do you see this too ?
> 
> I am running this on ubuntu 12.04 64bit with eglibc-2.15 and gcc-4.6.3.

Thanks.  I've tried this with current mainline, and I see the same.
I suspect that the issue is GDB's inferior thread list just keeps
growing, and linear walks over the list cost more and more.
If you ctrl-c, and do "info threads; c", you'll see dt= coming back
down, as that cleans up stale thread entries.

gprof seems to confirm it:

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 66.55     39.01    39.01  1323158     0.03     0.03  find_thread_ptid
  9.35     44.49     5.48    85368     0.06     0.07  set_executing
  6.07     48.05     3.56 3310723008     0.00     0.00  ptid_equal
  3.89     50.33     2.28    42684     0.05     0.07  set_running
  3.60     52.44     2.11   149391     0.01     0.03  iterate_over_threads
  3.54     54.52     2.08 227719151     0.00     0.00  currently_stepping_or_nexting_callback
  1.57     55.44     0.92   272137     0.00     0.00  ptid_get_tid


Please file a bug report at <http://sourceware.org/bugzilla/>.

Thanks,
-- 
Pedro Alves

Re: unexpected slowdown and cancellation point

[Mathis Ahrens]

Thanks for confirming.

On 30.10.2012 10:13, Pedro Alves wrote:
>
> Please file a bug report at <http://sourceware.org/bugzilla/>.
>

http://sourceware.org/bugzilla/show_bug.cgi?id=14789

Cheers,
Mathis