very different compilation times [no optimisation]

[Basile Starynkevitch]

Hello All,

While working on the MELT branch (or plugin), I noticed something
strange regarding compilation time without any optimisations.

MELT is made of auto-generated C files, which are actually monster
files. One of the biggest file is warmelt-normal-0.c from
svn cat -r 153969 \
svn://gcc.gnu.org/svn/gcc/branches/melt-branch/gcc/melt/warmelt-normal-0.c

or you could download it using
http://gcc.gnu.org/viewcvs/branches/melt-branch/gcc/melt/warmelt-normal-0.c?revision=153969&view=co

It is a file of 114882 lines [many of them blanks or comments or #line]
or 5818723 bytes. There are about 157 routines inside.

The biggest routine in this file is probably an initialization (ie
mostly sequential) routine start_module_melt. This routine has 30712
lines. It calls the initialize_module_cdata routine, which has 11926
lines and is filling a local struct cdata_st of 1589 members (each being
a structure of a few words long).

I am running a shell script -called gcc/built-melt-cc-script in MELT
build directory and similar to the gcc/melt-cc-script.proto in MELT
subversion repository. The compiler run by that script is from the
GCCMELT_CC environment variable or else gcc.

This script first generate a tiny C file like
% cat /tmp/bdat7oohwd.c
const char melt_compiled_timestamp[]="Fri Nov  6 15:36:20 2009\
warmelt-normal-1.c";
const char melt_md5[]="32fc8c51c3439811d7c840fff7f0f588\
warmelt-normal-1.c";
const char melt_csource[]="warmelt-normal-1.c";

You imagine that generating that (using date & md5sum commands) don't
take long, and compiling that is quick also.

Then script compiles the big warmelt-normal-0.c file

gcc-4.3 -Wall -fPIC -g -DIN_GCC -DHAVE_CONFIG_H -I
/usr/src/Lang/_Obj_Gcc_Melt/gcc/melt-private-build-include
warmelt-normal-0.c -c -o /tmp/dobjCZd6Ag.o

This takes most of the time, as you could guess.

At last, the script links together the two files.
gcc-4.3 -Wall -fPIC -shared -g -DIN_GCC -DHAVE_CONFIG_H -I
/usr/src/Lang/_Obj_Gcc_Melt/gcc/melt-private-build-include
/tmp/bdat7oohwd.c /tmp/dobjCZd6Ag.o -o warmelt-normal-0-gcc4.3.so

Now the compilation timing, that is the total time for running the
script (as given by the time internal utility of zsh)  Almost all of the
time is spent in compiling the warmelt-normal-0.c file. Notice that
there is no optimisation flag.

My system is a Debian/Sid/AMD64.

With the system's gcc-4.2
% gcc-4.2 -v
Using built-in specs.
Target: x86_64-linux-gnu
Configured with: ../src/configure -v
--enable-languages=c,c++,fortran,objc,obj-c++ --prefix=/usr
--enable-shared --with-system-zlib --libexecdir=/usr/lib
--without-included-gettext --enable-threads=posix --enable-nls
--with-gxx-include-dir=/usr/include/c++/4.2 --program-suffix=-4.2
--enable-clocale=gnu --enable-libstdcxx-debug --enable-objc-gc
--enable-mpfr --with-tune=generic --enable-checking=release
--build=x86_64-linux-gnu --host=x86_64-linux-gnu --target=x86_64-linux-gnu
Thread model: posix
gcc version 4.2.4 (Debian 4.2.4-6)

GCC 4.2 time:::: 63.64s user 3.46s system 98% cpu 1:07.80 total



With the system's gcc-4.3
% gcc-4.3 -v
Using built-in specs.
Target: x86_64-linux-gnu
Configured with: ../src/configure -v --with-pkgversion='Debian 4.3.4-6'
--with-bugurl=file:///usr/share/doc/gcc-4.3/README.Bugs
--enable-languages=c,c++,fortran,objc,obj-c++ --prefix=/usr
--enable-shared --enable-multiarch --enable-linker-build-id
--with-system-zlib --libexecdir=/usr/lib --without-included-gettext
--enable-threads=posix --enable-nls
--with-gxx-include-dir=/usr/include/c++/4.3 --program-suffix=-4.3
--enable-clocale=gnu --enable-libstdcxx-debug --enable-objc-gc
--enable-mpfr --with-tune=generic --enable-checking=release
--build=x86_64-linux-gnu --host=x86_64-linux-gnu --target=x86_64-linux-gnu
Thread model: posix
gcc version 4.3.4 (Debian 4.3.4-6)

GCC 4.3 time:::: 22.20s user 1.38s system 95% cpu 24.806 total


With the system's gcc-4.4
% gcc-4.4 -v
Using built-in specs.
Target: x86_64-linux-gnu
Configured with: ../src/configure -v --with-pkgversion='Debian 4.4.2-2'
--with-bugurl=file:///usr/share/doc/gcc-4.4/README.Bugs
--enable-languages=c,c++,fortran,objc,obj-c++ --prefix=/usr
--enable-shared --enable-multiarch --enable-linker-build-id
--with-system-zlib --libexecdir=/usr/lib --without-included-gettext
--enable-threads=posix --with-gxx-include-dir=/usr/include/c++/4.4
--program-suffix=-4.4 --enable-nls --enable-clocale=gnu
--enable-libstdcxx-debug --enable-objc-gc --with-arch-32=i486
--with-tune=generic --enable-checking=release --build=x86_64-linux-gnu
--host=x86_64-linux-gnu --target=x86_64-linux-gnu
Thread model: posix
gcc version 4.4.2 (Debian 4.4.2-2)

GCC 4.4 time:::: 98.79s user 4.16s system 98% cpu 1:44.92 total

Notice that gcc 4.4 is running four times slower that gcc-4.3!

With a recent gcc-trunk, with checking enabled, so the timing is not
very significant.
  % gcc-trunk -v
Using built-in specs.
COLLECT_GCC=gcc-trunk
COLLECT_LTO_WRAPPER=/usr/local/libexec/gcc-trunk/gcc/x86_64-unknown-linux-gnu/4.5.0/lto-wrapper
Target: x86_64-unknown-linux-gnu
Configured with: /usr/src/Lang/gcc-trunk-bstarynk/configure
--program-suffix=-trunk --libdir=/usr/local/lib/gcc-trunk
--libexecdir=/usr/local/libexec/gcc-trunk
--with-gxx-include-dir=/usr/local/lib/gcc-trunk/include/c++/
--disable-multilib --enable-languages=c,c++ --enable-lto
--enable-plugins --enable-maintainer-mode : (reconfigured)
/usr/src/Lang/gcc-trunk-bstarynk/configure --program-suffix=-trunk
--libdir=/usr/local/lib/gcc-trunk
--libexecdir=/usr/local/libexec/gcc-trunk
--with-gxx-include-dir=/usr/local/lib/gcc-trunk/include/c++/
--disable-multilib --enable-languages=c,c++ --enable-lto
--enable-plugins --enable-maintainer-mode : (reconfigured)
/usr/src/Lang/gcc-trunk-bstarynk/configure --program-suffix=-trunk
--libdir=/usr/local/lib/gcc-trunk
--libexecdir=/usr/local/libexec/gcc-trunk
--with-gxx-include-dir=/usr/local/lib/gcc-trunk/include/c++/
--disable-multilib --enable-lto --enable-plugins
--enable-maintainer-mode --enable-languages=c,c++,lto --no-create
--no-recursion : (reconfigured)
/usr/src/Lang/gcc-trunk-bstarynk/configure --program-suffix=-trunk
--libdir=/usr/local/lib/gcc-trunk
--libexecdir=/usr/local/libexec/gcc-trunk
--with-gxx-include-dir=/usr/local/lib/gcc-trunk/include/c++/
--disable-multilib --enable-lto --enable-plugins
--enable-maintainer-mode --enable-languages=c,c++,lto --no-create
--no-recursion : (reconfigured)
/usr/src/Lang/gcc-trunk-bstarynk/configure --program-suffix=-trunk
--libdir=/usr/local/lib/gcc-trunk
--libexecdir=/usr/local/libexec/gcc-trunk
--with-gxx-include-dir=/usr/local/lib/gcc-trunk/include/c++/
--disable-multilib --enable-lto --enable-plugins
--enable-maintainer-mode --enable-languages=c,c++,lto --no-create
--no-recursion : (reconfigured)
/usr/src/Lang/gcc-trunk-bstarynk/configure --program-suffix=-trunk
--libdir=/usr/local/lib/gcc-trunk
--libexecdir=/usr/local/libexec/gcc-trunk
--with-gxx-include-dir=/usr/local/lib/gcc-trunk/include/c++/
--disable-multilib --enable-lto --enable-plugins
--enable-maintainer-mode --enable-languages=c,c++,lto --no-create
--no-recursion : (reconfigured)
/usr/src/Lang/gcc-trunk-bstarynk/configure --program-suffix=-trunk
--libdir=/usr/local/lib/gcc-trunk
--libexecdir=/usr/local/libexec/gcc-trunk
--with-gxx-include-dir=/usr/local/lib/gcc-trunk/include/c++/
--disable-multilib --enable-lto --enable-plugins
--enable-maintainer-mode --enable-languages=c,c++,lto --no-create
--no-recursion
Thread model: posix
gcc version 4.5.0 20091105 (experimental) (GCC)


GCC-TRUNK 4.5.0 20091105 (experimental) time::: 161.37s user 3.84s
system 96% cpu 2:50.64 total


With a recent clang+llvm  [gotten by subversion less than a week ago)
% clang -v
clang version 1.1 (trunk 86234)
Target: x86_64-unknown-linux-gnu
Thread model: posix
CLANG time:::  31.27s user 4.31s system 77% cpu 45.641 total


With tinycc 0.9.25 which generates bad code:
5.71s user 0.77s system 99% cpu 6.524 total


To summarize (I actually compiled the generated warmelt-normal-1.c which
is almost the same as warmelt-normal-0.c)

time env GCCMELT_CC=gcc-trunk ./built-melt-cc-script -x
warmelt-normal-1.c
161.37s user 3.84s system 96% cpu 2:50.64 total

time env GCCMELT_CC=gcc-4.4 ./built-melt-cc-script -x
warmelt-normal-1.c
98.79s user 4.16s system 98% cpu 1:44.92 total

time env GCCMELT_CC=gcc-4.3 ./built-melt-cc-script -x
warmelt-normal-1.c
22.20s user 1.38s system 95% cpu 24.806 total

time env GCCMELT_CC=gcc-4.2 ./built-melt-cc-script -x
warmelt-normal-1.c
63.64s user 3.46s system 98% cpu 1:07.80 total

time env GCCMELT_CC=clang ./built-melt-cc-script -x
warmelt-normal-1.c
31.27s user 4.31s system 77% cpu 45.641 total

# tinycc 0.9.25 generates bad code
time env GCCMELT_CC=tcc ./built-melt-cc-script -x warmelt-normal-1.c
5.71s user 0.77s system 99% cpu 6.524 total


The preprocessed warmelt-normal-1.i has 225697 lines or 11470145 bytes.
[Should I make a bugreport with it on GCC/Bugzilla?]

I am very surprised by the difference of compilation time between 4.3 & 4.4.

Regards.

--
Basile STARYNKEVITCH         http://starynkevitch.net/Basile/
email: basile<at>starynkevitch<dot>net mobile: [phone]
8, rue de la Faiencerie, 92340 Bourg La Reine, France
*** opinions {are only mines, sont seulement les miennes} ***

[Dave Korn-6]

Basile STARYNKEVITCH wrote:

> The preprocessed warmelt-normal-1.i has 225697 lines or 11470145 bytes.
> [Should I make a bugreport with it on GCC/Bugzilla?]

  From the sound of it, it should bzip fairly well.

> I am very surprised by the difference of compilation time between 4.3 &
> 4.4.

  Me too.  I'm particularly surprised if none of the automated checkers have
spotted it, maybe there's something your code triggers that they don't
exercise, so you probably should file a PR.

    cheers,
      DaveK

[Ian Lance Taylor-3]

Basile STARYNKEVITCH <basile@...> writes:

> Notice that gcc 4.4 is running four times slower that gcc-4.3!

Use the -ftime-report option with both compilers to see where the time
is going.

Ian

[Basile Starynkevitch]

Dave Korn wrote:

> Basile STARYNKEVITCH wrote:
>
>> The preprocessed warmelt-normal-1.i has 225697 lines or 11470145 bytes.
>> [Should I make a bugreport with it on GCC/Bugzilla?]
>
>   From the sound of it, it should bzip fairly well.
>
>> I am very surprised by the difference of compilation time between 4.3 &
>> 4.4.
>
>   Me too.  I'm particularly surprised if none of the automated checkers have
> spotted it, maybe there's something your code triggers that they don't
> exercise, so you probably should file a PR.

I filled http://gcc.gnu.org/bugzilla/show_bug.cgi?id=41971 with the bzip2-ed preprocessed warmelt-normal-1.i file

Regards.

--
Basile STARYNKEVITCH         http://starynkevitch.net/Basile/
email: basile<at>starynkevitch<dot>net mobile: [phone]
8, rue de la Faiencerie, 92340 Bourg La Reine, France
*** opinions {are only mines, sont seulement les miennes} ***

[Basile Starynkevitch]

Ian Lance Taylor wrote:
> Basile STARYNKEVITCH <basile@...> writes:
>
>> Notice that gcc 4.4 is running four times slower that gcc-4.3!
>
> Use the -ftime-report option with both compilers to see where the time
> is going.

I also put the figures in the PR41971

glinka ~/tmp 16:39 % gcc-4.3 -ftime-report -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o

Execution times (seconds)
  garbage collection    :   1.02 ( 3%) usr   0.00 ( 0%) sys   1.02 ( 3%) wall       0 kB ( 0%) ggc
  cfg cleanup           :   0.56 ( 2%) usr   0.00 ( 0%) sys   0.58 ( 2%) wall      19 kB ( 0%) ggc
  trivially dead code   :   0.24 ( 1%) usr   0.00 ( 0%) sys   0.24 ( 1%) wall       0 kB ( 0%) ggc
  df live regs          :   0.47 ( 1%) usr   0.03 ( 1%) sys   0.49 ( 1%) wall       0 kB ( 0%) ggc
  df reg dead/unused notes:   0.52 ( 2%) usr   0.00 ( 0%) sys   0.52 ( 1%) wall    6838 kB ( 2%) ggc
  register information  :   0.53 ( 2%) usr   0.00 ( 0%) sys   0.54 ( 1%) wall       0 kB ( 0%) ggc
  alias analysis        :   0.27 ( 1%) usr   0.01 ( 0%) sys   0.29 ( 1%) wall    2315 kB ( 1%) ggc
  rebuild jump labels   :   0.34 ( 1%) usr   0.00 ( 0%) sys   0.34 ( 1%) wall       0 kB ( 0%) ggc
  preprocessing         :   0.96 ( 3%) usr   0.53 (16%) sys   1.75 ( 5%) wall   24801 kB ( 7%) ggc
  lexical analysis      :   0.51 ( 2%) usr   1.28 (38%) sys   1.63 ( 4%) wall       0 kB ( 0%) ggc
  parser                :   2.72 ( 8%) usr   0.76 (23%) sys   3.54 (10%) wall  100081 kB (28%) ggc
  inline heuristics     :   1.26 ( 4%) usr   0.00 ( 0%) sys   1.22 ( 3%) wall      70 kB ( 0%) ggc
  tree gimplify         :   2.23 ( 7%) usr   0.15 ( 5%) sys   2.39 ( 7%) wall   58497 kB (16%) ggc
  tree eh               :   0.21 ( 1%) usr   0.00 ( 0%) sys   0.20 ( 1%) wall       0 kB ( 0%) ggc
  tree CFG construction :   0.65 ( 2%) usr   0.06 ( 2%) sys   0.73 ( 2%) wall   37602 kB (10%) ggc
  tree CFG cleanup      :   0.42 ( 1%) usr   0.00 ( 0%) sys   0.43 ( 1%) wall       0 kB ( 0%) ggc
  dominance computation :   0.21 ( 1%) usr   0.00 ( 0%) sys   0.22 ( 1%) wall       0 kB ( 0%) ggc
  expand                :   7.09 (21%) usr   0.28 ( 8%) sys   7.36 (20%) wall   89051 kB (24%) ggc
  jump                  :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall       0 kB ( 0%) ggc
  local alloc           :   2.87 ( 9%) usr   0.02 ( 1%) sys   2.91 ( 8%) wall    3032 kB ( 1%) ggc
  global alloc          :   7.31 (22%) usr   0.12 ( 4%) sys   7.42 (20%) wall   18079 kB ( 5%) ggc
  thread pro- & epilogue:   0.66 ( 2%) usr   0.00 ( 0%) sys   0.68 ( 2%) wall     256 kB ( 0%) ggc
  final                 :   1.95 ( 6%) usr   0.08 ( 2%) sys   2.01 ( 5%) wall     360 kB ( 0%) ggc
  symout                :   0.10 ( 0%) usr   0.01 ( 0%) sys   0.09 ( 0%) wall   21440 kB ( 6%) ggc
  TOTAL                 :  33.13             3.33            36.64             363506 kB
glinka ~/tmp 16:40 % gcc-4.4 -ftime-report -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o

Execution times (seconds)
  garbage collection    :   0.11 ( 1%) usr   0.00 ( 0%) sys   0.11 ( 1%) wall       0 kB ( 0%) ggc
  callgraph construction:   0.25 ( 2%) usr   0.01 ( 0%) sys   0.28 ( 2%) wall   13570 kB ( 3%) ggc
  callgraph optimization:   0.04 ( 0%) usr   0.00 ( 0%) sys   0.04 ( 0%) wall     339 kB ( 0%) ggc
  cfg cleanup           :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.05 ( 0%) wall      24 kB ( 0%) ggc
  trivially dead code   :   0.07 ( 1%) usr   0.00 ( 0%) sys   0.10 ( 1%) wall       0 kB ( 0%) ggc
  df live regs          :   0.06 ( 1%) usr   0.00 ( 0%) sys   0.06 ( 0%) wall       0 kB ( 0%) ggc
  df reg dead/unused notes:   0.13 ( 1%) usr   0.00 ( 0%) sys   0.13 ( 1%) wall    6956 kB ( 2%) ggc
  register information  :   0.09 ( 1%) usr   0.00 ( 0%) sys   0.08 ( 1%) wall       0 kB ( 0%) ggc
  alias analysis        :   0.04 ( 0%) usr   0.00 ( 0%) sys   0.05 ( 0%) wall    2405 kB ( 1%) ggc
  rebuild jump labels   :   0.05 ( 0%) usr   0.01 ( 0%) sys   0.06 ( 0%) wall       0 kB ( 0%) ggc
  preprocessing         :   0.98 ( 9%) usr   0.61 (20%) sys   1.76 (13%) wall   25440 kB ( 6%) ggc
  lexical analysis      :   0.41 ( 4%) usr   1.15 (38%) sys   1.61 (12%) wall       0 kB ( 0%) ggc
  parser                :   1.69 (16%) usr   0.83 (27%) sys   2.37 (17%) wall   71977 kB (17%) ggc
  inline heuristics     :   0.02 ( 0%) usr   0.00 ( 0%) sys   0.04 ( 0%) wall       0 kB ( 0%) ggc
  tree gimplify         :   1.46 (13%) usr   0.14 ( 5%) sys   1.56 (11%) wall   88334 kB (21%) ggc
  tree eh               :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall       0 kB ( 0%) ggc
  tree CFG construction :   0.05 ( 0%) usr   0.00 ( 0%) sys   0.05 ( 0%) wall   13199 kB ( 3%) ggc
  tree CFG cleanup      :   0.05 ( 0%) usr   0.00 ( 0%) sys   0.08 ( 1%) wall       0 kB ( 0%) ggc
  tree find ref. vars   :   0.05 ( 0%) usr   0.01 ( 0%) sys   0.05 ( 0%) wall    9130 kB ( 2%) ggc
  tree PHI insertion    :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) wall     189 kB ( 0%) ggc
  tree SSA rewrite      :   0.04 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall   11835 kB ( 3%) ggc
  tree SSA other        :   0.06 ( 1%) usr   0.02 ( 1%) sys   0.12 ( 1%) wall     193 kB ( 0%) ggc
  tree operand scan     :   0.07 ( 1%) usr   0.03 ( 1%) sys   0.05 ( 0%) wall    7012 kB ( 2%) ggc
  tree SSA to normal    :   0.08 ( 1%) usr   0.00 ( 0%) sys   0.09 ( 1%) wall     448 kB ( 0%) ggc
  dominance computation :   0.05 ( 0%) usr   0.01 ( 0%) sys   0.01 ( 0%) wall       0 kB ( 0%) ggc
  expand                :   1.80 (17%) usr   0.06 ( 2%) sys   1.65 (12%) wall  131397 kB (31%) ggc
  varconst              :   0.00 ( 0%) usr   0.01 ( 0%) sys   0.00 ( 0%) wall      24 kB ( 0%) ggc
  integrated RA         :   1.42 (13%) usr   0.01 ( 0%) sys   1.54 (11%) wall    3144 kB ( 1%) ggc
  reload                :   0.94 ( 9%) usr   0.01 ( 0%) sys   0.93 ( 7%) wall   17800 kB ( 4%) ggc
  thread pro- & epilogue:   0.13 ( 1%) usr   0.00 ( 0%) sys   0.15 ( 1%) wall     342 kB ( 0%) ggc
  final                 :   0.40 ( 4%) usr   0.01 ( 0%) sys   0.47 ( 3%) wall    2487 kB ( 1%) ggc
  symout                :   0.20 ( 2%) usr   0.02 ( 1%) sys   0.22 ( 2%) wall   22415 kB ( 5%) ggc
  TOTAL                 :  10.83             3.03            13.90             429820 kB
glinka ~/tmp 16:41 %


Regards

--
Basile STARYNKEVITCH         http://starynkevitch.net/Basile/
email: basile<at>starynkevitch<dot>net mobile: [phone]
8, rue de la Faiencerie, 92340 Bourg La Reine, France
*** opinions {are only mines, sont seulement les miennes} ***

[Ian Lance Taylor-3]

Dave Korn <dave.korn.cygwin@...> writes:

> Basile STARYNKEVITCH wrote:
>
>>>> Notice that gcc 4.4 is running four times slower that gcc-4.3!
>
>> glinka ~/tmp 16:39 % gcc-4.3 -ftime-report -O0 -g -fPIC
>> warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o
>>
>> Execution times (seconds)
>>  TOTAL                 :  33.13             3.33          
>> 36.64             363506 kB
>
>> glinka ~/tmp 16:40 % gcc-4.4 -ftime-report -O0 -g -fPIC
>> warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o
>>  TOTAL                 :  10.83             3.03          
>> 13.90             429820 kB
>> glinka ~/tmp 16:41 %
>
>   Wait, what? :-P
>
>
>   Assuming you got those results swapped round, I see it's mostly expand and
> global alloc.  Side effect of IRA on functions with loooong unbroken sequences
> of initialisations maybe?

He  didn't swap them--you can tell by the presence of "integrated RA"
rather than "global".

Basile, you posted the time for the wrong file, or you got something
else wrong.

Ian

[Dave Korn-6]

Basile STARYNKEVITCH wrote:

>>> Notice that gcc 4.4 is running four times slower that gcc-4.3!

> glinka ~/tmp 16:39 % gcc-4.3 -ftime-report -O0 -g -fPIC
> warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o
>
> Execution times (seconds)
>  TOTAL                 :  33.13             3.33          
> 36.64             363506 kB

> glinka ~/tmp 16:40 % gcc-4.4 -ftime-report -O0 -g -fPIC
> warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o
>  TOTAL                 :  10.83             3.03          
> 13.90             429820 kB
> glinka ~/tmp 16:41 %

  Wait, what? :-P


  Assuming you got those results swapped round, I see it's mostly expand and
global alloc.  Side effect of IRA on functions with loooong unbroken sequences
of initialisations maybe?

    cheers,
      DaveK

[Basile Starynkevitch]

Basile STARYNKEVITCH wrote:
> Ian Lance Taylor wrote:
>> Basile STARYNKEVITCH <basile@...> writes:
>>
>>> Notice that gcc 4.4 is running four times slower that gcc-4.3!
>>
>> Use the -ftime-report option with both compilers to see where the time
>> is going.
>
> I also put the figures in the PR41971

Strangely, the timing varies widely from one run to another with the same compiler.
glinka ~/tmp 16:41 % time gcc-4.4  -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o
gcc-4.4 -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o  32.44s user 1.75s system 99% cpu 34.472 total
glinka ~/tmp 16:56 % time gcc-4.4  -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o
gcc-4.4 -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o  14.43s user 0.64s system 99% cpu 15.125 total
glinka ~/tmp 16:56 % time gcc-4.4  -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o
gcc-4.4 -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o  39.23s user 1.95s system 99% cpu 41.298 total
glinka ~/tmp 16:57 % time gcc-4.4  -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o
gcc-4.4 -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o  8.69s user 0.32s system 99% cpu 9.046 total
glinka ~/tmp 16:57 % time gcc-4.4  -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o
gcc-4.4 -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o  20.98s user 1.18s system 99% cpu 22.282 total



glinka ~/tmp 16:58 % time gcc-4.3  -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o
gcc-4.3 -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o  44.04s user 2.14s system 99% cpu 46.563 total
glinka ~/tmp 16:59 % time gcc-4.3  -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o
gcc-4.3 -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o  7.12s user 0.27s system 99% cpu 7.402 total
glinka ~/tmp 17:00 % time gcc-4.3  -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o
gcc-4.3 -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o  75.16s user 3.32s system 99% cpu 1:18.97 total
glinka ~/tmp 17:01 % time gcc-4.3  -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o
gcc-4.3 -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o  20.78s user 0.96s system 99% cpu 21.856 total
glinka ~/tmp 17:01 % time gcc-4.3  -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o
gcc-4.3 -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o  7.11s user 0.32s system 99% cpu 7.442 total

I have no idea of what is happenning. (Maybe randomized address & malloc???) My desktop is not loaded (and is quadricore).


Regards.


--
Basile STARYNKEVITCH         http://starynkevitch.net/Basile/
email: basile<at>starynkevitch<dot>net mobile: [phone]
8, rue de la Faiencerie, 92340 Bourg La Reine, France
*** opinions {are only mines, sont seulement les miennes} ***

[Basile Starynkevitch]

Ian Lance Taylor wrote:
> Basile, you posted the time for the wrong file, or you got something
> else wrong.

Here are other runs. The warmelt-normal-1.i is exactly the one uploaded in the bug report. Its md5sum is
944b6e0f8c6da76a7f0698e927fc4a60  warmelt-normal-1.i

And it does not seem to be some excess swapping. The cc1 process seems to eat half a gigabyte, and I have 8 gigabytes
(and mozilla, emacs, thunderbird don't eat all of them).
During a cc1

% free
              total       used       free     shared    buffers     cached
Mem:       8197136    5181216    3015920          0    1435412    1777752
-/+ buffers/cache:    1968052    6229084
Swap:     15141244          0   15141244


I checked on my wristwatch and the real timing is similar to the one reported by the computer (so its hardware clock is
apparently ok).

################ gcc 4.3

glinka ~/tmp 17:05 % time gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o
# cc1 18.90 0.97
# as 0.74 0.04
gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.  19.64s user 1.02s system 99% cpu 20.839 total
glinka ~/tmp 17:06 % time gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o
# cc1 6.36 0.28
# as 0.74 0.05
gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.  7.10s user 0.33s system 99% cpu 7.440 total
glinka ~/tmp 17:06 % time gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o
# cc1 8.78 0.67
# as 0.72 0.05
gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.  9.50s user 0.72s system 98% cpu 10.337 total
glinka ~/tmp 17:06 %
glinka ~/tmp 17:06 % time gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o
# cc1 6.28 0.34
# as 0.73 0.03
gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.  7.01s user 0.37s system 99% cpu 7.401 total
glinka ~/tmp 17:06 % time gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o
# cc1 67.33 2.92
# as 7.54 0.49
gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.  74.88s user 3.44s system 99% cpu 1:18.92
total
glinka ~/tmp 17:11 % time gcc-4.3 -ftime-report -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o

Execution times (seconds)
  garbage collection    :   0.10 ( 1%) usr   0.00 ( 0%) sys   0.10 ( 1%) wall       0 kB ( 0%) ggc
  cfg cleanup           :   0.07 ( 1%) usr   0.00 ( 0%) sys   0.06 ( 1%) wall      19 kB ( 0%) ggc
  trivially dead code   :   0.05 ( 1%) usr   0.00 ( 0%) sys   0.05 ( 1%) wall       0 kB ( 0%) ggc
  df live regs          :   0.10 ( 1%) usr   0.00 ( 0%) sys   0.07 ( 1%) wall       0 kB ( 0%) ggc
  df reg dead/unused notes:   0.07 ( 1%) usr   0.00 ( 0%) sys   0.08 ( 1%) wall    6838 kB ( 2%) ggc
  register information  :   0.10 ( 1%) usr   0.00 ( 0%) sys   0.09 ( 1%) wall       0 kB ( 0%) ggc
  alias analysis        :   0.04 ( 1%) usr   0.00 ( 0%) sys   0.07 ( 1%) wall    2315 kB ( 1%) ggc
  rebuild jump labels   :   0.05 ( 1%) usr   0.00 ( 0%) sys   0.04 ( 0%) wall       0 kB ( 0%) ggc
  preprocessing         :   0.42 ( 6%) usr   0.22 (17%) sys   0.65 ( 8%) wall   24801 kB ( 7%) ggc
  lexical analysis      :   0.18 ( 3%) usr   0.57 (44%) sys   0.64 ( 8%) wall       0 kB ( 0%) ggc
  parser                :   0.86 (13%) usr   0.30 (23%) sys   1.29 (16%) wall  100081 kB (28%) ggc
  inline heuristics     :   0.21 ( 3%) usr   0.01 ( 1%) sys   0.23 ( 3%) wall      70 kB ( 0%) ggc
  tree gimplify         :   0.44 ( 7%) usr   0.03 ( 2%) sys   0.44 ( 5%) wall   58497 kB (16%) ggc
  tree eh               :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall       0 kB ( 0%) ggc
  tree CFG construction :   0.07 ( 1%) usr   0.03 ( 2%) sys   0.10 ( 1%) wall   37602 kB (10%) ggc
  tree CFG cleanup      :   0.08 ( 1%) usr   0.00 ( 0%) sys   0.07 ( 1%) wall       0 kB ( 0%) ggc
  dominance computation :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.04 ( 0%) wall       0 kB ( 0%) ggc
  expand                :   1.39 (21%) usr   0.05 ( 4%) sys   1.41 (18%) wall   89051 kB (24%) ggc
  varconst              :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall      92 kB ( 0%) ggc
  jump                  :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.00 ( 0%) wall       0 kB ( 0%) ggc
  local alloc           :   0.55 ( 8%) usr   0.00 ( 0%) sys   0.61 ( 8%) wall    3032 kB ( 1%) ggc
  global alloc          :   1.22 (18%) usr   0.05 ( 4%) sys   1.25 (16%) wall   18079 kB ( 5%) ggc
  thread pro- & epilogue:   0.11 ( 2%) usr   0.00 ( 0%) sys   0.13 ( 2%) wall     256 kB ( 0%) ggc
  final                 :   0.43 ( 6%) usr   0.03 ( 2%) sys   0.45 ( 6%) wall     360 kB ( 0%) ggc
  symout                :   0.10 ( 1%) usr   0.01 ( 1%) sys   0.11 ( 1%) wall   21440 kB ( 6%) ggc
  TOTAL                 :   6.73             1.30             8.05             363506 kB
gcc-4.3 -ftime-report -O0 -g -fPIC warmelt-normal-1.i -c -o   7.47s user 1.36s system 99% cpu 8.846 total
glinka ~/tmp 17:12 % time gcc-4.3 -ftime-report -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.3.o

Execution times (seconds)
  garbage collection    :   0.99 ( 2%) usr   0.00 ( 0%) sys   0.99 ( 1%) wall       0 kB ( 0%) ggc
  cfg cleanup           :   0.58 ( 1%) usr   0.00 ( 0%) sys   0.62 ( 1%) wall      19 kB ( 0%) ggc
  trivially dead code   :   0.41 ( 1%) usr   0.00 ( 0%) sys   0.40 ( 1%) wall       0 kB ( 0%) ggc
  df live regs          :   0.71 ( 1%) usr   0.02 ( 0%) sys   0.73 ( 1%) wall       0 kB ( 0%) ggc
  df reg dead/unused notes:   0.87 ( 1%) usr   0.01 ( 0%) sys   0.78 ( 1%) wall    6838 kB ( 2%) ggc
  register information  :   0.84 ( 1%) usr   0.00 ( 0%) sys   0.90 ( 1%) wall       0 kB ( 0%) ggc
  alias analysis        :   0.42 ( 1%) usr   0.00 ( 0%) sys   0.48 ( 1%) wall    2315 kB ( 1%) ggc
  rebuild jump labels   :   0.59 ( 1%) usr   0.00 ( 0%) sys   0.59 ( 1%) wall       0 kB ( 0%) ggc
  preprocessing         :   4.16 ( 6%) usr   2.28 (22%) sys   6.49 ( 9%) wall   24801 kB ( 7%) ggc
  lexical analysis      :   1.59 ( 2%) usr   3.88 (37%) sys   5.62 ( 7%) wall       0 kB ( 0%) ggc
  parser                :   7.16 (11%) usr   2.70 (26%) sys   9.69 (13%) wall  100081 kB (28%) ggc
  inline heuristics     :   2.02 ( 3%) usr   0.05 ( 0%) sys   2.12 ( 3%) wall      70 kB ( 0%) ggc
  tree gimplify         :   4.39 ( 7%) usr   0.33 ( 3%) sys   4.68 ( 6%) wall   58497 kB (16%) ggc
  tree eh               :   0.23 ( 0%) usr   0.00 ( 0%) sys   0.21 ( 0%) wall       0 kB ( 0%) ggc
  tree CFG construction :   0.85 ( 1%) usr   0.10 ( 1%) sys   1.00 ( 1%) wall   37602 kB (10%) ggc
  tree CFG cleanup      :   0.55 ( 1%) usr   0.00 ( 0%) sys   0.55 ( 1%) wall       0 kB ( 0%) ggc
  dominance computation :   0.21 ( 0%) usr   0.02 ( 0%) sys   0.28 ( 0%) wall       0 kB ( 0%) ggc
  expand                :  13.40 (21%) usr   0.66 ( 6%) sys  14.22 (19%) wall   89051 kB (24%) ggc
  varconst              :   0.06 ( 0%) usr   0.02 ( 0%) sys   0.03 ( 0%) wall      92 kB ( 0%) ggc
  jump                  :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.04 ( 0%) wall       0 kB ( 0%) ggc
  local alloc           :   6.01 ( 9%) usr   0.06 ( 1%) sys   5.94 ( 8%) wall    3032 kB ( 1%) ggc
  global alloc          :  12.39 (19%) usr   0.14 ( 1%) sys  12.66 (17%) wall   18079 kB ( 5%) ggc
  thread pro- & epilogue:   1.05 ( 2%) usr   0.00 ( 0%) sys   1.16 ( 2%) wall     256 kB ( 0%) ggc
  final                 :   4.01 ( 6%) usr   0.19 ( 2%) sys   4.20 ( 6%) wall     360 kB ( 0%) ggc
  symout                :   1.05 ( 2%) usr   0.07 ( 1%) sys   1.14 ( 2%) wall   21440 kB ( 6%) ggc
  TOTAL                 :  64.60            10.53            75.56             363506 kB
gcc-4.3 -ftime-report -O0 -g -fPIC warmelt-normal-1.i -c -o   70.82s user 11.11s system 99% cpu 1:22.40 total


################### gcc 4.4
glinka ~/tmp 17:15 % time gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o
# cc1 14.78 0.84
# as 0.75 0.04
gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.  15.53s user 0.89s system 99% cpu 16.498 total
glinka ~/tmp 17:15 % time gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o
# cc1 71.20 2.06
# as 7.70 0.51
gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.  78.90s user 2.60s system 99% cpu 1:21.71
total
glinka ~/tmp 17:17 % time gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o
# cc1 85.06 2.72
# as 7.83 0.47
gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.  92.89s user 3.23s system 99% cpu 1:36.72
total

glinka ~/tmp 17:20 % time gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o
# cc1 49.80 2.12
# as 0.75 0.03
gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.  50.56s user 2.16s system 99% cpu 52.947 total
glinka ~/tmp 17:20 % time gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o
# cc1 34.11 1.02
# as 7.68 0.54
gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.  41.79s user 1.59s system 99% cpu 43.733 total
glinka ~/tmp 17:21 % time gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o
# cc1 84.43 2.72
# as 7.77 0.44
gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.  92.21s user 3.19s system 99% cpu 1:35.87
total
glinka ~/tmp 17:23 % time gcc-4.4 -ftime-report -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o

Execution times (seconds)
  garbage collection    :   1.08 ( 1%) usr   0.01 ( 0%) sys   1.09 ( 1%) wall       0 kB ( 0%) ggc
  callgraph construction:   2.81 ( 3%) usr   0.12 ( 1%) sys   2.97 ( 3%) wall   13570 kB ( 3%) ggc
  callgraph optimization:   0.46 ( 1%) usr   0.00 ( 0%) sys   0.50 ( 0%) wall     339 kB ( 0%) ggc
  cfg cleanup           :   0.46 ( 1%) usr   0.00 ( 0%) sys   0.48 ( 0%) wall      24 kB ( 0%) ggc
  trivially dead code   :   0.86 ( 1%) usr   0.00 ( 0%) sys   0.81 ( 1%) wall       0 kB ( 0%) ggc
  df live regs          :   0.79 ( 1%) usr   0.02 ( 0%) sys   0.72 ( 1%) wall       0 kB ( 0%) ggc
  df reg dead/unused notes:   1.49 ( 2%) usr   0.03 ( 0%) sys   1.64 ( 2%) wall    6956 kB ( 2%) ggc
  register information  :   0.92 ( 1%) usr   0.01 ( 0%) sys   0.88 ( 1%) wall       0 kB ( 0%) ggc
  alias analysis        :   0.43 ( 0%) usr   0.00 ( 0%) sys   0.48 ( 0%) wall    2405 kB ( 1%) ggc
  rebuild jump labels   :   0.58 ( 1%) usr   0.00 ( 0%) sys   0.60 ( 1%) wall       0 kB ( 0%) ggc
  preprocessing         :   4.75 ( 5%) usr   2.84 (21%) sys   7.58 ( 7%) wall   25440 kB ( 6%) ggc
  lexical analysis      :   2.06 ( 2%) usr   5.45 (39%) sys   7.28 ( 7%) wall       0 kB ( 0%) ggc
  parser                :   6.08 ( 7%) usr   3.18 (23%) sys   9.44 ( 9%) wall   71977 kB (17%) ggc
  inline heuristics     :   0.50 ( 1%) usr   0.02 ( 0%) sys   0.49 ( 0%) wall       0 kB ( 0%) ggc
  tree gimplify         :  10.00 (11%) usr   0.38 ( 3%) sys  10.58 (10%) wall   88334 kB (21%) ggc
  tree eh               :   0.18 ( 0%) usr   0.00 ( 0%) sys   0.20 ( 0%) wall       0 kB ( 0%) ggc
  tree CFG construction :   0.54 ( 1%) usr   0.05 ( 0%) sys   0.62 ( 1%) wall   13199 kB ( 3%) ggc
  tree CFG cleanup      :   0.66 ( 1%) usr   0.00 ( 0%) sys   0.56 ( 1%) wall       0 kB ( 0%) ggc
  tree find ref. vars   :   0.43 ( 0%) usr   0.05 ( 0%) sys   0.55 ( 1%) wall    9130 kB ( 2%) ggc
  tree PHI insertion    :   0.12 ( 0%) usr   0.00 ( 0%) sys   0.14 ( 0%) wall     189 kB ( 0%) ggc
  tree SSA rewrite      :   0.19 ( 0%) usr   0.05 ( 0%) sys   0.24 ( 0%) wall   11835 kB ( 3%) ggc
  tree SSA other        :   0.76 ( 1%) usr   0.24 ( 2%) sys   1.05 ( 1%) wall     193 kB ( 0%) ggc
  tree operand scan     :   0.58 ( 1%) usr   0.27 ( 2%) sys   0.77 ( 1%) wall    7012 kB ( 2%) ggc
  tree SSA to normal    :   1.08 ( 1%) usr   0.00 ( 0%) sys   1.01 ( 1%) wall     448 kB ( 0%) ggc
  dominance frontiers   :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall       0 kB ( 0%) ggc
  dominance computation :   0.44 ( 0%) usr   0.01 ( 0%) sys   0.41 ( 0%) wall       0 kB ( 0%) ggc
  expand                :  17.52 (20%) usr   0.39 ( 3%) sys  18.22 (18%) wall  131397 kB (31%) ggc
  varconst              :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall      24 kB ( 0%) ggc
  jump                  :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) wall       0 kB ( 0%) ggc
  integrated RA         :  16.00 (18%) usr   0.11 ( 1%) sys  16.10 (16%) wall    3144 kB ( 1%) ggc
  reload                :   9.56 (11%) usr   0.17 ( 1%) sys   9.74 ( 9%) wall   17800 kB ( 4%) ggc
  thread pro- & epilogue:   1.44 ( 2%) usr   0.00 ( 0%) sys   1.51 ( 1%) wall     342 kB ( 0%) ggc
  final                 :   4.81 ( 5%) usr   0.26 ( 2%) sys   5.04 ( 5%) wall    2487 kB ( 1%) ggc
  symout                :   1.17 ( 1%) usr   0.09 ( 1%) sys   1.29 ( 1%) wall   22415 kB ( 5%) ggc
  rest of compilation   :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.00 ( 0%) wall       0 kB ( 0%) ggc
  TOTAL                 :  88.87            13.85           103.23             429820 kB
gcc-4.4 -ftime-report -O0 -g -fPIC warmelt-normal-1.i -c -o   96.57s user 14.64s system 99% cpu 1:51.80 total
glinka ~/tmp 17:25 % time gcc-4.4 -ftime-report -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o

Execution times (seconds)
  garbage collection    :   1.07 ( 2%) usr   0.00 ( 0%) sys   1.08 ( 1%) wall       0 kB ( 0%) ggc
  callgraph construction:   2.78 ( 5%) usr   0.08 ( 1%) sys   2.95 ( 4%) wall   13570 kB ( 3%) ggc
  callgraph optimization:   0.44 ( 1%) usr   0.00 ( 0%) sys   0.46 ( 1%) wall     339 kB ( 0%) ggc
  cfg cleanup           :   0.11 ( 0%) usr   0.00 ( 0%) sys   0.12 ( 0%) wall      24 kB ( 0%) ggc
  trivially dead code   :   0.56 ( 1%) usr   0.00 ( 0%) sys   0.48 ( 1%) wall       0 kB ( 0%) ggc
  df live regs          :   0.30 ( 0%) usr   0.00 ( 0%) sys   0.33 ( 0%) wall       0 kB ( 0%) ggc
  df reg dead/unused notes:   0.67 ( 1%) usr   0.00 ( 0%) sys   0.72 ( 1%) wall    6956 kB ( 2%) ggc
  register information  :   0.44 ( 1%) usr   0.00 ( 0%) sys   0.45 ( 1%) wall       0 kB ( 0%) ggc
  alias analysis        :   0.31 ( 1%) usr   0.00 ( 0%) sys   0.29 ( 0%) wall    2405 kB ( 1%) ggc
  rebuild jump labels   :   0.34 ( 1%) usr   0.00 ( 0%) sys   0.33 ( 0%) wall       0 kB ( 0%) ggc
  preprocessing         :   4.59 ( 7%) usr   2.77 (21%) sys   7.63 (10%) wall   25440 kB ( 6%) ggc
  lexical analysis      :   2.11 ( 3%) usr   5.31 (40%) sys   7.55 (10%) wall       0 kB ( 0%) ggc
  parser                :   6.32 (10%) usr   3.19 (24%) sys   9.15 (12%) wall   71977 kB (17%) ggc
  inline heuristics     :   0.48 ( 1%) usr   0.00 ( 0%) sys   0.49 ( 1%) wall       0 kB ( 0%) ggc
  tree gimplify         :   9.69 (16%) usr   0.55 ( 4%) sys  10.26 (14%) wall   88334 kB (21%) ggc
  tree eh               :   0.22 ( 0%) usr   0.01 ( 0%) sys   0.18 ( 0%) wall       0 kB ( 0%) ggc
  tree CFG construction :   0.56 ( 1%) usr   0.06 ( 0%) sys   0.64 ( 1%) wall   13199 kB ( 3%) ggc
  tree CFG cleanup      :   0.53 ( 1%) usr   0.01 ( 0%) sys   0.56 ( 1%) wall       0 kB ( 0%) ggc
  tree find ref. vars   :   0.46 ( 1%) usr   0.03 ( 0%) sys   0.51 ( 1%) wall    9130 kB ( 2%) ggc
  tree PHI insertion    :   0.12 ( 0%) usr   0.01 ( 0%) sys   0.09 ( 0%) wall     189 kB ( 0%) ggc
  tree SSA rewrite      :   0.21 ( 0%) usr   0.07 ( 1%) sys   0.34 ( 0%) wall   11835 kB ( 3%) ggc
  tree SSA other        :   0.72 ( 1%) usr   0.19 ( 1%) sys   0.92 ( 1%) wall     193 kB ( 0%) ggc
  tree operand scan     :   0.65 ( 1%) usr   0.29 ( 2%) sys   0.86 ( 1%) wall    7012 kB ( 2%) ggc
  tree SSA to normal    :   0.49 ( 1%) usr   0.00 ( 0%) sys   0.43 ( 1%) wall     448 kB ( 0%) ggc
  dominance frontiers   :   0.02 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) wall       0 kB ( 0%) ggc
  dominance computation :   0.35 ( 1%) usr   0.02 ( 0%) sys   0.38 ( 1%) wall       0 kB ( 0%) ggc
  expand                :  10.54 (17%) usr   0.25 ( 2%) sys  10.81 (14%) wall  131397 kB (31%) ggc
  varconst              :   0.02 ( 0%) usr   0.02 ( 0%) sys   0.01 ( 0%) wall      24 kB ( 0%) ggc
  jump                  :   0.02 ( 0%) usr   0.00 ( 0%) sys   0.00 ( 0%) wall       0 kB ( 0%) ggc
  integrated RA         :   8.97 (15%) usr   0.06 ( 0%) sys   9.20 (12%) wall    3144 kB ( 1%) ggc
  reload                :   4.19 ( 7%) usr   0.05 ( 0%) sys   4.28 ( 6%) wall   17800 kB ( 4%) ggc
  thread pro- & epilogue:   0.54 ( 1%) usr   0.00 ( 0%) sys   0.60 ( 1%) wall     342 kB ( 0%) ggc
  final                 :   2.42 ( 4%) usr   0.19 ( 1%) sys   2.48 ( 3%) wall    2487 kB ( 1%) ggc
  symout                :   0.25 ( 0%) usr   0.02 ( 0%) sys   0.42 ( 1%) wall   22415 kB ( 5%) ggc
  TOTAL                 :  61.55            13.28            75.18             429820 kB
gcc-4.4 -ftime-report -O0 -g -fPIC warmelt-normal-1.i -c -o   62.30s user 13.36s system 99% cpu 1:16.00 total
glinka ~/tmp 17:27 % time gcc-4.4 -ftime-report -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-1-gcc-4.4.o

Execution times (seconds)
  garbage collection    :   1.07 ( 3%) usr   0.00 ( 0%) sys   1.08 ( 2%) wall       0 kB ( 0%) ggc
  callgraph construction:   2.75 ( 7%) usr   0.08 ( 2%) sys   2.92 ( 6%) wall   13570 kB ( 3%) ggc
  callgraph optimization:   0.45 ( 1%) usr   0.00 ( 0%) sys   0.47 ( 1%) wall     339 kB ( 0%) ggc
  cfg cleanup           :   0.08 ( 0%) usr   0.00 ( 0%) sys   0.12 ( 0%) wall      24 kB ( 0%) ggc
  trivially dead code   :   0.42 ( 1%) usr   0.00 ( 0%) sys   0.42 ( 1%) wall       0 kB ( 0%) ggc
  df live regs          :   0.35 ( 1%) usr   0.00 ( 0%) sys   0.35 ( 1%) wall       0 kB ( 0%) ggc
  df reg dead/unused notes:   0.57 ( 1%) usr   0.00 ( 0%) sys   0.66 ( 1%) wall    6956 kB ( 2%) ggc
  register information  :   0.29 ( 1%) usr   0.00 ( 0%) sys   0.28 ( 1%) wall       0 kB ( 0%) ggc
  alias analysis        :   0.18 ( 0%) usr   0.00 ( 0%) sys   0.18 ( 0%) wall    2405 kB ( 1%) ggc
  rebuild jump labels   :   0.32 ( 1%) usr   0.00 ( 0%) sys   0.31 ( 1%) wall       0 kB ( 0%) ggc
  preprocessing         :   0.88 ( 2%) usr   0.64 (16%) sys   1.56 ( 3%) wall   25440 kB ( 6%) ggc
  lexical analysis      :   0.53 ( 1%) usr   1.14 (29%) sys   1.80 ( 4%) wall       0 kB ( 0%) ggc
  parser                :   1.45 ( 3%) usr   0.72 (18%) sys   2.04 ( 4%) wall   71977 kB (17%) ggc
  inline heuristics     :   0.45 ( 1%) usr   0.00 ( 0%) sys   0.45 ( 1%) wall       0 kB ( 0%) ggc
  tree gimplify         :   2.68 ( 6%) usr   0.22 ( 6%) sys   2.88 ( 6%) wall   88334 kB (21%) ggc
  tree eh               :   0.18 ( 0%) usr   0.00 ( 0%) sys   0.20 ( 0%) wall       0 kB ( 0%) ggc
  tree CFG construction :   0.68 ( 2%) usr   0.04 ( 1%) sys   0.61 ( 1%) wall   13199 kB ( 3%) ggc
  tree CFG cleanup      :   0.56 ( 1%) usr   0.00 ( 0%) sys   0.58 ( 1%) wall       0 kB ( 0%) ggc
  tree find ref. vars   :   0.52 ( 1%) usr   0.02 ( 1%) sys   0.54 ( 1%) wall    9130 kB ( 2%) ggc
  tree PHI insertion    :   0.09 ( 0%) usr   0.00 ( 0%) sys   0.11 ( 0%) wall     189 kB ( 0%) ggc
  tree SSA rewrite      :   0.23 ( 1%) usr   0.04 ( 1%) sys   0.27 ( 1%) wall   11835 kB ( 3%) ggc
  tree SSA other        :   0.57 ( 1%) usr   0.20 ( 5%) sys   1.01 ( 2%) wall     193 kB ( 0%) ggc
  tree operand scan     :   0.71 ( 2%) usr   0.37 ( 9%) sys   0.81 ( 2%) wall    7012 kB ( 2%) ggc
  tree SSA to normal    :   0.42 ( 1%) usr   0.00 ( 0%) sys   0.45 ( 1%) wall     448 kB ( 0%) ggc
  dominance frontiers   :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall       0 kB ( 0%) ggc
  dominance computation :   0.25 ( 1%) usr   0.03 ( 1%) sys   0.33 ( 1%) wall       0 kB ( 0%) ggc
  expand                :  10.54 (25%) usr   0.21 ( 5%) sys  10.63 (23%) wall  131397 kB (31%) ggc
  varconst              :   0.00 ( 0%) usr   0.01 ( 0%) sys   0.00 ( 0%) wall      24 kB ( 0%) ggc
  jump                  :   0.04 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall       0 kB ( 0%) ggc
  integrated RA         :   7.38 (18%) usr   0.01 ( 0%) sys   7.45 (16%) wall    3144 kB ( 1%) ggc
  reload                :   4.11 (10%) usr   0.01 ( 0%) sys   4.06 ( 9%) wall   17800 kB ( 4%) ggc
  thread pro- & epilogue:   0.59 ( 1%) usr   0.00 ( 0%) sys   0.58 ( 1%) wall     342 kB ( 0%) ggc
  reg stack             :   0.00 ( 0%) usr   0.01 ( 0%) sys   0.00 ( 0%) wall       0 kB ( 0%) ggc
  final                 :   2.38 ( 6%) usr   0.15 ( 4%) sys   2.50 ( 5%) wall    2487 kB ( 1%) ggc
  symout                :   0.25 ( 1%) usr   0.03 ( 1%) sys   0.26 ( 1%) wall   22415 kB ( 5%) ggc
  TOTAL                 :  42.02             3.93            46.03             429820 kB
gcc-4.4 -ftime-report -O0 -g -fPIC warmelt-normal-1.i -c -o   42.77s user 3.99s system 99% cpu 46.832 total


####

The widely different figures from one run to the next are surprising.

Here are the figures on my laptop Ubuntu Karmic AMD64 (dual-core Intel Core 2 P9500 at 2.53Ghz)
time gcc-4.2 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.2.o
# cc1 5.39 0.31
# as 0.74 0.07
gcc-4.2 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.2.o  6.13s user 0.38s system 99% cpu 6.525 total

time gcc-4.2 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.2.o
# cc1 5.35 0.35
# as 0.75 0.05
gcc-4.2 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.2.o  6.10s user 0.41s system 100% cpu 6.508 total

time gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.3.o
# cc1 6.79 0.36
# as 0.79 0.03
gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.3.o  7.58s user 0.39s system 99% cpu 7.995 total

time gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.3.o
# cc1 6.80 0.31
# as 0.77 0.06
gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.3.o  7.57s user 0.37s system 99% cpu 7.965 total

time gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.3.o -ftime-report

Execution times (seconds)
  garbage collection    :   0.10 ( 1%) usr   0.00 ( 0%) sys   0.10 ( 1%) wall       0 kB ( 0%) ggc
  cfg cleanup           :   0.04 ( 1%) usr   0.00 ( 0%) sys   0.04 ( 0%) wall      19 kB ( 0%) ggc
  trivially dead code   :   0.05 ( 1%) usr   0.00 ( 0%) sys   0.05 ( 1%) wall       0 kB ( 0%) ggc
  df live regs          :   0.09 ( 1%) usr   0.00 ( 0%) sys   0.09 ( 1%) wall       0 kB ( 0%) ggc
  df reg dead/unused notes:   0.07 ( 1%) usr   0.02 ( 2%) sys   0.09 ( 1%) wall    6838 kB ( 2%) ggc
  register information  :   0.08 ( 1%) usr   0.01 ( 1%) sys   0.09 ( 1%) wall       0 kB ( 0%) ggc
  alias analysis        :   0.04 ( 1%) usr   0.00 ( 0%) sys   0.04 ( 0%) wall    2315 kB ( 1%) ggc
  rebuild jump labels   :   0.05 ( 1%) usr   0.00 ( 0%) sys   0.05 ( 1%) wall       0 kB ( 0%) ggc
  preprocessing         :   0.42 ( 6%) usr   0.17 (15%) sys   0.57 ( 7%) wall   24801 kB ( 7%) ggc
  lexical analysis      :   0.24 ( 3%) usr   0.39 (35%) sys   0.64 ( 8%) wall       0 kB ( 0%) ggc
  parser                :   1.00 (14%) usr   0.19 (17%) sys   1.20 (15%) wall  100143 kB (28%) ggc
  inline heuristics     :   0.21 ( 3%) usr   0.01 ( 1%) sys   0.22 ( 3%) wall      70 kB ( 0%) ggc
  tree gimplify         :   0.53 ( 7%) usr   0.04 ( 4%) sys   0.57 ( 7%) wall   58497 kB (16%) ggc
  tree eh               :   0.02 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) wall       0 kB ( 0%) ggc
  tree CFG construction :   0.08 ( 1%) usr   0.03 ( 3%) sys   0.11 ( 1%) wall   37602 kB (10%) ggc
  tree CFG cleanup      :   0.03 ( 0%) usr   0.02 ( 2%) sys   0.05 ( 1%) wall       0 kB ( 0%) ggc
  dominance computation :   0.02 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) wall       0 kB ( 0%) ggc
  expand                :   1.44 (20%) usr   0.12 (11%) sys   1.56 (19%) wall   89055 kB (24%) ggc
  local alloc           :   0.62 ( 9%) usr   0.02 ( 2%) sys   0.64 ( 8%) wall    3032 kB ( 1%) ggc
  global alloc          :   1.31 (18%) usr   0.03 ( 3%) sys   1.34 (16%) wall   18079 kB ( 5%) ggc
  thread pro- & epilogue:   0.11 ( 2%) usr   0.00 ( 0%) sys   0.11 ( 1%) wall     256 kB ( 0%) ggc
  final                 :   0.49 ( 7%) usr   0.02 ( 2%) sys   0.51 ( 6%) wall     360 kB ( 0%) ggc
  symout                :   0.10 ( 1%) usr   0.03 ( 3%) sys   0.13 ( 2%) wall   21440 kB ( 6%) ggc
  TOTAL                 :   7.14             1.12             8.26             363573 kB
# cc1 7.14 1.15
# as 0.79 0.02
gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.3.o   7.93s user 1.17s system 99% cpu 9.118 total

time gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o  warmelt-normal-4.3.o -ftime-report


Execution times (seconds)
  garbage collection    :   0.10 ( 1%) usr   0.00 ( 0%) sys   0.10 ( 1%) wall       0 kB ( 0%) ggc
  cfg cleanup           :   0.06 ( 1%) usr   0.00 ( 0%) sys   0.06 ( 1%) wall      19 kB ( 0%) ggc
  trivially dead code   :   0.06 ( 1%) usr   0.00 ( 0%) sys   0.06 ( 1%) wall       0 kB ( 0%) ggc
  df live regs          :   0.08 ( 1%) usr   0.00 ( 0%) sys   0.08 ( 1%) wall       0 kB ( 0%) ggc
  df reg dead/unused notes:   0.08 ( 1%) usr   0.00 ( 0%) sys   0.08 ( 1%) wall    6838 kB ( 2%) ggc
  register information  :   0.09 ( 1%) usr   0.00 ( 0%) sys   0.09 ( 1%) wall       0 kB ( 0%) ggc
  alias analysis        :   0.04 ( 1%) usr   0.00 ( 0%) sys   0.04 ( 0%) wall    2315 kB ( 1%) ggc
  rebuild jump labels   :   0.07 ( 1%) usr   0.00 ( 0%) sys   0.07 ( 1%) wall       0 kB ( 0%) ggc
  preprocessing         :   0.46 ( 6%) usr   0.24 (22%) sys   0.66 ( 8%) wall   24801 kB ( 7%) ggc
  lexical analysis      :   0.18 ( 2%) usr   0.38 (36%) sys   0.59 ( 7%) wall       0 kB ( 0%) ggc
  parser                :   1.00 (14%) usr   0.26 (24%) sys   1.28 (15%) wall  100143 kB (28%) ggc
  inline heuristics     :   0.28 ( 4%) usr   0.01 ( 1%) sys   0.29 ( 4%) wall      70 kB ( 0%) ggc
  tree gimplify         :   0.55 ( 8%) usr   0.03 ( 3%) sys   0.58 ( 7%) wall   58497 kB (16%) ggc
  tree eh               :   0.02 ( 0%) usr   0.01 ( 1%) sys   0.02 ( 0%) wall       0 kB ( 0%) ggc
  tree CFG construction :   0.08 ( 1%) usr   0.01 ( 1%) sys   0.09 ( 1%) wall   37602 kB (10%) ggc
  tree CFG cleanup      :   0.04 ( 1%) usr   0.00 ( 0%) sys   0.04 ( 0%) wall       0 kB ( 0%) ggc
  dominance computation :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall       0 kB ( 0%) ggc
  expand                :   1.44 (20%) usr   0.09 ( 8%) sys   1.53 (18%) wall   89055 kB (24%) ggc
  local alloc           :   0.64 ( 9%) usr   0.00 ( 0%) sys   0.64 ( 8%) wall    3032 kB ( 1%) ggc
  global alloc          :   1.30 (18%) usr   0.01 ( 1%) sys   1.31 (16%) wall   18079 kB ( 5%) ggc
  thread pro- & epilogue:   0.13 ( 2%) usr   0.00 ( 0%) sys   0.13 ( 2%) wall     256 kB ( 0%) ggc
  final                 :   0.37 ( 5%) usr   0.00 ( 0%) sys   0.37 ( 4%) wall     360 kB ( 0%) ggc
  symout                :   0.10 ( 1%) usr   0.01 ( 1%) sys   0.11 ( 1%) wall   21440 kB ( 6%) ggc
  TOTAL                 :   7.21             1.07             8.28             363573 kB
# cc1 7.21 1.10
# as 0.76 0.05
gcc-4.3 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.3.o   7.97s user 1.16s system 100% cpu 9.130 total

time gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.4.o
# cc1 8.59 0.26
# as 0.77 0.06
gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.4.o  9.36s user 0.32s system 99% cpu 9.685 total
time gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.4.o
# cc1 8.43 0.45
# as 0.79 0.05
gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.4.o  9.22s user 0.50s system 99% cpu 9.731 total


time gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.4.o -ftime-report

Execution times (seconds)
  garbage collection    :   0.10 ( 1%) usr   0.00 ( 0%) sys   0.10 ( 1%) wall       0 kB ( 0%) ggc
  callgraph construction:   0.29 ( 3%) usr   0.02 ( 2%) sys   0.31 ( 3%) wall   13570 kB ( 3%) ggc
  callgraph optimization:   0.04 ( 0%) usr   0.00 ( 0%) sys   0.04 ( 0%) wall     339 kB ( 0%) ggc
  cfg cleanup           :   0.05 ( 1%) usr   0.00 ( 0%) sys   0.05 ( 0%) wall      24 kB ( 0%) ggc
  trivially dead code   :   0.07 ( 1%) usr   0.00 ( 0%) sys   0.07 ( 1%) wall       0 kB ( 0%) ggc
  df live regs          :   0.05 ( 1%) usr   0.01 ( 1%) sys   0.06 ( 1%) wall       0 kB ( 0%) ggc
  df reg dead/unused notes:   0.15 ( 2%) usr   0.00 ( 0%) sys   0.15 ( 1%) wall    6957 kB ( 2%) ggc
  register information  :   0.07 ( 1%) usr   0.00 ( 0%) sys   0.07 ( 1%) wall       0 kB ( 0%) ggc
  alias analysis        :   0.06 ( 1%) usr   0.00 ( 0%) sys   0.06 ( 1%) wall    2405 kB ( 1%) ggc
  rebuild jump labels   :   0.05 ( 1%) usr   0.00 ( 0%) sys   0.05 ( 0%) wall       0 kB ( 0%) ggc
  preprocessing         :   0.56 ( 6%) usr   0.17 (16%) sys   0.75 ( 7%) wall   25440 kB ( 6%) ggc
  lexical analysis      :   0.18 ( 2%) usr   0.40 (38%) sys   0.59 ( 6%) wall       0 kB ( 0%) ggc
  parser                :   0.55 ( 6%) usr   0.30 (28%) sys   0.82 ( 8%) wall   72039 kB (17%) ggc
  inline heuristics     :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall       0 kB ( 0%) ggc
  tree gimplify         :   0.96 (11%) usr   0.03 ( 3%) sys   0.99 (10%) wall   88334 kB (21%) ggc
  tree eh               :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall       0 kB ( 0%) ggc
  tree CFG construction :   0.06 ( 1%) usr   0.00 ( 0%) sys   0.06 ( 1%) wall   13199 kB ( 3%) ggc
  tree CFG cleanup      :   0.07 ( 1%) usr   0.00 ( 0%) sys   0.07 ( 1%) wall       0 kB ( 0%) ggc
  tree find ref. vars   :   0.06 ( 1%) usr   0.00 ( 0%) sys   0.06 ( 1%) wall    9130 kB ( 2%) ggc
  tree PHI insertion    :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall     189 kB ( 0%) ggc
  tree SSA rewrite      :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall   11835 kB ( 3%) ggc
  tree SSA other        :   0.06 ( 1%) usr   0.04 ( 4%) sys   0.10 ( 1%) wall     193 kB ( 0%) ggc
  tree operand scan     :   0.06 ( 1%) usr   0.03 ( 3%) sys   0.09 ( 1%) wall    7012 kB ( 2%) ggc
  tree SSA to normal    :   0.11 ( 1%) usr   0.00 ( 0%) sys   0.11 ( 1%) wall     448 kB ( 0%) ggc
  dominance computation :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall       0 kB ( 0%) ggc
  expand                :   1.88 (21%) usr   0.01 ( 1%) sys   1.89 (19%) wall  131416 kB (31%) ggc
  integrated RA         :   1.68 (19%) usr   0.00 ( 0%) sys   1.68 (17%) wall    3144 kB ( 1%) ggc
  reload                :   0.99 (11%) usr   0.00 ( 0%) sys   0.99 (10%) wall   17785 kB ( 4%) ggc
  thread pro- & epilogue:   0.13 ( 1%) usr   0.00 ( 0%) sys   0.13 ( 1%) wall     342 kB ( 0%) ggc
  final                 :   0.43 ( 5%) usr   0.02 ( 2%) sys   0.45 ( 4%) wall    2487 kB ( 1%) ggc
  symout                :   0.11 ( 1%) usr   0.01 ( 1%) sys   0.12 ( 1%) wall   22415 kB ( 5%) ggc
  TOTAL                 :   8.95             1.06            10.01             429887 kB
# cc1 8.96 1.09
# as 0.77 0.06
gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.4.o   9.73s user 1.15s system 99% cpu 10.901 total

time gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.4.o -ftime-report

Execution times (seconds)
  garbage collection    :   0.11 ( 1%) usr   0.00 ( 0%) sys   0.11 ( 1%) wall       0 kB ( 0%) ggc
  callgraph construction:   0.31 ( 4%) usr   0.00 ( 0%) sys   0.31 ( 3%) wall   13570 kB ( 3%) ggc
  callgraph optimization:   0.07 ( 1%) usr   0.00 ( 0%) sys   0.07 ( 1%) wall     339 kB ( 0%) ggc
  cfg cleanup           :   0.05 ( 1%) usr   0.00 ( 0%) sys   0.05 ( 1%) wall      24 kB ( 0%) ggc
  trivially dead code   :   0.08 ( 1%) usr   0.00 ( 0%) sys   0.08 ( 1%) wall       0 kB ( 0%) ggc
  df live regs          :   0.06 ( 1%) usr   0.00 ( 0%) sys   0.06 ( 1%) wall       0 kB ( 0%) ggc
  df reg dead/unused notes:   0.15 ( 2%) usr   0.00 ( 0%) sys   0.15 ( 2%) wall    6957 kB ( 2%) ggc
  register information  :   0.08 ( 1%) usr   0.00 ( 0%) sys   0.08 ( 1%) wall       0 kB ( 0%) ggc
  alias analysis        :   0.05 ( 1%) usr   0.00 ( 0%) sys   0.05 ( 1%) wall    2405 kB ( 1%) ggc
  rebuild jump labels   :   0.07 ( 1%) usr   0.00 ( 0%) sys   0.07 ( 1%) wall       0 kB ( 0%) ggc
  preprocessing         :   0.37 ( 4%) usr   0.19 (16%) sys   0.56 ( 6%) wall   25440 kB ( 6%) ggc
  lexical analysis      :   0.21 ( 2%) usr   0.36 (31%) sys   0.63 ( 6%) wall       0 kB ( 0%) ggc
  parser                :   0.63 ( 7%) usr   0.33 (28%) sys   0.90 ( 9%) wall   72039 kB (17%) ggc
  inline heuristics     :   0.07 ( 1%) usr   0.00 ( 0%) sys   0.07 ( 1%) wall       0 kB ( 0%) ggc
  tree gimplify         :   1.03 (12%) usr   0.06 ( 5%) sys   1.09 (11%) wall   88334 kB (21%) ggc
  tree eh               :   0.02 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) wall       0 kB ( 0%) ggc
  tree CFG construction :   0.04 ( 0%) usr   0.01 ( 1%) sys   0.05 ( 1%) wall   13199 kB ( 3%) ggc
  tree CFG cleanup      :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall       0 kB ( 0%) ggc
  tree find ref. vars   :   0.03 ( 0%) usr   0.01 ( 1%) sys   0.04 ( 0%) wall    9130 kB ( 2%) ggc
  tree PHI insertion    :   0.02 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) wall     189 kB ( 0%) ggc
  tree SSA rewrite      :   0.01 ( 0%) usr   0.02 ( 2%) sys   0.03 ( 0%) wall   11835 kB ( 3%) ggc
  tree SSA other        :   0.04 ( 0%) usr   0.04 ( 3%) sys   0.07 ( 1%) wall     193 kB ( 0%) ggc
  tree operand scan     :   0.05 ( 1%) usr   0.04 ( 3%) sys   0.10 ( 1%) wall    7012 kB ( 2%) ggc
  tree SSA to normal    :   0.11 ( 1%) usr   0.00 ( 0%) sys   0.11 ( 1%) wall     448 kB ( 0%) ggc
  dominance computation :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall       0 kB ( 0%) ggc
  expand                :   1.79 (20%) usr   0.03 ( 3%) sys   1.82 (18%) wall  131416 kB (31%) ggc
  integrated RA         :   1.60 (18%) usr   0.01 ( 1%) sys   1.61 (16%) wall    3144 kB ( 1%) ggc
  reload                :   0.98 (11%) usr   0.04 ( 3%) sys   1.02 (10%) wall   17785 kB ( 4%) ggc
  thread pro- & epilogue:   0.12 ( 1%) usr   0.00 ( 0%) sys   0.12 ( 1%) wall     342 kB ( 0%) ggc
  final                 :   0.47 ( 5%) usr   0.01 ( 1%) sys   0.48 ( 5%) wall    2487 kB ( 1%) ggc
  symout                :   0.14 ( 2%) usr   0.00 ( 0%) sys   0.14 ( 1%) wall   22415 kB ( 5%) ggc
  TOTAL                 :   8.82             1.17             9.99             429887 kB
# cc1 8.83 1.20
# as 0.79 0.04
gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.4.o   9.62s user 1.24s system 99% cpu 10.861 total

time gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.4.o -ftime-report

Execution times (seconds)
  garbage collection    :   0.11 ( 1%) usr   0.00 ( 0%) sys   0.11 ( 1%) wall       0 kB ( 0%) ggc
  callgraph construction:   0.24 ( 3%) usr   0.03 ( 3%) sys   0.27 ( 3%) wall   13570 kB ( 3%) ggc
  callgraph optimization:   0.07 ( 1%) usr   0.00 ( 0%) sys   0.07 ( 1%) wall     339 kB ( 0%) ggc
  cfg cleanup           :   0.06 ( 1%) usr   0.00 ( 0%) sys   0.06 ( 1%) wall      24 kB ( 0%) ggc
  trivially dead code   :   0.09 ( 1%) usr   0.00 ( 0%) sys   0.09 ( 1%) wall       0 kB ( 0%) ggc
  df live regs          :   0.09 ( 1%) usr   0.00 ( 0%) sys   0.09 ( 1%) wall       0 kB ( 0%) ggc
  df reg dead/unused notes:   0.14 ( 2%) usr   0.00 ( 0%) sys   0.14 ( 1%) wall    6957 kB ( 2%) ggc
  register information  :   0.07 ( 1%) usr   0.00 ( 0%) sys   0.07 ( 1%) wall       0 kB ( 0%) ggc
  alias analysis        :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall    2405 kB ( 1%) ggc
  rebuild jump labels   :   0.05 ( 1%) usr   0.00 ( 0%) sys   0.05 ( 0%) wall       0 kB ( 0%) ggc
  preprocessing         :   0.49 ( 5%) usr   0.17 (16%) sys   0.74 ( 7%) wall   25440 kB ( 6%) ggc
  lexical analysis      :   0.27 ( 3%) usr   0.43 (39%) sys   0.65 ( 6%) wall       0 kB ( 0%) ggc
  parser                :   0.53 ( 6%) usr   0.21 (19%) sys   0.71 ( 7%) wall   72039 kB (17%) ggc
  inline heuristics     :   0.03 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall       0 kB ( 0%) ggc
  tree gimplify         :   1.00 (11%) usr   0.06 ( 6%) sys   1.06 (11%) wall   88334 kB (21%) ggc
  tree eh               :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall       0 kB ( 0%) ggc
  tree CFG construction :   0.06 ( 1%) usr   0.01 ( 1%) sys   0.07 ( 1%) wall   13199 kB ( 3%) ggc
  tree CFG cleanup      :   0.08 ( 1%) usr   0.00 ( 0%) sys   0.08 ( 1%) wall       0 kB ( 0%) ggc
  tree find ref. vars   :   0.04 ( 0%) usr   0.01 ( 1%) sys   0.05 ( 0%) wall    9130 kB ( 2%) ggc
  tree SSA rewrite      :   0.03 ( 0%) usr   0.01 ( 1%) sys   0.04 ( 0%) wall   11835 kB ( 3%) ggc
  tree SSA other        :   0.06 ( 1%) usr   0.00 ( 0%) sys   0.07 ( 1%) wall     193 kB ( 0%) ggc
  tree operand scan     :   0.07 ( 1%) usr   0.03 ( 3%) sys   0.09 ( 1%) wall    7012 kB ( 2%) ggc
  tree SSA to normal    :   0.09 ( 1%) usr   0.00 ( 0%) sys   0.09 ( 1%) wall     448 kB ( 0%) ggc
  dominance computation :   0.06 ( 1%) usr   0.00 ( 0%) sys   0.06 ( 1%) wall       0 kB ( 0%) ggc
  expand                :   1.69 (19%) usr   0.06 ( 6%) sys   1.75 (17%) wall  131416 kB (31%) ggc
  integrated RA         :   1.64 (18%) usr   0.01 ( 1%) sys   1.65 (16%) wall    3144 kB ( 1%) ggc
  reload                :   1.01 (11%) usr   0.02 ( 2%) sys   1.03 (10%) wall   17785 kB ( 4%) ggc
  thread pro- & epilogue:   0.15 ( 2%) usr   0.00 ( 0%) sys   0.15 ( 1%) wall     342 kB ( 0%) ggc
  final                 :   0.55 ( 6%) usr   0.00 ( 0%) sys   0.55 ( 5%) wall    2487 kB ( 1%) ggc
  symout                :   0.11 ( 1%) usr   0.02 ( 2%) sys   0.13 ( 1%) wall   22415 kB ( 5%) ggc
  TOTAL                 :   8.95             1.09            10.04             429887 kB
# cc1 8.95 1.12
# as 0.76 0.08
gcc-4.4 -time -O0 -g -fPIC warmelt-normal-1.i -c -o warmelt-normal-4.4.o   9.71s user 1.20s system 99% cpu 10.915 total

##

So I don't understand what happens to me. Perhaps I have two different brands of RAM on my desktop???

Anyway, you can retrieve the warmelt-normal-1.i file from the bug report PR41971 and try yourself.

Regards.
--
Basile STARYNKEVITCH         http://starynkevitch.net/Basile/
email: basile<at>starynkevitch<dot>net mobile: [phone]
8, rue de la Faiencerie, 92340 Bourg La Reine, France
*** opinions {are only mines, sont seulement les miennes} ***