[gn] Add trace entries for loading and blocking on imports

This adds trace entries for loading imports and for blocking on an
import for longer than 20ms. These make gn's tracelog significantly
easier to understand when imported files take a long time to process.
For example, in the Chrome build on Mac //build/toolchain/mac/BUILD.gn
blocks for ~240ms running sdk_info.py because
//build/config/mac/mac_sdk.gni runs that script and //ui/base/BUILD.gn
blocks for ~350ms because it is waiting for the import lock on
mac_sdk.gni to be released. Without these traces, it is not
immediately obvious why //build/toolchain/mac/BUILD.gn is running that
script and it is very unclear why //ui/base/BUILD.gn takes so long.

Review-Url: https://codereview.chromium.org/2424233002
Cr-Commit-Position: refs/heads/master@{#427151}

tools/gn/import_manager.cc

@@ -8,6 +8,7 @@
 #include "tools/gn/parse_tree.h"
 #include "tools/gn/scheduler.h"
 #include "tools/gn/scope_per_file_provider.h"
+#include "tools/gn/trace.h"
 
 namespace {
 
@@ -16,6 +17,8 @@ std::unique_ptr<Scope> UncachedImport(const Settings* settings,
                                       const SourceFile& file,
                                       const ParseNode* node_for_err,
                                       Err* err) {
+  ScopedTrace load_trace(TraceItem::TRACE_IMPORT_LOAD, file.value());
+
   const ParseNode* node = g_scheduler->input_file_manager()->SyncLoadFile(
       node_for_err->GetRange(), settings->build_settings(), file, err);
   if (!node)
@@ -87,6 +90,7 @@ bool ImportManager::DoImport(const SourceFile& file,
   // is already processing the import.
   const Scope* import_scope = nullptr;
   {
+    base::TimeTicks import_block_begin = base::TimeTicks::Now();
     base::AutoLock lock(import_info->load_lock);
 
     if (!import_info->scope) {
@@ -99,6 +103,21 @@ bool ImportManager::DoImport(const SourceFile& file,
         *err = import_info->load_result;
         return false;
       }
+    } else {
+      // Add trace if this thread was blocked for a long period of time and did
+      // not load the import itself.
+      base::TimeTicks import_block_end = base::TimeTicks::Now();
+      constexpr auto kImportBlockTraceThreshold =
+          base::TimeDelta::FromMilliseconds(20);
+      if (TracingEnabled() &&
+          import_block_end - import_block_begin > kImportBlockTraceThreshold) {
+        auto import_block_trace =
+            new TraceItem(TraceItem::TRACE_IMPORT_BLOCK, file.value(),
+                          base::PlatformThread::CurrentId());
+        import_block_trace->set_begin(import_block_begin);
+        import_block_trace->set_end(import_block_end);
+        AddTrace(import_block_trace);
+      }
     }
 
     // Promote the now-read-only scope to outside the load lock.

tools/gn/trace.cc

@@ -170,6 +170,10 @@ void EnableTracing() {
     trace_log = new TraceLog;
 }
 
+bool TracingEnabled() {
+  return !!trace_log;
+}
+
 void AddTrace(TraceItem* item) {
   trace_log->Add(item);
 }
@@ -203,6 +207,8 @@ std::string SummarizeTraces() {
       case TraceItem::TRACE_CHECK_HEADER:
         headers_checked++;
         break;
+      case TraceItem::TRACE_IMPORT_LOAD:
+      case TraceItem::TRACE_IMPORT_BLOCK:
       case TraceItem::TRACE_SETUP:
       case TraceItem::TRACE_FILE_LOAD:
       case TraceItem::TRACE_FILE_WRITE:
@@ -281,6 +287,12 @@ void SaveTraces(const base::FilePath& file_name) {
       case TraceItem::TRACE_FILE_WRITE:
         out << "\"file_write\"";
         break;
+      case TraceItem::TRACE_IMPORT_LOAD:
+        out << "\"import_load\"";
+        break;
+      case TraceItem::TRACE_IMPORT_BLOCK:
+        out << "\"import_block\"";
+        break;
       case TraceItem::TRACE_SCRIPT_EXECUTE:
         out << "\"script_exec\"";
         break;

tools/gn/trace.h

@@ -26,6 +26,8 @@ class TraceItem {
     TRACE_FILE_PARSE,
     TRACE_FILE_EXECUTE,
     TRACE_FILE_WRITE,
+    TRACE_IMPORT_LOAD,
+    TRACE_IMPORT_BLOCK,
     TRACE_SCRIPT_EXECUTE,
     TRACE_DEFINE_TARGET,
     TRACE_ON_RESOLVED,
@@ -88,6 +90,9 @@ class ScopedTrace {
 // Call to turn tracing on. It's off by default.
 void EnableTracing();
 
+// Returns whether tracing is enabled.
+bool TracingEnabled();
+
 // Adds a trace event to the log. Takes ownership of the pointer.
 void AddTrace(TraceItem* item);