GNOME Bugzilla – Bug 788156
Remote content download slows down message preview
Last modified: 2017-10-03 09:53:46 UTC
I just upgraded to Fedora 26 which includes Evolution 3.24.x and, unlike previous versions I've used, this one is very very slow to view email. It can retrieve the email from my POP3 mailbox quickly but once it's in the Evolution inbox folder, viewing it takes 3 to 5 minutes per message. After I click on an email in the inbox, the bottom task bar begins filling with status messages like "Saving user interface state", "Parsing message", "Retrieving Message" (that one makes no sense to me, the message is already retrieved and in Evolution's inbox at this point!). If I scroll through a few messages in the inbox using the arrow keys, the number of task messages on the status bar multiplies rapidly until there are just a lot of little stop-sign icons and foot throbbers (or whatever they're called) visible there. Occasionally, the delays drop to just 30 seconds to minute per message but other times they extend to as long as 10 minutes before the interface becomes usable again. I've used Evolution on Fedora for many years and never seen anything like this. I have a fairly straightforward mail setup with a POP3 mailbox, an SMTP server for outbound mail, and a lot of local mail folders where I archive old mail. I'm happy to provide additional information if needed.
Two additional comments that might be relevant: 1. I've found that if I select File -> Quit and then restart Evolution, sometimes the per-message delays will be shorter after restarting, down in the 30 second per message range to render them. However, the shutdown takes a very long time too and often pops up "Close Evolution with pending background operations?" dialogs. I select "keep waiting" on these as I don't know what effect forcing a shut down might have on the mail folder integrity. Sometimes after a shutdown and restart Evolution will remaining usable for hours. But the problem does eventually come back. 2. My local mail archive is stored as a Maildir on my local hard disk because of its size and for compatibility reasons. Not sure if this would have any connection to the problem or not.
How large is your local inbox folder? Do you have any remote accounts configured?
Maybe five or ten messages are in the inbox during the day, but it spikes up to around 100 emails each morning when I first check my mail. As soon as I examine and respond to a piece of mail in the inbox it gets moved from the inbox to an archive folder. I also have several filters set up that move email from various mailing lists directly out of the Inbox into appropriate archive folders for later reading. If I understand what you mean, I have two remote accounts, a POP3 mailbox that is retrieved into my Evolution Inbox and an SMTP account where my outbound email is sent. Those are the only non-local accounts accessed by Evolution.
> it gets moved from the inbox to an archive folder. Have you ever expunged the Inbox folder? https://help.gnome.org/users/evolution/stable/mail-delete-and-undelete.html If not, any moved messages are still in the Inbox as they are just marked as deleted after moving, but not expunged. (In reply to Steve Rainwater from comment #3) > If I understand what you mean, I have two remote accounts, a POP3 mailbox > that is retrieved into my Evolution Inbox and an SMTP account where my > outbound email is sent. POP3 by definition is local. :) IMAP would be remote, for example.
(In reply to André Klapper from comment #4) > If not, any moved messages are still in the Inbox as they are just marked as > deleted after moving, but not expunged. Errm, wait, I think I am wrong about this. Still, if you enable "View > Show Deleted Messages", maybe there are way more messages than you expect? :-/
Thanks for a bug report. Once the message list is filled the count of local messages doesn't matter. I would think of bug #787514, but it was mainly for IMAP, thus nothing you use. Could you install debuginfo packages for evolution-data-server, evolution and glib2 and then grab a backtrace of running evolution in that "waiting state" to see what it does, please? You can install them with this command: $ sudo dnf install --enablerepo=updates-debuginfo glib2-debuginfo \ evolution-data-server-debuginfo evolution-debuginfo To catch the backtrace run this command as a regular user: $ gdb --batch --ex "t a a bt" -pid=`pidof evolution` &>bt.txt Please check the bt.txt for any private information, like passwords, email address, server addresses,... I usually search for "pass" at least (quotes for clarity only). There is a chance that evolution is waiting for a response from WebKitGTK+, which runs in a separate process, called WebKitWebProcess. You can list all of them running with: $ ps ax | grep WebProcess Evolution itself uses up to two of them, one for message preview (that's the one we are interested in) and one for message composer, which is running only if at least one message composer is opened. Other applications can have opened its own WebKitWebProcess too, in which case it's harder to catch which one belongs to evolution. You can list them before you run evolution and then after you run it. That added will be from Evolution. It really should not take that long to render a message which is already downloaded. That "Saving user interface state" message stuck in the status bar usually means that GTask thread pool is full of tasks, which are starving. It allows only 10 threads, which is not enough for evolution with many accounts configured, but that's not your case (many accounts means more than 5-10).
I noticed that even most of the times when I move to a different message in one of my On This Computer subfolders, the message is shown almost instantly, then it sometimes delays a bit. Not so long as for you, it's like half of a second or a second, but still (my messages are short and simple). I added some debug prints and it shows me that the preprocessing on the evolution side is quick: [11:42:01.413] mail_reader_message_selected_timeout_cb: [11:42:01.422] mail_reader_message_loaded_cb: error:none [11:42:01.423] mail_reader_set_display_formatter_for_message: parts:(nil) [11:42:01.428] mail_display_load_changed_cb: load finished [11:42:01.431] set_mail_display_part_list: error:none [11:42:01.431] e_mail_display_load: part_list:0x7f241c00d4f0 msg_uri:(null) [11:42:02.487] mail_display_load_changed_cb: load finished It takes the WebKitGTK+ one second to finish rendering of the message (the time between the last and the previous call is when evolution requested web view to display some message). It doesn't necessarily mean that it's WebKitGTK+ fault, evolution installs its own web extensions to it and it provides the data too, thus it can still be evolution causing it. I'm not able to get backtrace of the running WebKitWebProcess, nor evolution, the second (or more often half of it) is not enough to give me a chance to catch backtrace of it, but I hope that with your extra lag you'll be more lucky.
(In reply to André Klapper from comment #5) > (In reply to André Klapper from comment #4) > > If not, any moved messages are still in the Inbox as they are just marked as > > deleted after moving, but not expunged. > > Errm, wait, I think I am wrong about this. Still, if you enable "View > Show > Deleted Messages", maybe there are way more messages than you expect? :-/ After starting Evolution this morning and checking my POP3, the Evolution Inbox showed 65 messages. After I enabled "Show Deleted Messages" it shows 441 messages. That's a lot of but there have been cases on previous versions of Evolution where I had several thousand messages in the inbox with any problem.
(In reply to André Klapper from comment #4) > Have you ever expunged the Inbox folder? > https://help.gnome.org/users/evolution/stable/mail-delete-and-undelete.html > If not, any moved messages are still in the Inbox as they are just marked as > deleted after moving, but not expunged. I have done that occasionally in the past. I tried it this morning after checking my POP3 and prior to going through my mail and replying. At first it seemed to help but I think maybe it was just a coincidence as it begin slowing down later. However, I tried to pay more careful attention to each email and I have a theory. I get emails from certain senders that contain images, such as from eBay or Pinterest, on which I have in the past clicked the "allow remote content from this domain" option so that the images will load automatically. As I come to each of those emails in the process of reading my inbox email, I think Evolution must set up a background task to try loading the images. Often that takes a very long time for some sites, Pinterest is notoriously slow these days. So I just move on to the next email and keep going. Is it possible that these image loading tasks are accumulating in the background to the point they eventually slow down or prevent altogether Evolution's rendering and displaying of emails? Is there a timeout on image loading or will Evolution try forever once I have viewed an email with images? I'm not sure how to definitely test this theory. Maybe create some HTML email with remote content from one of my own servers so that I can force delays? Just an idea. > (In reply to Steve Rainwater from comment #3) > > POP3 by definition is local. :) IMAP would be remote, for example. Ok, understood, then I have no remote accounts. -Steve
(In reply to Milan Crha from comment #6) > Could you install debuginfo packages for evolution-data-server, evolution > and glib2 and then grab a backtrace of running evolution in that "waiting > state" to see what it does, please? You can install them... Thanks for the detailed suggestion. I will try this later today and post results when I have something.
Dumb question: I got the debug stuff installed and thought it would wise to restart Evolution before doing any tests with it. I shut it down via the GUI menu and then did a ps and noticed all sorts of Evolution-related processes still running (dataservers, factories, subprocesses, etc). I tried "evolution --force-shutdown" which I though used to work and it had no effect. What's the correct method to actually, completely shutdown Evolution and all its related tasks? I guess a reboot would do it but then I'd feel like was running Windows! :)
Those are evolution-data-server processes, not Evolution (frontend) itself, and that should not influence picking up the installed debug information :)
(In reply to André Klapper from comment #12) > Those are evolution-data-server processes, not Evolution (frontend) itself, > and that should not influence picking up the installed debug information :) I'd only add to this that the `evolution --force-shutdown` does kill those background processes too, but if you run for example GNOME Shell, then it restarts them on their own, thus the `ps` command you use will show them running, but with a different process ID. Some other desktop environments do not auto-start the evolution-data-server processes.
Created attachment 360553 [details] backtrace results during inbox message rendering delay (In reply to Milan Crha from comment #6) > To catch the backtrace run this command as a regular user: > > $ gdb --batch --ex "t a a bt" -pid=`pidof evolution` &>bt.txt Ok, I was able to do this successfully I think. Here is the resulting bt.txt file.
Thanks for the backtrace. It shows evolution basically idle, expect of 11 threads trying to download images from a remote site, which corresponds with your theory about image download from comment #9. Already downloaded images should be pretty quick, because they are taken from local cache (stored in ~/.cache/evolution/http/). There is set 90 seconds timeout for each single image download. I thought it's something with WebKitGTK+, but even when I downgraded to 2.14.1, then the web view had not been updating until the message had been finished with the download (until then the web view didn't use CSS as provided by evolution in a separate file, not inlined). I looked also on the backtrace of the corresponding WebKitWebProcess process, but it didn't show anything, all threads idle/in poll. Definitely nothing from evolution, which would eventually block it. Due to change of WebKigGTK+ not helping the issue, it can be somewhere else. I do not know where yet, it can be evolution, of course, or maybe libsoup? I do not know how WebKitGTK+ decides when it can (re-)render the web view, eventually how it decides that the CSS provided as a separate resource is ready to be used in the web view. Knowing that would help me to narrow the further investigation.
(In reply to Milan Crha from comment #15) > I > do not know how WebKitGTK+ decides when it can (re-)render the web view, > eventually how it decides that the CSS provided as a separate resource is > ready to be used in the web view. Knowing that would help me to narrow the > further investigation. Rendering should be handled automatically. CSS should be applied once loaded. I'm not an expert in either area, though. The one thing that strikes me as odd is the image downloading. Not saying that's the problem, but it's odd. Why are you manually downloading the images in the UI process? You know you can tell WebKit whether or not to do that by using WebKitResponsePolicyDecision? Connect to WebKitWebView::decide-policy, check if the WebKitPolicyDecision is WebKitResponsePolicyDecision, and ref it if so. Then you can at any point in time (when the user decides to allow the images, or close the info bar) allow/deny the policy decision and they should be loaded automatically by the network process. Probably simpler than the code you have now. Anyway, the backtrace just shows Evolution downloading resources manually in its UI process, so I don't see anything to implicate WebKit here (at least not yet).
One additional observation that might help. I've decided there are two distinct cases that I'm experiencing: 1. Evolution renders the emails very slowly but eventually catches up and clears the status bar, becoming responsive again. This is what was happening in the case I've provided the backtrace for. After about 4 to 5 minutes, the entire backlog of tasks on the status bar cleared and I could view messages again. 2. Same as #1 but the number of tasks continues to accumulate and never clears, even after as much as an hour. The UI eventually becomes completely unresponsive and the only solution I've found is to use --force-shutdown from the command line. Once I restart, things seem normal again. So #1 happens frequently, multiple times per day. But #2 seems to only happen occasionally, maybe once a week or so at most. I'm waiting for the next time it happens and will try to post a backtrace from one of those occasions too. Maybe #2 could be an extreme case of #1 where an image never downloads? But If there's a 90 second timeout, it seems like things should eventually clear. I've experimentally tried removing all the sites listed in Preferences -> Mail Preferences -> HTML Messages -> Loading Remote Content -> "Allow for Senders" and set the main option to "Never load remote content". So far, this significantly improves the speed of rendering messages in my inbox with no slowing for at least the last hour. Messages become visible within one second or less (with no images of course) of clicking on them, matching the speed I was used to with prior versions of Evolution.
(In reply to Michael Catanzaro from comment #16) > Why are you manually downloading the images in the UI process? It might be an artefact of the old code, because it was the way it was done in time of GtkHTML usage and got into WebKit1 port and then later into the WebKit1 port as well. Evolution does its own http/s cache which it maintains in some way, which is one more reason for manual processing of the requests (evolution has disabled webkit page caching, of course). (In reply to Steve Rainwater from comment #17) > Maybe #2 could be an extreme case of #1 where an image never downloads? But > If there's a 90 second timeout, it seems like things should eventually clear. Could it be that it's reproducible with certain messages only, like when they have "too many" images? Is the slowdown of the message showing reproducible also when you manually initiate remote content load (Ctrl+I)?
(In reply to Milan Crha from comment #18) > ...in time of GtkHTML usage and got into WebKit1 port and then later into the > WebKit1 port as well. ... Oops, the second "WebKit1" had been meant to be "WebKit2".
(In reply to Milan Crha from comment #18) > Is the slowdown of the message showing reproducible also when you manually > initiate remote content load (Ctrl+I)? Not really. Pinterest emails are the slowest. They often contain 10+ images and the Pinterest servers are very slow on some days, sometimes taking a minute or more to serve one image. If I click "load remote content" on one of those, I see a task appear in the Evolution task bar until the images are loaded. But the Evolution UI in general remains responsive, allowing me to click around to other emails or folders. So I wouldn't describe it as a problem, just a slow server. Also, the email itself is visible the entire time, just without images; I don't see a blank preview pane with "Retrieving Message..." like I do when automatic content loading is on. I've tried going to message after message clicking "load remote content" but can't seem to do it fast enough to trigger any sort of problem. The problem has largely vanished for me now that I've turned off all automatic remote content loading. In most cases, seeing the images was nice but not essential, so this looks like an acceptable work-around to me.
(In reply to Steve Rainwater from comment #20) > Pinterest emails are the slowest. Would you mind to share one such message, please? I guess they are mostly about advertisement and such, nothing personal there, right? You might still remove private things from it, like your email address, unsubscribe link and such. If unsure, then feel free to send it to my bugzilla email (as an attachment) and I'll modify it accordingly myself, just mention this bug report in the message Subject, otherwise I'd probably overlook it in my spam folder. The thing is that I'd like to have a real life message, rather than a cooked message. (In reply to Steve Rainwater from comment #20) > Also, the email itself is visible the entire time, just without images; > I don't see a blank preview pane with "Retrieving Message..." like I do when > automatic content loading is on. What had been set precisely in Edit->Preferences->Mail Preferences->HTML Messages->Load Remote Content section, please? I do not mind of the Allow for site/sender parts, I'm more interested in the options above these two. > I've tried going to message after message clicking "load remote content" > but can't seem to do it fast enough to trigger any sort of problem. Ah, it can be due to the images being already downloaded in ~/.cache/evolution/http/ You can move to a different message, delete that folder, then select the message again and when you request image download then it'll download them from the network, not from the local disk. Even though the images are supposed to be shown when they are found in the local cache.
(In reply to Milan Crha from comment #21) > Would you mind to share one such message, please? Ehm, never mind. I thought this will be harder to get, but I made a test message with 50 remote images received from an unresponsive server and I see the same what you see, but only when I open the message for the second time. The problem is that the remote content download uses GTask, which has only 10 threads available. The same thread pool is used for other operations, like the retrieving messages and many other. When the message is selected and the GTask thread pool is empty, then the message is properly parsed and formatted and even shown (without images) in the message preview, but when the remote content download is requested, then it fills the GTask thread pool, which causes all new tasks to wait until the currently running threads (which try to download images) are finished. In this case the preview shows only "Retrieving message", because the other task is waiting in the GTask queue. In other words, this is a variant of bug #774448, but I'm going to change it in Evolution, to not use the GTask pool for the remote content download.
(In reply to Michael Catanzaro from comment #16) > Rendering should be handled automatically. CSS should be applied once > loaded. I'm not an expert in either area, though. Michael, after a bit deeper look on this, I see that evolution passes some base CSS as a file, then it "injects" its own overrides with webkit_dom_css_style_sheet_add_rule() on the web-extension side. These changes are propagated only after WebKitWebView::load-changed signal is called with load_event WEBKIT_LOAD_FINISHED, which kind of makes sense, but the problem is that with image download the finish is called after all images are resolved (with or without error). Evolution doesn't use WebKitUserContentManager, which seems to suit better, maybe? Anyway, I do not want to steal this bug report with semi-related issue, I'll ping you on IRC for some guidance.
Back to the original report. Even when I made it use its own thread pool it didn't help much, due to all requests being processed in the same pool, no matter whether it was a request for message body or remote image. Thus I ended with two thread pools, one for low priority requests (remote image download) and one for other higher priority requests (like message body to show). I also made the ongoing requests cancellable, thus when moving to a different message any ongoing requests are cancelled, thus they free the thread pool for new requests. Created commit aff7195492 in evo master (3.27.1+) Created commit f141fcb306 in evo gnome-3-26 (3.26.2+)
(In reply to Milan Crha from comment #23) > Evolution doesn't use WebKitUserContentManager, which seems to suit better, > maybe? I see it does not fit for evolution needs here (it is used elsewhere), because the CSS rules being inserted on the web-extension side are rather merged, than inserted, because they remove previous selectors in it. WebKitUserContentManager doesn't allow to remove only some rules, thus it doesn't fit here. Unless there's something better that WEBKIT_LOAD_FINISHED, we've bad luck.