Closed Bug 505577 Opened 10 years ago Closed 10 years ago

Scrolling in folder pane is choppy, slow, with high memory when accounts are expanded in folder pane due to junquilla add-on checking db folder info

Categories

(Thunderbird :: Folder and Message Lists, defect)

x86
Windows XP
defect
Not set

Tracking

(Not tracked)

RESOLVED INVALID

People

(Reporter: wsmwk, Unassigned)

Details

(Keywords: perf, Whiteboard: [no l10n impact])

Attachments

(1 file)

+++ This bug was initially created as a clone of Bug #469448 +++

Since quite a long time I see heavy disk activity (very low cpu) when I scroll the folder pane. The activity is related to getting folder information (message counts?) because I see the .msf files being hit when I run filemon. It's not related to any update activity because I see this even if I go offline

It is worse when there more folders exposed in the accounts. And oddly, if I collapse the accounts and uncollapse, then I don't see the problem. That is also seen in filemon.

My folder pane typically has 200 folders exposed.

steps:
1. 200 folders visible in folder pane (RSS, news, 2 imap accounts, local)
2. drag slider from top to bottom

results: there is a visible delay before the slider gets to the mouse position, often it stops briefly at midpoint

alternatives:
a) click below the slider to move it "one step", eg 40 folders, and there is no visible delay
b) scroll quickly up and down from top to bottom

reproducible: Mostly
bienvenu mentioned the folder pane should be getting info from panacea.dat and not going to all the msf files.
(In reply to comment #1)
> bienvenu mentioned the folder pane should be getting info from panacea.dat and
> not going to all the msf files.

Nominating blocking-thunderbird3 in case this is a real perf issue.
Flags: blocking-thunderbird3?
blocking on investigation.  asuth had some thoughts.

wayne, still seeing this?
Flags: blocking-thunderbird3? → blocking-thunderbird3+
(In reply to comment #3)
> blocking on investigation.  asuth had some thoughts.
> 
> wayne, still seeing this?

with 20090722 build I started in safe-mode, couldn't reproduce. started in unsafe mode, couldn't reproduce. (hey now, that's not nice!)  Either it's gone or transient. But I'm sure I wasn't hallucinating when I saw it.  I'll try again after I reboot my windows PC.

I can't test most recent trunk because of bug 507188.
(In reply to comment #4)
> I can't test most recent trunk because of bug 507188.

I can now work around bug 507188.

I no longer see a scroll delay, but still hear IO activity while scrolling, just not as much. I'll test with filemon again to see if it's the same type of activity. I'd be happy for asuth's thoughts

Windows search indexing and gloda is off.  
New mail notifications are never enabled on this machine.
Whiteboard: [no l10n impact]
Given the state of this bug, removing blocking-- if you get significant UX impact, renominate please!
Flags: blocking-thunderbird3+ → blocking-thunderbird3-
This doesn't seem worthy of further time. Will reopen if problem reappears.
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Resolution: FIXED → WORKSFORME
I'm seeing this again. 

I've been running TB3rc2 most of the day. no problems. but scrolling has been strange - like laggy, but different from the behavior described previously in this bug. i.e. I scroll the folder pane and the scroll bar moves just fine, no lag, jerkyness or feeling of bad performance, but the textual content lags by several seconds.

In a fit of cleanup I removed a few huge virtual folders, and changed those that remained by unchecking "online".  No other changes to accounts or addons.

now it changes
last couple starts, i'm at 90mb with one imap folder open.
scroll folder pane down to bottom of news.mozilla.org and I'm at 380mb.
eventually drops down back to ~270mb
but that's still ~100mb more than I've normally been at for the past months.

this last (third or so) startup ...
90mb after start
closed an imap folder (wsm0 account), RSS, and local folders
scrolled down to bottom of news.mozilla.org and I'm at 90mb = no change

something's rotten in denmark
more to come...
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
now consistently seeing this on my vista PC after I moved my main message store with lots of local folders and accounts to this faster PC (vista previously had just a couple accounts and no big local folder store)

xref  Bug 531052
.msfs aren't closing?

100% reproducible today.  After many restarts, I've determined the greatest memory usage (about 400MB) is due to newsgroups - so maybe bug 185634 is to partly blame.  But the whammy is, the memory usage doesn't ever substantially drop, even for the imap accounts/folders. (same results with All Folders vs Smart Folders)

approx figures for vista. 

             MB 
time         memory handles
1. startup   102    400
2. startup+1  95    318
3. scroll    618    521   (about 400MB of which is due to newsgroups)
4. scroll+1  600    400     

1. startup:   ~peak usage without touching UI (35 folders visible in panel)
2. startup+1: peak + 1 minute idle 
3. scroll:    scroll from top imap account to bottom news folder
4. scroll+1:  wait 1-2 minutes, memory goes down a little, but quickly stabilizes

Setup:
* 20091221 Shredder/3.0.1pre
* 2 imap auto logged in @startup, 1 pop not logged in, ~175 imap/news/RSS/virtual folders expanded in pane (l)
* mail.check_all_imap_folders_for_new  = false
* enigmail = no
* theme = default, no others installed

disabled/uninstalled ~1/2 my extensions and no impact no scrolling's memory usage
Status: REOPENED → NEW
Summary: Scrolling in folder pane is choppy, slow → Scrolling in folder pane is choppy, slow, with high memory when accounts are expanded in folder pane
Wayne, I've requested a try server build - http://tinderbox.mozilla.org/showbuilds.cgi?tree=ThunderbirdTry

it adds a new pr log module, MSGDB, that logs db opens and closes. It would be interesting to load the log file in the browser, scroll around, and reload, and see if we've opened and closed the db's.
I get nothing with 
 NSPR_LOG_MODULES=MSGDB:5
meanwhile, I have fiddled with addons, and disabling rkent's junquilla (leaving several others enabled) avoids the problem. I'll do some more tests tomorrow to reconfirm
hmm, maybe I have to do the FORCE_PRLOG stuff for a release build. The debug build logs just fine.
JunQuilla does an an element to the folder pane, the "Uncertain" folder, which then changes the folder icon based on message properties. I take it that there is a theory here that the scrolling issues are associated with the database access. The extension does a call to "db.dBFolderInfo.getBooleanProperty(" on each displayed folder in the folder pane, to see if it needs to have the special "Uncertain" folder processing.

I always though that this was likely to be less disruptive than calculating the number of unread messages, that is also done for each folder by the standard code. But looking at the underlying code I see that unread is calculated using folder member variables and not the database.

I'll try to test this some more myself.

I've never been able to reproduce the symptoms that Wayne has though.
(In reply to comment #14)
> hmm, maybe I have to do the FORCE_PRLOG stuff for a release build. The debug
> build logs just fine.

What's the perf cost of having that logging available all the time ?
(In reply to comment #16)
> (In reply to comment #14)
> > hmm, maybe I have to do the FORCE_PRLOG stuff for a release build. The debug
> > build logs just fine.
> 
> What's the perf cost of having that logging available all the time ?

iirc logging is buffered, so I think in general it's not bad. 

I often have imap logging turned on *all* the time one some of my machines, and I don't notice any delays. heck, I even forget it's turned on (as I found out yesterday doing this bug)
(In reply to comment #16)
> (In reply to comment #14)
> > hmm, maybe I have to do the FORCE_PRLOG stuff for a release build. The debug
> > build logs just fine.
> 
> What's the perf cost of having that logging available all the time ?
Extremely negligible - it doesn't do anything if the env var is not set, other than check that the env var is set. Compare that to the cost of doing file i/o, which is basically what we're logging, and you come up with extremely negligible.
(In reply to comment #15)
> JunQuilla does an an element to the folder pane, the "Uncertain" folder, which
> then changes the folder icon based on message properties. I take it that there
> is a theory here that the scrolling issues are associated with the database
> access. The extension does a call to "db.dBFolderInfo.getBooleanProperty(" on
> each displayed folder in the folder pane, to see if it needs to have the
> special "Uncertain" folder processing.

just to be clear, I'm not blaming junquilla, just reporting results. In fact, in my detailed personal notes of dec 29, the basis for comment 10, I write I uninstalled junquilla and was able to reproduce the problem. go figure.
I've requested a try server build with this patch - it adds two levels of logging of opening and closing db's, and logs the open dbs along with the number of headers in use. NSPR_LOG_MODULES=MSGDB:5 gets you all that; MSGDB:1 just gets you the open and close actions.

From what rkent said, it does sound like junquilla is opening the db's, because that's required to get the db folder info. It's also unclear if it's closing the db's (though it shouldn't if it's asking for that stuff on paint, because it's better just to leave all the db's open.) All of which leads to the fact that it would be nice for extensions to be able to plugin to the folder cache mechanism, to avoid having to open the db to get folder meta info.
Attachment #421640 - Flags: superreview?(neil)
Attachment #421640 - Flags: review?(bugmail)
logging using tryserver worked peachy that time. mailed longs to rkent & bienvenu

(In reply to comment #20)
> it would be nice for extensions to be able to plugin to the folder cache
> mechanism, to avoid having to open the db to get folder meta info.

do we need a bug for that?
worth targeting 3.1?
actually, I think if junquilla used nsIMsgFolder::Get/SetStringProperty, it would automatically get to use the folder cache and not have to worry about this.
Comment on attachment 421640 [details] [diff] [review]
patch to add logging - checked in.

on file: mailnews/db/msgdb/src/nsMsgDatabase.cpp line 103
> PRLogModuleInfo* DBLog;

shouldn't this be static?


on file: mailnews/db/msgdb/src/nsMsgDatabase.cpp line 857
>     PR_LOG(DBLog, PR_LOG_ALWAYS, ("%s - %ld hdrs in use \n",

nit that I don't care about: extra space here before the newline.
Attachment #421640 - Flags: review?(bugmail) → review+
Comment on attachment 421640 [details] [diff] [review]
patch to add logging - checked in.

>+  PR_LOG(DBLog, PR_LOG_ALWAYS, ("closing database    %s \n",
>+    (const char*)m_dbName.get()));
>+
>   RemoveFromCache(this);
>-#ifdef DEBUG_bienvenu1
>-  if (GetNumInCache() != 0)
>-  {
>-    XP_Trace("closing %s\n", m_dbName);
>-    DumpCache();
>-  }
>-#endif

>+  PR_LOG(DBLog, PR_LOG_ALWAYS, ("nsMsgDatabase::Open(%s, %s, %p, %s) \n",
>+    (const char*)summaryFilePath.get(), aCreate ? "TRUE":"FALSE",
>+    this, aLeaveInvalidDB ? "TRUE":"FALSE"));
>+
>+
>   err = OpenMDB(summaryFilePath.get(), aCreate);
>+  if (NS_FAILED(err))
>+    PR_LOG(DBLog, PR_LOG_ALWAYS, ("error opening db %lx", err));
>+
>+  if (PR_LOG_TEST(DBLog, PR_LOG_DEBUG))
>+    DumpCache();
I'm slightly curious as to why you want to dump the cache in a different place.
Attachment #421640 - Flags: superreview?(neil) → superreview+
(In reply to comment #24)
> >+
> >   err = OpenMDB(summaryFilePath.get(), aCreate);
> >+  if (NS_FAILED(err))
> >+    PR_LOG(DBLog, PR_LOG_ALWAYS, ("error opening db %lx", err));
> >+
> >+  if (PR_LOG_TEST(DBLog, PR_LOG_DEBUG))
> >+    DumpCache();
> I'm slightly curious as to why you want to dump the cache in a different place.

It's marginally easier to force a database to get opened than it is to get one closed, so you can do something that forces a new db to get opened, and then you can reload the log to see what db's are open.
Attachment #421640 - Attachment description: patch to add logging → patch to add logging - checked in.
I've updated https://wiki.mozilla.org/MailNews:Logging with info about this log module.
closing invalid since it's caused by extension
Status: NEW → RESOLVED
Closed: 10 years ago10 years ago
Resolution: --- → INVALID
Summary: Scrolling in folder pane is choppy, slow, with high memory when accounts are expanded in folder pane → Scrolling in folder pane is choppy, slow, with high memory when accounts are expanded in folder pane due to junquilla add-on checking db folder info
Version: Trunk → 3.0
Comment on attachment 421640 [details] [diff] [review]
patch to add logging - checked in.

bienvenu, is this also checked in on 1.9.2?
Attachment #421640 - Flags: approval1.9.2.1?
this is a comm-central patch, and is on the comm-central trunk, but not the 3.0x branch.
Comment on attachment 421640 [details] [diff] [review]
patch to add logging - checked in.

I landed this for 3.02, so it will be in 3.0x builds going forward.
Attachment #421640 - Flags: approval1.9.2.1?
Comment on attachment 421640 [details] [diff] [review]
patch to add logging - checked in.

Standard8 gave approval in person last week.
Attachment #421640 - Flags: approval-thunderbird3.0.2+
Strange to have a+ on an INVALID bug.
it's a+ on a patch, not on the bug.
Comment on attachment 421640 [details] [diff] [review]
patch to add logging - checked in.

clearing approval because it messes up the queries and looks like a patch that needs landing.
Attachment #421640 - Flags: approval-thunderbird3.0.2+
You need to log in before you can comment on or make changes to this bug.