Subject: bug#44610: 27.1; Keyboard Macro Performance Problem

From: Jean Louis <[email-masked]>
Date: Sat, 14 Nov 2020 19:03:11 +0300

* Eli Zaretskii <[email-masked]> [2020-11-14 17:27]:
> > From: Robert Thorpe <[email-masked]>
> > Date: Fri, 13 Nov 2020 02:51:12 +0000
> > 
> > 
> > This bug report comes from a discussion on Emacs reddit.
> > 
> > Start with a blank buffer and create about ~300 lines of the string:
> > 
> >   ffffffffffffffffffff (pppppppppppppppppppp);
> > 
> > This will be turned into:
> > 
> >   'ffffffffffffffffffff':
> > 
> > That can be done using the following keyboard macro: M-m ' M-f ' : C-k
> > C-n
> > 
> > You can apply that to every line in the buffer using C-u 300 f4.
> > 
> > Now here's the strange bit.  In a fundamental-mode buffer this is
> > extremely fast, nearly instantaneous.  But, in a python-mode buffer it
> > takes 20 to 30 seconds.  If the mode is c-mode then it is also much
> > slower than fundamental-mode.  It will also exceed the variable binding
> > depth in some cases.  Oddly it is faster if you use forward-line instead
> > of C-n.
> 
> I suggest to produce and present a profile of this.  Invoke this macro
> after "M-x profiler-start RET RET", then "M-x profiler-report RET",
> expand the profile fully by "C-u RET" on the top line, and post the
> result here.  That should give some clues.

That is great advise to learn from. Macro took just about less than 2
seconds on my notebook Lenovo Thinkpad T410.

I am not the initial reporter. I have tested it in python-mode in
plain emacs -Q with the latest development version:

- command-execute                                          20,601,881  99%
 - call-interactively                                      20,601,881  99%
  - funcall-interactively                                  19,934,160  96%
   - kmacro-end-or-call-macro                              15,337,767  74%
    - kmacro-call-macro                                    15,337,767  74%
     - call-last-kbd-macro                                 15,242,727  73%
      - command-execute                                    15,102,838  73%
       - call-interactively                                15,021,006  72%
        - funcall-interactively                            14,985,294  72%
         - next-line                                       13,970,433  67%
          - line-move                                      13,968,321  67%
           - line-move-visual                              12,842,225  62%
            - vertical-motion                               9,925,619  48%
             - jit-lock-function                            9,925,619  48%
              - jit-lock-fontify-now                        9,925,619  48%
               - jit-lock--run-functions                    7,165,300  34%
                - run-hook-wrapped                          7,157,012  34%
                 - #<compiled 0x5b100c193163db5>            7,157,012  34%
                  - font-lock-fontify-region                7,157,012  34%
                   - font-lock-default-fontify-region       7,153,844  34%
                    - font-lock-fontify-keywords-region     5,169,903  25%
                       #<compiled 0x19a45f465d8aaf17>         369,664   1%
                       #<compiled -0x1210e8980f7ecafc>        308,861   1%
                     - python--font-lock-f-strings            306,448   1%
                        syntax-ppss                            11,536   0%
                    - font-lock-fontify-syntactically-region     1,975,653   9%
                     - python-font-lock-syntactic-face-function     1,889,981   9%
                      - python-info-docstring-p             1,878,263   9%
                       - python-nav-backward-sexp           1,150,110   5%
                        - python-nav-forward-sexp           1,144,830   5%
                         - python-nav--forward-sexp         1,144,830   5%
                          - python-info-beginning-of-block-p       519,389   2%
                           - python-info-statement-starts-block-p       407,940   1%
                            - python-nav-beginning-of-statement       100,032   0%
                             - syntax-ppss                     46,400   0%
                                #<compiled 0x1c65d0f034163548>         4,320   0%
                             - python-info-line-ends-backslash-p        45,344   0%
                              - syntax-ppss                    45,344   0%
                                 #<compiled 0x1c65d0f034163548>         4,320   0%
                           - python-info-beginning-of-statement-p       103,161   0%
                            - python-nav-beginning-of-statement       103,161   0%
                             - syntax-ppss                     54,825   0%
                                make-byte-code                  4,377   0%
                             - python-info-line-ends-backslash-p        35,904   0%
                                syntax-ppss                    35,904   0%
                          - python-info-current-line-empty-p       307,473   1%
                             beginning-of-line                  4,377   0%
                          - python-info-end-of-block-p        130,384   0%
                           - python-info-end-of-statement-p       130,384   0%
                            - python-nav-end-of-statement       130,384   0%
                               syntax-ppss                     91,472   0%
                             - python-info-line-ends-backslash-p        34,768   0%
                                syntax-ppss                    34,768   0%
                          - python-info-beginning-of-statement-p       116,336   0%
                           - python-nav-beginning-of-statement       116,336   0%
                            - python-info-line-ends-backslash-p        55,648   0%
                               syntax-ppss                     55,648   0%
                              syntax-ppss                      44,112   0%
                          - python-nav-beginning-of-statement        53,456   0%
                           - python-info-line-ends-backslash-p        21,040   0%
                              syntax-ppss                      21,040   0%
                             syntax-ppss                       19,984   0%
                          - python-syntax-context-type          9,504   0%
                             syntax-ppss                        9,504   0%
                       - python-info-assignment-statement-p       314,499   1%
                        - python-nav-beginning-of-statement        19,587   0%
                         - python-info-line-ends-backslash-p         7,392   0%
                            syntax-ppss                         7,392   0%
                           syntax-ppss                          6,336   0%
                       - python-nav-beginning-of-statement        36,902   0%
                        - syntax-ppss                          22,595   0%
                           #<compiled 0x1c65d0f034163548>         5,859   0%
                        - python-info-line-ends-backslash-p         8,448   0%
                           syntax-ppss                          8,448   0%
                       syntax-ppss                             27,216   0%
                       replace-regexp-in-string                 2,112   0%
                      font-lock-unfontify-region                4,144   0%
               - run-with-timer                             2,730,692  13%
                - apply                                     2,730,692  13%
                 - run-at-time                              2,729,636  13%
                  - timer-activate                          2,717,252  13%
                   - timer--activate                        2,716,196  13%
                    - timer--time-less-p                    2,716,196  13%
                       timer--time                             36,054   0%
                       time-less-p                             24,036   0%
                  - timer-set-time                             12,384   0%
                     timer--time-setter                        12,384   0%
                 make-byte-code                                 5,859   0%
            - posn-at-point                                 2,878,318  13%
               file-remote-p                                2,360,868  11%
             - jit-lock-function                              340,326   1%
              - jit-lock-fontify-now                          340,326   1%
               - jit-lock--run-functions                      335,086   1%
                - run-hook-wrapped                            330,942   1%
                 - #<compiled 0x5b100c193163db5>              330,942   1%
                  - font-lock-fontify-region                  330,942   1%
                   - font-lock-default-fontify-region         329,886   1%
                    - font-lock-fontify-keywords-region       202,469   0%
                       #<compiled 0x19a45f465d8aaf17>          15,872   0%
                     - python--font-lock-f-strings             15,456   0%
                        syntax-ppss                             3,168   0%
                       #<compiled -0x1210e8980f7ecafc>         12,288   0%
                    - font-lock-fontify-syntactically-region       123,273   0%
                     - python-font-lock-syntactic-face-function        99,145   0%
                      - python-info-docstring-p                99,145   0%
                       - python-nav-backward-sexp              49,329   0%
                        - python-nav-forward-sexp              48,273   0%
                         - python-nav--forward-sexp            48,273   0%
                          - python-info-beginning-of-block-p        15,105   0%
                             python-info-statement-starts-block-p        15,105   0%
                          - python-nav-beginning-of-statement        12,512   0%
                             syntax-ppss                        8,368   0%
                            python-info-current-line-empty-p        12,288   0%
                          - python-syntax-context-type          4,224   0%
                             syntax-ppss                        4,224   0%
                          - python-info-beginning-of-statement-p         4,144   0%
                             python-nav-beginning-of-statement         4,144   0%
                       - python-info-assignment-statement-p        20,784   0%
                        - python-nav-beginning-of-statement         8,368   0%
                         - python-info-line-ends-backslash-p         3,168   0%
                            syntax-ppss                         3,168   0%
                           syntax-ppss                          1,056   0%
                       - python-nav-beginning-of-statement         8,368   0%
                          syntax-ppss                           2,112   0%
                        - python-info-line-ends-backslash-p         2,112   0%
                           syntax-ppss                          2,112   0%
                       syntax-ppss                              8,368   0%
                       replace-regexp-in-string                 4,144   0%
                      font-lock-unfontify-region                4,144   0%
             - eval                                           144,979   0%
                if                                            132,784   0%
                unless                                          6,336   0%
           - default-line-height                            1,089,216   5%
              default-font-height                           1,089,216   5%
           - window-inside-pixel-edges                         21,120   0%
            - window-edges                                     15,840   0%
               window-current-scroll-bars                      11,616   0%
         - kill-line                                          498,749   2%
          - kill-region                                       498,749   2%
           - kill-new                                         424,312   2%
              menu-bar-update-yank-menu                       340,984   1%
            - gui-select-text                                  74,880   0%
             - gui-set-selection                               74,880   0%
              - gui-backend-set-selection                      73,824   0%
               - apply                                         73,824   0%
                  #<compiled -0x1ef4cefd5124968d>              73,824   0%
           - filter-buffer-substring                           74,437   0%
            - buffer-substring--filter                         68,101   0%
             - #<compiled -0x1e2a987f6542516b>                 68,101   0%
              - apply                                          68,101   0%
               - #<compiled 0xd88b599ee0a5190>                 63,957   0%
                - delete-and-extract-region                    21,901   0%
                 - jit-lock-after-change                        9,666   0%
                  - run-hook-with-args                          4,833   0%
                   - font-lock-extend-jit-lock-region-after-change         4,833   0%
                      get-text-property                         4,833   0%
         - self-insert-command                                485,032   2%
          - python-indent-post-self-insert-function           421,304   2%
           - syntax-ppss                                      421,304   2%
            - syntax-propertize                               325,688   1%
               #<compiled 0x14be23ea75627c25>                 311,064   1%
             - run-hook-wrapped                                 1,056   0%
                #<compiled -0x10385ae61af9e5a6>                 1,056   0%
          - electric-indent-post-self-insert-function          22,016   0%
           - syntax-ppss                                       22,016   0%
            - syntax-propertize                                 3,168   0%
             - run-hook-wrapped                                 1,056   0%
                #<compiled -0x1038556930f9e5a6>                 1,056   0%
          - jit-lock-after-change                              12,432   0%
             run-hook-with-args                                 4,144   0%
          - undo-auto--undoable-change                             32   0%
           - undo-auto--boundary-ensure-timer                      32   0%
            - run-at-time                                          32   0%
             - timer-set-time                                      32   0%
                timer--time-setter                                 32   0%
      - jit-lock--antiblink-post-command                      113,809   0%
       - syntax-ppss                                           79,729   0%
          vconcat                                               4,833   0%
          syntax-propertize                                     2,112   0%
       - run-with-idle-timer                                   29,936   0%
        - timer-activate-when-idle                             25,712   0%
         - timer--activate                                     25,712   0%
            timer--time-less-p                                 25,712   0%
        - timer-set-idle-time                                   4,224   0%
           timer--time-setter                                   4,224   0%
      - undo-auto--add-boundary                                 4,224   0%
         undo-auto--boundaries                                  4,224   0%
   - execute-extended-command                               4,593,217  22%
    - command-execute                                       3,494,291  16%
     - call-interactively                                   3,494,291  16%
      - funcall-interactively                               3,494,275  16%
       - profiler-report                                    3,491,303  16%
          profiler-memory-running-p                             5,863   0%
       - profiler-start                                         2,972   0%
          message                                               2,341   0%
    - sit-for                                                 745,896   3%
     - redisplay                                              744,768   3%
      - redisplay_internal (C function)                       277,761   1%
       - tool-bar-make-keymap                                 271,923   1%
        - tool-bar-make-keymap-1                              271,923   1%
         - mapcar                                             271,923   1%
          - #<compiled -0xe8295ef54b23da6>                    271,923   1%
           - eval                                              17,416   0%
            - find-image                                       17,416   0%
               image-search-load-path                          17,416   0%
       - find-image                                             1,048   0%
          image-search-load-path                                1,048   0%
         kill-this-buffer-enabled-p                             1,024   0%
       - menu-bar-update-buffers                                  672   0%
          menu-bar-update-buffers-1                               672   0%
       - substitute-command-keys                                   21   0%
          generate-new-buffer                                      21   0%
     - read-event                                                  16   0%
      - command-execute                                            16   0%
         call-interactively                                        16   0%
    - execute-extended-command--shorter                       195,259   0%
     - completion-try-completion                              187,931   0%
      - completion--nth-completion                            186,883   0%
       - completion--some                                     186,883   0%
        - #<compiled 0x81c0cf17cf07668>                       185,827   0%
         - completion-pcm-try-completion                      184,779   0%
          - completion-pcm--merge-try                         148,675   0%
           - completion-pcm--merge-completions                 23,355   0%
              string-match                                      2,099   0%
              completion-pcm--pattern->regex                    2,096   0%
             completion-pcm--pattern->string                    1,048   0%
          - completion-pcm--find-all-completions               35,048   0%
           - completion-pcm--all-completions                   20,568   0%
              completion-pcm--pattern->regex                    1,048   0%
             completion-pcm--optimize-pattern                   1,056   0%
             completion-pcm--string->pattern                    1,024   0%
     - execute-extended-command--shorter-1                      7,328   0%
      - execute-extended-command--shorter-1                     5,232   0%
       - execute-extended-command--shorter-1                    2,096   0%
        - execute-extended-command--shorter-1                   2,096   0%
           mapcar                                               1,048   0%
         - execute-extended-command--shorter-1                  1,048   0%
          - execute-extended-command--shorter-1                 1,048   0%
             mapcar                                             1,048   0%
        mapcar                                                  1,048   0%
      commandp                                                  5,863   0%
      #<compiled -0x1910b770d84f49d5>                              42   0%
   - handle-focus-in                                            2,112   0%
    - #<compiled 0x189e2a0a0dde442>                             2,112   0%
     - apply                                                    2,112   0%
      - blink-cursor--rescan-frames                             2,112   0%
       - blink-cursor-check                                     2,112   0%
        - blink-cursor--should-blink                            2,112   0%
           frame-focus-state                                    2,112   0%
   - digit-argument                                             1,064   0%
    - universal-argument--mode                                  1,064   0%
       set-transient-map                                        1,064   0%
  - byte-code                                                 667,721   3%
   - read-extended-command                                    667,721   3%
    - completing-read                                         667,721   3%
     - completing-read-default                                667,721   3%
      - read-from-minibuffer                                  663,459   3%
       - redisplay_internal (C function)                      208,291   1%
        - tool-bar-make-keymap                                206,571   1%
         - tool-bar-make-keymap-1                             206,571   1%
          - mapcar                                            206,571   1%
           - #<compiled -0xe8295ef54b23da6>                   206,571   1%
            - eval                                              1,048   0%
             - find-image                                       1,048   0%
                image-search-load-path                          1,048   0%
        - find-image                                            1,048   0%
           image-search-load-path                               1,048   0%
        - menu-bar-update-buffers                                 672   0%
           menu-bar-update-buffers-1                              672   0%
       - command-execute                                        1,320   0%
        - call-interactively                                    1,320   0%
         - funcall-interactively                                1,080   0%
          - self-insert-command                                 1,080   0%
             #<compiled 0x23be74412ab8ae>                       1,048   0%
           - undo-auto--undoable-change                            32   0%
            - undo-auto--boundary-ensure-timer                     32   0%
             - run-at-time                                         32   0%
              - timer-set-time                                     32   0%
                 timer--time-setter                                32   0%
+ redisplay_internal (C function)                              33,424   0%
+ internal-echo-keystrokes-prefix                              15,490   0%
+ timer-event-handler                                           2,662   0%
  ...                                                               0   0%