From 40ed3ff07e1f370c6452789895c77fe5be58e292 Mon Sep 17 00:00:00 2001 From: henrika Date: Tue, 3 Oct 2023 10:35:52 +0200 Subject: [PATCH] Improved event tracing in FrameCadenceAdapter This CL is a minor cleanup of the work done earlier in [1]. We now remove the arguments which contained the measured delta times between two TRACE_EVENT_ASYNC_BEGIN and TRACE_EVENT_ASYNC_END events. Also, the ID for FrameToQueue1 is now unique which was not the case previously. The same information can be obtained from the `slice` table and the `dur` key. Also renames the events to OnFrameToEncode (total), OnFrameToQueue and QueueToEncode to match what it measures better. [1] https://webrtc-review.googlesource.com/c/src/+/322121 Bug: webrtc:15456 Change-Id: Ibe2d7bb53380710671c2c36012dcd573942bae69 Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/322220 Commit-Queue: Henrik Andreassson Reviewed-by: Markus Handell Cr-Commit-Position: refs/heads/main@{#40860} --- video/frame_cadence_adapter.cc | 30 +++++++++++++++--------------- 1 file changed, 15 insertions(+), 15 deletions(-) diff --git a/video/frame_cadence_adapter.cc b/video/frame_cadence_adapter.cc index 918f19a5b1..6d7de566ca 100644 --- a/video/frame_cadence_adapter.cc +++ b/video/frame_cadence_adapter.cc @@ -376,18 +376,18 @@ void ZeroHertzAdapterMode::OnFrame(Timestamp post_time, int frame_id = current_frame_id_; current_frame_id_++; scheduled_repeat_ = absl::nullopt; - Timestamp task_post_time = clock_->CurrentTime(); - TimeDelta time_spent_since_post = task_post_time - post_time; - TRACE_EVENT_ASYNC_BEGIN0(TRACE_DISABLED_BY_DEFAULT("webrtc"), "FrameToQueue2", + TimeDelta time_spent_since_post = clock_->CurrentTime() - post_time; + TRACE_EVENT_ASYNC_BEGIN0(TRACE_DISABLED_BY_DEFAULT("webrtc"), "QueueToEncode", frame_id); queue_->PostDelayedHighPrecisionTask( SafeTask(safety_.flag(), - [this, frame_id, task_post_time] { + [this, frame_id, frame] { RTC_DCHECK_RUN_ON(&sequence_checker_); - TRACE_EVENT_ASYNC_END1( - TRACE_DISABLED_BY_DEFAULT("webrtc"), "FrameToQueue2", - frame_id, "delay_us", - (clock_->CurrentTime() - task_post_time).us()); + TRACE_EVENT_ASYNC_END0(TRACE_DISABLED_BY_DEFAULT("webrtc"), + "QueueToEncode", frame_id); + TRACE_EVENT_ASYNC_END0(TRACE_DISABLED_BY_DEFAULT("webrtc"), + "OnFrameToEncode", + frame.video_frame_buffer().get()); ProcessOnDelayedCadence(); }), std::max(frame_delay_ - time_spent_since_post, TimeDelta::Zero())); @@ -655,17 +655,17 @@ void FrameCadenceAdapterImpl::OnFrame(const VideoFrame& frame) { // Local time in webrtc time base. Timestamp post_time = clock_->CurrentTime(); frames_scheduled_for_processing_.fetch_add(1, std::memory_order_relaxed); - TRACE_EVENT_ASYNC_BEGIN0(TRACE_DISABLED_BY_DEFAULT("webrtc"), "FrameToQueue1", - frame.id()); + TRACE_EVENT_ASYNC_BEGIN0(TRACE_DISABLED_BY_DEFAULT("webrtc"), + "OnFrameToEncode", frame.video_frame_buffer().get()); + TRACE_EVENT_ASYNC_BEGIN0(TRACE_DISABLED_BY_DEFAULT("webrtc"), + "OnFrameToQueue", frame.video_frame_buffer().get()); queue_->PostTask(SafeTask(safety_.flag(), [this, post_time, frame] { RTC_DCHECK_RUN_ON(queue_); - Timestamp current_time = clock_->CurrentTime(); - TRACE_EVENT_ASYNC_END1(TRACE_DISABLED_BY_DEFAULT("webrtc"), "FrameToQueue1", - frame.id(), "delay_us", - (current_time - post_time).us()); + TRACE_EVENT_ASYNC_END0(TRACE_DISABLED_BY_DEFAULT("webrtc"), + "OnFrameToQueue", frame.video_frame_buffer().get()); if (zero_hertz_adapter_created_timestamp_.has_value()) { TimeDelta time_until_first_frame = - current_time - *zero_hertz_adapter_created_timestamp_; + clock_->CurrentTime() - *zero_hertz_adapter_created_timestamp_; zero_hertz_adapter_created_timestamp_ = absl::nullopt; RTC_HISTOGRAM_COUNTS_10000( "WebRTC.Screenshare.ZeroHz.TimeUntilFirstFrameMs",