[Bug c/109237] New: csmith: another timeout with -g -O3 this time

[Bug c/109237] New: csmith: another timeout with -g -O3 this time

[dcb314 at hotmail dot com]

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

            Bug ID: 109237
           Summary: csmith: another timeout with -g -O3 this time
           Product: gcc
           Version: 13.0
            Status: UNCONFIRMED
          Severity: normal
          Priority: P3
         Component: c
          Assignee: unassigned at gcc dot gnu.org
          Reporter: dcb314 at hotmail dot com
  Target Milestone: ---

Created attachment 54722
  --> https://gcc.gnu.org/bugzilla/attachment.cgi?id=54722&action=edit
C source code

The attached C code, when compiled by -O3, seems to take a reasonable time:

$ time ~/gcc/results/bin/gcc -c -w -O3 bug901.c

real    0m0.619s
user    0m0.597s
sys     0m0.012s

But adding -g seems to cause trouble:

$ (ulimit -t 120; time ~/gcc/results/bin/gcc -c -w -g -O3 bug901.c)
gcc: fatal error: Killed signal terminated program cc1
compilation terminated.

real    2m1.255s
user    1m58.650s
sys     0m1.593s

$ ~/gcc/results/bin/gcc -v 2>&1 | fgrep exp
gcc version 13.0.1 20230321 (experimental) (0963cb5fde158cce) 

So the version I used seems to include today's patch from Andrew Macleod
for timing reduction.

[Bug middle-end/109237] csmith: another timeout with -g -O3 this time

[dcb314 at hotmail dot com]

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

David Binderman <dcb314 at hotmail dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           Keywords|                            |needs-bisection,
                   |                            |needs-reduction

--- Comment #1 from David Binderman <dcb314 at hotmail dot com> ---
It looks as if this bug has existed for more than a year or so:

$ (ulimit -t 300; time ~/gcc/results.20220403/bin/gcc -c -w -g -O3 bug901.c)
gcc: fatal error: Killed signal terminated program cc1
compilation terminated.

real    5m3.060s
user    4m56.316s
sys     0m4.150s
$

[Bug middle-end/109237] csmith: another timeout with -g -O3 this time

[pinskia at gcc dot gnu.org]

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

--- Comment #2 from Andrew Pinski <pinskia at gcc dot gnu.org> ---
Note it seems worse with checking enabled as it is verification that takes a
long time.

[Bug middle-end/109237] csmith: another timeout with -g -O3 this time

[pinskia at gcc dot gnu.org]

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

--- Comment #3 from Andrew Pinski <pinskia at gcc dot gnu.org> ---
 cfg cleanup                        :  10.35 (  5%)   0.00 (  0%)  10.36 (  4%)
 7072  (  0%)
 trivially dead code                :  29.89 ( 14%)   0.00 (  0%)  29.89 ( 13%)
  352  (  0%)
 tree CFG cleanup                   :  10.41 (  5%)   0.00 (  0%)  10.44 (  4%)
   90k (  0%)
...
 tree operand scan                  :  11.85 (  6%)   8.90 ( 32%)  20.93 (  9%)
 4074k (  0%)
...
 backwards jump threading           :  12.18 (  6%)   7.53 ( 27%)  19.66 (  8%)
 2549M ( 37%)
...
 expand                             :   9.37 (  4%)   0.35 (  1%)   9.72 (  4%)
 2177M ( 31%)
...
 scheduling 2                       :  19.13 (  9%)   3.44 ( 13%)  22.57 ( 10%)
  746M ( 11%)
...
 variable tracking                  :   6.84 (  3%)   0.00 (  0%)   6.84 (  3%)
   27M (  0%)

From what I can tell it is just there are a lot (much more) more debug
statements causing the influence here ...

And the slow down is not just in one location either.

Note the above is the trunk with --enable-checking=yes but with -fno-checking
added to not take into account the gimple verifications which also slow it down
even further.

[Bug debug/109237] csmith: another timeout with -g -O3 this time

[pinskia at gcc dot gnu.org]

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

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

           What    |Removed                     |Added
----------------------------------------------------------------------------
          Component|middle-end                  |debug

--- Comment #4 from Andrew Pinski <pinskia at gcc dot gnu.org> ---
To give an insight into how much the verifiers give:
 CFG verifier                       :  61.10 ( 11%)   3.97 ( 13%)  65.09 ( 11%)
    0  (  0%)
...
 tree SSA verifier                  :  39.90 (  7%)   0.02 (  0%)  39.93 (  7%)
    0  (  0%)
 tree STMT verifier                 : 141.76 ( 26%)   0.00 (  0%) 141.95 ( 25%)
    0  (  0%)
...
 verify RTL sharing                 :  82.20 ( 15%)   0.00 (  0%)  82.25 ( 14%)
    0  (  0%)

Which is almost due to the number of debug statements (RTL and gimple level).
The only way to reduce the cost here is reduce the number of debug statements
...

[Bug debug/109237] csmith: another timeout with -g -O3 this time

[rguenth at gcc dot gnu.org]

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

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

           What    |Removed                     |Added
----------------------------------------------------------------------------
   Last reconfirmed|                            |2023-03-22
             Status|UNCONFIRMED                 |NEW
     Ever confirmed|0                           |1
                 CC|                            |rguenth at gcc dot gnu.org

--- Comment #5 from Richard Biener <rguenth at gcc dot gnu.org> ---
Confirmed.  Maybe the only suspicious thing is

 trivially dead code                :  10.65 ( 13%)

and

 tree CFG cleanup                   :   5.06 (  6%)
 cfg cleanup                        :   5.41 (  7%)

But yes, we're likely facing a lot of debug stmts, csmith tends to leave around
tons of dead code.

[Bug debug/109237] csmith: another timeout with -g -O3 this time

[rguenth at gcc dot gnu.org]

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

--- Comment #6 from Richard Biener <rguenth at gcc dot gnu.org> ---
For delete_trivially_dead_insns we have

  for (insn = get_last_insn (); insn; insn = prev)
    {
      int live_insn = 0;

      prev = PREV_INSN (insn);
      if (!INSN_P (insn))
        continue;

      live_insn = insn_live_p (insn, counts);

      /* If this is a dead insn, delete it and show registers in it aren't
         being used.  */

      if (! live_insn && dbg_cnt (delete_trivial_dead))
        {
          if (DEBUG_INSN_P (insn))
...

but insn_live_p has "interesting" behavior for debug_insns:

  else if (DEBUG_INSN_P (insn))
    {
      rtx_insn *next;

      if (DEBUG_MARKER_INSN_P (insn))
        return true;

      for (next = NEXT_INSN (insn); next; next = NEXT_INSN (next))
        if (NOTE_P (next))
          continue;
        else if (!DEBUG_INSN_P (next))
          return true;
        /* If we find an inspection point, such as a debug begin stmt,
           we want to keep the earlier debug insn.  */
        else if (DEBUG_MARKER_INSN_P (next))
          return true;
        else if (INSN_VAR_LOCATION_DECL (insn) == INSN_VAR_LOCATION_DECL
(next))
          return false;

      return true;

that's ending up doing quadratic work that would have been better done
by keeping track of some state during the backwards walk of the insn
stream.

[Bug debug/109237] csmith: another timeout with -g -O3 this time

[rguenth at gcc dot gnu.org]

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

--- Comment #7 from Richard Biener <rguenth at gcc dot gnu.org> ---
Created attachment 54727
  --> https://gcc.gnu.org/bugzilla/attachment.cgi?id=54727&action=edit
patch for delete_trivially_dead_insns

The attached improves that to

 trivially dead code                :   2.16 (  3%)

I've verified the set of debug insns kept is the same as before.

[Bug debug/109237] csmith: another timeout with -g -O3 this time since r12-156-g8d4c374c4419a875

[marxin at gcc dot gnu.org]

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

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

           What    |Removed                     |Added
----------------------------------------------------------------------------
            Summary|csmith: another timeout     |csmith: another timeout
                   |with -g -O3 this time       |with -g -O3 this time since
                   |                            |r12-156-g8d4c374c4419a875
           Keywords|needs-bisection             |
                 CC|                            |marxin at gcc dot gnu.org

--- Comment #8 from Martin Liška <marxin at gcc dot gnu.org> ---
I think it started with r12-156-g8d4c374c4419a875.

[Bug debug/109237] csmith: another timeout with -g -O3 this time since r12-156-g8d4c374c4419a875

[rguenth at gcc dot gnu.org]

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

--- Comment #9 from Richard Biener <rguenth at gcc dot gnu.org> ---
Samples: 289K of event 'cycles:u', Event count (approx.): 384226334976          
Overhead       Samples  Command  Shared Object     Symbol                       
   3.52%          9747  cc1      cc1               [.] bb_is_just_return       
           #
   2.94%          8241  cc1      cc1               [.] df_note_compute         
           #
   2.92%          8085  cc1      cc1               [.] init_alias_analysis     
           #
   2.55%          7035  cc1      cc1               [.]
delete_trivially_dead_insns         #
   2.28%          6372  cc1      cc1               [.]
contains_no_active_insn_p           #
   2.16%          6288  cc1      cc1               [.] get_ref_base_and_extent 
           #
   2.02%          5785  cc1      cc1               [.] ggc_set_mark            
           #
   1.55%          4308  cc1      cc1               [.] fast_dce                
           #

I see that bb_is_just_return is high in the profile and looking at its
implementation I wonder whether on RTL we can scan insns backwards and
stop if the last (real?) insn isn't ANY_RETURN_P ()?  Using
FOR_BB_INSNS_REVERSE puts it off the profile completely.  Will test a patch.

Similar contains_no_active_insn_p is high up in the profile and it looks
like micro-optimizing it a bit would help.  Using NONDEBUG_INSN_P to
guard the flow_active_insn_p call doesn't seem to help (but perf is always
noisy).

[Bug debug/109237] csmith: another timeout with -g -O3 this time since r12-156-g8d4c374c4419a875

[rguenth at gcc dot gnu.org]

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

--- Comment #10 from Richard Biener <rguenth at gcc dot gnu.org> ---
There's similar issues with GIMPLE uses of last_stmt () which generally (but
not always) want to look at a possible control transfer stmt.  It looks like
we're
not guaranteed to have no debug stmts after such, in particular CFG cleanup
seems to be ready to remove debug stmts after a noreturn call.  But
GIMPLE verify_flow_info should already choke on that, so it might be only a
temporary thing to accept?

[Bug debug/109237] csmith: another timeout with -g -O3 this time since r12-156-g8d4c374c4419a875

[cvs-commit at gcc dot gnu.org]

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

--- Comment #11 from CVS Commits <cvs-commit at gcc dot gnu.org> ---
The master branch has been updated by Richard Biener <rguenth@gcc.gnu.org>:

https://gcc.gnu.org/g:776a5bb5894315ab144dc74222fc580fde8fdd87

commit r13-6873-g776a5bb5894315ab144dc74222fc580fde8fdd87
Author: Richard Biener <rguenther@suse.de>
Date:   Wed Mar 22 10:05:19 2023 +0100

    rtl-optimization/109237 - speedup bb_is_just_return

    For the testcase bb_is_just_return is on top of the profile, changing
    it to walk BB insns backwards puts it off the profile.  That's because
    in the forward walk you have to process possibly many debug insns
    but in a backward walk you very likely run into control insns first.

            PR rtl-optimization/109237
            * cfgcleanup.cc (bb_is_just_return): Walk insns backwards.

[Bug debug/109237] csmith: another timeout with -g -O3 this time since r12-156-g8d4c374c4419a875

[rguenth at gcc dot gnu.org]

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

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

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |ASSIGNED
           Assignee|unassigned at gcc dot gnu.org      |rguenth at gcc dot gnu.org

--- Comment #12 from Richard Biener <rguenth at gcc dot gnu.org> ---
I have some more queued patches.

[Bug debug/109237] csmith: another timeout with -g -O3 this time since r12-156-g8d4c374c4419a875

[cvs-commit at gcc dot gnu.org]

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

--- Comment #13 from CVS Commits <cvs-commit at gcc dot gnu.org> ---
The master branch has been updated by Richard Biener <rguenth@gcc.gnu.org>:

https://gcc.gnu.org/g:8f81100115f68b37fb2723e987c14a3185d1f47d

commit r14-60-g8f81100115f68b37fb2723e987c14a3185d1f47d
Author: Richard Biener <rguenther@suse.de>
Date:   Wed Mar 22 10:05:19 2023 +0100

    rtl-optimization/109237 - speedup bb_is_just_return

    For the testcase bb_is_just_return is on top of the profile, changing
    it to walk BB insns backwards puts it off the profile.  That's because
    in the forward walk you have to process possibly many debug insns
    but in a backward walk you very likely run into control insns first.

            PR rtl-optimization/109237
            * cfgcleanup.cc (bb_is_just_return): Walk insns backwards.

--- Comment #14 from CVS Commits <cvs-commit at gcc dot gnu.org> ---
The master branch has been updated by Richard Biener <rguenth@gcc.gnu.org>:

https://gcc.gnu.org/g:675ac8822b51a39f6a66a44858d7c31ece8700f2

commit r14-61-g675ac8822b51a39f6a66a44858d7c31ece8700f2
Author: Richard Biener <rguenther@suse.de>
Date:   Wed Mar 22 09:29:49 2023 +0100

    rtl-optimization/109237 - quadraticness in delete_trivially_dead_insns

    The following addresses quadraticness in processing debug insns
    in delete_trivially_dead_insns and insn_live_p by using TREE_VISITED
    on the INSN_VAR_LOCATION_DECL to indicate a later debug bind
    with the same decl and no intervening real insn or debug marker.
    That gets rid of the NEXT_INSN walk in insn_live_p in favor of
    first clearing TREE_VISITED in the first loop over insn and
    the book-keeping of decls we set the bit since we need to clear
    them when visiting a real or debug marker insn.

    That improves the time spent in delete_trivially_dead_insns from
    10.6s to 2.2s for the testcase.

            PR rtl-optimization/109237
            * cse.cc (insn_live_p): Remove NEXT_INSN walk, instead check
            TREE_VISITED on INSN_VAR_LOCATION_DECL.
            (delete_trivially_dead_insns): Maintain TREE_VISITED on
            active debug bind INSN_VAR_LOCATION_DECL.

[Bug debug/109237] csmith: another timeout with -g -O3 this time since r12-156-g8d4c374c4419a875

[rguenth at gcc dot gnu.org]

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

--- Comment #15 from Richard Biener <rguenth at gcc dot gnu.org> ---
Spread pretty evenly now.  Everything >= 5%

 tree CFG cleanup                   :   5.25 (  8%)   0.00 (  0%)   5.27 (  7%)
   89k (  0%)
 expand                             :   3.22 (  5%)   0.18 (  2%)   3.41 (  4%)
 2177M ( 31%)
 scheduling 2                       :   6.93 ( 10%)   1.37 ( 18%)   8.29 ( 11%)
  746M ( 11%)
 TOTAL                              :  69.08          7.60         76.70       
 6951M

and the profile is

Samples: 287K of event 'cycles:u', Event count (approx.): 376155371739          
Overhead       Samples  Command  Shared Object     Symbol                       
   3.02%          8226  cc1      cc1               [.] init_alias_analysis
   3.02%          8300  cc1      cc1               [.] df_note_compute
   2.65%          7299  cc1      cc1               [.]
contains_no_active_insn_p
   2.53%          7016  cc1      cc1               [.]
delete_trivially_dead_insns
   2.15%          6150  cc1      cc1               [.] get_ref_base_and_extent
   1.92%          5443  cc1      cc1               [.] ggc_set_mark
   1.58%          4291  cc1      cc1               [.] fast_dce
   1.58%          4348  cc1      cc1               [.]
gimple_purge_dead_eh_edges
   1.53%          4141  cc1      cc1               [.] delete_unmarked_insns
   1.52%          4146  cc1      cc1               [.] prescan_insns_for_dce
   1.40%          3841  cc1      cc1               [.] cleanup_control_flow_bb
   1.28%          3467  cc1      cc1               [.] rebuild_jump_labels_1
   1.16%          3176  cc1      cc1               [.] df_live_bb_local_compute
   1.13%          3114  cc1      cc1               [.] gimple_merge_blocks
   1.09%          2977  cc1      cc1               [.] df_lr_bb_local_compute
   1.05%          2962  cc1      cc1               [.] (anonymous
namespace)::pass_rtl_cprop::execute
   1.03%          2988  cc1      cc1               [.] for_each_inc_dec
   1.01%          3168  cc1      cc1               [.] walk_tree_1
   0.87%          2790  cc1      cc1               [.] ggc_internal_alloc

[Bug debug/109237] csmith: another timeout with -g -O3 this time since r12-156-g8d4c374c4419a875

[rguenth at gcc dot gnu.org]

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

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

           What    |Removed                     |Added
----------------------------------------------------------------------------
           Assignee|rguenth at gcc dot gnu.org         |unassigned at gcc dot gnu.org
           Keywords|needs-reduction             |
             Status|ASSIGNED                    |NEW

--- Comment #16 from Richard Biener <rguenth at gcc dot gnu.org> ---
I wouldn't say "fixed", but at least it's as far as hotspots go.