[debugger] Block timers accept messages.

This makes it easier to fine grain debug messages.

Added timing statements to loading modules, as this is the cause of
a latest timing regression.

Change-Id: I964d1083414d278b12ff2f97aaf609c76f24be39

src/developer/debug/shared/logging/block_timer.cc

@@ -6,6 +6,7 @@
 
 #include "src/developer/debug/shared/logging/debug.h"
 #include "src/developer/debug/shared/logging/logging.h"
+#include "src/lib/fxl/strings/string_printf.h"
 
 namespace debug_ipc {
 
@@ -16,15 +17,15 @@ BlockTimer::BlockTimer(FileLineFunction origin)
 
 BlockTimer::~BlockTimer() { EndTimer(); }
 
-void BlockTimer::EndTimer() {
+double BlockTimer::EndTimer() {
   if (!should_log_)
-    return;
+    return 0;
 
   // The timer won't trigger again.
   should_log_ = false;
 
   if (!IsLogCategoryActive(LogCategory::kTiming))
-    return;
+    return 0;
 
   const char* unit = "ms";
   double time = timer_.Elapsed().ToMillisecondsF();
@@ -37,8 +38,17 @@ void BlockTimer::EndTimer() {
   }
 
   auto preamble = LogPreamble(LogCategory::kTiming, origin_);
-  printf("\r%s Took %.3f %s.\r\n", preamble.c_str(), time, unit);
+  auto context = stream_.str();
+
+  std::stringstream ss;
+  ss << "\r" << preamble;
+  if (!context.empty())
+    ss << "[" << context << "] ";
+  ss << fxl::StringPrintf("Took %.3f %s.\r\n", time, unit);
+  printf("%s", ss.str().c_str());
   fflush(stdout);
+
+  return time;
 }
 
 }  // namespace debug_ipc

src/developer/debug/shared/logging/block_timer.h

@@ -4,6 +4,8 @@
 
 #pragma once
 
+#include <sstream>
+
 #include "src/developer/debug/shared/logging/file_line_function.h"
 #include "src/lib/fxl/macros.h"
 #include "src/lib/fxl/time/stopwatch.h"
@@ -25,23 +27,47 @@ class BlockTimer {
 
   // This is what get called on destruction. You can call it before destruction
   // to trigger the timer before that. Will not trigger again.
-  void EndTimer();
+  // Returns the timing (in milliseconds).
+  double EndTimer();
 
   // BlockTimers should only measure the block they're in. No weird stuff.
   FXL_DISALLOW_COPY_AND_ASSIGN(BlockTimer);
   FXL_DISALLOW_MOVE(BlockTimer);
 
+  std::ostream& stream() { return stream_; }
+
  private:
   FileLineFunction origin_;  // Where this timer was called from.
   fxl::Stopwatch timer_;
   bool should_log_;
+
+  std::ostringstream stream_;
 };
 
 // We use this macro to ensure the concatenation of the values. Oh macros :)
 #define TIME_BLOCK_TOKEN(x, y) x##y
 #define TIME_BLOCK_TOKEN2(x, y) TIME_BLOCK_TOKEN(x, y)
 
+// Meant to be used at a scope.
+// Foo() {
+//  TIME_BLOCK() << "Timing on Foo description.";
+//  ...
+//  <REST OF FUNCTION>
+//  ...
+// }  <-- Logs the timing on the destructor.
 #define TIME_BLOCK() \
-  ::debug_ipc::BlockTimer TIME_BLOCK_TOKEN2(block_timer_, __LINE__)(FROM_HERE)
+  TIME_BLOCK_WITH_NAME(TIME_BLOCK_TOKEN2(__timer__, __LINE__))
+
+// Useful for calling timing on code that is not easily "scopable":
+//
+// TIME_BLOCK_WITH_NAME(timer_name) << "Some description.";
+// ...
+// <CODE TO BE TIMED>
+// ...
+// double time_in_ms = timer_name.EndTimer();
+// DoSomethingWithTiming(time_is_ms);
+#define TIME_BLOCK_WITH_NAME(var_name)         \
+  ::debug_ipc::BlockTimer var_name(FROM_HERE); \
+  var_name.stream()
 
 }  // namespace debug_ipc

src/developer/debug/shared/logging/logging.h

@@ -4,14 +4,17 @@
 
 #pragma once
 
+// This header is meant to be the hub of debug logging: timers, logging, etc.
+// There is no need to include the other headers directly.
+
 #include <sstream>
 
+#include "src/developer/debug/shared/logging/block_timer.h"
 #include "src/developer/debug/shared/logging/debug.h"
 #include "src/developer/debug/shared/logging/file_line_function.h"
 
 namespace debug_ipc {
 
-
 // Normally you would use this macro to create logging statements.
 // Example:
 //

src/developer/debug/zxdb/symbols/module_symbols_impl.cc

@@ -15,6 +15,7 @@
 #include "llvm/Object/ELFObjectFile.h"
 #include "llvm/Object/ObjectFile.h"
 #include "src/developer/debug/ipc/protocol.h"
+#include "src/developer/debug/shared/logging/logging.h"
 #include "src/developer/debug/shared/message_loop.h"
 #include "src/developer/debug/zxdb/common/string_util.h"
 #include "src/developer/debug/zxdb/symbols/dwarf_expr_eval.h"
@@ -124,6 +125,7 @@ ModuleSymbolStatus ModuleSymbolsImpl::GetStatus() const {
 }
 
 Err ModuleSymbolsImpl::Load() {
+  TIME_BLOCK() << "Loading " << binary_name_ << " (" << name_ << ").";
   if (auto elf = elflib::ElfLib::Create(binary_name_)) {
     if (auto debug = elflib::ElfLib::Create(name_)) {
       if (elf->SetDebugData(std::move(debug))) {