From 9bb13c56b3b14253f4eb17afa3330c5465e5f4a4 Mon Sep 17 00:00:00 2001 From: Andrew Kryczka Date: Fri, 12 Nov 2021 19:45:03 -0800 Subject: [PATCH] Use system-wide thread ID in info log lines (#9164) Summary: This makes it easier to debug with tools like `ps`. The change only applies to builds with glibc 2.30+ and _GNU_SOURCE extensions enabled. We could adopt it in more cases by using the syscall but this is enough for our build. Replaces https://github.com/facebook/rocksdb/issues/2973. Pull Request resolved: https://github.com/facebook/rocksdb/pull/9164 Test Plan: - ran some benchmarks and correlated logged thread IDs with those shown by `ps -L`. - verified no noticeable regression in throughput for log heavy (more than 700k log lines and over 5k / second) scenario. Benchmark command: ``` $ TEST_TMPDIR=/dev/shm ./db_bench -benchmarks=filluniquerandom -compression_type=none -max_bytes_for_level_multiplier=2 -write_buffer_size=262144 -num_levels=7 -max_bytes_for_level_base=2097152 -target_file_size_base=524288 -level_compaction_dynamic_level_bytes=true -max_background_jobs=12 -num=20000000 ``` Results before: 15.9MB/s, 15.8MB/s, 16.0MB/s Results after: 16.3MB/s, 16.3MB/s, 15.8MB/s - Rely on CI to test the fallback behavior Reviewed By: riversand963 Differential Revision: D32399660 Pulled By: ajkr fbshipit-source-id: c24d44fdf7782faa616ef0a0964eaca3539d9c24 --- HISTORY.md | 1 + env/env_posix.cc | 21 +++++++++++++-------- logging/posix_logger.h | 12 +++--------- 3 files changed, 17 insertions(+), 17 deletions(-) diff --git a/HISTORY.md b/HISTORY.md index 45938eae5..709cb9701 100644 --- a/HISTORY.md +++ b/HISTORY.md @@ -21,6 +21,7 @@ ### Public Interface Change * When options.ttl is used with leveled compaction with compactinon priority kMinOverlappingRatio, files exceeding half of TTL value will be prioritized more, so that by the time TTL is reached, fewer extra compactions will be scheduled to clear them up. At the same time, when compacting files with data older than half of TTL, output files may be cut off based on those files' boundaries, in order for the early TTL compaction to work properly. +* Info log ("LOG" file) lines now print a system-wide thread ID from `gettid()` when the compiler flags/glibc version make it available instead of the process-local `pthread_self()`. For all users, the thread ID format is changed from hexadecimal to decimal integer. ### Public API change * Made FileSystem extend the Customizable class and added a CreateFromString method. Implementations need to be registered with the ObjectRegistry and to implement a Name() method in order to be created via this method. diff --git a/env/env_posix.cc b/env/env_posix.cc index 712e75d74..be824fb4f 100644 --- a/env/env_posix.cc +++ b/env/env_posix.cc @@ -37,6 +37,8 @@ #include #endif #include +#include + #include // Get nano time includes #if defined(OS_LINUX) || defined(OS_FREEBSD) || defined(OS_GNU_KFREEBSD) @@ -302,19 +304,22 @@ class PosixEnv : public CompositeEnv { return thread_status_updater_->GetThreadList(thread_list); } - static uint64_t gettid(pthread_t tid) { + uint64_t GetThreadID() const override { uint64_t thread_id = 0; +#if defined(_GNU_SOURCE) && defined(__GLIBC_PREREQ) +#if __GLIBC_PREREQ(2, 30) + thread_id = ::gettid(); +#else // __GLIBC_PREREQ(2, 30) + pthread_t tid = pthread_self(); memcpy(&thread_id, &tid, std::min(sizeof(thread_id), sizeof(tid))); - return thread_id; - } - - static uint64_t gettid() { +#endif // __GLIBC_PREREQ(2, 30) +#else // defined(_GNU_SOURCE) && defined(__GLIBC_PREREQ) pthread_t tid = pthread_self(); - return gettid(tid); + memcpy(&thread_id, &tid, std::min(sizeof(thread_id), sizeof(tid))); +#endif // defined(_GNU_SOURCE) && defined(__GLIBC_PREREQ) + return thread_id; } - uint64_t GetThreadID() const override { return gettid(pthread_self()); } - Status GetHostName(char* name, uint64_t len) override { int ret = gethostname(name, static_cast(len)); if (ret < 0) { diff --git a/logging/posix_logger.h b/logging/posix_logger.h index 0bf14c3b6..115d42fdb 100644 --- a/logging/posix_logger.h +++ b/logging/posix_logger.h @@ -108,15 +108,9 @@ class PosixLogger : public Logger { const time_t seconds = now_tv.tv_sec; struct tm t; localtime_r(&seconds, &t); - p += snprintf(p, limit - p, - "%04d/%02d/%02d-%02d:%02d:%02d.%06d %llx ", - t.tm_year + 1900, - t.tm_mon + 1, - t.tm_mday, - t.tm_hour, - t.tm_min, - t.tm_sec, - static_cast(now_tv.tv_usec), + p += snprintf(p, limit - p, "%04d/%02d/%02d-%02d:%02d:%02d.%06d %llu ", + t.tm_year + 1900, t.tm_mon + 1, t.tm_mday, t.tm_hour, + t.tm_min, t.tm_sec, static_cast(now_tv.tv_usec), static_cast(thread_id)); // Print the message