Open Bug 1504141 Opened 6 years ago Updated 8 months ago

New and Edit have long delay in opening Filter Rules dialog

Categories

(Thunderbird :: Filters, defect)

Product:
Thunderbird
Component:
Filters
Version:
52 Branch
Type:
defect

Tracking

(Not tracked)

People

(Reporter: helmo, Unassigned, NeedInfo)

References

Details

(Keywords: perf, Whiteboard: [filtermgmt]) 

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0

Steps to reproduce:

I click on the 'New' button in the Message Filters dialog.
Then I have to wait 10+ seconds for the 'Filter Rules' dialog to appear.

I've selected version 60 because that's what I'm using, but this problem has existed for a while.

I get the feeling that it's related to things that work on a list of folders. The 'Move to' and 'Copy to' context menu's are also affected by these delays.

I know I have a lot of folders, 400+ spread over 5 imap accounts.



Actual results:

After about 5 seconds the whole ui is grayed out.
After 10+ seconds it appears and works OK.


Expected results:

The dialog should open seemingly instant.
How much memory is Thunderbird using?
Also, does this reproduce after help > restart with addons disabled?
Component: Untriaged → Filters
Flags: needinfo?(helmo)
Keywords: perf
Version: 60 → 52 Branch
I just tried it again and yes, when started in safemode it is just as slow.


After running in safemode for a few minutes:
$ cat /proc/8734/status 
Name:	thunderbird
State:	S (sleeping)
Tgid:	8734
Ngid:	0
Pid:	8734
PPid:	12404
TracerPid:	0
Uid:	1000	1000	1000	1000
Gid:	1000	1000	1000	1000
FDSize:	1024
Groups:	4 20 24 27 30 33 46 109 124 127 136 140 1000 
NStgid:	8734
NSpid:	8734
NSpgid:	8734
NSsid:	12404
VmPeak:	 4556504 kB
VmSize:	 3092596 kB
VmLck:	       0 kB
VmPin:	       0 kB
VmHWM:	 2559336 kB
VmRSS:	  445748 kB
VmData:	 2565648 kB
VmStk:	     140 kB
VmExe:	     196 kB
VmLib:	  170300 kB
VmPTE:	    3640 kB
VmPMD:	      28 kB
VmSwap:	       0 kB
HugetlbPages:	       0 kB
Threads:	89
SigQ:	1/128341
SigPnd:	0000000000000000
ShdPnd:	0000000000000000
SigBlk:	0000000000000000
SigIgn:	0000000000001000
SigCgt:	0000000f820044ff
CapInh:	0000000000000000
CapPrm:	0000000000000000
CapEff:	0000000000000000
CapBnd:	0000003fffffffff
CapAmb:	0000000000000000
Seccomp:	0
Speculation_Store_Bypass:	thread vulnerable
Cpus_allowed:	ff
Cpus_allowed_list:	0-7
Mems_allowed:	00000000,00000001
Mems_allowed_list:	0
voluntary_ctxt_switches:	59661
nonvoluntary_ctxt_switches:	5321
```


And in normal mode:
$ cat /proc/12589/status
Name:	thunderbird
State:	S (sleeping)
Tgid:	12589
Ngid:	0
Pid:	12589
PPid:	12404
TracerPid:	0
Uid:	1000	1000	1000	1000
Gid:	1000	1000	1000	1000
FDSize:	1024
Groups:	4 20 24 27 30 33 46 109 124 127 136 140 1000 
NStgid:	12589
NSpid:	12589
NSpgid:	12589
NSsid:	12404
VmPeak:	 4931008 kB
VmSize:	 4223216 kB
VmLck:	       0 kB
VmPin:	       0 kB
VmHWM:	 2824836 kB
VmRSS:	 2132660 kB
VmData:	 3695584 kB
VmStk:	     176 kB
VmExe:	     196 kB
VmLib:	  170300 kB
VmPTE:	    5560 kB
VmPMD:	      28 kB
VmSwap:	       0 kB
HugetlbPages:	       0 kB
Threads:	78
SigQ:	1/128341
SigPnd:	0000000000000000
ShdPnd:	0000000000000000
SigBlk:	0000000000000000
SigIgn:	0000000000001000
SigCgt:	0000000f820044ff
CapInh:	0000000000000000
CapPrm:	0000000000000000
CapEff:	0000000000000000
CapBnd:	0000003fffffffff
CapAmb:	0000000000000000
Seccomp:	0
Speculation_Store_Bypass:	thread vulnerable
Cpus_allowed:	ff
Cpus_allowed_list:	0-7
Mems_allowed:	00000000,00000001
Mems_allowed_list:	0
voluntary_ctxt_switches:	32758
nonvoluntary_ctxt_switches:	1266
Flags: needinfo?(helmo)
400 isn't an excessive amount of folders.  And the Move to speed issue shouldn't (bad word) be related. 
I have no idea what is going on
How many filters are there?

I only have 15 folders with a total of 19 filters and don't see this behavior.
Flags: needinfo?(helmo)
roughly 50 filter rules split over the various accounts. But loading the list of filters is near instant. It's the New and edit dialogs that take a long time.
Flags: needinfo?(helmo)
Not seeing any problem with my Thunderbird 60.2.1 on Linux.

Do you have the Filter Log enabled, and clear the log periodically? 

Do you compact folders regularly?

Have you tried going to Help > Troubleshooting Information, clicking on about:memory, then clicking GC, CC and the Minimize memory usage buttons in the Free memory section? You have to click the Measure button in the Free memory section after clicking each of the buttons in the Free memory section.
Hmm, I see that I have the filter log enabled ... the window seems empty at first .... but after waiting a while it shows logs going back 10 years ;)  ... wow 470000+ lines

I guess I never waited long enough there to see it... a spinner there to show that the log is loading might have been a good indication.

Thanks for the hints, I'll try to remember to clear that log periodically.

Why would anything be done with that log anyway? I don't see where the new/edit dialog needs access to the filter log.

The root of this issue has improved a bit now that I cleared that log.

However opening the first new/edit dialog from message filters is still equally slow, when I close it and directly open a new one it now opens near quickly.
When I leave the message filters window idle for a few minutes and try the edit button it's slow again.
> Hmm, I see that I have the filter log enabled ... the window seems empty at first .... but after waiting a while it shows logs going back 10 years ;)  ... wow 470000+ lines

aceman, do we not have a bug report for this?  I couldn't find one, which is hard to believe
Flags: needinfo?(acelists)
> I know I have a lot of folders, 400+ spread over 5 imap accounts.

I probably have more than this, but not on linux.  And way more than 50 rules.

I cannot find a bug report for this so my instinct is this must be something in your environment.
Are you seeing it with version 60?
Flags: needinfo?(helmo)
(In reply to Wayne Mery (:wsmwk) from comment #8)
> > Hmm, I see that I have the filter log enabled ... the window seems empty at first .... but after waiting a while it shows logs going back 10 years ;)  ... wow 470000+ lines
> 
> aceman, do we not have a bug report for this?  I couldn't find one, which is
> hard to believe

I don't remember one. But opening a 470000 line html document may take a while. But it should not affect opening the New filter dialog. If it does, it is a bug.

The reporter has 400 folders. The New filter dialog instantiates 2 folder pickers for the Moveto/Copy to actions. But the pickers only initially read through the top level accounts, not any deeper children. The reporter only has 5 accounts.
Flags: needinfo?(acelists)
(In reply to :aceman from comment #10)
> (In reply to Wayne Mery (:wsmwk) from comment #8)
> > aceman, do we not have a bug report for this?  I couldn't find one, which is
> > hard to believe
> 
> I don't remember one. But opening a 470000 line html document may take a
> while. But it should not affect opening the New filter dialog. If it does,
> it is a bug.

It is definitely a thing with processing email because I've had it mentioned in https://wiki.mozilla.org/Thunderbird:Testing:Memory_Usage_Problems for years - never occurred to me to file a bug.  

But this was the first I've heard it affecting opening filters.  Shouldn't be hard to reproduce.
Flags: needinfo?(vseerror)
Thanks for looking into this.

I'm using version 60.2.1+build1-0ubuntu0.16.04.4

Another hint might be that when I open the context menu on an email message and select the MoveTo or CopyTo option I see a similar delay before it opens.
Once opened and closed again it does open quickly the next time.
But only then a few minutes later the delay is back.
Flags: needinfo?(helmo)
Thanks also for the wiki link, I've gone over the list.

Removing the only gmail account in there did NOT change this.

global-messages-db.sqlite is 8,5GB with the ImapMail folder being 27GB. but the global search works fine.

I do have a few folders larger the 3GB but opening them is near instant.

One moment where Thunderbird does sometimes freeze completely is while it's indexing a batch of new messages. E.g. after a fresh start it will refresh most folders is the background... when it hits a folder with some new messages it will freeze for a moment. I've confirmed this by opening the ActivityManager. It would be nice if indexing could be done in a separate thread... but that's for another issue ;)
It could have to with populating the "Recent" folder list in the folder picker. That one has to go over all the folders.

Can you try some picker that does not have that list?
E.g. if you customize the main toolbar, there is a "Folder location" widget. This folder picker also shows all accounts and folders, but without the "Recent" submenu.
The "Folder location" widget is a nice gem to find :) ... 
Without the 'Quick Folder Move' add-on that is indeed missing the "Recent" part and quick.

The "Recent" list sounds like a prime suspect.

I do however love the Quick Folder Move add-on, so it would be great if the recent list could be improved.
I'm eyeing to improve the Recent list in bug 809066 :)
(In reply to Herman van Rink from comment #12)
> Another hint might be that when I open the context menu on an email message
> and select the MoveTo or CopyTo option I see a similar delay before it opens.
> Once opened and closed again it does open quickly the next time.
> But only then a few minutes later the delay is back.

Then this could be caused by the folder caching. First population of the cache is slow, then next use of the folder (list) is fast, until other folders get into the cache and push out the previous entries.

If you have enough RAM, you can try to play with higher values of prefs controlling the cache:
// How long should we leave idle db's open, in milliseconds.
pref("mail.db.idle_limit", 300000);
// How many db's should we leave open? LRU db's will be closed first
pref("mail.db.max_open", 30);

You can set these in Edit->Preferences->Advanced->Config editor .

If you have 400 folders, the default limit of 30 folders in the cache can be a bottleneck and folders are 'fighting' for a place in the cache constantly :)
Mem usage was normally around 2.8% (of my 32GB physical RAM)

When I open a MoveTo menu it rises to 9.5% during the time it takes to show the result.

I tried to time how long it takes to drop down to 2.8% again...but it varies ...sometimes more but sometimes also less then the 300 seconds of mail.db.idle_limit

I tried doubling mail.db.idle_limit and mail.db.max_open but did show little effect, base memory went from 2.8 to 3.5%

Setting mail.db.max_open to 500 seems to keep memory usage at 9.5% longer. After the idle_limit it eventually dropped to 5.3%.


Still strange that these need to be open just to create a list of recently used folders ... but I'll just set db.idle_limit to a 8 hours.

(In reply to Herman van Rink from comment #18)

Still strange that these need to be open just to create a list of recently
used folders ...

Yes, I thought there is also some other cache that stores folder properties so that they do not need to be loaded in full just to read their name and last access time. But I'm no expert in this area.

Meanwhile, I have fixed bug 809066 so that the Recent submenu is populated with all the folders only if you really open it, not when the folder picker (e.g. in the Move To context item) is built. That should improve things a lot. But sadly it probably want be backported do TB 60.

If you solved your problem with setting db.idle_limit then that is probably a good workaround for now, until then next release of TB.

Do you think there is anything more to be done in this bug?

Depends on: 809066
OS: Unspecified → All
Hardware: Unspecified → All

I still see some delays as the memory usage is sometimes dropping well within the idle_limit. But not as far down as before so it's often a second or two(and now I know what yo look for)
I guess there are conditions in which caches are dropped for other reasons.

Finding a separate storage for these properties would still be a good optimization, but that should be a separate bug to keep it focused.
I've just opened bug 1519375 for that.

Lets close this one.

While I was playing with bug 809066 I did NOT see all the folders in 'Recent' list be opened and in the cache.

Can you please retry disabling the 'Quick Folder Move' addon whether it causes the slowness and opening/caching of many folders? AFAIK it allows some search facilities so maybe it loads more folders beforehand, than the base TB would do.

strange.
I've checked again and with that add-on disabled(and restarted)... I see the same delay.

I have about 1700 local folders. Message Filters: New or Edit is instant for me, even with "Quick Folder Move" installed.

In Comment 18 I learned that it's related to memory usage. If most of it is open in memory then it's instant. Do you have any modified config options?

Flags: needinfo?(vseerror)

Please run the performance profiler:

  1. install profiler add-on into thunderbird - download the file from https://github.com/firefox-devtools/Gecko-Profiler-Addon/blob/master/gecko_profiler.xpi?raw=true and in Tools > add-ons click the gear to install add-on from file

  2. Follow instructions at https://profiler.firefox.com/ (videos BASED ON FIREFOX at https://profiler.firefox.com/docs/#/./videos-intro )

  3. Create a profiler URL and post it here.

You must be using Thunderbird beta from https://www.thunderbird.net/en-US/channel/ or current nightly build from https://archive.mozilla.org/pub/thunderbird/nightly/latest-comm-central/

Flags: needinfo?(helmo)

Sad that the thunderbird-next PPA is no longer up to date.

I downloaded thunderbird-69.0b1.tar.bz2 and started it...

The 'New' button in the Message Filters dialog seems quick in my first few tries ... and opening the 'Copy To' context also opens directly ... only when opening the 'Recent' sub menu I see (?a shorter then before?) slowdown.
Good to see the result of #809066 being solved, thanks :aceman

Then it still takes almost 6 seconds to open the 'Recent' sub menu. All of which was spent in the addIfRecent function. Posted as https://perfht.ml/33bwcX6
Opening the same 'Recent' sub menu again a bit later is quick.
I did notice that when I open Recent via the 'Move To' menu it again takes these 6 seconds to load ... apparently that data is now shared??

Unfortunately as most add-ons are disabled because they're 'not compatible', testing the impact of/on the 'Quick Folder Move' add-on is not available for now.
Is there an easy way to override that without unzipping and adjusting the meta data?

PS: I had a bit of a hard time initially to find the profiller after installing the xpi.
I had to open View -> Toolbars -> Customize to add it to a toolbar. There it's double the height of the other icons, thus stretching the toolbar in height.

I hope this version makes it to (Ubuntu)stable soon :)

Flags: needinfo?(helmo)

TB 69 will be released as beta only. Next stable release: TB 68 ESR planned for later this month. It should behave the same.

See Also: → 1519375

Thanks for the profiler output.
If all the time is used in addIfRecent(), I tried to change the algorithm there.
You can download and test build (of TB71) from there: https://queue.taskcluster.net/v1/task/J3FLB0WFSZeKFQD5yAOqBQ/runs/0/artifacts/public/build/target.tar.bz2
There is even output in the Error console of how long it took to build the Recent list.

But beware of the downgrading problem after you are done:
https://support.mozilla.org/en-US/kb/unable-launch-older-version-profile

You may want to test it on a copy of your profile.

Thanks ... I just tried that build.

Move to -> Recent: "Built recent list in:23895ms"

After this memory usage had fallen again in just a few minutes to ~ 1.5GB, peak was at 3.5gb+ when recent list was just finished.

Copy to -> Recent : "Built recent list in:20610ms"

Tools -> Message Filters -> New -> Choose folder -> Recent

Built recent list in:14604ms
When I close the message filters window, and directly open it again

Built recent list in:12ms

Apparently this is not cached in the same way, and just quick because most data is still in memory.

30 minutes later, opening message filters again... "Built recent list in:6596ms" (Memory usage was at ~3gb, so most was in memory)

Even after memory usage has fallen again the recent folder list for moveto/copyto opens quickly. So :)
It would still be nice if those caches could be combined into one though.

Thanks, so you say this experiment wasn't any improvement, it was actually worse, taking 23 seconds (compared to 6s in your comment 26) and taking 2GB of RAM temporarily. That is quite excessive if you only have 400 folders.

I'm afraid this workstation is far from a clean lab setting, but agree that it does not look good.
Do you have a link for me to the code changes?

The change of algorithm is here:
https://hg.mozilla.org/try-comm-central/rev/8fb9eedbfc193409f6ba9afe087ad13ca1f3a132

Instead of maintaining (often sorting the array and popping items) of the 15 most recent folders inside the function, I tried to just list all folders, sort by the recency and return the top 15.

Summary: Delay in opening Filter Rules dialog → New and Edit have long delay in opening Filter Rules dialog
Whiteboard: [filtermgmt]

So the path forward is bug 1519375 and we should close this one? Or make this dependent?

Flags: needinfo?(helmo)
Flags: needinfo?(acelists)

They are different approaches to the problem.
I would prefer to just fix the algorithm if it can be made fast, instead of maintaining some new folder cache.

Flags: needinfo?(acelists)

Strictly looking at the title of this bug I'd say to continue with just bug 1519375.

The filter rules dialog was just a manifestation of the slow access to the recent folder list. And now that the recent list is moved to a lazy loaded sub menu it no longer affects this dialog.

If :aceman still sees an opportunity to optimize then we can either rename this or create a new bug with a title like 'Optimize code to generate recent folder list'.
But unless you can remove the need to load all folder data files from disk into memory I see only limited benefit in that. Having this list instantly available is very important when you use it for moving messages. I often use the quick-folder-move add-on which shows an autocomplete list of folders to move a message to(it prioritized recently used folders) (Development version on github

Flags: needinfo?(helmo)
Status: UNCONFIRMED → NEW
Ever confirmed: true
See Also: → 1588155
Severity: normal → S3

Herman, do you still see this performance issue?

(I use filters a lot and never see this)

Flags: needinfo?(helmo)
You need to log in before you can comment on or make changes to this bug.