[Bug c++/28935] New: GDB very slow stepping through LLVM compiled by Clang

[Bug c++/28935] New: GDB very slow stepping through LLVM compiled by Clang

[msebor at gmail dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=28935

            Bug ID: 28935
           Summary: GDB very slow stepping through LLVM compiled by Clang
           Product: gdb
           Version: 11.1
            Status: UNCONFIRMED
          Severity: normal
          Priority: P2
         Component: c++
          Assignee: unassigned at sourceware dot org
          Reporter: msebor at gmail dot com
  Target Milestone: ---

Stepping through C++ code compiled by Clang takes much longer than when the
code is compiled by GCC.  For example, when debugging LLVM, each step takes a
second or more.  This is with the stock GDB (11.1-5.fc35) on x86_64 running
Fedora 35.  That makes using GDB for interactive work impractical.  Using GCC
instead of Clang to compile LLVM is a viable workaround but it's not without
issues of its own.  LLDB doesn't have the same problem as GDB but because it's
not fully compatible with GDB it's not a great solution for those of us used to
GDB.

I'd like to try to help isolate and fix this problem.  Below is a test case
independent of LLVM that shows a small but measurable difference between these
two scenarios.  The output is the number of microseconds it takes the three
'next' GDB commands to step over the three C++ statements in A::f(), averaged
over 100 runs.  In GCC-compiled code the average is 5.2 microseconds, in
Clang-compiled code it's 5.5 microseconds.  If the difference grows with code
size and/or complexity it could explain the much bigger 1 second delay in LLVM.
 If this test case isn't representative of the problem can you suggest what
might be?

$ (cat t.C && g++ -ggdb -o a.gcc.out t.C && (n=0; while [ $n -lt 100 ]; do gdb
-batch -nx -ex "break A::f" -ex run -ex next -ex next -ex next -ex continue
./a.gcc.out >/dev/null; n=$((n+1)); done) 2>&1 | awk 'BEGIN { t = 0.0 } { t +=
$1 } END { print t / 100 }' )
#include <iostream>
#include <string>
#include <time.h>

struct A
{
  void f () const
    {
      std::string s = "Hello, ";
      s += "World!";
      std::cout << s << std::endl;
    }
};

A a;

int main ()
{
  struct timespec t0, t1;
  clock_gettime (CLOCK_MONOTONIC, &t0);

  a.f ();

  clock_gettime (CLOCK_MONOTONIC, &t1);
  double t = (t1.tv_sec - t0.tv_sec) * 1e3 + (t1.tv_nsec - t0.tv_nsec) / 1e3; 
  fprintf (stderr, "%f ms\n", t / 1e3);
}
5.19838

$ (clang++ -ggdb -o a.clang.out t.C && (n=0; while [ $n -lt 100 ]; do gdb
-batch -nx -ex "break A::f" -ex run -ex next -ex next -ex next -ex continue
./a.clang.out >/dev/null; n=$((n+1)); done) 2>&1 | awk 'BEGIN { n = 0.0 } { n
+= $1 } END { print n / 100 }' )
5.52529

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug c++/28935] GDB very slow stepping through LLVM compiled by Clang

[simark at simark dot ca]

https://sourceware.org/bugzilla/show_bug.cgi?id=28935

Simon Marchi <simark at simark dot ca> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |simark at simark dot ca

--- Comment #1 from Simon Marchi <simark at simark dot ca> ---
Hi Martin,

In your reproducer, are you sure that the three "next"s step the sames lines in
both cases?  I initially saw results similar to yours (not in absolute numbers,
but in relative numbers), but then noticed the steps weren't the same.

With GCC, running to "A::f" and doing 3 nexts does:

Breakpoint 1, A::f (this=0x555555559269 <a>) at t.C:7
7         void f () const
(gdb) n
9             std::string s = "Hello, ";
(gdb) n
10            s += "World!";
(gdb) n
11            std::cout << s << std::endl;
(gdb) 

With clang:

Breakpoint 1, A::f (this=0x55555555809a <a>) at t.C:9
9             std::string s = "Hello, ";
(gdb) n
10            s += "World!";
(gdb) n
11            std::cout << s << std::endl;
(gdb) n
Hello, World!
12          }

The reason GDB stops on line 7 for GCC is that in fails to notice the stack
protector in the prologue, its puts the breakpoint here:

=> 0x000055555555646d <+13>:    mov    %fs:0x28,%rax

whereas it should put it a bit further.  If I compile the GCC version with
-fno-stack-protector, then the three nexts become the same as with Clang, and
the numbers become similar.

If there is any significant different in the time it takes to "next" a line in
a binary generated with Clang vs a binary generated with GCC, the differences
in debug info are likely the culprit.  When you do "next", it's possible that
you step into a function that is in a CU that GDB needs to expand, and for some
reason the Clang-generated binary has some constructs that GDB isn't good with.

If you give some clear reproduction instructions involving LLVM, I would be
ready to give it a try.  I would need:

 - GCC version
 - Clang version
 - LLVM cmake line
 - GDB command line to reproduce one such step, that is significantly longer on
a Clang-built LLVM than with a GCC-built LLVM.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug c++/28935] GDB very slow stepping through LLVM compiled by Clang

[msebor at gmail dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=28935

--- Comment #2 from Martin Sebor <msebor at gmail dot com> ---
In both of my sessions GDB stops on the same lines and shows the same output (I
pasted the output below just in case I'm overlooking something).  But with more
testing I think the problem might be more involved than I thought.  I
reproduces in GDB in Emacs (and also in VSCode) but it's not nearly as
pronounced with GDB invoked in the terminal (there's a still a delay there but
much shorter).

If you're willing to try to reproduce it with LLVM (and ideally with Emacs)
that would be great.

I use stock GCC and LLVM (and Emacs) on Fedora 35 to build LLVM:

  gcc version 11.2.1 20211203 (Red Hat 11.2.1-7) (GCC)
  clang version 13.0.0 (Fedora 13.0.0-3.fc35)

I invoke CMake to configure LLVM for Clang and Ninja either in
/build/llvm-clang or /build/llvm-gcc, respectively, like so:

  $ CC=clang CXX=clang++ cmake -G Ninja /src/llvm/llvm -DLLVM_USE_LINKER=lld
-DLLVM_ENABLE_PROJECTS="llvm"

(or without CC and CXX to use the stock GCC), and the use Ninja to build:

  $ ninja -C /build/llvm-clang -j16 -l12 -v
or
  $ ninja -C /build/llvm-gcc -j16 -l12 -v

While LLVM is building, create an a.ll file from the C program shown below:

  $ cat a.c && clang -O1 -S -emit-llvm -Xclang -disable-llvm-passes -o a.ll a.c
  void f (void *p, void *q)
  {
    __builtin_memcpy (p, q, 4);
  }

Once LLVM is finished building, start a GDB session (either on the command
line, or better, in Emacs, with M-x gdb) with opt as the executable, set a
breakpoint in llvm::MemCpyOptPass::processMemCpy, and run the opt executable
with the options as shown and the a.ll file as an operand:

  $ gdb -nx /build/llvm-clang/bin/opt
  (gdb) break llvm::MemCpyOptPass::processMemCpy
  (gdb) run -S -basic-aa -memcpyopt a.ll
  Breakpoint 1, llvm::MemCpyOptPass::processMemCpy (this=0x994ba28,
M=0x994c2c0, BBI=...) at
/src/llvm/llvm/lib/Transforms/Scalar/MemCpyOptimizer.cpp:1375
  1375    if (M->isVolatile()) return false;
  (gdb) step
  llvm::MemIntrinsic::isVolatile (this=0x994c2c0) at
/src/llvm/llvm/include/llvm/IR/IntrinsicInst.h:953
  953     bool isVolatile() const { return !getVolatileCst()->isZero(); }

(Your line numbers will be different than mine.)  The step command and other
next or step commands in this context take about a second to complete in GDB
started in a terminal.  That's long but actually tolerable.  It takes about 3
seconds when I start the same GDB session in Emacs (or in VSCode).  When I
follow the same steps with LLVM compiled with GCC the step and next commands
complete pretty much instantaneously, both in GDB started in a terminal or
(with a slight delay) in Emacs.  In other contexts (like in main()), step and
next complete without a delay either way.

So there must be something about the Emacs GDB IDE mode that causes this
multi-second delay.  Sorry I didn't mention it to begin with.  I just noticed
it as I was preparing this reply.

$ (g++ -ggdb -o a.gcc.out t.C && (n=0; while [ $n -lt 1 ]; do gdb -batch -nx
-ex "break A::f" -ex run -ex next -ex next -ex next -ex continue ./a.gcc.out;
n=$((n+1)); done))
Breakpoint 1 at 0x402439: file t.C, line 9.
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".

Breakpoint 1, A::f (this=0x405269 <a>) at t.C:9
9             std::string s = "Hello, ";
10            s += "World!";
11            std::cout << s << std::endl;
Hello, World!
12          }
5.195867 ms
[Inferior 1 (process 279003) exited normally]

$ (clang++ -ggdb -o a.clang.out t.C && (n=0; while [ $n -lt 1 ]; do gdb -batch
-nx -ex "break A::f" -ex run -ex next -ex next -ex next -ex continue
./a.clang.out; n=$((n+1)); done))
Breakpoint 1 at 0x401314: file t.C, line 9.
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".

Breakpoint 1, A::f (this=0x4041ea <a>) at t.C:9
9             std::string s = "Hello, ";
10            s += "World!";
11            std::cout << s << std::endl;
Hello, World!
12          }
5.536339 ms
[Inferior 1 (process 279049) exited normally]

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug c++/28935] GDB very slow stepping through LLVM compiled by Clang

[simark at simark dot ca]

https://sourceware.org/bugzilla/show_bug.cgi?id=28935

--- Comment #3 from Simon Marchi <simark at simark dot ca> ---
(In reply to Martin Sebor from comment #2)
> In both of my sessions GDB stops on the same lines and shows the same output
> (I pasted the output below just in case I'm overlooking something).  But
> with more testing I think the problem might be more involved than I thought.
> I reproduces in GDB in Emacs (and also in VSCode) but it's not nearly as
> pronounced with GDB invoked in the terminal (there's a still a delay there
> but much shorter).
> 
> If you're willing to try to reproduce it with LLVM (and ideally with Emacs)
> that would be great.
> 
> I use stock GCC and LLVM (and Emacs) on Fedora 35 to build LLVM:
> 
>   gcc version 11.2.1 20211203 (Red Hat 11.2.1-7) (GCC)
>   clang version 13.0.0 (Fedora 13.0.0-3.fc35)
> 
> I invoke CMake to configure LLVM for Clang and Ninja either in
> /build/llvm-clang or /build/llvm-gcc, respectively, like so:
> 
>   $ CC=clang CXX=clang++ cmake -G Ninja /src/llvm/llvm -DLLVM_USE_LINKER=lld
> -DLLVM_ENABLE_PROJECTS="llvm"
> 
> (or without CC and CXX to use the stock GCC), and the use Ninja to build:
> 
>   $ ninja -C /build/llvm-clang -j16 -l12 -v
> or
>   $ ninja -C /build/llvm-gcc -j16 -l12 -v
> 
> While LLVM is building, create an a.ll file from the C program shown below:
> 
>   $ cat a.c && clang -O1 -S -emit-llvm -Xclang -disable-llvm-passes -o a.ll
> a.c
>   void f (void *p, void *q)
>   {
>     __builtin_memcpy (p, q, 4);
>   }
>
> Once LLVM is finished building, start a GDB session (either on the command
> line, or better, in Emacs, with M-x gdb) with opt as the executable, set a
> breakpoint in llvm::MemCpyOptPass::processMemCpy, and run the opt executable
> with the options as shown and the a.ll file as an operand:
> 
>   $ gdb -nx /build/llvm-clang/bin/opt
>   (gdb) break llvm::MemCpyOptPass::processMemCpy
>   (gdb) run -S -basic-aa -memcpyopt a.ll
>   Breakpoint 1, llvm::MemCpyOptPass::processMemCpy (this=0x994ba28,
> M=0x994c2c0, BBI=...) at
> /src/llvm/llvm/lib/Transforms/Scalar/MemCpyOptimizer.cpp:1375
>   1375	  if (M->isVolatile()) return false;
>   (gdb) step
>   llvm::MemIntrinsic::isVolatile (this=0x994c2c0) at
> /src/llvm/llvm/include/llvm/IR/IntrinsicInst.h:953
>   953	  bool isVolatile() const { return !getVolatileCst()->isZero(); }
> 
> (Your line numbers will be different than mine.)  The step command and other
> next or step commands in this context take about a second to complete in GDB
> started in a terminal.  That's long but actually tolerable.  It takes about
> 3 seconds when I start the same GDB session in Emacs (or in VSCode).  When I
> follow the same steps with LLVM compiled with GCC the step and next commands
> complete pretty much instantaneously, both in GDB started in a terminal or
> (with a slight delay) in Emacs.  In other contexts (like in main()), step
> and next complete without a delay either way.

Ok, I tried to follow this as best as I could, but I can't see a noticeable
difference between both, unfortunately.  I tested on Ubuntu 20.04 (but also gcc
11, from the Ubuntu toolchain PPA, and clang 13, from the LLVM apt repo).

I didn't test with emacs, as I have no idea how to use it.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug c++/28935] GDB very slow stepping through LLVM compiled by Clang

[ssbssa at sourceware dot org]

https://sourceware.org/bugzilla/show_bug.cgi?id=28935

Hannes Domani <ssbssa at sourceware dot org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |ssbssa at sourceware dot org

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug c++/28935] GDB very slow stepping through LLVM compiled by Clang

[tromey at sourceware dot org]

https://sourceware.org/bugzilla/show_bug.cgi?id=28935

Tom Tromey <tromey at sourceware dot org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |tromey at sourceware dot org

--- Comment #4 from Tom Tromey <tromey at sourceware dot org> ---
> It takes about 3 seconds when I start the same GDB session in Emacs (or in VSCode).

This may point the finger at MI.
One thing to try is to get a transcript of the MI traffic and
see if the problem can be isolated that way.
Maybe there's some MI command with a bug.

-- 
You are receiving this mail because:
You are on the CC list for the bug.