Re: [PATCH v2 00/32] Rewrite the DWARF "partial" reader

[Tom de Vries <tdevries@suse.de>]

On 11/17/21 12:56 AM, Tom Tromey wrote:
> Tom> This triggered a fair amount of times:
> Tom> ...
> Tom> $ grep -c "has duplicate debug_info_offset 0x0, ignoring .debug_aranges" LOG
> Tom> 40
> 
> I think this is something of a latent bug, and the fix I applied is to
> skip DWZ units in this loop.  I don't think .debug_aranges can refer to
> a CU coming from the DWZ file.
> 

Ack, that makes sense to me.

> Tom> $ grep -c "DW_FORM_GNU_strp_alt used without .debug_str" LOG
> Tom> 16
> Tom> ...
> 
> I think this happens because I failed to consider DWZ files in the
> pre-reading patch.  I've applied a fix to pre-read some of the debug
> sections from this file.  I couldn't reproduce the bug myself.
> 
Both problems are gone in the latest version, thanks.

> I really appreciate the testing you've done. 

No problem :)

> I'll send v3 of the series
> once I do some more testing... I plan to regression test with a few
> different approaches (dwz, probably split DWARF too).  Meanwhile the
> unpolished version is on the 'submit/no-more-psym' branch in my github.
> 

I've done now the experiment I set out to do: I build with -O2 two
configurations:
- merge-base (git merge-base master no-more-psym)
- no-more-psym
and ran the loop over .debug files, twice (with gdb worker-threads
defaulting to 4 on my dual-core-4-thread CPU).

results merge-base:

real    2m44.899s
user    2m43.299s
sys     0m11.635s

real    2m44.451s
user    2m43.121s
sys     0m11.515s

results no-more-psym:

real    1m47.708s
user    2m0.686s
sys     0m12.500s

real    1m47.426s
user    2m0.960s
sys     0m12.089s

That's 35% real time reduction on average.

Then I picked the largest file:
/usr/lib/debug/usr/lib64/libLLVM.so.10-10.0.1-lp152.35.10.x86_64.debug,
and used just that one.

results merge-base:

real    0m35.661s
user    0m35.654s
sys     0m0.172s

real    0m35.692s
user    0m35.654s
sys     0m0.207s

results no-more-psym:

real    0m13.268s
user    0m18.084s
sys     0m0.620s

real    0m13.362s
user    0m18.181s
sys     0m0.582s

That's a 62% real time reduction.

Interesting to see that in both comparisons we have speedup because of:
- doing less (decrease in user time)
- doing things in parallel (real < user)

Indeed, switching off parallelism using "maint set worker-threads 0"
while redoing the last measurement still gives us a nice speedup:

real    0m15.498s
user    0m15.120s
sys     0m0.380s

real    0m15.540s
user    0m15.152s
sys     0m0.401s

Thanks,
- Tom