Add basic tracing support to the gtest launcher

base/test/launcher/test_launcher.cc

 // Copyright 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "base/test/launcher/test_launcher.h"
 
 #include <memory>
 
 #include "base/at_exit.h"
 #include "base/bind.h"
@@ skipping 13 matching lines @@
 #include "base/process/launch.h"
 #include "base/single_thread_task_runner.h"
 #include "base/strings/pattern.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_split.h"
 #include "base/strings/string_util.h"
 #include "base/strings/stringize_macros.h"
 #include "base/strings/stringprintf.h"
 #include "base/strings/utf_string_conversions.h"
 #include "base/test/gtest_util.h"
+#include "base/test/launcher/test_launcher_tracer.h"
 #include "base/test/launcher/test_results_tracker.h"
 #include "base/test/sequenced_worker_pool_owner.h"
 #include "base/test/test_switches.h"
 #include "base/test/test_timeouts.h"
 #include "base/threading/thread_checker.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "base/time/time.h"
 #include "build/build_config.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
@@ skipping 39 matching lines @@
 // Avoids flooding the logs with amount of output that gums up
 // the infrastructure.
 const size_t kOutputSnippetLinesLimit = 5000;
 
 // Set of live launch test processes with corresponding lock (it is allowed
 // for callers to launch processes on different threads).
 LazyInstance<std::map<ProcessHandle, CommandLine> > g_live_processes
     = LAZY_INSTANCE_INITIALIZER;
 LazyInstance<Lock> g_live_processes_lock = LAZY_INSTANCE_INITIALIZER;
 
+// Performance trace generator.
+LazyInstance<TestLauncherTracer> g_tracer = LAZY_INSTANCE_INITIALIZER;
+
 #if defined(OS_POSIX)
 // Self-pipe that makes it possible to do complex shutdown handling
 // outside of the signal handler.
 int g_shutdown_pipe[2] = { -1, -1 };
 
 void ShutdownPipeSignalHandler(int signal) {
   HANDLE_EINTR(write(g_shutdown_pipe[1], "q", 1));
 }
 
 void KillSpawnedTestProcesses() {
@@ skipping 137 matching lines @@
   new_command_line.PrependWrapper(wrapper);
 #endif
 
   return new_command_line;
 }
 
 // Launches a child process using |command_line|. If the child process is still
 // running after |timeout|, it is terminated and |*was_timeout| is set to true.
 // Returns exit code of the process.
 int LaunchChildTestProcessWithOptions(
     const CommandLine& command_line,

[Primiano Tucci (use gerrit), 2016/07/01 11:34:29]

If you want to you dump the command line as well.
The pattern here is to have an "args" argument to the event. The UI will
automatically show the detail of the event.
In other words:

{"pid": ..., "tid":...., args: {"command_line": "--foo --bar --baz"}}

     const LaunchOptions& options,
     int flags,
     TimeDelta timeout,
     const TestLauncher::GTestProcessLaunchedCallback& launched_callback,
     bool* was_timeout) {
+  TimeTicks start_time(TimeTicks::Now());
+
 #if defined(OS_POSIX)
   // Make sure an option we rely on is present - see LaunchChildGTestProcess.
   DCHECK(options.new_process_group);
 #endif
 
   LaunchOptions new_options(options);
 
 #if defined(OS_WIN)
   DCHECK(!new_options.job_handle);
 
@@ skipping 71 matching lines @@
       // or due to it timing out, we need to clean up any child processes that
       // it might have created. On Windows, child processes are automatically
       // cleaned up using JobObjects.
       KillProcessGroup(process.Handle());
     }
 #endif
 
     g_live_processes.Get().erase(process.Handle());
   }
 
+  g_tracer.Get().RecordProcessExecution(

[Primiano Tucci (use gerrit), 2016/07/01 11:34:29]

If this is really what you need it's ok. But if you need more events you can
consider having:
-  a TestLauncherTracer::ScopedEvent object which records one 'B' event in the
ctor and one 'B' event in the dtor
- A method g_tracer.RecordScopedEvent() which returns the ScopedEvent object. 
 so you can just add to your code like we do with TRACE_EVENT macros without
having to diff the time by hand.
But if this is really what you want, it's probably ok as it is.

[Paweł Hajdan Jr., 2016/07/01 12:47:32]

Yeah, it's OK for now. I can take another look if I need something more
advanced.

+      start_time, TimeTicks::Now() - start_time);
+
   return exit_code;
 }
 
 void RunCallback(const TestLauncher::GTestProcessCompletedCallback& callback,
                  int exit_code,
                  const TimeDelta& elapsed_time,
                  bool was_timeout,
                  const std::string& output) {
   callback.Run(exit_code, elapsed_time, was_timeout, output);
 }
@@ skipping 670 matching lines @@
 
 void TestLauncher::MaybeSaveSummaryAsJSON() {
   const CommandLine* command_line = CommandLine::ForCurrentProcess();
   if (command_line->HasSwitch(switches::kTestLauncherSummaryOutput)) {
     FilePath summary_path(command_line->GetSwitchValuePath(
                               switches::kTestLauncherSummaryOutput));
     if (!results_tracker_.SaveSummaryAsJSON(summary_path)) {
       LOG(ERROR) << "Failed to save test launcher output summary.";
     }
   }
+  if (command_line->HasSwitch(switches::kTestLauncherTrace)) {
+    FilePath trace_path(command_line->GetSwitchValuePath(
+        switches::kTestLauncherTrace));
+    if (!g_tracer.Get().Dump(trace_path)) {
+      LOG(ERROR) << "Failed to save test launcher trace.";

[Primiano Tucci (use gerrit), 2016/07/01 11:34:30]

maybe move this error logging to the Dump method and make it void. Not sure in
how many other cases you really care about the success return code and want to
Dump() but ignore the eventual failure.

[Paweł Hajdan Jr., 2016/07/01 12:47:32]

This is consistent with above code. I think as an interface, it's preferred to
have bool return value rather than void and log inside.

+    }
+  }
 }
 
 void TestLauncher::OnLaunchTestProcessFinished(
     const GTestProcessCompletedCallback& callback,
     int exit_code,
     const TimeDelta& elapsed_time,
     bool was_timeout,
     const std::string& output) {
   DCHECK(thread_checker_.CalledOnValidThread());
 
@@ skipping 74 matching lines @@
   }
 
   std::string snippet(full_output.substr(run_pos));
   if (end_pos != std::string::npos)
     snippet = full_output.substr(run_pos, end_pos - run_pos);
 
   return snippet;
 }
 
 }  // namespace base