Closed Rutherther closed 1 month ago
Rutherther
commented
1 month ago Additionally since I named all the bridges I use, I've tried stopping all of those so the bot accounts don't get a chance to update anything temselves. This didn't solve anything
phil-s
commented
1 month ago You can fully-expand a node in the profile report with C-uRET
You want to read C-hig (elisp)Profiling
Rutherther
commented
1 month ago Right, that makes sense, should've read the manual thoroughly...
17169 94% - timer-event-handler
17169 94% - apply
17169 94% - plz--respond
17169 94% - #<compiled 0x8d5096906d58e94>
17165 94% - #<compiled -0xade022a6f6d61b0>
17165 94% - apply
17165 94% - ement--sync-callback
17165 94% - run-hook-with-args
17157 94% - ement-room-list-auto-update
17157 94% - revert-buffer
17157 94% - ement-room-list-revert
17157 94% - ement-room-list
17049 93% - taxy-magit-section-format-items
17049 93% - #<compiled -0xa7c2710a7245255>
17049 93% - #<compiled -0xa7c2710a7245255>
17029 93% - #<compiled -0xa7c2710a7245255>
15961 87% - #<compiled 0x1f264c6d0a102517>
15961 87% - #<compiled 0x1ccd7f36e7b5ed28>
15439 84% - ement-room-list-column-format-name
15362 84% - ement--room-display-name
15354 84% - #<compiled -0xa2f04426fcf8645>
15326 84% - mapcar
15318 84% - #<compiled -0xc0db1ca136f5bc5>
6335 34% - ement--user-displayname-in
1387 7% #<compiled 0x53b2892b14fda62>
12 0% - cl-remove-if-not
4 0% - cl-remove
4 0% - cl-delete
4 0% - #<compiled -0xd07981da80d5c6f>
4 0% apply
4 0% #<compiled -0x66e54a1270e5219>
72 0% truncate-string-to-width
5 0% - ement--room-direct-p
5 0% - #<compiled 0x1c375647c4cf9cae>
5 0% seq-contains-p
503 2% #<compiled 0x2689ac9dafa9eef>
8 0% - ement-room-list-column-format-latest
4 0% ement--human-format-duration
4 0% map-put!
3 0% - ement-room-list-column-format-notifications
3 0% - ement-room-notification-state
3 0% - map-nested-elt
3 0% - seq-reduce
3 0% - seq-do
3 0% - mapc
3 0% - #<compiled 0x1a0c8572a1b1c6fe>
3 0% - #<subr F616e6f6e796d6f75732d6c616d626461_anonymous_lambda_14>
3 0% map-elt
1068 5% - #<compiled -0xa7c2710a7245255>
1064 5% - #<compiled 0x1f264c6d0a102517>
1064 5% - #<compiled 0x1ccd7f36e7b5ed28>
972 5% #<compiled 0x2689ac9dafa9eef>
48 0% - ement-room-list-column-format-name
28 0% - ement--room-direct-p
28 0% - #<compiled 0x1c375647c4cf9cae>
24 0% - seq-contains-p
12 0% - seq-do
8 0% - mapc
4 0% #<compiled 0xa1508dc680577d0>
8 0% ement--room-display-name
4 0% truncate-string-to-width
4 0% - ement--room-unread-p
4 0% - map-nested-elt
4 0% - seq-reduce
4 0% - seq-do
4 0% - mapc
4 0% - #<compiled 0x1a0cbb08a1b1c6fe>
4 0% - #<subr F616e6f6e796d6f75732d6c616d626461_anonymous_lambda_14>
4 0% - map-elt
4 0% apply
16 0% - map-put!
16 0% - apply
12 0% - #<compiled 0x1fe906d3872180>
4 0% assoc
12 0% - ement-room-list-column-format-notifications
12 0% - ement-room-notification-state
8 0% - #<compiled -0x171045b66f07ec2e>
8 0% - map-nested-elt
8 0% - seq-reduce
8 0% - seq-do
8 0% - mapc
8 0% - #<compiled 0x1a0c833aa1b1c6fe>
8 0% - #<subr F616e6f6e796d6f75732d6c616d626461_anonymous_lambda_14>
8 0% - map-elt
4 0% apply
4 0% - cl-find-if
4 0% - cl-find
4 0% cl-position
4 0% - ement-room-list-column-format-topic
4 0% replace-regexp-in-string
4 0% map-elt
20 0% - #<compiled 0x1f264c6d0a102517>
20 0% - #<compiled 0x1ccd7f36e7b5ed28>
12 0% #<compiled 0x2689ac9dafa9eef>
4 0% - ement-room-list-column-format-name
4 0% ement--room-direct-p
4 0% - ement-room-list-column-format-🐱
4 0% map-elt
60 0% - taxy-fill
60 0% - #<compiled 0xd9ce7609f704410>
24 0% - #<lambda 0x5b7290e5d7>
24 0% - taxy-take-keyed
24 0% - taxy-take-keyed
24 0% - taxy-take-keyed
24 0% - taxy-take-keyed
24 0% - taxy-take-keyed
24 0% - taxy-take-keyed
24 0% - taxy-take-keyed
20 0% - taxy-take-keyed
20 0% - taxy-take-keyed
16 0% - #<lambda 0x9884c6d4680d254>
16 0% - when
16 0% - if
12 0% - cl-loop
8 0% - cl-block
4 0% - cl--block-wrapper
4 0% - catch
4 0% let*
4 0% #<compiled -0x118465efb9c3cb7a>
4 0% - taxy-take-keyed
4 0% - cl-find-if
4 0% - cl-find
4 0% - cl-position
4 0% cl--position
4 0% - #<lambda -0x1667dbc0235e70fe>
4 0% - when
4 0% - if
4 0% - cl-loop
4 0% #<compiled -0x18ca13412de6202b>
20 0% - #<lambda 0x5b7290e5d7>
20 0% - taxy-take-keyed
20 0% - taxy-take-keyed
20 0% - taxy-take-keyed
20 0% - taxy-take-keyed
20 0% - taxy-take-keyed
20 0% - taxy-take-keyed
20 0% - taxy-take-keyed
20 0% - taxy-take-keyed
16 0% - taxy-take-keyed
16 0% - taxy-take-keyed
12 0% - taxy-take-keyed
8 0% - taxy-take-keyed
8 0% - ement-room-list-key-space
8 0% - #<compiled -0xb12d938b9c3b04a>
8 0% - cl-find
8 0% - cl-position
4 0% - cl--position
4 0% ement-room-id
4 0% - ement-room-list-key-people
4 0% - ement--room-direct-p
4 0% - #<compiled 0x1c375647c4cf9cae>
4 0% seq-contains-p
4 0% - cl-find-if
4 0% - cl-find
4 0% cl-position
4 0% - #<lambda -0x1667dbc0235e6d66>
4 0% - when
4 0% - if
4 0% cl-loop
16 0% - #<lambda 0x5b7290e5d7>
16 0% - taxy-take-keyed
16 0% - taxy-take-keyed
16 0% - taxy-take-keyed
16 0% - taxy-take-keyed
16 0% - taxy-take-keyed
16 0% - taxy-take-keyed
16 0% - taxy-take-keyed
16 0% - taxy-take-keyed
16 0% - taxy-take-keyed
12 0% - taxy-take-keyed
8 0% - ement-room-list-key-people
8 0% - ement--room-direct-p
8 0% - #<compiled 0x1c375647c4cf9cae>
8 0% seq-contains-p
4 0% - taxy-take-keyed
4 0% - ement-room-list-key-people
4 0% - ement--room-direct-p
4 0% - #<compiled 0x1c375647c4cf9cae>
4 0% seq-contains-p
4 0% - #<lambda -0x1667dbc0235e6d66>
4 0% - when
4 0% if
36 0% - taxy-magit-section-insert
36 0% - #<compiled -0x1e8784fb555b0cfa>
36 0% - #<compiled -0x1aa0cdce6d225f87>
36 0% - #<compiled -0x1e8784fb555b0cfa>
36 0% - #<compiled -0x1fa4b3834370d217>
32 0% - #<compiled -0x1e8784fb555b0cfa>
32 0% - #<compiled 0x7c103c4459c9ae>
28 0% - #<compiled -0x1e8784fb555b0cfa>
24 0% - #<compiled -0x3bd58746dd0a204>
24 0% - #<compiled 0x10d6bdcfa45d7357>
12 0% - magit-insert-section--create
8 0% - run-hook-with-args-until-success
4 0% - magit-section-cached-visibility
4 0% - magit-section-ident
4 0% eieio-oref
4 0% taxy-magit-section-visibility
4 0% - apply
4 0% - ement-room-list-section
4 0% apply
4 0% - magit-insert-section--create
4 0% eieio-oset
4 0% - #<compiled 0x10d6bdcfa45d7357>
4 0% #<compiled 0x351f1af2b08050d>
4 0% #<compiled 0x10d6bdcfa45d7357>
8 0% - taxy-sort
8 0% - taxy-mapc*
8 0% - taxy-mapc-taxys
4 0% - #<compiled 0x485719bda9c4691>
4 0% - cl-sort
4 0% - #<compiled -0xd2b365d0d882dc3>
4 0% - #<compiled 0x1587f0a2f36a7ac6>
4 0% - ement--room-unread-p
4 0% map-nested-elt
4 0% - taxy-mapc-taxys
4 0% - #<compiled 0x1f478977502fc02>
4 0% cl-sort
4 0% - taxy-sort*
4 0% - taxy-mapc*
4 0% - taxy-mapc-taxys
4 0% - taxy-mapc-taxys
4 0% #<compiled 0xde8c33a96b565f4>
8 0% - ement--auto-sync
8 0% - ement--sync
8 0% - ement-api
8 0% - apply
8 0% plz
4 0% - plz--coding-system
4 0% coding-system-from-name
624 3% - command-execute
535 2% - funcall-interactively
334 1% - next-line
242 1% - line-move
12 0% - line-move-partial
9 0% - window-screen-lines
5 0% - window-inside-pixel-edges
2 0% window-edges
4 0% default-line-height
3 0% - default-line-height
1 0% default-font-height
8 0% default-line-height
201 1% - previous-line
178 0% - line-move
4 0% - line-move-partial
4 0% default-line-height
89 0% - byte-code
89 0% - read-extended-command
89 0% - read-extended-command-1
35 0% - completing-read-default
7 0% command-execute
377 2% + ...
26 0% + magit-section-post-command-hook
17 0% + redisplay_internal (C function)
12 0% internal-timer-start-idle
2 0% + magit-section-pre-command-hookI think you'll want to test https://github.com/alphapapa/ement.el/commit/2212b38ad3f1d12b5f84b4cf323439613ee05491
Rutherther
commented
1 month ago Maybe I should've been more specific. Yes, I know about it, I've tested it. alphapapa made it when I told them about the lags. It makes it a bit better, since it doesn't lag when doing operations with emacs quickly, but after I am idle for only a second, it usually lags again, if not right after the second, then after few more seconds.
phil-s
commented
1 month ago You can, of course, (setq ement-room-list-update-idle-delay N) to some N which is more than the 1 second value currently specified.
If you have ement-room-list-auto-update enabled at all then it's going to Do Things periodically, but the above lets you decide how often that might happen.
alphapapa
commented
1 month ago There are a few fundamental issues here:
So there are various possible ways to address these issues:
taxy-magit-section. There might be some caching that could be implemented. That probably won't happen anytime soon, as I have other priorities for the near future. Another possibility would be to see if individual rooms could be updated, but AFAIK magit-section doesn't really support that, so it's unlikely to work; and it might take a few hours of work just to find out.ement-tabulated-room-list library is still present. It may still work. It may work more quickly than the taxy-magit-section-based one, but it does no grouping. Maybe it could be an alternative for you.vtable-based room list. It would also have no grouping features, but it might render more quickly.None of these are great options, but they're all I know of now.
phil-s
commented
1 month ago @Rutherther, you should look into all the above suggestions first; but if you've tried everything you can and still can't get a good result, another option could be https://github.com/alphapapa/ement.el/pull/294#issuecomment-2313116728.
That (or rather a previous version of that code) was my workaround back when I was afflicted by a Matrix server bug which was having a somewhat similar effect to your issue.
Rutherther
commented
1 month ago --with-inputs=emacs-minimal=emacs to get everything native compiled). I set it to true and verified that stuff gets jit native compiled.
ie.
ement-room-list is an autoloaded interactive native-compiled Lisp
function in ‘ement-room-list.el’.Thanks for the suggestions, I will try to look into some of them, and probably as the most used workaround for now I will just close this buffer, as I do not need it very often.
alphapapa
commented
1 month ago
- So if any event from any of the rooms is received, the whole buffer gets redrawn now? Still it's strange that for me this redraw is slow compared to yours since you also are in many rooms.
When a sync response is received from the server, the room list buffer is updated, and that re-renders the whole buffer, because anything that was previously rendered could have changed.
3. Yes, Guix decided to disable jit native compilation by default - by making a patch that sets the default value of native-jit-compilation in low level C code - https://git.savannah.gnu.org/cgit/guix.git/tree/gnu/packages/patches/emacs-disable-jit-compilation.patch. That made stuff outside of Guix not native compile (apart from that also many emacs packages from Guix are made to not native compiled by default and one has to actively do something like `--with-inputs=emacs-minimal=emacs` to get everything native compiled).
Yes, see https://debbugs.gnu.org/cgi/bugreport.cgi?bug=71725
I set it to true and verified that stuff gets jit native compiled. ie.
ement-room-list is an autoloaded interactive native-compiled Lisp function in ‘ement-room-list.el’.
Ok, but that function is not what renders the room buffer, it just calls the functions that do. So you would need to verify that all of the relevant functions are native-compiled.
Thanks for the suggestions, I will try to look into some of them, and probably as the most used workaround for now I will just close this buffer, as I do not need it very often.
Ok.
phil-s
commented
1 month ago @alphapapa, I started using wip/debounce-room-list-update yesterday, and noticed that the idle timer was only going to fire once at most in any idle period, and I wasn't sure that was the intention (although it might be).
I started writing some more complicated idle-time code, and then thought "why not just check how long it's been since the last refresh vs the duration set by the user, and not refresh if it hasn't been long enough. So I did that, and then realised that didn't quite work either (as a long period between syncs could prevent the refresh from happening in any timely fashion).
Then I wrote myself this comment, and turned off my laptop for the day :)
;; What we ACTUALLY want (I think):
;;
;; - If time-since-refresh > threshold, update the buffer.
;; - Otherwise, `run-with-timer' or `timer-set-time'
;; as appropriate for a REGULAR (not-idle) timer,
;; to re-try the refresh in (threshold - time-since-refresh)
;; seconds from now.
;; - Regardless... once the refresh is actually triggered
;; (whether directly or by timer), run THAT using an
;; idle timer with a short delay (1s).
;; - Two new user options, for the two durations.
;; If either is nil, that part doesn't use a timer.
;;
;; This way:
;; - We don't refresh more frequently than every N seconds.
;; - We don't refresh while the user is actively doing things,
;; but rather wait until they've paused.And re-reading that, I'd be inclined to:
Does that sound like a good approach?
alphapapa
commented
1 month ago I don't know. We seem to be making it more complicated, which I'd like to avoid.
But another factor to consider is whether the room list buffer is visible. If it's not in a visible window, then it doesn't seem as urgent to update it, so an idle timer would seem to make sense. If the buffer is visible, I feel like it ought to be updated in real time, otherwise we'd be showing incorrect information to the user. So we might also need to use a function on the window configuration hook to update the buffer immediately if it becomes visible.
I still don't fully understand what the performance problem is. I am in 127 rooms--which isn't as many as 200, but if 200 were causing a significant delay, I'd expect 127 to cause a noticeable one too--and I notice no pauses from updating the buffer. So I also wonder whether users who are reporting problems are running the relevant code as interpreted, byte-compiled, or native-compiled, or some combination. I don't feel like we have enough information to understand what's really going on. There could also be something unusual going on, e.g. if a room's avatar image were very large, and it were having to be resized down to icon size on every redraw (which shouldn't happen, since that image does get cached, but who knows), then only users in such a room would have the problem. IOW this doesn't seem like a universal problem, which suggests there's more to it.
The ultimate solution might be to refactor taxy-magit-section to more effectively cache values between redraws. But that would be a lot of work, so I don't intend to do that soon.
phil-s
commented
1 month ago I'd intermittently experienced some performance issues from it in the past week or so, which is why I initially added your patch the other day, but I don't really have any insights -- most of the time it was fine, so it just seemed like the server was deciding to temporarily be super chatty for some reason. I don't recall having similar issues anytime recently, but maybe the server was updated and introduced something relatively noisy.
we might also need to use a function on the window configuration hook to update the buffer immediately if it becomes visible.
Yep, good idea. The buffer-local hook value works well for that sort of thing.
alphapapa
commented
1 month ago For future reference, I pushed v0.14.2 of taxy-magit-section today, which includes a minor performance optimization: https://github.com/alphapapa/taxy.el/tree/package/taxy-magit-section?tab=readme-ov-file#0142 I don't know if it will make a noticeable difference, but it may help a little.
Rutherther
commented
1 month ago So I also wonder whether users who are reporting problems are running the relevant code as interpreted, byte-compiled, or native-compiled, or some combination. I don't feel like we have enough information to understand what's really going on.
@alphapapa Okay, so how should I convince you it's native-compiled? is there an Emacs function that will say if the whole tree is native compiled, or should I send each function description output as I did for the one I already sent as an example?
Rutherther
commented
1 month ago For future reference, I pushed v0.14.2 of taxy-magit-section today, which includes a minor performance optimization: https://github.com/alphapapa/taxy.el/tree/package/taxy-magit-section?tab=readme-ov-file#0142 I don't know if it will make a noticeable difference, but it may help a little.
Switched to v0.14.2 and no observable difference for me
phil-s
commented
1 month ago @Rutherther would you like to give https://github.com/phil-s/ement.el/commit/6e696d56d2b32710d9e39d80019bdc99a57e4031 a try?
(setq ement-room-list--show-debug-messages nil) will silence the *Messages* saying what it's doing, but I'd encourage you to watch them while testing to get a feel for what it's doing.
The user options ement-room-list-update-interval and ement-room-list-update-idle-delay control the delays. You should set them to values which work for you. If you set them both to nil you get the behaviour of the current release version, and if you only set the idle delay you essentially get the behaviour of the previous patch. With both values non-nil you get the new behaviour.
I'm keen to know whether / to what extent this alleviates things for you.
Rutherther
commented
1 month ago Hello @phil-s, thanks for that. Yes, debouncing is solving part of the problem. But the underlying problem of rendering being slow is not solved. So Emacs still lags when it syncs, but not only that. Thanks to it being delayed I can actually start doing something in the ement room list, and notice that even toggling sections is causing this slowness for me. I suppose that also does the redraw of the whole buffer.
Rutherther
commented
1 month ago 46373 96% - ...
28177 58% - #<lambda 0x189e4f6bbe25258a>
28177 58% - progn
28177 58% - let
28177 58% - while
28177 58% - let
28177 58% - funcall
28177 58% - #<lambda 0xef1f897f362716f>
28177 58% - puthash
28177 58% - let*
28177 58% - while
28177 58% - setq
28177 58% - cons
28177 58% - funcall
28177 58% - #<lambda -0x1002b59e799cf870>
28177 58% - let*
28165 58% - funcall
28087 58% - ement-room-list-column-format-name
27994 58% - ement--room-display-name
27994 58% - let*
27986 58% - let
27970 58% - or
27970 58% - funcall
27906 57% - #<lambda 0x121001c773bbe1e2>
27906 57% - let*
27894 57% - if
27894 57% - string-join
27894 57% - delete-dups
27890 57% - mapcar
27886 57% - #<lambda 0x121001dcaa361c72>
27886 57% - ement--user-displayname-in
27882 57% - let*
27878 57% - if
27878 57% - let*
27854 57% - let*
27850 57% - and
27850 57% - or
27850 57% - let*
27387 56% - while
23417 48% - and
19897 41% - progn
11793 24% - if
8278 17% - funcall
3255 6% - #<lambda -0x1e870bd4ffb71f72>
2154 4% and
2877 5% setq
2142 4% setq
4 0% + progn
4 0% + if
20 0% + function
4 0% and
4 0% progn
4 0% + let
12 0% + and
64 0% + #<lambda 0x120e306f085321fe>
12 0% + setq
8 0% + function
57 0% + ement--room-unread-p
20 0% truncate-string-to-width
16 0% + ement--room-direct-p
66 0% + ement-room-list-column-format-notifications
8 0% + #<lambda 0x19b1fd14e15fe4>
4 0% + ement-room-list-column-format-latest
12 0% + let*
12352 25% - ement--push-joined-room-events
12352 25% - ement-notify
12352 25% - run-hook-with-args-until-success
12352 25% - ement-notify--event-mentions-session-user-p
12352 25% - ement-room--event-mentions-user-p
12352 25% - ement--user-displayname-in
12352 25% - let*
12352 25% - if
12352 25% - let*
12352 25% - let*
12352 25% - and
12352 25% - or
12352 25% - let*
12352 25% - while
12352 25% - and
12352 25% - progn
12348 25% - if
12348 25% - funcall
12344 25% - #<lambda -0x1e870bd4ffb71f72>
12344 25% - and
12316 25% - eq
10897 22% - progn
7459 15% - or
6355 13% - progn
4369 9% - and
1600 3% memq
24 0% + equal
3831 7% - #<lambda 0x189e4f6bbe25258a>
3831 7% - progn
3831 7% - let
3831 7% - while
3831 7% - let
3831 7% - funcall
3831 7% - #<lambda 0xef1f9e7f9b2c16f>
3831 7% - puthash
3831 7% - let*
3831 7% - while
3831 7% - setq
3831 7% - cons
3831 7% - funcall
3831 7% - #<lambda -0x1002b59e799cf870>
3831 7% - let*
3819 7% - funcall
3255 6% - ement-room-list-column-format-name
3239 6% - ement--room-display-name
3239 6% - let*
3222 6% - let
3218 6% - or
3218 6% - funcall
3206 6% - #<lambda 0x121001c773bbe1e2>
3206 6% - let*
3198 6% - if
3198 6% - string-join
3198 6% - delete-dups
3186 6% - mapcar
3186 6% - #<lambda 0x121001dcaa361c72>
3182 6% - ement--user-displayname-in
3178 6% - let*
3174 6% - if
3174 6% - let*
2388 4% - let*
2384 4% - and
2384 4% - or
2380 4% - let*
2007 4% while
4 0% + if
774 1% + function
4 0% and
8 0% + let
8 0% + and
12 0% + #<lambda 0x120e306f085321fe>
4 0% + setq
17 0% + function
16 0% truncate-string-to-width
512 1% + #<lambda 0x19b1fd14e15fe4>
44 0% + ement-room-list-column-format-notifications
4 0% + ement-room-list-column-format-latest
4 0% + ement-room-list-column-format-topic
8 0% + alist-get
4 0% + let*
2009 4% Automatic GC
4 0% + magit-section-ident
1664 3% + command-execute
64 0% + timer-event-handler
13 0% + magit-section-post-command-hook
7 0% evil-normal-post-command
4 0% + redisplay_internal (C function)
4 0% plz--stderr-sentinel
1 0% + which-key--hide-popup@alphapapa here as per your suggestion of re-evaluating everything, and obtaining profiler report for that. I hope that with interpretation the bottleneck as the same place as with compilation. This also isn't obtained from the timer sync, but from tabbing the sections. There the lag also occurs.
Based on this I've tried redefining ement--user-displayname-in as (defun ement--user-displayname-in (room user) "Steve") and the issue seems to be away for now. Of course that means there is couple of rooms with name Steve instead of the real one. :) But I am wondering... maybe this function could cache the displaynames or be optimized? Why is it taking so much time to get a display name?
Rutherther
commented
1 month ago The defun I presented is obviously not a good alternative to the function, but I am now trying
(defun ement--user-displayname-in (room user)
(or (ement-user-displayname user)
(ement-user-id user)))and although it still not 100% smooth with this and probably that debounce is good to have, it lowers the delay considerably to something much more pleasant for me.
phil-s
commented
1 month ago Well that's weird -- in the regular function there's a hash table caching the results of the expensive look-ups, so that should be fast.
Ah -- the hash table is not updated if it uses the fallback case. So that must be what's happening -- every time it tries and fails at the expensive look-up.
phil-s
commented
1 month ago So I think we just want to cache that case as well:
@@ -1658,8 +1658,9 @@
(calculated-name displayname))
(puthash user calculated-name (ement-room-displaynames room))
;; No membership state event: use pre-calculated displayname or ID.
- (or (ement-user-displayname user)
- (ement-user-id user))))))
+ (puthash user (or (ement-user-displayname user)
+ (ement-user-id user))
+ (ement-room-displaynames room))))))
(defun ement--xml-escape-string (string)
"Return STRING having been escaped with `xml-escape-string'.Thanks to both of you for narrowing down the problem.
AFAIR I intentionally didn't cache that case because, if a membership event for that user arrived later with the user's displayname in the room, having cached the result could prevent it from being used...although theoretically the handler for the event should take care of that...but I don't know off the top of my head if it actually does, or if it relies on this function to do the right thing.
Anyway, this does seem like the problem, iterating over all of a room's events repeatedly looking for a displayname event. It also explains why it doesn't happen to every user (i.e. we might not be in such rooms, or we might be in them but they might have very few events to iterate over). And it's good news that the taxy-magit-section code is apparently fast enough for this many rooms, that the problem lies elsewhere.
I'll implement a fix soon...
alphapapa
commented
1 month ago This should be fixed now. @Rutherther Please test the current HEAD of master and let me know if it performs better for you.
alphapapa
commented
1 month ago Targeted to v0.16 since the changes are a bit more involved.
Rutherther
commented
1 month ago it is much better with this. However, there is still observable delay in emacs render when I receive a new message. I will investigate and report with the functions that are causing this now based on the profiler report. I have not measured how much it is, but I think for this one the debouncer solution would also be fine solution for me.
alphapapa
commented
1 month ago @Rutherther Here's a patch that I used to see how often the room list buffer is being updated and how long it's taking. Please try it and collect some data (if you are willing, both with and without the commit https://github.com/alphapapa/ement.el/commit/b20fda0216e1bd3b575248a04ee97445dbb9766a). It would be helpful to have some hard numbers on exactly how long this is taking.
diff --git a/ement-room-list.el b/ement-room-list.el
index 0dbcff8..7d2c9a7 100644
--- a/ement-room-list.el
+++ b/ement-room-list.el
@@ -842,9 +842,13 @@ (defun ement-room-list-auto-update (_session)
(buffer-live-p (get-buffer "*Ement Room List*")))
(with-current-buffer (get-buffer "*Ement Room List*")
(unless (region-active-p)
- ;; Don't refresh the list if the region is active (e.g. if the user is trying to
- ;; operate on multiple rooms).
- (revert-buffer)))))
+ (let ((start-time (current-time)))
+ ;; Don't refresh the list if the region is active (e.g. if the user is trying to
+ ;; operate on multiple rooms).
+ (revert-buffer)
+ (message "Ement: Updated room list buffer at %s (elapsed: %s)."
+ (format-time-string "%H:%M:%S")
+ (format-seconds "%,2s" (time-subtract (current-time) start-time))))))))
(defun ement-room-list--timestamp-colors ()
"Return a vector of generated latest-timestamp colors for rooms.That's good idea, okay. Here with the optimization of the function
Ement: Updated room list buffer at 18:06:37 (elapsed: 2.96).
Ement: Updated room list buffer at 18:06:38 (elapsed: 1.87).
Ement: Updated room list buffer at 18:06:45 (elapsed: 0.28).
Ement: Updated room list buffer at 18:06:45 (elapsed: 0.24).
Ement: Updated room list buffer at 18:06:54 (elapsed: 0.25).
Ement: Updated room list buffer at 18:06:56 (elapsed: 2.50).
Ement: Updated room list buffer at 18:06:56 (elapsed: 0.28).
Ement: Updated room list buffer at 18:06:57 (elapsed: 0.27).
Ement: Updated room list buffer at 18:06:58 (elapsed: 0.26).
Ement: Updated room list buffer at 18:07:00 (elapsed: 2.92).
Ement: Updated room list buffer at 18:07:00 (elapsed: 0.28).
Ement: Updated room list buffer at 18:07:00 (elapsed: 0.25).
Ement: Updated room list buffer at 18:07:00 (elapsed: 0.27).
Ement: Updated room list buffer at 18:07:03 (elapsed: 2.39).
Ement: Updated room list buffer at 18:07:03 (elapsed: 0.28).
Ement: Updated room list buffer at 18:07:03 (elapsed: 0.24).
Ement: Updated room list buffer at 18:07:04 (elapsed: 0.28).
Ement: Updated room list buffer at 18:07:07 (elapsed: 2.35).
Ement: Updated room list buffer at 18:07:07 (elapsed: 0.29).
Ement: Updated room list buffer at 18:07:07 (elapsed: 0.28).
Ement: Updated room list buffer at 18:07:08 (elapsed: 0.28).
Ement: Updated room list buffer at 18:07:10 (elapsed: 2.24).
Ement: Updated room list buffer at 18:07:10 (elapsed: 0.18).Most of the time it's not so bad, but then there are a few where it takes more than 2 seconds. I've been sending myself messages to update it this many times in a few seconds. But still, if someone sent me longer message split to several, or mutliple group chats had activity, even that 0.2 would probably slow my typing, and be disturbing. (which is why I think debounce would still be a good idea if that is the final time it will settle at)
Here is before the commit
Ement: Updated room list buffer at 18:11:59 (elapsed: 1.95).
Ement: Updated room list buffer at 18:12:01 (elapsed: 1.49).
Ement: Updated room list buffer at 18:12:02 (elapsed: 1.93).
Ement: Updated room list buffer at 18:12:04 (elapsed: 1.04).
Ement: Updated room list buffer at 18:12:05 (elapsed: 1.89).
Ement: Updated room list buffer at 18:12:15 (elapsed: 4.50).
Ement: Updated room list buffer at 18:12:17 (elapsed: 2.77).
Ement: Updated room list buffer at 18:12:18 (elapsed: 1.95).
Ement: Updated room list buffer at 18:12:18 (elapsed: 1.93).
Ement: Updated room list buffer at 18:12:19 (elapsed: 1.97).
Ement: Updated room list buffer at 18:12:20 (elapsed: 1.98).
Ement: Updated room list buffer at 18:12:22 (elapsed: 2.91).
Ement: Updated room list buffer at 18:12:23 (elapsed: 1.91).
Ement: Updated room list buffer at 18:12:24 (elapsed: 1.95).
Ement: Updated room list buffer at 18:12:25 (elapsed: 1.94).
Ement: Updated room list buffer at 18:12:26 (elapsed: 1.93).
Ement: Updated room list buffer at 18:12:27 (elapsed: 1.89).
Ement: Updated room list buffer at 18:12:32 (elapsed: 4.14).
Ement: Updated room list buffer at 18:12:34 (elapsed: 2.50).
Ement: Updated room list buffer at 18:12:35 (elapsed: 1.98).
Ement: Updated room list buffer at 18:12:36 (elapsed: 1.97).
Ement: Updated room list buffer at 18:12:37 (elapsed: 1.93).
Ement: Updated room list buffer at 18:12:37 (elapsed: 1.92).
Ement: Updated room list buffer at 18:12:42 (elapsed: 4.91).
Ement: Updated room list buffer at 18:12:44 (elapsed: 2.51).
Ement: Updated room list buffer at 18:12:45 (elapsed: 1.95). [2 times]
Ement: Updated room list buffer at 18:12:56 (elapsed: 3.89).
Ement: Updated room list buffer at 18:12:59 (elapsed: 3.85).
Ement: Updated room list buffer at 18:13:02 (elapsed: 3.10).
Ement: Updated room list buffer at 18:13:03 (elapsed: 1.06).
Ement: Updated room list buffer at 18:13:04 (elapsed: 1.94).
Ement: Updated room list buffer at 18:13:05 (elapsed: 1.92).
Ement: Updated room list buffer at 18:13:06 (elapsed: 1.89).
Ement: Updated room list buffer at 18:13:13 (elapsed: 4.10).
Ement: Updated room list buffer at 18:13:15 (elapsed: 3.57).Never under a second, and sometimes even close to 5 seconds.
Rutherther
commented
1 month ago May I ask, how long does it take for you?
alphapapa
commented
1 month ago Thanks, that's helpful.
May I ask, how long does it take for you?
For me it takes 0.02-0.04 seconds, and less than 10% of the time it takes about 0.4 seconds (which is probably due to Emacs doing GC, which is out of our control).
So this helps me understand why it's so noticeable to you, because that's 1-2 orders of magnitude more than what I experience. But that doesn't explain why it's taking that long, since you're only in about 2x as many rooms as I am. More profiling is probably called for, with the recent changes.
Also, did you native-compile the code when doing that testing? i.e. I use M-x emacs-lisp-native-compile-and-load on ement-room-list.el.
Rutherther
commented
1 month ago I evaluated only the function I changed, so I didn't think native compilation is necessary at that point, since it only calls another function to do the update, or is it? I can try it once more with native comp if you want.
Rutherther
commented
1 month ago (by changed function I mean the one doing logging, then for the second test I used elpaca-build after reverting the commit to build the whole file, and restarted emacs)
alphapapa
commented
1 month ago What I mean is, the changes in https://github.com/alphapapa/ement.el/commit/b20fda0216e1bd3b575248a04ee97445dbb9766a need to be native-compiled (or at least, you must be careful to load the same kind of code when conducting the before/after tests). The function that's changed by the diff I shared, which times the execution and prints the message, needn't be native-compiled.
Icy-Thought
commented
1 month ago Experiencing the same issue but a lot less rooms, so I thought I should evaluate/compile the code in https://github.com/alphapapa/ement.el/issues/298#issuecomment-2365205019. What more logs do y'all need for me to gather?
Emacs info:
Ement: Updated room list buffer at 01:05:12 (elapsed: 0.02).
Mark saved where search started [2 times]
Invalid image size (see ‘max-image-size’) [3 times]
Ement: Updated room list buffer at 01:05:16 (elapsed: 1.78).
Mark saved where search started [2 times]
Invalid image size (see ‘max-image-size’) [3 times]
Ement: Updated room list buffer at 01:05:22 (elapsed: 1.84).
Invalid image size (see ‘max-image-size’) [5 times]
Ement: Updated room list buffer at 01:05:23 (elapsed: 1.37).
Invalid image size (see ‘max-image-size’) [6 times]
Ement: Updated room list buffer at 01:05:25 (elapsed: 1.30).
Invalid image size (see ‘max-image-size’) [6 times]
Ement: Updated room list buffer at 01:05:26 (elapsed: 1.35).
Invalid image size (see ‘max-image-size’) [6 times]
Ement: Updated room list buffer at 01:05:29 (elapsed: 1.31).
evil-line-move: End of buffer [2 times]
evil-line-move: End of bufferInvalid image size (see ‘max-image-size’)
Invalid image size (see ‘max-image-size’) [5 times]
Ement: Updated room list buffer at 01:05:36 (elapsed: 1.28).
Invalid image size (see ‘max-image-size’) [6 times]
Ement: Updated room list buffer at 01:05:40 (elapsed: 1.31).
Invalid image size (see ‘max-image-size’) [6 times]
Ement: Updated room list buffer at 01:06:11 (elapsed: 1.32).
Invalid image size (see ‘max-image-size’) [6 times]
Ement: Updated room list buffer at 01:06:12 (elapsed: 1.29).
Invalid image size (see ‘max-image-size’) [6 times]
Ement: Updated room list buffer at 01:06:27 (elapsed: 1.31).
Invalid image size (see ‘max-image-size’) [6 times]
Ement: Updated room list buffer at 01:06:29 (elapsed: 1.29).
Invalid image size (see ‘max-image-size’) [6 times]
Ement: Updated room list buffer at 01:06:30 (elapsed: 1.31).
Invalid image size (see ‘max-image-size’) [6 times]
Ement: Updated room list buffer at 01:06:33 (elapsed: 1.31).Invalid image size (see ‘max-image-size’) [6 times]
I guess the first question is where is this coming from, and is it a factor?
Edit: Answers are (a) image.c:
static void
image_size_error (void)
{
image_error ("Invalid image size (see `max-image-size')");
}and (b): I'm guessing it's not a factor, but I might be wrong -- and it does kinda look like the same aborted processing is happening repeatedly, which could be having a similar effect to the uncached values we saw earlier in this discussion.
You probably want to figure out which images are causing that, and see if you can test in their absence.
alphapapa
commented
1 month ago Experiencing the same issue but a lot less rooms, so I thought I should evaluate/compile the code in #298 (comment). What more logs do y'all need for me to gather?
Thanks. I'd suggest disabling ement-auto-sync and then profiling just revert-buffer in the room list buffer.
alphapapa
commented
1 month ago and (b): I'm guessing it's not a factor, but I might be wrong -- and it does kinda look like the same aborted processing is happening repeatedly, which could be having a similar effect to the uncached values we saw earlier in this discussion.
I've been seeing this myself sometimes, and I haven't mentioned it because it's so mysterious. My impression is that it started happening with this commit: https://github.com/alphapapa/taxy.el/commit/9e76b7fd59ba1ae096f520fb782adfed0077b21f
Which reminds me: @Icy-Thought What version of taxy-magit-section do you currently have loaded?
Anyway, I added some debugging code to show what value image-size is returning and for what image, and I saw that, when that image size error is shown, it's for a room avatar image (e.g. 2 out of all the ones I'm in), and the image width being computed was 3, which is, according to the relevant code in image.c, a valid size that should not trigger the error. At the same time, an image width of 5 and 2 were not triggering the error. And then, a few minutes later, the error stopped being triggered for the same images that were triggering it before, and AFAIK I hadn't done anything that could make a difference.
To be more specific, the computed image width I'm referring to is from (floor (car (image-size ...))); the actual image size cons-cell values were usually floats with repeating decimal places, but according to the docs and code, they should have been valid. I can't find any reason in the code for them to be triggering an error.
Also, if that commit did trigger the error, I don't understand why...although I suddenly have an idea: all of my visible frames are maximized, but maybe there's an invisible one that's tiny, and maybe it sometimes gets selected by the loop first...? ...Yeah, looks like it might be something like that: even though I only have one visible Emacs frame at the moment, look what this code returns:
(cl-loop for frame in (frame-list)
when (member (framep frame) '(x w32 ns pgtk))
collect (list frame (frame-width frame) (frame-height frame)))
;; ((#<frame 0x110250a0> 28 10) (#<frame *scratch* - GNU Emacs 0x277b0b0> 211 52))Now those numbers still look like they shouldn't cause an error, but if that first frame is some invisible one, who knows what its sizes might be at various times.
So I can probably fix that in taxy-magit-section soon by making sure the frame actually exists as a tangible (but not necessarily visible) one or something like that.
But IME that image-size error wasn't causing a performance problem, so I don't know if it's causing one for @Icy-Thought here. We'll have to wait for the profiler report.
Icy-Thought
commented
1 month ago I don't know how to profile individual functions tbh, so I just attached the whole profiling data to this message. profile.txt
What version of taxy-magit-section do you currently have loaded?
installed version: 0.14.2 b7b60a4
phil-s
commented
1 month ago even though I only have one visible Emacs frame at the moment, look what this code returns
Yep, there's always one frame at minimum, which means that if you run Emacs as as daemon there's always that invisible initial frame behind the scenes.
(This is a notorious reason for people's frame-based tweaks in their init file suddenly 'breaking' when they start using a daemon, as things start getting applied to the invisible frame instead.)
Edit: Oh, no your case is something different? Or, at least, I see t from framep for an initial frame if I run a daemon... but maybe if you run a daemon from a desktop session or something other than a terminal, it winds up not being t? I don't know. I haven't the foggiest what going on there, at any rate.
alphapapa
commented
1 month ago even though I only have one visible Emacs frame at the moment, look what this code returns
Yep, there's always one frame at minimum, which means that if you run Emacs as as daemon there's always that invisible initial frame behind the scenes.
(This is a notorious reason for people's frame-based tweaks in their init file suddenly 'breaking' when they start using a daemon, as things start getting applied to the invisible frame instead.)
@phil-s Yep, I think that explains it.
Edit: Oh, no your case is something different!
It is? Why do you say that?
phil-s
commented
1 month ago Too quick for me :) I just added this:
Edit: Oh, no your case is something different? Or, at least, I see t from framep for an initial frame if I run a daemon... but maybe if you run a daemon from a desktop session or something other than a terminal, it winds up not being t? I don't know. I haven't the foggiest what going on there, at any rate.
alphapapa
commented
1 month ago I don't know how to profile individual functions tbh, so I just attached the whole profiling data to this message. profile.txt
What version of taxy-magit-section do you currently have loaded?
installed version: 0.14.2 b7b60a4
I still see automatic sync responses in that profiler report, so it would seem that ement-auto-sync wasn't disabled.
Also, there are many byte-compiled functions involved. It would help to M-x find-library on taxy-magit-section and ement-room-list and eval-buffer on each of them before running the profiler, that way the functions won't be obscured by byte-compilation.
alphapapa
commented
1 month ago Edit: Oh, no your case is something different? Or, at least, I see
tfromframepfor an initial frame if I run a daemon... but maybe if you run a daemon from a desktop session or something other than a terminal, it winds up not beingt? I don't know. I haven't the foggiest what going on there, at any rate.
Yeah, now I'm a bit confused too: server-mode is t, and I can run emacsclient -c and get a new frame of the same Emacs process...but I can't find where in my config server-mode is being enabled. Which is quite strange, since I haven't touched that part of my config for a long time... shrug
alphapapa
commented
1 month ago Anyway, it seems like the key is frame-visible-p:
(cl-loop for frame in (frame-list)
when (member (framep frame) '(x w32 ns pgtk))
collect (list frame (frame-visible-p frame) (frame-width frame) (frame-height frame)))
;; ((#<frame 0x18cde470> nil 25 10)
;; (#<frame *scratch* 0x97bbe98> t 211 52)
;; (#<frame *Ement Notifications* 0x277b0b0> t 211 52))So I think the code in taxy-magit-section needs to be:
(cl-loop for frame in (frame-list)
when (and (frame-visible-p frame)
(memq (framep frame)
'(x w32 ns pgtk)))
return frame)I'm guessing that will fix the image-size error.
I'm not sure if that will have any effect on performance, but we'll see.
alphapapa
commented
1 month ago Just pushed v0.14.3 of taxy-magit-section, which I hope will fix the "invalid image size" error (which might also help with performance, but I don't know).
Icy-Thought
commented
1 month ago The update you pushed to taxy-magit-section seems to have reduced the lag for me to such an extent that it has become unnoticeable? As for the profiler-report:
1401 87% - command-execute
1400 87% - byte-code
1323 82% - ement-room-read-string
1323 82% - read-from-minibuffer
598 37% - corfu--post-command
598 37% - corfu--exhibit
598 37% - apply
598 37% - #<byte-code-function 126>
598 37% - apply
598 37% - #<byte-code-function 700>
583 36% - corfu--update
576 35% - corfu--recompute
575 35% - corfu--filter-completions
575 35% - apply
575 35% - completion-all-completions
575 35% - apply
575 35% - #<native-comp-function completion-all-completions>
575 35% - completion--nth-completion
575 35% - seq-some
575 35% - seq-do
575 35% - mapc
575 35% - #<byte-code-function B2C>
575 35% - #<byte-code-function E23>
575 35% - orderless-all-completions
573 35% - orderless--filter
573 35% - all-completions
571 35% - #<native-comp-function F616e6f6e796d6f75732d6c616d626461_anonymous_lambda_56>
571 35% - complete-with-action
571 35% - all-completions
23 1% - #<byte-code-function 015>
12 0% - #<byte-code-function 2AD>
8 0% - commandp
1 0% - interactive-form
1 0% - oclosure-interactive-form
1 0% - apply
1 0% - #<byte-code-function 422>
1 0% - advice--interactive-form
1 0% advice--interactive-form-1
2 0% - command-completion-default-include-p
1 0% - command-completion-using-modes-p
1 0% - command-completion-with-modes-p
1 0% - seq-intersection
1 0% - seq-reduce
1 0% - seq-do
1 0% - mapc
1 0% - #<byte-code-function 07A>
1 0% - #<byte-code-function 011>
1 0% - seq-contains-p
1 0% - seq-do
1 0% - mapc
1 0% - #<byte-code-function 046>
1 0% eq
1 0% version-to-list
2 0% - #<byte-code-function FC1>
2 0% - complete-with-action
2 0% - #<byte-code-function 0C4>
2 0% - complete-with-action
2 0% - #<byte-code-function ECE>
1 0% - complete-with-action
1 0% all-completions
1 0% - cape--dict-list
1 0% - apply
1 0% - process-lines-ignore-status
1 0% - process-lines-handling-status
1 0% call-process
2 0% - orderless--compile
2 0% - orderless-compile
1 0% - orderless--compile-component
1 0% - rx-to-string
1 0% - rx--translate
1 0% - rx--translate-form
1 0% - rx--translate-or
1 0% - rx--translate
1 0% - rx--translate-form
1 0% - rx--translate-regexp
1 0% string-match
1 0% corfu--move-prefix-candidates-to-front
7 0% - redisplay
7 0% - redisplay_internal (C function)
2 0% - redisplay--pre-redisplay-functions
1 0% - run-hook-with-args
1 0% - cursor-sensor--move-to-tangible
1 0% - cursor-sensor-move-to-tangible
1 0% set-window-parameter
9 0% - corfu--candidates-popup
6 0% - corfu--popup-show
4 0% erase-buffer
1 0% window-inside-pixel-edges
1 0% mapconcat
1 0% - #<byte-code-function 3A5>
1 0% - apply
1 0% orderless--highlight
1 0% - corfu--affixate
1 0% - #<byte-code-function 42D>
1 0% - kind-icon-formatted
1 0% default-font-width
4 0% posn-at-point
2 0% - corfu-quit
2 0% - completion-in-region-mode
1 0% called-interactively-p
282 17% - timer-event-handler
282 17% - apply
231 14% - corfu--auto-complete-deferred
163 10% - corfu--exhibit
163 10% - apply
163 10% - #<byte-code-function 126>
163 10% - apply
163 10% - #<byte-code-function 700>
150 9% - corfu--update
150 9% - redisplay
148 9% - redisplay_internal (C function)
14 0% - eval
6 0% - doom-modeline-format--main
3 0% - doom-modeline-string-pixel-width
3 0% - string-pixel-width
3 0% buffer-text-pixel-size
3 0% - format-mode-line
3 0% - eval
1 0% - doom-modeline-segment--vcs
1 0% - doom-modeline-display-icon
1 0% - doom-modeline-propertize-icon
1 0% - doom-modeline-icon-displayable-p
1 0% featurep
1 0% doom-modeline-segment--indent-info
1 0% - doom-modeline-segment--github
1 0% - doom-modeline-icon
1 0% nerd-icons--function-name
4 0% - doom-modeline-segment--buffer-info
4 0% - doom-modeline-update-buffer-file-state-icon
4 0% - doom-modeline-buffer-file-state-icon
4 0% - doom-modeline-icon
4 0% - apply
4 0% - nerd-icons-mdicon
4 0% assoc
1 0% - doom-modeline-segment--buffer-encoding
1 0% doom-modeline-face
1 0% - doom-modeline-segment--debug
1 0% propertize
1 0% - doom-modeline-segment--modals
1 0% - doom-modeline--modal-icon
1 0% - doom-modeline-icon
1 0% - apply
1 0% nerd-icons-mdicon
1 0% - doom-modeline-segment--major-mode
1 0% - format-mode-line
1 0% eval
4 0% - redisplay--pre-redisplay-functions
4 0% - run-hook-with-args
2 0% - org-modern--pre-redisplay
2 0% default-font-width
1 0% - doom-modeline-set-selected-window
1 0% - doom-modeline--selected-window
1 0% frame-selected-window
1 0% - cursor-sensor--move-to-tangible
1 0% - cursor-sensor-move-to-tangible
1 0% set-window-parameter
7 0% - corfu--candidates-popup
4 0% - corfu--popup-show
2 0% - corfu--make-buffer
2 0% - use-local-map
2 0% - apply
2 0% - evil--do-normalize-keymaps
2 0% - evil-normalize-keymaps
2 0% - evil-state-keymaps
2 0% - evil-state-auxiliary-keymaps
1 0% current-active-maps
1 0% - evil-get-auxiliary-keymap
1 0% lookup-key
1 0% - corfu--make-frame
1 0% frame-parameters
1 0% - mapconcat
1 0% #<byte-code-function D15>
2 0% - corfu--format-candidates
2 0% truncate-string-to-width
1 0% - #<byte-code-function 988>
1 0% - apply
1 0% - orderless--highlight
1 0% string-match
5 0% - corfu-quit
5 0% - completion-in-region-mode
5 0% - apply
5 0% - run-hooks
2 0% - #:corfu--teardown
2 0% - corfu--teardown
2 0% - apply
2 0% - #<interpreted-function EE3>
2 0% - evil-normalize-keymaps
2 0% - evil-initialize-local-keymaps
2 0% local-variable-p
1 0% - #:corfu--teardown
1 0% remove-hook
1 0% - #:corfu--teardown
1 0% - corfu--teardown
1 0% - apply
1 0% - #<interpreted-function EE3>
1 0% - evil-normalize-keymaps
1 0% - evil-state-keymaps
1 0% - evil-state-auxiliary-keymaps
1 0% - evil-get-auxiliary-keymap
1 0% lookup-key
1 0% - #:corfu--teardown
1 0% - corfu--teardown
1 0% - apply
1 0% - #<interpreted-function EE3>
1 0% - evil-normalize-keymaps
1 0% - evil-state-keymaps
1 0% - evil-state-auxiliary-keymaps
1 0% - evil-get-auxiliary-keymap
1 0% lookup-key
1 0% posn-at-point
66 4% - run-hook-wrapped
66 4% - corfu--capf-wrapper
61 3% - completion-try-completion
61 3% - completion--nth-completion
60 3% - seq-some
60 3% - seq-do
60 3% - mapc
60 3% - #<byte-code-function 325>
60 3% - #<byte-code-function 023>
54 3% - orderless-try-completion
47 2% - completion-emacs21-try-completion
35 2% - #<byte-code-function 169>
35 2% - complete-with-action
35 2% - #<byte-code-function 861>
35 2% - complete-with-action
35 2% - #<byte-code-function A9D>
34 2% - cape--dict-list
33 2% - apply
33 2% - process-lines-ignore-status
33 2% - process-lines-handling-status
29 1% call-process
2 0% - #<byte-code-function 4D6>
2 0% - kill-buffer
1 0% - replace-buffer-in-windows
1 0% unrecord-window-buffer
1 0% format
1 0% - complete-with-action
1 0% try-completion
12 0% - #<byte-code-function CEA>
6 0% - complete-with-action
6 0% try-completion
6 0% - #<byte-code-function 340>
6 0% - ement-room--member-names-and-ids
6 0% delete-dups
7 0% - orderless--filter
7 0% - all-completions
7 0% - #<byte-code-function CEA>
5 0% - complete-with-action
5 0% all-completions
2 0% - #<byte-code-function 340>
2 0% - ement-room--member-names-and-ids
1 0% delete-dups
1 0% - maphash
1 0% #<byte-code-function F13>
6 0% - completion-basic-try-completion
6 0% - #<byte-code-function CEA>
4 0% - complete-with-action
4 0% try-completion
2 0% - #<byte-code-function 340>
2 0% - ement-room--member-names-and-ids
1 0% delete-dups
1 0% ement--user-displayname-in
1 0% - completion-metadata-get
1 0% - apply
1 0% - nerd-icons-completion-completion-metadata-get
1 0% #<advice 5EC>
4 0% - cape-dict
2 0% - cape--bounds
2 0% - bounds-of-thing-at-point
1 0% - #<byte-code-function 042>
1 0% - forward-thing
1 0% forward-word
1 0% - #<byte-code-function CB9>
1 0% forward-thing
2 0% cape--properties-table
1 0% - ement-room--complete-rooms-at-point
1 0% re-search-backward
1 0% corfu--auto-tick
1 0% - corfu--setup
1 0% - apply
1 0% - #<interpreted-function E31>
1 0% - evil-normalize-keymaps
1 0% - evil-state-keymaps
1 0% evil-state-auxiliary-keymaps
32 1% - savehist-autosave
32 1% - savehist-save
15 0% prin1
8 0% read
3 0% - savehist-printable
2 0% prin1
1 0% read
2 0% write-region
1 0% md5
13 0% - corfu--hide-frame-deferred
11 0% make-frame-invisible
2 0% erase-buffer
2 0% - ement-room--send-typing
2 0% - ement-api
2 0% - apply
2 0% - plz
2 0% make-process
2 0% - show-paren-function
2 0% - apply
2 0% - evil--match-paren-in-normal-state
2 0% - apply
2 0% - #<native-comp-function show-paren-function>
2 0% - show-paren--default
2 0% - show-paren--locate-near-paren
2 0% back-to-indentation
1 0% - plz--respond
1 0% - #<byte-code-function A8F>
1 0% - plz--coding-system
1 0% - coding-system-from-name
1 0% canonicalize-coding-system-name
1 0% - #<native-comp-function F616e6f6e796d6f75732d6c616d626461_anonymous_lambda_9>
1 0% jit-lock-context-fontify
270 16% - redisplay_internal (C function)
23 1% - eval
9 0% - doom-modeline-format--main
5 0% - doom-modeline-string-pixel-width
5 0% - string-pixel-width
4 0% buffer-text-pixel-size
4 0% - format-mode-line
2 0% - eval
2 0% - doom-modeline-segment--buffer-encoding
2 0% define-key
6 0% - doom-modeline-segment--buffer-info
5 0% - doom-modeline-update-buffer-file-state-icon
4 0% - doom-modeline-buffer-file-state-icon
4 0% - doom-modeline-icon
4 0% - apply
4 0% - nerd-icons-mdicon
4 0% assoc
1 0% file-remote-p
1 0% - doom-modeline-display-icon
1 0% doom-modeline--active
2 0% - doom-modeline-segment--vcs
2 0% - doom-modeline-display-icon
2 0% - doom-modeline-propertize-icon
2 0% - doom-modeline-icon-displayable-p
2 0% featurep
1 0% - doom-modeline-segment--buffer-position
1 0% string-replace
1 0% - doom-modeline-segment--bar
1 0% - doom-modeline--font-height
1 0% window-font-height
1 0% - centaur-tabs-line
1 0% centaur-tabs-hide-tab-cached
1 0% - doom-modeline-segment--workspace-name
1 0% frame-parameter
1 0% - doom-modeline-segment--modals
1 0% boundp
1 0% - doom-modeline-segment--major-mode
1 0% - doom-modeline-face
1 0% doom-modeline--active
11 0% - redisplay--pre-redisplay-functions
7 0% - run-hook-with-args
4 0% - org-modern--pre-redisplay
4 0% default-font-width
2 0% - redisplay--update-region-highlight
1 0% #<advice FAF>
1 0% - doom-modeline-set-selected-window
1 0% minibuffer-selected-window
1 0% - centaur-tabs-on-window-buffer-change
1 0% - centaur-tabs-buffer-update-groups
1 0% - mapcar
1 0% - #<byte-code-function 66F>
1 0% - centaur-tabs-buffer-groups
1 0% - centaur-tabs-project-name
1 0% - project-current
1 0% - project--find-in-directory
1 0% - run-hook-with-args-until-success
1 0% - project-try-vc
1 0% - locate-dominating-file
1 0% - #<byte-code-function 69D>
1 0% directory-files
14 0% - command-execute
11 0% - funcall-interactively
11 0% - self-insert-command
3 0% - electric-pair-post-self-insert-function
3 0% - electric-pair-syntax-info
1 0% - syntax-ppss
1 0% parse-partial-sexp
2 0% evil-track-last-insertion
1 0% electric-indent-post-self-insert-function
1 0% syntax-ppss-flush-cache
2 0% interactive-form
6 0% - corfu--auto-post-command
2 0% timer-relative-time
2 0% - cancel-timer
2 0% timerp
2 0% timer-activate
4 0% - gcmh-register-idle-gc
4 0% - run-with-timer
4 0% - run-at-time
4 0% timer-relative-time
3 0% - evil-repeat-pre-hook
2 0% - evil-repeat-force-abort-p
1 0% evil-emacs-state-p
1 0% this-command-keys-vector
1 0% - evil--repeat-type
1 0% functionp
2 0% - minibuffer-mode
1 0% - run-mode-hooks
1 0% - run-hooks
1 0% - global-treesit-auto-mode-enable-in-buffer
1 0% require
2 0% - evil-collection-minibuffer-insert
2 0% - evil-insert
2 0% - if
2 0% - evil-insert-state
1 0% - evil-change-state
1 0% - evil-insert-state
1 0% - evil-set-marker
1 0% - apply
1 0% - #<byte-code-function C41>
1 0% markerp
1 0% - evil-local-mode
1 0% - evil-initialize-state
1 0% - evil-change-state
1 0% - evil-insert-state
1 0% - run-hooks
1 0% - evil-start-track-last-insertion
1 0% add-hook
2 0% - internal-timer-start-idle
1 0% timerp
2 0% - evil--jump-handle-buffer-crossing
2 0% window-list
1 0% - undo-auto--add-boundary
1 0% - undo-auto--boundaries
1 0% undo-auto--ensure-boundary
1 0% minibuffer-inactive-mode
73 4% - read-extended-command
73 4% - read-extended-command-1
72 4% - completing-read-default
72 4% - apply
72 4% - vertico--advice
72 4% - apply
72 4% - #<native-comp-function completing-read-default>
27 1% - vertico--exhibit
20 1% - vertico--update
14 0% - redisplay
14 0% - redisplay_internal (C function)
1 0% redisplay--pre-redisplay-functions
6 0% - vertico--recompute
4 0% - vertico-sort-history-length-alpha
1 0% gethash
1 0% append
1 0% - mapcan
1 0% - #<byte-code-function 493>
1 0% - sort
1 0% #<primitive-function string-lessp>
1 0% - sort
1 0% #<byte-code-function 1E5>
2 0% - vertico--filter-completions
2 0% - apply
2 0% - completion-all-completions
2 0% - apply
2 0% - #<native-comp-function completion-all-completions>
2 0% - completion--nth-completion
2 0% - completion-metadata-get
1 0% - apply
1 0% nerd-icons-completion-completion-metadata-get
7 0% - vertico--arrange-candidates
6 0% - vertico--affixate
6 0% - #<byte-code-function 98A>
6 0% - #<byte-code-function DE4>
6 0% - apply
6 0% - marginalia--affixate
3 0% - marginalia--cached
3 0% - marginalia-annotate-command
2 0% - marginalia--function-doc
2 0% - documentation
2 0% - substitute-command-keys
1 0% - help--describe-map-tree
1 0% describe-map
1 0% buffer-string
1 0% - marginalia-annotate-binding
1 0% where-is-internal
3 0% - select-window
3 0% - apply
3 0% - evil--sw-refresh-cursor
3 0% - evil-refresh-cursor
2 0% frame-parameter
1 0% evil-state-property
1 0% - vertico--format-candidate
1 0% - apply
1 0% - #<byte-code-function 8E5>
1 0% apply
25 1% - redisplay_internal (C function)
1 0% - eval
1 0% - doom-modeline-format--main
1 0% - doom-modeline-string-pixel-width
1 0% string-pixel-width
3 0% - timer-event-handler
3 0% - apply
1 0% - show-paren-function
1 0% - apply
1 0% - evil--match-paren-in-normal-state
1 0% - apply
1 0% - #<native-comp-function show-paren-function>
1 0% - show-paren--enabled-p
1 0% - buffer-match-p
1 0% - #<byte-code-function 506>
1 0% - #<byte-code-function 506>
1 0% - provided-mode-derived-p
1 0% derived-mode-all-parents
1 0% - #<native-comp-function F616e6f6e796d6f75732d6c616d626461_anonymous_lambda_9>
1 0% jit-lock-context-fontify
1 0% - auto-revert-buffers
1 0% auto-revert--buffer-candidates
2 0% - command-execute
2 0% - funcall-interactively
2 0% - self-insert-command
2 0% syntax-ppss-flush-cache
1 0% - minibuffer-mode
1 0% - run-mode-hooks
1 0% - run-hooks
1 0% - global-treesit-auto-mode-enable-in-buffer
1 0% require
1 0% - evil-collection-minibuffer-insert
1 0% - evil-insert
1 0% - if
1 0% - evil-insert-state
1 0% - evil-local-mode
1 0% - evil-initialize-state
1 0% - evil-change-state
1 0% - evil-insert-state
1 0% - evil-normalize-keymaps
1 0% - evil-state-keymaps
1 0% - evil-state-intercept-keymaps
1 0% - evil-get-auxiliary-keymap
1 0% format
1 0% - minibuffer-inactive-mode
1 0% - run-mode-hooks
1 0% - run-hooks
1 0% - global-treesit-auto-mode-enable-in-buffer
1 0% - easy-mmode--globalized-predicate-p
1 0% - derived-mode-p
1 0% provided-mode-derived-p
3 0% - #<byte-code-function DCA>
3 0% - ement-room--send-typing
3 0% - ement-api
2 0% - url-recreate-url
2 0% - url-port-if-non-default
2 0% type-of
1 0% - apply
1 0% - plz
1 0% make-process
1 0% run-at-time
1 0% add-to-history
119 7% Automatic GC
79 4% + redisplay_internal (C function)
6 0% + timer-event-handler
1 0% help-command-error-confusable-suggestions
0 0% ...The update you pushed to taxy-magit-section seems to have reduced the lag for me to such an extent that it has become unnoticeable?
That's good to hear. If you have time to use the code in https://github.com/alphapapa/ement.el/issues/298#issuecomment-2365205019 to time the redrawing now, it would be good to know what the hard numbers are.
As for the profiler-report:
Unfortunately, I don't see anything in that report about reverting the room list buffer. What's needed is:
(setq ement-auto-syncs nil).M-x profiler-start RET cpu RET.g in the room list buffer.M-x profiler-stop RET.M-x profiler-report RET.That way the only thing that's being profiled is the reverting of the room list buffer (plus minor UI like completion, but that can't be avoided).
Icy-Thought
commented
1 month ago Profiler report: (only relevant bits. If you still want the whole report, please tell me!)
34 3% - funcall-interactively
34 3% - revert-buffer
34 3% - ement-room-list-revert
34 3% - ement-room-list
11 1% - taxy-fill
11 1% - #<byte-code-function 1F2>
11 1% - #<lambda AEF>
11 1% - taxy-take-keyed
11 1% - taxy-take-keyed
11 1% - taxy-take-keyed
11 1% - taxy-take-keyed
10 1% - taxy-take-keyed
10 1% - taxy-take-keyed
10 1% - taxy-take-keyed@Icy-Thought Please post the whole report, otherwise we don't have a full picture of what Emacs is doing.
Icy-Thought
commented
1 month ago Apologies. I had assumed that you were not interested in the remaining profiling data. I have attached the profiler.txt file as usual within this comment. If you want me to perform more profiles, please ping me! :) profile.txt
OS/platform
Guix System or NixOS
Emacs version and provenance
Tried from both Nix and Guix, both times with jit native compilation enabled. GNU Emacs 29.4 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.24.41, cairo version 1.18.0)
Emacs command
./with-emacs.sh --dir /tmp/test
Emacs frame type
GUI
Ement package version and provenance
I've used method in README to obtain from latest commit. That is 3f87a95 when trying this.
Actions taken
Observed results
After few seconds Emacs lags, for a few seconds without being able to do anything. This repeats every few seconds between the lags.
Expected results
I should be able to use emacs normally when having ement room list open.
Backtrace
No response
Etc.
I have not used profiler at all till now and I am not sure how to get relevant information. I can run for specific functions, but I don't know what to target.
I observe this behavior both in my regular Emacs installation and on a fresh new emacs version obtained with with-emacs.sh script.
I am on Conduit server. I also have sliding sync running on the server. I am in more than 200 rooms. Few of the rooms are bigger groups. But most of them are bridged DM rooms. I use Mautrix Discord (no guild bridged, only DMs), Mautrix Telegram, Mautrix Whatsapp, Mautrix Meta, Heisenbridge (bridging a few irc groups).
I have tried registering a separate account and join a few rooms (I am in those on my main account) that have more members. I did not observe this behavior on that account.
I have already reached alphapapa through Ement.el room, where it was suggested to open an issue. This was like two weeks ago (sorry for taking so long)