From 7289d5c2561f5789bec9c4f0114b73eb0e7476ee Mon Sep 17 00:00:00 2001 From: David 'Digit' Turner Date: Thu, 12 May 2022 18:18:16 +0200 Subject: [PATCH 1/2] Fix .ninja parse time reported by `-d stats`. Because Parser::Load() is called recursively during Ninja manifest parsing, the call to METRIC_RECORD() in this function used to over-count the total parsing time (for example, by a factor of 2 for the Fuchsia build). This fixes the problem by introducing a new RECORD_METRIC_IF() macro, which only records anything if a given condition is true. This ensures that metric collection only starts and stops with the outer Parser::Load() call, and none of its recursive sub-calls. The effect on the output of `-d stats`is, for a Fuchsia build plan where `ninja -d stats nothing` takes a bit more than 5s: BEFORE: metric count avg (us) total (ms) .ninja parse 27304 372.6 10172.2 AFTER: metric count avg (us) total (ms) .ninja parse 1 4165297.0 4165.3 Note that |count| went to 1, since there is only one top-level Parser::Load() operation in this build. It would be more if dyndeps files were loaded, which does not happen in this build plan. --- src/metrics.h | 7 +++++++ src/parser.cc | 5 ++++- 2 files changed, 11 insertions(+), 1 deletion(-) diff --git a/src/metrics.h b/src/metrics.h index c9ba2366af..937d905de7 100644 --- a/src/metrics.h +++ b/src/metrics.h @@ -85,6 +85,13 @@ struct Stopwatch { g_metrics ? g_metrics->NewMetric(name) : NULL; \ ScopedMetric metrics_h_scoped(metrics_h_metric); +/// A variant of METRIC_RECORD that doesn't record anything if |condition| +/// is false. +#define METRIC_RECORD_IF(name, condition) \ + static Metric* metrics_h_metric = \ + g_metrics ? g_metrics->NewMetric(name) : NULL; \ + ScopedMetric metrics_h_scoped((condition) ? metrics_h_metric : NULL); + extern Metrics* g_metrics; #endif // NINJA_METRICS_H_ diff --git a/src/parser.cc b/src/parser.cc index 5f303c557c..139a347ac3 100644 --- a/src/parser.cc +++ b/src/parser.cc @@ -20,7 +20,10 @@ using namespace std; bool Parser::Load(const string& filename, string* err, Lexer* parent) { - METRIC_RECORD(".ninja parse"); + // If |parent| is not NULL, metrics collection has been started by a parent + // Parser::Load() in our call stack. Do not start a new one here to avoid + // over-counting parsing times. + METRIC_RECORD_IF(".ninja parse", parent == NULL); string contents; string read_err; if (file_reader_->ReadFile(filename, &contents, &read_err) != From cff9dce3cd2187a7671b05d2437a426ca6e06ca0 Mon Sep 17 00:00:00 2001 From: David 'Digit' Turner Date: Mon, 30 May 2022 23:04:46 +0200 Subject: [PATCH 2/2] Don't double-count the 'node stat' metric. This is already done in RealDiskInterface::Stat() itself, and removes a confusing duplicate line in `-d stats` output, e.g.: BEFORE: metric count avg (us) total (ms) ... node stat 119145 3.0 355.2 node stat 270673 3.1 834.9 AFTER: metric count avg (us) total (ms) ... node stat 270673 2.9 774.0 --- src/graph.cc | 1 - 1 file changed, 1 deletion(-) diff --git a/src/graph.cc b/src/graph.cc index 199294d481..ad7031f92e 100644 --- a/src/graph.cc +++ b/src/graph.cc @@ -32,7 +32,6 @@ using namespace std; bool Node::Stat(DiskInterface* disk_interface, string* err) { - METRIC_RECORD("node stat"); mtime_ = disk_interface->Stat(path_, err); if (mtime_ == -1) { return false;