Open Bug 1334655 Opened 4 years ago Updated 2 years ago

PCompositorBridge::Msg_WillClose can block the UI thread when closing a window

Categories

(Core :: Graphics: Layers, defect, P3)

defect

Tracking

()

People

(Reporter: ehsan, Unassigned)

References

(Blocks 3 open bugs)

Details

(Keywords: hang, perf, Whiteboard: [qf:p3][gfx-noted])

Attachments

(1 file)

See this profile: <https://clptr.io/2jFN1SY>

We start by a sync IPC from the parent main thread to the compositor thread for about 500ms and then the compositor thread somehow disappears from the profile for about 10 *seconds* after which things resume both on the compositor and UI thread sides.

I have no idea what is happening in this profile at the time when the samples disappear.  Markus, do you know?
Blocks: SyncIPC
Keywords: hang
Priority: -- → P3
Whiteboard: [gfx-noted]
Blocks: 1336241
Blocks: UIJank
Actually we are doing some cleanup in [1] but maybe we have chance to return early to main thread.
Jerry, any idea?


[1]http://searchfox.org/mozilla-central/source/gfx/layers/ipc/CompositorBridgeParent.cpp#445
Assignee: nobody → hshih
Hi Markus,

This is the interval that we can't see the sample on both main and compositor thread.
https://perf-html.io/public/1924d93901fbe4000cc018179115ef67cedea68d/calltree/?range=385.2865_432.0684~389.0925_391.3270&thread=0

The more interesting thing is that we can see the "composite", "layer transaction" and "rasterize" markers, but there is no sample shown in profiler.
Are gecko running out of the sampling buffer?
Assignee: hshih → nobody
Flags: needinfo?(mstange)
We pause the profiler just before collecting the profile, and then resume it afterwards. I believe this gap is caused by such a pause. I think Ehsan had the profiler running, collected a profile (which paused the profiler for a bit), interacted with the browser some more, and then collected another profile. The first collection is what caused the gap, the second collection resulted in the profile you're looking at.
Flags: needinfo?(mstange)
Oh, and we still collect markers while the profiler is paused, for some reason. Maybe we should fix that.
Hi Ehsan,
Is the PCompositorBridge::Msg_WillClose() blocking problem shown in the profiler? Are we going to fix the Msg_WillClose() problem in this bug?
Flags: needinfo?(ehsan)
(In reply to Jerry Shih[:jerry] (UTC+8) from comment #5)
> Hi Ehsan,
> Is the PCompositorBridge::Msg_WillClose() blocking problem shown in the
> profiler?

Yeah, all you have to do is search for Msg_WillClose in the profile.

> Are we going to fix the Msg_WillClose() problem in this bug?

I don't understand your question, I'm afraid.  Isn't that what I filed the bug for?

The issue about lack of the profile samples in that 10 second range is not relevant here, it just makes it hard to tell what happened after Msg_WillClose.
Flags: needinfo?(ehsan)
The most of time used in Msg_WillClose() is at gl shader deletion[1]. It's about 400ms[2].

Jeff, any idea for this situation?

[1]
gl shader deletion:
https://dxr.mozilla.org/mozilla-central/rev/d0462b0948e0b1147dcce615bddcc46379bdadb2/gfx/layers/opengl/CompositorOGL.cpp#190
[2]
profiler:
https://perf-html.io/public/1924d93901fbe4000cc018179115ef67cedea68d/calltree/?range=385.2865_432.0684~388.2881_389.0031&thread=1
Flags: needinfo?(jgilbert)
Please search "glDeleteObjectARB_Exec" in profiler.
Deleting shaders shouldn't be that slow. Not sure what's going on in that code, specifically.
Flags: needinfo?(jgilbert) → needinfo?(jmuizelaar)
Jerry can you check how many shaders we're deleting? I was looking at Safari and it deletes shaders pretty often so it seems like there's no obviously slow about deletion.
Flags: needinfo?(jmuizelaar) → needinfo?(hshih)
Hi Ehsan,
Could you please check the map size[1] in comment 0? What's the total time for the all shaders deletion? Is it about 400ms? Could you show the test url here?

[1]
https://dxr.mozilla.org/mozilla-central/rev/d0462b0948e0b1147dcce615bddcc46379bdadb2/gfx/layers/opengl/CompositorOGL.cpp#190
Flags: needinfo?(hshih) → needinfo?(ehsan)
(In reply to Jerry Shih[:jerry] (UTC+8) from comment #11)
> Hi Ehsan,
> Could you please check the map size[1] in comment 0?

I can't really go back in time to when I captured the profile and investigate how many shaders we had there.  :-)

> What's the total time
> for the all shaders deletion? Is it about 400ms? Could you show the test url
> here?

Sounds like these are the types of questions that you want to answer by adding telemetry probes and gathering real world data on.
Flags: needinfo?(ehsan)
I haven't checked the shaders deletion time locally yet. The total shader object number is not fixed. The shader object is created on demand. And I'm afraid that it's related to device issue(apple intel hd5000 gl graphic driver in the profiler). If there is test url to test the shutdown time, I can try to capture the profiler again to see the difference.
Flags: needinfo?(ehsan)
I don't have a test URL unfortunately.  I've seen this a few times in profiles after I have filed the bug, and I'll try to see if I have more info to share the next time I hit this.  Still I think we should add telemetry here.
Flags: needinfo?(ehsan)
Whiteboard: [gfx-noted] → [qf:p1][gfx-noted]
Jerry, what is the next step here?  It's not clear to me if you're actively working on this?  If not, we need to find an owner.  Thank you.
Flags: needinfo?(hshih)
(In reply to :Ehsan Akhgari from comment #14)
> I don't have a test URL unfortunately.  I've seen this a few times in
> profiles after I have filed the bug, and I'll try to see if I have more info
> to share the next time I hit this.  Still I think we should add telemetry
> here.

Ehsan, could you share the about:support of your testing machine(with discrete or integrated GPU)? Then we can try to try some WebGL links to reproduce shader deletion in comment 7.

If we still couldn't reproduce it, we can consider to log shader deletion into telemetry.
Flags: needinfo?(hshih) → needinfo?(ehsan)
Michael,
Could you please try to log the gl shader number and shader deletion time with mbpr 2013(comment 7)?
I see the call-stack with "Apple intel hd 5000 driver".
Flags: needinfo?(cleu)
I opened couple of tabs for random websites and close the window.

It deletes 11 shaders, their deletion time is too little for PR_IntervalNow() so I got all 0 here.

Do you have some particular case which can reproduce the issue?
Flags: needinfo?(cleu)
I used a late-2013 Macbook pro 15-inch but got no luck reproducing it.

I think this issue is driver-related.

Hi Ehsan, can you post your about:support here for a better diagnose of this bug?
about:support:

Application Basics
------------------

Name: Firefox
Version: 55.0a1
Build ID: 20170312030213
Update Channel: nightly
User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:55.0) Gecko/20100101 Firefox/55.0
OS: Darwin 16.4.0
Multiprocess Windows: 9/9 (Enabled by user)
Google Key: Found
Mozilla Location Service Key: Found
Safe Mode: false

Crash Reports for the Last 3 Days
---------------------------------

All Crash Reports

Extensions
----------

Name: about:media
Version: 2.5
Enabled: true
ID: aboutmedia@gavinsharp.com

Name: Activity Stream
Version: 0.0.0
Enabled: true
ID: activity-stream@mozilla.org

Name: Activity Stream
Version: 1.6.0
Enabled: true
ID: @activity-streams

Name: Always Ask
Version: 2.1.2
Enabled: true
ID: alwaysask@zpao.com

Name: Application Update Service Helper
Version: 2.0
Enabled: true
ID: aushelper@mozilla.org

Name: Bugzilla Socorro Lens
Version: 0.5
Enabled: true
ID: bugzilla-socorro-lens@ashughes.com

Name: FlyWeb
Version: 1.0.0
Enabled: true
ID: flyweb@mozilla.org

Name: Form Autofill
Version: 1.0
Enabled: true
ID: formautofill@mozilla.org

Name: Gecko Profiler
Version: 2.0.34
Enabled: true
ID: jid0-edalmuivkozlouyij0lpdx548bc@jetpack

Name: Google Analytics Opt-out Browser Add-on
Version: 0.9.8
Enabled: true
ID: {6d96bb5e-1175-4ebf-8ab5-5f56f1c79f65}

Name: Mass Password Reset
Version: 1.05.1-signed.1-signed
Enabled: true
ID: masspasswordreset@johnathan.nightingale

Name: Multi-process staged rollout
Version: 1.11
Enabled: true
ID: e10srollout@mozilla.org

Name: Paywall Pass
Version: 0.0.3.1-signed
Enabled: true
ID: @paywall-pass

Name: Pocket
Version: 1.0.5
Enabled: true
ID: firefox@getpocket.com

Name: Presentation
Version: 1.0.0
Enabled: true
ID: presentation@mozilla.org

Name: Shield Recipe Client
Version: 1.0.0
Enabled: true
ID: shield-recipe-client@mozilla.org

Name: Test Pilot
Version: 1.1.1-dev-97fd716
Enabled: true
ID: @testpilot-addon

Name: uBlock Origin
Version: 1.11.2
Enabled: true
ID: uBlock0@raymondhill.net

Name: Wayback Machine
Version: 1.8.1
Enabled: true
ID: wayback_machine@mozilla.org

Name: Web Compat
Version: 1.1
Enabled: true
ID: webcompat@mozilla.org

Name: WebCompat Reporter
Version: 1.0.0
Enabled: true
ID: webcompat-reporter@mozilla.org

Name: ADB Helper
Version: 0.9.2
Enabled: false
ID: adbhelper@mozilla.org

Name: Check4Change
Version: 1.9.8.3
Enabled: false
ID: check4change-owner@mozdev.org

Name: Content PID
Version: 0.0.3
Enabled: false
ID: @content-pid

Name: DOM Inspector
Version: 2.0.16.1-signed
Enabled: false
ID: inspector@mozilla.org

Name: Force RTL
Version: 2.3
Enabled: false
ID: {5fa014b6-c474-4c5d-8b0e-c1e73cbefbc4}

Name: MEGA
Version: 3.7.40
Enabled: false
ID: firefox@mega.co.nz

Name: Min Vid
Version: 0.3.4
Enabled: false
ID: @min-vid

Name: Statuser
Version: 0.1.4
Enabled: false
ID: @statuser

Name: uBlock
Version: 0.9.5.0.1-let-fixed
Enabled: false
ID: {2b10c1c8-a11f-4bad-fe9c-1c11e82cac42}

Name: Valence
Version: 0.3.7
Enabled: false
ID: fxdevtools-adapters@mozilla.org

Graphics
--------

Features
Compositing: OpenGL
Asynchronous Pan/Zoom: wheel input enabled; scrollbar drag enabled
WebGL 1 Driver WSI Info: CGL
WebGL 1 Driver Renderer: NVIDIA Corporation -- NVIDIA GeForce GT 750M OpenGL Engine
WebGL 1 Driver Version: 2.1 NVIDIA-10.14.20 355.10.05.15f03
WebGL 1 Driver Extensions: GL_ARB_color_buffer_float GL_ARB_depth_buffer_float GL_ARB_depth_clamp GL_ARB_depth_texture GL_ARB_draw_buffers GL_ARB_draw_elements_base_vertex GL_ARB_draw_instanced GL_ARB_fragment_program GL_ARB_fragment_program_shadow GL_ARB_fragment_shader GL_ARB_framebuffer_object GL_ARB_framebuffer_sRGB GL_ARB_half_float_pixel GL_ARB_half_float_vertex GL_ARB_imaging GL_ARB_instanced_arrays GL_ARB_multisample GL_ARB_multitexture GL_ARB_occlusion_query GL_ARB_pixel_buffer_object GL_ARB_point_parameters GL_ARB_point_sprite GL_ARB_provoking_vertex GL_ARB_seamless_cube_map GL_ARB_shader_objects GL_ARB_shader_texture_lod GL_ARB_shading_language_100 GL_ARB_shadow GL_ARB_sync GL_ARB_texture_border_clamp GL_ARB_texture_compression GL_ARB_texture_compression_rgtc GL_ARB_texture_cube_map GL_ARB_texture_env_add GL_ARB_texture_env_combine GL_ARB_texture_env_crossbar GL_ARB_texture_env_dot3 GL_ARB_texture_float GL_ARB_texture_mirrored_repeat GL_ARB_texture_non_power_of_two GL_ARB_texture_rectangle GL_ARB_texture_rg GL_ARB_transpose_matrix GL_ARB_vertex_array_bgra GL_ARB_vertex_blend GL_ARB_vertex_buffer_object GL_ARB_vertex_program GL_ARB_vertex_shader GL_ARB_window_pos GL_EXT_abgr GL_EXT_bgra GL_EXT_bindable_uniform GL_EXT_blend_color GL_EXT_blend_equation_separate GL_EXT_blend_func_separate GL_EXT_blend_minmax GL_EXT_blend_subtract GL_EXT_clip_volume_hint GL_EXT_debug_label GL_EXT_debug_marker GL_EXT_depth_bounds_test GL_EXT_draw_buffers2 GL_EXT_draw_range_elements GL_EXT_fog_coord GL_EXT_framebuffer_blit GL_EXT_framebuffer_multisample GL_EXT_framebuffer_multisample_blit_scaled GL_EXT_framebuffer_object GL_EXT_framebuffer_sRGB GL_EXT_geometry_shader4 GL_EXT_gpu_program_parameters GL_EXT_gpu_shader4 GL_EXT_multi_draw_arrays GL_EXT_packed_depth_stencil GL_EXT_packed_float GL_EXT_provoking_vertex GL_EXT_rescale_normal GL_EXT_secondary_color GL_EXT_separate_specular_color GL_EXT_shadow_funcs GL_EXT_stencil_two_side GL_EXT_stencil_wrap GL_EXT_texture_array GL_EXT_texture_compression_dxt1 GL_EXT_texture_compression_s3tc GL_EXT_texture_env_add GL_EXT_texture_filter_anisotropic GL_EXT_texture_integer GL_EXT_texture_lod_bias GL_EXT_texture_mirror_clamp GL_EXT_texture_rectangle GL_EXT_texture_shared_exponent GL_EXT_texture_sRGB GL_EXT_texture_sRGB_decode GL_EXT_timer_query GL_EXT_transform_feedback GL_EXT_vertex_array_bgra GL_APPLE_aux_depth_stencil GL_APPLE_client_storage GL_APPLE_element_array GL_APPLE_fence GL_APPLE_float_pixels GL_APPLE_flush_buffer_range GL_APPLE_flush_render GL_APPLE_object_purgeable GL_APPLE_packed_pixels GL_APPLE_pixel_buffer GL_APPLE_rgb_422 GL_APPLE_row_bytes GL_APPLE_specular_vector GL_APPLE_texture_range GL_APPLE_transform_hint GL_APPLE_vertex_array_object GL_APPLE_vertex_array_range GL_APPLE_vertex_point_size GL_APPLE_vertex_program_evaluators GL_APPLE_ycbcr_422 GL_ATI_separate_stencil GL_ATI_texture_env_combine3 GL_ATI_texture_float GL_ATI_texture_mirror_once GL_IBM_rasterpos_clip GL_NV_blend_square GL_NV_conditional_render GL_NV_depth_clamp GL_NV_fog_distance GL_NV_fragment_program_option GL_NV_fragment_program2 GL_NV_light_max_exponent GL_NV_multisample_filter_hint GL_NV_point_sprite GL_NV_texgen_reflection GL_NV_texture_barrier GL_NV_vertex_program2_option GL_NV_vertex_program3 GL_SGIS_generate_mipmap GL_SGIS_texture_edge_clamp GL_SGIS_texture_lod
WebGL 1 Extensions: ANGLE_instanced_arrays EXT_blend_minmax EXT_color_buffer_half_float EXT_frag_depth EXT_sRGB EXT_shader_texture_lod EXT_texture_filter_anisotropic MOZ_debug_get 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: CGL
WebGL 2 Driver Renderer: NVIDIA Corporation -- NVIDIA GeForce GT 750M OpenGL Engine
WebGL 2 Driver Version: 4.1 NVIDIA-10.14.20 355.10.05.15f03
WebGL 2 Driver Extensions: GL_ARB_blend_func_extended GL_ARB_draw_buffers_blend GL_ARB_draw_indirect GL_ARB_ES2_compatibility GL_ARB_explicit_attrib_location GL_ARB_gpu_shader_fp64 GL_ARB_gpu_shader5 GL_ARB_instanced_arrays GL_ARB_internalformat_query GL_ARB_occlusion_query2 GL_ARB_sample_shading GL_ARB_sampler_objects GL_ARB_separate_shader_objects GL_ARB_shader_bit_encoding GL_ARB_shader_subroutine GL_ARB_shading_language_include GL_ARB_tessellation_shader GL_ARB_texture_buffer_object_rgb32 GL_ARB_texture_cube_map_array GL_ARB_texture_gather GL_ARB_texture_query_lod GL_ARB_texture_rgb10_a2ui GL_ARB_texture_storage GL_ARB_texture_swizzle GL_ARB_timer_query GL_ARB_transform_feedback2 GL_ARB_transform_feedback3 GL_ARB_vertex_attrib_64bit GL_ARB_vertex_type_2_10_10_10_rev GL_ARB_viewport_array GL_EXT_debug_label GL_EXT_debug_marker GL_EXT_depth_bounds_test GL_EXT_framebuffer_multisample_blit_scaled GL_EXT_texture_compression_s3tc GL_EXT_texture_filter_anisotropic GL_EXT_texture_mirror_clamp GL_EXT_texture_sRGB_decode GL_APPLE_client_storage GL_APPLE_container_object_shareable GL_APPLE_flush_render GL_APPLE_object_purgeable GL_APPLE_rgb_422 GL_APPLE_row_bytes GL_APPLE_texture_range GL_ATI_texture_mirror_once GL_NV_texture_barrier
WebGL 2 Extensions: EXT_color_buffer_float EXT_texture_filter_anisotropic EXT_disjoint_timer_query MOZ_debug_get 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: audiounit
GPU #1
Active: Yes
Vendor ID: 0x8086
Device ID: 0x0d26

Diagnostics
AzureCanvasAccelerated: 1
AzureCanvasBackend: skia
AzureContentBackend: skia
AzureFallbackCanvasBackend: none
TileHeight: 1024
TileWidth: 1024
Decision Log
WEBRENDER:
unavailable by runtime: Build doesn't include WebRender




Important Modified Preferences
------------------------------

accessibility.mouse_focuses_formcontrol: true
accessibility.typeaheadfind.flashBar: 0
accessibility.warn_on_browsewithcaret: false
browser.cache.disk.capacity: 358400
browser.cache.disk.filesystem_reported: 1
browser.cache.disk.hashstats_reported: 1
browser.cache.disk.smart_size_cached_value: 358400
browser.cache.disk.smart_size.first_run: false
browser.cache.disk.smart_size.use_old_max: false
browser.cache.frecency_experiment: 3
browser.download.importedFromSqlite: true
browser.fixup.domainwhitelist.git: true
browser.fixup.domainwhitelist.pastebin: true
browser.fixup.domainwhitelist.treeherder: true
browser.places.importBookmarksHTML: false
browser.places.smartBookmarksVersion: 8
browser.search.useDBForOrder: true
browser.sessionstore.max_windows_undo: 10
browser.sessionstore.resume_from_crash: false
browser.sessionstore.upgradeBackup.latestBuildID: 20170308030207
browser.startup.homepage: resource://activity-streams/data/content/activity-streams.html#/
browser.startup.homepage_override.buildID: 20170312030213
browser.startup.homepage_override.mstone: 55.0a1
browser.tabs.crashReporting.includeURL: true
browser.tabs.drawInTitlebar: false
browser.tabs.remote.autostart: true
browser.tabs.remote.autostart.2: false
browser.tabs.warnOnClose: false
browser.urlbar.autoFill: false
browser.urlbar.maxRichResults: 12
browser.urlbar.suggest.searches: true
browser.urlbar.usepreloadedtopurls.enabled: false
browser.urlbar.userMadeSearchSuggestionsChoice: true
dom.allow_XUL_XBL_for_file: true
dom.apps.lastUpdate.buildID: 20160725030248
dom.apps.lastUpdate.mstone: 50.0a1
dom.apps.reset-permissions: true
dom.gamepad.extensions.enabled: true
dom.min_tracking_background_timeout_value: 10000
dom.mozApps.maxLocalId: 1005
dom.mozApps.runUpdate: false
dom.mozApps.used: true
dom.push.userAgentID: 8bdeaa2c38fd451586f5cefad5601a08
dom.w3c_touch_events.expose: false
extensions.checkCompatibility.3.6.previous: false
extensions.checkCompatibility.3.6b.previous: false
extensions.checkCompatibility.3.6p.previous: false
extensions.checkCompatibility.3.6pre.previous: false
extensions.checkCompatibility.3.7a.previous: false
extensions.checkCompatibility.4.0.previous: false
extensions.checkCompatibility.4.0b.previous: false
extensions.checkCompatibility.4.0p.previous: false
extensions.checkCompatibility.4.0pre.previous: false
extensions.checkCompatibility.4.2.previous: false
extensions.checkCompatibility.4.2a.previous: false
extensions.checkCompatibility.4.2b.previous: false
extensions.checkCompatibility.4.2p.previous: false
extensions.checkCompatibility.4.2pre.previous: false
extensions.checkCompatibility.5.0.previous: false
extensions.checkCompatibility.5.0a.previous: false
extensions.checkCompatibility.5.0b.previous: false
extensions.checkCompatibility.5.0p.previous: false
extensions.checkCompatibility.5.0pre.previous: false
extensions.checkCompatibility.6.0.previous: false
extensions.checkCompatibility.6.0a.previous: false
extensions.checkCompatibility.7.0.previous: false
extensions.checkCompatibility.7.0a.previous: false
extensions.checkCompatibility.8.0.previous: false
extensions.checkCompatibility.8.0a.previous: false
extensions.checkCompatibility.nightly.previous: false
extensions.checkCompatibility.previous: false
extensions.lastAppVersion: 55.0a1
font.internaluseonly.changed: false
font.language.group: ar
font.size.variable.ar: 13
gfx.blacklist.direct2d.failureid: FEATURE_FAILURE_DL_BLACKLIST_g984
gfx.blacklist.hardwarevideodecoding.failureid: FEATURE_FAILURE_DL_BLACKLIST_g1208
gfx.crash-guard.glcontext.appVersion: 43.0a1
gfx.crash-guard.glcontext.deviceID: 0x0d26
gfx.crash-guard.status.glcontext: 2
gfx.force_atsui_text: true
javascript.options.asyncstack: false
media.benchmark.vp9.fps: 136
media.benchmark.vp9.versioncheck: 2
media.gmp-gmpopenh264.abi: x86_64-gcc3
media.gmp-gmpopenh264.lastUpdate: 1481423428
media.gmp-gmpopenh264.path: /Users/ehsan/Library/Application Support/Firefox/Profiles/mf0c19uk.trunk/gmp-gmpopenh264
media.gmp-gmpopenh264.version: 1.6
media.gmp-manager.buildID: 20170312030213
media.gmp-manager.lastCheck: 1489357696
media.gmp-widevinecdm.abi: x86_64-gcc3
media.gmp-widevinecdm.lastUpdate: 1481423456
media.gmp-widevinecdm.version: 1.4.8.903
media.gmp.storage.version.observed: 1
media.webaudio.legacy.AudioBufferSourceNode: false
media.webaudio.legacy.AudioContext: false
media.webrtc.debug.aec_log_dir: /tmp/
media.webrtc.debug.log_file: /tmp/WebRTC.log
network.cookie.prefsMigrated: true
network.dns.disablePrefetch: true
network.http.spdy.enabled.http2draft: false
network.http.speculative-parallel-limit: 0
network.predictor.cleaned-up: true
network.prefetch-next: false
network.warnOnAboutNetworking: false
places.database.lastMaintenance: 1489357933
places.favicons.optimizeToDimension: 64
places.history.expiration.transient_current_max_pages: 125471
plugin.disable_full_page_plugin_for_types: application/pdf
plugin.importedState: true
plugin.state.adobeaamdetect: 0
plugin.state.adobepdfviewernpapi: 0
plugin.state.default browser: 0
plugin.state.divxbrowserplugin: 0
plugin.state.doubletwistwebplugin: 0
plugin.state.flash: 0
plugin.state.flip4mac wmv plugin: 0
plugin.state.google earth web plug-in: 0
plugin.state.googletalkbrowserplugin: 0
plugin.state.iphotophotocast: 0
plugin.state.java: 0
plugin.state.npgtpo3dautoplugin: 2
plugin.state.o1dbrowserplugin: 0
plugin.state.ovshelper: 0
plugin.state.quicktime plugin: 0
plugin.state.sharepointbrowserplugin: 0
plugin.state.silverlight: 0
plugin.state.unity web player: 0
print.print_bgcolor: false
print.print_bgimages: false
print.print_colorspace:
print.print_command:
print.print_downloadfonts: false
print.print_duplex: 0
print.print_evenpages: true
print.print_in_color: true
print.print_margin_bottom: 0.5
print.print_margin_left: 0.5
print.print_margin_right: 0.5
print.print_margin_top: 0.5
print.print_oddpages: true
print.print_orientation: 0
print.print_page_delay: 50
print.print_pagedelay: 500
print.print_paper_data: 0
print.print_paper_height: 11.00
print.print_paper_name:
print.print_paper_size_type: 1
print.print_paper_size_unit: 0
print.print_paper_width: 8.50
print.print_plex_name:
print.print_printer:
print.print_resolution: 0
print.print_resolution_name:
print.print_reversed: false
print.print_scaling: 1.00
print.print_shrink_to_fit: true
print.print_to_file: false
print.print_unwriteable_margin_bottom: 12
print.print_unwriteable_margin_left: 12
print.print_unwriteable_margin_right: 12
print.print_unwriteable_margin_top: 12
print.printer__.print_bgcolor: false
print.printer__.print_bgimages: false
print.printer__.print_duplex: 0
print.printer__.print_edge_bottom: 0
print.printer__.print_edge_left: 0
print.printer__.print_edge_right: 0
print.printer__.print_edge_top: 0
print.printer__.print_evenpages: true
print.printer__.print_footercenter:
print.printer__.print_footerleft: &PT
print.printer__.print_footerright: &D
print.printer__.print_headercenter:
print.printer__.print_headerleft: &T
print.printer__.print_headerright: &U
print.printer__.print_in_color: true
print.printer__.print_margin_bottom: 0.5
print.printer__.print_margin_left: 0.5
print.printer__.print_margin_right: 0.5
print.printer__.print_margin_top: 0.5
print.printer__.print_oddpages: true
print.printer__.print_orientation: 0
print.printer__.print_page_delay: 50
print.printer__.print_paper_data: 0
print.printer__.print_paper_height: 11.00
print.printer__.print_paper_name: na-letter
print.printer__.print_paper_size_unit: 0
print.printer__.print_paper_width: 8.50
print.printer__.print_resolution: 0
print.printer__.print_reversed: false
print.printer__.print_scaling: 1.00
print.printer__.print_shrink_to_fit: true
print.printer__.print_to_file: false
print.printer__.print_unwriteable_margin_bottom: 12
print.printer__.print_unwriteable_margin_left: 12
print.printer__.print_unwriteable_margin_right: 12
print.printer__.print_unwriteable_margin_top: 12
print.printer_EPSON_WF-3620_Series.print_bgcolor: false
print.printer_EPSON_WF-3620_Series.print_bgimages: false
print.printer_EPSON_WF-3620_Series.print_duplex: 0
print.printer_EPSON_WF-3620_Series.print_edge_bottom: 0
print.printer_EPSON_WF-3620_Series.print_edge_left: 0
print.printer_EPSON_WF-3620_Series.print_edge_right: 0
print.printer_EPSON_WF-3620_Series.print_edge_top: 0
print.printer_EPSON_WF-3620_Series.print_evenpages: true
print.printer_EPSON_WF-3620_Series.print_footercenter:
print.printer_EPSON_WF-3620_Series.print_footerleft: &PT
print.printer_EPSON_WF-3620_Series.print_footerright: &D
print.printer_EPSON_WF-3620_Series.print_headercenter:
print.printer_EPSON_WF-3620_Series.print_headerleft: &T
print.printer_EPSON_WF-3620_Series.print_headerright: &U
print.printer_EPSON_WF-3620_Series.print_in_color: true
print.printer_EPSON_WF-3620_Series.print_margin_bottom: 0.5
print.printer_EPSON_WF-3620_Series.print_margin_left: 0.5
print.printer_EPSON_WF-3620_Series.print_margin_right: 0.5
print.printer_EPSON_WF-3620_Series.print_margin_top: 0.5
print.printer_EPSON_WF-3620_Series.print_oddpages: true
print.printer_EPSON_WF-3620_Series.print_orientation: 0
print.printer_EPSON_WF-3620_Series.print_page_delay: 50
print.printer_EPSON_WF-3620_Series.print_paper_data: 0
print.printer_EPSON_WF-3620_Series.print_paper_height: 11.00
print.printer_EPSON_WF-3620_Series.print_paper_name:
print.printer_EPSON_WF-3620_Series.print_paper_size_type: 1
print.printer_EPSON_WF-3620_Series.print_paper_size_unit: 0
print.printer_EPSON_WF-3620_Series.print_paper_width: 8.50
print.printer_EPSON_WF-3620_Series.print_resolution: 0
print.printer_EPSON_WF-3620_Series.print_reversed: false
print.printer_EPSON_WF-3620_Series.print_scaling: 1.00
print.printer_EPSON_WF-3620_Series.print_shrink_to_fit: true
print.printer_EPSON_WF-3620_Series.print_to_file: false
print.printer_EPSON_WF-3620_Series.print_unwriteable_margin_bottom: 12
print.printer_EPSON_WF-3620_Series.print_unwriteable_margin_left: 12
print.printer_EPSON_WF-3620_Series.print_unwriteable_margin_right: 12
print.printer_EPSON_WF-3620_Series.print_unwriteable_margin_top: 12
print.printer_TOR5-DrClaw.print_bgcolor: false
print.printer_TOR5-DrClaw.print_bgimages: false
print.printer_TOR5-DrClaw.print_duplex: 0
print.printer_TOR5-DrClaw.print_edge_bottom: 0
print.printer_TOR5-DrClaw.print_edge_left: 0
print.printer_TOR5-DrClaw.print_edge_right: 0
print.printer_TOR5-DrClaw.print_edge_top: 0
print.printer_TOR5-DrClaw.print_evenpages: true
print.printer_TOR5-DrClaw.print_footercenter:
print.printer_TOR5-DrClaw.print_footerleft: &PT
print.printer_TOR5-DrClaw.print_footerright: &D
print.printer_TOR5-DrClaw.print_headercenter:
print.printer_TOR5-DrClaw.print_headerleft: &T
print.printer_TOR5-DrClaw.print_headerright: &U
print.printer_TOR5-DrClaw.print_in_color: true
print.printer_TOR5-DrClaw.print_margin_bottom: 0.5
print.printer_TOR5-DrClaw.print_margin_left: 0.5
print.printer_TOR5-DrClaw.print_margin_right: 0.5
print.printer_TOR5-DrClaw.print_margin_top: 0.5
print.printer_TOR5-DrClaw.print_oddpages: true
print.printer_TOR5-DrClaw.print_orientation: 0
print.printer_TOR5-DrClaw.print_page_delay: 50
print.printer_TOR5-DrClaw.print_paper_data: 0
print.printer_TOR5-DrClaw.print_paper_height: 11.00
print.printer_TOR5-DrClaw.print_paper_name:
print.printer_TOR5-DrClaw.print_paper_size_type: 1
print.printer_TOR5-DrClaw.print_paper_size_unit: 0
print.printer_TOR5-DrClaw.print_paper_width: 8.50
print.printer_TOR5-DrClaw.print_resolution: 0
print.printer_TOR5-DrClaw.print_reversed: false
print.printer_TOR5-DrClaw.print_scaling: 1.00
print.printer_TOR5-DrClaw.print_shrink_to_fit: true
print.printer_TOR5-DrClaw.print_to_file: false
print.printer_TOR5-DrClaw.print_unwriteable_margin_bottom: 17
print.printer_TOR5-DrClaw.print_unwriteable_margin_left: 17
print.printer_TOR5-DrClaw.print_unwriteable_margin_right: 17
print.printer_TOR5-DrClaw.print_unwriteable_margin_top: 17
privacy.clearOnShutdown.passwords: false
privacy.cpd.cookies: false
privacy.cpd.downloads: false
privacy.cpd.formdata: false
privacy.cpd.history: false
privacy.cpd.sessions: false
privacy.donottrackheader.enabled: true
privacy.sanitize.migrateClearSavedPwdsOnExit: true
privacy.sanitize.migrateFx3Prefs: true
privacy.sanitize.timeSpan: 2
privacy.trackingprotection.introCount: 20
security.disable_button.openCertManager: false
security.disable_button.openDeviceManager: false
security.enable_java: false
security.notification_enable_delay: 0
security.OCSP.disable_button.managecrl: false
security.OCSP.enabled: 0
security.sandbox.content.tempDirSuffix: {df7099ab-7ebd-6244-9489-d4a5a42ad06b}
security.ssl.errorReporting.automatic: true
security.ssl3.dhe_rsa_aes_128_sha: false
security.ssl3.dhe_rsa_aes_256_sha: false
security.warn_viewing_mixed: false
services.sync.declinedEngines: history,forms,tabs,prefs,bookmarks,addons
services.sync.engine.addons: false
services.sync.engine.bookmarks: false
services.sync.engine.history: false
services.sync.engine.prefs: false
services.sync.engine.prefs.modified: false
services.sync.engine.tabs: false
services.sync.lastPing: 1489434158
services.sync.lastSync: Mon Mar 13 2017 16:20:01 GMT-0400 (EDT)
services.sync.numClients: 2
social.enabledByActivityStream: true
storage.vacuum.last.index: 0
storage.vacuum.last.places.sqlite: 1489357932
webgl.msaa-force: true
webgl.verbose: true

Important Locked Preferences
----------------------------

Places Database
---------------

JavaScript
----------

Incremental GC: true

Accessibility
-------------

Activated: false
Prevent Accessibility: 0

Library Versions
----------------

NSPR
Expected minimum version: 4.13.1
Version in use: 4.13.1

NSS
Expected minimum version: 3.30 Beta
Version in use: 3.30 Beta

NSSSMIME
Expected minimum version: 3.30 Beta
Version in use: 3.30 Beta

NSSSSL
Expected minimum version: 3.30 Beta
Version in use: 3.30 Beta

NSSUTIL
Expected minimum version: 3.30 Beta
Version in use: 3.30 Beta

Experimental Features
---------------------

Sandbox
-------

Content Process Sandbox Level: 2
Flags: needinfo?(ehsan)
FWIW, this bug is moving a bit off the rails, let me try to re-focus the effort.  What matters the most here is for us to drive the cost of this for the majority of our users, not for me specifically.  There is no reason at all to keep focusing on anything about my machine.

We have some generic telemetry about these sync IPC issues.  For example, this is the current data on Aurora:

Start	End	IPC_SYNC_LATENCY_MS Count
0	1	0 (0%)
1	3	419.31k (76.44%)
3	8	69.31k (12.64%)
8	20	35.48k (6.47%)
20	50	14.07k (2.56%)
50	126	6.75k (1.23%)
126	317	2.45k (0.45%)
317	796	846 (0.15%)
796	2k	253 (0.05%)
2k	Infinity	73 (0.01%)

The telemetry that we collect ignores sync IPC issues that finish really quickly (currently on Aurora less than 1ms).  The current data shows that a ton of these probes take some time between 1-3 ms, but a good number of them can jank us for several frames.  Note that this can happen during closing a window (can this happen on any other code path also?) where we have several other expensive operations and the cost of everything on this path adds up making the overall performance of closing a window less than ideal.  Since the work here happens on the UI thread and locks up the compositor as well, any significant amount of time we spend deleting shaders can have disastrous performance consequences.
The WillClose only happened when users tried to close the window. 

Based on the discussion from Jerry and nical, one purpose of sync IPC is to make sure the requests from child side are handled properly by parent[1]. But there comes a question that which share resource we need this sync IPC approach to protect.

[1]http://searchfox.org/mozilla-central/source/gfx/layers/ipc/CrossProcessCompositorBridgeParent.h#54
Trying to understand this bug; the particular sync IPC being mentioned is Mac only.  On the other hand, comment 21 talks about sync IPC in more general terms.

Is this bug "fix all graphics related sync IPC on close on all platforms"?
Flags: needinfo?(ehsan)
I think this 'WillClose' sync IPC happens on all paltforms.
(In reply to Peter Chang[:pchang] from comment #24)
> I think this 'WillClose' sync IPC happens on all platforms.

Comment 7 shows the time spent in GL shader deletion on the Mac - do we have a profile for Windows?  Do we know how long it takes on Windows?
Before comment 21, we thought this was caused by GL shader deletion based on ehsan's profile but we couldn't reproduce this in taipei with Mac or Windows machine.

But looking the data in comment 21, it mentioned about the latency distribution that caused by this sync IPC on all platforms. Therefore, we might need to think about how to improve this sync IPC or change to async approach.
Assign to Jerry and he will start to work on this after 4/10.
Assignee: nobody → hshih
(In reply to Milan Sreckovic [:milan] from comment #23)
> Trying to understand this bug; the particular sync IPC being mentioned is
> Mac only.  On the other hand, comment 21 talks about sync IPC in more
> general terms.

I don't see anything in the discussion this bug which seems Mac specific.  I don't really know much about the code that is sending this IPC message, but since it's only called from one place it was easy to see where it's coming from.  This code was added in bug 1215265 (see this code <http://searchfox.org/mozilla-central/rev/7419b368156a6efa24777b21b0e5706be89a9c2f/gfx/layers/ipc/CompositorBridgeChild.cpp#166>) and based on the discussion in that bug, this should affect all platforms.

> Is this bug "fix all graphics related sync IPC on close on all platforms"?

This is the only graphics sync IPC bug that happens when closing a window that I'm aware of currently.
Blocks: 1215265
Flags: needinfo?(ehsan)
Assignee: hshih → dvander
Ehsan, if we're only collecting how often these messages jank, it seems like we wouldn't know how often they *don't* jank. To find out if this really impacts users we'd have to correlate it with another metric, like how often a window is closed and then brings a background window into the foreground.

This message was synchronous long before bug 1215265 - in fact that one removed a sync message. The original sync message was added in [1] which helpfully has no bug or commit message.

I think in modern IPDL this one might not be so hard to remove, I'll do a try run and see. The tricky part is that before the GPU process, the compositor relied on that sync message scoping the lifetime of its resources. If the main thread destroys the window before an in-process compositor "forgets" it, we'll crash. But it should be possible to negotiate shutdown asynchronously.
No longer blocks: 1215265
This is a good thing to do on top of bug 1349699, to make sure we're not about to add more IPDL crashes.
Blocks: 1349699
This is proving to be not so easy. The X11 compositor flat out crashes if it races with a widget that is closing (assumedly, because X11 resources have gone away). Our choices are probably (1) have platform specific shutdown logic, or (2) make WillClose async, but refuse to destroy a composited widget until the compositor has sent back an ACK message. I would expect either one to cause problems with general browser shutdown, since layers expects to be cleaned up by xpcom-shutdown time, which would not be true anymore.

I'd like to do some Telemetry first to make sure this is actually worth fixing - I think we already collect enough data to make a correlation.
Based on comment 16, I add a telemetry for measuring shader deletion time.
Since the number of shader is not fixed, the data is classified according to the number.
I've tried to measured it by opening some websites locally and the shader number was around 10 and the deletion time was 1 ms; therefore, I expect the data will mainly in first two categories but I still defined some categories cases with more shader number.

Is this what we need for the telemetry?
Flags: needinfo?(hshih)
Flags: needinfo?(dvander)
(In reply to Kevin Chen[:kechen] (UTC + 8) from comment #33)
> Created attachment 8856348 [details] [diff] [review]
> Add telemetry for shader deletion.
> 
> Based on comment 16, I add a telemetry for measuring shader deletion time.
> Since the number of shader is not fixed, the data is classified according to
> the number.
> I've tried to measured it by opening some websites locally and the shader
> number was around 10 and the deletion time was 1 ms; therefore, I expect the
> data will mainly in first two categories but I still defined some categories
> cases with more shader number.
> 
> Is this what we need for the telemetry?

I don't think it answers the question, "how important is fixing this bug?". The D3D11 compositor doesn't delete shaders until the last window is closed, and I'm not too worried about dropping synchronous messages on shutdown. What we really want is to know how often these messages are delaying a background window coming into the foreground.
Flags: needinfo?(dvander)
(In reply to David Anderson [:dvander] from comment #29)
> Ehsan, if we're only collecting how often these messages jank, it seems like
> we wouldn't know how often they *don't* jank. To find out if this really
> impacts users we'd have to correlate it with another metric, like how often
> a window is closed and then brings a background window into the foreground.

Yes, that's a good point.  The telemetry here is just a crude generic probe that measures all long running sync IPC, but in this case I agree that it's not enough data.

I think it makes sense to get a sense of how often this janks out of the number of times that janks against the sync IPC call happening and not janking (I think that's what the "window is closed and bring up a background window into the foreground" case roughly would be?)

Please note that for the UX team, the performance of the window closing is critical, i.e., they want the window to disappear as soon as the user presses the X button.  So this bug would be important to fix if it even slows down a small-ish number of cases significantly, or if it slows down a large number of cases but by a little bit only (but enough to make things perceivable added on top of other slowness).  The hard question would be to turn this into some precise thresholds of course.

(Not that this should block getting the telemetry!)

> This message was synchronous long before bug 1215265 - in fact that one
> removed a sync message. The original sync message was added in [1] which
> helpfully has no bug or commit message.

Ugh. :(

(In reply to David Anderson [:dvander] from comment #32)
> This is proving to be not so easy. The X11 compositor flat out crashes if it
> races with a widget that is closing (assumedly, because X11 resources have
> gone away). Our choices are probably (1) have platform specific shutdown
> logic, or (2) make WillClose async, but refuse to destroy a composited
> widget until the compositor has sent back an ACK message. I would expect
> either one to cause problems with general browser shutdown, since layers
> expects to be cleaned up by xpcom-shutdown time, which would not be true
> anymore.

Couldn't we use an async shutdown blocker for that?  They're pretty neat, they allow you to force some cleanup C++ code to run before xpcom-shutdown, so we can wait for any remaining widgets to be destroyed before allowing the shutdown to proceed.  See <http://searchfox.org/mozilla-central/rev/624d25b2980cf5f83452b040e6d664460f9b7ec5/dom/media/MediaManager.cpp#1807> for an example.
(In reply to :Ehsan Akhgari (super long backlog, slow to respond) from comment #35)
> Couldn't we use an async shutdown blocker for that?  They're pretty neat,
> they allow you to force some cleanup C++ code to run before xpcom-shutdown,
> so we can wait for any remaining widgets to be destroyed before allowing the
> shutdown to proceed.  See
> <http://searchfox.org/mozilla-central/rev/
> 624d25b2980cf5f83452b040e6d664460f9b7ec5/dom/media/MediaManager.cpp#1807>
> for an example.

That *is* neat, thanks! That might make this easier.
Hrm, I don't think an async shutdown blocker will help that much. If we can't destroy some widgets until the compositor shuts down, then we're still delaying the visual effect of the window closing. Perhaps longer than if we just synchronously blocked.

When I query this in the telemetry backend, 96% of IPC_SYNC_MAIN_LATENCY_MS values for Msg_WillClose are < 32ms. That's not a terribly useful statistic, but it does suggest things aren't that bad. Very few sessions are only in the awful buckets. There's no real correlation with compositor type.

However, there is a correlation with the GPU process: only 0.8% of sessions with any Msg_WillClose statistic have the GPU process enabled - versus 20% in the full population I queried. Does this suggest the main process is way too busy and the GPU process is alleviating the load? That wouldn't surprise me but it totally wasn't an expected outcome.

Anyway, I'm doing some try runs to see if I can make WillClose a Linux/Mac thing and drop it for Windows. I think I sorted out the layers/xpcom-shutdown issue.
Actually I take that back, I didn't realize IPC_SYNC_MAIN_LATENCY_MS is such a new statistic. When I limit the population to that, there's no correlation. But oddly, only 0.7% of sessions with that histogram appearing have the GPU process enabled. That is very odd and suggests we accidentally turned it off or something.
(In reply to David Anderson [:dvander] from comment #38)
> Actually I take that back, I didn't realize IPC_SYNC_MAIN_LATENCY_MS is such
> a new statistic.

This probe was rename from IPC_SYNC_LATENCY_MS in bug 1337073.  Does that help make sense of the data?
(In reply to :Ehsan Akhgari (super long backlog, slow to respond) from comment #39)
> (In reply to David Anderson [:dvander] from comment #38)
> > Actually I take that back, I didn't realize IPC_SYNC_MAIN_LATENCY_MS is such
> > a new statistic.
> 
> This probe was rename from IPC_SYNC_LATENCY_MS in bug 1337073.  Does that
> help make sense of the data?

Nope... I'm legitimately confused. I re-ran my telemetry job and IPC_SYNC_MAIN_LATENCY_MS in the parent process is highly correlated with not having the GPU process. Users with the GPU process are extremely unlikely to have high-latency sync messages. (And users with high-latency sync messages are extremely unlikely to have the GPU process.)
That is - in the UI process. I didn't do any correlation for sync messages from content, I'm assuming there isn't one but I will check.
(In reply to David Anderson [:dvander] from comment #34)
> (In reply to Kevin Chen[:kechen] (UTC + 8) from comment #33)
> > 
> > Is this what we need for the telemetry?
> 
> I don't think it answers the question, "how important is fixing this bug?".
> The D3D11 compositor doesn't delete shaders until the last window is closed,
> and I'm not too worried about dropping synchronous messages on shutdown.
> What we really want is to know how often these messages are delaying a
> background window coming into the foreground.

I still think we should fix the long shader deletion time problem. The ~compositor() is running at compositor thread. If there is a ~compositor() call spending 500ms, all rendering task will be blocked for 500ms. Add the data into telemetry could give us the impact factor for ~compositor().
(In reply to Jerry Shih[:jerry] (UTC+8) from comment #42)
> (In reply to David Anderson [:dvander] from comment #34)
> > (In reply to Kevin Chen[:kechen] (UTC + 8) from comment #33)
> > > 
> > > Is this what we need for the telemetry?
> > 
> > I don't think it answers the question, "how important is fixing this bug?".
> > The D3D11 compositor doesn't delete shaders until the last window is closed,
> > and I'm not too worried about dropping synchronous messages on shutdown.
> > What we really want is to know how often these messages are delaying a
> > background window coming into the foreground.
> 
> I still think we should fix the long shader deletion time problem. The
> ~compositor() is running at compositor thread. If there is a ~compositor()
> call spending 500ms, all rendering task will be blocked for 500ms. Add the
> data into telemetry could give us the impact factor for ~compositor().

Can you file a separate bug for fixing that?
After a lot of unsuccessful try runs, this is still looking difficult to fix. Given we're focusing on Windows 8+ and E10S, and the data in comment #40 suggests the GPU process is a big win for UI sync messages, it should be enough to try turning the GPU process on for more users. We're aiming to do that in bug 1356448, so after that has had time to settle, I'll re-check the stats.
Flags: needinfo?(hshih)
Whiteboard: [qf:p1][gfx-noted] → [qf:p2][gfx-noted]
(In reply to David Anderson [:dvander] from comment #44)
> it should be
> enough to try turning the GPU process on for more users. We're aiming to do
> that in bug 1356448, so after that has had time to settle, I'll re-check the
> stats.

(Looks like bug 1356448 hit Nightlies 9 days ago. Not sure if that's enough "time to settle" :), but tagging you for needinfo to follow up on this once you get a chance. Thanks!)
Flags: needinfo?(dvander)
I filed bug 1370690 to re-do that analysis.
Assignee: dvander → nobody
Flags: needinfo?(dvander)
Keywords: perf
The analysis seems to indicate this is not a significant issue anymore. I think this bug can stay open as making the message async altogether, but it's not a priority anymore.
Summary: PCompositorBridge::Msg_WillClose can lock up the UI thread for a long time when closing a window → PCompositorBridge::Msg_WillClose can block the UI thread when closing a window
Whiteboard: [qf:p2][gfx-noted] → [qf:p3][gfx-noted]
Whiteboard: [qf:p3][gfx-noted] → [qf:p3][gfx-noted][fxperf]
Whiteboard: [qf:p3][gfx-noted][fxperf] → [qf:p3][gfx-noted]
You need to log in before you can comment on or make changes to this bug.