Re: [PERFORMANCE] Why some org code is so deep invoked?
Ihor Radchenko writes: > "Christopher M. Miles" writes: > >> After applying this patch, seems deep level has improved. > > Thanks for testing! > Applied onto main via 6ad65f333. > https://git.savannah.gnu.org/cgit/emacs/org-mode.git/commit/?id=6ad65f3332937dee81b1a7dc56a6dca7bd4865ae > Thanks for quick fixing. >> I attched the profiler report in attachments. > > May I know if you have a nil value of org-element-use-cache? Yes, it's `nil'. I will change it to `t' to test for a few days. Because I got stacktrace raised up many times before, so I disabled it. If I got more problem, I will report here. Thanks for asking. -- [ stardiviner ] I try to make every word tell the meaning that I want to express without misunderstanding. Blog: https://stardiviner.github.io/ IRC(libera.chat, freenode): stardiviner, Matrix: stardiviner GPG: F09F650D7D674819892591401B5DF1C95AE89AC3 signature.asc Description: PGP signature
Re: [PERFORMANCE] Why some org code is so deep invoked?
"Christopher M. Miles" writes: > After applying this patch, seems deep level has improved. Thanks for testing! Applied onto main via 6ad65f333. https://git.savannah.gnu.org/cgit/emacs/org-mode.git/commit/?id=6ad65f3332937dee81b1a7dc56a6dca7bd4865ae > I attched the profiler report in attachments. May I know if you have a nil value of org-element-use-cache? -- Ihor Radchenko, Org mode contributor, Learn more about Org mode at https://orgmode.org/. Support Org development at https://liberapay.com/org-mode, or support my work at https://liberapay.com/yantar92
Re: [PERFORMANCE] Why some org code is so deep invoked?
"Christopher M. Miles" writes: > 668 28%- > org-agenda-prepare-buffers > ... > 523 22% - > org--tag-add-to-alist I have a suspicion where the bottleneck is. Can you try the attached patch? >From 1f5cdbd05c7012962ba3f12671805d77f52d836e Mon Sep 17 00:00:00 2001 Message-Id: <1f5cdbd05c7012962ba3f12671805d77f52d836e.1660373309.git.yanta...@gmail.com> From: Ihor Radchenko Date: Sat, 13 Aug 2022 14:45:01 +0800 Subject: [PATCH] org-agenda-prepare-buffers: Avoid quadratic behavior when merging tags * lisp/org.el (org-agenda-prepare-buffers): Use the shortest list as the first argument in `org--tag-add-to-alist'. `org--tag-add-to-alist' is looping over the first argument. When we use the accumulated tags as the first argument, each buffer tag will need to be looped over N_buffers/2 times on average, creating quadratic complexity. Avoid this. Reported in https://orgmode.org/list/62f66552.050a0220.ed346.ac05smtpin_added_bro...@mx.google.com --- lisp/org.el | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lisp/org.el b/lisp/org.el index 4eef56f45..b21bdf291 100644 --- a/lisp/org.el +++ b/lisp/org.el @@ -15196,8 +15196,8 @@ (defun org-agenda-prepare-buffers (files) (append org-todo-keyword-alist-for-agenda org-todo-key-alist)) (setq org-tag-alist-for-agenda (org--tag-add-to-alist - org-tag-alist-for-agenda - org-current-tag-alist)) + org-current-tag-alist + org-tag-alist-for-agenda)) ;; Merge current file's tag groups into global ;; `org-tag-groups-alist-for-agenda'. (when org-group-tags -- 2.35.1 -- Ihor Radchenko, Org mode contributor, Learn more about Org mode at https://orgmode.org/. Support Org development at https://liberapay.com/org-mode, or support my work at https://liberapay.com/yantar92
Re: [PERFORMANCE] Why some org code is so deep invoked?
"Christopher M. Miles" writes: >> Also, I suggest to use M-x write-file in the profiler buffer when >> sharing something as deeply nested as you got. The resulting file is >> much more comfortable to view - it will preserve all the actual profiler >> data. > > I see, I tried it, it indeed kept the profiler data! > >> >> I will refrain from trying to deduce anything from the profiler for now. >> >> Please try to reproduce the report again and share it with us. Then, I >> will try to see if we can do anything on the Org side. > > Ok, I attached the new generated profiler reports. Oops. I was wrong about M-x write-file. Should be M-x profiler-report-write-profile Sorry for creating confusion. -- Ihor Radchenko, Org mode contributor, Learn more about Org mode at https://orgmode.org/. Support Org development at https://liberapay.com/org-mode, or support my work at https://liberapay.com/yantar92
Re: [PERFORMANCE] Why some org code is so deep invoked?
Bill Burdick writes: > You'll have this with recursive code and recursion is fairly normal in Lisp > programs. > > -- Bill I think this profiler report invocation stack is not recursive code. WDYT? > > On Fri, Aug 12, 2022 at 8:22 AM Christopher M. Miles > wrote: > > Ihor Radchenko writes: > > > "Christopher M. Miles" writes: > > > >> When I profiling Org Agenda generation, I found that org code is deeply > invoked in Emacs profiler report. > >> > >> My Question: > >> > >> - What reason caused this situation? > >> - Can Org Mode optimize those deeply invoked code? > > > > Could you please clarify what exactly is your problem? > > Is agenda generation slow? > > From the profiler report, you can see that Agenda is slow on clock table > generation because I have ~org-agenda-start-with-clockreport-mode~ > enabled. And this deep code invocation is from it too. It's about 5 > seconds to generate the org-agenda clock table. Actually I can tolerate > this time, Just found this performance issue when profiling and curious > to ask this question. > > > I do not see much issue with deep nesting of the code. > > Is this deep nested code normal in Emacs Lisp? > > Usually (based on my less than 20 times profiling experience), Emacs > wouldn't have deeper code than 40 levels. But my attachment profiler > report has more than 100 levels. > > If this is normal and fine, It's OK. I repeat, I ask this question for > curious purpose which want to get an answer for not important question. > > -- > > [ stardiviner ] > I try to make every word tell the meaning that I want to express without > misunderstanding. > > Blog: https://stardiviner.github.io/ > IRC(libera.chat, freenode): stardiviner, Matrix: stardiviner > GPG: F09F650D7D674819892591401B5DF1C95AE89AC3 -- [ stardiviner ] I try to make every word tell the meaning that I want to express without misunderstanding. Blog: https://stardiviner.github.io/ IRC(libera.chat, freenode): stardiviner, Matrix: stardiviner GPG: F09F650D7D674819892591401B5DF1C95AE89AC3 signature.asc Description: PGP signature
Re: [PERFORMANCE] Why some org code is so deep invoked?
Ihor Radchenko writes: > "Christopher M. Miles" writes: > >>> I do not see much issue with deep nesting of the code. >> >> Is this deep nested code normal in Emacs Lisp? >> >> Usually (based on my less than 20 times profiling experience), Emacs >> wouldn't have deeper code than 40 levels. But my attachment profiler >> report has more than 100 levels. >> >> If this is normal and fine, It's OK. I repeat, I ask this question for >> curious purpose which want to get an answer for not important question. > > It depends. You are looking at the complex code here, which is not > necessarily common. > > However, lisp nesting is tangent to performance. Shallow nesting can be > slow while deep nesting can be fast. Or vice versa. > I see, thanks for answering. >>> Could you please clarify what exactly is your problem? >>> Is agenda generation slow? >> >> From the profiler report, you can see that Agenda is slow on clock table >> generation because I have ~org-agenda-start-with-clockreport-mode~ >> enabled. And this deep code invocation is from it too. It's about 5 >> seconds to generate the org-agenda clock table. Actually I can tolerate >> this time, Just found this performance issue when profiling and curious >> to ask this question. > > Note that your profiler result does not look like taken from a 5 > second-lasting code: > > 390 13% - completing-read > > Completing read takes >10% *CPU time* of the 5 seconds? Suspicious. I'd > retry to get the profile. I re-profiled three times, around 4 seconds. > > Also, I suggest to use M-x write-file in the profiler buffer when > sharing something as deeply nested as you got. The resulting file is > much more comfortable to view - it will preserve all the actual profiler > data. I see, I tried it, it indeed kept the profiler data! > > I will refrain from trying to deduce anything from the profiler for now. > > Please try to reproduce the report again and share it with us. Then, I > will try to see if we can do anything on the Org side. Ok, I attached the new generated profiler reports. 1284 57% + command-execute 935 41% + ... 21 0% + timer-event-handler 2 0% + redisplay_internal (C function) 410,957,330 97% - command-execute 410,957,330 97% - call-interactively 405,537,622 95% - funcall-interactively 331,652,432 78%- org-agenda-redo-all 331,652,432 78% - if 331,651,376 78% - org-agenda-redo 331,651,376 78% - let* 331,649,112 78%- if 331,649,112 78% - progn 331,649,112 78% - let* 331,649,112 78% - eval 331,649,112 78%- let 331,649,112 78% - funcall 331,649,112 78% - # 331,649,112 78% - eval 331,649,112 78%- org-agenda-list 331,649,112 78% - catch 299,277,191 70% - let* 213,251,714 50% - if 213,105,362 50%- progn 213,105,362 50% - let 212,941,062 50% - setq 212,940,006 50% - apply 212,940,006 50%- org-clock-get-clocktable 212,940,006 50% + let 1,056 0% + org-plist-delete 124,712 0% + org-agenda-files 16,584 0%insert 7,764 0% + if 58,632 0%+ or 19,576 0%+ if 3,136 0%+ let* 78,430,580 18% + while 7,306,892 1% + org-agenda-finalize 148,040 0% add-text-properties 139,819 0% + org-agenda-files 48 0% + org-today 32,366,705 7% + org-agenda-prepare 4,160 0% + org-compile-prefix-format 1,024 0%+ or 1,056 0% + turn-on-ligature-mode 35,958,904 8%+ eyebrowse-create-window-config 30,440,458 7%+ org-agenda 6,646,049 1% delete-window 839,779 0%+ execute-extended-command 5,419,708 1% + byte-code 11,917,712 2% + redisplay_internal (C function) 280,655 0% + ... 1,984 0% + timer-event-handler 1,152 0% + corfu--auto-post-command 80 0% flyspell-post-command-hook 80 0% + indent-guide-pre-command-hook 80 0% + flycheck-maybe-display-error-at-point-soon -- [ stardiviner ] I try to make every word tell the meaning that I want to express without misunderstanding. Blog: https://stardiviner.github.io/ IRC(libera.chat, freenode): stardiviner, Matrix: stardiviner GPG: F09F650D7D674819892591401B5DF1C95AE89AC3
Re: [PERFORMANCE] Why some org code is so deep invoked?
"Christopher M. Miles" writes: >> I do not see much issue with deep nesting of the code. > > Is this deep nested code normal in Emacs Lisp? > > Usually (based on my less than 20 times profiling experience), Emacs > wouldn't have deeper code than 40 levels. But my attachment profiler > report has more than 100 levels. > > If this is normal and fine, It's OK. I repeat, I ask this question for > curious purpose which want to get an answer for not important question. It depends. You are looking at the complex code here, which is not necessarily common. However, lisp nesting is tangent to performance. Shallow nesting can be slow while deep nesting can be fast. Or vice versa. >> Could you please clarify what exactly is your problem? >> Is agenda generation slow? > > From the profiler report, you can see that Agenda is slow on clock table > generation because I have ~org-agenda-start-with-clockreport-mode~ > enabled. And this deep code invocation is from it too. It's about 5 > seconds to generate the org-agenda clock table. Actually I can tolerate > this time, Just found this performance issue when profiling and curious > to ask this question. Note that your profiler result does not look like taken from a 5 second-lasting code: 390 13% - completing-read Completing read takes >10% *CPU time* of the 5 seconds? Suspicious. I'd retry to get the profile. Also, I suggest to use M-x write-file in the profiler buffer when sharing something as deeply nested as you got. The resulting file is much more comfortable to view - it will preserve all the actual profiler data. I will refrain from trying to deduce anything from the profiler for now. Please try to reproduce the report again and share it with us. Then, I will try to see if we can do anything on the Org side. -- Ihor Radchenko, Org mode contributor, Learn more about Org mode at https://orgmode.org/. Support Org development at https://liberapay.com/org-mode, or support my work at https://liberapay.com/yantar92
Re: [PERFORMANCE] Why some org code is so deep invoked?
You'll have this with recursive code and recursion is fairly normal in Lisp programs. -- Bill On Fri, Aug 12, 2022 at 8:22 AM Christopher M. Miles wrote: > > Ihor Radchenko writes: > > > "Christopher M. Miles" writes: > > > >> When I profiling Org Agenda generation, I found that org code is deeply > invoked in Emacs profiler report. > >> > >> My Question: > >> > >> - What reason caused this situation? > >> - Can Org Mode optimize those deeply invoked code? > > > > Could you please clarify what exactly is your problem? > > Is agenda generation slow? > > From the profiler report, you can see that Agenda is slow on clock table > generation because I have ~org-agenda-start-with-clockreport-mode~ > enabled. And this deep code invocation is from it too. It's about 5 > seconds to generate the org-agenda clock table. Actually I can tolerate > this time, Just found this performance issue when profiling and curious > to ask this question. > > > I do not see much issue with deep nesting of the code. > > Is this deep nested code normal in Emacs Lisp? > > Usually (based on my less than 20 times profiling experience), Emacs > wouldn't have deeper code than 40 levels. But my attachment profiler > report has more than 100 levels. > > If this is normal and fine, It's OK. I repeat, I ask this question for > curious purpose which want to get an answer for not important question. > > -- > > [ stardiviner ] > I try to make every word tell the meaning that I want to express without > misunderstanding. > > Blog: https://stardiviner.github.io/ > IRC(libera.chat, freenode): stardiviner, Matrix: stardiviner > GPG: F09F650D7D674819892591401B5DF1C95AE89AC3 >
Re: [PERFORMANCE] Why some org code is so deep invoked?
Ihor Radchenko writes: > "Christopher M. Miles" writes: > >> When I profiling Org Agenda generation, I found that org code is deeply >> invoked in Emacs profiler report. >> >> My Question: >> >> - What reason caused this situation? >> - Can Org Mode optimize those deeply invoked code? > > Could you please clarify what exactly is your problem? > Is agenda generation slow? From the profiler report, you can see that Agenda is slow on clock table generation because I have ~org-agenda-start-with-clockreport-mode~ enabled. And this deep code invocation is from it too. It's about 5 seconds to generate the org-agenda clock table. Actually I can tolerate this time, Just found this performance issue when profiling and curious to ask this question. > I do not see much issue with deep nesting of the code. Is this deep nested code normal in Emacs Lisp? Usually (based on my less than 20 times profiling experience), Emacs wouldn't have deeper code than 40 levels. But my attachment profiler report has more than 100 levels. If this is normal and fine, It's OK. I repeat, I ask this question for curious purpose which want to get an answer for not important question. -- [ stardiviner ] I try to make every word tell the meaning that I want to express without misunderstanding. Blog: https://stardiviner.github.io/ IRC(libera.chat, freenode): stardiviner, Matrix: stardiviner GPG: F09F650D7D674819892591401B5DF1C95AE89AC3 signature.asc Description: PGP signature
Re: [PERFORMANCE] Why some org code is so deep invoked?
"Christopher M. Miles" writes: > When I profiling Org Agenda generation, I found that org code is deeply > invoked in Emacs profiler report. > > My Question: > > - What reason caused this situation? > - Can Org Mode optimize those deeply invoked code? Could you please clarify what exactly is your problem? Is agenda generation slow? I do not see much issue with deep nesting of the code. -- Ihor Radchenko, Org mode contributor, Learn more about Org mode at https://orgmode.org/. Support Org development at https://liberapay.com/org-mode, or support my work at https://liberapay.com/yantar92
[PERFORMANCE] Why some org code is so deep invoked?
When I profiling Org Agenda generation, I found that org code is deeply invoked in Emacs profiler report. My Question: - What reason caused this situation? - Can Org Mode optimize those deeply invoked code? I have option ~org-agenda-start-with-clockreport-mode~ enabled. And have lot files in ~org-agenda-files~ list: #+begin_src emacs-lisp (length org-agenda-files) #+end_src #+RESULTS[(2022-08-12 08:29:28) 1c2c57fd8db39360b33abd3465e5ebb26c817627]: : 46 And here is those files lines size: #+begin_src emacs-lisp :results value verbatim (sort (let ((return '())) (dolist (file org-agenda-files return) (when-let ((buffer (get-buffer (file-name-nondirectory file (with-current-buffer buffer (setf return (add-to-list 'return (count-lines (point-min) (point-max '>) #+end_src #+RESULTS[(2022-08-12 09:03:07) 2af183ec8f3ea19e280dc2c53e861b75c3e42b7a]: : (25455 12361 11772 10938 9530 8506 4457 3752 2316 2041 1277 1216 1196 1163 1006 1005 878 762 689 685 657 510 378 353 316 268 228 226 197 143 133 94 93 78 68 46 44 39 38 36 34 20 18 17 14 0) Here is the Emacs profiler reports in attachments: 1618 56% - command-execute 1618 56% - call-interactively 1228 42% - funcall-interactively 1224 42%- org-agenda 1224 42% - catch 1224 42% - let* 1193 41% - cond 1193 41%- call-interactively 1193 41% - funcall-interactively 1193 41% - org-agenda-list 1193 41% - catch 1119 39%- let* 1077 37% - if 1074 37% - progn 1074 37% - let 1073 37%- setq 1073 37% - apply 1073 37% - org-clock-get-clocktable 1073 37% - let 1073 37%- save-current-buffer 1073 37% - unwind-protect 1073 37% - progn 1072 37% - org-update-dblock 1072 37%- save-excursion 1072 37% - let* 1069 37% - funcall 1069 37% - org-dblock-write:clocktable 1069 37%- catch 1069 37% - let* 1033 36% - org-agenda-prepare-buffers 1033 36% - let 1032 35%- let 1032 35% - while 1032 35% - let 1032 35% - catch 1032 35%- save-current-buffer 999 34% - save-excursion 999 34% - save-restriction 577 20% - or 547 19%- org-refresh-stats-properties 547 19% - let* 547 19% - unwind-protect 547 19% - progn 547 19%- let 547 19% - save-excursion 547 19% - save-excursion 547 19% - save-restriction 547 19%- let 537 18% - progn 537 18% - let* 537 18% - let 537 18%- while 537 18% - let 536 18% - cond 459 16% - if 459 16%- progn 459 16% - let 443 15% - unwind-protect 443 15% - progn 441 15%- if 441 15% - if 441 15% - and 437 15%
