1359550 - High CPU Usage on some sites

Status: RESOLVED INCOMPLETE

(Firefox :: Untriaged, defect)

Description

[Paul Roland]

Attachment: ffperf.png

User Agent: Mozilla/5.0 (Windows NT 6.3; Win64; x64; rv:53.0) Gecko/20100101 Firefox/53.0
Build ID: 20170413192749

Steps to reproduce:

Navigate on example: http://www.ebay.ie/sch/Enterprise-Networking-Servers/175698/i.html?LH_Auction=1&_sop=10


Actual results:

I am using both Firefox 52.1.0esr now and Chrome, but I prefer Firefox
I have the exact same bookmarks, and doing an hourly browse on ebay auction in enterprise section. The one thing I notice is that on the same page Firefox uses alot of CPU (I can hear the cooler and it's getting hot air) while Chrome doesn't.
The ebay page is just an example, is far worse in facebook and some other sites, some heavy loaded some not.
I have no extensions or addons and flash is disabled (ask to activate)
I tried deleting the profile, settings from scratch, no avail



Expected results:

Use less resources

Comment 1

[Paul Roland]

Actually using 52.1.0esr, tried on 53 when submitting the "bug" thought maybe could help but I see the same behavior

Comment 2

[Emil Pasca [:emilpasca]]

User Agent: Mozilla/5.0 (Windows NT 6.3; Win64; x64; rv:53.0) Gecko/20100101 Firefox/53.0

I have tested this issue on Windows 7 x64 with the latest Firefox release (53.0) and the latest Nightly (55.0a1-20170428030259) and managed to reproduce it.
After navigating to Facebook or Twitter, in about:performance you can observe that Firefox uses a lot of CPU (CPU usage > 20% and System usage > 2%) similar to the results from the attachment 8861567 [details].

I have used the Gecko Profiler add-on to measure the performance, but since I don't really have to much knowledge in this area I can't really tell what could be the cause of this.

https://perfht.ml/2qeAiNk
https://perfht.ml/2qeAz2O

Mike, could you please give your opinion on this in order to figure out what would be the next steps here?

Thank you!

Comment 3

[Mike Conley (:mconley) (:⚙️)]

Hm. I see plenty of Facebook scripts blocking the main thread in the content process, but beyond that, not much else...

Hey ehsan, do you see anything in those two profiles that I don't?

Comment 4

[Paul Roland]

Hello, I am submitting a perf profile as well.
I am able to reproduce this always. Go to that ebay page, scroll a bit and the CPU goes bananas. This is an i7-6600U CPU.
Again, same page browsing with Chrome and none of this happens. Still using Firefox only at work where even if it behaves like this it does not bother me.

So, the profile: https://perfht.ml/2pzbWuX

Comment 5

[Mike Conley (:mconley) (:⚙️)]

(In reply to Paul Roland from comment #4)

> So, the profile: https://perfht.ml/2pzbWuX

Hm... this one is different. This seems to be a non-Nightly instance of Firefox, so I'm seeing things we've already fixed in here (like the PScreenManager sync IPC messages).

One thing I'll note is that there's quite a bit of the content process calling NtGdiDdDDILock inside nsDisplayText::Paint.

https://perf-html.io/public/5c3c2d37fda62d52a38f8dddb0ace7e6dcffa53f/calltree/?implementation=cpp&search=NtGdiDdDDILock&thread=2

Hey Bas, does making that system call so frequently cause any concern?

Comment 6

[Paul Roland]

Yep, using 52.1.0 ESR
Also layout.css.devPixelsPerPx is set to 1.5 but resetting that makes no difference.

Comment 7

[Paul Roland]

https://perfht.ml/2pz528Y

This would be nightly, sorry cannot edit

Comment 8

[Bas Schouten (:bas.schouten)]

This is just a pseudostack, it doesn't give us quite the information we need to diagnose this properly. This -may- be related to bug 1360696. But there's no evidence in the profile as of yet.

Comment 9

[Bas Schouten (:bas.schouten)]

(In reply to Mike Conley (:mconley) from comment #5)
> (In reply to Paul Roland from comment #4)
> 
> > So, the profile: https://perfht.ml/2pzbWuX
> 
> Hm... this one is different. This seems to be a non-Nightly instance of
> Firefox, so I'm seeing things we've already fixed in here (like the
> PScreenManager sync IPC messages).
> 
> One thing I'll note is that there's quite a bit of the content process
> calling NtGdiDdDDILock inside nsDisplayText::Paint.
> 
> https://perf-html.io/public/5c3c2d37fda62d52a38f8dddb0ace7e6dcffa53f/
> calltree/?implementation=cpp&search=NtGdiDdDDILock&thread=2
> 
> Hey Bas, does making that system call so frequently cause any concern?

i.e. spending 5% of time doing rasterization doesn't seem crazy. (Which is likely just what this call is, although it's impossible to say without the full stack) Some of this rendering may not even be text, flushing the drawing batches may just happen most often inside nsDisplayText (there's some reason's why this may be the case, I've seen this elsewhere in a bug this week, and there may be room for improvement there).

It's not directly a 'cause for concern' per sé.

Comment 10

[Paul Roland]

Quick one, should I use this: https://developer.mozilla.org/en-US/docs/Mozilla/How_to_get_a_stacktrace_with_WinDbg
For "full stack"? I am ready to provide more info, I miss Firefox

Comment 11

[(no longer active)]

(In reply to Mike Conley (:mconley) from comment #3)
> Hm. I see plenty of Facebook scripts blocking the main thread in the content
> process, but beyond that, not much else...
> 
> Hey ehsan, do you see anything in those two profiles that I don't?

Sorry, these profiles lack full native backtraces, so I can't really analyze them usefully.  I suggest reprofiling on Nightly.

Comment 12

[Mike Conley (:mconley) (:⚙️)]

Hey Paul,

Are you sure you were using Nightly in the profile you posted in comment 7? It's a pseudostack only, which usually only occurs for other channels (Beta and Release, last I checked - though I think that's changing soon...).

Comment 13

[Paul Roland]

Hi Mike, it appears that I was tired to scroll down a bit further on that page. I was using beta... indeed.
Therefore, just downloaded nightly 55.0a1 (2017-05-04) (64-bit), deleted history and it seems to behave the same: https://perfht.ml/2qwU5aT
Thank you for your help

Comment 14

[Mike Conley (:mconley) (:⚙️)]

Yeah, the profile in comment 13 looks much better, thanks!

I'm seeing many long paints in this profile that are blocking the main thread of the content process (#2). Hey Bas, now that we've got a proper profile here, are you able to take a look?

Comment 15

[Bas Schouten (:bas.schouten)]

There's some time spent clipping, although not a shocking amount compared to what we've seen elsewhere, and we do know our clipping happiness could use some work but that's in layout land. Then there's a fair amount of time spent rendering text, which is not terribly surprising, but not great. There's also a bit of time spent uploading images, again nothing shocking but it's -possible- there's some small room for improvement there.

All in all though, if this page is not invalidating excessively (and that's hard to see from the profile), there's nothing in there that looks particularly actionable.

Comment 16

[Ciprian Muresan [:cmuresan], Ecosystem QA]

Mike, based on the Bas's comment the issue isn't really actionable. What should we do with it?

Comment 17

[Mike Conley (:mconley) (:⚙️)]

We analyzed the profile during the second pilot episode of The Joy of Profiling: https://air.mozilla.org/the-joy-of-profiling-pilot-2/

Our conclusions were:

1) We're spending a lot of time drawing text. I filed bug 1368090 about that.
2) We're not seeing much else that would explain the high CPU usage. We also note that the Gecko Profiler is optimized for finding jank, and not high CPU consumers. Using something like UIforETW[1] might be more useful for gathering an actionable profile here.

[1]: https://randomascii.wordpress.com/2015/09/01/xperf-basics-recording-a-trace-the-ultimate-easy-way/

Comment 18

[Emil Pasca [:emilpasca]]

I have re-tested this issue on Windows 10 x64 with latest Nightly (55.0a1-20170529030204) and using the UIforETW tool suggested in comment 17, I have provided an ETW trace recording of the issue here: https://goo.gl/oQQajl

Mike, can you please take a look at the recording?

Paul, could you also follow the steps from comment 17 and provide a ETW trace recording?

Comment 19

[Mike Conley (:mconley) (:⚙️)]

I'm afraid my skills reading and interpreting UIforETW profiles is somewhat limited[1]. dmajor is far more skilled at it, so redirecting needinfo.

[1]: Though I do hope to beef up those abilities in the future.

Comment 20

[(Away)]

ETW would be helpful in the case where activity is coming from some other process or other thread that Gecko Profiler normally doesn't monitor (system media libraries come to mind). In Emil's trace I don't see anything abnormal in this category. All I see is "the browser doing work" but I don't know the platform broadly enough to tell you if the proportions are out of balance. In any case I think we can probably stick to Gecko Profiler traces.

Comment 21

[Mike Conley (:mconley) (:⚙️)]

(In reply to David Major [:dmajor] from comment #20)

So, just to double-check, there are no unmonitored-by-Gecko-Profiler Firefox threads in emilpasca's UIforETW trace going hogwild?

Comment 22

[(Away)]

> So, just to double-check, there are no unmonitored-by-Gecko-Profiler Firefox
> threads in emilpasca's UIforETW trace going hogwild?

Mmm, maybe I should revisit my statement. There's nothing horrible happening in non-Mozilla code: system networking, media codecs, etc. I'm not entirely sure if all the Mozilla threads would be covered under Gecko profiler though - or maybe not by default.

For example I see ~4% of the trace in:
xul.dll!nsThread::ProcessNextEvent
|- xul.dll!mozilla::image::DecodePoolWorker::Run
|    |- xul.dll!mozilla::image::DecodedSurfaceProvider::Run
|    |    |- xul.dll!mozilla::image::Decoder::Decode

Another ~3% in:
xul.dll!mozilla::BackgroundHangManager::RunMonitorThread, 1032, 1,027.798134, , 0.52
|- xul.dll!mozilla::CondVar::Wait, 1010, 1,006.017806, , 0.51
|    |- mozglue.dll!<PDB not found>, 999, 995.003752, , 0.51
|    |    |- KernelBase.dll!SleepConditionVariableSRW, 998, 994.003752, , 0.51

Another few percent in various JS off-thread helpers, etc.

But even so none of them look egregious enough to explain excessive CPU. Even the total CPU usage graph in Emil's trace isn't that bad, so I'm wondering if maybe we're not quite capturing the same scenario as in the original report.

Comment 24

[Paul Roland]

Hello everyone, I am back. Just downloaded current nightly, navigated the page and created another profile if it helps: https://perfht.ml/2rWkxel

It is the same behavior, unfortunately... I would like to point out that I just submitted that ebay site as a mid-solution, it is far worse in facebook and/or heavy loaded sites.
This, could also be a hardware issue? Strangely although not sure, I don't think Firefox on my workstations behaves the same and they are both Gen6 cpus. CPU in this bug report is i7-6600U and could it be missing some extension somehow?
I've attached about:support info here specially for the graphics sections.

Thanks,
Paul

Comment 25

[Paul Roland]

I could not attach about:support sorry for 2 posts and bothering, pasting info:

Features
Compositing	Direct3D 11
Asynchronous Pan/Zoom	wheel input enabled; scrollbar drag enabled
WebGL 1 Driver WSI Info	EGL_VENDOR: Google Inc. (adapter LUID: 000000000000ae72)
EGL_VERSION: 1.4 (ANGLE 2.1.0.dec065540d5f)
EGL_EXTENSIONS: EGL_EXT_create_context_robustness EGL_ANGLE_d3d_share_handle_client_buffer EGL_ANGLE_d3d_texture_client_buffer EGL_ANGLE_surface_d3d_texture_2d_share_handle EGL_ANGLE_query_surface_pointer EGL_ANGLE_window_fixed_size EGL_ANGLE_keyed_mutex EGL_ANGLE_surface_orientation EGL_ANGLE_direct_composition EGL_NV_post_sub_buffer EGL_KHR_create_context EGL_EXT_device_query EGL_KHR_image EGL_KHR_image_base EGL_KHR_gl_texture_2D_image EGL_KHR_gl_texture_cubemap_image EGL_KHR_gl_renderbuffer_image EGL_KHR_get_all_proc_addresses EGL_KHR_stream EGL_KHR_stream_consumer_gltexture EGL_NV_stream_consumer_gltexture_yuv EGL_ANGLE_flexible_surface_compatibility EGL_ANGLE_stream_producer_d3d_texture_nv12 EGL_ANGLE_create_context_webgl_compatibility EGL_CHROMIUM_create_context_bind_generates_resource 
EGL_EXTENSIONS(nullptr): EGL_EXT_client_extensions EGL_EXT_platform_base EGL_EXT_platform_device EGL_ANGLE_platform_angle EGL_ANGLE_platform_angle_d3d EGL_ANGLE_device_creation EGL_ANGLE_device_creation_d3d11 EGL_ANGLE_experimental_present_path EGL_KHR_client_get_all_proc_addresses 
WebGL 1 Driver Renderer	Google Inc. -- ANGLE (Intel(R) HD Graphics 520 Direct3D11 vs_5_0 ps_5_0)
WebGL 1 Driver Version	OpenGL ES 2.0 (ANGLE 2.1.0.dec065540d5f)
WebGL 1 Driver Extensions	GL_ANGLE_depth_texture GL_ANGLE_framebuffer_blit GL_ANGLE_framebuffer_multisample GL_ANGLE_instanced_arrays GL_ANGLE_lossy_etc_decode GL_ANGLE_pack_reverse_row_order GL_ANGLE_request_extension GL_ANGLE_robust_client_memory GL_ANGLE_texture_compression_dxt3 GL_ANGLE_texture_compression_dxt5 GL_ANGLE_texture_usage GL_ANGLE_translated_shader_source GL_CHROMIUM_bind_generates_resource GL_CHROMIUM_bind_uniform_location GL_CHROMIUM_copy_compressed_texture GL_CHROMIUM_copy_texture GL_CHROMIUM_sync_query GL_EXT_blend_minmax GL_EXT_color_buffer_half_float GL_EXT_debug_marker GL_EXT_discard_framebuffer GL_EXT_disjoint_timer_query GL_EXT_draw_buffers GL_EXT_frag_depth GL_EXT_map_buffer_range GL_EXT_occlusion_query_boolean GL_EXT_read_format_bgra GL_EXT_robustness GL_EXT_sRGB GL_EXT_shader_texture_lod GL_EXT_texture_compression_dxt1 GL_EXT_texture_filter_anisotropic GL_EXT_texture_format_BGRA8888 GL_EXT_texture_rg GL_EXT_texture_storage GL_EXT_unpack_subimage GL_KHR_debug GL_NV_EGL_stream_consumer_external GL_NV_fence GL_NV_pack_subimage GL_NV_pixel_buffer_object GL_OES_EGL_image GL_OES_EGL_image_external GL_OES_compressed_ETC1_RGB8_texture GL_OES_depth32 GL_OES_element_index_uint GL_OES_get_program_binary GL_OES_mapbuffer GL_OES_packed_depth_stencil GL_OES_rgb8_rgba8 GL_OES_standard_derivatives GL_OES_texture_float GL_OES_texture_float_linear GL_OES_texture_half_float GL_OES_texture_half_float_linear GL_OES_texture_npot GL_OES_vertex_array_object 
WebGL 1 Extensions	ANGLE_instanced_arrays EXT_blend_minmax EXT_color_buffer_half_float EXT_frag_depth EXT_shader_texture_lod EXT_texture_filter_anisotropic EXT_disjoint_timer_query MOZ_debug OES_element_index_uint OES_standard_derivatives OES_texture_float OES_texture_float_linear OES_texture_half_float OES_texture_half_float_linear OES_vertex_array_object WEBGL_color_buffer_float WEBGL_compressed_texture_s3tc WEBGL_debug_renderer_info WEBGL_debug_shaders WEBGL_depth_texture WEBGL_draw_buffers WEBGL_lose_context MOZ_WEBGL_lose_context MOZ_WEBGL_compressed_texture_s3tc MOZ_WEBGL_depth_texture
WebGL 2 Driver WSI Info	EGL_VENDOR: Google Inc. (adapter LUID: 000000000000ae72)
EGL_VERSION: 1.4 (ANGLE 2.1.0.dec065540d5f)
EGL_EXTENSIONS: EGL_EXT_create_context_robustness EGL_ANGLE_d3d_share_handle_client_buffer EGL_ANGLE_d3d_texture_client_buffer EGL_ANGLE_surface_d3d_texture_2d_share_handle EGL_ANGLE_query_surface_pointer EGL_ANGLE_window_fixed_size EGL_ANGLE_keyed_mutex EGL_ANGLE_surface_orientation EGL_ANGLE_direct_composition EGL_NV_post_sub_buffer EGL_KHR_create_context EGL_EXT_device_query EGL_KHR_image EGL_KHR_image_base EGL_KHR_gl_texture_2D_image EGL_KHR_gl_texture_cubemap_image EGL_KHR_gl_renderbuffer_image EGL_KHR_get_all_proc_addresses EGL_KHR_stream EGL_KHR_stream_consumer_gltexture EGL_NV_stream_consumer_gltexture_yuv EGL_ANGLE_flexible_surface_compatibility EGL_ANGLE_stream_producer_d3d_texture_nv12 EGL_ANGLE_create_context_webgl_compatibility EGL_CHROMIUM_create_context_bind_generates_resource 
EGL_EXTENSIONS(nullptr): EGL_EXT_client_extensions EGL_EXT_platform_base EGL_EXT_platform_device EGL_ANGLE_platform_angle EGL_ANGLE_platform_angle_d3d EGL_ANGLE_device_creation EGL_ANGLE_device_creation_d3d11 EGL_ANGLE_experimental_present_path EGL_KHR_client_get_all_proc_addresses 
WebGL 2 Driver Renderer	Google Inc. -- ANGLE (Intel(R) HD Graphics 520 Direct3D11 vs_5_0 ps_5_0)
WebGL 2 Driver Version	OpenGL ES 3.0 (ANGLE 2.1.0.dec065540d5f)
WebGL 2 Driver Extensions	GL_ANGLE_depth_texture GL_ANGLE_framebuffer_blit GL_ANGLE_framebuffer_multisample GL_ANGLE_instanced_arrays GL_ANGLE_lossy_etc_decode GL_ANGLE_pack_reverse_row_order GL_ANGLE_request_extension GL_ANGLE_robust_client_memory GL_ANGLE_texture_compression_dxt3 GL_ANGLE_texture_compression_dxt5 GL_ANGLE_texture_usage GL_ANGLE_translated_shader_source GL_CHROMIUM_bind_generates_resource GL_CHROMIUM_bind_uniform_location GL_CHROMIUM_copy_compressed_texture GL_CHROMIUM_copy_texture GL_CHROMIUM_sync_query GL_EXT_blend_minmax GL_EXT_color_buffer_float GL_EXT_color_buffer_half_float GL_EXT_debug_marker GL_EXT_discard_framebuffer GL_EXT_disjoint_timer_query GL_EXT_draw_buffers GL_EXT_frag_depth GL_EXT_map_buffer_range GL_EXT_occlusion_query_boolean GL_EXT_read_format_bgra GL_EXT_robustness GL_EXT_sRGB GL_EXT_shader_texture_lod GL_EXT_texture_compression_dxt1 GL_EXT_texture_filter_anisotropic GL_EXT_texture_format_BGRA8888 GL_EXT_texture_norm16 GL_EXT_texture_rg GL_EXT_texture_storage GL_EXT_unpack_subimage GL_KHR_debug GL_NV_EGL_stream_consumer_external GL_NV_fence GL_NV_pack_subimage GL_NV_pixel_buffer_object GL_OES_EGL_image GL_OES_EGL_image_external GL_OES_EGL_image_external_essl3 GL_OES_compressed_ETC1_RGB8_texture GL_OES_depth32 GL_OES_element_index_uint GL_OES_get_program_binary GL_OES_mapbuffer GL_OES_packed_depth_stencil GL_OES_rgb8_rgba8 GL_OES_standard_derivatives GL_OES_texture_float GL_OES_texture_float_linear GL_OES_texture_half_float GL_OES_texture_half_float_linear GL_OES_texture_npot GL_OES_vertex_array_object 
WebGL 2 Extensions	EXT_color_buffer_float EXT_texture_filter_anisotropic EXT_disjoint_timer_query MOZ_debug OES_texture_float_linear WEBGL_compressed_texture_s3tc WEBGL_debug_renderer_info WEBGL_debug_shaders WEBGL_lose_context MOZ_WEBGL_lose_context MOZ_WEBGL_compressed_texture_s3tc
Audio Backend	wasapi
Direct2D	true
DirectWrite	true (10.0.14393.1198)
GPU #1
Active	Yes
Description	Intel(R) HD Graphics 520
Vendor ID	0x8086
Device ID	0x1916
Driver Version	21.20.16.4590
Driver Date	1-18-2017
Drivers	igdumdim64 igd10iumd64 igd10iumd64 igd12umd64 igdumdim32 igd10iumd32 igd10iumd32 igd12umd32
Subsys ID	505317aa
RAM	Unknown
Diagnostics
AzureCanvasAccelerated	0
AzureCanvasBackend	Direct2D 1.1
AzureCanvasBackend (UI Process)	skia
AzureContentBackend	Direct2D 1.1
AzureContentBackend (UI Process)	skia
AzureFallbackCanvasBackend (UI Process)	cairo
GPUProcessPid	588
GPUProcess	
Decision Log
WEBRENDER	
opt-in by default: WebRender is an opt-in feature

Comment 26

[Mike Conley (:mconley) (:⚙️)]

Does disabling hardware acceleration in about:preferences help?

Comment 27

[Paul Roland]

Hello, it does not but media.hardware-video-decoding.failed is "modified" to true in about:config.

Comment 28

[Paul Roland]

I think I am up to something here. I have moved the ssd on another laptop, some dell e5520.
I have deleted the profile for Firefox, and started it from scratch. OS is the same, some drivers replaced here and there.
On this one, I do not have  the CPU issue. It rarely starts and even then for 10-15 seconds on really heavy workload. 
Another thing that I noticed is in about:config media.hardware-video-decoding.failed is false, and on the other one problematic t460 is was autoset to true.

Therefore I have two laptops, both using the same Firefox, one kills the cpu other doesn't. How can we inspect this further?

Thanks,
Paul

Comment 29

[Emil Pasca [:emilpasca]]

I have re-tested this issue on Windows 10 x64 with the latest Firefox Release (54.0.1) and the latest Nightly(56.0a1-20170703030203) with the following prefs set to true:
gfx.direct2d.disabled
layers.acceleration.disabled
media.hardware-video-decoding.failed
When opening the browser and surfing on Facebook, Twitter, Ebay and other sites as well, the issue is reproducible as mentioned in comment 2.

Mike, what more can we do to make this issue more actionable?

Comment 30

[Mike Conley (:mconley) (:⚙️)]

(In reply to Emil Pasca [:emilpasca], Desktop Engineering QA from comment #29)
> Mike, what more can we do to make this issue more actionable?

And if you flip media.hardware-video-decoding.failed to false, does the heightened CPU usage go away again?

Comment 31

[Emil Pasca [:emilpasca]]

I'm experiencing the same behavior when setting the "media.hardware-video-decoding.failed" pref to false.

Comment 32

[Mike Conley (:mconley) (:⚙️)]

Honestly, not sure what to do here. High CPU is not a thing that the Gecko Profiler is set up to highlight.

UIforETW wasn't able to give us any actionable data here either.

I'm stumped. :(

Comment 33

[Emil Pasca [:emilpasca]]

The issue is still reproducible on the latest Firefox Release (55.0.1), latest Beta (56.0b2-20170810180547) and the latest Nightly (57.0a1-20170813183258).

Comment 34

[Emil Pasca [:emilpasca]]

Closing as Resolved-Incomplete for now, since we don't have the tools to better measure this kind of performance issues.