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

[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.

Committed: https://crrev.com/840ab52b0bbdbe46a093c76c4a57b505d7e29e17
Cr-Commit-Position: refs/heads/master@{#427151}

[jamesr, 2016-10-17 21:49:44]

jamesr@chromium.org changed reviewers:
+ brettw@chromium.org

[jamesr, 2016-10-17 21:49:45]

I wrote this to investigate some issues in a non-Chrome environment but it turns
out to be very useful in Chrome's build as well.  The 20ms threshold is somewhat
arbitrarily chosen to avoid adding an extra trace to every import of a .gni file
after the first. This is about how long it takes to spin up an empty python
process on my linux box so the trace will show up when multiple threads are
serializing on one import that blocks on an exec_script().

[Nico, 2016-10-17 21:54:14]

(make sure you have the two changes on
https://bugs.chromium.org/p/chromium/issues/detail?id=609541 in your clone)

On Oct 17, 2016 5:49 PM, <jamesr@chromium.org> wrote:

> Reviewers: brettw (ping on IM after 24h)
> CL: https://codereview.chromium.org/2424233002/
>
> Message:
> I wrote this to investigate some issues in a non-Chrome environment but it
> turns
> out to be very useful in Chrome's build as well. The 20ms threshold is
> somewhat
> arbitrarily chosen to avoid adding an extra trace to every import of a
> .gni file
> after the first. This is about how long it takes to spin up an empty python
> process on my linux box so the trace will show up when multiple threads are
> serializing on one import that blocks on an exec_script().
>
> Description:
> [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.
>
> Affected files (+37, -1 lines):
> M tools/gn/import_manager.cc
> M tools/gn/trace.h
> M tools/gn/trace.cc
>
>
> Index: tools/gn/import_manager.cc
> diff --git a/tools/gn/import_manager.cc b/tools/gn/import_manager.cc
> index 01c88b5a68c85dd1bce16a19c78d09d9ba6be4e1..
> 0213c3367a41c5b6208cc6f62a52b7eae7c07f39 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 @@ 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.
> Index: tools/gn/trace.cc
> diff --git a/tools/gn/trace.cc b/tools/gn/trace.cc
> index 2a1b460d56b11e856cbc121186a541b4439c35e7..
> 74a3e71c03e73d8bcda5560ff93ad9868a97b839 100644
> --- a/tools/gn/trace.cc
> +++ b/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;
> Index: tools/gn/trace.h
> diff --git a/tools/gn/trace.h b/tools/gn/trace.h
> index de8ab09d490770bd78dfb1faa42db4dfd88a6cea..
> d2116410bd59446582cc67f61eaf98f57fcbd6ef 100644
> --- a/tools/gn/trace.h
> +++ b/tools/gn/trace.h
> @@ -26,10 +26,12 @@ 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,
> - TRACE_CHECK_HEADER, // One file.
> + TRACE_CHECK_HEADER, // One file.
> TRACE_CHECK_HEADERS, // All files.
> };
>
> @@ -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);
>
>
>
>

-- 
You received this message because you are subscribed to the Google Groups
"Chromium-reviews" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to chromium-reviews+unsubscribe@chromium.org.

[jamesr, 2016-10-17 21:55:37]

The CQ bit was checked by jamesr@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-10-17 21:56:16]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-10-17 22:46:02]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-10-17 22:46:02]

Dry run: This issue passed the CQ dry run.

[brettw, 2016-10-24 19:17:00]

lgtm

[jamesr, 2016-10-24 19:59:11]

The CQ bit was checked by jamesr@chromium.org

[commit-bot: I haz the power, 2016-10-24 19:59:43]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-10-24 21:16:38]

Committed patchset #1 (id:1)

[commit-bot: I haz the power, 2016-10-24 21:18:06]

Description was changed from

==========
[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.
==========

to

==========
[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.

Committed: https://crrev.com/840ab52b0bbdbe46a093c76c4a57b505d7e29e17
Cr-Commit-Position: refs/heads/master@{#427151}
==========

[commit-bot: I haz the power, 2016-10-24 21:18:07]

Patchset 1 (id:??) landed as
https://crrev.com/840ab52b0bbdbe46a093c76c4a57b505d7e29e17
Cr-Commit-Position: refs/heads/master@{#427151}