Package: emacs;
Reported by: Robert Thorpe <rt <at> robertthorpeconsulting.com>
Date: Fri, 13 Nov 2020 02:52:02 UTC
Severity: normal
Found in version 27.1
Message #23 received at 44610 <at> debbugs.gnu.org (full text, mbox):
From: Robert Thorpe <rt <at> robertthorpeconsulting.com> To: Eli Zaretskii <eliz <at> gnu.org>, Jean Louis <bugs <at> gnu.support> Cc: 44610 <at> debbugs.gnu.org Subject: Re: bug#44610: 27.1; Keyboard Macro Performance Problem Date: Sun, 15 Nov 2020 23:44:32 +0000
Eli Zaretskii <eliz <at> gnu.org> writes:
>> From: Robert Thorpe <rt <at> robertthorpeconsulting.com>
>> 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.
Here is the report. I did it in Python-mode using Emacs -Q on Emacs
27.1. My machine is a Dell 14-3480. The profile I've got seems to be a
bit different to the one Jean Louis got.
It is a little faster using Emacs -Q than my own init, but it's
still fairly slow.
I notice that in my report the GC is taking about 39% of runtime. I'm
not sure why it's taking longer than in Jen Louis' report.
It's faster if I use forward-line rather than pressing C-n. Also the
report looks very different. I've added that at the end. The first
report is the one using C-n.
- command-execute 3499 60%
- call-interactively 3499 60%
- funcall-interactively 3480 59%
- kmacro-end-or-call-macro 3474 59%
- kmacro-call-macro 3474 59%
- call-last-kbd-macro 3464 59%
- command-execute 3419 58%
- call-interactively 3417 58%
- funcall-interactively 3417 58%
- next-line 3345 57%
- line-move 3345 57%
- line-move-visual 3339 57%
- vertical-motion 3132 53%
- jit-lock-function 3132 53%
- jit-lock-fontify-now 3131 53%
- jit-lock--run-functions 3112 53%
- run-hook-wrapped 3112 53%
- #<compiled 0x15629e8957cd> 3111 53%
- font-lock-fontify-region 3111 53%
- font-lock-default-fontify-region 3111 53%
- font-lock-fontify-syntactically-region 3082 53%
- python-font-lock-syntactic-face-function 3063 52%
- python-info-docstring-p 3055 52%
- python-nav-backward-sexp 3016 51%
- python-nav-forward-sexp 3007 51%
- python-nav--forward-sexp 2968 51%
- python-info-beginning-of-block-p 2005 34%
- python-info-beginning-of-statement-p 1670 28%
- python-nav-beginning-of-statement 1644 28%
- syntax-ppss 1392 23%
#<compiled 0x15629eb1977d> 1 0%
- python-info-line-ends-backslash-p 138 2%
- syntax-ppss 103 1%
#<compiled 0x15629ea9bac1> 1 0%
back-to-indentation 56 0%
- python-info-statement-starts-block-p 314 5%
- python-nav-beginning-of-statement 277 4%
- python-info-line-ends-backslash-p 112 1%
syntax-ppss 76 1%
- syntax-ppss 82 1%
#<compiled 0x15629ea55d29> 3 0%
back-to-indentation 33 0%
- python-info-end-of-block-p 385 6%
- python-info-end-of-statement-p 370 6%
- python-nav-end-of-statement 359 6%
- syntax-ppss 185 3%
#<compiled 0x15629eb2ece5> 2 0%
- python-info-line-ends-backslash-p 104 1%
- syntax-ppss 87 1%
#<compiled 0x15629ea943f5> 2 0%
- python-info-beginning-of-statement-p 274 4%
- python-nav-beginning-of-statement 252 4%
- python-info-line-ends-backslash-p 105 1%
- syntax-ppss 76 1%
#<compiled 0x15629eb1e6a1> 1 0%
syntax-ppss 72 1%
back-to-indentation 44 0%
- python-nav-beginning-of-statement 107 1%
- syntax-ppss 37 0%
#<compiled 0x15629eb2a9b5> 1 0%
- python-info-line-ends-backslash-p 29 0%
syntax-ppss 20 0%
back-to-indentation 21 0%
- python-nav--lisp-forward-sexp 63 1%
forward-sexp 58 0%
- python-info-current-line-empty-p 45 0%
match-string-no-properties 6 0%
- python-syntax-context-type 39 0%
syntax-ppss 28 0%
- python-info-statement-ends-block-p 2 0%
- python-nav-end-of-block 1 0%
- python-nav-beginning-of-block 1 0%
python-info-current-line-empty-p 1 0%
- python-nav-end-of-statement 1 0%
syntax-ppss 1 0%
syntax-after 2 0%
syntax-class 1 0%
- python-nav-beginning-of-statement 2 0%
syntax-ppss 2 0%
- python-info-assignment-statement-p 1 0%
- python-nav-beginning-of-statement 1 0%
python-info-line-ends-backslash-p 1 0%
syntax-ppss 18 0%
- font-lock-fontify-keywords-region 27 0%
#<compiled 0x15629e89743d> 11 0%
#<compiled 0x15629e897459> 7 0%
- run-with-timer 16 0%
- apply 16 0%
- run-at-time 15 0%
- timer-activate 13 0%
- timer--activate 12 0%
timer--time-less-p 12 0%
timer-relative-time 1 0%
- posn-at-point 50 0%
- jit-lock-function 40 0%
- jit-lock-fontify-now 39 0%
- jit-lock--run-functions 38 0%
- run-hook-wrapped 38 0%
- #<compiled 0x15629eb1cfd5> 38 0%
- font-lock-fontify-region 38 0%
- font-lock-default-fontify-region 36 0%
- font-lock-fontify-syntactically-region 33 0%
- python-font-lock-syntactic-face-function 33 0%
- python-info-docstring-p 32 0%
- python-nav-backward-sexp 26 0%
- python-nav-forward-sexp 26 0%
- python-nav--forward-sexp 25 0%
- python-syntax-context-type 7 0%
syntax-ppss 7 0%
- python-info-beginning-of-block-p 6 0%
python-info-statement-starts-block-p 4 0%
python-info-beginning-of-statement-p 1 0%
- python-nav-beginning-of-statement 4 0%
syntax-ppss 3 0%
python-info-line-ends-backslash-p 1 0%
- python-info-beginning-of-statement-p 2 0%
python-nav-beginning-of-statement 1 0%
- python-nav--lisp-forward-sexp 2 0%
forward-sexp 2 0%
- python-info-end-of-block-p 1 0%
python-info-end-of-statement-p 1 0%
python-info-current-line-empty-p 1 0%
python-nav-beginning-of-statement 2 0%
- python-info-assignment-statement-p 1 0%
- python-nav-beginning-of-statement 1 0%
- python-info-line-ends-backslash-p 1 0%
syntax-ppss 1 0%
- font-lock-fontify-keywords-region 3 0%
#<compiled 0x15629e89743d> 2 0%
- eval 6 0%
if 2 0%
mode-line-eol-desc 2 0%
file-remote-p 4 0%
- window-inside-pixel-edges 1 0%
window-edges 1 0%
- self-insert-command 51 0%
- python-indent-post-self-insert-function 48 0%
- syntax-ppss 48 0%
- syntax-propertize 6 0%
#<compiled 0x15629e89748d> 3 0%
syntax-ppss-flush-cache 1 0%
electric-indent-post-self-insert-function 1 0%
- jit-lock-after-change 1 0%
run-hook-with-args 1 0%
- kill-line 14 0%
- kill-region 14 0%
- kill-new 14 0%
- gui-select-text 12 0%
- gui-set-selection 12 0%
- gui-backend-set-selection 12 0%
- apply 11 0%
#<compiled 0x1fd8bb00bf7f> 11 0%
menu-bar-update-yank-menu 1 0%
- jit-lock--antiblink-post-command 35 0%
- syntax-ppss 29 0%
- syntax-propertize 5 0%
#<compiled 0x15629e89748d> 1 0%
- run-with-idle-timer 2 0%
- timer-set-idle-time 2 0%
timer--time-setter 2 0%
cancel-timer 1 0%
- undo-auto--add-boundary 3 0%
undo-auto--boundaries 1 0%
- execute-extended-command 6 0%
- sit-for 5 0%
redisplay 3 0%
- command-execute 1 0%
- call-interactively 1 0%
- funcall-interactively 1 0%
profiler-report 1 0%
- byte-code 19 0%
- read-extended-command 19 0%
- completing-read 19 0%
- completing-read-default 19 0%
- read-from-minibuffer 10 0%
- redisplay_internal (C function) 1 0%
- tool-bar-make-keymap 1 0%
- tool-bar-make-keymap-1 1 0%
- mapcar 1 0%
- #<compiled 0x1fd8bb03930b> 1 0%
- eval 1 0%
- find-image 1 0%
image-search-load-path 1 0%
+ ... 2303 39%
+ redisplay_internal (C function) 1 0%
The following report is from using M-x forward-line instead of C-n:
- redisplay_internal (C function) 1237 38%
- jit-lock-function 1212 37%
- jit-lock-fontify-now 1212 37%
- jit-lock--run-functions 1212 37%
- run-hook-wrapped 1212 37%
- #<compiled 0x15629ead2fe5> 1212 37%
- font-lock-fontify-region 1212 37%
- font-lock-default-fontify-region 1212 37%
- font-lock-fontify-syntactically-region 1196 37%
- python-font-lock-syntactic-face-function 1191 37%
- python-info-docstring-p 1189 36%
- python-nav-backward-sexp 1172 36%
- python-nav-forward-sexp 1168 36%
- python-nav--forward-sexp 1154 35%
- python-info-beginning-of-block-p 767 23%
- python-info-beginning-of-statement-p 666 20%
- python-nav-beginning-of-statement 656 20%
syntax-ppss 589 18%
- python-info-line-ends-backslash-p 44 1%
syntax-ppss 30 0%
back-to-indentation 11 0%
- python-info-statement-starts-block-p 97 3%
- python-nav-beginning-of-statement 84 2%
- python-info-line-ends-backslash-p 34 1%
syntax-ppss 22 0%
syntax-ppss 25 0%
back-to-indentation 11 0%
- python-info-end-of-block-p 162 5%
- python-info-end-of-statement-p 158 4%
- python-nav-end-of-statement 154 4%
syntax-ppss 80 2%
- python-info-line-ends-backslash-p 53 1%
syntax-ppss 46 1%
- python-info-beginning-of-statement-p 108 3%
- python-nav-beginning-of-statement 101 3%
- python-info-line-ends-backslash-p 43 1%
syntax-ppss 34 1%
syntax-ppss 27 0%
back-to-indentation 17 0%
- python-nav-beginning-of-statement 47 1%
- python-info-line-ends-backslash-p 20 0%
syntax-ppss 13 0%
syntax-ppss 17 0%
back-to-indentation 4 0%
- python-syntax-context-type 20 0%
syntax-ppss 18 0%
- python-nav--lisp-forward-sexp 16 0%
forward-sexp 15 0%
- python-info-current-line-empty-p 15 0%
match-string-no-properties 2 0%
- python-info-statement-ends-block-p 1 0%
python-nav-end-of-statement 1 0%
syntax-class 1 0%
syntax-after 1 0%
- python-nav-beginning-of-statement 5 0%
syntax-ppss 3 0%
- python-info-line-ends-backslash-p 2 0%
syntax-ppss 2 0%
- python-info-assignment-statement-p 1 0%
- python-nav-beginning-of-statement 1 0%
syntax-ppss 1 0%
syntax-ppss 3 0%
- replace-regexp-in-string 1 0%
apply 1 0%
- font-lock-fontify-keywords-region 15 0%
#<compiled 0x15629e89743d> 9 0%
#<compiled 0x15629e897459> 5 0%
- eval 9 0%
if 7 0%
- unless 1 0%
- if 1 0%
- display-graphic-p 1 0%
framep-on-display 1 0%
- tool-bar-make-keymap 5 0%
- tool-bar-make-keymap-1 5 0%
- mapcar 5 0%
- #<compiled 0x1fd8bb03930b> 5 0%
- eval 4 0%
- find-image 4 0%
image-search-load-path 3 0%
- #<compiled 0x1fd8bb05b46f> 3 0%
- apply 3 0%
- redisplay--pre-redisplay-functions 3 0%
- run-hook-with-args 2 0%
- redisplay--update-region-highlight 1 0%
#<compiled 0x1fd8baff3977> 1 0%
- mode-line-default-help-echo 3 0%
- window-at-side-p 2 0%
- window-pixel-edges 2 0%
window-edges 1 0%
file-remote-p 3 0%
x-gtk-map-stock 1 0%
- command-execute 988 30%
- call-interactively 986 30%
- funcall-interactively 889 27%
- kmacro-end-or-call-macro 617 19%
- kmacro-call-macro 617 19%
- call-last-kbd-macro 592 18%
- command-execute 540 16%
- call-interactively 531 16%
- byte-code 412 12%
- read-extended-command 412 12%
- completing-read 410 12%
- completing-read-default 409 12%
- read-from-minibuffer 48 1%
- command-execute 23 0%
- call-interactively 15 0%
- funcall-interactively 15 0%
- self-insert-command 7 0%
#<compiled 0x1fd8baffa1bd> 3 0%
- minibuffer-complete-and-exit 4 0%
- completion-complete-and-exit 4 0%
- completion--complete-and-exit 2 0%
- test-completion 2 0%
- #<compiled 0x1fd8baff9e61> 2 0%
- complete-with-action 2 0%
test-completion 2 0%
- minibuffer-inactive-mode 11 0%
- run-mode-hooks 7 0%
- run-hooks 7 0%
- global-font-lock-mode-enable-in-buffers 7 0%
- turn-on-font-lock-if-desired 7 0%
- turn-on-font-lock 7 0%
- font-lock-mode 7 0%
font-lock-default-function 3 0%
called-interactively-p 2 0%
- kill-all-local-variables 2 0%
global-eldoc-mode-cmhh 1 0%
- window--sanitize-window-sizes 3 0%
- walk-window-tree 2 0%
- walk-window-tree-1 2 0%
- #<compiled 0x15629e90c20d> 2 0%
- window-min-size 2 0%
- window--min-size-1 1 0%
window-size-fixed-p 1 0%
- frame-windows-min-size 2 0%
- window-min-size 2 0%
- window--min-size-1 1 0%
- window-size-fixed-p 1 0%
window--size-fixed-1 1 0%
clear-minibuffer-message 1 0%
#<compiled 0x15629ea97fd1> 1 0%
add-hook 1 0%
- funcall-interactively 116 3%
- self-insert-command 47 1%
- python-indent-post-self-insert-function 39 1%
- syntax-ppss 39 1%
- syntax-propertize 4 0%
#<compiled 0x15629e89748d> 2 0%
- electric-indent-post-self-insert-function 4 0%
- syntax-ppss 4 0%
syntax-propertize 1 0%
- jit-lock-after-change 2 0%
run-hook-with-args 1 0%
- execute-extended-command 42 1%
- sit-for 41 1%
- redisplay 2 0%
- redisplay_internal (C function) 2 0%
- jit-lock-function 2 0%
- jit-lock-fontify-now 2 0%
- jit-lock--run-functions 2 0%
- run-hook-wrapped 2 0%
- #<compiled 0x15629e917a4d> 2 0%
- font-lock-fontify-region 2 0%
- font-lock-default-fontify-region 2 0%
- font-lock-fontify-keywords-region 2 0%
#<compiled 0x15629e89743d> 2 0%
input-pending-p 2 0%
- kill-line 20 0%
- kill-region 18 0%
- kill-new 13 0%
- gui-select-text 10 0%
- gui-set-selection 10 0%
- gui-backend-set-selection 10 0%
- apply 10 0%
#<compiled 0x1fd8bb00bf7f> 10 0%
menu-bar-update-yank-menu 2 0%
- filter-buffer-substring 3 0%
- buffer-substring--filter 3 0%
- #<compiled 0x15629ea7fcf5> 3 0%
- apply 3 0%
- #<compiled 0x1fd8bafd224d> 3 0%
delete-and-extract-region 1 0%
back-to-indentation 1 0%
- jit-lock--antiblink-post-command 42 1%
syntax-ppss 36 1%
- run-with-idle-timer 1 0%
- timer-activate-when-idle 1 0%
- timer--activate 1 0%
timer--time-less-p 1 0%
global-font-lock-mode-check-buffers 2 0%
undo-auto--add-boundary 1 0%
- execute-extended-command 224 6%
- execute-extended-command--shorter 194 6%
- completion-try-completion 194 6%
- completion--nth-completion 194 6%
- completion--some 194 6%
- #<compiled 0x15629eb8865d> 194 6%
- completion-pcm-try-completion 127 3%
- completion-pcm--find-all-completions 124 3%
completion-pcm--all-completions 123 3%
- completion-pcm--merge-try 2 0%
completion-pcm--merge-completions 1 0%
completion-basic-try-completion 67 2%
- sit-for 17 0%
redisplay 14 0%
- command-execute 10 0%
- call-interactively 10 0%
- byte-code 5 0%
- completing-read 5 0%
- completing-read-default 5 0%
read-from-minibuffer 1 0%
- funcall-interactively 4 0%
- profiler-report 3 0%
- profiler-report-cpu 3 0%
- profiler-report-profile-other-window 3 0%
- profiler-report-setup-buffer 2 0%
- profiler-report-render-calltree 2 0%
- profiler-report-rerender-calltree 2 0%
- profiler-report-render-calltree-1 2 0%
- profiler-calltree-build 2 0%
- profiler-calltree-build-unified 2 0%
- maphash 2 0%
#<compiled 0x15629e778d71> 1 0%
- switch-to-buffer-other-window 1 0%
- pop-to-buffer 1 0%
- display-buffer 1 0%
- display-buffer--maybe-pop-up-frame-or-window 1 0%
- display-buffer--maybe-pop-up-window 1 0%
- display-buffer-pop-up-window 1 0%
window--maybe-raise-frame 1 0%
- python-mode 1 0%
python-indent-guess-indent-offset 1 0%
#<compiled 0x15629eacb3e5> 1 0%
- yank 26 0%
- push-mark 17 0%
mark 1 0%
insert-for-yank 5 0%
- current-kill 3 0%
- gui-selection-value 3 0%
- gui--selection-value-internal 3 0%
gui-get-selection 3 0%
- previous-line 9 0%
- line-move 9 0%
line-move-visual 7 0%
- profiler-report-toggle-entry 5 0%
- profiler-report-expand-entry 5 0%
- profiler-report-expand-entry 5 0%
- profiler-report-insert-calltree-children 5 0%
- mapc 5 0%
- profiler-report-insert-calltree 1 0%
- profiler-report-line-format 1 0%
- profiler-format 1 0%
- apply 1 0%
- profiler-format 1 0%
apply 1 0%
end-of-buffer 2 0%
- yank-pop 2 0%
insert-for-yank 1 0%
- kill-line 2 0%
- kill-region 2 0%
- kill-new 1 0%
- gui-select-text 1 0%
- gui-set-selection 1 0%
- gui-backend-set-selection 1 0%
- apply 1 0%
#<compiled 0x1fd8bb00bf7f> 1 0%
- filter-buffer-substring 1 0%
- buffer-substring--filter 1 0%
- #<compiled 0x15629e83a3c1> 1 0%
- apply 1 0%
- #<compiled 0x1fd8bafd224d> 1 0%
- delete-and-extract-region 1 0%
jit-lock-after-change 1 0%
- handle-focus-in 1 0%
- #<compiled 0x15629e827df9> 1 0%
- apply 1 0%
- blink-cursor--rescan-frames 1 0%
- blink-cursor-check 1 0%
- blink-cursor--start-idle-timer 1 0%
- run-with-idle-timer 1 0%
- timer-set-idle-time 1 0%
timer--time-setter 1 0%
- kmacro-start-macro-or-insert-counter 1 0%
kmacro-start-macro 1 0%
- byte-code 90 2%
- read-extended-command 80 2%
- completing-read 80 2%
- completing-read-default 80 2%
- read-from-minibuffer 46 1%
- undo-auto--add-boundary 2 0%
- undo-auto--boundaries 2 0%
undo-auto--ensure-boundary 2 0%
- redisplay_internal (C function) 2 0%
- tool-bar-make-keymap 1 0%
- tool-bar-make-keymap-1 1 0%
- mapcar 1 0%
- #<compiled 0x1fd8bb03930b> 1 0%
- eval 1 0%
- find-image 1 0%
- cond 1 0%
not 1 0%
- eval 1 0%
if 1 0%
- command-execute 1 0%
- call-interactively 1 0%
- funcall-interactively 1 0%
- self-insert-command 1 0%
electric-indent-post-self-insert-function 1 0%
- read-buffer-to-switch 10 0%
- read-buffer 10 0%
- completing-read-default 10 0%
- read-from-minibuffer 6 0%
- redisplay_internal (C function) 1 0%
x-gtk-map-stock 1 0%
- completing-read-default 7 0%
read-from-minibuffer 3 0%
+ ... 974 30%
+ timer-event-handler 6 0%
+ gui-set-selection 3 0%
+ deactivate-mark 2 0%
+ xselect-convert-to-string 1 0%
+ #<compiled 0x1fd8bb09a70d> 1 0%
clear-minibuffer-message 1 0%
+ undo-auto--add-boundary 1 0%
internal-timer-start-idle 1 0%
internal-echo-keystrokes-prefix 1 0%
BR,
Robert Thorpe
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997,2003 nCipher Corporation Ltd,
1994-97 Ian Jackson.