Closed Bug 579653 Opened 15 years ago Closed 14 years ago

extreme performance degradation (lack of responsiveness, temp-freezes) of firefox with long app uptime usage; time spent in cycle collector

Categories

(Core :: XPCOM, defect)

Product:
Core
Component:
XPCOM
Platform:
x86
All
Type:
defect
Priority:
Not set
Severity:
major

Tracking

()

Status:
RESOLVED INCOMPLETE
Tracking Flags:
Tracking Status
blocking2.0 --- -

People

(Reporter: abittner, Unassigned)

Details

(Keywords: perf, Whiteboard: [closeme 2011-10-22] )

Attachments

(1 file)

firefox.exe process spikes in load after 3.5days of process uptime
57.99 KB, image/png
Details
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:2.0b1) Gecko/20100630 Firefox/4.0b1 ( .NET CLR 3.5.30729; .NET4.0E) Build Identifier: Build identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:2.0b1) Gecko/20100630 Firefox/4.0b1 ( .NET CLR 3.5.30729; .NET4.0E) ever since maybe firefox 3.x or even 2.x i have developed a rather extensive usage of firefox. i have like 10-15 real firefox main windows open, every window with at least like say 4-20 tabs. normally i have these tabs reopen after a firefox restart (save upon close/quit), reload/restore when firefox starts. so far so good. situation: firefox starts initially with restoring all my tabs and windows. everything is seemingly fine. after starting to use it, it develops awful pauses where the whole gui isnt reacting. the longer firfox is running (app uptime), the more severe this phenomenon gets. it just works some stuff internally, until i can continue with just anything that i was doing presently inside the firefox windows. whether it was typing a text in this bugreport textbox here, or scrolling a firefox content window, or navigating the firefox app menus, or navigating the firefox html/web content, javascript actions, filedownload or anything. i am getting 100% cpu/core spikes of the firefox app during these soft-freeze events, the whole gui goes unresponsive basically, but for example continuing to type here in this textbox for example somewhere buffers (maybe its the operating system level though) my keystrokes and after unfreeze of the gui the text appears quickly then and i can use firefox normally again for a while. but the longer i use firefox the more unusable it gets. interestingly using the app means just anything with even the slightest operations inside the app, so typing this text triggers this cycle of small 100%-loads and freezes and unfreezing/normalusagepossible times again. when i leave firefox just minimized or even displaying the actual content but dont do, klick or type anything it doesnt really produce these spikes. i have read through some performance profiling webpages at the mozilladevelopers site, and tried to narrow down the problem to some areas with the help of various sysinternals/msft tools (windows platform that is). so bascially i have figured also with the help of processexplorer http://technet.microsoft.com/en-us/sysinternals/bb896653.aspx and with the help of the amd codeanalyst profiling tool https://developer.mozilla.org/Profiling_with_AMD_CodeAnalyst that its some weirdness with most likely xul.dll and there probably especially GraphWalker<scanVisitor>::DoWalk functions or related stuff. when i leave firefox alone for a little while these spikes calm down after a while and no more process load spikes are being created. but as soon as i just click some part of the firefox gui areas or just switch back to any part of firefox or type scroll or click just a little anything anywhere inside the firefox app it starts all over again with "spiking". so sometimes its real bad after like a few hours of firefox usage already, especially when opening and closing additional tabs, new windows and i somehow have a feeling especially with javascript based contents. when i surf and visit lots of that kind of sites, or with interactive content its easier to repro this situation more quickly. dont get me wrong: when i quit/close down firefox from its present state with all my currently opened tabs windows and whatnot, and reopen it and it restores all these tabs and windows again, its immediately reactive and everything (same actions as those that caused the spikes previously i described above) is working just fine. until again a few hours or after a few days of runtime of firefox its starting all over again. and the longer i keep using firefox in that state the worse it gets. so maybe its a kind of architectural or real deep problem, and maybe its not even (just?) xul.dll or a combination of many things. i am not a real professional in terms of development or all your mozilla parts libraries and subsystems and what not, but i am thinking about memory corruption or fragmentation, or some memory leaks or stuff like that. i have created several logs/runs with that amd codeanalyst app. profiling the whole winxp system directly immediately after firefox startup (when it calmed down after having restored all the windows tabs and loaded all their contents). cpu usage is almost nul for firefox then. no funny things. everything fine. also dont get me wrong: the windowsxp system is fine. no other app show these behaviour, and this problem also happens since many years now also on other systems i use heavily with firefox (other windows xp boxes, other hardware, other drivers). so its not a specific release of firefox that has introduced this behaviour, and nothing to do with windows itself, operating systems or hardware. its the mere uptime and heave usage of the firefox app itself. and i highly doubt that i am the only heavy firefox user, but still i wonder that i couldnt find any meaningful bugreports about performance degradation within firefox describing my situation. over the years i think when firefox made the step from the 3.0.x line to 3.5.x line i think i remembered a time when this problem was less severe at the systems i used back then, maybe i had fewer windows (with fewer tabs in those windows) open during the firefox 2.x and 3.0.x times, and then when it initially improved a bit with 3.5 i increased my windows and tabs volume accordingly, so that i ended up having the same or similar problem with firefox 3.5, 3.6 and now with 4.0/beta1 as i max out the capability of these versions as well it seems. maybe this bugreport or issue will take quite some time to hunt down and to be able to come up with some enhancements. additionally i also came across some of the javascript and crt dlls of mozilla and some load excess in those dlls as well, but i have too little experience in this to be able to tell which area would be the most promising to start with. hope that somebody could give me a hand with this bug and ask some bright questions so that i can provide some possible answers and we can close in on the problem. will attach some processexplorer screenshot of the process-load spikes as well as some amd-codeanalyst data if i can. i have taken amd-codeanalyst samples after initial start of firefox loaded with tabs/windows, and every hour now and then during runtime of firefox, and now rather towards the end of my firefox runtime-cycle where its already quite annoying and slightly unbearable to wait every 20-30seconds for the gui suddenly freeze, wait 5-10secs before being able to continue using the firefox app again..... thanks for listening. best regards. Reproducible: Always
firefox.exe process started 3,4days ago constantly running, and having developed these spikes in 100% cpu (core / thread load) whenever i am using it. spikes are like half a minute apart and last like 5-8seconds or so. really annoying.
firefox.exe thread summaries: initially after firefox.exe starts and created its windows and filled tabs: most timersamples used by dll/modules via firefox.exe: firefox.exe fresh (barely any uptime) samples: Process Name 64-bit Timer samples xul.dll 39.47 mozjs.dll 26.42 MOZCRT19.dll 10.13 ntkrnlpa.exe 5.18 ntdll.dll 4.47 hal.dll 4.2 nspr4.dll 3.15 win32k.sys 2.7 kernel32.dll 1.28 ---- xul.dll: most samples from functions used: CS:EIP Symbol + Offset 64-bit Timer samples 0x100e6e70 XPC_WN_GetterSetter 3.8 0x100f9c30 nsIFrame::InvalidateInternal 2.66 0x102f9c70 pixman_fill_sse2 2.66 0x100f9980 nsBlockFrame::InvalidateInternal 2.57 0x100fd9f0 XPCConvert::NativeInterface2JSObject 2.09 0x1069dd39 imgContainer::DrawFrameTo 2.09 0x100f6810 nsCOMPtr_base::assign_from_qi 1.71 7 functions, 95 instructions, Total: 185 samples, 17.59% of samples in the module, 0.46% of total session samples ----------------- mozjs.dll most samples from functions used: CS:EIP Symbol + Offset 64-bit Timer samples 0x561270 js::PurgeScriptFragments 13.78 0x561170 js_DestroyScript 12.5 0x526db0 js_Interpret 11.36 0x54ea60 js_NewScriptFromCG 4.55 0x5265d0 js_GetPropertyHelper 4.4 0x525ec0 js_Invoke 3.69 6 functions, 150 instructions, Total: 354 samples, 50.28% of samples in the module, 0.89% of total session samples ------------ mozcrt19.dll samples: --- CS:EIP Symbol + Offset 64-bit Timer samples 0x781348c0 _realloc_crt 27.78 0x78137d00 expand 24.44 0x78147b50 strncmp 17.78 0x781399e0 malloc 5.93 0x781475c0 memcpy 5.56 0x78139660 free 4.44 0x78150200 memmove 3.7 7 functions, 105 instructions, Total: 242 samples, 89.63% of samples in the module, 0.61% of total session samples ------------------------------- firefox.exe middle-aged (uptime): most samples from dll/modules used: Process Name 64-bit Timer samples xul.dll 41.81 mozjs.dll 33.07 MOZCRT19.dll 8.34 ------- xul.dll samples: --- CS:EIP Symbol + Offset 64-bit Timer samples 0x101cfbe0 GraphWalker<scanVisitor>::DoWalk 9.78 0x100f4b40 SearchTable 5.95 0x1031f794 nsCycleCollectingAutoRefCnt::get 2.97 0x100f4c50 PL_DHashTableOperate 2.5 0x100f9c30 nsIFrame::InvalidateInternal 2.35 5 functions, 86 instructions, Total: 301 samples, 23.55% of samples in the module, 0.75% of total session samples ------- mozjs.dll samples: --- CS:EIP Symbol + Offset 64-bit Timer samples 0x561270 js::PurgeScriptFragments 12.96 0x561170 js_DestroyScript 9.69 0x526db0 js_Interpret 9.4 0x54e3e0 js_TraceObject 8.8 0x54e280 js_CallGCMarker 7.12 5 functions, 180 instructions, Total: 485 samples, 47.97% of samples in the module, 1.22% of total session samples ---------- firefox.exe older/aged (uptime, 3,5days) most samples in dll/modules: Process Name 64-bit Timer samples xul.dll 57.57 MOZCRT19.dll 24.22 mozjs.dll 13.73 -------- xul.dll samples: --- CS:EIP Symbol + Offset 64-bit Timer samples 0x101cfbe0 GraphWalker<scanVisitor>::DoWalk 38.4 0x101cfbe0 GraphWalker<scanVisitor>::DoWalk 20.28 0x1007e3b0 nsPrefBranch::RemoveObserver 9.63 0x100f4b40 SearchTable 5.64 0x1031f794 nsCycleCollectingAutoRefCnt::get 2.34 0x100e2740 nsGenericElement::cycleCollection::Traverse 2.13 6 functions, 142 instructions, Total: 2281 samples, 78.41% of samples in the module, 11.42% of total session samples -------- mozcrt19.dll samples: --- CS:EIP Symbol + Offset 64-bit Timer samples 0x78193cc0 strcmp 89.71 0x78150200 memmove 4.17 0x781348c0 _realloc_crt 1.96 0x78137d00 expand 1.63 4 functions, 44 instructions, Total: 1193 samples, 97.47% of samples in the module, 5.97% of total session samples ---------- mozjs.dll samples: --- CS:EIP Symbol + Offset 64-bit Timer samples 0x4ef8f0 fun_finalize 62.68 0x54e3e0 js_TraceObject 9.51 0x54e280 js_CallGCMarker 7.06 0x53a8c0 JS_DHashTableEnumerate 3.31 0x54e8a0 JS_TraceChildren 3.17 0x54e050 fun_trace 3.03 0x4e9480 js::SweepScopeProperties 2.45 0x54f460 FinalizeArenaList<JSObject,&FinalizeObject> 1.87 8 functions, 124 instructions, Total: 646 samples, 93.08% of samples in the module, 3.23% of total session samples ----------- firefox.exe oldest (uptime): dll/modules samples: Process Name 64-bit Timer samples xul.dll 75.13 MOZCRT19.dll 12.05 mozjs.dll 8.71 hal.dll 1.11 -------- xul.dll samples: --- CS:EIP Symbol + Offset 64-bit Timer samples 0x101cfbe0 GraphWalker<scanVisitor>::DoWalk 35.13 0x101cfbe0 GraphWalker<scanVisitor>::DoWalk 17.81 0x100f4b40 SearchTable 8.8 0x1007e3b0 nsPrefBranch::RemoveObserver 4.12 0x1031f794 nsCycleCollectingAutoRefCnt::get 2.76 0x100e2740 nsGenericElement::cycleCollection::Traverse 2.55 0x100f4c50 PL_DHashTableOperate 2.53 0x100a0f50 ChangeTable 2.28 0x100f5180 GCGraphBuilder::NoteXPCOMChild 2.08 0x101168c0 nsContentUtils::UnregisterPrefCallback 2.04 0x100dffc0 nsCycleCollector::MarkRoots 1.7 11 functions, 362 instructions, Total: 4528 samples, 81.79% of samples in the module, 22.64% of total session samples --------- mozcrt19.dll samples: --- CS:EIP Symbol + Offset 64-bit Timer samples 0x78193cc0 strcmp 76.58 0x78137d00 expand 5.07 0x78139660 free 4.95 0x781348c0 _realloc_crt 4.62 0x78147fa0 strnicmp 2.82 0x781475c0 memcpy 2.25 6 functions, 85 instructions, Total: 855 samples, 96.28% of samples in the module, 4.28% of total session samples ---------- mozjs.dll samples: --- CS:EIP Symbol + Offset 64-bit Timer samples 0x4ef8f0 fun_finalize 28.04 0x54e3e0 js_TraceObject 18.38 0x54e280 js_CallGCMarker 11.99 0x54e8a0 JS_TraceChildren 6.7 0x53a8c0 JS_DHashTableEnumerate 4.98 0x54e050 fun_trace 4.52 0x4e9480 js::SweepScopeProperties 3.89 0x54f460 FinalizeArenaList<JSObject,&FinalizeObject> 3.43 8 functions, 149 instructions, Total: 526 samples, 81.93% of samples in the module, 2.63% of total session samples ------------- summary: basically it seems as if the longer firefox.exe is running, the more workload inside the xul.dll is being used on: - GraphWalker <scanVisitor> :: DoWalk and - SearchTable routines and the longer firefox.exe is running more time is being consumed for mozjs.dll routines: - funfinalize - js_TraceObject - JS_TraceChildren - js_CallGCMarker i am not that sure about the mozjs.dll stuff overall, but the xul.dll stuff is really pretty heavy, as i even succeed manually seeing stack signatures whenever firefox.exe causes this 100% cpu spike loads and i manually check it then quickly via processexplorer tool, and navigate to the cpu-hogging thread-id and trigger the stack-trace window on that thread id, i often see loads of xul stuff in there. maybe this helps a bit. thanks and regards.
sorry for the stupid question but you have tested without addons ?
hmm not really, as i come across this behavior obviously after quite some firefox process uptime. so the easiest way for me to actually recognize this behavior was on my production machines. i could maybe recreate my tabs/windows on some testsetup without a great deal of addons, but i am wondering as i am experiencing this bug already for a long time over many versions of firefox. thats also the reason why i was asking if actually nobody noticed this behaviour with their style of firefox usage. doesnt anybody leave their machines running and their firefox started all the time for many days or weeks and use a lot of windows and tabs? right now i can only provide this information that i was posting, but maybe i can manage to do some long-term trials also without any addons.
abittner, thanks for the data! The GraphWalker stuff is definitely cycle collector. SearchTable and the mozjs.dll numbers are consistent with that. Without the mozjs.dll numbers I would have guessed that a big chunk of the object graph had leaked and we keep traversing it over and over... but the jseng part of this is finalizers. Are we actually ending up with a lot of garbage instead (or in addition to?) what looks like a likely leak? Over to xpcom, since xul.dll is really "the layout engine", not xul per se, and the cycle collector is definitely xpcom. We certainly have at least one existing report of cycle collector taking up more and more time as the process gets older, and in that case it even happened in safe mode. So while it might be good to get data here in safe mode too, chances are it'll show the same thing. I wonder whether we could hook up more stuff to about:memory to get a better idea of what sorts of objects are live.... not that this would tell us why they're live. :(
URL: doesnt matter; gui / main app (e.g. f...
Status: UNCONFIRMED → NEW
Component: XUL → XPCOM
Ever confirmed: true
QA Contact: xptoolkit.widgets → xpcom
Summary: extreme performance degradation (lack of responsiveness, temp-freezes) of firefox with long app uptime usage → extreme performance degradation (lack of responsiveness, temp-freezes) of firefox with long app uptime usage; time spent in cycle collector
blocking2.0: --- → ?
This is some great data.
I have seen this one in profiles before. Its purging the JIT cache for specific global scripts and is known to be expensive. If we have a ton of live scripts, that would explain why this becomes so long running. 0x561270 js::PurgeScriptFragments 12.96
Could this be the leak sayrer recently identified? (PrefObservers). Those did a long of string comparisons. 0x78193cc0 strcmp 76.58
This is regular GC stuff. Its a bit curious that funfinalize is so high up. It means we actually finalize a ton, not just mark it. This kinda goes hand in hand with the PurgeScriptFragments thing above. - fun_finalize - js_TraceObject - JS_TraceChildren - js_CallGCMarker As for fun_finalize, I have a hunch that this is the same bug dbaron and brendan have been chasing (we grow ourselves a huge property tree). fun_finalize does PropertyCache::purgeForScript, which can get expensive for very large property trees. Again, this is some really great data. Thanks a lot.
I filed bug 584619 on a probably-related PurgeScriptFragments issue.
as of recently inside the firefox4betas (currently using beta4, and used beta5 but had some other problems there), i see complete gui unresponsiveness from time to time. a process load sample during that time shows: inside firefox.exe: Process Name 64-bit Timer samples xul.dll 94.03 hal.dll 1.53 MOZCRT19.dll 1.29 ntkrnlpa.exe 1.19 win32k.sys 0.78 ntdll.dll 0.28 ati2dvag.dll 0.2 ------ inside xul.dll CS:EIP Symbol + Offset 64-bit Timer samples 0x104f0025 js::PropertyTree::emptyShapeChange 87.68 0x100e2180 JS_TraceChildren 2.24 0x100e1a40 js_TraceScript 0.68 0x100b1860 js::Interpret 0.66 0x10149200 write_string 0.32 5 functions, 99 instructions, Total: 4327 samples, 91.52% of samples in the module, 30.70% of total session samples ------------------ another measurement of firefox.exe during such a hang, with xul.dll at 72% inside firefox results in xul.dll details as follows: CS:EIP Symbol + Offset 64-bit Timer samples 0x104f0025 js::PropertyTree::emptyShapeChange 32.75 0x100e2180 JS_TraceChildren 10.15 0x100e1a40 js_TraceScript 2.88 0x101a5760 js::PurgeScriptFragments 2.79 0x100b1860 js::Interpret 1.89 0x101a5850 js_DestroyScript 1.75 6 functions, 162 instructions, Total: 1162 samples, 50.79% of samples in the module, 5.82% of total session samples -------------------------- apparently js::PropertyTree::emptyShapeChange seems to be consuming your cpu cycles during such events. regards.
That looks like bug 570435 (which is fixed on the TM branch, and should merge to MC any day now).
abittner, can you check recent mozilla-central nightlies to see whether this is less of a problem? Also, the GC compartments work will land soon and significantly change the nature of the problem. Not a blocker because this is not a regression from prior releases and seems to be somewhat uncommon, but I'd definitely like to see whether it persists or gets better.
blocking2.0: ? → -
well its a really hard thing to get the most current ffx4 beta7pre ones measured, maybe this specific bug is gone in some way, but i have hugeloads of problems as of the recent few days/weeks with the beta7pre ones. to sum it up: one day/nightly is pretty neat, reactive, low delay/latency, kinda okay, the next thing you know is that i get plenty of problems, mozalloc.dll crashes on hourly/minute basis (unfortunately these crashes never got handled by breakpad/crashreporter, leading to a question does mozilla make use of the operating system crashreporting on windows, aka windows error reporting/drwatson that comes ever since winxp, microsoft wanting code-signing activated on crashing parts (a problem for nightly builds, as far as i know mozilla doesnt sign everything/those regularly, wasting a lot of statistics that microsoft is collecting and generating especially these parts (i never came across mozalloc.dll crashes before the ffx4 beta7pre builds from some days ago, todays and yesterdays build didnt mozalloccrash on my just yet ;) ) anyways, where do i find a meta/bug for finding out how to make use of operatingsystem-supplied crashreporting, i have asked for the same in other bugreports as well but nobody came up with real information :( ) so mozalloc.dll bug is here: https://bugzilla.mozilla.org/show_bug.cgi?id=600481 as with todays b7pre build: Build identifier: Mozilla/5.0 (Windows NT 5.1; rv:2.0b7pre) Gecko/20101006 Firefox/4.0b7pre about:buildconfig Source Built from http://hg.mozilla.org/mozilla-central/rev/dee1e01fd8ed i am having the insane situation right now, that it seems to generate loads of hal.dll (winxp, core-load (red-curve in taskmanager/procexplorer) for firefox.exe process), somewhat similar to one of my other bugs as well: https://bugzilla.mozilla.org/show_bug.cgi?id=592321 so i am somewhat out of luck as the whole firefox4 as of recently is chaning in behaviour so many times and literally on a daily basis that its virtually impossible to track down all the potential conflicts and dependencies of these buggy behaviours. its also hard for be to find the appropriate bugreports from other people that might suffer from the same problems or more neutrally who might have discovered similar behaviour. which leads me to the question whether there is any kind of place where these generic (overall) performance issues could be discussed before being able to find out more exactly what part of firefox is affected and being able to file more helpful bugreports. maybe the most feasible solution would actually be to wait for the actual real beta releases which would be hopefully authenticode/digitalcertificate signed for the windows platform, and then at least being able to catch these mozalloc.dll crashes as well (?) at least on the drwatson/windowserrorreporting(wer) side but still not being helpful if mozilla isnt making use of the statistics gathered by msft that way and maybe not participating in the windowserrorreport facilities by microsoft. regards.
what is your list of addons?
OS: Windows XP → All
abittner? (In reply to Robert Sayre from comment #15) > what is your list of addons? (In reply to Benjamin Smedberg [:bsmedberg] from comment #13) > abittner, can you check recent mozilla-central nightlies ...
Severity: normal → major
Keywords: perf
Whiteboard: [closeme 2011-10-22]
I'm going to close this for now, as Firefox has changed a fair amount since this was filed. abittner, feel free to reopen or file a new bug if you are still having problems. Thanks again for the detailed information.
Status: NEW → RESOLVED
Closed: 14 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: