[Bug gdb/29104] New: GDB very slow running LLVM opt

[Bug gdb/29104] New: GDB very slow running LLVM opt

[msebor at gmail dot com]

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

            Bug ID: 29104
           Summary: GDB very slow running LLVM opt
           Product: gdb
           Version: 11.1
            Status: UNCONFIRMED
          Severity: normal
          Priority: P2
         Component: gdb
          Assignee: unassigned at sourceware dot org
          Reporter: msebor at gmail dot com
  Target Milestone: ---

GDB takes an inordinate amount of time to start the LLVM opt program (the
optimizer process), making it exceedingly tedious to debug.

The test case below shows the size of the executable, the libraries it's linked
with, and how long it takes to run it on its own to compile a simple program (0
seconds), how long it takes to run it in LLDB (5 seconds), and how long in GDB
(26 seconds).

Importantly, while LLDB takes 5 seconds to start up and load the program and
then no time at all to run it each time, in GDB each invocation of the run
command takes the same excessive amount of time (i.e., 25 seconds on my
machine).  That makes GDB essentially unusable to debug LLVM.

I'm using GNU gdb (GDB) Fedora 11.1-5.fc35.

$ cat x.ll && time /build/llvm-gcc/bin/opt -S -instcombine x.ll && time lldb
-batch /build/llvm-gcc/bin/opt -o run -- -S -instcombine x.ll && time gdb
--batch -nx -ex "r -S -instcombine x.ll" /build/llvm-gcc/bin/opt
declare i64 @strlen(i8*)

define i64 @f(i8* %s) {
  %n = call i64 @strlen(i8* %s)
  ret i64 %n
}
; ModuleID = 'x.ll'
source_filename = "x.ll"

declare i64 @strlen(i8*)

define i64 @f(i8* %s) {
  %n = call i64 @strlen(i8* noundef nonnull dereferenceable(1) %s)
  ret i64 %n
}

real    0m0.022s
user    0m0.016s
sys     0m0.006s
(lldb) target create "/build/llvm-gcc/bin/opt"
Current executable set to '/build/llvm-gcc/bin/opt' (x86_64).
(lldb) settings set -- target.run-args  "-S" "-instcombine" "x.ll"
(lldb) run
; ModuleID = 'x.ll'
source_filename = "x.ll"

declare i64 @strlen(i8*)

define i64 @f(i8* %s) {
  %n = call i64 @strlen(i8* noundef nonnull dereferenceable(1) %s)
  ret i64 %n
}
Process 12635 exited with status = 0 (0x00000000)
Process 12635 launched: '/build/llvm-gcc/bin/opt' (x86_64)

real    0m5.394s
user    0m30.647s
sys     0m1.196s
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
; ModuleID = 'x.ll'
source_filename = "x.ll"

declare i64 @strlen(i8*)

define i64 @f(i8* %s) {
  %n = call i64 @strlen(i8* noundef nonnull dereferenceable(1) %s)
  ret i64 %n
}
[Inferior 1 (process 12720) exited normally]

real    0m25.887s
user    0m28.233s
sys     0m0.446s

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

[Bug gdb/29104] GDB very slow running LLVM opt

[tromey at sourceware dot org]

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

Tom Tromey <tromey at sourceware dot org> changed:

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

--- Comment #1 from Tom Tromey <tromey at sourceware dot org> ---
Could you "gdb -nx", then "maint time 1", and then do each step
separately?  That would help narrow down where the performance
problem lies.

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

[Bug gdb/29104] GDB very slow running LLVM opt

[msebor at gmail dot com]

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

--- Comment #2 from Martin Sebor <msebor at gmail dot com> ---
Like this?  (The 25 second delay is after the Command execution time: line is
printed and before the rest of the output.)

$ gdb -nx -q /build/llvm-gcc/bin/opt
Reading symbols from /build/llvm-gcc/bin/opt...
(gdb) maint time 1
(gdb) r -S -instcombine x.ll
2022-04-29 12:10:34.658 - command started
Starting program: /ssd/build/llvm-gcc/bin/opt -S -instcombine x.ll
2022-04-29 12:10:34.737 - command finished
Command execution time: 0.070464 (cpu), 0.078909 (wall)
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
; ModuleID = 'x.ll'
source_filename = "x.ll"

declare i64 @strlen(i8*)

define i64 @f(i8* %s) {
  %n = call i64 @strlen(i8* noundef nonnull dereferenceable(1) %s)
  ret i64 %n
}
[Inferior 1 (process 20983) exited normally]
(gdb) r -S -instcombine x.ll
2022-04-29 12:11:04.466 - command started
Starting program: /ssd/build/llvm-gcc/bin/opt -S -instcombine x.ll
2022-04-29 12:11:04.731 - command finished
Command execution time: 0.265862 (cpu), 0.265208 (wall)
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
; ModuleID = 'x.ll'
source_filename = "x.ll"

declare i64 @strlen(i8*)

define i64 @f(i8* %s) {
  %n = call i64 @strlen(i8* noundef nonnull dereferenceable(1) %s)
  ret i64 %n
}
[Inferior 1 (process 20991) exited normally]

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

[Bug gdb/29104] GDB very slow running LLVM opt

[tromey at sourceware dot org]

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

--- Comment #3 from Tom Tromey <tromey at sourceware dot org> ---
(In reply to Martin Sebor from comment #2)
> Like this?  (The 25 second delay is after the Command execution time: line
> is printed and before the rest of the output.)

Normally it's better not to pass the file name on the command line,
and use "file", in case it's symbol reading that is slow.

Anyway here that doesn't seem to be an issue.

I guess you mean the first time that is printed?

> (gdb) r -S -instcombine x.ll
> 2022-04-29 12:10:34.658 - command started
> Starting program: /ssd/build/llvm-gcc/bin/opt -S -instcombine x.ll
> 2022-04-29 12:10:34.737 - command finished
> Command execution time: 0.070464 (cpu), 0.078909 (wall)

^^^ right here.

I forgot that "run" doesn't really DTRT with "maint time 1".
There's a bug about this somewhere.

Last time I had a problem like this it was due to a bad interaction
between "gcc -g3" and an lld/mold linker problem.
If that isn't your issue then there's no better approach than
profiling to see if the problem can be discovered.  It's possible
there's just a very large CU and expanding it is slow, though 25
seconds seems a bit beyond.

Another possibility is expanding too many CUs.
"set debug dwarf-read 1" might uncover this.

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

[Bug gdb/29104] GDB very slow running LLVM opt

[msebor at gmail dot com]

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

--- Comment #4 from Martin Sebor <msebor at gmail dot com> ---
Created attachment 14086
  --> https://sourceware.org/bugzilla/attachment.cgi?id=14086&action=edit
GDB debug dwarf-read output.

Attached is the output with "set debug dwarf-read 1".  Does it narrow it down?

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

[Bug gdb/29104] GDB very slow running LLVM opt

[msebor at gmail dot com]

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

--- Comment #5 from Martin Sebor <msebor at gmail dot com> ---
(In reply to Tom Tromey from comment #3)
> 
> I guess you mean the first time that is printed?

I'm not sure I understand the question but to be clear: the 25 second delay
happens for each run command, so from each time the "Command execution time:"
line prints and until the "[Inferior 1 (process PID) exited normally]" line
appears.

I thought maybe the delay was caused by GDB reading the debug or symbol info
from the executable and the DSOs the file links with but then it should only
happen once (during the file command or the first run command), correct?  Or
does it reload/reread everything on each run?

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

[Bug gdb/29104] GDB very slow running LLVM opt

[tromey at sourceware dot org]

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

--- Comment #6 from Tom Tromey <tromey at sourceware dot org> ---
(In reply to Martin Sebor from comment #5)
> I'm not sure I understand the question but to be clear: the 25 second delay
> happens for each run command, so from each time the "Command execution
> time:" line prints and until the "[Inferior 1 (process PID) exited
> normally]" line appears.

Ok, I see.  Thank you.

> I thought maybe the delay was caused by GDB reading the debug or symbol info
> from the executable and the DSOs the file links with but then it should only
> happen once (during the file command or the first run command), correct?  Or
> does it reload/reread everything on each run?

I believe it reloads the shared libraries each time.
This is unfortunate... I've considered adding some hysteresis
here so gdb can reuse these when appropriate.

However, that won't help if the underlying libraries change a lot.
>From your run I see:

6 matches for "_hard" in buffer: dwarf-read-llvm.log
     11:[dwarf-read] dwarf2_build_psymtabs_hard: Building psymtabs of objfile
/ssd/build/llvm-gcc/bin/opt ...
     27:[dwarf-read] dwarf2_build_psymtabs_hard: Done building psymtabs of
/ssd/build/llvm-gcc/bin/opt
     34:[dwarf-read] dwarf2_build_psymtabs_hard: Building psymtabs of objfile
/lib64/ld-linux-x86-64.so.2 ...
    377:[dwarf-read] dwarf2_build_psymtabs_hard: Done building psymtabs of
/lib64/ld-linux-x86-64.so.2
    653:[dwarf-read] dwarf2_build_psymtabs_hard: Building psymtabs of objfile
/ssd/build/llvm-gcc/bin/../lib/libLLVM-15git.so ...
   2973:[dwarf-read] dwarf2_build_psymtabs_hard: Done building psymtabs of
/ssd/build/llvm-gcc/bin/../lib/libLLVM-15git.so

So I'd say that is the problem.

You might try gdb git master.  It has a new DWARF scanner that is significantly
faster.

If any of these libraries have significant debuginfo but do not change often,
another
choice is "set index-cache on".  This will cache an index after the first read.

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

[Bug gdb/29104] GDB very slow running LLVM opt

[msebor at gmail dot com]

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

--- Comment #7 from Martin Sebor <msebor at gmail dot com> ---
GDB trunk indeed solves the problem!  Thank you!

$ time ~/bin/gdb-trunk/bin/gdb --batch -nx -q -ex "r -S -instcombine x.ll"
/build/llvm-gcc/bin/opt

This GDB supports auto-downloading debuginfo from the following URLs:
  <https://debuginfod.fedoraproject.org/>
Enable debuginfod for this session? (y or [n]) [answered N; input not from
terminal]
Debuginfod has been disabled.
To make this setting permanent, add 'set debuginfod enabled off' to .gdbinit.
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
; ModuleID = 'x.ll'
source_filename = "x.ll"

declare i64 @strlen(i8*)

define i64 @f(i8* %s) {
  %n = call i64 @strlen(i8* noundef nonnull dereferenceable(1) %s)
  ret i64 %n
}
[Inferior 1 (process 133664) exited normally]

real    0m1.440s
user    0m10.096s

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

[Bug gdb/29104] GDB very slow running LLVM opt

[tromey at sourceware dot org]

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

Tom Tromey <tromey at sourceware dot org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
   Target Milestone|---                         |13.1
           Assignee|unassigned at sourceware dot org   |tromey at sourceware dot org
             Status|UNCONFIRMED                 |RESOLVED
         Resolution|---                         |FIXED

--- Comment #8 from Tom Tromey <tromey at sourceware dot org> ---
(In reply to Martin Sebor from comment #7)
> GDB trunk indeed solves the problem!  Thank you!

I'm glad to hear it.
I'm going to close this bug.

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