[mu4e bug] mu 1.6.1 emacs interface very slow

telmich commented 3 years ago

Describe the bug

As reported before, mu4e can be extremely slow. Right now with mu 1.6.1 there is however a huge difference between searching inside emacs and searching using mu find:

To Reproduce

Index ca. 1.5M messages, execute a simple search like:

find flag:flagged OR maildir:/ungleich/inbox OR maildir:/gmail/inbox OR maildir:/otherfish/inbox

Time with mu find: ca. 1s Time with mu4e: minutes (ca 2-3m)

If I repeat the same query, it always takes extremely long inside emacs and is always fast outside.

While in my previous report it was related to updating and did not always happen, the situation changed now:

in emacs: always slow
outside emacs: always fast

(independent of whether update is running or not)

Environment

nb3:~# apk list -I mu mu4e emacs-x11
mu-1.6.1-r0 x86_64 {mu} (GPL-3.0) [installed]
mu4e-1.6.1-r0 x86_64 {mu} (GPL-3.0) [installed]
emacs-x11-27.2-r1 x86_64 {emacs} (GPL-3.0-or-later) [installed]

[17:18] nb3:~% du -sh Maildir/
35G Maildir/
[17:17] nb3:~% find Maildir/ -type f | wc -l
1510809

Checklist

[x] you are running vanilla emacs (i.e. without Doom, Evil, Spacemacs etc.) (otherwise, please try to reproduce without those
[x] you are running mu4e without any third-party extensions (otherwise, please try to reproduce without those)
[ ] mu/mu4e version 1.6.1

telmich commented 2 years ago

I have an update from running 1.7.9: until today, mu4e on the 1.7.x series was working "fast enough". Since today, the "Searching ..." messages does not disappear anymore for the standard inbox search and no results are shown ever.

I am now upgrading to 1.7.13 (1.6.5-344-gd0619b1d) and will see if that fixes the problem.

telmich commented 2 years ago

What is very interesting to see is that with 1.7.13 mu index hangs for about 5 seconds every 10000 messages it processes: 69999........ and then switches over to 70000. I assume this is some buffering/syncing, but haven't noticed that in earlier versions.

peterhoeg commented 2 years ago

I’m not sure if I should open a new issue or this is related “enough” to add to this issue.

Details:

OS: NixOS unstable
mu: 1.8.5
xapian: 1.4.19
about 1100 contacts

Database:

Permissions Size User  Date Modified Name
.rw-r--r--  379M peter 13 Jul 14:25  docdata.glass
.rw-r--r--     0 peter 13 Jul 14:32  flintlock
.rw-r--r--   166 peter 13 Jul 14:22  iamglass
.rw-r--r--  2.2G peter 13 Jul 14:22  position.glass
.rw-r--r--  1.2G peter 13 Jul 14:25  postlist.glass
.rw-r--r--  691M peter 13 Jul 14:22  termlist.glass

Observed behaviour:

mu

time mu find -n 500 -r -t -r 'maildir:/hoeg/inbox AND NOT flag:trash' > /dev/null
0.13s user 0.14s system 99% cpu 0.268 total

mu server

time mu server --eval '(find :query "maildir:/hoeg/inbox AND NOT flag:trash" :maxnum 500 :threads t)' > /dev/null
0.12s user 0.15s system 98% cpu 0.271 total

mu4e

The same query (through a shortcut) takes 20 seconds.
According to top, mu is maxing out one core to run this while mu4e is just saying “Searching…”
For about 10 seconds after mu exists, the emacs process is maxing out one core but it’s still responsive.
Running any search just times out randomly and needs to be run again in order to produce a result
Running the same search again is sometimes instant and at other times takes a long as the original query
(setq mu4e-index-cleanup nil) makes no difference

There are no issues with mails being re-indexed. A new indexing run takes around 6 seconds with 1.3m mails.

djcb commented 2 years ago

That seems like a slightly different issue; it also seems this is purely on the emacs/mu4e side. So perhaps:

check with some emacs tools (profile-start etc.).
try with a smaller maxnum (do things change with 100, 10 , ..)

And what emacs version are you using? Does this reproduce with just emacs -q and loading mu4e?

peterhoeg commented 2 years ago

No difference with maxnum, but according to the profiler, it looks like a lot of time is spent in vertico doing auto-completion which really doesn't make sense....


429  58% - command-execute
408  56%  - byte-code
408  56%   - read-extended-command
408  56%    - read-extended-command-1
408  56%     - completing-read-default
408  56%      - apply
408  56%       - vertico--advice
300  41%        - #
275  37%         - vertico--exhibit
252  34%          - vertico--update-candidates
243  33%           - vertico--recompute-candidates
231  31%            - vertico--all-completions
231  31%             - completion-all-completions
231  31%              - apply
231  31%               - #
231  31%                - completion--nth-completion
231  31%                 - completion--some
231  31%                  - #
231  31%                   - orderless-all-completions
231  31%                    - orderless-filter
231  31%                     - #
231  31%                      - complete-with-action
 37   5%                       - all-completions
 20   2%                        - #
 16   2%                         + #

peterhoeg commented 2 years ago

But damn mu on its own is fast.

peterhoeg commented 2 years ago

Apologies, I think the vertico stuff was a consequence of me hitting M-x to toggle the profiler.

Here's another run using a shortcut to trigger it instead:

26,922,151  67% - command-execute
26,922,151  67%  - funcall-interactively
15,503,744  39%   - mu4e-headers-search-bookmark
15,482,624  39%    - mu4e-search
15,481,062  39%     - mu4e--search-execute
15,376,682  38%      - switch-to-buffer
15,369,290  38%       - set-window-buffer
15,369,290  38%        - apply
15,369,290  38%           ad-Advice-set-window-buffer
     7,392   0%       + select-window
    97,040   0%      + mu4e-headers-mode
     3,140   0%      + mu4e--server-find
     2,112   0%      + run-hooks
       504   0%       mu4e-format
     5,284   0%    + mu4e-ask-bookmark
 7,720,992  19%   - mu4e~headers-quit-buffer
 7,689,925  19%    - replace-buffer-in-windows
 7,689,925  19%     - switch-to-prev-buffer
 7,687,813  19%      - set-window-buffer-start-and-point
 7,687,813  19%       - set-window-buffer
 7,687,813  19%        - apply
 7,687,813  19%         - ad-Advice-set-window-buffer
     3,168   0%          + #
    14,784   0%    + walk-windows
    14,171   0%    + mu4e--main-view
     2,112   0%    + run-hooks
 3,697,415   9%   + doom/toggle-profiler
10,551,925  26% - mu4e--server-filter
 8,870,295  22%  - mu4e~headers-append-handler
 8,870,295  22%   - seq-do
 8,870,295  22%    - mapc
 4,913,180  12%     - #
 4,735,262  11%      - #
 3,748,550   9%       - #
   876,272   2%          truncate-string-to-width
   490,536   1%          mu4e~headers-flags-str
   368,688   0%        + #
   277,336   0%        + mu4e~headers-thread-prefix
   272,152   0%        + mu4e~headers-from-or-to
   962,160   2%       + mu4e~headers-truncate-field-fast
   113,096   0%  + #
     3,670   0%  + mu4e~headers-found-handler
 1,594,183   4% + timer-event-handler
   534,238   1% + redisplay_internal (C function)
     2,112   0% + winner-save-old-configurations
     2,048   0% + evil--jump-handle-buffer-crossing
     1,056   0%   yas--post-command-handler
       384   0% + gcmh-register-idle-gc
       160   0% + evil-normal-post-command
        21   0% + help-command-error-confusable-suggestions
         0   0%   ...

djcb commented 2 years ago

Hmmm.... those sample numbers look very high. What's this ad-Advice-set-window-buffer? Can you try with emacs -q and only loading mu4e?

peterhoeg commented 2 years ago

Great, I can no longer blame you...... It is wickedly fast with emacs -Q. Like instant fast.

All the advised functions come either from doom or one of the packages it pulls in - I haven't messed around with it. I'll take my bug report over there.

peterhoeg commented 2 years ago

Thanks again for your awesome software!

peterhoeg commented 2 years ago

I'm adding some additional info in case someone else sees this. The problem is the dashboard (or I guess mu4e-main-mode is the correct term).

When launching mu4e it overwhelms mu server with something I haven't figured out causing mu to max out one CPU. If I wait for it to settle down and then do a search, it's instantaneous. Hitting q to go back to the main screen now maxes out the CPU again so if I try to do another search, I need to wait for mu to die down and then it's executed (quickly).

peterhoeg commented 2 years ago

I'm so sorry about the noise. Turns out it was the unread search for a search with lots of regexps that caused it. Adding :hide-unread t made everything snappy again.

And it's even in the manual.

djcb commented 1 year ago

Closing this one; discussion continues in #2089

peterhoeg commented 1 year ago

That link just goes back to this same issue @djcb

djcb commented 1 year ago

Like life itself... anyway, I meant #2320.

djcb / mu

[mu4e bug] mu 1.6.1 emacs interface very slow #2089