From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 28920 invoked by alias); 4 Nov 2008 23:58:26 -0000 Received: (qmail 28808 invoked by uid 22791); 4 Nov 2008 23:58:25 -0000 X-Spam-Check-By: sourceware.org Received: from smtp-out.google.com (HELO smtp-out.google.com) (216.239.33.17) by sourceware.org (qpsmtpd/0.31) with ESMTP; Tue, 04 Nov 2008 23:57:49 +0000 Received: from zps78.corp.google.com (zps78.corp.google.com [172.25.146.78]) by smtp-out.google.com with ESMTP id mA4Nve84008362; Tue, 4 Nov 2008 23:57:41 GMT Received: from localhost (elbrus.corp.google.com [172.18.116.17]) by zps78.corp.google.com with ESMTP id mA4NvbDc019059; Tue, 4 Nov 2008 15:57:38 -0800 Received: by localhost (Postfix, from userid 74925) id CD4763A6B0B; Tue, 4 Nov 2008 15:57:37 -0800 (PST) To: gdb@sourceware.org Cc: ppluzhnikov@google.com, dan@codesourcery.com Subject: quadratic slowdown in 'where' command Message-Id: <20081104235737.CD4763A6B0B@localhost> Date: Tue, 04 Nov 2008 23:58:00 -0000 From: ppluzhnikov@google.com (Paul Pluzhnikov) 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: 2008-11/txt/msg00030.txt.bz2 Greetings, While debugging something else, I noticed extreme slowdown of 'where' command for a deeply recursive stack trace, and was able to reproduce it on a small example (below). AFAICT, this is related to this change: 2008-04-30 Daniel Jacobowitz * valops.c (value_fetch_lazy): Handle both memory and register lvals. Here is the timing info (doubling size quadruples time): $ time gdb -nx -ex 'set height 0' -ex 'set confirm off' -ex run -ex where -ex quit --args ./deep 2500 > /dev/null real 0m0.617s user 0m0.575s sys 0m0.034s $ time gdb -nx -ex 'set height 0' -ex 'set confirm off' -ex run -ex where -ex quit --args ./deep 5000 > /dev/null real 0m2.121s user 0m2.049s sys 0m0.048s $ time gdb -nx -ex 'set height 0' -ex 'set confirm off' -ex run -ex where -ex quit --args ./deep 10000 > /dev/null real 0m9.140s user 0m8.991s sys 0m0.077s $ time gdb -nx -ex 'set height 0' -ex 'set confirm off' -ex run -ex where -ex quit --args ./deep 20000 > /dev/null real 0m47.940s user 0m47.543s sys 0m0.182s I used current CVS head: GNU gdb (GDB) 6.8.50.20081104-cvs ... The results are also rather interesting: running 'where' by hand shows that GDB prints all levels except the last one rather fast, but then 'freezes' for a long time printing the last level. This can be seen in dramatic difference between these timings: $ time gdb64-cvs -nx -ex 'set height 0' -ex 'set confirm off' -ex run -ex 'where 10004' -ex quit --args ./deep 10000 > /dev/null real 0m0.438s user 0m0.353s sys 0m0.073s $ time gdb64-cvs -nx -ex 'set height 0' -ex 'set confirm off' -ex run -ex 'where 10005' -ex quit --args ./deep 10000 > /dev/null real 0m9.083s user 0m8.953s sys 0m0.067s I looked at "what's different WRT the last frame" in valops.c, but couldn't spot anything obvious :-( Finally, here is the test case: --- cut --- deep.c --- // Compile with GCC-4.3.1: "gcc -g deep.c -o deep -O2". // Note: -O2 is required to see the bad behavior. // // The test case itself is nonsense, crafted to prevent // GCC from optimizing too much. #include struct Node { struct Node *l; struct Node *r; int x; }; int limit; int visit (struct Node *n) { int ll, rr; if (!n) return 0; if (limit < n->x) abort (); n->x += 1; ll = visit (n->l); rr = visit (n->r); return ll + rr + n->x; } int main (int argc, char *argv[]) { struct Node n; limit = 1000; if (1 < argc) limit = atoi (argv[1]); n.x = 0; n.l = &n; n.r = &n; return visit (&n); } --- cut --- deep.c --- -- Paul Pluzhnikov