From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 23116 invoked by alias); 20 Oct 2012 18:00:15 -0000 Received: (qmail 23087 invoked by uid 22791); 20 Oct 2012 18:00:14 -0000 X-SWARE-Spam-Status: No, hits=-2.7 required=5.0 tests=AWL,BAYES_00,FREEMAIL_FROM,RCVD_IN_DNSWL_NONE,RCVD_IN_HOSTKARMA_NO,RCVD_IN_HOSTKARMA_YE X-Spam-Check-By: sourceware.org Received: from mailout-de.gmx.net (HELO mailout-de.gmx.net) (213.165.64.23) by sourceware.org (qpsmtpd/0.43rc1) with SMTP; Sat, 20 Oct 2012 18:00:09 +0000 Received: (qmail invoked by alias); 20 Oct 2012 18:00:07 -0000 Received: from d134058.adsl.hansenet.de (EHLO [192.168.24.245]) [80.171.134.58] by mail.gmx.net (mp037) with SMTP; 20 Oct 2012 20:00:07 +0200 Message-ID: <5082E6A6.4050402@gmx.de> Date: Sat, 20 Oct 2012 18:00:00 -0000 From: Mathis Ahrens User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:16.0) Gecko/20121011 Thunderbird/16.0.1 MIME-Version: 1.0 To: gdb@sourceware.org Subject: unexpected slowdown and cancellation point Content-Type: multipart/mixed; boundary="------------030403010808080104030801" X-IsSubscribed: yes Mailing-List: contact gdb-help@sourceware.org; run by ezmlm Precedence: bulk List-Id: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: gdb-owner@sourceware.org X-SW-Source: 2012-10/txt/msg00090.txt.bz2 This is a multi-part message in MIME format. --------------030403010808080104030801 Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit Content-length: 1409 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 --------------030403010808080104030801 Content-Type: text/x-csrc; name="test.c" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="test.c" Content-length: 1798 #include #include #include #include #include #include #include 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; } --------------030403010808080104030801--