This is an automated email from the ASF dual-hosted git repository.
wangdan pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/incubator-pegasus.git
The following commit(s) were added to refs/heads/master by this push:
new febb95874 feat(macro): add LOG_TIMING* series macros (#1879)
febb95874 is described below
commit febb9587456c9ef9ad5a71c7ecfacf2012f03654
Author: Yingchun Lai <[email protected]>
AuthorDate: Thu Feb 1 20:24:02 2024 +0800
feat(macro): add LOG_TIMING* series macros (#1879)
---
src/http/pprof_http_service.cpp | 20 +----
src/utils/fmt_logging.h | 8 ++
src/utils/test/logging.cpp | 30 +++++++-
src/utils/timer.h | 165 ++++++++++++++++++++++++++++++++++++++++
4 files changed, 206 insertions(+), 17 deletions(-)
diff --git a/src/http/pprof_http_service.cpp b/src/http/pprof_http_service.cpp
index d25f596d0..8d9757fe9 100644
--- a/src/http/pprof_http_service.cpp
+++ b/src/http/pprof_http_service.cpp
@@ -28,7 +28,6 @@
#include <pthread.h>
#include <stdio.h>
#include <unistd.h>
-#include <chrono>
#include <cstdint>
#include <cstdlib>
#include <fstream>
@@ -42,6 +41,7 @@
#include "http/http_server.h"
#include "http/http_status_code.h"
#include "runtime/api_layer1.h"
+#include "utils/api_utilities.h"
#include "utils/blob.h"
#include "utils/defer.h"
#include "utils/fmt_logging.h"
@@ -98,8 +98,7 @@ static bool has_ext(const std::string &name, const
std::string &ext)
static int extract_symbols_from_binary(std::map<uintptr_t, std::string>
&addr_map,
const lib_info &lib_info)
{
- timer tm;
- tm.start();
+ SCOPED_LOG_TIMING(INFO, "load {}", lib_info.path);
std::string cmd = "nm -C -p ";
cmd.append(lib_info.path);
std::stringstream ss;
@@ -191,15 +190,12 @@ static int
extract_symbols_from_binary(std::map<uintptr_t, std::string> &addr_ma
if (addr_map.find(lib_info.end_addr) == addr_map.end()) {
addr_map[lib_info.end_addr] = std::string();
}
- tm.stop();
- LOG_INFO("Loaded {} in {}ms", lib_info.path, tm.m_elapsed().count());
return 0;
}
static void load_symbols()
{
- timer tm;
- tm.start();
+ SCOPED_LOG_TIMING(INFO, "load all symbols");
auto fp = fopen("/proc/self/maps", "r");
if (fp == nullptr) {
return;
@@ -270,9 +266,8 @@ static void load_symbols()
info.path = program_invocation_name;
extract_symbols_from_binary(symbol_map, info);
- timer tm2;
- tm2.start();
size_t num_removed = 0;
+ LOG_TIMING_IF(INFO, num_removed > 0, "removed {} entries", num_removed);
bool last_is_empty = false;
for (auto it = symbol_map.begin(); it != symbol_map.end();) {
if (it->second.empty()) {
@@ -287,13 +282,6 @@ static void load_symbols()
++it;
}
}
- tm2.stop();
- if (num_removed) {
- LOG_INFO("Removed {} entries in {}ms", num_removed,
tm2.m_elapsed().count());
- }
-
- tm.stop();
- LOG_INFO("Loaded all symbols in {}ms", tm.m_elapsed().count());
}
static void find_symbols(std::string *out, std::vector<uintptr_t> &addr_list)
diff --git a/src/utils/fmt_logging.h b/src/utils/fmt_logging.h
index 8e147466c..989e6eb91 100644
--- a/src/utils/fmt_logging.h
+++ b/src/utils/fmt_logging.h
@@ -349,3 +349,11 @@ inline const char *null_str_printer(const char *s) {
return s == nullptr ? "(nul
#define DCHECK_GT_PREFIX(var1, var2)
#define DCHECK_LT_PREFIX(var1, var2)
#endif
+
+// Macro that allows definition of a variable appended with the current line
+// number in the source file. Typically for use by other macros to allow the
+// user to declare multiple variables with the same "base" name inside the same
+// lexical block.
+#define VARNAME_LINENUM(varname) VARNAME_LINENUM_INTERNAL(varname##_L,
__LINE__)
+#define VARNAME_LINENUM_INTERNAL(v, line) VARNAME_LINENUM_INTERNAL2(v, line)
+#define VARNAME_LINENUM_INTERNAL2(v, line) v##line
diff --git a/src/utils/test/logging.cpp b/src/utils/test/logging.cpp
index b1dd6ed22..64eccf29e 100644
--- a/src/utils/test/logging.cpp
+++ b/src/utils/test/logging.cpp
@@ -24,13 +24,15 @@
* THE SOFTWARE.
*/
-#include <gtest/gtest.h>
#include <iostream>
#include <string>
+#include <utility>
+#include "gtest/gtest.h"
#include "utils/api_utilities.h"
#include "utils/fail_point.h"
#include "utils/fmt_logging.h"
+#include "utils/timer.h"
TEST(LoggingTest, GlobalLog)
{
@@ -67,3 +69,29 @@ TEST(LoggingTest, LogMacro)
dsn::fail::teardown();
}
+
+TEST(LoggingTest, TestLogTiming)
+{
+ LOG_TIMING_PREFIX_IF(INFO, true, "prefix", "foo test{}", 0) {}
+ LOG_TIMING_IF(INFO, true, "no_prefix foo test{}", 1) {}
+ LOG_TIMING_PREFIX(INFO, "prefix", "foo test{}", 2) {}
+ LOG_TIMING(INFO, "foo test{}", 3){}
+ {
+ SCOPED_LOG_TIMING(INFO, "bar {}", 0);
+ SCOPED_LOG_SLOW_EXECUTION(INFO, 1, "bar {}", 1);
+ SCOPED_LOG_SLOW_EXECUTION_PREFIX(INFO, 1, "prefix", "bar {}", 1);
+ }
+ LOG_SLOW_EXECUTION(INFO, 1, "baz {}", 0) {}
+
+ // Previous implementations of the above macro confused clang-tidy's
use-after-move
+ // check and generated false positives.
+ std::string s1 = "hello";
+ std::string s2;
+ LOG_SLOW_EXECUTION(INFO, 1, "baz")
+ {
+ LOG_INFO(s1);
+ s2 = std::move(s1);
+ }
+
+ ASSERT_EQ("hello", s2);
+}
diff --git a/src/utils/timer.h b/src/utils/timer.h
index 083b94067..ee5113ac7 100644
--- a/src/utils/timer.h
+++ b/src/utils/timer.h
@@ -17,7 +17,98 @@
#pragma once
+#include <string>
+
+#include "utils/api_utilities.h"
#include "utils/chrono_literals.h"
+#include "utils/fmt_logging.h"
+
+/// These macros are inspired by Apache Kudu
+/// https://github.com/apache/kudu/blob/1.17.0/src/kudu/util/stopwatch.h.
+
+// Macro for logging timing of a block. Usage:
+// LOG_TIMING_PREFIX_IF(INFO, FLAGS_should_record_time, "Tablet X: ", "doing
some task") {
+// ... some task which takes some time
+// }
+// If FLAGS_should_record_time is true, yields a log like:
+// I1102 14:35:51.726186 23082 file.cc:167] Tablet X: Time spent doing some
task:
+// real 3.729s user 3.570s sys 0.150s
+// The task will always execute regardless of whether the timing information is
+// printed.
+#define LOG_TIMING_PREFIX_IF(severity, condition, prefix, ...)
\
+ for (dsn::timer_internal::LogTiming _l(__FILENAME__,
\
+ __FUNCTION__,
\
+ __LINE__,
\
+ LOG_LEVEL_##severity,
\
+ prefix,
\
+ fmt::format(__VA_ARGS__),
\
+ -1,
\
+ (condition));
\
+ !_l.HasRun();
\
+ _l.MarkHasRun())
+
+// Conditionally log, no prefix.
+#define LOG_TIMING_IF(severity, condition, ...)
\
+ LOG_TIMING_PREFIX_IF(severity, (condition), "", (fmt::format(__VA_ARGS__)))
+
+// Always log, including prefix.
+#define LOG_TIMING_PREFIX(severity, prefix, ...)
\
+ LOG_TIMING_PREFIX_IF(severity, true, (prefix), (fmt::format(__VA_ARGS__)))
+
+// Always log, no prefix.
+#define LOG_TIMING(severity, ...) LOG_TIMING_IF(severity, true,
(fmt::format(__VA_ARGS__)))
+
+// Macro to log the time spent in the rest of the block.
+#define SCOPED_LOG_TIMING(severity, ...)
\
+ dsn::timer_internal::LogTiming VARNAME_LINENUM(_log_timing)(__FILENAME__,
\
+ __FUNCTION__,
\
+ __LINE__,
\
+
LOG_LEVEL_##severity, \
+ "",
\
+
fmt::format(__VA_ARGS__), \
+ -1,
\
+ true);
+
+// Scoped version of LOG_SLOW_EXECUTION().
+#define SCOPED_LOG_SLOW_EXECUTION(severity, max_expected_millis, ...)
\
+ dsn::timer_internal::LogTiming VARNAME_LINENUM(_log_timing)(__FILENAME__,
\
+ __FUNCTION__,
\
+ __LINE__,
\
+
LOG_LEVEL_##severity, \
+ "",
\
+
fmt::format(__VA_ARGS__), \
+
max_expected_millis, \
+ true)
+
+// Scoped version of LOG_SLOW_EXECUTION() but with a prefix.
+#define SCOPED_LOG_SLOW_EXECUTION_PREFIX(severity, max_expected_millis,
prefix, ...) \
+ dsn::timer_internal::LogTiming VARNAME_LINENUM(_log_timing)(__FILENAME__,
\
+ __FUNCTION__,
\
+ __LINE__,
\
+
LOG_LEVEL_##severity, \
+ prefix,
\
+
fmt::format(__VA_ARGS__), \
+
max_expected_millis, \
+ true)
+
+// Macro for logging timing of a block. Usage:
+// LOG_SLOW_EXECUTION(INFO, 5, "doing some task") {
+// ... some task which takes some time
+// }
+// when slower than 5 milliseconds, yields a log like:
+// I1102 14:35:51.726186 23082 file.cc:167] Time spent doing some task:
+// real 3.729s user 3.570s sys 0.150s
+#define LOG_SLOW_EXECUTION(severity, max_expected_millis, ...)
\
+ for (dsn::timer_internal::LogTiming _l(__FILENAME__,
\
+ __FUNCTION__,
\
+ __LINE__,
\
+ LOG_LEVEL_##severity,
\
+ "",
\
+ fmt::format(__VA_ARGS__),
\
+ max_expected_millis,
\
+ true);
\
+ !_l.HasRun();
\
+ _l.MarkHasRun())
namespace dsn {
@@ -59,4 +150,78 @@ private:
std::chrono::time_point<std::chrono::system_clock> _start;
};
+namespace timer_internal {
+// Internal class used by the LOG_TIMING* macros.
+class LogTiming
+{
+public:
+ LogTiming(const char *file,
+ const char *function,
+ int line,
+ log_level_t severity,
+ std::string prefix,
+ std::string description,
+ int64_t max_expected_millis,
+ bool should_print)
+ : file_(file),
+ function_(function),
+ line_(line),
+ severity_(severity),
+ prefix_(std::move(prefix)),
+ description_(std::move(description)),
+ max_expected_millis_(max_expected_millis),
+ should_print_(should_print),
+ has_run_(false)
+ {
+ stopwatch_.start();
+ }
+
+ ~LogTiming()
+ {
+ if (should_print_) {
+ Print(max_expected_millis_);
+ }
+ }
+
+ // Allows this object to be used as the loop variable in for-loop macros.
+ // Call HasRun() in the conditional check in the for-loop.
+ bool HasRun() { return has_run_; }
+
+ // Allows this object to be used as the loop variable in for-loop macros.
+ // Call MarkHasRun() in the "increment" section of the for-loop.
+ void MarkHasRun() { has_run_ = true; }
+
+private:
+ timer stopwatch_;
+ const char *file_;
+ const char *function_;
+ const int line_;
+ const log_level_t severity_;
+ const std::string prefix_;
+ const std::string description_;
+ const int64_t max_expected_millis_;
+ const bool should_print_;
+ bool has_run_;
+
+ // Print if the number of expected millis exceeds the max.
+ // Passing a negative number implies "always print".
+ void Print(int64_t max_expected_millis)
+ {
+ stopwatch_.stop();
+ auto ms = stopwatch_.m_elapsed();
+ if (max_expected_millis < 0 || ms.count() > max_expected_millis) {
+ global_log(file_,
+ function_,
+ line_,
+ severity_,
+ fmt::format("{}ime spent {}: {}ms",
+ prefix_.empty() ? "T" : fmt::format("{} t",
prefix_),
+ description_,
+ ms.count())
+ .c_str());
+ }
+ }
+};
+
+} // namespace timer_internal
} // namespace dsn
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
