Issue metadata
Sign in to add a comment
|
Interval of timeupdate events can be bigger then required 250ms (2nd issue)
Reported by
ddy...@vewd.com,
Apr 26 2018
|
||||||||||||||||||||
Issue descriptionUserAgent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.117 Safari/537.36 Example URL: https://jsfiddle.net/4m7spd4e/ Steps to reproduce the problem: 1. Do heavy-stressing operation on your computer (stress CPU and I/O) 2. Open provided URL (https://jsfiddle.net/4m7spd4e/) 3. Wait for video to start playing 4. Observe logs 5. Observe TC results (green = pass, red = fail) What is the expected behavior? Simply: Interval between two `timeupdate` fired events should be smaller then 250ms (spec says it should be in range [15ms, 250ms]). From HTML5 specification (https://dev.w3.org/html5/spec-preview/media-elements.html): "If the time was reached through the usual monotonic increase of the current playback position during normal playback, and if the user agent has not fired a timeupdate event at the element in the past 15 to 250ms and is not still running event handlers for such an event, then the user agent must queue a task to fire a simple event named timeupdate at the element. (In the other cases, such as explicit seeks, relevant events get fired as part of the overall process of changing the current playback position.)" "The event thus is not to be fired faster than about 66Hz or slower than 4Hz (assuming the event handlers don't take longer than 250ms to run). User agents are encouraged to vary the frequency of the event based on the system load and the average cost of processing the event each time, so that the UI updates are not any more frequent than the user agent can comfortably handle while decoding the video." What went wrong? Chromium/Chrome sometimes fires timeupdate too later, after more then 250ms already passed then last timeupdate event. This happens due to scheduling of internal tasks in BLINK. The problem is that in HTMLMediaElement::ScheduleTimeupdateEvent() we schedule next timeupdate event after (at lest! which is crucial here!) 250 ms (value of constant kMaxTimeupdateEventFrequency). Let's consider now the scenario, where: 1. At 0ms time position we trigger `timeupdate` event and schedule next one at 250ms time position 2. At 240ms time position a task X is taken from task runner's queue and execution of it is started 3. Task X finishes at 300ms time position (or later), since task runners cannot interrupt running tasks, we had to wait for task X to finish. 4. Delayed post-task which schedules `timeupdate` event is executed now and triggers `timeupdate` event at 300ms time position (or later). This clearly shows, that on slower devices/platforms `timeupdate` event can be fired much later then it should be. Did this work before? No Is it a problem with Flash or HTML5? HTML5 Does this work in other browsers? N/A Chrome version: 66.0.3359.117 Channel: stable OS Version: Ubuntu 16.04 Flash Version: Contents of chrome://gpu: Graphics Feature Status Canvas: Hardware accelerated CheckerImaging: Disabled Flash: Hardware accelerated Flash Stage3D: Hardware accelerated Flash Stage3D Baseline profile: Hardware accelerated Compositing: Hardware accelerated Multiple Raster Threads: Enabled Native GpuMemoryBuffers: Software only. Hardware acceleration disabled Rasterization: Software only. Hardware acceleration disabled Surface Synchronization: Enabled Video Decode: Unavailable WebGL: Hardware accelerated WebGL2: Hardware accelerated Driver Bug Workarounds adjust_src_dst_region_for_blitframebuffer clear_uniforms_before_first_program_use count_all_in_varyings_packing decode_encode_srgb_for_generatemipmap disable_framebuffer_cmaa disable_post_sub_buffers_for_onscreen_surfaces disable_software_to_accelerated_canvas_upgrade dont_remove_invariant_for_fragment_input force_cube_map_positive_x_allocation force_int_or_srgb_cube_texture_complete init_texture_max_anisotropy regenerate_struct_names remove_invariant_and_centroid_for_essl3 scalarize_vec_and_mat_constructor_args Problems Detected Accelerated video decode is unavailable on Linux: 137247 Disabled Features: accelerated_video_decode Clear uniforms before first program use on all platforms: 124764, 349137 Applied Workarounds: clear_uniforms_before_first_program_use Mesa drivers in Linux handle varyings without static use incorrectly: 333885 Applied Workarounds: count_all_in_varyings_packing Linux AMD drivers incorrectly return initial value of 1 for TEXTURE_MAX_ANISOTROPY: 348237 Applied Workarounds: init_texture_max_anisotropy Always rewrite vec/mat constructors to be consistent: 398694 Applied Workarounds: scalarize_vec_and_mat_constructor_args Linux AMD drivers handle struct scopes incorrectly: 403957 Applied Workarounds: regenerate_struct_names Linux ATI drivers crash on binding incomplete cube map texture to FBO: 518889 Applied Workarounds: force_cube_map_positive_x_allocation Use GL_INTEL_framebuffer_CMAA on ChromeOS: 535198 Applied Workarounds: disable_framebuffer_cmaa Disable partial swaps on Mesa drivers (detected with GL_VERSION): 339493 Applied Workarounds: disable_post_sub_buffers_for_onscreen_surfaces Decode and encode before generateMipmap for srgb format textures on os except macosx: 634519 Applied Workarounds: decode_encode_srgb_for_generatemipmap adjust src/dst region if blitting pixels outside read framebuffer on Linux AMD: 664740 Applied Workarounds: adjust_src_dst_region_for_blitframebuffer AMD drivers in Linux require invariant qualifier to match between vertex and fragment shaders: 659326, 639760 Applied Workarounds: remove_invariant_and_centroid_for_essl3, dont_remove_invariant_for_fragment_input Disable KHR_blend_equation_advanced until cc shaders are updated: 661715 Applied Workarounds: disable(GL_KHR_blend_equation_advanced), disable(GL_KHR_blend_equation_advanced_coherent) Decode and Encode before generateMipmap for srgb format textures on Linux AMD: 634519 Applied Workarounds: decode_encode_srgb_for_generatemipmap Software to Accelerated canvas update breaks Linux AMD: 710029 Applied Workarounds: disable_software_to_accelerated_canvas_upgrade Force integer or srgb cube map texture complete on Linux AMD: 712117 Applied Workarounds: force_int_or_srgb_cube_texture_complete Don't expose disjoint_timer_query extensions to WebGL: 808744 Native GpuMemoryBuffers have been disabled, either via about:flags or command line. Disabled Features: native_gpu_memory_buffers Checker-imaging has been disabled via finch trial or the command line. Disabled Features: checker_imaging Version Information Data exported 2018-04-26T11:58:43.463Z Chrome version Chrome/66.0.3359.117 Operating system Linux 4.13.0-39-generic Software rendering list URL https://chromium.googlesource.com/chromium/src/+/7f59c28e25283df88e0c6ac8d8b2551d8c6ad93b/gpu/config/software_rendering_list.json Driver bug list URL https://chromium.googlesource.com/chromium/src/+/7f59c28e25283df88e0c6ac8d8b2551d8c6ad93b/gpu/config/gpu_driver_bug_list.json ANGLE commit id 22c768fbda54 2D graphics backend Skia/66 773868fdade5f9f0e7697e6d09c9bd80aaa9b402- Command Line /usr/bin/google-chrome-stable --flag-switches-begin --flag-switches-end Driver Information Initialization time 39 In-process GPU false Passthrough Command Decoder false Direct Composition false Supports overlays false Sandboxed false GPU0 VENDOR = 0x1002, DEVICE= 0x6610 *ACTIVE* Optimus false Optimus false AMD switchable false Driver vendor Mesa Driver version 17.2.8 Driver date Pixel shader version 1.30 Vertex shader version 1.30 Max. MSAA samples 8 Machine model name Machine model version GL_VENDOR X.Org GL_RENDERER AMD OLAND (DRM 2.50.0 / 4.13.0-39-generic, LLVM 5.0.0) GL_VERSION 3.0 Mesa 17.2.8 GL_EXTENSIONS GL_AMD_conservative_depth GL_AMD_draw_buffers_blend GL_AMD_performance_monitor GL_AMD_pinned_memory GL_AMD_seamless_cubemap_per_texture GL_AMD_shader_stencil_export GL_AMD_shader_trinary_minmax GL_ANGLE_texture_compression_dxt3 GL_ANGLE_texture_compression_dxt5 GL_APPLE_packed_pixels GL_ARB_ES2_compatibility GL_ARB_ES3_compatibility GL_ARB_arrays_of_arrays GL_ARB_base_instance GL_ARB_bindless_texture GL_ARB_blend_func_extended GL_ARB_buffer_storage GL_ARB_clear_buffer_object GL_ARB_clear_texture GL_ARB_clip_control GL_ARB_color_buffer_float GL_ARB_compressed_texture_pixel_storage GL_ARB_compute_shader GL_ARB_compute_variable_group_size GL_ARB_conditional_render_inverted GL_ARB_conservative_depth GL_ARB_copy_buffer GL_ARB_copy_image GL_ARB_cull_distance GL_ARB_debug_output GL_ARB_depth_buffer_float GL_ARB_depth_clamp GL_ARB_depth_texture GL_ARB_derivative_control GL_ARB_draw_buffers GL_ARB_draw_buffers_blend GL_ARB_draw_elements_base_vertex GL_ARB_draw_instanced GL_ARB_explicit_attrib_location GL_ARB_explicit_uniform_location GL_ARB_fragment_coord_conventions GL_ARB_fragment_program GL_ARB_fragment_program_shadow GL_ARB_fragment_shader GL_ARB_framebuffer_no_attachments GL_ARB_framebuffer_object GL_ARB_framebuffer_sRGB GL_ARB_get_program_binary GL_ARB_get_texture_sub_image GL_ARB_half_float_pixel GL_ARB_half_float_vertex GL_ARB_instanced_arrays GL_ARB_internalformat_query GL_ARB_internalformat_query2 GL_ARB_invalidate_subdata GL_ARB_map_buffer_alignment GL_ARB_map_buffer_range GL_ARB_multi_bind GL_ARB_multisample GL_ARB_multitexture GL_ARB_occlusion_query GL_ARB_occlusion_query2 GL_ARB_pipeline_statistics_query GL_ARB_pixel_buffer_object GL_ARB_point_parameters GL_ARB_point_sprite GL_ARB_program_interface_query GL_ARB_provoking_vertex GL_ARB_query_buffer_object GL_ARB_robust_buffer_access_behavior GL_ARB_robustness GL_ARB_sample_shading GL_ARB_sampler_objects GL_ARB_seamless_cube_map GL_ARB_seamless_cubemap_per_texture GL_ARB_separate_shader_objects GL_ARB_shader_atomic_counter_ops GL_ARB_shader_atomic_counters GL_ARB_shader_ballot GL_ARB_shader_bit_encoding GL_ARB_shader_clock GL_ARB_shader_group_vote GL_ARB_shader_image_load_store GL_ARB_shader_image_size GL_ARB_shader_objects GL_ARB_shader_precision GL_ARB_shader_stencil_export GL_ARB_shader_storage_buffer_object GL_ARB_shader_texture_image_samples GL_ARB_shader_texture_lod GL_ARB_shading_language_100 GL_ARB_shading_language_420pack GL_ARB_shading_language_packing GL_ARB_shadow GL_ARB_stencil_texturing GL_ARB_sync GL_ARB_texture_barrier GL_ARB_texture_border_clamp GL_ARB_texture_compression GL_ARB_texture_compression_bptc GL_ARB_texture_compression_rgtc GL_ARB_texture_cube_map GL_ARB_texture_cube_map_array 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_gather GL_ARB_texture_mirror_clamp_to_edge GL_ARB_texture_mirrored_repeat GL_ARB_texture_multisample GL_ARB_texture_non_power_of_two GL_ARB_texture_query_levels GL_ARB_texture_query_lod GL_ARB_texture_rectangle GL_ARB_texture_rg GL_ARB_texture_rgb10_a2ui GL_ARB_texture_stencil8 GL_ARB_texture_storage GL_ARB_texture_storage_multisample GL_ARB_texture_swizzle GL_ARB_texture_view GL_ARB_timer_query GL_ARB_transform_feedback2 GL_ARB_transform_feedback3 GL_ARB_transform_feedback_instanced GL_ARB_transpose_matrix GL_ARB_uniform_buffer_object GL_ARB_vertex_array_bgra GL_ARB_vertex_array_object GL_ARB_vertex_attrib_binding GL_ARB_vertex_buffer_object GL_ARB_vertex_program GL_ARB_vertex_shader GL_ARB_vertex_type_10f_11f_11f_rev GL_ARB_vertex_type_2_10_10_10_rev GL_ARB_window_pos GL_ATI_blend_equation_separate GL_ATI_draw_buffers GL_ATI_fragment_shader GL_ATI_meminfo GL_ATI_separate_stencil GL_ATI_texture_compression_3dc GL_ATI_texture_env_combine3 GL_ATI_texture_float GL_ATI_texture_mirror_once GL_EXT_abgr GL_EXT_bgra GL_EXT_blend_color GL_EXT_blend_equation_separate GL_EXT_blend_func_separate GL_EXT_blend_minmax GL_EXT_blend_subtract GL_EXT_compiled_vertex_array GL_EXT_copy_texture GL_EXT_depth_bounds_test GL_EXT_draw_buffers2 GL_EXT_draw_instanced 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_gpu_program_parameters GL_EXT_multi_draw_arrays GL_EXT_packed_depth_stencil GL_EXT_packed_float GL_EXT_packed_pixels GL_EXT_pixel_buffer_object GL_EXT_point_parameters GL_EXT_polygon_offset GL_EXT_polygon_offset_clamp GL_EXT_provoking_vertex GL_EXT_rescale_normal GL_EXT_secondary_color GL_EXT_separate_specular_color GL_EXT_shader_integer_mix GL_EXT_shadow_funcs GL_EXT_stencil_two_side GL_EXT_stencil_wrap GL_EXT_subtexture GL_EXT_texture GL_EXT_texture3D GL_EXT_texture_array GL_EXT_texture_compression_dxt1 GL_EXT_texture_compression_latc GL_EXT_texture_compression_rgtc GL_EXT_texture_compression_s3tc GL_EXT_texture_cube_map GL_EXT_texture_edge_clamp GL_EXT_texture_env_add GL_EXT_texture_env_combine GL_EXT_texture_env_dot3 GL_EXT_texture_filter_anisotropic GL_EXT_texture_integer GL_EXT_texture_lod_bias GL_EXT_texture_mirror_clamp GL_EXT_texture_object GL_EXT_texture_rectangle GL_EXT_texture_sRGB GL_EXT_texture_sRGB_decode GL_EXT_texture_shared_exponent GL_EXT_texture_snorm GL_EXT_texture_swizzle GL_EXT_timer_query GL_EXT_transform_feedback GL_EXT_vertex_array GL_EXT_vertex_array_bgra GL_IBM_multimode_draw_arrays GL_IBM_rasterpos_clip GL_IBM_texture_mirrored_repeat GL_INGR_blend_func_separate GL_KHR_context_flush_control GL_KHR_debug GL_KHR_no_error GL_KHR_robust_buffer_access_behavior GL_KHR_robustness GL_MESA_pack_invert GL_MESA_shader_integer_functions GL_MESA_texture_signed_rgba GL_MESA_window_pos GL_NVX_gpu_memory_info GL_NV_blend_square GL_NV_conditional_render GL_NV_depth_clamp GL_NV_fog_distance GL_NV_light_max_exponent GL_NV_packed_depth_stencil GL_NV_primitive_restart GL_NV_texgen_reflection GL_NV_texture_barrier GL_NV_texture_env_combine4 GL_NV_texture_rectangle GL_NV_vdpau_interop GL_OES_EGL_image GL_OES_read_format GL_S3_s3tc GL_SGIS_generate_mipmap GL_SGIS_texture_border_clamp GL_SGIS_texture_edge_clamp GL_SGIS_texture_lod GL_SUN_multi_draw_arrays Disabled Extensions GL_KHR_blend_equation_advanced GL_KHR_blend_equation_advanced_coherent Disabled WebGL Extensions EXT_disjoint_timer_query EXT_disjoint_timer_query_webgl2 Window system binding vendor SGI Window system binding version 1.4 Window system binding extensions GLX_ARB_create_context GLX_ARB_create_context_profile GLX_ARB_create_context_robustness GLX_ARB_fbconfig_float GLX_ARB_framebuffer_sRGB GLX_ARB_multisample GLX_EXT_create_context_es_profile GLX_EXT_create_context_es2_profile GLX_EXT_fbconfig_packed_float GLX_EXT_framebuffer_sRGB GLX_EXT_import_context GLX_EXT_libglvnd GLX_EXT_texture_from_pixmap GLX_EXT_visual_info GLX_EXT_visual_rating GLX_MESA_copy_sub_buffer GLX_OML_swap_method GLX_SGI_make_current_read GLX_SGI_swap_control GLX_SGIS_multisample GLX_SGIX_fbconfig GLX_SGIX_pbuffer GLX_SGIX_visual_select_group GLX_INTEL_swap_event Window manager Compiz XDG_CURRENT_DESKTOP Unity GDMSESSION ubuntu Compositing manager Yes Direct rendering Yes Reset notification strategy 0x8261 GPU process crash count 0 System visual ID 33 RGBA visual ID 114 Compositor Information Tile Update Mode One-copy Partial Raster Enabled GpuMemoryBuffers Status ATC Software only ATCIA Software only DXT1 Software only DXT5 Software only ETC1 Software only R_8 Software only R_16 Software only RG_88 Software only BGR_565 Software only RGBA_4444 Software only RGBX_8888 Software only RGBA_8888 Software only BGRX_8888 Software only BGRX_1010102 Software only RGBX_1010102 Software only BGRA_8888 Software only RGBA_F16 Software only YVU_420 Software only YUV_420_BIPLANAR Software only UYVY_422 Software only Display(s) Information Info Display[8564183066946816] bounds=0,0 1920x1080, workarea=57,24 1863x1056, scale=1, external Color space information {primaries:[[0.3590,0.4464,0.1589,],[0.1959,0.7428,0.0612,],[0.0097,0.0435,0.7717,],], transfer:0.0000*x + 0.0000 if x < 0.0000 else (1.0000*x + 0.0000)**2.2000 + 0.0000, matrix:RGB, range:FULL} Bits per color component 8 Bits per pixel 24 Info Display[8564183066946817] bounds=1920,0 1920x1080, workarea=1920,0 1920x1080, scale=1, external Color space information {primaries:[[0.3590,0.4464,0.1589,],[0.1959,0.7428,0.0612,],[0.0097,0.0435,0.7717,],], transfer:0.0000*x + 0.0000 if x < 0.0000 else (1.0000*x + 0.0000)**2.2000 + 0.0000, matrix:RGB, range:FULL} Bits per color component 8 Bits per pixel 24 Video Acceleration Information Log Messages [2546:2546:0426/092802.155153:ERROR:sandbox_linux.cc(379)] : InitializeSandbox() called with multiple threads in process gpu-process. There are many ways in which this can be fixed. Some that I though of right now are: * reduce the value of kMaxTimeupdateEventFrequency and fire it more often (giving some possibility to make it in allowed range when slightly delayed) (ugly and bad, so I wouldn't recommend it) * refactor it to run these schedules on separate task runner/thread which won't be blocked by heavy tasks to avoid long delays
,
Apr 26 2018
,
Apr 27 2018
Thanks for filing. I understand the issue. 'timeupdate' is mostly used for players to update their seek bar / current time UI. Is that your use case? UIs are important, but I haven't seen a case where a UI is super sensitive to this timing (e.g. such that 4 hz would be ok, but 3.5 hz would be bad). Raising this event and the triggered UI updates have a performance cost, so we try to stay at the very edge of the upper bound to minimize that. My recent change increased timeupdate frequency very slightly, and even this was enough to trigger performance regression alerts (see Issue 817135 ). All this to say, perhaps this is working as intended. If your system is super burdened such that the event scheduling is held up, you probably don't want us adding even more to that burden by strictly enforcing 'timeupdate' fires <= 4hz for the sake of updating a video player UI. The task runner for this timer is currently TaskType::kUnthrottled, meaning the scheduler will do its best to make things happen on time. Sorry I didn't see your post on the earlier bug. I forgot to mark myself owner when I 'fixed' it, so didn't get the notification.
,
May 1 2018
,
May 7 2018
chcunningham@chromium.org Thanks for detailed response. While I agree with your points, I would like to point that the problem is about being conformant to HTML5 specification, even though this requirement (at least in my mind) seems a bit too restrictive (in my mind, it should mandate to try to queue this event within 250ms range, but also allow longer intervals when system is under heavy load). I also know of at least one application/ecosystem that requires from users/implementers to stay within this this [15ms, 250ms] time window - YouTube. In YouTube 2018's QUAL test suite there are tests that verify that `timeupdate` events are sent within correct range (with some small margin not to throw false-positives when missed by couple milliseconds): http://yt-media-test.appspot.com/2018.html?test_type=progressive-test As you can see, a big service like YouTube can require that this condition is met according to specification, so any browser that wants to conform to HTML5 specification should make sure that it's doing everything (sane) to met this requirement. Also the way it is designed now, it can start failing randomly when one rare task that happens to execute for long time is started right before that time point. In that case it will be very hard to debug anything and find why does this happen. And this is exactly what I'm seeing. It's not like it fails all the time, but once per couple seconds, depending on current tasks. I do think that setting smaller timeout/time interval for firing this event is sane solution and I don't propose to do this (as it will most likely introduce noticable performance regressions). However, I think that there is a sane solution (although probably not that easy to implement right away) that will not slow down Chromium. I think that time-ciritcal operations should be execute in separate thread/task runner. All these tasks should be small and not block thread for too long to allow other tasks to execute without noticeable delay. Since I'm not that familiar with whole BLINK, I wasn't able to asses how much work would be needed to implement that, but I think that with time Chromium should do something like that either way, so it doesn't depend on currently running tasks to do something "correct". What do you think about such solution?
,
May 7 2018
> http://yt-media-test.appspot.com/2018.html?test_type=progressive-test To your point, chrome may fail a test here if run under extreme system load (just theorizing, haven't observed it). But in the average case I expect we pass these tests without issue. I can't speak for YT, but I'd expect they focus on the average case to certify a device. > Also the way it is designed now, it can start failing randomly when one rare task that happens to execute for long time is started right before that time point. I'm not sure whether you mean an internal chrome task or a task chrome is running on behalf of javascript (e.g. some long loop). Chrome should not hog the main thread (exceptions under extreme load) - we'd be happy to have a bug filed (and see improvements below). But if a site is scheduling a lot of long running tasks while trying to do media playback, that's a bug on them. > I think that time-ciritcal operations should be execute in separate thread/task runner. All these tasks should be small and not block thread for too long to allow other tasks to execute without noticeable delay. FWIW, I think this is already what's implemented, but the scheduling team is constantly improving it. 'timeupdate' scheduling is coordinated between HTMLMediaElement::playback_progress_timer_ [0] and MediaElementEventQueue::timer_ [1]. These use task types kUnthrottled and kMediaElementEvent - both are essentially the highest priority. We (media team) always advocate that media events be treated that way because apps rely on timely notifications to keep the data buffered and avoid playback stalls. Right now the unthrottled task types are used too often. The scheduling team is actively working [2] on defining more granular task types and moving lower priority things off that scheduler queue, meaning better priority scheduling down the road. [0] https://cs.chromium.org/chromium/src/third_party/blink/renderer/core/html/media/html_media_element.cc?rcl=158ac70fe7e8f46635a2cc38b265d1832acae35a&l=454 [1] https://cs.chromium.org/chromium/src/third_party/blink/renderer/core/dom/events/media_element_event_queue.cc?rcl=158ac70fe7e8f46635a2cc38b265d1832acae35a&l=44 [2] https://docs.google.com/document/d/1k7EEHQUEujgQ7BAhbmNdeaddwfJPWp7qjLy8mnVTQ9Y/edit#heading=h.v2zo2j7te1qj
,
May 8 2018
The NextAction date has arrived: 2018-05-08
,
May 9 2018
,
May 16 2018
The NextAction date has arrived: 2018-05-16
,
May 16 2018
Outside of general scheduling improvements, no action items are identified for timeupdate. Closing, "Working as intended". Feel free to re-open if new ideas for improvements come up. |
|||||||||||||||||||||
►
Sign in to add a comment |
|||||||||||||||||||||
Comment 1 by ddy...@vewd.com
, Apr 26 2018