Alice0775 White Reporter
	Description • 11 years ago

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.

	Alice0775 White Reporter
	Comment 1 • 11 years ago

In Windows7
Steps seems to be slightly different.

4. Click NewTab Button [+]
   --- observe Memory and CPU usage of plugin-container.exe

	Alice0775 White Reporter
	Comment 2 • 11 years ago

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

	Drew Willcoxon :adw
	Comment 3 • 11 years ago

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.

	Alice0775 White Reporter
	Comment 4 • 11 years ago

(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.

	Drew Willcoxon :adw
	Comment 5 • 11 years ago

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.

	Drew Willcoxon :adw
	Comment 6 • 11 years ago

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

	Alice0775 White Reporter
	Comment 8 • 11 years ago

(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

	Drew Willcoxon :adw
	Comment 9 • 11 years ago

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.

	Alice0775 White Reporter
	Comment 10 • 11 years ago

(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

	Drew Willcoxon :adw
	Comment 11 • 11 years ago

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?

	Alice0775 White Reporter
	Comment 12 • 11 years ago

I do not understand how to use it at all.
Anyway, I attach a link
http://people.mozilla.org/~bgirard/cleopatra/#report=b1ab41bfe71a217a181a588ee9df08e60c03ab63

	Drew Willcoxon :adw
	Comment 13 • 11 years ago

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.

	Drew Willcoxon :adw
	Comment 14 • 11 years ago

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.

	Alice0775 White Reporter
	Comment 15 • 11 years ago

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)

	Drew Willcoxon :adw
	Comment 16 • 11 years ago

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?

	Alice0775 White Reporter
	Comment 17 • 11 years ago

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.

	Graham Perrin
	Comment 18 • 7 years ago

If still no longer reproducible, then can this issue be closed?