WebXR: add "xr.debug" DISABLED_BY_DEFAULT traces

Add a new DISABLED_BY_DEFAULT trace category "xr.debug", and use
that for some timing traces that are useful when debugging scheduling
issues but a bit verbose otherwise.

Change-Id: Id72c0b6c8f7a7fab2e7428adcffa095915a61f54
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2468277
Commit-Queue: Klaus Weidner <klausw@chromium.org>
Reviewed-by: Piotr Bialecki <bialpio@chromium.org>
Reviewed-by: Sami Kyöstilä <skyostil@chromium.org>
Cr-Commit-Position: refs/heads/master@{#816740}

base/trace_event/builtin_categories.h

@@ -254,7 +254,8 @@
   X(TRACE_DISABLED_BY_DEFAULT("viz.triangles"))                          \
   X(TRACE_DISABLED_BY_DEFAULT("webaudio.audionode"))                     \
   X(TRACE_DISABLED_BY_DEFAULT("webrtc"))                                 \
-  X(TRACE_DISABLED_BY_DEFAULT("worker.scheduler"))
+  X(TRACE_DISABLED_BY_DEFAULT("worker.scheduler"))                       \
+  X(TRACE_DISABLED_BY_DEFAULT("xr.debug"))
 
 #define INTERNAL_TRACE_INIT_CATEGORY_NAME(name) name,
 

device/vr/android/arcore/arcore_gl.cc

@@ -396,8 +396,8 @@ void ArCoreGl::GetFrameData(
   base::TimeDelta frame_timestamp = arcore_->GetFrameTimestamp();
   if (!last_arcore_frame_timestamp_.is_zero()) {
     base::TimeDelta delta = frame_timestamp - last_arcore_frame_timestamp_;
-    TRACE_COUNTER1("xr", "ARCore camera frame interval (ms)",
-                   delta.InMilliseconds());
+    TRACE_COUNTER1(TRACE_DISABLED_BY_DEFAULT("xr.debug"),
+                   "ARCore camera frame interval (ms)", delta.InMilliseconds());
   }
   last_arcore_frame_timestamp_ = frame_timestamp;
 
@@ -560,6 +560,8 @@ base::TimeDelta ArCoreGl::WaitTimeForArCoreUpdate() {
   base::TimeTicks now = base::TimeTicks::Now();
   base::TimeDelta wait =
       next_update - now - kScheduleFrametimeMarginForUpdate * frametime;
+  TRACE_COUNTER1(TRACE_DISABLED_BY_DEFAULT("xr.debug"),
+                 "GetFrameData update wait (ms)", wait.InMilliseconds());
   return wait;
 }
 
@@ -582,12 +584,24 @@ base::TimeDelta ArCoreGl::WaitTimeForRenderCompletion() {
   base::TimeTicks now = base::TimeTicks::Now();
   base::TimeDelta render_wait = expected_render_complete - now - render_margin;
 
+  TRACE_COUNTER1(TRACE_DISABLED_BY_DEFAULT("xr.debug"),
+                 "GetFrameData render wait (ms)", render_wait.InMilliseconds());
   // Once the next frame starts animating, we won't be able to finish processing
   // it until the current frame finishes rendering. If rendering is slower than
   // the animating (JS processing) time, increase the delay to compensate.
   if (avg_animate < avg_render) {
     render_wait += avg_render - avg_animate;
   }
+  TRACE_COUNTER1(TRACE_DISABLED_BY_DEFAULT("xr.debug"),
+                 "GetFrameData adjusted render wait (ms)",
+                 render_wait.InMilliseconds());
+  TRACE_COUNTER1(TRACE_DISABLED_BY_DEFAULT("xr.debug"),
+                 "Avg animating time (ms)", avg_animate.InMilliseconds());
+  TRACE_COUNTER1(TRACE_DISABLED_BY_DEFAULT("xr.debug"),
+                 "Avg processing time (ms)",
+                 average_process_time_.GetAverage().InMilliseconds());
+  TRACE_COUNTER1(TRACE_DISABLED_BY_DEFAULT("xr.debug"),
+                 "Avg rendering time (ms)", avg_render.InMilliseconds());
   return render_wait;
 }