diff --git a/src/developer/debug/shared/logging/block_timer.cc b/src/developer/debug/shared/logging/block_timer.cc index e17c1b672c09c6c311ab40a35d171ddcb9a266c0..0bb367b7bdf266059bf67f31c054af9df8cf7176 100644 --- a/src/developer/debug/shared/logging/block_timer.cc +++ b/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 diff --git a/src/developer/debug/shared/logging/block_timer.h b/src/developer/debug/shared/logging/block_timer.h index 9de1e235c020b5fa5aafbe6497c3640dc9057c3e..904da8c2333dd4c6c8fe681d1e7b520efb81208f 100644 --- a/src/developer/debug/shared/logging/block_timer.h +++ b/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 diff --git a/src/developer/debug/shared/logging/logging.h b/src/developer/debug/shared/logging/logging.h index e7f03d0a29b0242c8d95d959f93883b09620f7f1..346305a143fffe6f2fb3a83e441beb28ed91e7a2 100644 --- a/src/developer/debug/shared/logging/logging.h +++ b/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: // diff --git a/src/developer/debug/zxdb/symbols/module_symbols_impl.cc b/src/developer/debug/zxdb/symbols/module_symbols_impl.cc index 5f5f4b08b7001958e3fb46d41d0ea09ca3c60c2b..4b04feca79e11d6adfb1d07b2b69dd9c69b73637 100644 --- a/src/developer/debug/zxdb/symbols/module_symbols_impl.cc +++ b/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))) {