From ad36c16d9156f14e6af2e15482f731b2feea65bd Mon Sep 17 00:00:00 2001 From: Roland Conybeare Date: Fri, 15 Sep 2023 16:30:34 -0400 Subject: [PATCH] nestlog: + time-of-day column --- example/ex3/ex3.cpp | 6 +- include/nestlog/log_config.hpp | 18 ++ include/nestlog/log_state.hpp | 33 ++- include/nestlog/scope.hpp | 5 + include/nestlog/time.hpp | 362 +++++++++++++++++++++++++++++++++ 5 files changed, 420 insertions(+), 4 deletions(-) create mode 100644 include/nestlog/time.hpp diff --git a/example/ex3/ex3.cpp b/example/ex3/ex3.cpp index 89d7ad2c..a0507147 100644 --- a/example/ex3/ex3.cpp +++ b/example/ex3/ex3.cpp @@ -21,10 +21,12 @@ fib(int n) { int main(int argc, char ** argv) { + log_config::time_enabled = true; + log_config::time_local_flag = true; log_config::style = FS_Streamlined; log_config::indent_width = 4; log_config::max_indent_width = 14; - log_config::location_tab = 70; + log_config::location_tab = 80; log_config::encoding = CE_Xterm; log_config::function_entry_color = 69; log_config::function_exit_color = 70; @@ -36,7 +38,7 @@ main(int argc, char ** argv) { int fn = fib(n); - xtag("n", n); + log(tag("n", n)); log("<-", xtag("fib(n)", fn)); } diff --git a/include/nestlog/log_config.hpp b/include/nestlog/log_config.hpp index cf5ea3aa..fa0d3902 100644 --- a/include/nestlog/log_config.hpp +++ b/include/nestlog/log_config.hpp @@ -10,6 +10,12 @@ namespace xo { /* Tag here b/c we want header-only library */ template struct log_config_impl { + /* true to log local time */ + static bool time_enabled; + /* true to log time-of-day in local coords; false for UTC coords */ + static bool time_local_flag; + /* true to log time-of-day with microsecond precision; false for millisecond precision */ + static bool time_usec_flag; /* spaces per nesting level */ static std::uint32_t indent_width; /* max #of spaces to introduce when indenting */ @@ -35,6 +41,18 @@ namespace xo { static std::uint32_t code_location_color; }; /*log_config_impl*/ + template + bool + log_config_impl::time_enabled = 1; + + template + bool + log_config_impl::time_local_flag = true; + + template + bool + log_config_impl::time_usec_flag = true; + template std::uint32_t log_config_impl::indent_width = 1; diff --git a/include/nestlog/log_state.hpp b/include/nestlog/log_state.hpp index 8273a6ec..06999ccb 100644 --- a/include/nestlog/log_state.hpp +++ b/include/nestlog/log_state.hpp @@ -7,6 +7,7 @@ #include "pad.hpp" #include "filename.hpp" #include "code_location.hpp" +#include "time.hpp" #include #include #include // for std::unique_ptr @@ -146,6 +147,29 @@ namespace xo { log_streambuf_type * sbuf = this->p_sbuf_phase1_.get(); sbuf->reset_stream(); + + /* e.g: + * + * 14:38:19.914 + * ------------- + * 0123456789012 + * 0 1 + * + * (13 chars including trailing space) + */ + if (log_config::time_enabled) { + if (log_config::time_local_flag) { + if (log_config::time_usec_flag) + this->ss_ << xo::time::hms_usec::local(xo::time::time::now()) << " "; + else + this->ss_ << xo::time::hms_msec::local(xo::time::time::now()) << " "; + } else { + if (log_config::time_usec_flag) + this->ss_ << xo::time::hms_usec::utc(xo::time::time::now()) << " "; + else + this->ss_ << xo::time::hms_msec::utc(xo::time::time::now()) << " "; + } + } this->indent(' '); char ee_label = '\0'; @@ -309,8 +333,13 @@ namespace xo { * - minimum indent = nesting level; * - however if space_after_nonspace defined, also indent for that */ - std::uint32_t n_indent = std::min(this->nesting_level_ * log_config::indent_width, - log_config::max_indent_width); + std::uint32_t n_indent = 0; + + if (log_config::time_enabled) + n_indent += 13; /*strlen("14:38:19.974 ")*/ + + n_indent += std::min(this->nesting_level_ * log_config::indent_width, + log_config::max_indent_width); /* this is just to indent for per-line entry/exit label */ if(space_after_nonspace) diff --git a/include/nestlog/scope.hpp b/include/nestlog/scope.hpp index 04451aaf..e343c9a3 100644 --- a/include/nestlog/scope.hpp +++ b/include/nestlog/scope.hpp @@ -118,6 +118,11 @@ namespace xo { } else { state_impl_type * logstate = require_indent_thread_local_state(); + /* indent for timestamp */ + if (log_config::time_enabled) + logstate->ss() << pad(13, ' '); + //logstate->indent(' '); + /* log to per-thread stream to prevent data races */ tosn(logstate2stream(logstate), std::forward(rest)...); diff --git a/include/nestlog/time.hpp b/include/nestlog/time.hpp new file mode 100644 index 00000000..04344195 --- /dev/null +++ b/include/nestlog/time.hpp @@ -0,0 +1,362 @@ +/* @file Time.hpp */ + +#pragma once + +#include +#include +#ifdef NOT_YET +# include +#endif +#include +#include +#include + +namespace xo { + namespace time { + + using utc_nanos = std::chrono::time_point; + + using nanos = std::chrono::nanoseconds; + using microseconds = std::chrono::microseconds; + using milliseconds = std::chrono::milliseconds; + using seconds = std::chrono::seconds; + using hours = std::chrono::hours; + using days = std::chrono::days; + + struct time { + static utc_nanos now() { + return utc_nanos(std::chrono::system_clock::now()); + } + + static utc_nanos epoch() { + return utc_nanos(std::chrono::system_clock::from_time_t(0)); + } /*epoch*/ + + static utc_nanos ymd_hms(uint32_t ymd, uint32_t hms) { + /* e.g. ymd=20220610 -> n_yr=2022, n_mon=06, n_dy=10 */ + + uint32_t n_yr = ymd / 10000; + uint32_t n_mon = (ymd % 10000) / 100; + uint32_t n_dy = ymd % 100; + + uint32_t n_hr = hms / 10000; + uint32_t n_min = (hms % 10000) / 100; + uint32_t n_sec = hms % 100; + + struct tm t; + + t.tm_year = n_yr - 1900; /* 0 means 1900 */ + t.tm_mon = n_mon - 1; /* 0 means january */ + t.tm_mday = n_dy; + + t.tm_hour = n_hr; /* 24 hour clock */ + t.tm_min = n_min; + t.tm_sec = n_sec; + + /* time since epoch */ + time_t epoch_time = timegm(&t); + + return std::chrono::system_clock::from_time_t(epoch_time); + } /*ymd_hms*/ + + /* midnight UTC on date ymd. + * e.g. ymd_midnight(20220707) -> midnight UTC on 7jul22 + */ + static utc_nanos ymd_midnight(uint32_t ymd) { + return ymd_hms(ymd, 0); + } /*ymd_midnight*/ + + static utc_nanos ymd_hms_usec(uint32_t ymd, uint32_t hms, uint32_t usec) { + utc_nanos s = ymd_hms(ymd, hms); + + return s + microseconds(usec); + } /*ymd_hms_usec*/ + + /* .first: UTC midnight on same calendar day as t0 + * .second: elapsed time from .first to t0 (i.e. UTC time-of-day for t0) + */ + static std::pair utc_split_vs_midnight(utc_nanos t0) { + using xo::time::microseconds; + using xo::time::utc_nanos; + + /* use yyyymmdd.hh:mm:ss.nnnnnn */ + + time_t t0_time_t = (std::chrono::system_clock::to_time_t + (std::chrono::time_point_cast(t0))); + + /* convert to std::tm, + * only provides 1-second precision + */ + std::tm t0_tm; + ::gmtime_r(&t0_time_t, &t0_tm); + + /* midnight on the same calendar day as t0_tm */ + std::tm midnight_tm = t0_tm; + { + midnight_tm.tm_hour = 0; + midnight_tm.tm_min = 0; + midnight_tm.tm_sec = 0; + } + + /* convert to UTC epoch seconds */ + time_t midnight_time_t = ::timegm(&midnight_tm); + + utc_nanos t0_midnight = + (std::chrono::time_point_cast( + std::chrono::system_clock::from_time_t(midnight_time_t))); + + nanos t0_tdy = t0 - t0_midnight; + + return std::pair(t0_midnight, t0_tdy); + } /*utc_split_vs_midnight*/ + + /* .first: LOCAL midnight on same calendar day as t0 (but in UTC coords) + * .second: elapsed time from .first to t0 (i.e. LOCAL time-of-day for t0) + */ + static std::pair local_split_vs_midnight(utc_nanos t0) { + using xo::time::microseconds; + using xo::time::utc_nanos; + + /* use yyyymmdd.hh:mm:ss.nnnnnn */ + + time_t t0_time_t = (std::chrono::system_clock::to_time_t + (std::chrono::time_point_cast(t0))); + + /* convert to std::tm, + * only provides 1-second precision + */ + std::tm t0_tm; + ::localtime_r(&t0_time_t, &t0_tm); + + /* midnight on the same calendar day as t0_tm */ + std::tm midnight_tm = t0_tm; + { + midnight_tm.tm_hour = 0; + midnight_tm.tm_min = 0; + midnight_tm.tm_sec = 0; + } + + /* convert local midnight to UTC epoch seconds */ + time_t midnight_time_t = ::timelocal(&midnight_tm); + + utc_nanos t0_midnight = + (std::chrono::time_point_cast( + std::chrono::system_clock::from_time_t(midnight_time_t))); + + nanos t0_tdy = t0 - t0_midnight; + + return std::pair(t0_midnight, t0_tdy); + } /*local_split_vs_midnight*/ + + /* split utc_nanos into + * std::tm + * .tm_year + * .tm_mon (1-12) + * .tm_mday (1-31) + * .tm_hour (0-23) + * .tm_min (0-59) + * .tm_sec (0-59) + * .tm_wday (0=sunday .. 6=saturday) + * .tm_yday (0=1jan .. 365) + * .tm_isdst (daylight savings time flag) + * usec (0-999999) + */ + static std::pair split_tm(utc_nanos t0) { + using xo::time::microseconds; + using xo::time::utc_nanos; + + /* use yyyymmdd.hh:mm:ss.nnnnnn */ + + time_t t0_time_t = (std::chrono::system_clock::to_time_t + (std::chrono::time_point_cast(t0))); + + /* convert to std::tm, un UTC coords, + * only provides 1-second precision + */ + std::tm t0_tm; + ::gmtime_r(&t0_time_t, &t0_tm); + + /* midnight on the same calendar day as t0_tm */ + std::tm midnight_tm = t0_tm; + + midnight_tm.tm_isdst = 0; + midnight_tm.tm_hour = 0; + midnight_tm.tm_min = 0; + midnight_tm.tm_sec = 0; + + /* convert back to epoch seconds */ + time_t midnight_time_t = ::mktime(&midnight_tm); + + utc_nanos t0_midnight = + (std::chrono::time_point_cast( + std::chrono::system_clock::from_time_t(midnight_time_t))); + + uint32_t usec = + (std::chrono::duration_cast( + std::chrono::hh_mm_ss(t0 - t0_midnight).subseconds())) + .count(); + + return std::make_pair(t0_tm, usec); + } /*split_tm*/ + + static void print_hms_msec(nanos dt, std::ostream & os) { + /* use hhmmss.nnn */ + using std::int32_t; + + auto hms = std::chrono::hh_mm_ss(dt); + int32_t h = hms.hours().count(); + int32_t m = hms.minutes().count(); + int32_t s = hms.seconds().count(); + int32_t msec = std::chrono::duration_cast(hms.subseconds()).count(); + + char buf[32]; + snprintf(buf, sizeof(buf), "%02d:%02d:%02d.%03d", h, m, s, msec); + + os << buf; + } /*print_hms_msec*/ + + static void print_utc_hms_msec(utc_nanos t0, std::ostream & os) { + print_hms_msec(utc_split_vs_midnight(t0).second, os); + } /*print_utc_hms_usec*/ + + static void print_hms_usec(nanos dt, std::ostream & os) { + /* use hhmmss.uuuuuu */ + using std::int32_t; + + auto hms = std::chrono::hh_mm_ss(dt); + int32_t h = hms.hours().count(); + int32_t m = hms.minutes().count(); + int32_t s = hms.seconds().count(); + int32_t usec = std::chrono::duration_cast(hms.subseconds()).count(); + + char buf[32]; + snprintf(buf, sizeof(buf), "%02d:%02d:%02d.%06d", h, m, s, usec); + + os << buf; + } /*print_hms_usec*/ + + static void print_utc_ymd_hms_usec(utc_nanos t0, std::ostream & os) { + using xo::time::microseconds; + using xo::time::utc_nanos; + + /* use yyyymmdd.hh:mm:ss.nnnnnn */ + + //std::tm t0_tm; + //uint32_t t0_usec; + + /* (structured binding ftw!) */ + auto [t0_tm, t0_usec] = split_tm(t0); + + /* no std::format in clang11 afaict */ + char usec_buf[7]; + snprintf(usec_buf, sizeof(usec_buf), "%06d", t0_usec); + + + /* control string | example + * ----------------------------+-------------------------- + * %c - locale-specific string | Fri Jun 10 16:29:05 2022 + * %Y - year | 2022 + * %m - month | 06 + * %d - day of month | 10 + * %H - hour | 16 + * %M - minute | 29 + * %S - second | 05 + * %Z - timezone | UTC + */ + os << std::put_time(&t0_tm, "%Y%m%d:%H:%M:%S.") << usec_buf; + } /*print_utc_ymd_hms_usec*/ + + /* print datetime in format compatible with ISO 8601. + * copying the format javascript uses, e.g: + * 2012-04-23T18:25:43.511Z + */ + static void print_iso8601(utc_nanos t0, std::ostream & os) { + auto [t0_tm, t0_usec] = split_tm(t0); + + char msec_buf[8]; + snprintf(msec_buf, sizeof(msec_buf), "%03d", t0_usec / 1000); + + os << std::put_time(&t0_tm, "%Y-%m-%dT%H:%M:%S.") << msec_buf << "Z"; + } /*print_iso8601*/ + }; /*time*/ + + /* stream inserter that displays time in ISO 8601 format: + * 2012-04-23T18:25:43.511Z + */ + struct iso8601 { + iso8601(utc_nanos t0) : t0_{t0} {} + + utc_nanos t0_; + }; /*iso8601*/ + + inline std::ostream & + operator<<(std::ostream & os, + iso8601 x) + { + time::print_iso8601(x.t0_, os); + return os; + } /*operator<<*/ + + /* stream inserter that display time like: + * hh:mm:ss.nnn + */ + struct hms_msec { + hms_msec(nanos dt) : dt_{dt} {} + + static hms_msec utc(utc_nanos t0) { return hms_msec(time::utc_split_vs_midnight(t0).second); } + static hms_msec local(utc_nanos t0) { return hms_msec(time::local_split_vs_midnight(t0).second); } + + nanos dt_; + }; /*hms_msec*/ + + inline std::ostream & + operator<<(std::ostream & os, hms_msec x) + { + time::print_hms_msec(x.dt_, os); + return os; + } /*operator<<*/ + + + /* stream inserter that display time like: + * hh:mm:ss.nnnnnn + */ + struct hms_usec { + hms_usec(nanos dt) : dt_{dt} {} + + static hms_usec utc(utc_nanos t0) { return hms_usec(time::utc_split_vs_midnight(t0).second); } + static hms_usec local(utc_nanos t0) { return hms_usec(time::local_split_vs_midnight(t0).second); } + + nanos dt_; + }; /*hms_msec*/ + + inline std::ostream & + operator<<(std::ostream & os, hms_usec x) + { + time::print_hms_usec(x.dt_, os); + return os; + } /*operator<<*/ + + + } /*namespace time*/ +} /*namespace xo*/ + +namespace std { + namespace chrono { + inline std::ostream & operator<<(std::ostream & os, + xo::time::utc_nanos t0) + { + xo::time::time::print_utc_ymd_hms_usec(t0, os); + return os; + } /*operator<<*/ + + inline std::ostream & operator<<(std::ostream & os, + xo::time::nanos dt) + { + xo::time::time::print_hms_usec(dt, os); + return os; + } /*operator<<*/ + } /*namespace chrono*/ +} /*namespace std*/ + +/* end Time.hpp */