Bug 30725 - severe objdump performance regression
Summary: severe objdump performance regression
Status: UNCONFIRMED
Alias: None
Product: binutils
Classification: Unclassified
Component: binutils (show other bugs)
Version: 2.41
: P2 normal
Target Milestone: ---
Assignee: Not yet assigned to anyone
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2023-08-05 09:22 UTC by Achim
Modified: 2023-08-19 15:18 UTC (History)
3 users (show)

See Also:
Host:
Target:
Build:
Last reconfirmed:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Achim 2023-08-05 09:22:58 UTC
On Cygwin the performance of objdump has further degraded with 2.41.  The extraction of the debuginfo source files from the objects with "objdump -d -l" that was already quite slow sees an additional 2× slowdown cs. the previous version.

* cygport gcc install

2.39:  8763.607u 284.933s   29:14.38 515.7%   0+0k 0+0io 41005478pf+0w
2.40: 10122.687u 249.745s   31:29.71 548.8%   0+0k 0+0io 41382419pf+0w
2.41: 23065.196u 516.525s 1:02:40.22 627.1%   0+0k 0+0io 41348709pf+0w

The timing of install phase of gcc is dominated by the objdump invocation and there mainly by the compiler executables (d21 usually takes the longest).
Comment 1 Achim 2023-08-06 13:28:47 UTC
The preformance regression is unrelated to bug#30724.  Results for running "objdump -l -d" in various versions on the same gcc-11.4 build directory:

objdump 2.39
gcc-ar.exe        0.000u 0.000s  0:00.03   0.0%  0+0k 0+0io  3435pf+0w
gcc-nm.exe        0.000u 0.000s  0:00.03   0.0%  0+0k 0+0io  3436pf+0w
gcc-ranlib.exe    0.015u 0.000s  0:00.04  25.0%  0+0k 0+0io  3439pf+0w
gcov-dump.exe     1.046u 0.000s  0:01.05  99.0%  0+0k 0+0io  4816pf+0w
collect2.exe      1.187u 0.000s  0:01.39  84.8%  0+0k 0+0io  4875pf+0w
gcov-tool.exe     1.250u 0.015s  0:01.37  91.9%  0+0k 0+0io  4857pf+0w
gcov.exe          1.390u 0.000s  0:01.50  92.6%  0+0k 0+0io  7264pf+0w
lto-wrapper.exe   1.796u 0.015s  0:02.05  87.8%  0+0k 0+0io  6865pf+0w
gnatkr.exe        2.000u 0.030s  0:02.03 100.0%  0+0k 0+0io  8786pf+0w
gnat.exe          2.062u 0.015s  0:02.17  95.3%  0+0k 0+0io  9225pf+0w
gnatlink.exe      2.093u 0.015s  0:02.24  93.7%  0+0k 0+0io  9614pf+0w
gnatfind.exe      2.436u 0.015s  0:02.55  95.6%  0+0k 0+0io 10834pf+0w
gnatchop.exe      2.453u 0.046s  0:02.59  96.1%  0+0k 0+0io 11102pf+0w
gnatxref.exe      2.561u 0.031s  0:02.51 103.1%  0+0k 0+0io 10843pf+0w
gfortran.exe      2.671u 0.031s  0:02.60 103.8%  0+0k 0+0io  6934pf+0w
gnatclean.exe     3.250u 0.031s  0:03.62  90.6%  0+0k 0+0io 14318pf+0w
gnatprep.exe      3.296u 0.015s  0:03.49  94.5%  0+0k 0+0io 14389pf+0w
gnatname.exe      3.312u 0.015s  0:03.40  97.6%  0+0k 0+0io 13866pf+0w
gnatmake.exe      3.484u 0.046s  0:03.80  92.6%  0+0k 0+0io 16010pf+0w
gnatls.exe        3.562u 0.031s  0:03.53 101.6%  0+0k 0+0io 14998pf+0w
gnatbind.exe      5.312u 0.031s  0:05.55  96.2%  0+0k 0+0io  8087pf+0w
lto-dump.exe    569.250u 0.750s 10:09.66  93.4%  0+0k 0+0io 35970pf+0w
lto1.exe        571.968u 0.390s 10:11.07  93.6%  0+0k 0+0io 35402pf+0w
f951.exe        755.796u 0.468s 13:17.20  94.8%  0+0k 0+0io 36542pf+0w
cc1.exe         758.156u 0.515s 13:19.18  94.9%  0+0k 0+0io 36959pf+0w
gnat1.exe       810.328u 0.702s 14:12.46  95.1%  0+0k 0+0io 38941pf+0w
cc1objplus.exe  901.734u 0.812s 15:45.78  95.4%  0+0k 0+0io 39698pf+0w
cc1plus.exe     977.656u 0.578s 16:59.69  95.9%  0+0k 0+0io 39439pf+0w
d21.exe        1106.406u 0.421s 19:09.61  96.2%  0+0k 0+0io 38081pf+0w

objdump 2.40
gcc-ar.exe  	  0.000u 0.000s  0:00.03   0.0%  0+0k 0+0io  3458pf+0w
gcc-nm.exe  	  0.000u 0.000s  0:00.03   0.0%  0+0k 0+0io  3449pf+0w
gcc-ranlib.exe    0.000u 0.000s  0:00.04   0.0%  0+0k 0+0io  3454pf+0w
gcov-dump.exe     0.937u 0.000s  0:01.12  83.0%  0+0k 0+0io  4846pf+0w
collect2.exe      1.187u 0.000s  0:01.36  86.7%  0+0k 0+0io  4885pf+0w
gcov-tool.exe     1.327u 0.046s  0:01.30 104.6%  0+0k 0+0io  4870pf+0w
gcov.exe    	  1.406u 0.000s  0:01.50  93.3%  0+0k 0+0io  7256pf+0w
gnat.exe    	  1.765u 0.031s  0:02.07  86.4%  0+0k 0+0io  9176pf+0w
lto-wrapper.exe   1.781u 0.030s  0:01.84  98.3%  0+0k 0+0io  6836pf+0w
gnatkr.exe        1.953u 0.062s  0:01.95 103.0%  0+0k 0+0io  8762pf+0w
gnatlink.exe      2.109u 0.015s  0:02.11 100.0%  0+0k 0+0io  9578pf+0w
cpp.exe     	  2.218u 0.031s  0:02.53  88.5%  0+0k 0+0io  6916pf+0w
gnatfind.exe      2.296u 0.061s  0:02.50  94.0%  0+0k 0+0io 10787pf+0w
gnatchop.exe      2.358u 0.046s  0:02.57  92.9%  0+0k 0+0io 11017pf+0w
gnatxref.exe      2.359u 0.015s  0:02.45  96.3%  0+0k 0+0io 10763pf+0w
gdc.exe           2.436u 0.015s  0:02.63  92.7%  0+0k 0+0io  6905pf+0w
gfortran.exe      2.453u 0.015s  0:02.56  96.0%  0+0k 0+0io  6907pf+0w
gnatprep.exe      3.093u 0.031s  0:03.35  93.1%  0+0k 0+0io 14292pf+0w
gnatname.exe      3.125u 0.015s  0:03.17  98.7%  0+0k 0+0io 13776pf+0w
gnatclean.exe     3.218u 0.093s  0:03.46  95.3%  0+0k 0+0io 14215pf+0w
gnatmake.exe      3.406u 0.061s  0:03.72  93.0%  0+0k 0+0io 15897pf+0w
gnatls.exe        3.484u 0.030s  0:03.52  99.7%  0+0k 0+0io 14897pf+0w
gnatbind.exe      5.250u 0.030s  0:05.27 100.1%  0+0k 0+0io  8061pf+0w
lto1.exe        578.750u 0.640s 10:20.99  93.3%  0+0k 0+0io 35910pf+0w
lto-dump.exe    586.765u 0.531s 10:30.07  93.2%  0+0k 0+0io 35379pf+0w
f951.exe    	792.859u 0.500s 13:58.40  94.6%  0+0k 0+0io 36740pf+0w
cc1.exe     	842.187u 0.640s 14:50.09  94.6%  0+0k 0+0io 36959pf+0w
gnat1.exe   	865.765u 0.734s 15:15.06  94.6%  0+0k 0+0io 39099pf+0w
cc1plus.exe 	935.328u 0.531s 16:22.22  95.2%  0+0k 0+0io 39441pf+0w
cc1objplus.exe  962.718u 0.375s 16:48.90  95.4%  0+0k 0+0io 39544pf+0w
d21.exe        1116.828u 0.531s 19:24.78  95.9%  0+0k 0+0io 38061pf+0w

objdump 2.41
gcc-ar.exe  	  0.031u 0.000s  0:00.05  60.0%  0+0k 0+0io  3445pf+0w
gcc-nm.exe  	  0.031u 0.000s  0:00.06  50.0%  0+0k 0+0io  3449pf+0w
gcc-ranlib.exe    0.031u 0.000s  0:00.04  75.0%  0+0k 0+0io  3461pf+0w
gcov-dump.exe     2.031u 0.046s  0:02.17  95.3%  0+0k 0+0io  4828pf+0w
collect2.exe      2.859u 0.000s  0:03.11  91.6%  0+0k 0+0io  4888pf+0w
gcov.exe          2.906u 0.000s  0:03.06  94.7%  0+0k 0+0io  7215pf+0w
gcov-tool.exe     2.953u 0.015s  0:03.13  94.5%  0+0k 0+0io  4849pf+0w
gnatkr.exe  	  4.109u 0.000s  0:04.24  96.6%  0+0k 0+0io  8720pf+0w
gnatlink.exe      4.281u 0.046s  0:04.46  96.8%  0+0k 0+0io  9530pf+0w
gnat.exe          4.437u 0.015s  0:04.57  97.1%  0+0k 0+0io  9131pf+0w
gnatfind.exe      4.906u 0.031s  0:05.04  97.8%  0+0k 0+0io 10738pf+0w
gnatchop.exe      4.984u 0.000s  0:05.28  94.3%  0+0k 0+0io 10981pf+0w
lto-wrapper.exe   4.999u 0.000s  0:04.93 101.2%  0+0k 0+0io  6822pf+0w
gnatxref.exe      5.202u 0.062s  0:05.17 101.7%  0+0k 0+0io 10734pf+0w
gnatclean.exe     5.640u 0.062s  0:06.06  94.0%  0+0k 0+0io 14151pf+0w
gnatname.exe      5.999u 0.078s  0:06.13  98.8%  0+0k 0+0io 13717pf+0w
gnatprep.exe      6.078u 0.015s  0:06.22  97.7%  0+0k 0+0io 14228pf+0w
gnatls.exe        6.171u 0.015s  0:06.39  96.7%  0+0k 0+0io 14827pf+0w
gnatmake.exe      6.375u 0.046s  0:06.66  96.2%  0+0k 0+0io 15826pf+0w
gfortran.exe      6.562u 0.015s  0:06.78  96.9%  0+0k 0+0io  6870pf+0w
cpp.exe           6.593u 0.000s  0:06.76  97.4%  0+0k 0+0io  6881pf+0w
gdc.exe     	  6.781u 0.015s  0:06.81  99.7%  0+0k 0+0io  6871pf+0w
gnatbind.exe     13.281u 0.030s  0:13.69  97.2%  0+0k 0+0io  8032pf+0w
lto1.exe       1756.015u 1.437s 31:22.98  93.3%  0+0k 0+0io 36681pf+0w
lto-dump.exe   1769.875u 1.186s 31:40.13  93.2%  0+0k 0+0io 36039pf+0w
f951.exe       2049.375u 1.453s 36:21.40  94.0%  0+0k 0+0io 37781pf+0w
cc1.exe        2050.484u 1.265s 36:25.53  93.8%  0+0k 0+0io 37353pf+0w
gnat1.exe      2265.608u 1.468s 39:56.32  94.6%  0+0k 0+0io 39379pf+0w
d21.exe        2305.953u 1.734s 40:38.78  94.6%  0+0k 0+0io 39299pf+0w
cc1plus.exe    2317.828u 1.125s 40:50.77  94.6%  0+0k 0+0io 40303pf+0w
cc1objplus.exe 2350.812u 1.484s 41:25.30  94.6%  0+0k 0+0io 40401pf+0w
Comment 2 Nick Clifton 2023-08-15 13:22:31 UTC
Hi Achim,

  Is the Cygwin version of objdump build with debuginfod support enabled ?

  If so, does adding -wE or --dwarf=do-not-use-debuginfod to the command line
  improve the performance times ?

  I suspect that the presence of the -l option is the trigger for the slow
  down, since this means that the debug information has to be processed in
  order to determine the line numbers.  Processing DWARF is a slow business
  and it has only become slower over successive releases as bug fixing means
  that more care has to be taken to handle all the possible intricacies.

  Hence - as a workaround, could you omit the use of the -l option ?

Cheers
  Nick
Comment 3 Achim 2023-08-17 18:14:24 UTC
No, the debuginfod is not enabled and the option has no effect other than a warning about E being an unrecognized debug letter option.

Again, both extracting the line number information from the DWARF5 section and the disassembly alone doesn't produce anthing that looks unusual in terms of runtime.  Disassembly runtime scales almost lineraly with amount of I/O, DWARF5 record extraction (which must do a fair bit of interpretation of the records I assume rather seems to scale roughly linearly by number of records.

objdump 2.41-3 -d -l
gcc-ar.exe         0.031u 0.062s  0:00.08 112.5% 0+0k 0+0io  3332pf+0w
gcc-ranlib.exe     0.031u 0.000s  0:00.06  50.0% 0+0k 0+0io  3332pf+0w
gcc-nm.exe         0.046u 0.015s  0:00.07  71.4% 0+0k 0+0io  3344pf+0w
gcov-dump.exe      2.125u 0.046s  0:02.24  96.4% 0+0k 0+0io  4695pf+0w
gcov.exe           2.765u 0.000s  0:02.97  92.9% 0+0k 0+0io  7077pf+0w
collect2.exe       2.953u 0.000s  0:03.26  90.4% 0+0k 0+0io  4746pf+0w
gcov-tool.exe      3.078u 0.031s  0:03.09 100.3% 0+0k 0+0io  4714pf+0w
gnatkr.exe         4.218u 0.030s  0:04.31  98.3% 0+0k 0+0io  8583pf+0w
gnatlink.exe       4.374u 0.000s  0:04.49  97.3% 0+0k 0+0io  9394pf+0w
gnat.exe           4.406u 0.015s  0:04.54  97.1% 0+0k 0+0io  8995pf+0w
lto-wrapper.exe    4.718u 0.015s  0:04.96  95.1% 0+0k 0+0io  6682pf+0w
gnatfind.exe       4.859u 0.046s  0:05.09  96.0% 0+0k 0+0io 10604pf+0w
gnatxref.exe       4.984u 0.031s  0:05.32  94.1% 0+0k 0+0io 10596pf+0w
gnatchop.exe       5.125u 0.030s  0:05.22  98.6% 0+0k 0+0io 10846pf+0w
gnatclean.exe      5.828u 0.031s  0:06.14  95.2% 0+0k 0+0io 14015pf+0w
gnatname.exe       5.968u 0.061s  0:06.18  97.4% 0+0k 0+0io 13581pf+0w
gnatprep.exe       6.093u 0.000s  0:06.19  98.3% 0+0k 0+0io 14091pf+0w
gnatls.exe         6.187u 0.000s  0:06.39  96.7% 0+0k 0+0io 14690pf+0w
gnatmake.exe       6.281u 0.031s  0:06.76  93.3% 0+0k 0+0io 15692pf+0w
gfortran.exe       6.593u 0.015s  0:06.98  94.5% 0+0k 0+0io  6736pf+0w
cpp.exe            6.703u 0.000s  0:06.97  96.1% 0+0k 0+0io  6731pf+0w
gdc.exe            7.000u 0.030s  0:07.00 100.4% 0+0k 0+0io  6735pf+0w
gnatbind.exe      13.406u 0.000s  0:13.88  96.5% 0+0k 0+0io  7892pf+0w
lto-dump.exe    1764.452u 7.656s 32:35.54  90.6% 0+0k 0+0io 34002pf+0w
lto1.exe        1799.812u 7.406s 33:06.78  90.9% 0+0k 0+0io 34351pf+0w
f951.exe        2075.375u 6.562s 37:54.62  91.5% 0+0k 0+0io 35373pf+0w
cc1.exe         2105.890u 7.593s 38:24.45  91.7% 0+0k 0+0io 34919pf+0w
gnat1.exe       2281.406u 6.656s 41:16.20  92.4% 0+0k 0+0io 36665pf+0w
d21.exe         2320.968u 8.031s 42:03.11  92.3% 0+0k 0+0io 36393pf+0w
cc1plus.exe     2322.546u 7.812s 42:01.87  92.4% 0+0k 0+0io 37496pf+0w
cc1objplus.exe  2398.765u 7.859s 43:19.73  92.5% 0+0k 0+0io 37661pf+0w

objdump 2.41-3 -d
gcc-ar.exe         0.015u 0.000s 0:00.03  33.3%  0+0k 0+0io  3388pf+0w	   5523
gcc-ranlib.exe     0.015u 0.015s 0:00.03  66.6%  0+0k 0+0io  3387pf+0w	   5523
gcc-nm.exe         0.031u 0.015s 0:00.03 133.3%  0+0k 0+0io  3389pf+0w	   5523
gcov-dump.exe      0.484u 0.000s 0:00.60  80.0%  0+0k 0+0io  3966pf+0w	 143895
collect2.exe       0.546u 0.000s 0:00.68  79.4%  0+0k 0+0io  4012pf+0w   160080
gcov-tool.exe      0.546u 0.000s 0:00.62  87.0%  0+0k 0+0io  3997pf+0w   150923
cpp.exe            0.703u 0.015s 0:01.02  69.6%  0+0k 0+0io  4494pf+0w   241130
lto-wrapper.exe    0.796u 0.000s 0:00.89  88.7%  0+0k 0+0io  4426pf+0w   218062
gfortran.exe       0.875u 0.062s 0:00.98  94.8%  0+0k 0+0io  4487pf+0w   241676
gcov.exe           0.890u 0.015s 0:00.89 101.1%  0+0k 0+0io  4780pf+0w   218018
gdc.exe            0.921u 0.015s 0:00.98  94.8%  0+0k 0+0io  4488pf+0w   241859
gnatkr.exe         0.936u 0.000s 0:01.00  93.0%  0+0k 0+0io  4638pf+0w   244411
gnat.exe           0.953u 0.015s 0:01.03  93.2%  0+0k 0+0io  4694pf+0w   259251
gnatlink.exe       1.015u 0.030s 0:01.11  93.6%  0+0k 0+0io  4759pf+0w   274573
gnatxref.exe       1.187u 0.030s 0:01.30  93.0%  0+0k 0+0io  4866pf+0w   328849
gnatfind.exe       1.218u 0.015s 0:01.27  96.0%  0+0k 0+0io  4871pf+0w   329068
gnatchop.exe       1.437u 0.000s 0:01.33 107.5%  0+0k 0+0io  4894pf+0w   334560
gnatprep.exe       1.625u 0.015s 0:01.83  89.0%  0+0k 0+0io  5393pf+0w   467170
gnatclean.exe      1.703u 0.015s 0:01.82  93.9%  0+0k 0+0io  5389pf+0w   464192
gnatname.exe       1.718u 0.031s 0:01.76  98.8%  0+0k 0+0io  5325pf+0w   447727
gnatls.exe         1.843u 0.000s 0:01.96  93.8%  0+0k 0+0io  5473pf+0w   491418
gnatbind.exe       1.984u 0.015s 0:02.23  89.2%  0+0k 0+0io  5506pf+0w   563078
gnatmake.exe       2.046u 0.015s 0:02.09  98.0%  0+0k 0+0io  5585pf+0w   447727
lto-dump.exe      15.359u 0.015s 0:16.16  95.0%  0+0k 0+0io 30823pf+0w  6836384
lto1.exe          15.390u 0.046s 0:16.41  94.0%  0+0k 0+0io 30811pf+0w  6836218
cc1.exe           16.562u 0.078s 0:17.90  92.9%  0+0k 0+0io 31598pf+0w  7102189
d21.exe           17.265u 0.156s 0:18.38  94.7%  0+0k 0+0io 32801pf+0w  7303055
f951.exe          17.312u 0.078s 0:18.33  94.8%  0+0k 0+0io 31843pf+0w  7332302
cc1objplus.exe    18.218u 0.046s 0:19.45  93.8%  0+0k 0+0io 33912pf+0w  7739494
gnat1.exe         18.968u 0.156s 0:19.92  95.9%  0+0k 0+0io 33564pf+0w  8221327
cc1plus.exe       19.812u 0.062s 0:21.03  94.4%  0+0k 0+0io 33728pf+0w	7102189

objdump 2.41-3 -WNl
gcc-ar.exe         0.000u 0.000s 0:00.01   0.0%   0+0k 0+0io  3354pf+0w	   1257
gcc-nm.exe         0.000u 0.000s 0:00.01   0.0%   0+0k 0+0io  3342pf+0w	   1257
gcc-ranlib.exe     0.000u 0.000s 0:00.01   0.0%   0+0k 0+0io  3355pf+0w	   1257
collect2.exe       0.031u 0.000s 0:00.09  33.3%   0+0k 0+0io  3834pf+0w	  34420
gdc.exe            0.031u 0.031s 0:00.20  30.0%   0+0k 0+0io  4259pf+0w	  83717
d21.exe            0.062u 0.015s 0:00.28  25.0%   0+0k 0+0io 25490pf+0w	  85911
cc1.exe            0.078u 0.093s 0:00.27  59.2%   0+0k 0+0io 24512pf+0w	  83717
gcov.exe           0.078u 0.000s 0:00.19  36.8%   0+0k 0+0io  4587pf+0w	  85686
gcov-tool.exe      0.078u 0.000s 0:00.10  70.0%   0+0k 0+0io  3831pf+0w	  34317
gnat1.exe          0.078u 0.031s 0:00.31  32.2%   0+0k 0+0io 25521pf+0w	  89938
gfortran.exe       0.093u 0.000s 0:00.20  45.0%   0+0k 0+0io  4253pf+0w	  83717
gcov-dump.exe      0.109u 0.000s 0:00.08 125.0%   0+0k 0+0io  3796pf+0w	  34317
cpp.exe            0.125u 0.000s 0:00.19  63.1%   0+0k 0+0io  4259pf+0w	  83717
f951.exe           0.125u 0.062s 0:00.30  60.0%   0+0k 0+0io 24530pf+0w	  85911
lto1.exe           0.125u 0.046s 0:00.25  64.0%   0+0k 0+0io 23996pf+0w	  85911
lto-dump.exe       0.140u 0.046s 0:00.25  72.0%   0+0k 0+0io 24005pf+0w	  85911
lto-wrapper.exe    0.140u 0.000s 0:00.18  77.7%   0+0k 0+0io  4212pf+0w	  83717
gnat.exe           0.187u 0.000s 0:00.41  43.9%   0+0k 0+0io  4489pf+0w	 174350
gnatbind.exe       0.218u 0.000s 0:00.20 105.0%   0+0k 0+0io  4987pf+0w	  87641
gnatxref.exe       0.296u 0.031s 0:00.46  69.5%   0+0k 0+0io  4619pf+0w	 245773
gnatchop.exe       0.328u 0.015s 0:00.58  56.8%   0+0k 0+0io  4660pf+0w	 252902
gnatlink.exe       0.328u 0.000s 0:00.44  72.7%   0+0k 0+0io  4543pf+0w	 195741
gnatprep.exe       0.359u 0.015s 0:00.66  54.5%   0+0k 0+0io  5072pf+0w	 412973
gnatkr.exe         0.375u 0.000s 0:00.37 100.0%   0+0k 0+0io  4424pf+0w	 159885
gnatname.exe       0.390u 0.000s 0:00.65  60.0%   0+0k 0+0io  5010pf+0w	 387875
gnatfind.exe       0.546u 0.015s 0:00.55 100.0%   0+0k 0+0io  4619pf+0w	 245898
gnatls.exe         0.640u 0.000s 0:00.74  86.4%   0+0k 0+0io  5135pf+0w	 439869
gnatclean.exe      0.656u 0.000s 0:00.79  82.2%   0+0k 0+0io  5065pf+0w	 408163
gnatmake.exe       0.671u 0.000s 0:00.79  84.8%   0+0k 0+0io  5225pf+0w	 485037

dwarf-parse.pl (includes exec of objdump -WNl)
gcc-ar.exe         0.000u 0.045s 0:00.06  66.6%   0+0k 0+0io  7054pf+0w  LNS:   1 (  12 locations) <=> FNT:   4 (  78 locations)
gcc-ranlib.exe     0.000u 0.000s 0:00.07   0.0%   0+0k 0+0io  7054pf+0w  LNS:   1 (  12 locations) <=> FNT:   4 (  78 locations)
gcc-nm.exe         0.030u 0.030s 0:00.07  85.7%   0+0k 0+0io  7064pf+0w  LNS:   1 (  12 locations) <=> FNT:   4 (  78 locations)
collect2.exe       0.031u 0.000s 0:00.14  21.4%   0+0k 0+0io  7570pf+0w  LNS:  37 ( 306 locations) <=> FNT:  63 ( 400 locations)
cc1obj.exe         0.108u 0.015s 0:00.33  33.3%   0+0k 0+0io 28363pf+0w  LNS:  68 (5021 locations) <=> FNT: 116 ( 766 locations)
gcov-dump.exe      0.124u 0.046s 0:00.13 123.0%   0+0k 0+0io  7528pf+0w  LNS:  37 ( 305 locations) <=> FNT:  63 ( 390 locations)
gcov-tool.exe      0.155u 0.015s 0:00.13 123.0%   0+0k 0+0io  7566pf+0w  LNS:  37 ( 305 locations) <=> FNT:  63 ( 390 locations)
cpp.exe            0.186u 0.030s 0:00.25  84.0%   0+0k 0+0io  7992pf+0w  LNS:  63 (5007 locations) <=> FNT: 108 ( 751 locations)
cc1.exe            0.202u 0.062s 0:00.31  83.8%   0+0k 0+0io 28257pf+0w  LNS:  68 (5021 locations) <=> FNT: 116 ( 766 locations)
lto-dump.exe       0.218u 0.046s 0:00.35  71.4%   0+0k 0+0io 27743pf+0w  LNS:  68 (5021 locations) <=> FNT: 116 ( 766 locations)
lto-wrapper.exe    0.218u 0.030s 0:00.27  88.8%   0+0k 0+0io  7942pf+0w  LNS:  63 (5007 locations) <=> FNT: 108 ( 751 locations)
gnatbind.exe       0.233u 0.045s 0:00.27 100.0%   0+0k 0+0io  8715pf+0w  LNS:  74 (5037 locations) <=> FNT: 133 ( 777 locations)
f951.exe           0.249u 0.108s 0:00.34 100.0%   0+0k 0+0io 28267pf+0w  LNS:  68 (5021 locations) <=> FNT: 116 ( 766 locations)
lto1.exe           0.264u 0.061s 0:00.34  94.1%   0+0k 0+0io 27728pf+0w  LNS:  68 (5021 locations) <=> FNT: 116 ( 766 locations)
gcov.exe           0.265u 0.015s 0:00.26 103.8%   0+0k 0+0io  8318pf+0w  LNS:  65 (5015 locations) <=> FNT: 110 ( 749 locations)
gdc.exe            0.311u 0.015s 0:00.24 133.3%   0+0k 0+0io  7993pf+0w  LNS:  63 (5007 locations) <=> FNT: 108 ( 751 locations)
gfortran.exe       0.311u 0.015s 0:00.26 123.0%   0+0k 0+0io  7991pf+0w  LNS:  63 (5007 locations) <=> FNT: 108 ( 751 locations)
d21.exe            0.312u 0.093s 0:00.35 114.2%   0+0k 0+0io 29228pf+0w  LNS:  68 (5021 locations) <=> FNT: 116 ( 766 locations)
gnat1.exe          0.312u 0.078s 0:00.36 105.5%   0+0k 0+0io 29251pf+0w  LNS:  78 (5052 locations) <=> FNT: 140 ( 802 locations)
cc1plus.exe        0.358u 0.015s 0:00.40  90.0%   0+0k 0+0io 29830pf+0w  LNS:  72 (7067 locations) <=> FNT: 121 ( 860 locations)
cc1objplus.exe     0.421u 0.077s 0:00.39 125.6%   0+0k 0+0io 29966pf+0w  LNS:  72 (7067 locations) <=> FNT: 121 ( 860 locations)
gnatkr.exe         0.468u 0.030s 0:00.47 104.2%   0+0k 0+0io  8174pf+0w  LNS: 102 (5941 locations) <=> FNT: 184 (1352 locations)
gnatxref.exe       0.514u 0.030s 0:00.59  91.5%   0+0k 0+0io  8371pf+0w  LNS: 112 (6607 locations) <=> FNT: 210 (1796 locations)
gnat.exe           0.530u 0.076s 0:00.44 136.3%   0+0k 0+0io  8248pf+0w  LNS: 106 (6167 locations) <=> FNT: 192 (1496 locations)
gnatlink.exe       0.609u 0.015s 0:00.54 112.9%   0+0k 0+0io  8291pf+0w  LNS: 128 (6460 locations) <=> FNT: 229 (1459 locations)
gnatname.exe       0.624u 0.015s 0:00.81  77.7%   0+0k 0+0io  8765pf+0w  LNS: 136 (7349 locations) <=> FNT: 247 (2003 locations)
gnatfind.exe       0.687u 0.030s 0:00.66 107.5%   0+0k 0+0io  8372pf+0w  LNS: 113 (6614 locations) <=> FNT: 211 (1801 locations)
gnatchop.exe       0.780u 0.046s 0:00.65 126.1%   0+0k 0+0io  8405pf+0w  LNS: 110 (6582 locations) <=> FNT: 203 (1855 locations)
gnatls.exe         0.780u 0.030s 0:00.92  88.0%   0+0k 0+0io  8906pf+0w  LNS: 152 (7619 locations) <=> FNT: 264 (2176 locations)
gnatmake.exe       0.812u 0.031s 0:00.94  89.3%   0+0k 0+0io  8983pf+0w  LNS: 187 (7980 locations) <=> FNT: 326 (2417 locations)
gnatprep.exe       0.812u 0.076s 0:00.81 108.6%   0+0k 0+0io  8829pf+0w  LNS: 145 (7427 locations) <=> FNT: 257 (2098 locations)
gnatclean.exe      1.046u 0.045s 0:00.97 111.3%   0+0k 0+0io  8826pf+0w  LNS: 139 (7352 locations) <=> FNT: 247 (2033 locations)

Looking at the ratio of "objdump -dl" vs. "dwarf-parse.pl" should make it clear that size or IO alone (in whatever metric) isn't what's driving the runtime explosion.  It however looks like there's some way of arranging the information so that there's roughly a LNS pre-factor on the complexity, i.e. the program seems to do the same work again and again for each LNS (but not always).

| Objectfile      |     user |   sys |      tot |  user |   sys |   tot |  ratio |  LNS |  FNT |
|-----------------+----------+-------+----------+-------+-------+-------+--------+------+------|
| gcc-ranlib.exe  |    0.031 | 0.000 |    0.031 | 0.030 | 0.000 | 0.030 |    1.0 |   12 |   78 |
| gcc-nm.exe      |    0.046 | 0.015 |    0.061 | 0.030 | 0.030 | 0.060 |    1.0 |   12 |   78 |
| gcc-ar.exe      |    0.031 | 0.062 |    0.093 | 0.000 | 0.045 | 0.045 |    2.1 |   12 |   78 |
| gcov-dump.exe   |    2.125 | 0.046 |    2.171 | 0.124 | 0.046 | 0.170 |   12.8 |  305 |  390 |
| gcov.exe        |    2.765 | 0.000 |    2.765 | 0.265 | 0.015 | 0.280 |    9.9 | 5015 |  749 |
| collect2.exe    |    2.953 | 0.000 |    2.953 | 0.031 | 0.000 | 0.031 |   95.3 |  306 |  400 |
| gcov-tool.exe   |    3.078 | 0.031 |    3.109 | 0.155 | 0.015 | 0.170 |   18.3 |  305 |  390 |
| gnatkr.exe      |    4.218 | 0.030 |    4.248 | 0.468 | 0.030 | 0.498 |    8.5 | 5941 | 1352 |
| gnatlink.exe    |    4.374 | 0.000 |    4.374 | 0.609 | 0.015 | 0.624 |    7.0 | 6460 | 1459 |
| gnat.exe        |    4.406 | 0.015 |    4.421 | 0.530 | 0.076 | 0.606 |    7.3 | 6167 | 1496 |
| lto-wrapper.exe |    4.718 | 0.015 |    4.733 | 0.218 | 0.030 | 0.248 |   19.1 | 5007 |  751 |
| gnatfind.exe    |    4.859 | 0.046 |    4.905 | 0.687 | 0.030 | 0.717 |    6.8 | 6614 | 1801 |
| gnatxref.exe    |    4.984 | 0.031 |    5.015 | 0.514 | 0.030 | 0.544 |    9.2 | 6607 | 1796 |
| gnatchop.exe    |    5.125 | 0.030 |    5.155 | 0.780 | 0.046 | 0.826 |    6.2 | 6582 | 1855 |
| gnatclean.exe   |    5.828 | 0.031 |    5.859 | 1.046 | 0.045 | 1.091 |    5.4 | 7352 | 2033 |
| gnatname.exe    |    5.968 | 0.061 |    6.029 | 0.624 | 0.015 | 0.639 |    9.4 | 7349 | 2003 |
| gnatprep.exe    |    6.093 | 0.000 |    6.093 | 0.812 | 0.076 | 0.888 |    6.9 | 7427 | 2098 |
| gnatls.exe      |    6.187 | 0.000 |    6.187 | 0.780 | 0.030 | 0.810 |    7.6 | 7619 | 2176 |
| gnatmake.exe    |    6.281 | 0.031 |    6.312 | 0.812 | 0.031 | 0.843 |    7.5 | 7980 | 2417 |
| gfortran.exe    |    6.593 | 0.015 |    6.608 | 0.311 | 0.015 | 0.326 |   20.3 | 5007 |  751 |
| cpp.exe         |    6.703 | 0.000 |    6.703 | 0.186 | 0.030 | 0.216 |   31.0 | 5007 |  751 |
| gdc.exe         |    7.000 | 0.030 |    7.030 | 0.311 | 0.015 | 0.326 |   21.6 | 5007 |  751 |
| gnatbind.exe    |   13.406 | 0.000 |   13.406 | 0.233 | 0.045 | 0.278 |   48.2 | 5037 |  777 |
| lto-dump.exe    | 1764.452 | 7.656 | 1772.108 | 0.218 | 0.046 | 0.264 | 6712.5 | 5021 |  766 |
| lto1.exe        | 1799.812 | 7.406 | 1807.218 | 0.264 | 0.061 | 0.325 | 5560.7 | 5021 |  766 |
| f951.exe        | 2075.375 | 6.562 | 2081.937 | 0.249 | 0.108 | 0.357 | 5831.8 | 5021 |  766 |
| cc1.exe         | 2105.890 | 7.593 | 2113.483 | 0.202 | 0.062 | 0.264 | 8005.6 | 5021 |  766 |
| gnat1.exe       | 2281.406 | 6.656 | 2288.062 | 0.312 | 0.078 | 0.390 | 5866.8 | 5052 |  802 |
| d21.exe         | 2320.968 | 8.031 | 2328.999 | 0.312 | 0.093 | 0.405 | 5750.6 | 5021 |  766 |
| cc1plus.exe     | 2322.546 | 7.812 | 2330.358 | 0.358 | 0.015 | 0.373 | 6247.6 | 7067 |  860 |
| cc1objplus.exe  | 2398.765 | 7.859 | 2406.624 | 0.421 | 0.077 | 0.498 | 4832.6 | 7067 |  860 |
Comment 4 Achim 2023-08-19 15:18:26 UTC
Looking at the code in objdump, it relies on bfd to return the line number information in constant time.  This is what _should_ be happening if the debuginfo stash is actually working, but apparently it either doesn't for some files or recreation of info not in the stash takes a really long time so that O(1) becomes O(N) somehow for the line number lookup.