[Bug c++/94781] New: version 9.3 g++ compilation time is slower by 20% or much more (closer to 50 % sometimes) in comparison to v7.

[Bug c++/94781] New: version 9.3 g++ compilation time is slower by 20% or much more (closer to 50 % sometimes) in comparison to v7.

[ishikawa at yk dot rim.or.jp]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=94781

            Bug ID: 94781
           Summary: version 9.3 g++ compilation time is slower by 20% or
                    much more (closer to 50 % sometimes)  in comparison to
                    v7.
           Product: gcc
           Version: 9.3.0
            Status: UNCONFIRMED
          Severity: normal
          Priority: P3
         Component: c++
          Assignee: unassigned at gcc dot gnu.org
          Reporter: ishikawa at yk dot rim.or.jp
  Target Milestone: ---

Created attachment 48380
  --> https://gcc.gnu.org/bugzilla/attachment.cgi?id=48380&action=edit
-ftime-print log for V9, V8 and V7 g++ compiler compiling preprocessed
UnifiedBindings23.cpp

Thank you for maintaining the great package. I use GCC for PC and embedded
systems development.

I compile mozilla Thunderbird mail client source files using GCC to create
patches to fix the bugs of the mail client.

Lately, when I switched from GCC V7 to GCC v9, I noticed a great slowdown of
compilation time. I was hampered with other bugs which I sorted out and then 
the slow compilation time became very apparent.

I created a small awk script to check the compilation time of thunderbird
source files.
The following is what I found.

top 20  in terms of elapsed time for g++-7 compilation time.
 165.097862 :   UnifiedBindings23.cpp
 102.842003 :   UnifiedBindings1.cpp
 102.387905 :   Unified_cpp_dom_base2.cpp
 79.692992  :   Unified_cpp_layout_generic2.cpp
 78.299717  :   UnifiedBindings4.cpp
 78.239538  :   Unified_cpp_dom_ipc0.cpp
 77.236254  :   Unified_cpp_src_peerconnection0.cpp
 75.737330  :   UnifiedBindings12.cpp
 72.586055  :   Unified_cpp_dom_canvas0.cpp
 72.564836  :   UnifiedBindings10.cpp
 72.556511  :   UnifiedProtocols12.cpp
 71.924969  :   Unified_cpp_layout_painting0.cpp
 70.908968  :  
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/indexedDB/ActorsParent.cpp
 70.167488  :   UnifiedBindings3.cpp
 69.194670  :   UnifiedBindings22.cpp
 68.657080  :   UnifiedBindings21.cpp
 68.106164  :   Unified_cpp_docshell_base0.cpp
 67.494041  :   Unified_cpp_layout_base1.cpp
 65.638745  :   Unified_cpp_dom_canvas4.cpp

top 20  in terms of elapsed time for g++-9 compilation time.

Elapsed time 259.956334  :  UnifiedBindings23.cpp
Elapsed time 149.609287  :  UnifiedBindings1.cpp
Elapsed time 132.656618  :  Unified_cpp_layout_generic2.cpp
Elapsed time 125.823251  :  Unified_cpp_dom_base2.cpp
Elapsed time 113.072732  :  UnifiedBindings4.cpp
Elapsed time 107.252363  :  Unified_cpp_layout_painting0.cpp
Elapsed time 100.176409  : 
/NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/indexedDB/ActorsParent.cpp
Elapsed time 99.760067   :  UnifiedProtocols12.cpp
Elapsed time 99.549702   :  Unified_cpp_dom_canvas0.cpp
Elapsed time 99.372578   :  Unified_cpp_dom_ipc0.cpp
Elapsed time 97.947955   :  Unified_cpp_image_test_gtest0.cpp
Elapsed time 97.134518   :  UnifiedBindings21.cpp
Elapsed time 95.530481   :  UnifiedBindings3.cpp
Elapsed time 94.182883   :  UnifiedBindings12.cpp
Elapsed time 92.836375   :  Unified_cpp_src_peerconnection0.cpp
Elapsed time 92.755637   :  Unified_cpp_editor_libeditor1.cpp
Elapsed time 91.168096   :  UnifiedBindings7.cpp
Elapsed time 90.080235   :  UnifiedBindings10.cpp
Elapsed time 89.838960   :  Unified_cpp_layout_base1.cpp

You can see that the compilation time slows down by about 20 % most of the time
and 30, 50% slow down can be observed for the top two files.

I am going to show the -ftime-print output for the compilation of V9, V8, V7
g++ compiler of the same file in the attachment.
But do note that mozilla Thunderbird configure script is very clever and try to
add as many options as supported to each version of the compiler and thus,
obviously v9 compiler may be doing a bit more than other version.

Oh, yes, the slowdown has happened in v8 already (!)

In the attachment, you can see that v8 and v9 are equally slow in terms of
elapsed time.
I can see that "phase last asm" has large elapsed time for v8 and v9 in
comparison to v7. Otherwise, I could not see a clear smoking gun.

The elapsed time of v7 and V9 arey  133 and  159sec for UnifiedBindings23.cpp
(prepressed). But this difference is obviously inflated in real world workload
when the compilation is run in parallel with "make -j6" in a 7 hypercore
VirtualBox image.

In any case, a single thread run has about 26 second difference which is about
20% slower already. Any possible hint or fix for speedup is appreciated.
The compilation time slowdown hurts.: now building thunderbird in my spare time
is a one night job after modifying a few source file. I used to check the
behavior of modified binary before going to bed at least shortly and let a test
suite run.  I can't do that any more. Any checking needs to be done the next
day...

[Bug c++/94781] version 9.3 g++ compilation time is slower by 20% or much more (closer to 50 % sometimes) in comparison to v7.

[ishikawa at yk dot rim.or.jp]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=94781

--- Comment #1 from ishikawa,chiaki <ishikawa at yk dot rim.or.jp> ---
BTW, UnifiedBindings23.cpp is huge. It is about 28MB and more than 3MB
compressed (by gzip). I can send the compressed file by e-mail to anyone
interested in this issue.

As the name suggests, the source file is a clever concatenation of source files
to avoid the duplicated processing of include files in each source file by
lumping them together and run the compiler once.

I don't know if there is a time consumer that takes non-linear time of its
input source file size in g++, but there may be...
OTOH, the "phase last asm" elapsed time may explain the most of the elapsed
time slow down, and so it should be the first target of investigation.

[Bug c++/94781] version 9.3 g++ compilation time is slower by 20% or much more (closer to 50 % sometimes) in comparison to v7.

[marxin at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=94781

Martin Liška <marxin at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           Keywords|                            |compile-time-hog
     Ever confirmed|0                           |1
   Last reconfirmed|                            |2020-04-27
                 CC|                            |marxin at gcc dot gnu.org
             Status|UNCONFIRMED                 |WAITING

--- Comment #2 from Martin Liška <marxin at gcc dot gnu.org> ---
Thank you for the report. Please send the file via e.g.
https://send.firefox.com/ and we'll analyze that.

[Bug c++/94781] version 9.3 g++ compilation time is slower by 20% or much more (closer to 50 % sometimes) in comparison to v7.

[ishikawa at yk dot rim.or.jp]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=94781

--- Comment #3 from ishikawa,chiaki <ishikawa at yk dot rim.or.jp> ---
https://send.firefox.com/download/bdf77223953903fa/#WMrJbMYdsL7AXf2vXYm82g

I uploaded the file, UnifiedBindings23-v7.cpp, to the link above.

It is huge as I explained. Approximately 28MB. 

The compiler options I used for each version of the g++ compiler is in 
the attachment: https://gcc.gnu.org/bugzilla/attachment.cgi?id=48380
 -ftime-print log for V9, V8 and V7 g++ compiler compiling preprocessed
UnifiedBindings23.cpp 

Since the file was already preprocessed, -I options won't have any meaning, but
I simply copied from the original build command.

Thank you again for your attention on this matter.

[Bug c++/94781] version 9.3 g++ compilation time is slower by 20% or much more (closer to 50 % sometimes) in comparison to v7.

[rguenth at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=94781

Richard Biener <rguenth at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|WAITING                     |NEW

--- Comment #4 from Richard Biener <rguenth at gcc dot gnu.org> ---
The time-report you attached is mostly flat and I don't see anything
eye-popping pointing at a regression.  With -O0 my GCC9 is faster (well,
noise).
Confirmed for -O2:

> /usr/bin/time /space/rguenther/install/gcc-7.5/bin/g++ -S UnifiedBindings23-v7.cpp -std=gnu++1z -w -O2
112.50user 1.83system 2:01.65elapsed 93%CPU (0avgtext+0avgdata
2732664maxresident)k
1952inputs+36528outputs (6major+678054minor)pagefaults 0swaps
> /usr/bin/time /space/rguenther/install/gcc-8.4/bin/g++ -S UnifiedBindings23-v7.cpp -std=gnu++1z -w -O2
83.44user 1.27system 1:26.34elapsed 98%CPU (0avgtext+0avgdata
2789396maxresident)k
48640inputs+41088outputs (62major+687702minor)pagefaults 0swaps
> /usr/bin/time /space/rguenther/install/gcc-9.3/bin/g++ -S UnifiedBindings23-v7.cpp -std=gnu++1z -w -O2
128.28user 1.90system 2:19.51elapsed 93%CPU (0avgtext+0avgdata
2695708maxresident)k

Note how my GCC 8 build is significantly faster than GCC 7!

note that this kind of regression can easily happen because we generate
more code because of some different optimization decisions.  For example
the GCC 8 generated object is

> size UnifiedBindings23-v7.o
   text    data     bss     dec     hex filename
2502864   10136   37392 2550392  26ea78 UnifiedBindings23-v7.o

while GCC 9 generates

> size UnifiedBindings23-v7.o
   text    data     bss     dec     hex filename
2788944   16488   37392 2842824  2b60c8 UnifiedBindings23-v7.o

I realize I didn't use the full set of options you did (in particular I omitted
-g).  My tests also seem noisy (machine isn't idle, 2nd run of the GCC 9
compile
dialed in at 100s)

[Bug c++/94781] version 9.3 g++ compilation time is slower by 20% or much more (closer to 50 % sometimes) in comparison to v7.

[ishikawa at yk dot rim.or.jp]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=94781

--- Comment #5 from ishikawa,chiaki <ishikawa at yk dot rim.or.jp> ---
Thank you for your comment.

(In reply to Richard Biener from comment #4)
> The time-report you attached is mostly flat and I don't see anything
> eye-popping pointing at a regression.  With -O0 my GCC9 is faster (well,
> noise).

I was concerned with the ELAPSED time, and 
I notice that, in my testing, "phase last asm" of v9 and v8 spent a tad long
time than v7.

v9
phase last asm                     :   6.03 (  5%)   0.24 (  2%)  19.07 ( 12%) 
127204 kB (  2%)

v8
 phase last asm                     :   5.62 (  4%)   0.24 (  2%)  15.43 ( 10%)
 103215 kB (  2%)

v7
phase last asm          :   4.03 ( 3%) usr   0.16 ( 1%) sys   6.51 ( 5%) wall 
101000 kB ( 2%) ggc

v9 spends more than 12 seconds and v8 spends about 9 seconds longer than v7.
But I am not sure what this "phase last asm" does and why it spends more
ELAPSED time in v9 and v8 than in v7.


> Confirmed for -O2:
> 
> > /usr/bin/time /space/rguenther/install/gcc-7.5/bin/g++ -S UnifiedBindings23-v7.cpp -std=gnu++1z -w -O2
> 112.50user 1.83system 2:01.65elapsed 93%CPU (0avgtext+0avgdata
> 2732664maxresident)k
> 1952inputs+36528outputs (6major+678054minor)pagefaults 0swaps
> > /usr/bin/time /space/rguenther/install/gcc-8.4/bin/g++ -S UnifiedBindings23-v7.cpp -std=gnu++1z -w -O2
> 83.44user 1.27system 1:26.34elapsed 98%CPU (0avgtext+0avgdata
> 2789396maxresident)k
> 48640inputs+41088outputs (62major+687702minor)pagefaults 0swaps
> > /usr/bin/time /space/rguenther/install/gcc-9.3/bin/g++ -S UnifiedBindings23-v7.cpp -std=gnu++1z -w -O2
> 128.28user 1.90system 2:19.51elapsed 93%CPU (0avgtext+0avgdata
> 2695708maxresident)k
> 
> Note how my GCC 8 build is significantly faster than GCC 7!

Hmm... 

Did you use special flag to create your compiler?

I am using AMD Ryzen 7 1700 eight core CPU (my linux runs inside VirtualBox
image under Windows 10 and it is assigned 7 virtual CPU core.).
Maybe I need to build my own G++ compiler tuned for AMD Ryzen 7 if you used a
special compiler flags when you built your V8 and V9 compiler because the
elapsed time difference between v7 and v9 is rather smallish in comparison to
the difference I observed on my PC (module the option difference.)

> 
> note that this kind of regression can easily happen because we generate
> more code because of some different optimization decisions.  For example
> the GCC 8 generated object is
> 
> > size UnifiedBindings23-v7.o
>    text    data     bss     dec     hex filename
> 2502864   10136   37392 2550392  26ea78 UnifiedBindings23-v7.o
> 
> while GCC 9 generates
> 
> > size UnifiedBindings23-v7.o
>    text    data     bss     dec     hex filename
> 2788944   16488   37392 2842824  2b60c8 UnifiedBindings23-v7.o
> 
> I realize I didn't use the full set of options you did (in particular I
> omitted
> -g).  

The few extra options I needed to omit for v7 and v8 might explain the 
slow down. I will check for this by removing the options from v9 compilation as
well.

> My tests also seem noisy (machine isn't idle, 2nd run of the GCC 9
> compile
> dialed in at 100s)

I bet you are using very fast CPU :-)

[Bug c++/94781] version 9.3 g++ compilation time is slower by 20% or much more (closer to 50 % sometimes) in comparison to v7.

[marxin at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=94781

--- Comment #6 from Martin Liška <marxin at gcc dot gnu.org> ---
(In reply to ishikawa,chiaki from comment #3)
> https://send.firefox.com/download/bdf77223953903fa/#WMrJbMYdsL7AXf2vXYm82g
> 
> I uploaded the file, UnifiedBindings23-v7.cpp, to the link above.
> 

Sorry, the link has expired. Can you please re-upload it?

[Bug c++/94781] version 9.3 g++ compilation time is slower by 20% or much more (closer to 50 % sometimes) in comparison to v7.

[ishikawa at yk dot rim.or.jp]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=94781

--- Comment #7 from ishikawa,chiaki <ishikawa at yk dot rim.or.jp> ---
(In reply to Martin Liška from comment #6)
> (In reply to ishikawa,chiaki from comment #3)
> > https://send.firefox.com/download/bdf77223953903fa/#WMrJbMYdsL7AXf2vXYm82g
> > 
> > I uploaded the file, UnifiedBindings23-v7.cpp, to the link above.
> > 
> 
> Sorry, the link has expired. Can you please re-upload it?

Thank you for your attention on this matter.

I have re-upload it now.

https://send.firefox.com/download/496fe37075c2429f/#izMu3peg8oBwFQhg1RXuLQ


If we can make "phase last asm" elapsed time as short as v7, the total build
time of thunderbird mailer would be shorter, I suppose.

TIA

[Bug c++/94781] version 9.3 g++ compilation time is slower by 20% or much more (closer to 50 % sometimes) in comparison to v7.

[ishikawa at yk dot rim.or.jp]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=94781

--- Comment #8 from ishikawa,chiaki <ishikawa at yk dot rim.or.jp> ---
(In reply to ishikawa,chiaki from comment #7)
> (In reply to Martin Liška from comment #6)
> > (In reply to ishikawa,chiaki from comment #3)
> > > https://send.firefox.com/download/bdf77223953903fa/#WMrJbMYdsL7AXf2vXYm82g
> > > 
> > > I uploaded the file, UnifiedBindings23-v7.cpp, to the link above.
> > > 
> > 
> > Sorry, the link has expired. Can you please re-upload it?
> 
> Thank you for your attention on this matter.
> 
> I have re-upload it now.
> 
> https://send.firefox.com/download/496fe37075c2429f/#izMu3peg8oBwFQhg1RXuLQ
> 
> 
> If we can make "phase last asm" elapsed time as short as v7, the total build
> time of thunderbird mailer would be shorter, I suppose.
> 
> TIA

Sorry I did not set the expiration condition properly.:

https://send.firefox.com/download/c1e1bef0d9c360a6/#TWmiEAGr3zFfRIEDAcOsIQ

The above link should work for one week or 20 downloads, which ever comes
first.

TIA

[Bug c++/94781] version 9.3 g++ compilation time is slower by 20% or much more (closer to 50 % sometimes) in comparison to v7.

[marxin at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=94781

--- Comment #9 from Martin Liška <marxin at gcc dot gnu.org> ---
Thanks.
I've made a more permanent link here:
https://drive.google.com/file/d/1s9i_l68CR8UGhqPfq0pdgQTH26G7YEFW/view?usp=sharing

I get these numbers for g++ UnifiedBindings23-v7.cpp -c -std=c++17 -O2
-fno-checking -fmax-errors=1 -Wno-invalid-offsetof:

  7.4.0 (adafdb1e7212d53a)(06 Dec 2018 10:00): [took: 68.766s] result: OK
  7.5.0 (b2d961e7342b5ba4)(14 Nov 2019 07:40): [took: 68.694s] result: OK
  8.1.0 (406c2abec3f998e9)(02 May 2018 10:13): [took: 73.308s] result: OK
  8.2.0 (ddeb81e76461fc00)(26 Jul 2018 09:47): [took: 72.738s] result: OK
  8.3.0 (4c44b708f11eec6f)(22 Feb 2019 14:20): [took: 72.058s] result: OK
  8.4.0 (8cd3bffead2ed1d1)(04 Mar 2020 08:30): [took: 71.730s] result: OK
  9.1.0 (c8913260b0756f97)(03 May 2019 07:59): [took: 77.404s] result: OK
  9.2.0 (a0c06cc27d2146b7)(12 Aug 2019 09:38): [took: 76.432s] result: OK
  9.3.0 (4212a6a3e44f8704)(12 Mar 2020 11:08): [took: 76.636s] result: OK

current master:
  438085cc66ed5801(05 May 2020 12:24)(Michael Meissner meissner@linux.ibm.com):
[took: 78.698s] result: OK

Which is a regression of ~12% and one can't point to a single point where it
jumped rapidly. Note that we do more inlining and more optimizations in
general.

[Bug c++/94781] version 9.3 g++ compilation time is slower by 20% or much more (closer to 50 % sometimes) in comparison to v7.

[ishikawa at yk dot rim.or.jp]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=94781

--- Comment #10 from ishikawa,chiaki <ishikawa at yk dot rim.or.jp> ---
(In reply to Martin Liška from comment #9)
> Thanks.
> I've made a more permanent link here:
> https://drive.google.com/file/d/1s9i_l68CR8UGhqPfq0pdgQTH26G7YEFW/
> view?usp=sharing
> 
> I get these numbers for g++ UnifiedBindings23-v7.cpp -c -std=c++17 -O2
> -fno-checking -fmax-errors=1 -Wno-invalid-offsetof:
> 
>   7.4.0 (adafdb1e7212d53a)(06 Dec 2018 10:00): [took: 68.766s] result: OK
>   7.5.0 (b2d961e7342b5ba4)(14 Nov 2019 07:40): [took: 68.694s] result: OK
>   8.1.0 (406c2abec3f998e9)(02 May 2018 10:13): [took: 73.308s] result: OK
>   8.2.0 (ddeb81e76461fc00)(26 Jul 2018 09:47): [took: 72.738s] result: OK
>   8.3.0 (4c44b708f11eec6f)(22 Feb 2019 14:20): [took: 72.058s] result: OK
>   8.4.0 (8cd3bffead2ed1d1)(04 Mar 2020 08:30): [took: 71.730s] result: OK
>   9.1.0 (c8913260b0756f97)(03 May 2019 07:59): [took: 77.404s] result: OK
>   9.2.0 (a0c06cc27d2146b7)(12 Aug 2019 09:38): [took: 76.432s] result: OK
>   9.3.0 (4212a6a3e44f8704)(12 Mar 2020 11:08): [took: 76.636s] result: OK
> 
> current master:
>   438085cc66ed5801(05 May 2020 12:24)(Michael Meissner
> meissner@linux.ibm.com): [took: 78.698s] result: OK
> 
> Which is a regression of ~12% and one can't point to a single point where it
> jumped rapidly. Note that we do more inlining and more optimizations in
> general.

I will try to see if assigning more CPU cores to VirtualBox image I am using
locally can improve the situation. I am not sure how CPU cache is handled in
such a setting, but there may be some improvement.

Thank you again for your attention on this matter. I have been using GCC for
quite a long time on workstations and embedded systems. Thank you for making
the great package available to the wide developer community.

Chiaki

[Bug c++/94781] version 9.3 g++ compilation time is slower by 20% or much more (closer to 50 % sometimes) in comparison to v7.

[marxin at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=94781

--- Comment #11 from Martin Liška <marxin at gcc dot gnu.org> ---
> 
> I will try to see if assigning more CPU cores to VirtualBox image I am using
> locally can improve the situation. I am not sure how CPU cache is handled in
> such a setting, but there may be some improvement.

Note that our core developer Honza Hubička takes care of compile time (also
comparing to Clang), for more numbers take a look at
http://hubicka.blogspot.com/

He's been measuring Firefox build time (mainly with LTO) for a couple of years.

> 
> Thank you again for your attention on this matter. I have been using GCC for
> quite a long time on workstations and embedded systems. Thank you for making
> the great package available to the wide developer community.
> 
> Chiaki

Thank you!