[Bug c/67396] New: [4.9/5.0 regression] Performance regression compiling variadic function with many arguments

[Bug c/67396] New: [4.9/5.0 regression] Performance regression compiling variadic function with many arguments

[ppluzhnikov at google dot com]

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

            Bug ID: 67396
           Summary: [4.9/5.0 regression] Performance regression compiling
                    variadic function with many arguments
           Product: gcc
           Version: unknown
            Status: UNCONFIRMED
          Severity: normal
          Priority: P3
         Component: c
          Assignee: unassigned at gcc dot gnu.org
          Reporter: ppluzhnikov at google dot com
  Target Milestone: ---

Created attachment 36270
  --> https://gcc.gnu.org/bugzilla/attachment.cgi?id=36270&action=edit
test generator script

For https://sourceware.org/bugzilla/show_bug.cgi?id=18872, I need a test case
that calls printf() with >= 2700 arguments.

GCC-4.9 and 5.0 (and current trunk) take excessively long to compile such test
cases with optimization:

$ perl gen_bz18872.pl 500 > t.c && time gcc-svn-r227321/bin/gcc -c -O2 t.c
user    0m1.506s

$ perl gen_bz18872.pl 1000 > t.c && time gcc-svn-r227321/bin/gcc -c -O2 t.c
user    0m11.976s

$ perl gen_bz18872.pl 2000 > t.c && gcc-svn-r227321/bin/gcc -c -O2 t.c
user    1m40.911s

$ perl gen_bz18872.pl 4000 > t.c && gcc-svn-r227321/bin/gcc -c -O2 t.c
user    14m0.767s  ### Yikes!

For comparison, gcc-4.8 (Ubuntu 4.8.4-2ubuntu1~14.04) 4.8.4 compiles the 4000
argument case in 1.3s.

The problem is already present in r220312 (the oldest build I have).

[Bug c/67396] [4.9/5.0 regression] Performance regression compiling variadic function with many arguments

[ppluzhnikov at google dot com]

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

Paul Pluzhnikov <ppluzhnikov at google dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |jh at suse dot cz

--- Comment #1 from Paul Pluzhnikov <ppluzhnikov at google dot com> ---
This is "caused" by r206947:

 2014-01-22  Jan Hubicka  <jh@suse.cz>

+       * config/i386/x86-tune.def (X86_TUNE_ACCUMULATE_OUTGOING_ARGS):
+       Enable for generic and recent AMD targets.
+
+2014-01-22  Jan Hubicka  <jh@suse.cz>
+
        * combine-stack-adj.c (combine_stack_adjustments_for_block): Remove
        ARG_SIZE note when adjustment was eliminated.

Index: gcc/config/i386/x86-tune.def
===================================================================
--- gcc/config/i386/x86-tune.def        (revision 206946)
+++ gcc/config/i386/x86-tune.def        (revision 206947)
@@ -146,7 +146,7 @@
    use of the frame pointer in 32bit mode.  */
 DEF_TUNE (X86_TUNE_ACCUMULATE_OUTGOING_ARGS, "accumulate_outgoing_args",
          m_PPRO | m_P4_NOCONA | m_BONNELL | m_SILVERMONT | m_INTEL
-         | m_AMD_MULTIPLE | m_GENERIC)
+         | m_ATHLON_K8)

 /* X86_TUNE_PROLOGUE_USING_MOVE: Do not use push/pop in prologues that are
    considered on critical path.  */



The patch appears to be backwards from what the commit message says though?

$ time gcc-svn-r206948/bin/gcc -c -O2 t.c -mtune=k8

real    0m1.411s
user    0m1.391s
sys     0m0.019s

$ time gcc-svn-r206948/bin/gcc -c -O2 t.c
^C

real    1m31.462s
user    0m0.000s
sys     0m0.006s

$ time gcc-svn-r206948/bin/gcc -c -O2 t.c -mtune=generic
^C

real    1m14.054s
user    0m0.000s
sys     0m0.004s

[Bug target/67396] [4.9/5.0 regression] Performance regression compiling variadic function with many arguments

[pinskia at gcc dot gnu.org]

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

Andrew Pinski <pinskia at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           Keywords|                            |compile-time-hog
          Component|c                           |target

--- Comment #2 from Andrew Pinski <pinskia at gcc dot gnu.org> ---
https://gcc.gnu.org/ml/gcc-patches/2014-01/msg00008.html

Can you provide -ftime-report ?

[Bug target/67396] [4.9/5.0 regression] Performance regression compiling variadic function with many arguments

[ppluzhnikov at google dot com]

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

--- Comment #3 from Paul Pluzhnikov <ppluzhnikov at google dot com> ---
(In reply to Andrew Pinski from comment #2)

> Can you provide -ftime-report ?

Sure:

perl gen_bz18872.pl 2000 > t.c && gcc-svn-r227321/bin/gcc -c -O2 t.c
-ftime-report

Execution times (seconds)
 phase setup             :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.00 ( 0%) wall 
  1066 kB (19%) ggc
 phase parsing           :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) wall 
  1486 kB (27%) ggc
 phase opt and generate  : 102.09 (100%) usr   0.01 (100%) sys 102.29 (100%)
wall    2997 kB (54%) ggc
 garbage collection      :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
     0 kB ( 0%) ggc
 CFG verifier            :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
     0 kB ( 0%) ggc
 df use-def / def-use chains:   0.01 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%)
wall       0 kB ( 0%) ggc
 preprocessing           :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
   948 kB (17%) ggc
 lexical analysis        :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
     0 kB ( 0%) ggc
 parser (global)         :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.00 ( 0%) wall 
   297 kB ( 5%) ggc
 tree STMT verifier      :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
     0 kB ( 0%) ggc
 dominance computation   :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
     0 kB ( 0%) ggc
 expand                  :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
   484 kB ( 9%) ggc
 dead store elim1        : 101.85 (100%) usr   0.01 (100%) sys 101.96 (100%)
wall     171 kB ( 3%) ggc
 dead store elim2        :   0.11 ( 0%) usr   0.00 ( 0%) sys   0.11 ( 0%) wall 
   171 kB ( 3%) ggc
 CSE 2                   :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
     0 kB ( 0%) ggc
 integrated RA           :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
    24 kB ( 0%) ggc
 reload CSE regs         :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
   280 kB ( 5%) ggc
 thread pro- & epilogue  :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) wall 
     1 kB ( 0%) ggc
 peephole 2              :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
     0 kB ( 0%) ggc
 scheduling 2            :   0.06 ( 0%) usr   0.00 ( 0%) sys   0.08 ( 0%) wall 
  1558 kB (28%) ggc
 initialize rtl          :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.00 ( 0%) wall 
    12 kB ( 0%) ggc
 rest of compilation     :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) wall 
     2 kB ( 0%) ggc
 unaccounted todo        :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.00 ( 0%) wall 
     0 kB ( 0%) ggc
 verify RTL sharing      :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.00 ( 0%) wall 
     0 kB ( 0%) ggc
 TOTAL                 : 102.10             0.01           102.31              
5558 kB
Extra diagnostic checks enabled; compiler may run slowly.
Configure with --enable-checking=release to disable checks.


perf report says:

Samples: 409K of event 'cycles', Event count (approx.): 374080784459
 32.25%  cc1  cc1                [.] find_base_term(rtx_def*)
 27.15%  cc1  cc1                [.] get_addr(rtx_def*) [clone .part.39]
 16.57%  cc1  cc1                [.] rtx_equal_for_memref_p(rtx_def const*,
rtx_def const*)
 11.37%  cc1  cc1                [.] memrefs_conflict_p(int, rtx_def*, int,
rtx_def*, long) [clone .constprop.113]
  5.76%  cc1  cc1                [.] addr_side_effect_eval(rtx_def*, int, int)
[clone .constprop.114]
  2.81%  cc1  cc1                [.] ix86_find_base_term(rtx_def*)
  2.52%  cc1  cc1                [.] cselib_sp_based_value_p(cselib_val*)
  1.11%  cc1  cc1                [.] cselib_have_permanent_equivalences()
  0.13%  cc1  cc1                [.] record_store(rtx_def*, dse_bb_info_type*)
...

[Bug target/67396] [4.9/5.0 regression] Performance regression compiling variadic function with many arguments

[pinskia at gcc dot gnu.org]

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

--- Comment #4 from Andrew Pinski <pinskia at gcc dot gnu.org> ---
So it looks like you did not configure with --enable-checking=release please do
before you report compile time regressions.


Configure with --enable-checking=release to disable checks.

[Bug target/67396] [4.9/5.0 regression] Performance regression compiling variadic function with many arguments

[ppluzhnikov at google dot com]

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

--- Comment #5 from Paul Pluzhnikov <ppluzhnikov at google dot com> ---
> please do before you report compile time regressions.

Ok. Here are the new numbers from current trunk built with
--enable-checking=release
(nothing's changed that I can see; still very slow):

for j in 500 1000 2000 3000; do perl ./gen_bz18872.pl $j > t.c ; (time
gcc-svn-r227326-rel/bin/gcc -c -O2 t.c) |& grep user; done

user    0m1.488s
user    0m12.010s
user    1m40.353s
user    5m47.668s

Here is the -ftime-report:

perl ./gen_bz18872.pl 2000 > t.c && gcc-svn-r227326-rel/bin/gcc -c -O2 t.c
-ftime-report

Execution times (seconds)
 phase setup             :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.00 ( 0%) wall 
  1066 kB (19%) ggc
 phase parsing           :   0.02 ( 0%) usr   0.00 ( 0%) sys   0.02 ( 0%) wall 
  1486 kB (27%) ggc
 phase opt and generate  : 100.30 (100%) usr   0.00 ( 0%) sys 100.43 (100%)
wall    2997 kB (54%) ggc
 trivially dead code     :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
     0 kB ( 0%) ggc
 df scan insns           :   0.01 ( 0%) usr   0.00 ( 0%) sys   0.00 ( 0%) wall 
     0 kB ( 0%) ggc
 preprocessing           :   0.02 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
   948 kB (17%) ggc
 lexical analysis        :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 0%) wall 
     0 kB ( 0%) ggc
 dead store elim1        : 100.17 (100%) usr   0.00 ( 0%) sys 100.29 (100%)
wall     171 kB ( 3%) ggc
 dead store elim2        :   0.10 ( 0%) usr   0.00 ( 0%) sys   0.10 ( 0%) wall 
   171 kB ( 3%) ggc
 scheduling 2            :   0.02 ( 0%) usr   0.00 ( 0%) sys   0.03 ( 0%) wall 
  1558 kB (28%) ggc
 TOTAL                 : 100.32             0.00           100.45              
5558 kB


perf report:

Samples: 406K of event 'cycles', Event count (approx.): 372444339282
 32.97%  cc1  cc1                [.] find_base_term(rtx_def*)
 25.58%  cc1  cc1                [.] get_addr(rtx_def*) [clone .part.33]
 17.70%  cc1  cc1                [.] rtx_equal_for_memref_p(rtx_def const*,
rtx_def const*)
 11.33%  cc1  cc1                [.] memrefs_conflict_p(int, rtx_def*, int,
rtx_def*, long) [clone .constprop.107]
  5.79%  cc1  cc1                [.] addr_side_effect_eval(rtx_def*, int, int)
[clone .constprop.108]
  2.43%  cc1  cc1                [.] cselib_sp_based_value_p(cselib_val*)
  2.34%  cc1  cc1                [.] ix86_find_base_term(rtx_def*)
  1.41%  cc1  cc1                [.] cselib_have_permanent_equivalences()
  0.14%  cc1  cc1                [.] record_store(rtx_def*, dse_bb_info_type*)

[Bug rtl-optimization/67396] [4.9/5/6 regression] Performance regression compiling variadic function with many arguments in RTL DSE

[rguenth at gcc dot gnu.org]

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

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

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Target|                            |x86_64-*-*
          Component|target                      |rtl-optimization
            Version|unknown                     |5.2.0
   Target Milestone|---                         |4.9.4
            Summary|[4.9/5.0 regression]        |[4.9/5/6 regression]
                   |Performance regression      |Performance regression
                   |compiling variadic function |compiling variadic function
                   |with many arguments         |with many arguments in RTL
                   |                            |DSE

--- Comment #6 from Richard Biener <rguenth at gcc dot gnu.org> ---
I suppose this is a quite old quadraticness in RTL DSE (or rather
find_base_term).

[Bug rtl-optimization/67396] [4.9/5.0 regression] Performance regression compiling variadic function with many arguments

[miyuki at gcc dot gnu.org]

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

Mikhail Maltsev <miyuki at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Target|x86_64-*-*                  |
                 CC|                            |miyuki at gcc dot gnu.org
            Version|5.2.0                       |unknown
   Target Milestone|4.9.4                       |---
            Summary|[4.9/5/6 regression]        |[4.9/5.0 regression]
                   |Performance regression      |Performance regression
                   |compiling variadic function |compiling variadic function
                   |with many arguments in RTL  |with many arguments
                   |DSE                         |

--- Comment #7 from Mikhail Maltsev <miyuki at gcc dot gnu.org> ---
(In reply to Paul Pluzhnikov from comment #5)

> for j in 500 1000 2000 3000; do perl ./gen_bz18872.pl $j > t.c ; (time
> gcc-svn-r227326-rel/bin/gcc -c -O2 t.c) |& grep user; done
> 
> user	0m1.488s
> user	0m12.010s
> user	1m40.353s
> user	5m47.668s

Rough fitting suggests that it is O(n^3).

I did some profiling and it looks like we get rather deep recursion in alias
analysis. Most time is spent in the following call chain: dse_step1 ->
scan_insn -> record_store -> canon_true_dependence -> true_dependence1. It has
2 callees, which start deep recursion: memrefs_conflict_p and find_base_term
(the latter is invoked twice, the profiler suggests that only the second call,
i.e.

rtx mem_base = find_base_term (true_mem_addr);

is a hot spot). Then we start to recur via these 2 (interleaving) calls:

      f = val->locs;
      /* Temporarily reset val->locs to avoid infinite recursion.  */
      val->locs = NULL;

      for (l = f; l; l = l->next)
        if (GET_CODE (l->loc) == VALUE
            && CSELIB_VAL_PTR (l->loc)->locs
            && !CSELIB_VAL_PTR (l->loc)->locs->next
            && CSELIB_VAL_PTR (l->loc)->locs->loc == x)
          continue;
        else if ((ret = find_base_term (l->loc)) != 0)

1865            else if ((ret = find_base_term (l->loc)) != 0)
(gdb) p l->loc
$6 = (rtx_def *) (plus:DI (value:DI 2:4321 @0x1abc518/0x1ab8a20)
    (const_int -8 [0xfffffffffffffff8]))


and:

        /* Go ahead and find the base term for both operands.  If either base
           term is from a pointer or is a named object or a special address
           (like an argument or stack reference), then use it for the
           base term.  */
        rtx base = find_base_term (tmp1);
        if (base != NULL_RTX
            && ((REG_P (tmp1) && REG_POINTER (tmp1))
                 || known_base_value_p (base)))
          return base;

#1  0x000000000062b92a in find_base_term (x=<optimized out>) at
/home/miyuki/gcc/src/gcc/alias.c:1917
1917            rtx base = find_base_term (tmp1);
(gdb) p tmp1
$7 = (rtx_def *) (value:DI 2:4321 @0x1abc518/0x1ab8a20)

It's harder to say what happens in memrefs_conflict_p because it is
tail-recursive. This function has ~20 calls of itself. Perhaps basic block
profiling will tell more.

P.S. The profiler shows an estimate: alias.c:get_addr is invoked ~300000000
times (that is for 1000 printf arguments).
>From gcc-bugs-return-495959-listarch-gcc-bugs=gcc.gnu.org@gcc.gnu.org Mon Aug 31 09:24:43 2015
Return-Path: <gcc-bugs-return-495959-listarch-gcc-bugs=gcc.gnu.org@gcc.gnu.org>
Delivered-To: listarch-gcc-bugs@gcc.gnu.org
Received: (qmail 9005 invoked by alias); 31 Aug 2015 09:24:42 -0000
Mailing-List: contact gcc-bugs-help@gcc.gnu.org; run by ezmlm
Precedence: bulk
List-Id: <gcc-bugs.gcc.gnu.org>
List-Archive: <http://gcc.gnu.org/ml/gcc-bugs/>
List-Post: <mailto:gcc-bugs@gcc.gnu.org>
List-Help: <mailto:gcc-bugs-help@gcc.gnu.org>
Sender: gcc-bugs-owner@gcc.gnu.org
Delivered-To: mailing list gcc-bugs@gcc.gnu.org
Received: (qmail 8947 invoked by uid 48); 31 Aug 2015 09:24:39 -0000
From: "ro at gcc dot gnu.org" <gcc-bugzilla@gcc.gnu.org>
To: gcc-bugs@gcc.gnu.org
Subject: [Bug bootstrap/67363] [6 Regression] r227188 breaks build for mingw-w64
Date: Mon, 31 Aug 2015 09:24:00 -0000
X-Bugzilla-Reason: CC
X-Bugzilla-Type: changed
X-Bugzilla-Watch-Reason: None
X-Bugzilla-Product: gcc
X-Bugzilla-Component: bootstrap
X-Bugzilla-Version: 6.0
X-Bugzilla-Keywords:
X-Bugzilla-Severity: normal
X-Bugzilla-Who: ro at gcc dot gnu.org
X-Bugzilla-Status: NEW
X-Bugzilla-Resolution:
X-Bugzilla-Priority: P3
X-Bugzilla-Assigned-To: dmalcolm at redhat dot com
X-Bugzilla-Target-Milestone: 6.0
X-Bugzilla-Flags:
X-Bugzilla-Changed-Fields: bug_status cf_reconfirmed_on cc everconfirmed
Message-ID: <bug-67363-4-1Y2863e9aS@http.gcc.gnu.org/bugzilla/>
In-Reply-To: <bug-67363-4@http.gcc.gnu.org/bugzilla/>
References: <bug-67363-4@http.gcc.gnu.org/bugzilla/>
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: 7bit
X-Bugzilla-URL: http://gcc.gnu.org/bugzilla/
Auto-Submitted: auto-generated
MIME-Version: 1.0
X-SW-Source: 2015-08/txt/msg02101.txt.bz2
Content-length: 726

https://gcc.gnu.org/bugzilla/show_bug.cgi?idg363

Rainer Orth <ro at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|UNCONFIRMED                 |NEW
   Last reconfirmed|                            |2015-08-31
                 CC|                            |ro at gcc dot gnu.org
     Ever confirmed|0                           |1

--- Comment #4 from Rainer Orth <ro at gcc dot gnu.org> ---
Right: using xstrndup instead of strndup is the right fix and matches other
parts
of the gcc directory.  This patch also broke Solaris 10 bootstrap.

I'll later commit that fix as obvious.

  Rainer

[Bug rtl-optimization/67396] [4.9/5/6 regression] Performance regression compiling variadic function with many arguments in RTL DSE

[miyuki at gcc dot gnu.org]

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

Mikhail Maltsev <miyuki at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Target|                            |x86_64-*-*
   Target Milestone|---                         |4.9.4
            Summary|[4.9/5.0 regression]        |[4.9/5/6 regression]
                   |Performance regression      |Performance regression
                   |compiling variadic function |compiling variadic function
                   |with many arguments         |with many arguments in RTL
                   |                            |DSE
      Known to fail|                            |5.2.0