[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-Original-Commit-Position: refs/heads/master@{#427151}
Cr-Mirrored-From: https://chromium.googlesource.com/chromium/src
Cr-Mirrored-Commit: 840ab52b0bbdbe46a093c76c4a57b505d7e29e17
diff --git a/tools/gn/import_manager.cc b/tools/gn/import_manager.cc
index 01c88b5..0213c33 100644
--- a/tools/gn/import_manager.cc
+++ b/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 @@
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 @@
// 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 @@
*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.
diff --git a/tools/gn/trace.cc b/tools/gn/trace.cc
index 2a1b460..74a3e71 100644
--- a/tools/gn/trace.cc
+++ b/tools/gn/trace.cc
@@ -170,6 +170,10 @@
trace_log = new TraceLog;
}
+bool TracingEnabled() {
+ return !!trace_log;
+}
+
void AddTrace(TraceItem* item) {
trace_log->Add(item);
}
@@ -203,6 +207,8 @@
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 @@
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;
diff --git a/tools/gn/trace.h b/tools/gn/trace.h
index de8ab09..d211641 100644
--- a/tools/gn/trace.h
+++ b/tools/gn/trace.h
@@ -26,10 +26,12 @@
TRACE_FILE_PARSE,
TRACE_FILE_EXECUTE,
TRACE_FILE_WRITE,
+ TRACE_IMPORT_LOAD,
+ TRACE_IMPORT_BLOCK,
TRACE_SCRIPT_EXECUTE,
TRACE_DEFINE_TARGET,
TRACE_ON_RESOLVED,
- TRACE_CHECK_HEADER, // One file.
+ TRACE_CHECK_HEADER, // One file.
TRACE_CHECK_HEADERS, // All files.
};
@@ -88,6 +90,9 @@
// 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);
