Bug 11139 - (int-161187) Long delays in email interface
(int-161187)
: Long delays in email interface
Status: RESOLVED FIXED
Product: Email
General
: 5.0:(10.2010.19-1)
: N900 Maemo
: Unspecified critical with 9 votes (vote)
: 5.0/(20.2010.36-2)
Assigned To: unassigned
: modest-bugs
:
:
:
:
  Show dependency tree
 
Reported: 2010-08-15 19:00 UTC by Richard Merren
Modified: 2010-10-26 17:44 UTC (History)
8 users (show)

See Also:


Attachments
gconf file that results in poor performance (42.36 KB, text/xml)
2010-09-07 20:43 UTC, Neil MacLeod
Details


Note

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


Description Richard Merren (reporter) 2010-08-15 19:00:13 UTC
SOFTWARE VERSION:unknown, but using N900 with pr1.2
(Settings > General > About product)

EXACT STEPS LEADING TO PROBLEM: 
(Explain in detail what you do (e.g. tap on OK) and what you see (e.g. message
Connection Failed appears))
1. Click on email icon
2. when list of mail accounts comes up, click on Mail for Exchange
3. There is a very long delay (sometimes a minute or more while waiting for the
list of emails to appear.
4. When list of emails comes up, click on an email.  It highlights in blue, and
then there is another long delay waiting for the email to open
5. The email finally opens.  Click the left and right arrows to navigate to
other emails.  This happens without delay.

Also: Click on the yellow email alert and there is a long delay before the
email opens.

EXPECTED OUTCOME: The list appears quickly or the email opens quickly

ACTUAL OUTCOME: Long delays to get list of emails or individual emails

REPRODUCIBILITY: ALWAYS
(always, less than 1/10, 5/10, 9/10)

EXTRA SOFTWARE INSTALLED: unsure how to generate the list or what is relevant. 
Please advise if this is necessary.

OTHER COMMENTS:

A few (possibly related) items:

If I run dbus-monitor, during the delay time I see several of these:

method call sender=:1.71 -> dest=org.freedesktop.Notifications serial=99757
path=/org/freedesktop/Notifications; interface=org.freedesktop.Notifications;
member=CloseNotification
   uint32 163
signal sender=:1.31 -> dest=(null destination) serial=99227
path=/org/freedesktop/Notifications; interface=org.freedesktop.Notifications;
member=NotificationClosed
   uint32 163
method call sender=:1.31 -> dest=com.nokia.HildonSVNotificationDaemon
serial=99228 path=/com/nokia/HildonSVNotificationDaemon;
interface=com.nokia.HildonSVNotificationDaemon; member=StopEvent
   int32 165
method return sender=:1.31 -> dest=:1.71 reply_serial=99757
method call sender=:1.71 -> dest=org.freedesktop.Notifications serial=99758
path=/org/freedesktop/Notifications; interface=org.freedesktop.Notifications;
member=CloseNotification
   uint32 162
signal sender=:1.31 -> dest=(null destination) serial=99230
path=/org/freedesktop/Notifications; interface=org.freedesktop.Notifications;
member=NotificationClosed
   uint32 162

and then lots of these:

error sender=:1.31 -> dest=:1.71
error_name=org.freedesktop.DBus.GLib.ErrorError reply_serial=99776
   string "Method invoked for CloseNotification returned FALSE but did not set
error"
method call sender=:1.71 -> dest=org.freedesktop.Notifications serial=99777
path=/org/freedesktop/Notifications; interface=org.freedesktop.Notifications;
member=CloseNotification
   uint32 142
error sender=:1.31 -> dest=:1.71
error_name=org.freedesktop.DBus.GLib.ErrorError reply_serial=99777
   string "Method invoked for CloseNotification returned FALSE but did not set
error"
method call sender=:1.71 -> dest=org.freedesktop.Notifications serial=99778
path=/org/freedesktop/Notifications; interface=org.freedesktop.Notifications;
member=CloseNotification
   uint32 141
error sender=:1.31 -> dest=:1.71
error_name=org.freedesktop.DBus.GLib.ErrorError reply_serial=99778
   string "Method invoked for CloseNotification returned FALSE but did not set
error"
method call sender=:1.71 -> dest=org.freedesktop.Notifications serial=99779
path=/org/freedesktop/Notifications; interface=org.freedesktop.Notifications;
member=CloseNotification
   uint32 140
error sender=:1.31 -> dest=:1.71
error_name=org.freedesktop.DBus.GLib.ErrorError reply_serial=99779
   string "Method invoked for CloseNotification returned FALSE but did not set
error"
method call sender=:1.71 -> dest=org.freedesktop.Notifications serial=99780
path=/org/freedesktop/Notifications; interface=org.freedesktop.Notifications;
member=CloseNotification
   uint32 139
error sender=:1.31 -> dest=:1.71
error_name=org.freedesktop.DBus.GLib.ErrorError reply_serial=99780
   string "Method invoked for CloseNotification returned FALSE but did not set
error"
method call sender=:1.71 -> dest=org.freedesktop.Notifications serial=99781
path=/org/freedesktop/Notifications; interface=org.freedesktop.Notifications;
member=CloseNotification
   uint32 138

The file
/var/lib/gconf/apps/modest/accounts/Mail@32@for@32@ExchangeID/%gconf.xml is
growing frequently, and it appears to be the <li> nodes in the notification
ids.  A sample:

<?xml version="1.0"?>
<gconf>
        <entry name="notification_ids" mtime="1281391489" type="list"
ltype="int">
                <li type="int" value="163"/>
                <li type="int" value="162"/>
                <li type="int" value="160"/>
                <li type="int" value="159"/>
                <li type="int" value="158"/>
                <li type="int" value="157"/>
                <li type="int" value="156"/>
                <li type="int" value="155"/>
                <li type="int" value="154"/>
                <li type="int" value="153"/>
                <li type="int" value="152"/>
                <li type="int" value="151"/>
                <li type="int" value="150"/>
                <li type="int" value="149"/>
                <li type="int" value="148"/>

This is making email unusable.  I would like to find a solution short of
re-flashing the device--especially because a reflash would not help others
avoid the bug or conflict responsible for this.

User-Agent:       Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.2.8)
Gecko/20100723 Ubuntu/10.04 (lucid) Firefox/3.6.8
Comment 1 Neil MacLeod maemo.org 2010-08-17 00:20:14 UTC
Similar behaviour here - I have few if any emails in my Nokia Messaging device
inbox, yet navigating from the account selection screen to the folder list can
take 20-30 seconds, and opening the inbox takes another 20-30 seconds (even if
it contains only a single email) and opening an email (any email) can take
20-30 seconds.

Modest is awful, really. With each passing day it's becoming less and less
practical to read emails on the device - when I do have an important email to
read I make sure I have plenty of time to do so.
Comment 2 Andre Klapper maemo.org 2010-08-20 09:46:22 UTC
*** Bug 11162 has been marked as a duplicate of this bug. ***
Comment 3 Richard Merren (reporter) 2010-08-23 16:23:04 UTC
*** This bug has been confirmed by popular vote. ***
Comment 4 Bosikov 2010-08-23 18:47:42 UTC
This happen after last OS update for n900.
Comment 5 Richard Merren (reporter) 2010-08-23 19:06:59 UTC
Regarding comment #4: my issues started some time after I installed PR1.2, but
if the issue is related to the continually increasing number of dbus
notification messages being sent, then it may have taken some time for the
number of messages to create delays which were noticeable.

One more note: I can put the phone into offline mode and the delays are the
same.  That suggests that the issue is not related to communication between
modest and the email server.
Comment 6 gidyn 2010-08-27 09:21:30 UTC
In addition to the symptoms described, Modest often locks up on me when
attempting to display HTML email. A handful of modest pictures (which download
in a few seconds in the browser) will make Modest seize up for so long that the
OS offers to kill it.

An example of this is ebuyer emails (http://www.ebuyer.com/eblast), but I've
had others with worse delay-to-size ratio.
Comment 7 Richard Merren (reporter) 2010-08-27 17:31:53 UTC
I deleted the account from the phone and recreated it.  After a few minutes of
sync, the account was restored with nothing gone, and the delays were no longer
in place.  Whether it was related or not, the gconf file mentioned previously
no longer contained a node for entry name="notification_ids", which was
continually increasing in size before.  I will check to see if, over time, this
starts to build up again and if that corresponds to increasing delays.

In any case, if anyone else is experiencing this problem, I would suggest as a
workaround that you remove the account and then recreate it.  Much less drastic
than reflashing the phone, and it seems to eliminate the problem (for now).  I
will report here if the delays begin to creep up again.
Comment 8 Richard Merren (reporter) 2010-08-30 05:33:59 UTC
After recreating the account, the notification ids list immediately started
increasing again, and the size of the list was directly related to the number
of dbus calls that were seen when the email was opening.  Previously, I could
not delete the list from the gconf file because it simply reappeared shortly
after I saved the gconf file.

I was able to remove it, though, by killing the two instances of modest (with
pids found through a "ps -ef | grep modest", updating the file, then killing
the new pids found with another ps, then rebooting for good measure.  Not sure
if all of that was necessary (I'm sure there is some simpler combination that
will keep the file from being rewritten after the deletes), but the deleted
lines in the file stayed deleted, so I think this is a useable workaround short
of removing and restoring the account.  When the list builds up enough to cause
noticeable delays (I had thousands of entries in this list, causing thousands
of dbus calls on every email operation), I will try deleting like this again
and see if that clears it up.

None of this explains why the problem is happening, but at least it helps me
get my email back to usability when it gets bad.
Comment 9 Andre Klapper maemo.org 2010-08-30 14:49:27 UTC
(In reply to comment #6)
> In addition to the symptoms described

Please file a separate report & attach a testcase without confidential data.
Comment 10 Richard Merren (reporter) 2010-09-07 18:25:19 UTC
Just a quick update: after a week the delay was becoming noticeable again.  The
number of entries in the notification_ids node climbed up above 500.  I edited
the gconf file, removed the entries in the notification_ids node, and
immediately rebooted and the nodes stayed deleted.  The delay is gone again
(for now).  These notification ids building up are definitely the culprit for
the delay.  The question now is why the notification ids are building up
without being deleted.  I have a theory surrounding the spam filtering on my
exchange server (modest usually gives me an email notification BEFORE it gets
moved out of the inbox into junk mail) and I will try to test this theory and
report back here.
Comment 11 Richard Merren (reporter) 2010-09-07 18:59:52 UTC
Following up on the last comment, I observed the following by watching the
gconf file:

When an email comes in, a notification is delivered (the yellow alert) and an
li node is added to the notification node in the gconf file.  When the
notification is cleared, the li node remains.  When the email is read, the li
node remains.  When the email is deleted, the li node remains.  Even if I wait
a while and check again, the li node remains. 

I have a gmail account as well.  I rarely use it and don't get many emails at
all on it.  It is showing the same behavior as the MFE account: the li nodes
are added but never removed.

When I get spam on my MFE account, I get a notification (modest sees it in the
inbox and alerts me before my mail host moves it to the junk folder).  I get
mulitple li nodes for spam--the first one when the original message arrives and
additional ones when the mail is moved to the junk folder.

I have been getting a high volume of spam lately, as well as a large number of
automated email messages from systems at work, so the list was able to build up
quickly.  I don't know whether others are seeing this behavior, or whether I
have some setting that is causing these notification_ids (and the related dbus
messages that go with them) to build up.  I know there are a few others
watching this thread, so I would be interested to know if they are seeing the
notification_ids node in the gconf file (see the original bug description for
the file location) similarly growing.
Comment 12 Neil MacLeod maemo.org 2010-09-07 19:53:50 UTC
> I would be interested to know if they are seeing the notification_ids
> node in the gconf file

Yep, I have 1382 "<li>" nodes at the moment, some of which are duplicated more
than once, eg:

                <li type="int" value="228"/>
                <li type="int" value="228"/>
                <li type="int" value="228"/>

Each new email that arrives in my inbox creates one new "<li>" node.

I'm using Nokia Messaging accessing a single Google Mail account.

It's frustrating and saddening to see you put in all this effort diagnosing
what is almost certainly an easy to reproduce flaw, only to see it being
ignored by Nokia and in particular the Modest developers.

I can only hope the QT Messaging Framework[1] will finally give Nokia owners
the email client they deserve, but this is of precious little comfort for
existing N900/Maemo owners that are saddled with the amateur hour rubbish which
is Modest.

1. http://moimart.tumblr.com/post/898095695/qt-messaging-fw-is-in-meego
Comment 13 Neil MacLeod maemo.org 2010-09-07 20:04:12 UTC
I should also add that each new email is generating a new <li> node with a new
sequential number, the last number generated is 230.

However I there are <li> nodes in the gconf file that already have higher
sequential numbers (340, 341, 342 etc.) that are "further down" the gconf file,
eg. 

                <li type="int" value="2"/>
                <li type="int" value="1"/>
                <li type="int" value="341"/>
                <li type="int" value="340"/>
                <li type="int" value="339"/>

I have deleted my Nokia Messaging account in the past, I've also attempted a
restore from backup on two previous occasions (PR1.1, PR1.2, both failed due to
Nokia Messaing account details not restoring properly from backups) which may
have "corrupted" the gconf file.

Irrespective of the backups however, there seems little need to keep all these
old <li> nodes present in the file - my inbox currently contains 4 emails.

The performance of Modest on the device is now so bad that I don't even bother
reading emails unless I'm expecting to receive an important email.

Changing severity to Critical, because Modest is verging on the unusable.
Comment 14 Richard Merren (reporter) 2010-09-07 20:27:00 UTC
Neil: Try deleting the <li> nodes, saving the file, and then immediately
rebooting.  After reboot, check the file to see that the <li> nodes are still
gone (they can get rewritten by modest if you don't shut down).  Then test your
email to see if the delays are gone.

This is by no means a solution, but it should make your modest useable again.

I have looked through the modest code and I can find where these
notification_id nodes are being created, but I can't find any code that removes
them.

I agree that this is frustrating, but I am still trying to be nice to the
developers and Nokia people, who I would love to hear from in some fashion.
Comment 15 Neil MacLeod maemo.org 2010-09-07 20:43:35 UTC
Created an attachment (id=3077) [details]
gconf file that results in poor performance

Hi Richard, I can confirm that deleting all the <li> nodes (actually, I left
one as follows:

        <entry name="notification_ids" mtime="1283880647" type="list"
ltype="int">
                <li type="int" value="1"/>
        </entry>

and then rebooting *DOES* resolve the performance issue - the next email I
received created the following node:

                <li type="int" value="2"/>

and performance was more than acceptable (back to normal, one could say).

However as you point out, this isn't really an acceptable solution - it just
proves the point or at least identifies where problem is occurring, it's now up
to Nokia to provide a fix, hopefully there is still time for PR1.3 but chances
are the lack of any developer input on this bug means we have missed that boat.

Unfortunately the lack of Nokia developer involvement in Bugzilla has been a
major issue since it's inception in 2005 (see bug #630 for more details) and
it's unlikely this bug will ever be fixed on Maemo.

I am attaching my original gconf file to this bug should any Nokia or Modest
developer care to show the slightest bit of interest in their product.
Comment 16 Neil MacLeod maemo.org 2010-09-07 20:45:03 UTC
@Richard: Thanks for your efforts on this bug, btw.
Comment 17 Neil MacLeod maemo.org 2010-09-07 20:54:19 UTC
It's interesting to note that despite only having two <li> nodes in the gconf
file, I can still any existing emails in my inbox without a problem (I now have
7 emails in my inbox, and only two <li> node entries).

Switching between views in Modest is now fast (ie. selecting account, opening
inbox, opening emails etc.) when previously these same actions took many many
seconds suggesting that the gconf file is being parsed at every opportunity.
Not only is this grossly inefficient, it's compounded by the fact that old
entries are never removed.

Having deleted the <li> nodes, when a new email comes in the token that floats
across the top of the screen now appears more quickly and is less intrusive -
previously, the current application would freeze as the device vibrated to
signify a new email, then after a short delay the token would glide across the
top of the screen and then eventually the current application would begin to
respond again. Obviously this notification process is also parsing the gconf
file and bringing the device to it's knees...
Comment 18 Richard Merren (reporter) 2010-09-07 23:46:28 UTC
I don't think it is the parsing of the gconf file, but the dbus calls to
CloseNotification.  This call closes the yellow box on the task manager page. 
The id is not related to how many emails you have, but how many notifications
have opened since you started up the device.  The call is made when you open a
folder or email so that the notifications are cleared.

You can test it out yourself if you like if you have mdbus2 installed (I'm sure
you can use other dbus tools, also).  Wait until you have emails waiting and
then look at the gconf file to see what is at the top of the list (those appear
to be the newest ones).  You will see some notification id numbers.  Pick the
first one (for our example, we'll use the number 6).  From a command line type
the following:

mdbus2 org.freedesktop.Notifications /org/freedesktop/Notifications
org.freedesktop.Notifications.CloseNotification 6

You should see the notification disappear (or, if there are multiple
notifications, you will see the number decrement).

If you look at the dbus calls available on notify, you will see that there is
no way to obtain a list of open notifications.  So modest is keeping track of
ALL of the notifications it opens and just sending close messages for all of
them when you open the email.  But after it sends the close messages, it is
apparently NOT clearing out the list of messages.  This appears to be the bug. 
If, after sending the close messages, modest wiped out its list of
notification_ids, the list would never build up very big and and the
closenotification calls would not delay opening except in very rare cases.

The modest website lists some mail lists and an irc channel for communication. 
I am going to look at those and see if there is any info on fixes or releases,
etc.  It should be somewhat simple to install an updated version of modest
outside of the pr1.3 train...whether doing so a good idea is another question
entirely.
Comment 19 Richard Merren (reporter) 2010-09-08 01:24:58 UTC
It looks like this problem may be fixed in this commit:

http://gitorious.org/modest/modest/commit/cbfb96c950c42963ae971cc6a2355c8897f7bf28

which appears to be in version 3.3.  The version in our repositories (or, at
least, installed on my device) in 3.2.13.  I am looking into possibility of
upgrading (I know its possible...I just want to figure out how much trouble it
is an whether it is worth it.)  This will probably require some scratchbox
testing before I mess with the phone, but if I get to work on it soon I will
report here.
Comment 20 Neil MacLeod maemo.org 2010-09-08 04:03:47 UTC
> I don't think it is the parsing of the gconf file,

You're right, it's the dbus spamming and not parsing that is causing the delays
(although Modest does seem to be parsing or at least iterating the list with
each action, necessary in order for it to spam dbus so successfully).

I've now run dbus-monitor and I see the same multitude of dbus notifications as
you have seen, but now much reduced thanks to purging the gconf file of <li>
nodes.

As you have discovered Modest is firing out these dbus calls when navigating
between any action - whether that be navigating from the Nokia Messaging client
selection screen to the individual account selection screen, from there to the
folder selection screen, when viewing the inbox or even reading an email -
every time I change a view there follows a mass of these dbus notification
calls, one for each <li> node. Since I was up to 1382 of these <li> nodes it's
no wonder my device was performing like cr@p!

Modest is basically spamming dbus every time the user does something - anything
- and since these dbus calls are sent once for each <li> node it's a
horrifically inefficient design decision.

The mass of dbus notifications also seem to serve no real purpose once the user
is actively using Modest - if the intention is to close the new mail
notification icon then logically it this icon must already have been closed if
the user is navigating within Modest... so why are the dbus calls even
necessary?

Fixing the notification system so it cleans up the gconf file as each
notification is accessed is one part of the problem, but fixing Modest so that
it doesn't spam dbus unnecessarily would also be a very worthwhile improvement
(although fixing the former would almost certainly resolve - or at least hide -
the latter problem).

> It looks like this problem may be fixed in this commit:

Great news, let's hope it's not too late for PR1.3, assuming there is a PR1.3.
Hopefully Andre can give us an update in the few days, I pinged him on IRC
earlier this evening to see if this issue could get some official
attention/response as you have done so much of the donkey work identifying the
underlying issue. Thanks again for that.
Comment 21 Andre Klapper maemo.org 2010-09-08 09:23:38 UTC
(In reply to comment #19)
> It looks like this problem may be fixed in this commit: http://gitorious.org
> /modest/modest/commit/cbfb96c950c42963ae971cc6a2355c8897f7bf28 (int-161187)

Would be great to get a confirmation if that commit really fixes it.
Fix was included in the internal non-public image 2010.23-4 (modest 3.4.0+0m5)
and will definitely be part of the next public update for Maemo5.
Comment 22 Andre Klapper maemo.org 2010-09-08 09:38:05 UTC
Internal comment: "This fix is available in the next public release. And yes,
it was the reason for slow folder opening problem."
Comment 23 Neil MacLeod maemo.org 2010-09-08 20:17:36 UTC
Thanks Andre, Richard.
Comment 24 Andre Klapper maemo.org 2010-10-25 17:12:40 UTC
The problem reported here should be fixed in the update that was released today
for public: The Maemo5 update version 20.2010.36-2 (also called "PR1.3"
sometimes). Please leave a comment if the problem is not fixed for you in this
update version.
Comment 25 Javier S. Pedro 2010-10-26 02:43:11 UTC
I can confirm it works, but note that it seems you need to

A) Get a notification
B) Tap on it (so as to clear it)

.. in order to invoke "the fix" and clear all the notifications. After that,
delays are gone.
Comment 26 pancake 2010-10-26 17:44:44 UTC
Is this the way to remove those notification IDs? at least it looks a bit
faster

for a in `gconftool --all-dirs /apps/modest/accounts`; do gconftool -s --type
list --list-type int '[]' $a/notification_ids ; done