High Memory and High CPU usage of Firefox.exe and plugin-container.exe / firefox and browser after opening about:newtab

RESOLVED WORKSFORME

Status

()

defect
--
major
RESOLVED WORKSFORME
6 years ago
2 months ago

People

(Reporter: alice0775, Unassigned)

Tracking

({memory-footprint, perf})

28 Branch
x86_64
All
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(3 attachments)

Build Identifier:
http://hg.mozilla.org/mozilla-central/rev/abe6790a5dd8
Mozilla/5.0 (Windows NT 5.1; rv:28.0) Gecko/20100101 Firefox/28.0 ID:20131101030205

During such high CPU utilization, UI and Contents become choppy.

Steps To Reproduce:
0. Start Firefox with newly created plofile (Flash Player was installed 11.9.900.117)
1. Open several(10-15) youtube Flash video page in new Tab
   Ex. URL
   http://www.youtube.com/watch?v=nh7YyoDD138
   http://www.youtube.com/watch?v=F9z7MvF8ox4
   http://www.youtube.com/watch?v=MJHgMD1S0bg
   http://www.youtube.com/watch?v=EXDYIvFF_GY
   http://www.youtube.com/watch?v=1tefuif9fMM
   http://www.youtube.com/watch?v=W3RtyiFDlqE
   http://www.youtube.com/watch?v=jVrkGaZwF-8
   http://www.youtube.com/watch?v=-jhEm2Pw4mE
   http://www.youtube.com/watch?v=55s3T7VRQSc
   http://www.youtube.com/watch?v=dQw4w9WgXcQ
2. Close all tabs after tabs icon are spinning green
3. Restart Browser
   --- now about:home is only tab
4. Wait for a while (5sec and more)
   --- observe Memory and CPU usage of plugin-container.exe

Actual Results:
High Memory and High CPU usage of plugin-container.exe

Expected Results:
plugin-container.exe should not run (because, there is about:home tab only)
Memory and CPU usage should be less 


This does not happen if browser.newtabpage.enabled = false
I think background thumbnail capturing causes this problem.
OS: Windows 7 → Windows XP
In Windows7
Steps seems to be slightly different.

4. Click NewTab Button [+]
   --- observe Memory and CPU usage of plugin-container.exe
Summary: High Memory and High CPU usage of plugin-container.exe when start up Firefox → High Memory and High CPU usage of plugin-container.exe after 5sec of start up Firefox
OS: Windows XP → All
Summary: High Memory and High CPU usage of plugin-container.exe after 5sec of start up Firefox → High Memory and High CPU usage of Firefox.exe and plugin-container.exe / firefox and browser after 5sec of start up Firefox or open newTab
This also happens on Linux 
http://hg.mozilla.org/mozilla-central/rev/47c8e9b16918
Mozilla/5.0 (X11; Linux i686; rv:28.0) Gecko/20100101 Firefox/28.0 ID:20131103030204

Steps To Reproduce:
0. Start Firefox with newly created plofile (Flash Player was installed 11.9.900.117)
1. Open several(10-15) youtube Flash video page in new Tab
   Ex. URL
   http://www.youtube.com/watch?v=nh7YyoDD138
   http://www.youtube.com/watch?v=F9z7MvF8ox4
   http://www.youtube.com/watch?v=MJHgMD1S0bg
   http://www.youtube.com/watch?v=EXDYIvFF_GY
   http://www.youtube.com/watch?v=1tefuif9fMM
   http://www.youtube.com/watch?v=W3RtyiFDlqE
   http://www.youtube.com/watch?v=jVrkGaZwF-8
   http://www.youtube.com/watch?v=-jhEm2Pw4mE
   http://www.youtube.com/watch?v=55s3T7VRQSc
   http://www.youtube.com/watch?v=dQw4w9WgXcQ
2. Close all tabs after tabs icon are spinning green
3. Restart Browser
   --- now about:home is only tab
4. Click newTab button
   --- observe Memory and CPU usage of firefox and browser
Attachment #826473 - Attachment description: task manager → task manager on windows xp
Severity: normal → major
Increased CPU and memory usage are expected while the background thumbnail service captures all your missing thumbnails.  But that should only last as long as it takes to capture those thumbnails.

Are you seeing sustained high usage even after all your thumbnails load?  If so, that's a problem.  If not, I'm not sure this is really a bug, unless we want to use this to either fundamentally revisit how we're using the background thumbnail service or to improve resource usage when loading (off-screen) pages in Firefox in general.  If we accept that the background thumbnail service loads pages, then I don't think there's much more we can do to improve its resource usage in particular without improving it for all page loads in Firefox.

Bug 910036 landed recently, which means that this should only happen when about:newtab is open, so I'll change the summary slightly.

Plug-ins aren't involved here since the background thumbnail browser disables them, and plugin-container happens to be the process where content loads also, so moving to Toolkit.
Component: Plug-ins → General
Product: Core → Toolkit
Summary: High Memory and High CPU usage of Firefox.exe and plugin-container.exe / firefox and browser after 5sec of start up Firefox or open newTab → High Memory and High CPU usage of Firefox.exe and plugin-container.exe / firefox and browser after opening about:newtab
(In reply to Drew Willcoxon :adw from comment #3)

> Are you seeing sustained high usage even after all your thumbnails load?  If
> so, that's a problem. 

CPU usage become low after completion thumbnails
However, the high CPU usage continues for about 2-3 min. And it affected UI/content responses.
It is annoyance.

> Plug-ins aren't involved here since the background thumbnail browser disables them, and 
> plugin-container happens to be the process where content loads also, so moving to Toolkit.

I do not understand why plugin-container get high CPU utilization while capturing thumbnails.
The background thumbnail service loads pages out-of-process, and OOP content is loaded in the plugin-container process.  So "plugin-container" is kind of an unfortunate name.
Alice, does the choppiness happen only on 28?  Background thumbnails have been used on Nightly and Aurora starting on 25.

Does the choppiness happen only on Windows XP?

If you remove all your cached thumbnails and then try to reproduce, is it always reproducable?  Only some of the time?

Is Firefox or your computer doing anything else when the choppiness occurs?

Does the choppiness happen when your system is low on memory?  I'm wondering if your system's thrashing.

Could you please use the profiler to profile the main process when the choppiness occurs?  Described here under "Running the profiler": https://developer.mozilla.org/en-US/docs/Performance/Profiling_with_the_Built-in_Profiler
Flags: needinfo?(alice0775)
Posted file Profile 1.zip
Flags: needinfo?(alice0775)
(In reply to Drew Willcoxon :adw from comment #6)
> Alice, does the choppiness happen only on 28?  Background thumbnails have
> been used on Nightly and Aurora starting on 25.

The problem does not happen in Firefox25, Firefox26.0b2.
The problem happens Aurora26.0a2 and Nightly27.0a1.

> 
> Does the choppiness happen only on Windows XP?

It seems only on Windows XP.
It does not happen on Windows 7.

> 
> If you remove all your cached thumbnails and then try to reproduce, is it
> always reproducable?  Only some of the time?

The problem happens with the following cases.

STR 1
1  Follow STR step 0-4 in comment #0
2. Clrear Resent History - Everything 
3. Restart Browser
4. Follow STR step 1-4 in comment #2

STR2
1  Follow STR step 0-4 in comment #0
2. Restart Browser as soon as CPU utilization has begun to increase
4. Click newTab button


> 
> Is Firefox or your computer doing anything else when the choppiness occurs?

I ran Firefox and Task manager.

> 
> Does the choppiness happen when your system is low on memory?  I'm wondering
> if your system's thrashing.
> 

Free memory is about 50% available.
I do not think that the thrashing happens.

> Could you please use the profiler to profile the main process when the
> choppiness occurs?  Described here under "Running the profiler":
> https://developer.mozilla.org/en-US/docs/Performance/
> Profiling_with_the_Built-in_Profiler

See comment#7
Thanks, but that file won't load in what is apparently the profiler UI, so I can't easily examine it.  How did you produce it?  If I create my own profile json and compare it to yours, they have slightly different schemas, and I can load mine without a problem.  The profiler documentation is poor, so maybe we're both doing something wrong.
(In reply to Drew Willcoxon :adw from comment #9)
> Thanks, but that file won't load in what is apparently the profiler UI, so I
> can't easily examine it.  How did you produce it?  If I create my own
> profile json and compare it to yours, they have slightly different schemas,
> and I can load mine without a problem.  The profiler documentation is poor,
> so maybe we're both doing something wrong.

I did not install "Gecko Profiler" add-on.
I use built-in profiler.

Restart Browser
Shift+F5
Click "Start profiling" button at the left
Wait for a while
Click "Start profiling" button
Click "Save" link to create json file
I see, you used the JS profiler.  I'm looking at your profile, but nothing seems out of the ordinary.  Could you please generate a native profile as described on the page I linked?
I do not understand how to use it at all.
Anyway, I attach a link
http://people.mozilla.org/~bgirard/cleopatra/#report=b1ab41bfe71a217a181a588ee9df08e60c03ab63
I don't blame you, it's confusing.  Thanks for doing it.

I'm not sure what to make of it.  In your 12-second profile, 838 ms is reported as "jank," meaning that samples with > 50 ms responsiveness accounted for 838 ms of the profile.  838 ms is noticeable, but it's only 7% of 12000 ms.  Do you feel like you experienced in total only < 1 second of unresponsiveness while you were making the profile?

74% of that jank is due to KiFastSystemCallRet in ntdll.  The rest is spread out across many other sites.  A bunch of stacks end up in KiFastSystemCallRet, though, so there's no smoking gun.

There are a couple dozen main thread I/O syscalls, but they look like a small part of the jank.

One strange thing I don't understand is that BaseProcessStart is in the middle of some stacks, which looks like it starts up a new process, eventually leading to XRE_main.
Oh, bug 900524 explains why these stacks look weird.  Alice, would you be willing to install the Debugging Tools for Windows as bug 900524 comment 6 mentions?  You just need one updated DLL that the Tools include.

Something else you can try is going to about:telemetry and looking under Browser Hangs.  I think this only reports >= 5 second hangs, though.
Installed Debugging Tools for Windows from Windows SDK .

http://people.mozilla.org/~bgirard/cleopatra/#report=f7873b1b8b9d9a30f5701bb5b12a7b9e8bbb18ef


about:telemetry:


Browser Hangs
Click to collapse section
Show raw data from hangs

Hang Report #1 (12 seconds)
_VEC_memcpy (in msvcr100.i386.pdb)
huge_ralloc (in mozglue.pdb)
je_realloc (in mozglue.pdb)
js::StringBuffer::finishString() (in mozjs.pdb)
json_stringify(JSContext *,unsigned int,JS::Value *) (in mozjs.pdb)
-0x1
-0x1
-0x1
-0x1
-0x1
EnterBaseline (in mozjs.pdb)
js::Invoke(JSContext *,JS::CallArgs,js::MaybeConstruct) (in mozjs.pdb)
js::CallOrConstructBoundFunction(JSContext *,unsigned int,JS::Value *) (in mozjs.pdb)
js::Invoke(JSContext *,JS::CallArgs,js::MaybeConstruct) (in mozjs.pdb)
js::Invoke(JSContext *,JS::Value const &,JS::Value const &,unsigned int,JS::Value *,JS::MutableHandle<JS::Value>) (in mozjs.pdb)
JS_CallFunctionValue(JSContext *,JSObject *,JS::Value,unsigned int,JS::Value *,JS::Value *) (in mozjs.pdb)
nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS *,unsigned short,XPTMethodDescriptor const *,nsXPTCMiniVariant *) (in xul.pdb)
nsXPCWrappedJS::CallMethod(unsigned short,XPTMethodDescriptor const *,nsXPTCMiniVariant *) (in xul.pdb)
PrepareAndDispatch (in xul.pdb)
SharedStub (in xul.pdb)
nsRefreshDriver::Tick(__int64,mozilla::TimeStamp) (in xul.pdb)
mozilla::RefreshDriverTimer::Tick() (in xul.pdb)
nsTimerImpl::Fire() (in xul.pdb)
nsThread::ProcessNextEvent(bool,bool *) (in xul.pdb)
NS_ProcessPendingEvents(nsIThread *,unsigned int) (in xul.pdb)
nsBaseAppShell::NativeEventCallback() (in xul.pdb)
nsAppShell::EventWindowProc(HWND__ *,unsigned int,unsigned int,long) (in xul.pdb)
InternalCallWinProc (in user32.pdb)
UserCallWinProcCheckWow (in user32.pdb)
DispatchClientMessage (in user32.pdb)
__fnDWORD (in user32.pdb)
KiUserCallbackDispatcher (in ntdll.pdb)
RealDefWindowProcW (in user32.pdb)
DoMsgDefault(_THEME_MSG const *) (in uxtheme.pdb)
OnDwpSysCommand(CThemeWnd *,_THEME_MSG *) (in uxtheme.pdb)
_ThemeDefWindowProc(HWND__ *,unsigned int,unsigned int,long,int) (in uxtheme.pdb)
ThemeDefWindowProcW (in uxtheme.pdb)
GetPropW (in user32.pdb)
InternalCallWinProc (in user32.pdb)
UserCallWinProcCheckWow (in user32.pdb)
CallWindowProcAorW (in user32.pdb)
CallWindowProcW (in user32.pdb)
nsWindow::WindowProcInternal(HWND__ *,unsigned int,unsigned int,long) (in xul.pdb)
CallWindowProcCrashProtected (in xul.pdb)
nsWindow::WindowProc(HWND__ *,unsigned int,unsigned int,long) (in xul.pdb)
InternalCallWinProc (in user32.pdb)
__fnINOUTLPSCROLLINFO (in user32.pdb)
DispatchClientMessage (in user32.pdb)
__fnDWORD (in user32.pdb)
KiUserCallbackDispatcher (in ntdll.pdb)
RealDefWindowProcW (in user32.pdb)
DoMsgDefault(_THEME_MSG const *) (in uxtheme.pdb)
OnDwpNcLButtonDown(CThemeWnd *,_THEME_MSG *) (in uxtheme.pdb)
_ThemeDefWindowProc(HWND__ *,unsigned int,unsigned int,long,int) (in uxtheme.pdb)
ThemeDefWindowProcW (in uxtheme.pdb)
GetPropW (in user32.pdb)
InternalCallWinProc (in user32.pdb)
UserCallWinProcCheckWow (in user32.pdb)
CallWindowProcAorW (in user32.pdb)
CallWindowProcW (in user32.pdb)
nsWindow::WindowProcInternal(HWND__ *,unsigned int,unsigned int,long) (in xul.pdb)
CallWindowProcCrashProtected (in xul.pdb)
nsWindow::WindowProc(HWND__ *,unsigned int,unsigned int,long) (in xul.pdb)
InternalCallWinProc (in user32.pdb)
UserCallWinProcCheckWow (in user32.pdb)
DispatchMessageWorker (in user32.pdb)
DispatchMessageW (in user32.pdb)
nsAppShell::ProcessNextNativeEvent(bool) (in xul.pdb)
nsBaseAppShell::OnProcessNextEvent(nsIThreadInternal *,bool,unsigned int) (in xul.pdb)
nsThread::ProcessNextEvent(bool,bool *) (in xul.pdb)
NS_ProcessNextEvent(nsIThread *,bool) (in xul.pdb)
mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate *) (in xul.pdb)
MessageLoop::RunHandler() (in xul.pdb)
MessageLoop::Run() (in xul.pdb)
nsBaseAppShell::Run() (in xul.pdb)
nsAppShell::Run() (in xul.pdb)
nsAppStartup::Run() (in xul.pdb)
XREMain::XRE_mainRun() (in xul.pdb)
XREMain::XRE_main(int,char * * const,nsXREAppData const *) (in xul.pdb)
XRE_main (in xul.pdb)
do_main (in firefox.pdb)
NS_internal_main(int,char * *) (in firefox.pdb)
wmain (in firefox.pdb)
__tmainCRTStartup (in firefox.pdb)
BaseProcessStart (in kernel32.pdb)

Hang Report #2 (13 seconds)
js::ObjectImpl::getDenseInitializedLength() (in mozjs.pdb)
js::GCMarker::drainMarkStack(js::SliceBudget &) (in mozjs.pdb)
GCCycle (in mozjs.pdb)
Collect (in mozjs.pdb)
js::GCSlice(JSRuntime *,js::JSGCInvocationKind,JS::gcreason::Reason,__int64) (in mozjs.pdb)
js_InvokeOperationCallback(JSContext *) (in mozjs.pdb)
js::jit::InterruptCheck(JSContext *) (in mozjs.pdb)
js::jit::CheckOverRecursed(JSContext *) (in mozjs.pdb)
-0x1
-0x1
-0x1
-0x1
-0x1
EnterBaseline (in mozjs.pdb)
js::Invoke(JSContext *,JS::CallArgs,js::MaybeConstruct) (in mozjs.pdb)
js::CallOrConstructBoundFunction(JSContext *,unsigned int,JS::Value *) (in mozjs.pdb)
js::Invoke(JSContext *,JS::CallArgs,js::MaybeConstruct) (in mozjs.pdb)
js::Invoke(JSContext *,JS::Value const &,JS::Value const &,unsigned int,JS::Value *,JS::MutableHandle<JS::Value>) (in mozjs.pdb)
JS_CallFunctionValue(JSContext *,JSObject *,JS::Value,unsigned int,JS::Value *,JS::Value *) (in mozjs.pdb)
nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS *,unsigned short,XPTMethodDescriptor const *,nsXPTCMiniVariant *) (in xul.pdb)
nsXPCWrappedJS::CallMethod(unsigned short,XPTMethodDescriptor const *,nsXPTCMiniVariant *) (in xul.pdb)
PrepareAndDispatch (in xul.pdb)
SharedStub (in xul.pdb)
nsRefreshDriver::Tick(__int64,mozilla::TimeStamp) (in xul.pdb)
mozilla::RefreshDriverTimer::Tick() (in xul.pdb)
nsTimerImpl::Fire() (in xul.pdb)
nsThread::ProcessNextEvent(bool,bool *) (in xul.pdb)
NS_ProcessNextEvent(nsIThread *,bool) (in xul.pdb)
mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate *) (in xul.pdb)
MessageLoop::RunHandler() (in xul.pdb)
MessageLoop::Run() (in xul.pdb)
nsBaseAppShell::Run() (in xul.pdb)
nsAppShell::Run() (in xul.pdb)
nsAppStartup::Run() (in xul.pdb)
XREMain::XRE_mainRun() (in xul.pdb)
XREMain::XRE_main(int,char * * const,nsXREAppData const *) (in xul.pdb)
XRE_main (in xul.pdb)
do_main (in firefox.pdb)
NS_internal_main(int,char * *) (in firefox.pdb)
wmain (in firefox.pdb)
__tmainCRTStartup (in firefox.pdb)
BaseProcessStart (in kernel32.pdb)
Thanks, that profile looks much better.  Again, though, only 332 ms of 29275 ms (1%) is reported as "jank."  Does that match your experience?  68% of that is nsPluginHost loading and writing plug-in info, which was triggered by HttpDataUsage.js doing something on the idle timer.  Other things include layout reflows, acquiring locks, and side effects of the profiler.

As for the about:telemetry reports, I wonder if Hang Report #1 is the Gecko profiler add-on JSON.stringify'ing the profile data.  Hang Report #2 looks like a GC, maybe GC'ing the apparently giant string in the first hang report. :-\

As for the profile as a whole, jank and non-jank, 99.7% is spent in nsThread::ProcessNextEvent.  Of that roughly, 66% is in system calls waiting for messages and related overhead; 27% is in handling IPC messages (I presume mozilla::ipc means they're IPC), and most of that is in _VEC_memcpy and memcpy.  But none of that really shows up as "jank."  Maybe the profiler isn't accurately reporting it, or it's happening in a way that the profiler doesn't call out.  Maybe memcpy on Windows XP is really slow.  (_VEC_memcpy is the top-level frame in Hang Report #1.)  I wonder how much e10s/IPC testing we've done on Windows XP.  Probably not a lot.

If you set the browser.pagethumbnails.capturing_disabled pref to true, can you reproduce?
Because there is not a problem once after having captured a thumbnail, I think this is not a big problem. 

I cannot reproduce anymore when setting browser.pagethumbnails.capturing_disabled = true.
If still no longer reproducible, then can this issue be closed?

yes, no longer reproduce the issue with the STR comment0, comment1 and comment8 on Firefox67 as well as Nightly69.0a1.

Status: NEW → RESOLVED
Closed: 2 months ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.