vm_tools: Add temporary logging to track startup time in tast.

Sommelier is one of the startup tasks that is often slow in tast tests resulting in timeouts. Adding logs so that we can see the timestamps at which certain steps happen. BUG=b:303549040 TEST=none Change-Id: I93da1e1af8438e30a148943b08fdec7907685257 Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/platform2/+/4951557 Reviewed-by: Chloe Pelling <[email protected]> Tested-by: Lucy Qu <[email protected]> Commit-Queue: Lucy Qu <[email protected]>
WhatAmISupposedToPutHere · Oct 20, 2023 · a502ad7 · a502ad7
1 parent 2a9193c
commit a502ad7
Show file tree

Hide file tree

Showing 5 changed files with 147 additions and 74 deletions.
diff --git a/BUILD.gn b/BUILD.gn
@@ -117,6 +117,7 @@ static_library("libsommelier") {
     "sommelier-output.cc",
     "sommelier-pointer-constraints.cc",
     "sommelier-relative-pointer-manager.cc",
+    "sommelier-scope-timer.cc",
     "sommelier-seat.cc",
     "sommelier-shell.cc",
     "sommelier-stylus-tablet.cc",

diff --git a/meson.build b/meson.build
@@ -203,6 +203,7 @@ libsommelier = static_library('sommelier',
     'sommelier-output.cc',
     'sommelier-pointer-constraints.cc',
     'sommelier-relative-pointer-manager.cc',
+    'sommelier-scope-timer.cc',
     'sommelier-seat.cc',
     'sommelier-shell.cc',
     'sommelier-stylus-tablet.cc',

diff --git a/sommelier-scope-timer.cc b/sommelier-scope-timer.cc
@@ -0,0 +1,31 @@
+// Copyright 2023 The ChromiumOS Authors
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "sommelier-scope-timer.h"  // NOLINT(build/include_directory)
+
+#include <fstream>
+#include <iomanip>
+#include <iostream>
+#include <sstream>
+#include <string>
+
+#define NSEC_PER_SEC 1000000000
+
+static inline int64_t timespec_to_ns(timespec* t) {
+  return (int64_t)t->tv_sec * NSEC_PER_SEC + t->tv_nsec;
+}
+
+ScopeTimer::ScopeTimer(const char* event_name) : event_name_(event_name) {
+  clock_gettime(CLOCK_MONOTONIC, &start_time_);
+}
+
+ScopeTimer::~ScopeTimer() {
+  timespec end_time;
+  clock_gettime(CLOCK_MONOTONIC, &end_time);
+  int64_t end = timespec_to_ns(&end_time);
+  int64_t start = timespec_to_ns(&start_time_);
+  int64_t diff = end - start;
+  fprintf(stderr, "sommelier_scope_timer: %s: %f seconds\n", event_name_,
+          static_cast<float>(diff) / static_cast<float>(NSEC_PER_SEC));
+}
diff --git a/sommelier-scope-timer.h b/sommelier-scope-timer.h
@@ -0,0 +1,21 @@
+// Copyright 2023 The ChromiumOS Authors
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#ifndef VM_TOOLS_SOMMELIER_SOMMELIER_SCOPE_TIMER_H_
+#define VM_TOOLS_SOMMELIER_SOMMELIER_SCOPE_TIMER_H_
+
+#include <time.h>
+#include <string>
+
+// This is to time certain tasks sommelier performs at startup, see b/303549040
+class ScopeTimer {
+ public:
+  explicit ScopeTimer(const char* event_name);
+  ~ScopeTimer();
+
+ private:
+  const char* event_name_;
+  timespec start_time_;
+};      // class ScopeTimer
+#endif  // VM_TOOLS_SOMMELIER_SOMMELIER_SCOPE_TIMER_H_
diff --git a/sommelier.cc b/sommelier.cc
@@ -3,6 +3,7 @@
 // found in the LICENSE file.
 
 #include "sommelier.h"            // NOLINT(build/include_directory)
+#include "sommelier-scope-timer.h"  // NOLINT(build/include_directory)
 #include "sommelier-tracing.h"    // NOLINT(build/include_directory)
 #include "sommelier-transform.h"  // NOLINT(build/include_directory)
 #include "sommelier-window.h"     // NOLINT(build/include_directory)
@@ -4068,34 +4069,40 @@ int real_main(int argc, char** argv) {
     ctx.channel = new VirtWaylandChannel();
   }
 
-  event_loop = wl_display_get_event_loop(ctx.host_display);
-  if (!sl_context_init_wayland_channel(&ctx, event_loop, display)) {
-    return EXIT_FAILURE;
-  }
-
-  int drm_fd = -1;
-  char* drm_device = nullptr;
-  if (force_drm_device != nullptr) {
-    // Use DRM device specified on the command line.
-    drm_fd = open(force_drm_device, O_RDWR | O_CLOEXEC);
-    if (drm_fd == -1) {
-      fprintf(stderr, "error: could not open %s (%s)\n", force_drm_device,
-              strerror(errno));
+  {
+    ScopeTimer timer("init wayland channel");
+    event_loop = wl_display_get_event_loop(ctx.host_display);
+    if (!sl_context_init_wayland_channel(&ctx, event_loop, display)) {
       return EXIT_FAILURE;
     }
-    drm_device = strdup(force_drm_device);
-  } else {
-    // Enumerate render nodes to find the virtio_gpu device.
-    drm_fd = open_virtgpu(&drm_device);
   }
-  if (drm_fd >= 0) {
-    ctx.gbm = gbm_create_device(drm_fd);
-    if (!ctx.gbm) {
-      fprintf(stderr, "error: couldn't get display device\n");
-      return EXIT_FAILURE;
+
+  {
+    ScopeTimer timer("drm device");
+    int drm_fd = -1;
+    char* drm_device = nullptr;
+    if (force_drm_device != nullptr) {
+      // Use DRM device specified on the command line.
+      drm_fd = open(force_drm_device, O_RDWR | O_CLOEXEC);
+      if (drm_fd == -1) {
+        fprintf(stderr, "error: could not open %s (%s)\n", force_drm_device,
+                strerror(errno));
+        return EXIT_FAILURE;
+      }
+      drm_device = strdup(force_drm_device);
+    } else {
+      // Enumerate render nodes to find the virtio_gpu device.
+      drm_fd = open_virtgpu(&drm_device);
     }
+    if (drm_fd >= 0) {
+      ctx.gbm = gbm_create_device(drm_fd);
+      if (!ctx.gbm) {
+        fprintf(stderr, "error: couldn't get display device\n");
+        return EXIT_FAILURE;
+      }
 
-    ctx.drm_device = drm_device;
+      ctx.drm_device = drm_device;
+    }
   }
 
   wl_array_init(&ctx.dpi);
@@ -4120,70 +4127,82 @@ int real_main(int argc, char** argv) {
     return EXIT_FAILURE;
   }
 
-  if (ctx.virtwl_display_fd != -1) {
-    ctx.display = wl_display_connect_to_fd(ctx.virtwl_display_fd);
-  } else {
-    if (display == nullptr)
-      display = getenv("WAYLAND_DISPLAY");
-    if (display == nullptr)
-      display = "wayland-0";
-
-    ctx.display = wl_display_connect(display);
-  }
+  {
+    ScopeTimer timer("connect display");
+    if (ctx.virtwl_display_fd != -1) {
+      ctx.display = wl_display_connect_to_fd(ctx.virtwl_display_fd);
+    } else {
+      if (display == nullptr)
+        display = getenv("WAYLAND_DISPLAY");
+      if (display == nullptr)
+        display = "wayland-0";
 
-  if (!ctx.display) {
-    fprintf(stderr, "error: failed to connect to %s\n", display);
-    return EXIT_FAILURE;
-  }
+      ctx.display = wl_display_connect(display);
+    }
 
-  if (!sl_parse_accelerators(&ctx.accelerators, accelerators))
-    return EXIT_FAILURE;
-  if (!sl_parse_accelerators(&ctx.windowed_accelerators, windowed_accelerators))
-    return EXIT_FAILURE;
+    if (!ctx.display) {
+      fprintf(stderr, "error: failed to connect to %s\n", display);
+      return EXIT_FAILURE;
+    }
 
-  ctx.display_event_source.reset(
-      wl_event_loop_add_fd(event_loop, wl_display_get_fd(ctx.display),
-                           WL_EVENT_READABLE, sl_handle_event, &ctx));
+    if (!sl_parse_accelerators(&ctx.accelerators, accelerators))
+      return EXIT_FAILURE;
+    if (!sl_parse_accelerators(&ctx.windowed_accelerators,
+                               windowed_accelerators))
+      return EXIT_FAILURE;
 
-  wl_registry_add_listener(wl_display_get_registry(ctx.display),
-                           &sl_registry_listener, &ctx);
+    ctx.display_event_source.reset(
+        wl_event_loop_add_fd(event_loop, wl_display_get_fd(ctx.display),
+                             WL_EVENT_READABLE, sl_handle_event, &ctx));
 
-  if (ctx.runprog || ctx.xwayland) {
-    // Wayland connection from client.
-    int rv = socketpair(AF_UNIX, SOCK_STREAM | SOCK_CLOEXEC, 0, sv);
-    errno_assert(!rv);
-    client_fd = sv[0];
+    wl_registry_add_listener(wl_display_get_registry(ctx.display),
+                             &sl_registry_listener, &ctx);
   }
 
-  ctx.client = wl_client_create(ctx.host_display, client_fd);
+  {
+    ScopeTimer timer("client create");
+    if (ctx.runprog || ctx.xwayland) {
+      // Wayland connection from client.
+      int rv = socketpair(AF_UNIX, SOCK_STREAM | SOCK_CLOEXEC, 0, sv);
+      errno_assert(!rv);
+      client_fd = sv[0];
+    }
 
-  // Replace the core display implementation. This is needed in order to
-  // implement sync handler properly.
-  sl_set_display_implementation(&ctx, ctx.client);
+    ctx.client = wl_client_create(ctx.host_display, client_fd);
+  }
 
-  if (ctx.runprog || ctx.xwayland) {
-    ctx.sigchld_event_source.reset(
-        wl_event_loop_add_signal(event_loop, SIGCHLD, sl_handle_sigchld, &ctx));
+  {
+    ScopeTimer timer("display implementation");
+    // Replace the core display implementation. This is needed in order to
+    // implement sync handler properly.
+    sl_set_display_implementation(&ctx, ctx.client);
+  }
 
-    if (ctx.xwayland) {
-      sl_spawn_xwayland(&ctx, event_loop, sv[1], xwayland_cmd_prefix,
-                        xwayland_path, xdisplay, xauth_path, xfont_path,
-                        xwayland_gl_driver_path, glamor);
-    } else {
-      pid = fork();
-      errno_assert(pid != -1);
-      if (pid == 0) {
-        // Unset DISPLAY to prevent X clients from connecting to an existing X
-        // server when X forwarding is not enabled.
-        unsetenv("DISPLAY");
-        sl_execvp(ctx.runprog[0], ctx.runprog, sv[1]);
-        _exit(EXIT_FAILURE);
+  {
+    ScopeTimer timer("spawn xwayland");
+    if (ctx.runprog || ctx.xwayland) {
+      ctx.sigchld_event_source.reset(wl_event_loop_add_signal(
+          event_loop, SIGCHLD, sl_handle_sigchld, &ctx));
+
+      if (ctx.xwayland) {
+        sl_spawn_xwayland(&ctx, event_loop, sv[1], xwayland_cmd_prefix,
+                          xwayland_path, xdisplay, xauth_path, xfont_path,
+                          xwayland_gl_driver_path, glamor);
+      } else {
+        pid = fork();
+        errno_assert(pid != -1);
+        if (pid == 0) {
+          // Unset DISPLAY to prevent X clients from connecting to an existing X
+          // server when X forwarding is not enabled.
+          unsetenv("DISPLAY");
+          sl_execvp(ctx.runprog[0], ctx.runprog, sv[1]);
+          _exit(EXIT_FAILURE);
+        }
+        ctx.child_pid = pid;
       }
-      ctx.child_pid = pid;
+      close(sv[1]);
     }
-    close(sv[1]);
   }
-
   // Attempt to enable tracing.  This could be called earlier but would rather
   // spawn all children first.
   const bool tracing_needed = ctx.trace_filename || ctx.trace_system;