bug#33670: 26.1; very large c++-mode yank performance regression 25.3_1-x86_64 -> 26.1-x86_64

bug#33670: 26.1; very large c++-mode yank performance regression 25.3_1-x86_64 -> 26.1-x86_64

[Chris Hecker]

Hi, I recently upgraded from 25.3_1 to to 26.1 on Windows 7 x64 and I've
noticed a very large performance regression on yanks in C++ mode buffers
(it feels slower in many other operations as well, but I actually
measured yank with the profiler).  This happens even starting with with
emacs -Q.

If I start emacs and visit a moderately large cpp file (18k LOC), and go
to the same place in the middle of the file in both versions of emacs,
then kill and yank the current line, the performance on 26.1 is easily
10x worse...the yank is instant in 25.3_1 and takes literally almost a
second on 26.1 sometimes.  I decided to test this with a profiler run,
so I went to the same line in both, killed the line, and evaled this:

(progn (profiler-start 'cpu) (yank) (profiler-report) (profiler-stop))

Here are the results:

25.3_1:

- ...                                               1 100%
   Automatic GC                                     1 100%


26.1:
- command-execute                                  14 100%
 - call-interactively                              14 100%
  - funcall-interactively                          14 100%
   - eval-expression                               14 100%
    - eval                                         14 100%
     - progn                                       14 100%
      - yank                                       14 100%
       - insert-for-yank                           14 100%
        - insert-for-yank-1                        14 100%
         - c-after-change                          13  92%
          - mapc                                   13  92%
           - #<compiled 0x9dcce1>                  13  92%
            - c-after-change-re-mark-raw-strings    6  42%
             - c-in-literal                         3  21%
              - c-state-semi-pp-to-literal          3  21%
                 c-parse-ps-state-below             3  21%
            - c-restore-<>-properties               4  28%
               c-syntactic-re-search-forward        4  28%
              c-neutralize-syntax-in-CPP            3  21%
         - remove-yank-excluded-properties          1   7%
          - remove-list-of-text-properties          1   7%
           - c-after-change                         1   7%
            - c-before-change                       1   7%
             - mapc                                 1   7%
              - #<compiled 0xfcb439>                1   7%
                 c-depropertize-CPP                 1   7%
- ...                                               0   0%
   Automatic GC                                     0   0%

I'm going to try the older cc-mode with the newer emacs and see if that
fixes it, but I figured I'd report this bug now in case you haven't
gotten other reports yet.

Thanks,
Chris


In GNU Emacs 26.1 (build 1, x86_64-w64-mingw32)
 of 2018-05-30 built on CIRROCUMULUS
Repository revision: 07f8f9bc5a51f5aa94eb099f3e15fbe0c20ea1ea
Windowing system distributor 'Microsoft Corp.', version 6.1.7601
Recent messages:
For information about GNU Emacs and the GNU system, type C-h C-a.
spyparty_ui.cpp has auto save data; consider M-x recover-this-file
Mark saved where search started
Mark set
Quit
CPU profiler started
Mark set
CPU profiler stopped
"CPU profiler stopped"
C-; is undefined
Quit [3 times]
Configured using:
 'configure --without-dbus --host=x86_64-w64-mingw32
 --without-compress-install 'CFLAGS=-O2 -static -g3''

Configured features:
XPM JPEG TIFF GIF PNG RSVG SOUND NOTIFY ACL GNUTLS LIBXML2 ZLIB
TOOLKIT_SCROLL_BARS THREADS LCMS2

Important settings:
  value of $LANG: ENU
  locale-coding-system: cp1252

Major mode: Profiler-Report

Minor modes in effect:
  tooltip-mode: t
  global-eldoc-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  tool-bar-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  blink-cursor-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  buffer-read-only: t
  line-number-mode: t
  transient-mark-mode: t

Load-path shadows:
None found.

Features:
(shadow sort mail-extr emacsbug message rmc puny seq byte-opt gv
bytecomp byte-compile cconv dired dired-loaddefs format-spec rfc822 mml
mml-sec password-cache epa derived epg epg-config gnus-util rmail
rmail-loaddefs mm-decode mm-bodies mm-encode mail-parse rfc2231
mailabbrev gmm-utils mailheader sendmail rfc2047 rfc2045 ietf-drums
mm-util mail-prsvr mail-utils profiler misearch multi-isearch
vc-dispatcher vc-bzr cc-mode cc-fonts easymenu cc-guess cc-menus cc-cmds
cc-styles cc-align cc-engine cc-vars cc-defs cl-loaddefs cl-lib
elec-pair time-date mule-util tooltip eldoc electric uniquify ediff-hook
vc-hooks lisp-float-type mwheel dos-w32 ls-lisp disp-table term/w32-win
w32-win w32-vars term/common-win tool-bar dnd fontset image regexp-opt
fringe tabulated-list replace newcomment text-mode elisp-mode lisp-mode
prog-mode register page menu-bar rfn-eshadow isearch timer select
scroll-bar mouse jit-lock font-lock syntax facemenu font-core
term/tty-colors frame cl-generic cham georgian utf-8-lang misc-lang
vietnamese tibetan thai tai-viet lao korean japanese eucjp-ms cp51932
hebrew greek romanian slovak czech european ethiopic indian cyrillic
chinese composite charscript charprop case-table epa-hook jka-cmpr-hook
help simple abbrev obarray minibuffer cl-preloaded nadvice loaddefs
button faces cus-face macroexp files text-properties overlay sha1 md5
base64 format env code-pages mule custom widget hashtable-print-readable
backquote w32notify w32 lcms2 multi-tty make-network-process emacs)

Memory information:
((conses 16 126347 12125)
 (symbols 56 22860 1)
 (miscs 48 74 192)
 (strings 32 37966 2210)
 (string-bytes 1 1104314)
 (vectors 16 37221)
 (vector-slots 8 997518 11240)
 (floats 8 65 156)
 (intervals 56 1881 214)
 (buffers 992 15))

bug#33670: adding some info to my yank perf regression

[Chris Hecker]

[-- Attachment #1: Type: text/plain, Size: 270 bytes --]


I just downgrated cc-mode to the one that shipped with 25.3_1 (c-version
5.32.99) and that fixed the yank perf on 26.1, so it's something either
in cc-mode directly or something changed in emacs that slows down
something in the latest 5.33.1 version of cc-mode.

Chris

[-- Attachment #2: Type: text/html, Size: 473 bytes --]

bug#33670: 26.1; very large c++-mode yank performance regression 25.3_1-x86_64 -> 26.1-x86_64

[Eli Zaretskii]

> From: Chris Hecker <checker@d6.com>
> Date: Fri, 7 Dec 2018 18:42:23 -0800
> 
> If I start emacs and visit a moderately large cpp file (18k LOC), and go
> to the same place in the middle of the file in both versions of emacs,
> then kill and yank the current line, the performance on 26.1 is easily
> 10x worse...the yank is instant in 25.3_1 and takes literally almost a
> second on 26.1 sometimes.  I decided to test this with a profiler run,
> so I went to the same line in both, killed the line, and evaled this:
> 
> (progn (profiler-start 'cpu) (yank) (profiler-report) (profiler-stop))
> 
> Here are the results:
> 
> 25.3_1:
> 
> - ...                                               1 100%
>    Automatic GC                                     1 100%
> 
> 
> 26.1:
> - command-execute                                  14 100%
>  - call-interactively                              14 100%
>   - funcall-interactively                          14 100%
>    - eval-expression                               14 100%
>     - eval                                         14 100%
>      - progn                                       14 100%
>       - yank                                       14 100%
>        - insert-for-yank                           14 100%
>         - insert-for-yank-1                        14 100%
>          - c-after-change                          13  92%
>           - mapc                                   13  92%
>            - #<compiled 0x9dcce1>                  13  92%
>             - c-after-change-re-mark-raw-strings    6  42%
>              - c-in-literal                         3  21%

Please load cc-mode.el manually as a .el file, and then do this
experiment again and show the profile.  As you see from the above,
most of the time is taken by some function in the
c-before-font-lock-functions, but it's hard to tell which, because
it is shown as a byte code.  Emacs 26 puts 5 functions on
c-before-font-lock-functions, whereas Emacs 25 used only 2, and it's
IMO important to see which one(s) take the lion's share of time.

Also, do you see this kind of degradation in any C++ source file of
comparable size, or is that particular file you used for the profile
especially slow?

Finally, was the line you yanked a line of code or a part of a
comment (or some other syntactic element)?  Does that matter?

Thanks.

bug#33670: 26.1; very large c++-mode yank performance regression 25.3_1-x86_64 -> 26.1-x86_64

[Alan Mackenzie]

Hello, Chris.

In article <mailman.5359.1544236991.1284.bug-gnu-emacs@gnu.org> you wrote:

> Hi, I recently upgraded from 25.3_1 to to 26.1 on Windows 7 x64 and I've
> noticed a very large performance regression on yanks in C++ mode buffers
> (it feels slower in many other operations as well, but I actually
> measured yank with the profiler).  This happens even starting with with
> emacs -Q.

> If I start emacs and visit a moderately large cpp file (18k LOC), and go
> to the same place in the middle of the file in both versions of emacs,
> then kill and yank the current line, the performance on 26.1 is easily
> 10x worse...the yank is instant in 25.3_1 and takes literally almost a
> second on 26.1 sometimes.  I decided to test this with a profiler run,
> so I went to the same line in both, killed the line, and evaled this:

> (progn (profiler-start 'cpu) (yank) (profiler-report) (profiler-stop))

> Here are the results:

> 25.3_1:

> - ...                                               1 100%
>    Automatic GC                                     1 100%


> 26.1:
> - command-execute                                  14 100%
>  - call-interactively                              14 100%
>   - funcall-interactively                          14 100%
>    - eval-expression                               14 100%
>     - eval                                         14 100%
>      - progn                                       14 100%
>       - yank                                       14 100%
>        - insert-for-yank                           14 100%
>         - insert-for-yank-1                        14 100%
>          - c-after-change                          13  92%
>           - mapc                                   13  92%
>            - #<compiled 0x9dcce1>                  13  92%
>             - c-after-change-re-mark-raw-strings    6  42%
>              - c-in-literal                         3  21%
>               - c-state-semi-pp-to-literal          3  21%
>                  c-parse-ps-state-below             3  21%
>             - c-restore-<>-properties               4  28%
>                c-syntactic-re-search-forward        4  28%
>               c-neutralize-syntax-in-CPP            3  21%
>          - remove-yank-excluded-properties          1   7%
>           - remove-list-of-text-properties          1   7%
>            - c-after-change                         1   7%
>             - c-before-change                       1   7%
>              - mapc                                 1   7%
>               - #<compiled 0xfcb439>                1   7%
>                  c-depropertize-CPP                 1   7%
> - ...                                               0   0%
>    Automatic GC                                     0   0%

What is this line that you kill, then yank?  The profiler report
suggests that it has something to do with raw strings, and I wouldn't be
at all surprised if the line contains the opening delimiter or closing
delimiter of quite a big raw string.

> I'm going to try the older cc-mode with the newer emacs and see if that
> fixes it, but I figured I'd report this bug now in case you haven't
> gotten other reports yet.

There was no raw string handling at all in Emacs 25.3, so it is not
surprising that CC Mode is much faster, there.  When a raw string is
started or terminated, CC Mode needs to check, potentially, the rest of
the buffer for characters which need "text properties" changing on them.
This can be time consuming.

However, a change to a line in the inside of a raw string shouldn't be
slow, and if it is, that's a bug.

> Thanks,
> Chris


> In GNU Emacs 26.1 (build 1, x86_64-w64-mingw32)
>  of 2018-05-30 built on CIRROCUMULUS
> Repository revision: 07f8f9bc5a51f5aa94eb099f3e15fbe0c20ea1ea
> Windowing system distributor 'Microsoft Corp.', version 6.1.7601
> Recent messages:
> For information about GNU Emacs and the GNU system, type C-h C-a.
> spyparty_ui.cpp has auto save data; consider M-x recover-this-file
> Mark saved where search started
> Mark set
> Quit
> CPU profiler started
> Mark set
> CPU profiler stopped
> "CPU profiler stopped"
> C-; is undefined
> Quit [3 times]
> Configured using:
>  'configure --without-dbus --host=x86_64-w64-mingw32
>  --without-compress-install 'CFLAGS=-O2 -static -g3''

-- 
Alan Mackenzie (Nuremberg, Germany).

bug#33670: 26.1; very large c++-mode yank performance regression 25.3_1-x86_64 -> 26.1-x86_64

[Chris Hecker]

[-- Attachment #1: Type: text/plain, Size: 4834 bytes --]

It wasn’t a string, it was a single line function call.  Very simple code.

Like:

   Foo();

Chris


On Sat, Dec 8, 2018 at 12:40 Alan Mackenzie <acm@muc.de> wrote:

> Hello, Chris.
>
> In article <mailman.5359.1544236991.1284.bug-gnu-emacs@gnu.org> you wrote:
>
> > Hi, I recently upgraded from 25.3_1 to to 26.1 on Windows 7 x64 and I've
> > noticed a very large performance regression on yanks in C++ mode buffers
> > (it feels slower in many other operations as well, but I actually
> > measured yank with the profiler).  This happens even starting with with
> > emacs -Q.
>
> > If I start emacs and visit a moderately large cpp file (18k LOC), and go
> > to the same place in the middle of the file in both versions of emacs,
> > then kill and yank the current line, the performance on 26.1 is easily
> > 10x worse...the yank is instant in 25.3_1 and takes literally almost a
> > second on 26.1 sometimes.  I decided to test this with a profiler run,
> > so I went to the same line in both, killed the line, and evaled this:
>
> > (progn (profiler-start 'cpu) (yank) (profiler-report) (profiler-stop))
>
> > Here are the results:
>
> > 25.3_1:
>
> > - ...                                               1 100%
> >    Automatic GC                                     1 100%
>
>
> > 26.1:
> > - command-execute                                  14 100%
> >  - call-interactively                              14 100%
> >   - funcall-interactively                          14 100%
> >    - eval-expression                               14 100%
> >     - eval                                         14 100%
> >      - progn                                       14 100%
> >       - yank                                       14 100%
> >        - insert-for-yank                           14 100%
> >         - insert-for-yank-1                        14 100%
> >          - c-after-change                          13  92%
> >           - mapc                                   13  92%
> >            - #<compiled 0x9dcce1>                  13  92%
> >             - c-after-change-re-mark-raw-strings    6  42%
> >              - c-in-literal                         3  21%
> >               - c-state-semi-pp-to-literal          3  21%
> >                  c-parse-ps-state-below             3  21%
> >             - c-restore-<>-properties               4  28%
> >                c-syntactic-re-search-forward        4  28%
> >               c-neutralize-syntax-in-CPP            3  21%
> >          - remove-yank-excluded-properties          1   7%
> >           - remove-list-of-text-properties          1   7%
> >            - c-after-change                         1   7%
> >             - c-before-change                       1   7%
> >              - mapc                                 1   7%
> >               - #<compiled 0xfcb439>                1   7%
> >                  c-depropertize-CPP                 1   7%
> > - ...                                               0   0%
> >    Automatic GC                                     0   0%
>
> What is this line that you kill, then yank?  The profiler report
> suggests that it has something to do with raw strings, and I wouldn't be
> at all surprised if the line contains the opening delimiter or closing
> delimiter of quite a big raw string.
>
> > I'm going to try the older cc-mode with the newer emacs and see if that
> > fixes it, but I figured I'd report this bug now in case you haven't
> > gotten other reports yet.
>
> There was no raw string handling at all in Emacs 25.3, so it is not
> surprising that CC Mode is much faster, there.  When a raw string is
> started or terminated, CC Mode needs to check, potentially, the rest of
> the buffer for characters which need "text properties" changing on them.
> This can be time consuming.
>
> However, a change to a line in the inside of a raw string shouldn't be
> slow, and if it is, that's a bug.
>
> > Thanks,
> > Chris
>
>
> > In GNU Emacs 26.1 (build 1, x86_64-w64-mingw32)
> >  of 2018-05-30 built on CIRROCUMULUS
> > Repository revision: 07f8f9bc5a51f5aa94eb099f3e15fbe0c20ea1ea
> > Windowing system distributor 'Microsoft Corp.', version 6.1.7601
> > Recent messages:
> > For information about GNU Emacs and the GNU system, type C-h C-a.
> > spyparty_ui.cpp has auto save data; consider M-x recover-this-file
> > Mark saved where search started
> > Mark set
> > Quit
> > CPU profiler started
> > Mark set
> > CPU profiler stopped
> > "CPU profiler stopped"
> > C-; is undefined
> > Quit [3 times]
> > Configured using:
> >  'configure --without-dbus --host=x86_64-w64-mingw32
> >  --without-compress-install 'CFLAGS=-O2 -static -g3''
>
> --
> Alan Mackenzie (Nuremberg, Germany).
>
>

[-- Attachment #2: Type: text/html, Size: 6429 bytes --]

bug#33670: 26.1; very large c++-mode yank performance regression 25.3_1-x86_64 -> 26.1-x86_64

[Alan Mackenzie]

Hello, Chris.

On Sat, Dec 08, 2018 at 13:31:42 -0800, Chris Hecker wrote:
> It wasn’t a string, it was a single line function call.  Very simple code.

> Like:

>    Foo();

Ah.  That's worrying.  The cause of the slowdown will not be found in
that single line of code, rather in its context.

The way CC Mode works is, at each buffer change, a region around the
change where side effects might propagate is calculated.  This region is
then checked for any such side effects.  I'm guessing here, but it might
well be that the region in this case has been extended far more than is
necessary.

Is there any way you could get a copy of the file to me, specifying a
line which shows the problem?  It's practically impossible to debug
otherwise.

Thanks! 

> Chris

-- 
Alan Mackenzie (Nuremberg, Germany).

bug#33670: 26.1; very large c++-mode yank performance regression 25.3_1-x86_64 -> 26.1-x86_64

[Chris Hecker]

[-- Attachment #1: Type: text/plain, Size: 1053 bytes --]

I think I can send it to you privately, I’ll mail you off the bug list
later today.

Chris


On Sun, Dec 9, 2018 at 04:06 Alan Mackenzie <acm@muc.de> wrote:

> Hello, Chris.
>
> On Sat, Dec 08, 2018 at 13:31:42 -0800, Chris Hecker wrote:
> > It wasn’t a string, it was a single line function call.  Very simple
> code.
>
> > Like:
>
> >    Foo();
>
> Ah.  That's worrying.  The cause of the slowdown will not be found in
> that single line of code, rather in its context.
>
> The way CC Mode works is, at each buffer change, a region around the
> change where side effects might propagate is calculated.  This region is
> then checked for any such side effects.  I'm guessing here, but it might
> well be that the region in this case has been extended far more than is
> necessary.
>
> Is there any way you could get a copy of the file to me, specifying a
> line which shows the problem?  It's practically impossible to debug
> otherwise.
>
> Thanks!
>
> > Chris
>
> --
> Alan Mackenzie (Nuremberg, Germany).
>

[-- Attachment #2: Type: text/html, Size: 1464 bytes --]

bug#33670: 26.1; very large c++-mode yank performance regression 25.3_1-x86_64 -> 26.1-x86_64

[Alan Mackenzie]

Hello, Chris.

On Sun, Dec 09, 2018 at 09:57:10 -0800, Chris Hecker wrote:
> I think I can send it [the file demonstrating the bug] to you
> privately, I’ll mail you off the bug list later today.

That would be great.  If you want it kept private, that won't be a
problem.  Thanks!

> Chris

-- 
Alan Mackenzie (Nuremberg, Germany).

bug#33670: 26.1; very large c++-mode yank performance regression 25.3_1-x86_64 -> 26.1-x86_64

[Lars Ingebrigtsen]

Alan Mackenzie <acm@muc.de> writes:

> On Sun, Dec 09, 2018 at 09:57:10 -0800, Chris Hecker wrote:
>> I think I can send it [the file demonstrating the bug] to you
>> privately, I’ll mail you off the bug list later today.
>
> That would be great.  If you want it kept private, that won't be a
> problem.  Thanks!

(I'm going through old bug reports that unfortunately weren't resolved
at the time.)

This was three years ago -- was there any progress on this issue?  (And
do you still see this problem in recent Emacs versions, Chris?)

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#33670: 26.1; very large c++-mode yank performance regression 25.3_1-x86_64 -> 26.1-x86_64

[Alan Mackenzie]

Hello, Lars.

On Sat, Jan 29, 2022 at 16:20:07 +0100, Lars Ingebrigtsen wrote:
> Alan Mackenzie <acm@muc.de> writes:

> > On Sun, Dec 09, 2018 at 09:57:10 -0800, Chris Hecker wrote:
> >> I think I can send it [the file demonstrating the bug] to you
> >> privately, I’ll mail you off the bug list later today.

> > That would be great.  If you want it kept private, that won't be a
> > problem.  Thanks!

> (I'm going through old bug reports that unfortunately weren't resolved
> at the time.)

> This was three years ago -- was there any progress on this issue?  (And
> do you still see this problem in recent Emacs versions, Chris?)

Unfortunately, there was no further progress at the time.  There was a
great deal of C++ raw-string processing and template marking happening,
although Chris told me there was no raw string in the text.

I suspect the bug, whatever it was, will have been fixed since late
2018.  The raw string processing has been significantly enhanced since
then.

So, Chris, are the problems still apparent?

> -- 
> (domestic pets only, the antidote for overdose, milk.)
>    bloggy blog: http://lars.ingebrigtsen.no

-- 
Alan Mackenzie (Nuremberg, Germany).

bug#33670: 26.1; very large c++-mode yank performance regression 25.3_1-x86_64 -> 26.1-x86_64

[Lars Ingebrigtsen]

Alan Mackenzie <acm@muc.de> writes:

> I suspect the bug, whatever it was, will have been fixed since late
> 2018.  The raw string processing has been significantly enhanced since
> then.
>
> So, Chris, are the problems still apparent?

More information was requested, but no response was given within a
month, so I'm closing this bug report.  If the problem still exists,
please respond to this email and we'll reopen the bug report.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no