GNOME Bugzilla – Bug 783025
Idle CPU usage has increased since 0.11.3
Last modified: 2018-04-10 05:38:20 UTC
Geary's CPU usage seems to have crept up since 0.11.3 -- using a recent build gives me a minimum of 1% CPU usage reported on my notebook rather than 0%.
Same here, geary 0.12 is using CPU all the time (2.6%). Really bad on a laptop.
Hey, thanks for reporting this. I'd like to get the CPU utilisation back down again, but will need some help working out where it's going on your system, since there could be a number reasons why it's happening. Can I get you to do the following: 1. Run Geary in a terminal using this command: geary -d 2. When you notice Geary using non-trivial CPU when idle, look at the terminal window and see what is currently being printed in the debug log 3. Capture maybe 10-20 lines of the debug output, remove any private information from it, and attach/paste it here. Using Geary built from git master might provide some better results — I'm trying to improve the debug logging there a bit at the moment. Even better than the debug logging would be to install Sysprof (https://wiki.gnome.org/Apps/Sysprof) and debugging symbols for Geary, GTK and GLib, then when Geary us using the CPU when idle, launch Systprof, attach it to Geary, and profile it for a while, then attach the resulting trace file here. This will tell me exactly what Geary is doing during that time. Cheers!
Actually, minor update, use this command from the terminal window instead: geary -d --log-periodic
I have the same problem geary 0.12 uses ~3% of CPU time, with a little additional detail: It sometimes drop to almost 0%, in particular when the application window is not visible (or not on the current workspace, I do not know exactly). It does not occur always, but almost. I tried to run the command from comment 3, with long periods (20min) either on or off screen, without doing anything else with the application. When off screen CPU was close to 0%, on screen around 4% (with occasional peaks in both regimes). The output of "geary -d --log-periodic" looks very similar in both regimes with roughly 0-8 log messages/min as follows: [deb] 15:46:17 41,850533 do_flag_watch_async begin Other:xxx@xxx:INBOX (open_count=2 remote_opened=true) [deb] 15:46:17 0,026689 do_flag_watch_async: fetching 10 flags for Other:xxx@xxx:INBOX (open_count=2 remote_opened=true) [deb] 15:46:17 0,073396 do_flag_watch_async: completed Other:xxx@xxx:INBOX (open_count=2 remote_opened=true), 10 messages updates [deb] 15:46:25 7,899431 do_flag_watch_async begin Gmail:xxx@gmail.com.com:INBOX (open_count=1 remote_opened=true) [deb] 15:46:25 0,005673 do_flag_watch_async: completed Gmail:xxx@gmail.com.com:INBOX (open_count=1 remote_opened=true), 0 messages updates [deb] 15:46:27 1,995161 [0004/imap.xxx/default:993 GEARY_IMAP_CLIENT_SESSION_STATE_AUTHORIZED] Sending keepalive... [deb] 15:46:27 0,028964 [0004/imap.xxx/default:993 GEARY_IMAP_CLIENT_SESSION_STATE_AUTHORIZED] Keepalive result: a452 OK Completed [deb] 15:47:19 51,970834 [0005/imap.xxx/default:993 GEARY_IMAP_CLIENT_SESSION_STATE_AUTHORIZED] Sending keepalive... [deb] 15:47:19 0,028613 [0005/imap.xxx/default:993 GEARY_IMAP_CLIENT_SESSION_STATE_AUTHORIZED] Keepalive result: a422 OK Completed In addition, I run geary under "strace -f -t". Here there is a considerable difference, roughly 0-5000 loglines/min offscreen and 5000-12000 loglines/min onscreen.
Hey Jiri, thanks for looking into this. (In reply to Jiri Cerny from comment #4) > I tried to run the command from comment 3, with long periods (20min) either > on or off screen, without doing anything else with the application. When off > screen CPU was close to 0%, on screen around 4% (with occasional peaks in > both regimes). The output of "geary -d --log-periodic" looks very similar in > both regimes with roughly 0-8 log messages/min as follows: > > [deb] 15:46:17 41,850533 do_flag_watch_async begin Other:xxx@xxx:INBOX > (open_count=2 remote_opened=true) > [deb] 15:46:17 0,026689 do_flag_watch_async: fetching 10 flags for > Other:xxx@xxx:INBOX (open_count=2 remote_opened=true) > [deb] 15:46:17 0,073396 do_flag_watch_async: completed Other:xxx@xxx:INBOX > (open_count=2 remote_opened=true), 10 messages updates > [deb] 15:46:25 7,899431 do_flag_watch_async begin > Gmail:xxx@gmail.com.com:INBOX (open_count=1 remote_opened=true) > [deb] 15:46:25 0,005673 do_flag_watch_async: completed That looks like Bug 778276. Along with the AccountSyncronizer, the EmailFlagWatcher are two somewhat intensive processes that Geary runs periodically. Unlike the AccountSynchronizer which runs once at startup for every folder, then only again if something interesting happens to a folder, the EmailFlagWatcher runs on any open folder (i.e. every inboxes and any other folder currently selected in the MainWindow) every three minutes. If those folders contain a lot of messages, then it can take some time. I'm working on removing the EmailFlagWatcher altogether over in that bug, so please subscribe to it to keep track of progress there.
I am not sure if I was clear enough in comment 4. The log messages from comment 4 appear in both cases, when geary uses 4% of CPU and also when essentially idle. The problem is more that when geary window is on screen, I got the following in the strace output 60 times/s. poll([{fd=3, events=POLLIN}, {fd=7, events=POLLIN}, {fd=10, events=POLLIN}, {fd=18, events=POLLIN}, {fd=23, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}, {fd=27, events=POLLIN}, {fd=35, events=POLLIN}, {fd=40, events=POLLIN}, {fd=42, events=POLLIN}, {fd=43, events=POLLIN}, {fd=44, events=POLLIN}], 13, 16) = 0 (Timeout) I do not get those in the "almost idle situation" These polls correspond to 60 wakeups/s as reported by powertop. Given the fact that at my system the total number of wakeups/s is of order 100-200/s, this seems to be pretty battery heavy.
Oh I see! Okay, two things: - Can you see if you get the same number of wakeups if no conversations are selected, e.g. by opening an empty folder or Ctrl-clicking on the selected conversation in the list, so that "No conversations selected" is showing in the conversation view? - Either way, can you say what the file descriptors that are appearing in strace are open for - i.e. what does "lsof -p `pgrep geary`" give as the name of the FD's that are appearing there? Cheers!
I get the same number of wakeups also when no conversation is selected. Here is the edited output of the lsof command (I kept only fd's that show in the strace now) COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME geary 7792 cerny 3u a_inode 0,13 0 10156 [eventfd] geary 7792 cerny 7u unix 0xffff92169a1efc00 0t0 209230 type=STREAM geary 7792 cerny 10u unix 0xffff921710059800 0t0 212520 type=STREAM geary 7792 cerny 19u netlink 0t0 209232 ROUTE geary 7792 cerny 31u a_inode 0,13 0 10156 [eventpoll] geary 7792 cerny 37u IPv4 213368 0t0 TCP myhostname:42540->mailserver1:imaps (ESTABLISHED) geary 7792 cerny 38u IPv4 213369 0t0 TCP myhostname:43964->mailserver2:imaps (ESTABLISHED) geary 7792 cerny 39u IPv4 213503 0t0 TCP myhostname:42546->mailserver1:imaps (ESTABLISHED) geary 7792 cerny 40u IPv4 210800 0t0 TCP myhostname:43970->mailserver2:imaps (ESTABLISHED) geary 7792 cerny 41u IPv4 213502 0t0 TCP myhostname:43966->mailserver2:imaps (ESTABLISHED)
Okay, thanks for the info. I've been looking into it a bit, but it's not entirely obvious to me what's causing poll() to return. It *might* be a redraw handler, given it's happening at ~60Hz, but I need to dig into it a bit. I've also asked for some advice on the gtk-list, so we'll see if anyone has any advice.
I was looking into it as well, I think you are right with redraw handler. If understand correctly, the poll call has a very short timeout (16ms or sometimes 17ms), and there are no events arriving from the fd's, the poll always always timeouts. I tried to debut the issue. This is the suspicious backtrace at the poll: Thread 1 "geary" hit Breakpoint 1, 0x00007fffeef58870 in poll () from /lib64/libc.so.6
+ Trace 238183
which seems to confirm your redraw hypothesis. But g_source_attach is hit quite often, so I might pick a wrong backtrace. Here I am stuck ...
Jiri, are you on Wayland by any chance?
Looking into this some more, while the poll may well be running at 60Hz, Geary isn't painting every time - adding a debug draw handler on the main window's draw signal shows it stopping drawing while idle. I notice that putting an strace on Epiphany shows similar poll() behaviour, but doing same for a more simple GTK app such as Gitg doesn't show that poll() behaviour, so I'm back to thinking it is a WebKitGTK issue. I'll ask on the mailing list there and see what people think.
Looks like it could be a WebKitGTK2 issue, bug filed: https://bugs.webkit.org/show_bug.cgi?id=180330
(In reply to Michael Gratton from comment #11) > Jiri, are you on Wayland by any chance? Michael, yes I am on wayland, but I tried under X as well, and it is the same. In addition, under wayland the poll disappears, under some circumstances, when geary is not on the current workspace. Under X, it is always polling. By the way, if (under wayland) I disable desktop animations by setting /org/gnome/desktop/interface/enable-animations to false, the poll disappears and geary is idle when it should be.
Not related to https://bugs.webkit.org/show_bug.cgi?id=180330 I think. Here, Geary is using 6% CPU while epiphany is idle...
And can confirm it's related to animations.
Looks like this was actually caused by the conversation viewer's spinner not being stopped when hidden. I just pushed commit 71d05b6 to master that ensures this happens, and Geary spends most of its time sleeping on 0% CPU utilisation for me now. Can people here test this out and let me know if that helps the situation for them? heers!
Issue with the spinner reported to GTK: https://gitlab.gnome.org/GNOME/gtk/issues/166
(In reply to Michael Gratton from comment #17) > Can people here test this out and let me know if that helps the situation > for them? heers! It works for me.
Cool, thanks for the feedback. The fix has been now also been cherry picked to geary-0.12 as commit 1e8b265d. I'm going to call the problem fixed and close this issue. If you find anything else is causing Geary to wake up frequently, please open a new bug. Cheers!