diff --git a/protos/third_party/chromium/chrome_track_event.proto b/protos/third_party/chromium/chrome_track_event.proto index 503f8341e9..debc1f014b 100644 --- a/protos/third_party/chromium/chrome_track_event.proto +++ b/protos/third_party/chromium/chrome_track_event.proto @@ -1453,10 +1453,36 @@ message ChromeGraphicsPipeline { optional StepName step = 1; optional FrameSinkId frame_sink_id = 2; + // Id used to link `ChromeGraphicsPipeline`s corresponding to work done by a + // Viz client to produce a frame. This corresponds to + // `viz::BeginFrameAck.trace_id`. Covers steps: + // * STEP_ISSUE_BEGIN_FRAME + // * STEP_RECEIVE_BEGIN_FRAME + // * STEP_GENERATE_RENDER_PASS + // * STEP_GENERATE_COMPOSITOR_FRAME + // * STEP_SUBMIT_COMPOSITOR_FRAME + // * STEP_RECEIVE_COMPOSITOR_FRAME + // * STEP_RECEIVE_BEGIN_FRAME_DISCARD + // * STEP_DID_NOT_PRODUCE_FRAME + // * STEP_DID_NOT_PRODUCE_COMPOSITOR_FRAME + optional int64 surface_frame_trace_id = 10; + // Id used to link `ChromeGraphicsPipeline`s corresponding to work done - // on creating and presenting one frame. + // on creating and presenting one frame *after* surface aggregation. Covers + // steps: + // * STEP_DRAW_AND_SWAP + // * STEP_SURFACE_AGGREGATION + // * STEP_SEND_BUFFER_SWAP + // * STEP_BUFFER_SWAP_POST_SUBMIT + // * STEP_FINISH_BUFFER_SWAP + // * STEP_SWAP_BUFFERS_ACK optional int64 display_trace_id = 3; + // `viz::BeginFrameAck.trace_id`s for frames aggregated at this step. + // Used with `STEP_SURFACE_AGGREGATION` only. This can be "joined" with + // `surface_frame_trace_id`. + repeated int64 aggregated_surface_frame_trace_ids = 8; + optional LocalSurfaceId local_surface_id = 4; optional int64 frame_sequence = 5; optional FrameSkippedReason frame_skipped_reason = 6; @@ -1464,10 +1490,6 @@ message ChromeGraphicsPipeline { // Optional variable that can be set together with STEP_BACKEND*. optional int64 backend_frame_id = 7; - // `viz::BeginFrameAck.trace_id`s for frames aggregated at this step. - // Used with `STEP_SURFACE_AGGREGATION` only. - repeated int64 aggregated_frames_ids = 8; - // List of LatencyInfo.trace_ids associated with this frame, which // should allow us to match input to frame production. repeated int64 latency_ids = 9; @@ -1990,6 +2012,15 @@ message MainFramePipeline { optional BeginFrameId last_begin_frame_id_during_first_draw = 5; } +message CurrentTask { + // t1 - t0, where t1 is the start timestamp of this slice and t0 is the start + // timestamp of the task containing this slice. + optional uint64 event_offset_from_task_start_time_us = 1; + + // Timestamp in microseconds of the start of the task containing this slice. + optional uint64 task_start_time_us = 2; +} + message ChromeLatencyInfo2 { optional int64 trace_id = 1; @@ -2238,7 +2269,7 @@ message AndroidChoreographerFrameCallbackData { message ChromeTrackEvent { // Extension range for Chrome: 1000-1999 - // Next ID: 1071 + // Next ID: 1072 extend TrackEvent { optional ChromeAppState chrome_app_state = 1000; @@ -2389,5 +2420,7 @@ message ChromeTrackEvent { optional AndroidChoreographerFrameCallbackData android_choreographer_frame_callback_data = 1070; + + optional CurrentTask current_task = 1071; } } diff --git a/src/trace_processor/perfetto_sql/stdlib/chrome/event_latency.sql b/src/trace_processor/perfetto_sql/stdlib/chrome/event_latency.sql index 8e58912205..62b1d8884c 100644 --- a/src/trace_processor/perfetto_sql/stdlib/chrome/event_latency.sql +++ b/src/trace_processor/perfetto_sql/stdlib/chrome/event_latency.sql @@ -4,6 +4,23 @@ INCLUDE PERFETTO MODULE deprecated.v42.common.slices; +-- Finds the start timestamp for a given slice's descendant with a given name. +-- If there are multiple descendants with a given name, the function will return +-- the first one, so it's most useful when working with a timeline broken down +-- into phases, where each subphase can happen only once. +CREATE PERFETTO FUNCTION _descendant_slice_begin( + -- Id of the parent slice. + parent_id INT, + -- Name of the child with the desired start TS. + child_name STRING +) +-- Start timestamp of the child or NULL if it doesn't exist. +RETURNS INT AS +SELECT s.ts +FROM descendant_slice($parent_id) s +WHERE s.name GLOB $child_name +LIMIT 1; + -- Finds the end timestamp for a given slice's descendant with a given name. -- If there are multiple descendants with a given name, the function will return -- the first one, so it's most useful when working with a timeline broken down @@ -59,7 +76,24 @@ CREATE PERFETTO TABLE chrome_event_latencies( -- EventLatency event type. event_type STRING, -- Perfetto track this slice is found on. - track_id INT + track_id INT, + -- Vsync interval (in milliseconds). + vsync_interval_ms DOUBLE, + -- Whether the corresponding frame is janky. + is_janky_scrolled_frame BOOL, + -- Timestamp of the BufferAvailableToBufferReady substage. + buffer_available_timestamp INT, + -- Timestamp of the BufferReadyToLatch substage. + buffer_ready_timestamp INT, + -- Timestamp of the LatchToSwapEnd substage. + latch_timestamp INT, + -- Timestamp of the SwapEndToPresentationCompositorFrame substage. + swap_end_timestamp INT, + -- Frame presentation timestamp aka the timestamp of the + -- SwapEndToPresentationCompositorFrame substage. + -- TODO(b/341047059): temporarily use LatchToSwapEnd as a workaround if + -- SwapEndToPresentationCompositorFrame is missing due to b/247542163. + presentation_timestamp INT ) AS SELECT slice.id, @@ -70,9 +104,21 @@ SELECT has_descendant_slice_with_name( slice.id, 'SubmitCompositorFrameToPresentationCompositorFrame') - AS is_presented, + AS is_presented, EXTRACT_ARG(arg_set_id, 'event_latency.event_type') AS event_type, - slice.track_id + slice.track_id, + EXTRACT_ARG(arg_set_id, 'event_latency.vsync_interval_ms') + AS vsync_interval_ms, + COALESCE(EXTRACT_ARG(arg_set_id, 'event_latency.is_janky_scrolled_frame'), 0) + AS is_janky_scrolled_frame, + _descendant_slice_begin(slice.id, 'BufferAvailableToBufferReady') + AS buffer_available_timestamp, + _descendant_slice_begin(slice.id, 'BufferReadyToLatch') + AS buffer_ready_timestamp, + _descendant_slice_begin(slice.id, 'LatchToSwapEnd') AS latch_timestamp, + _descendant_slice_begin(slice.id, 'SwapEndToPresentationCompositorFrame') + AS swap_end_timestamp, + _get_presentation_timestamp(slice.id) AS presentation_timestamp FROM slice WHERE name = 'EventLatency'; diff --git a/test/trace_processor/diff_tests/stdlib/chrome/tests_scroll_jank.py b/test/trace_processor/diff_tests/stdlib/chrome/tests_scroll_jank.py index fcb98a79dc..6281564201 100755 --- a/test/trace_processor/diff_tests/stdlib/chrome/tests_scroll_jank.py +++ b/test/trace_processor/diff_tests/stdlib/chrome/tests_scroll_jank.py @@ -307,3 +307,48 @@ def test_chrome_scroll_jank_with_pinches(self): "BrowserMainToRendererCompositor","[NULL]",22.250000,50230,"GESTURE_SCROLL_UPDATE" "SubmitCompositorFrameToPresentationCompositorFrame","BufferReadyToLatch",22.267000,50517,"GESTURE_SCROLL_UPDATE" """)) + + def test_chrome_event_latencies(self): + return DiffTestBlueprint( + trace=DataPath('chrome_input_with_frame_view_new.pftrace'), + query=""" + INCLUDE PERFETTO MODULE chrome.event_latency; + + SELECT + id, + name, + ts, + dur, + scroll_update_id, + is_presented, + event_type, + track_id, + vsync_interval_ms, + is_janky_scrolled_frame, + buffer_available_timestamp, + buffer_ready_timestamp, + latch_timestamp, + swap_end_timestamp, + presentation_timestamp + FROM chrome_event_latencies + WHERE + ( + event_type = 'GESTURE_SCROLL_UPDATE' + OR event_type = 'INERTIAL_GESTURE_SCROLL_UPDATE') + AND is_presented + ORDER BY id + LIMIT 10; + """, + out=Csv(""" + "id","name","ts","dur","scroll_update_id","is_presented","event_type","track_id","vsync_interval_ms","is_janky_scrolled_frame","buffer_available_timestamp","buffer_ready_timestamp","latch_timestamp","swap_end_timestamp","presentation_timestamp" + 69,"EventLatency",4488833086777189,49497000,10,1,"GESTURE_SCROLL_UPDATE",14,11.111000,0,4488833114547189,4488833114874189,4488833119872189,4488833126765189,4488833136274189 + 431,"EventLatency",4488833114107189,33292000,14,1,"INERTIAL_GESTURE_SCROLL_UPDATE",27,11.111000,0,"[NULL]",4488833122361189,4488833137159189,4488833138924189,4488833147399189 + 480,"EventLatency",4488833125213189,33267000,15,1,"INERTIAL_GESTURE_SCROLL_UPDATE",29,11.111000,0,4488833131905189,4488833132275189,4488833148524189,4488833150809189,4488833158480189 + 531,"EventLatency",4488833142387189,27234000,16,1,"INERTIAL_GESTURE_SCROLL_UPDATE",32,11.111000,0,4488833147322189,4488833147657189,4488833159447189,4488833161654189,4488833169621189 + 581,"EventLatency",4488833153584189,27225000,17,1,"INERTIAL_GESTURE_SCROLL_UPDATE",34,11.111000,0,4488833158111189,4488833158333189,4488833170433189,4488833171562189,4488833180809189 + 630,"EventLatency",4488833164707189,27227000,18,1,"INERTIAL_GESTURE_SCROLL_UPDATE",36,11.111000,0,4488833169215189,4488833169529189,4488833181700189,4488833183880189,4488833191934189 + 679,"EventLatency",4488833175814189,27113000,19,1,"INERTIAL_GESTURE_SCROLL_UPDATE",38,11.111000,0,4488833180589189,4488833180876189,4488833192722189,4488833194160189,4488833202927189 + 728,"EventLatency",4488833186929189,38217000,20,1,"INERTIAL_GESTURE_SCROLL_UPDATE",40,11.111000,1,4488833201398189,4488833201459189,4488833215357189,4488833217727189,4488833225146189 + 772,"EventLatency",4488833198068189,38185000,21,1,"INERTIAL_GESTURE_SCROLL_UPDATE",42,11.111000,0,4488833211744189,4488833212097189,4488833226028189,4488833227246189,4488833236253189 + 819,"EventLatency",4488833209202189,38170000,22,1,"INERTIAL_GESTURE_SCROLL_UPDATE",43,11.111000,0,4488833223115189,4488833223308189,4488833237115189,4488833238196189,4488833247372189 + """))