Logging: don't emit ANSI color codes if !isatty()
This CL makes a bunch of changes to logging:
- Move the core logic to a dedicated .cc file
- Add a timestamp in front of the logs (wall time % 1000)
to better debug across processe (not in the logcat case)s.
- Enables the coloured output only when stderr is a tty.
- Fixes the truncation of the filename to be left-truncated
rather than right-truncated (which is more useful in general).
Bug: 145150184
Change-Id: Idd7864057ed9411cea0da94ffb7ef520c21bef4f
diff --git a/Android.bp b/Android.bp
index b722a95..6922b3b 100644
--- a/Android.bp
+++ b/Android.bp
@@ -4047,6 +4047,7 @@
srcs: [
"src/base/event_fd.cc",
"src/base/file_utils.cc",
+ "src/base/logging.cc",
"src/base/metatrace.cc",
"src/base/paged_memory.cc",
"src/base/pipe.cc",
diff --git a/BUILD b/BUILD
index 4d81a97..3b8cfc5 100644
--- a/BUILD
+++ b/BUILD
@@ -465,6 +465,7 @@
srcs = [
"src/base/event_fd.cc",
"src/base/file_utils.cc",
+ "src/base/logging.cc",
"src/base/metatrace.cc",
"src/base/paged_memory.cc",
"src/base/pipe.cc",
diff --git a/include/perfetto/base/compiler.h b/include/perfetto/base/compiler.h
index 0f08b42..d40fb5b 100644
--- a/include/perfetto/base/compiler.h
+++ b/include/perfetto/base/compiler.h
@@ -47,6 +47,13 @@
static_assert(false, "Not implemented for this compiler")
#endif
+#if defined(__GNUC__) || defined(__clang__)
+#define PERFETTO_PRINTF_FORMAT(x, y) \
+ __attribute__((__format__(__printf__, x, y)))
+#else
+#defien PERFETTO_PRINTF_FORMAT(x, y)
+#endif
+
namespace perfetto {
namespace base {
diff --git a/include/perfetto/base/logging.h b/include/perfetto/base/logging.h
index 2dda900..a8ba946 100644
--- a/include/perfetto/base/logging.h
+++ b/include/perfetto/base/logging.h
@@ -18,14 +18,12 @@
#define INCLUDE_PERFETTO_BASE_LOGGING_H_
#include <errno.h>
-#include <stdio.h>
-#include <stdlib.h>
#include <string.h> // For strerror.
#include "perfetto/base/build_config.h"
#include "perfetto/base/compiler.h"
-// TODO(primiano): movee this to base/build_config.h, turn into
+// TODO(primiano): move this to base/build_config.h, turn into
// PERFETTO_BUILDFLAG(DCHECK_IS_ON) and update call sites to use that instead.
#if defined(NDEBUG) && !defined(DCHECK_ALWAYS_ON)
#define PERFETTO_DCHECK_IS_ON() 0
@@ -54,10 +52,6 @@
#include <android/log.h>
#endif
-#if !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
-#include <unistd.h>
-#endif
-
namespace perfetto {
namespace base {
@@ -78,51 +72,22 @@
return BasenameRecursive(StrEnd(str), str, StrEnd(str));
}
-#define PERFETTO_LOG_LINE__(x) #x
-#define PERFETTO_LOG_LINE_(x) PERFETTO_LOG_LINE__(x)
-#define PERFETTO_LOG_LINE PERFETTO_LOG_LINE_(__LINE__)
-
enum LogLev { kLogDebug = 0, kLogInfo, kLogImportant, kLogError };
-#if PERFETTO_BUILDFLAG(PERFETTO_OS_WIN) || PERFETTO_BUILDFLAG(PERFETTO_OS_WASM)
-// The escape sequences don't work in a Windows command prompt.
-#define PERFETTO_XLOG_STDERR(level, fmt, ...) \
- fprintf(stderr, "%-24.24s " fmt "\n", \
- ::perfetto::base::Basename(__FILE__ "(" PERFETTO_LOG_LINE "):"), \
- ##__VA_ARGS__)
-#else
-constexpr const char* kLogFmt[] = {"\x1b[2m", "\x1b[39m", "\x1b[32m\x1b[1m",
- "\x1b[31m"};
-#define PERFETTO_XLOG_STDERR(level, fmt, ...) \
- fprintf(stderr, "\x1b[90m%-24.24s\x1b[0m %s" fmt "\x1b[0m\n", \
- ::perfetto::base::Basename(__FILE__ ":" PERFETTO_LOG_LINE), \
- ::perfetto::base::kLogFmt[::perfetto::base::LogLev::level], \
- ##__VA_ARGS__)
-#endif
+void LogMessage(LogLev, const char* fname, int line, const char* fmt, ...)
+ PERFETTO_PRINTF_FORMAT(4, 5);
-#if PERFETTO_BUILDFLAG(PERFETTO_OS_ANDROID) && \
- defined(PERFETTO_ANDROID_ASYNC_SAFE_LOG)
-#define PERFETTO_XLOG(level, fmt, ...) \
- do { \
- async_safe_format_log( \
- (ANDROID_LOG_DEBUG + ::perfetto::base::LogLev::level), "perfetto", \
- "%s " fmt, ::perfetto::base::Basename(__FILE__ ":" PERFETTO_LOG_LINE), \
- ##__VA_ARGS__); \
- } while (0)
-#elif PERFETTO_BUILDFLAG(PERFETTO_OS_ANDROID)
-// Standard logging marco on Android - log to both stderr and logcat. When part
-// of the Android tree, stderr points to /dev/null so logcat is the only way to
-// get some logging.
-#define PERFETTO_XLOG(level, fmt, ...) \
- do { \
- __android_log_print( \
- (ANDROID_LOG_DEBUG + ::perfetto::base::LogLev::level), "perfetto", \
- "%s " fmt, ::perfetto::base::Basename(__FILE__ ":" PERFETTO_LOG_LINE), \
- ##__VA_ARGS__); \
- PERFETTO_XLOG_STDERR(level, fmt, ##__VA_ARGS__); \
+#if defined(PERFETTO_ANDROID_ASYNC_SAFE_LOG)
+#define PERFETTO_XLOG(level, fmt, ...) \
+ do { \
+ async_safe_format_log((ANDROID_LOG_DEBUG + level), "perfetto", \
+ "%s:%d " fmt, ::perfetto::base::Basename(__FILE__), \
+ __LINE__, ##__VA_ARGS__); \
} while (0)
#else
-#define PERFETTO_XLOG PERFETTO_XLOG_STDERR
+#define PERFETTO_XLOG(level, fmt, ...) \
+ ::perfetto::base::LogMessage(level, ::perfetto::base::Basename(__FILE__), \
+ __LINE__, fmt, ##__VA_ARGS__)
#endif
#define PERFETTO_IMMEDIATE_CRASH() \
@@ -131,9 +96,12 @@
__builtin_unreachable(); \
} while (0)
-#define PERFETTO_LOG(fmt, ...) PERFETTO_XLOG(kLogInfo, fmt, ##__VA_ARGS__)
-#define PERFETTO_ILOG(fmt, ...) PERFETTO_XLOG(kLogImportant, fmt, ##__VA_ARGS__)
-#define PERFETTO_ELOG(fmt, ...) PERFETTO_XLOG(kLogError, fmt, ##__VA_ARGS__)
+#define PERFETTO_LOG(fmt, ...) \
+ PERFETTO_XLOG(::perfetto::base::kLogInfo, fmt, ##__VA_ARGS__)
+#define PERFETTO_ILOG(fmt, ...) \
+ PERFETTO_XLOG(::perfetto::base::kLogImportant, fmt, ##__VA_ARGS__)
+#define PERFETTO_ELOG(fmt, ...) \
+ PERFETTO_XLOG(::perfetto::base::kLogError, fmt, ##__VA_ARGS__)
#define PERFETTO_FATAL(fmt, ...) \
do { \
PERFETTO_PLOG(fmt, ##__VA_ARGS__); \
@@ -145,7 +113,8 @@
#if PERFETTO_DLOG_IS_ON()
-#define PERFETTO_DLOG(fmt, ...) PERFETTO_XLOG(kLogDebug, fmt, ##__VA_ARGS__)
+#define PERFETTO_DLOG(fmt, ...) \
+ PERFETTO_XLOG(::perfetto::base::kLogDebug, fmt, ##__VA_ARGS__)
#define PERFETTO_DPLOG(x, ...) \
PERFETTO_DLOG(x " (errno: %d, %s)", ##__VA_ARGS__, errno, strerror(errno))
diff --git a/src/base/BUILD.gn b/src/base/BUILD.gn
index 0e7a0d0..8a334b5 100644
--- a/src/base/BUILD.gn
+++ b/src/base/BUILD.gn
@@ -29,6 +29,7 @@
]
sources = [
"file_utils.cc",
+ "logging.cc",
"metatrace.cc",
"paged_memory.cc",
"string_splitter.cc",
diff --git a/src/base/logging.cc b/src/base/logging.cc
new file mode 100644
index 0000000..9832c18
--- /dev/null
+++ b/src/base/logging.cc
@@ -0,0 +1,117 @@
+/*
+ * Copyright (C) 2019 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include "perfetto/base/logging.h"
+
+#include <stdarg.h>
+#include <stdio.h>
+
+#if !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
+#include <unistd.h> // For isatty()
+#endif
+
+#include "perfetto/base/time.h"
+
+namespace perfetto {
+namespace base {
+
+namespace {
+const char kReset[] = "\x1b[0m";
+const char kDefault[] = "\x1b[39m";
+const char kDim[] = "\x1b[2m";
+const char kRed[] = "\x1b[31m";
+const char kBoldGreen[] = "\x1b[1m\x1b[32m";
+const char kLightGray[] = "\x1b[90m";
+
+} // namespace
+
+void LogMessage(LogLev level,
+ const char* fname,
+ int line,
+ const char* fmt,
+ ...) {
+ va_list args;
+ va_start(args, fmt);
+ char log_msg[1024];
+ vsnprintf(log_msg, sizeof(log_msg), fmt, args);
+ va_end(args);
+
+ const char* color = kDefault;
+ switch (level) {
+ case kLogDebug:
+ color = kDim;
+ break;
+ case kLogInfo:
+ color = kDefault;
+ break;
+ case kLogImportant:
+ color = kBoldGreen;
+ break;
+ case kLogError:
+ color = kRed;
+ break;
+ }
+
+#if !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN) && \
+ !PERFETTO_BUILDFLAG(PERFETTO_OS_WASM)
+ static const bool use_colors = isatty(STDERR_FILENO);
+#else
+ static const bool use_colors = false;
+#endif
+
+ // Formats file.cc:line as a space-padded fixed width string. If the file name
+ // |fname| is too long, truncate it on the left-hand side.
+ char line_str[10];
+ size_t line_len =
+ static_cast<size_t>(snprintf(line_str, sizeof(line_str), "%d", line));
+
+ // 24 will be the width of the file.cc:line column in the log event.
+ char file_and_line[24];
+ size_t fname_len = strlen(fname);
+ size_t fname_max = sizeof(file_and_line) - line_len - 2; // 2 = ':' + '\0'.
+ size_t fname_offset = fname_len <= fname_max ? 0 : fname_len - fname_max;
+ int len = snprintf(file_and_line, sizeof(file_and_line), "%s:%s",
+ fname + fname_offset, line_str);
+ memset(&file_and_line[len], ' ', sizeof(file_and_line) - size_t(len));
+ file_and_line[sizeof(file_and_line) - 1] = '\0';
+
+#if PERFETTO_BUILDFLAG(PERFETTO_OS_ANDROID)
+ // Logcat has already timestamping, don't re-emit it.
+ __android_log_print(ANDROID_LOG_DEBUG + level, "perfetto", "%s %s",
+ file_and_line, log_msg);
+#endif
+
+ // When printing on stderr, print also the timestamp. We don't really care
+ // about the actual time. We just need some reference clock that can be used
+ // to correlated events across differrent processses (e.g. traced and
+ // traced_probes). The wall time % 1000 is good enough.
+ char timestamp[32];
+ int t_ms = static_cast<int>(GetWallTimeMs().count());
+ int t_sec = t_ms / 1000;
+ t_ms -= t_sec * 1000;
+ t_sec = t_sec % 1000;
+ snprintf(timestamp, sizeof(timestamp), "[%03d.%03d] ", t_sec, t_ms);
+
+ if (use_colors) {
+ fprintf(stderr, "%s%s%s%s %s%s%s\n", kLightGray, timestamp, file_and_line,
+ kReset, color, log_msg, kReset);
+ } else {
+ fprintf(stderr, "%s%s %s\n", timestamp, file_and_line, log_msg);
+ }
+}
+
+} // namespace base
+} // namespace perfetto
diff --git a/src/tracing/api_impl/consumer_api_test.cc b/src/tracing/api_impl/consumer_api_test.cc
index ce8883a..220d72d 100644
--- a/src/tracing/api_impl/consumer_api_test.cc
+++ b/src/tracing/api_impl/consumer_api_test.cc
@@ -18,6 +18,8 @@
#include <array>
#include <atomic>
+#include <chrono>
+#include <thread>
#include "perfetto/base/logging.h"
#include "perfetto/public/consumer_api.h"
@@ -92,12 +94,12 @@
auto handle = Create(cfg.data(), cfg.size(), &OnStateChanged, &g_pointer);
PERFETTO_ILOG("Starting, handle=%" PRId64 " state=%d", handle,
static_cast<int>(PollState(handle)));
- usleep(100000);
+ std::this_thread::sleep_for(std::chrono::milliseconds(100));
StartTracing(handle);
// Wait for either completion or error.
while (static_cast<int>(PollState(handle)) > 0 &&
PollState(handle) != State::kTraceEnded) {
- usleep(10000);
+ std::this_thread::sleep_for(std::chrono::milliseconds(10));
}
if (PollState(handle) == State::kTraceEnded) {
@@ -130,14 +132,14 @@
all_connected = false;
}
}
- usleep(10000);
+ std::this_thread::sleep_for(std::chrono::milliseconds(10));
}
// Start only 3 out of 5 sessions, scattering them with 1 second delay.
for (size_t i = 0; i < handles.size(); i++) {
if (i % 2 == 0) {
StartTracing(handles[i]);
- sleep(1);
+ std::this_thread::sleep_for(std::chrono::seconds(1));
}
}
@@ -149,7 +151,7 @@
num_complete++;
}
}
- usleep(10000);
+ std::this_thread::sleep_for(std::chrono::milliseconds(10));
}
// Read the trace buffers.
diff --git a/test/client_api_example.cc b/test/client_api_example.cc
index e0f813d..62f04c6 100644
--- a/test/client_api_example.cc
+++ b/test/client_api_example.cc
@@ -16,6 +16,7 @@
#include "perfetto/tracing.h"
+#include <chrono>
#include <thread>
#include "protos/perfetto/config/gpu/gpu_counter_config.pbzero.h"
@@ -100,6 +101,6 @@
auto* cnt = gpu_packet->add_counters();
cnt->set_counter_id(1);
});
- sleep(1);
+ std::this_thread::sleep_for(std::chrono::seconds(1));
}
}
diff --git a/tools/trace_to_text/main.cc b/tools/trace_to_text/main.cc
index efcc053..8d1e811 100644
--- a/tools/trace_to_text/main.cc
+++ b/tools/trace_to_text/main.cc
@@ -14,6 +14,8 @@
* limitations under the License.
*/
+#include <stdio.h>
+
#include <fstream>
#include <iostream>
#include <limits>
@@ -34,6 +36,10 @@
#define PERFETTO_GET_GIT_REVISION() "unknown"
#endif
+#if !PERFETTO_BUILDFLAG(PERFETTO_OS_WIN)
+#include <unistd.h>
+#endif
+
namespace perfetto {
namespace trace_to_text {
namespace {