From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 14295 invoked by alias); 30 Oct 2012 17:14:06 -0000 Received: (qmail 14252 invoked by uid 22791); 30 Oct 2012 17:14:04 -0000 X-SWARE-Spam-Status: No, hits=-8.0 required=5.0 tests=AWL,BAYES_00,KHOP_RCVD_UNTRUST,KHOP_THREADED,RCVD_IN_DNSWL_HI,RCVD_IN_HOSTKARMA_W,RP_MATCHES_RCVD,SPF_HELO_PASS X-Spam-Check-By: sourceware.org Received: from mx1.redhat.com (HELO mx1.redhat.com) (209.132.183.28) by sourceware.org (qpsmtpd/0.43rc1) with ESMTP; Tue, 30 Oct 2012 17:13:53 +0000 Received: from int-mx02.intmail.prod.int.phx2.redhat.com (int-mx02.intmail.prod.int.phx2.redhat.com [10.5.11.12]) by mx1.redhat.com (8.14.4/8.14.4) with ESMTP id q9UHDZ3N013724 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=OK); Tue, 30 Oct 2012 13:13:35 -0400 Received: from [127.0.0.1] (ovpn01.gateway.prod.ext.ams2.redhat.com [10.39.146.11]) by int-mx02.intmail.prod.int.phx2.redhat.com (8.13.8/8.13.8) with ESMTP id q9UHDXLW016529; Tue, 30 Oct 2012 13:13:34 -0400 Message-ID: <50900ABD.8090406@redhat.com> Date: Tue, 30 Oct 2012 17:14:00 -0000 From: Pedro Alves User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:16.0) Gecko/20121016 Thunderbird/16.0.1 MIME-Version: 1.0 To: Mathis Ahrens CC: gdb@sourceware.org Subject: Re: unexpected slowdown and cancellation point References: <5082E6A6.4050402@gmx.de> In-Reply-To: <5082E6A6.4050402@gmx.de> Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 7bit 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/msg00118.txt.bz2 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 . Thanks, -- Pedro Alves