KUDU-2297 (part 2). Convert diagnostics log to a format closer to glog Previously the metrics/diagnostics log used a custom log format designed to be readable by scripts. The only timestamps were unix microtimes, which are convenient for computers but not for people. In order to make the log more easily greppable, this patch converts it over to use a glog-compatible prefix on each log line.
The aim is that, if an admin sees some issues at 10/23 15:03 they can simply grep the diagnostics log for '1021 15:0[0-6]' rather than having to go figure out the appropriate range of numeric timestamps. This patch also updates the docs accordingly. Change-Id: I10d93c84f8c738c26850ae3d1ae6afbb5519c7ad Reviewed-on: http://gerrit.cloudera.org:8080/9327 Tested-by: Todd Lipcon <t...@apache.org> Reviewed-by: Mike Percy <mpe...@apache.org> Project: http://git-wip-us.apache.org/repos/asf/kudu/repo Commit: http://git-wip-us.apache.org/repos/asf/kudu/commit/6309fb18 Tree: http://git-wip-us.apache.org/repos/asf/kudu/tree/6309fb18 Diff: http://git-wip-us.apache.org/repos/asf/kudu/diff/6309fb18 Branch: refs/heads/master Commit: 6309fb182070761da0ec75930b293fdec69cdb5a Parents: a8b51b2 Author: Todd Lipcon <t...@apache.org> Authored: Wed Feb 14 13:27:14 2018 -0800 Committer: Todd Lipcon <t...@apache.org> Committed: Fri Feb 23 02:37:36 2018 +0000 ---------------------------------------------------------------------- docs/administration.adoc | 26 +++++++++++++++++--------- src/kudu/server/diagnostics_log.cc | 5 ++++- src/kudu/util/logging.cc | 20 ++++++++++++++++++-- src/kudu/util/logging.h | 4 +++- src/kudu/util/trace.cc | 20 ++++---------------- 5 files changed, 46 insertions(+), 29 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/kudu/blob/6309fb18/docs/administration.adoc ---------------------------------------------------------------------- diff --git a/docs/administration.adoc b/docs/administration.adoc index 78a70cc..4d1afe8 100644 --- a/docs/administration.adoc +++ b/docs/administration.adoc @@ -178,21 +178,29 @@ $ curl -s 'http://example-ts:8050/metrics?metrics=log_append_latency' NOTE: All histograms and counters are measured since the server start time, and are not reset upon collection. -=== Collecting metrics to a log - -Kudu may be configured to periodically dump all of its metrics to a local log file using the -`--metrics_log_interval_ms` flag. Set this flag to the interval at which metrics should be written -to a `diagnostics` log file. +=== Diagnostics Logging +Kudu may be configured to dump various diagnostics information to a local log file. The diagnostics log will be written to the same directory as the other Kudu log files, with a similar naming format, substituting `diagnostics` instead of a log level like `INFO`. After any diagnostics log file reaches 64MB uncompressed, the log will be rolled and the previous file will be gzip-compressed. -The log file generated has three space-separated fields. The first field is the word -`metrics`. The second field is the current timestamp in microseconds since the Unix epoch. -The third is the current value of all metrics on the server, using a compact JSON encoding. -The encoding is the same as the metrics fetched via HTTP described above. +Each line in the diagnostics log consists of the following components: + +* A human-readable timestamp formatted in the same fashion as the other Kudu log files. +* The type of record. For example, a metrics record consists of the word `metrics`. +* A machine-readable timestamp, in microseconds since the Unix epoch. +* The record itself. + +Currently, the only type of diagnostics record is a periodic dump of the server metrics. +Each record is encoded in compact JSON format, and the server attempts to elide any metrics +which have not changed since the previous record. In addition, counters which have never +been incremented are elided. Otherwise, the format of the JSON record is identical to the +format exposed by the HTTP endpoint above. + +The frequency with which metrics are dumped to the diagnostics log is configured using the +`--metrics_log_interval_ms` flag. By default, Kudu logs metrics every 60 seconds. == Common Kudu workflows http://git-wip-us.apache.org/repos/asf/kudu/blob/6309fb18/src/kudu/server/diagnostics_log.cc ---------------------------------------------------------------------- diff --git a/src/kudu/server/diagnostics_log.cc b/src/kudu/server/diagnostics_log.cc index 862fd81..fc91a3a 100644 --- a/src/kudu/server/diagnostics_log.cc +++ b/src/kudu/server/diagnostics_log.cc @@ -30,6 +30,7 @@ #include "kudu/util/condition_variable.h" #include "kudu/util/env.h" #include "kudu/util/jsonwriter.h" +#include "kudu/util/logging.h" #include "kudu/util/metrics.h" #include "kudu/util/monotime.h" #include "kudu/util/mutex.h" @@ -130,7 +131,9 @@ Status DiagnosticsLog::LogMetrics() { opts.include_entity_attributes = false; std::ostringstream buf; - buf << "metrics " << GetCurrentTimeMicros() << " "; + MicrosecondsInt64 now = GetCurrentTimeMicros(); + buf << "I" << FormatTimestampForLog(now) + << " metrics " << now << " "; // Collect the metrics JSON string. int64_t this_log_epoch = Metric::current_epoch(); http://git-wip-us.apache.org/repos/asf/kudu/blob/6309fb18/src/kudu/util/logging.cc ---------------------------------------------------------------------- diff --git a/src/kudu/util/logging.cc b/src/kudu/util/logging.cc index 02b6b95..fcf035f 100644 --- a/src/kudu/util/logging.cc +++ b/src/kudu/util/logging.cc @@ -18,8 +18,10 @@ #include <unistd.h> +#include <cstdint> #include <cstdio> #include <cstdlib> +#include <ctime> #include <fstream> #include <mutex> #include <utility> @@ -32,6 +34,7 @@ #include "kudu/gutil/callback.h" // IWYU pragma: keep #include "kudu/gutil/port.h" #include "kudu/gutil/spinlock.h" +#include "kudu/gutil/stringprintf.h" #include "kudu/gutil/strings/substitute.h" #include "kudu/util/async_logger.h" #include "kudu/util/debug-util.h" @@ -43,8 +46,6 @@ #include "kudu/util/signal.h" #include "kudu/util/status.h" -struct tm; - DEFINE_string(log_filename, "", "Prefix of log filename - " "full path is <log_dir>/<log_filename>.[INFO|WARN|ERROR|FATAL]"); @@ -342,6 +343,21 @@ void GetFullLogFilename(google::LogSeverity severity, string* filename) { *filename = ss.str(); } +std::string FormatTimestampForLog(MicrosecondsInt64 micros_since_epoch) { + time_t secs_since_epoch = micros_since_epoch / 1000000; + int usecs = micros_since_epoch % 1000000; + struct tm tm_time; + localtime_r(&secs_since_epoch, &tm_time); + + return StringPrintf("%02d%02d %02d:%02d:%02d.%06d", + 1 + tm_time.tm_mon, + tm_time.tm_mday, + tm_time.tm_hour, + tm_time.tm_min, + tm_time.tm_sec, + usecs); +} + void ShutdownLoggingSafe() { SpinLockHolder l(&logging_mutex); if (!logging_initialized) return; http://git-wip-us.apache.org/repos/asf/kudu/blob/6309fb18/src/kudu/util/logging.h ---------------------------------------------------------------------- diff --git a/src/kudu/util/logging.h b/src/kudu/util/logging.h index 442f94b..9aa06ac 100644 --- a/src/kudu/util/logging.h +++ b/src/kudu/util/logging.h @@ -17,7 +17,6 @@ #ifndef KUDU_UTIL_LOGGING_H #define KUDU_UTIL_LOGGING_H -#include <cstdint> #include <iosfwd> #include <string> @@ -293,6 +292,9 @@ void UnregisterLoggingCallback(); // file corresponding to this severity void GetFullLogFilename(google::LogSeverity severity, std::string* filename); +// Format a timestamp in the same format as used by GLog. +std::string FormatTimestampForLog(MicrosecondsInt64 micros_since_epoch); + // Shuts down the google logging library. Call before exit to ensure that log files are // flushed. void ShutdownLoggingSafe(); http://git-wip-us.apache.org/repos/asf/kudu/blob/6309fb18/src/kudu/util/trace.cc ---------------------------------------------------------------------- diff --git a/src/kudu/util/trace.cc b/src/kudu/util/trace.cc index 2dc4273..ac56660 100644 --- a/src/kudu/util/trace.cc +++ b/src/kudu/util/trace.cc @@ -19,7 +19,6 @@ #include <cstdint> #include <cstring> -#include <ctime> #include <iomanip> #include <iostream> #include <map> @@ -32,8 +31,9 @@ #include "kudu/gutil/strings/substitute.h" #include "kudu/gutil/walltime.h" -#include "kudu/util/memory/arena.h" #include "kudu/util/jsonwriter.h" +#include "kudu/util/logging.h" +#include "kudu/util/memory/arena.h" using std::pair; using std::string; @@ -153,11 +153,6 @@ void Trace::Dump(std::ostream* out, int flags) const { int64_t prev_usecs = 0; for (TraceEntry* e : entries) { // Log format borrowed from glog/logging.cc - time_t secs_since_epoch = e->timestamp_micros / 1000000; - int usecs = e->timestamp_micros % 1000000; - struct tm tm_time; - localtime_r(&secs_since_epoch, &tm_time); - int64_t usecs_since_prev = 0; if (prev_usecs != 0) { usecs_since_prev = e->timestamp_micros - prev_usecs; @@ -165,15 +160,8 @@ void Trace::Dump(std::ostream* out, int flags) const { prev_usecs = e->timestamp_micros; using std::setw; - out->fill('0'); - - *out << setw(2) << (1 + tm_time.tm_mon) - << setw(2) << tm_time.tm_mday - << ' ' - << setw(2) << tm_time.tm_hour << ':' - << setw(2) << tm_time.tm_min << ':' - << setw(2) << tm_time.tm_sec << '.' - << setw(6) << usecs << ' '; + *out << FormatTimestampForLog(e->timestamp_micros); + *out << ' '; if (flags & INCLUDE_TIME_DELTAS) { out->fill(' '); *out << "(+" << setw(6) << usecs_since_prev << "us) ";
