Add a new "debug" status message, use for stats

This will allow the android build to always set "-d stats", and redirect
the output to a verbose log file for later analysis.

Test: NINJA_ARGS="-d stats" m nothing  (without changes to soong_ui -- prints to stdout)
Test: m nothing   (with changes to soong_ui, see in verbose.log.gz)
Change-Id: Idc6a9964970f8bc457b4c72cb177998d67149e4a

10 files changed, 44 insertions, 17 deletions

diff --git a/frontend/frontend.pb b/frontend/frontend.pb
index e0ac66e..718f173 100644
--- a/frontend/frontend.pb
+++ b/frontend/frontend.pb
diff --git a/frontend/native.py b/frontend/native.py
index 3794707..4862268 100755
--- a/frontend/native.py
+++ b/frontend/native.py
@@ -128,6 +128,8 @@ class NinjaNativeFrontend:
                 prefix = 'ninja: warning: '
             elif msg.message.level == 2:
                 prefix = 'ninja: error: '
+            else
+                prefix = ''
             self.printer.print_line(prefix + msg.message.message, LinePrinter.LINE_FULL)
 
         if not handled:
diff --git a/src/build_test.cc b/src/build_test.cc
index 7571e3f..ccfffa1 100644
--- a/src/build_test.cc
+++ b/src/build_test.cc
@@ -465,6 +465,7 @@ struct FakeStatus : public Status {
   virtual void BuildStarted() {}
   virtual void BuildFinished() {}
 
+  virtual void Debug(const char* msg, ...) {}
   virtual void Info(const char* msg, ...) {}
   virtual void Error(const char* msg, ...) {}
 
diff --git a/src/frontend.pb.h b/src/frontend.pb.h
index da6d152..53d2431 100644
--- a/src/frontend.pb.h
+++ b/src/frontend.pb.h
@@ -377,6 +377,7 @@ struct Status {
       INFO = 0,
       WARNING = 1,
       ERROR = 2,
+      DEBUG = 3,
     };
 
     ::ninja::Status::Message::Level level_;
diff --git a/src/frontend.proto b/src/frontend.proto
index ce4faa9..57423d8 100644
--- a/src/frontend.proto
+++ b/src/frontend.proto
@@ -71,8 +71,9 @@ message Status {
       INFO = 0;
       WARNING = 1;
       ERROR = 2;
+      DEBUG = 3;
     }
-    // Message priority level (INFO, WARNING, or ERROR).
+    // Message priority level (DEBUG, INFO, WARNING, ERROR).
     optional Level level = 1 [default = INFO];
     // Info/warning/error message from Ninja.
     optional string message = 2;
diff --git a/src/metrics.cc b/src/metrics.cc
index 8f155c9..5e4cef9 100644
--- a/src/metrics.cc
+++ b/src/metrics.cc
@@ -29,6 +29,7 @@
 
 #include <algorithm>
 
+#include "status.h"
 #include "util.h"
 
 Metrics* g_metrics = NULL;
@@ -94,7 +95,7 @@ Metric* Metrics::NewMetric(const string& name) {
   return result;
 }
 
-void Metrics::Report() {
+void Metrics::Report(Status *status) {
   std::lock_guard<std::mutex> lock(mutex_);
 
   int width = 0;
@@ -103,14 +104,14 @@ void Metrics::Report() {
     width = max((int)(*i)->name().size(), width);
   }
 
-  printf("%-*s\t%-6s\t%-9s\t%s\n", width,
+  status->Debug("%-*s\t%-6s\t%-9s\t%s", width,
          "metric", "count", "avg (us)", "total (ms)");
   for (vector<Metric*>::iterator i = metrics_.begin();
        i != metrics_.end(); ++i) {
     Metric* metric = *i;
     double total = metric->time() / (double)1000;
     double avg = metric->time() / (double)metric->count();
-    printf("%-*s\t%-6d\t%-8.1f\t%.1f\n", width, metric->name().c_str(),
+    status->Debug("%-*s\t%-6d\t%-8.1f\t%.1f", width, metric->name().c_str(),
            metric->count(), avg, total);
   }
 }
@@ -123,7 +124,7 @@ int64_t GetTimeMillis() {
   return TimerToMicros(HighResTimer()) / 1000;
 }
 
-void DumpMemoryUsage() {
+void DumpMemoryUsage(Status *status) {
 #if defined(__linux__)
   std::vector<std::string> words;
   struct rusage usage {};
@@ -148,13 +149,14 @@ void DumpMemoryUsage() {
     fclose(status_fp);
   }
   if (!words.empty()) {
+    string final;
     for (size_t i = 0; i < words.size(); ++i) {
       if (i > 0) {
-        printf(", ");
+        final += ", ";
       }
-      printf("%s", words[i].c_str());
+      final += words[i];
     }
-    printf("\n");
+    status->Debug("%s", final.c_str());
   }
 #endif
 }
diff --git a/src/metrics.h b/src/metrics.h
index 73d62af..48f26d1 100644
--- a/src/metrics.h
+++ b/src/metrics.h
@@ -23,6 +23,8 @@ using namespace std;
 
 #include "util.h"  // For int64_t.
 
+struct Status;
+
 /// The Metrics module is used for the debug mode that dumps timing stats of
 /// various actions.  To use, see METRIC_RECORD below.
 
@@ -101,7 +103,7 @@ struct Metrics {
   Metric* NewMetric(const string& name);
 
   /// Print a summary report to stdout.
-  void Report();
+  void Report(Status *status);
 
 private:
   std::mutex mutex_;
@@ -139,6 +141,6 @@ struct Stopwatch {
 
 extern Metrics* g_metrics;
 
-void DumpMemoryUsage();
+void DumpMemoryUsage(Status *status);
 
 #endif // NINJA_METRICS_H_
diff --git a/src/ninja.cc b/src/ninja.cc
index c84342d..4f7411b 100644
--- a/src/ninja.cc
+++ b/src/ninja.cc
@@ -161,7 +161,7 @@ struct NinjaMain : public BuildLogUser {
   int RunBuild(int argc, char** argv, Status* status);
 
   /// Dump the output requested by '-d stats'.
-  void DumpMetrics();
+  void DumpMetrics(Status *status);
 
   virtual bool IsPathDead(StringPiece s) const {
     Node* n = state_.LookupNode(s);
@@ -1259,15 +1259,16 @@ bool NinjaMain::OpenDepsLog(bool recompact_only) {
   return true;
 }
 
-void NinjaMain::DumpMetrics() {
-  g_metrics->Report();
+void NinjaMain::DumpMetrics(Status *status) {
+  g_metrics->Report(status);
+
+  status->Debug("");
 
-  printf("\n");
   int count = (int)state_.paths_.size();
   int buckets = (int)state_.paths_.bucket_count();
-  printf("path->node hash load %.2f (%d entries / %d buckets), %zu edges\n",
+  status->Debug("path->node hash load %.2f (%d entries / %d buckets), %zu edges",
          count / (double) buckets, count, buckets, state_.edges_.size());
-  DumpMemoryUsage();
+  DumpMemoryUsage(status);
 }
 
 bool NinjaMain::EnsureBuildDirExists() {
@@ -1584,7 +1585,7 @@ NORETURN void real_main(int argc, char** argv) {
     } while (options.persistent);
 
     if (g_metrics)
-      ninja.DumpMetrics();
+      ninja.DumpMetrics(status);
 
     delete status;
     exit(result);
diff --git a/src/status.cc b/src/status.cc
index e377c7d..bfa233b 100644
--- a/src/status.cc
+++ b/src/status.cc
@@ -238,6 +238,13 @@ void StatusPrinter::Info(const char* msg, ...) {
   va_end(ap);
 }
 
+void StatusPrinter::Debug(const char* msg, ...) {
+  va_list ap;
+  va_start(ap, msg);
+  ::Info(msg, ap);
+  va_end(ap);
+}
+
 #ifndef _WIN32
 
 #include "frontend.pb.h"
@@ -384,6 +391,13 @@ void StatusSerializer::Message(ninja::Status::Message::Level level,
   Send();
 }
 
+void StatusSerializer::Debug(const char* msg, ...) {
+  va_list ap;
+  va_start(ap, msg);
+  Message(ninja::Status::Message::DEBUG, msg, ap);
+  va_end(ap);
+}
+
 void StatusSerializer::Info(const char* msg, ...) {
   va_list ap;
   va_start(ap, msg);
diff --git a/src/status.h b/src/status.h
index 73073c6..832368d 100644
--- a/src/status.h
+++ b/src/status.h
@@ -35,6 +35,7 @@ struct Status {
   virtual void BuildStarted() = 0;
   virtual void BuildFinished() = 0;
 
+  virtual void Debug(const char* msg, ...) = 0;
   virtual void Info(const char* msg, ...) = 0;
   virtual void Warning(const char* msg, ...) = 0;
   virtual void Error(const char* msg, ...) = 0;
@@ -53,6 +54,7 @@ struct StatusPrinter : Status {
   virtual void BuildStarted();
   virtual void BuildFinished();
 
+  virtual void Debug(const char* msg, ...);
   virtual void Info(const char* msg, ...);
   virtual void Warning(const char* msg, ...);
   virtual void Error(const char* msg, ...);
@@ -134,6 +136,7 @@ struct StatusSerializer : Status {
   virtual void BuildStarted();
   virtual void BuildFinished();
 
+  virtual void Debug(const char* msg, ...);
   virtual void Info(const char* msg, ...);
   virtual void Warning(const char* msg, ...);
   virtual void Error(const char* msg, ...);