shell_surface_presentation_time_recorder.cc 6.1 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185
  1. // Copyright 2022 The Chromium Authors. All rights reserved.
  2. // Use of this source code is governed by a BSD-style license that can be
  3. // found in the LICENSE file.
  4. #include "components/exo/shell_surface_presentation_time_recorder.h"
  5. #include <cstdint>
  6. #include <memory>
  7. #include "base/bind.h"
  8. #include "base/logging.h"
  9. #include "base/metrics/histogram.h"
  10. #include "base/time/time.h"
  11. #include "base/trace_event/typed_macros.h"
  12. #include "components/exo/shell_surface.h"
  13. #include "components/exo/shell_surface_util.h"
  14. #include "components/exo/surface.h"
  15. #include "third_party/perfetto/include/perfetto/tracing/track.h"
  16. #include "ui/gfx/presentation_feedback.h"
  17. namespace exo {
  18. namespace {
  19. constexpr char kTraceCategory[] = "benchmark,ui";
  20. base::HistogramBase* CreateTimesHistogram(const char* name) {
  21. return base::Histogram::FactoryTimeGet(
  22. name, base::Milliseconds(1), base::Milliseconds(200), 50,
  23. base::HistogramBase::kUmaTargetedHistogramFlag);
  24. }
  25. // HistogramReporter reports latency and optional max latency as UMA histograms.
  26. class HistogramReporter
  27. : public ShellSurfacePresentationTimeRecorder::Reporter {
  28. public:
  29. HistogramReporter(const char* latency_histogram_name,
  30. absl::optional<const char*> max_latency_histogram_name)
  31. : latency_histogram_(CreateTimesHistogram(latency_histogram_name)),
  32. max_latency_histogram_name_(max_latency_histogram_name) {}
  33. HistogramReporter(const HistogramReporter&) = delete;
  34. HistogramReporter& operator=(const HistogramReporter&) = delete;
  35. ~HistogramReporter() override {
  36. if (max_latency_histogram_name_.has_value()) {
  37. CreateTimesHistogram(max_latency_histogram_name_.value())
  38. ->AddTimeMillisecondsGranularity(max_latency_);
  39. }
  40. }
  41. // PresentationTimeRecorder::Reporter
  42. void ReportTime(base::TimeDelta delta) override {
  43. latency_histogram_->AddTimeMillisecondsGranularity(delta);
  44. if (max_latency_histogram_name_.has_value() && delta > max_latency_) {
  45. max_latency_ = delta;
  46. }
  47. }
  48. private:
  49. base::HistogramBase* const latency_histogram_;
  50. const absl::optional<const char*> max_latency_histogram_name_;
  51. base::TimeDelta max_latency_;
  52. };
  53. } // namespace
  54. // static
  55. std::unique_ptr<ShellSurfacePresentationTimeRecorder::Reporter>
  56. ShellSurfacePresentationTimeRecorder::CreateHistogramReporter(
  57. const char* latency_histogram_name,
  58. absl::optional<const char*> max_latency_histogram_name) {
  59. return std::make_unique<HistogramReporter>(latency_histogram_name,
  60. max_latency_histogram_name);
  61. }
  62. ShellSurfacePresentationTimeRecorder::ShellSurfacePresentationTimeRecorder(
  63. ShellSurface* shell_surface,
  64. std::unique_ptr<Reporter> reporter)
  65. : shell_surface_(shell_surface), reporter_(std::move(reporter)) {
  66. scoped_observation_.Observe(shell_surface_);
  67. }
  68. ShellSurfacePresentationTimeRecorder::~ShellSurfacePresentationTimeRecorder() =
  69. default;
  70. void ShellSurfacePresentationTimeRecorder::PrepareToRecord() {
  71. if (pending_request_.has_value())
  72. return;
  73. pending_request_ = absl::make_optional<Request>();
  74. pending_request_->request_id = next_request_id_++;
  75. }
  76. bool ShellSurfacePresentationTimeRecorder::RequestNext() {
  77. // Underlying ShellSurface must still be alive.
  78. DCHECK(shell_surface_);
  79. // `PrepareToRecord()` must have happened.
  80. DCHECK(pending_request_.has_value());
  81. // Early out if there is a pending request that does not get a Configure.
  82. if (!pending_request_->serial.has_value())
  83. return false;
  84. TRACE_EVENT_BEGIN(kTraceCategory, "ShellSurfacePresentationTimeRecorder",
  85. perfetto::Track(pending_request_->request_id), "serial",
  86. pending_request_->serial.value());
  87. pending_request_->request_time = base::TimeTicks::Now();
  88. requests_.emplace_back(pending_request_.value());
  89. pending_request_.reset();
  90. LOG_IF(WARNING, requests_.size() > 100u)
  91. << "Number of requests waiting for ack has reached: " << requests_.size();
  92. return true;
  93. }
  94. void ShellSurfacePresentationTimeRecorder::OnConfigure(uint32_t serial) {
  95. if (!pending_request_.has_value())
  96. return;
  97. pending_request_->serial = serial;
  98. }
  99. void ShellSurfacePresentationTimeRecorder::OnAcknowledgeConfigure(
  100. uint32_t serial) {
  101. // Must not ack a serial in `pending_request_`. RequestNext() should happen
  102. // to commit the `pending_request_` before the ack.
  103. DCHECK(!pending_request_.has_value() ||
  104. !pending_request_->serial.has_value() ||
  105. serial > pending_request_->serial);
  106. Surface* root_surface = shell_surface_->root_surface();
  107. while (!requests_.empty()) {
  108. Request request = requests_.front();
  109. requests_.pop_front();
  110. root_surface->RequestPresentationCallback(base::BindRepeating(
  111. &ShellSurfacePresentationTimeRecorder::OnFramePresented,
  112. weak_ptr_factory_.GetWeakPtr(), request));
  113. if (request.serial.value() == serial)
  114. break;
  115. }
  116. }
  117. void ShellSurfacePresentationTimeRecorder::OnShellSurfaceDestroyed() {
  118. scoped_observation_.Reset();
  119. }
  120. void ShellSurfacePresentationTimeRecorder::OnFramePresented(
  121. const Request& request,
  122. const gfx::PresentationFeedback& feedback) {
  123. TRACE_EVENT_END(kTraceCategory, perfetto::Track(request.request_id), "flags",
  124. feedback.flags, "serial", request.serial.value());
  125. if (feedback.flags & gfx::PresentationFeedback::kFailure) {
  126. LOG(WARNING) << "PresentationFailed (serial=" << *request.serial << "):"
  127. << ", flags=" << feedback.flags;
  128. return;
  129. }
  130. if (feedback.timestamp.is_null()) {
  131. // TODO(b/165951963): ideally feedback.timestamp should not be null.
  132. // Consider replacing this by DCHECK or CHECK.
  133. LOG(ERROR) << "Invalid feedback timestamp (serial=" << *request.serial
  134. << "):"
  135. << " timestamp is not set";
  136. return;
  137. }
  138. const base::TimeDelta delta = feedback.timestamp - request.request_time;
  139. if (delta.InMilliseconds() < 0) {
  140. LOG(ERROR) << "Invalid timestamp for presentation feedback (serial="
  141. << *request.serial
  142. << "): requested_time=" << request.request_time
  143. << " feedback.timestamp=" << feedback.timestamp;
  144. return;
  145. }
  146. reporter_->ReportTime(delta);
  147. }
  148. } // namespace exo