Bug 1030629 - File->New->Mail takes long time to appear after update/restore
File->New->Mail takes long time to appear after update/restore
Status: CLOSED RAWHIDE
Product: Fedora
Classification: Fedora
Component: evolution (Show other bugs)
20
x86_64 Linux
unspecified Severity urgent
: ---
: ---
Assigned To: Matthew Barnes
Fedora Extras Quality Assurance
: Reopened
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-11-14 15:16 EST by Paul Finnigan
Modified: 2014-07-11 09:12 EDT (History)
6 users (show)

See Also:
Fixed In Version: evolution-3.12.3
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2014-07-11 09:11:31 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
backtrace requested but it has problems! (9.16 KB, text/plain)
2013-11-17 14:15 EST, Paul Finnigan
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
GNOME Desktop 710367 None None None Never

  None (edit)
Description Paul Finnigan 2013-11-14 15:16:46 EST
Description of problem:

In evolution pressing "New Mail" takes a long time to show window and cpu goes through the roof. With evolution running and before New Mail pressed top shows:

top - 19:56:37 up  4:12,  2 users,  load average: 1.21, 1.18, 1.00
Tasks: 199 total,   1 running, 198 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.3 us,  0.7 sy,  0.0 ni, 98.6 id,  0.1 wa,  0.2 hi,  0.1 si,  0.0 st
KiB Mem:   7915916 total,  7333104 used,   582812 free,      544 buffers
KiB Swap:  8009724 total,    59160 used,  7950564 free,  4633248 cached

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                           
 9483 ausr      20   0 3398608 115908  33616 S   1.0  1.5   0:05.63 evolution                                                                         
 1720 ausr      20   0 2076444 468964  45908 S   0.7  5.9   6:21.24 gnome-shell                                                                       
  355 root      20   0       0      0      0 S   0.3  0.0   0:06.49 btrfs-transacti                                                                   
  711 root      20   0  214272  31072  11224 S   0.3  0.4   8:35.10 Xorg                                                                              
 9294 root      20   0       0      0      0 S   0.3  0.0   0:00.41 kworker/1:2 


After pressing New Mail button top shows (typical):

top - 19:58:59 up  4:15,  2 users,  load average: 0.63, 0.88, 0.91
Tasks: 199 total,   2 running, 197 sleeping,   0 stopped,   0 zombie
%Cpu(s): 69.9 us, 10.7 sy,  0.0 ni, 17.3 id,  0.0 wa,  1.5 hi,  0.6 si,  0.0 st
KiB Mem:   7915916 total,  7528472 used,   387444 free,      544 buffers
KiB Swap:  8009724 total,    59096 used,  7950628 free,  4753004 cached

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                           
 9483 ausr      20   0 3430376 152692  35748 R 158.5  1.9   0:28.13 evolution                                                                         
 1725 ausr      20   0  178628   2400   1740 S  43.9  0.0  12:27.57 dconf-service                                                                     
 1556 ausr      20   0   34408   2888   1044 S  21.9  0.0   7:35.97 dbus-daemon                                                                       
 1905 ausr      20   0 1592768  52896  14112 S   4.3  0.7   1:24.67 evolution-calen                                                                   
 9576 ausr      20   0  929492  16620  12428 S   4.0  0.2   0:00.63 evolution-addre                                                                   
 1795 ausr      20   0  777672  15268  10452 S   3.3  0.2   0:59.41 gnome-shell-cal                                                                   
 1839 ausr      20   0  952496  15940   9932 S   3.3  0.2   1:04.42 evolution-alarm                                                                   
  711 root      20   0  216556  31460  11580 S   0.7  0.4   8:41.64 Xorg


Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1. Just press New Mail button.
2.
3.

Actual results:
Takes forever (can be over 10 minutes)

Expected results:
New Mail window within a few seconds

Additional info:

evolution.x86_64 3.10.1-1.fc20
Comment 1 Milan Crha 2013-11-15 14:58:25 EST
Thanks for a bug report. I believe it is related to email accounts which you have configured. For example, I have enabled about 5 accounts, and I do not see any such behaviour when I press Send/Receive button from the tool bar.

Could you install debuginfo packages for evolution-data-server and evolution, and maybe other evolution packages you might have installed and using, and grab a backtrace of evolution in the "waiting and CPU consuming" state, please? You can do that with this command:
   $ gdb --batch --ex "t a a bt" -pid=`pidof evolution` &>bt.txt
and attach the bt.txt file here. Please make sure you'll not expose any private data in it, like passwords or email addresses. I usually search for "pass" (quotes for clarity only).

By the way, is UI frozen, when the CPU is high, or you can click for example on the File menu and it'll expand with its submenus immediately?
Comment 2 Paul Finnigan 2013-11-17 14:15:43 EST
Created attachment 825293 [details]
backtrace requested but it has problems!

First the problem does not happen on "send/receive". It happens on pressing "New". It also does not happen when replying! It is only when you press the "New" button for a new mail (or File>New>Mail Message).

When the high CPU occurs evolution is frozen, no response from any element of the UI, although I get messages saying that the aprticular window is not responding and asking if I want to wait or force close evolution.

Another potential help is that (I think) the first time you use the "New" button after a reboot it works fine. It is the second time that it takes forever. This appears to be true even if evolution has been stopped and restarted. I have not tried enough reboots to be certain of these to say they are facts but my current tests would indicate that this is the case.

Final note. I appear to have run into a bug related to #972351 in that backtrace is not working. Bear in mind that I am a novice at this and I just cut and pasted your command to extract the attached report. 

Let me know if there is anything else you need. I will respond but it may take a couple of days as I have a few things to do this week. It is a real pain when work gets in the way :-)
Comment 3 Milan Crha 2013-11-20 07:13:59 EST
Thanks for the update. The backtrace looks fine, it shows some activity in DConf, notifying about changes. There can happen some ping-pong action with these updates, though I didn't see them when creating a new message, but rather in Edit->Preferences, thus what you see might be different from that what I have on mind [1], because the fix from there is already included in your 3.10.1.

Could you run this command on a terminal:
   $ gsettings monitor org.gnome.evolution.mail
and then create the new message, please? I tried it here, but it didn't show any activity, from which I suppose there was no change for me, but maybe there will be some for you.

[1] https://bugzilla.gnome.org/show_bug.cgi?id=698275
Comment 4 Paul Finnigan 2013-11-20 14:28:21 EST
Milan,

Thanks for continuing to look at my problem. I appreciate that is is difficult to trap bugs without being able to reproduce them.

I have tired a few times:

After gsettings command, start Evolution and attempt to send a new mail:

[~]$ gsettings monitor org.gnome.evolution.mail
junk-default-plugin: ''
junk-default-plugin: ''
browser-close-on-reply-policy: 'always'
forward-style-name: 'inline'
show-headers: [('From', true), ('Reply-To', true), ('To', true), ('Cc', true), ('Bcc', true), ('Subject', true), ('Date', true), ('Newsgroups', true), ('Face', true), ('x-evolution-mailer', false)]
reply-style-name: 'quoted'
image-loading-policy: 'never'


The above output is just evolution starting. After about 5-10 minutes the new mail window appeared, at about the same time as a SIGSEGV occured (see below).

Send a new mail (No Output)

[~]$ gsettings monitor org.gnome.evolution.mail

This was repeated several times, each taking either 5-10 minutes to appear with the same SIGSEGV error happening at times. 

Today I have not managed to send a new mail! Either the SIGSEGV error or things just taking so long in the new mail window I abandoned the effort.

Replay to a mail(this always works without problem)
[~]$ gsettings monitor org.gnome.evolution.mail
browser-close-on-reply-policy: 'always'

NB while investigating this problem I have had several aborts (SIGSEGV) that I have reported as https://bugzilla.redhat.com/show_bug.cgi?id=1032690

Is it possible that this is a related problem?

What am I doing now? I built the problem system as a new install from the Fedora 20 alpha release live disc, installing extra software using yum. The data was then restored from a backup of my Fedora 19 system. I restored the mail system from a backup. I then made some changes as I have altered my mail systems since the backup! 

I am ditching that and reconfiguing all my accounts from scratch. I will let you know if that alters anything. Currently I have partially reconfigured just one account (the SMTP is not what I want at present, it will not work everywhere I work) and the new mail button responds as expected. I have this and the original configuration backed up.
Comment 5 Paul Finnigan 2013-11-20 17:45:45 EST
I have just completed reconfiguring everything. It all looks good to me and new mail button responds within seconds, everytime.

It looks like I have an error in my backup! Not too sure what is going on. I have another machine with a similar configuration that restored without problems. I don't need the back-ups as my IMAP server ends up with a copy of everything.

I have even tried backing up and restoring Evolution a few times and it all appears to work OK.

Not only that but I have not seen the problem described in #1032690 since I cleared down my settings and started again.

I will give it a few days but it looks like this can be closed as due to Sue (Stupid user error).
Comment 6 Milan Crha 2013-11-21 06:22:29 EST
*** Bug 1032690 has been marked as a duplicate of this bug. ***
Comment 7 Milan Crha 2013-11-21 06:27:47 EST
Good it works for you, bad it required a start from scratch. This might not be needed, the restore/upgrade should work flawlessly. I'd like to know what caused the issue here, maybe it was just some GSettings data storage being broken, but I understand that the backup holds your personal data, thus I do not want you to share it.

I'm closing this for now, as you suggested, even I do not believe you did anything wrong here (referring to Sue).
Comment 8 Christian Stadelmann 2014-05-01 10:15:03 EDT
doesn't the referenced duplicate https://bugzilla.redhat.com/show_bug.cgi?id=1032690 provide the missing data?

btw: I ran into this bug (the duplicate) just now with evolution 3.10.4, but I am unable to reproduce it. I just opened a mailto: link from firefox multiple times to a already running instance of evolution. Evolution hang for multiple seconds unable to repaint its windows and crashed after a while.
Comment 9 Jozef Mlich 2014-07-10 08:42:33 EDT
I am experiencing more than 10 crashes per day (the duplicate #1032690). My reproducer is just "reading memo-list". The symptom "everything takes a lot of time" is also here.

$ gsettings monitor org.gnome.evolution.mail
browser-close-on-reply-policy: 'always'
browser-close-on-reply-policy: 'always'
browser-close-on-reply-policy: 'always'
browser-close-on-reply-policy: 'always'
...

The 'strace -p `pidof evolution`' gives me following: output
recvfrom(6, 0x20a70a4, 4096, 0, 0, 0)   = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN}], 4, 33) = 0 (Timeout)
recvfrom(6, 0x20a70a4, 4096, 0, 0, 0)   = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=3, events=POLLIN}, {fd=12, events=POLLIN}], 4, 33) = 0 (Timeout)
recvfrom(6, 0x20a70a4, 4096, 0, 0, 0)   = -1 EAGAIN (Resource temporarily unavailable)
...

During the "busy time", there is additionally:
===

close(21)                               = 0
futex(0x13a87d0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x13a87d0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x14713e0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x14713e0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x14158a0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x14158a0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x14158a0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x14158a0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x14158a0, FUTEX_WAKE_PRIVATE, 1) = 0
munmap(0x7f0ab7d32000, 40718)           = 0
munmap(0x7f0ab7d3c000, 1)               = 0
access("/run", F_OK)                    = 0
stat("/run", {st_mode=S_IFDIR|0755, st_size=1580, ...}) = 0
access("/run/user", F_OK)               = 0
stat("/run/user", {st_mode=S_IFDIR|0755, st_size=100, ...}) = 0
access("/run/user/21446", F_OK)         = 0
stat("/run/user/21446", {st_mode=S_IFDIR|0700, st_size=180, ...}) = 0
access("/run/user/21446/dconf", F_OK)   = 0
stat("/run/user/21446/dconf", {st_mode=S_IFDIR|0700, st_size=40, ...}) = 0
open("/run/user/21446/dconf/user", O_RDWR|O_CREAT, 0600) = 21
pwrite(21, "\0", 1, 1)                  = 1
mmap(NULL, 1, PROT_READ, MAP_SHARED, 21, 0) = 0x7f0ab7d3c000
close(21)                               = 0
open("/home/jmlich/.config/dconf/user", O_RDONLY) = 21
fstat(21, {st_mode=S_IFREG|0644, st_size=40718, ...}) = 0
mmap(NULL, 40718, PROT_READ, MAP_PRIVATE, 21, 0) = 0x7f0ab7d32000
close(21)                               = 0
munmap(0x7f0ab7d32000, 40718)           = 0
munmap(0x7f0ab7d3c000, 1)               = 0
access("/run", F_OK)                    = 0
stat("/run", {st_mode=S_IFDIR|0755, st_size=1580, ...}) = 0
access("/run/user", F_OK)               = 0
stat("/run/user", {st_mode=S_IFDIR|0755, st_size=100, ...}) = 0
access("/run/user/21446", F_OK)         = 0
stat("/run/user/21446", {st_mode=S_IFDIR|0700, st_size=180, ...}) = 0
access("/run/user/21446/dconf", F_OK)   = 0
stat("/run/user/21446/dconf", {st_mode=S_IFDIR|0700, st_size=40, ...}) = 0
open("/run/user/21446/dconf/user", O_RDWR|O_CREAT, 0600) = 21
pwrite(21, "\0", 1, 1)                  = 1
mmap(NULL, 1, PROT_READ, MAP_SHARED, 21, 0) = 0x7f0ab7d3c000
close(21)                               = 0
open("/home/jmlich/.config/dconf/user", O_RDONLY) = 21
fstat(21, {st_mode=S_IFREG|0644, st_size=40718, ...}) = 0
mmap(NULL, 40718, PROT_READ, MAP_PRIVATE, 21, 0) = 0x7f0ab7d32000
close(21)                               = 0
===


The backtrace is attached in duplicate bug. Let me know how I can provide you more details.
Comment 10 Matthew Barnes 2014-07-10 12:35:02 EDT
Ben Khan asked me yesterday about a similar delay when starting a new mail, and a backtrace revealed GtkFileChooser synchronously querying all his GVFS mounts in the main thread to assemble the "Places" sidebar, which locked up the UI.

May not be the same as what others are seeing here, but it's something else to look out for.
Comment 11 Milan Crha 2014-07-11 09:11:31 EDT
I suppose the crash from bug #1032690 is fixed upstream by bug:
https://bugzilla.gnome.org/show_bug.cgi?id=710367
I might mark it as a duplicate of it incorrectly, I'm sorry for that.

The "ping-pong" on false change notifications is fixed upstream in evolution with ending commit
https://git.gnome.org/browse/evolution/commit/?id=6e9e7b0676
for 3.13.3+, while a similar changes landed into evolution 3.12.3+ as well.
Comment 12 Milan Crha 2014-07-11 09:12:22 EDT
I forgot to mention, other reasons can influence the window open too, like what Matthew mentioned in the comment #10.

Note You need to log in before you can comment on or make changes to this bug.