diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index b7795ab..08e3088 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -2,6 +2,14 @@ set (DATADIR "${CMAKE_INSTALL_PREFIX}/share") set (PKGDATADIR "${DATADIR}/dm_logger") set (GETTEXT_PACKAGE "dm_logger") set (CMAKE_C_FLAGS "-g -O3") + +# Required so MinGW's exposes the inline localtime_r/gmtime_r +# shims (they forward to MSVC's localtime_s under the hood). On glibc +# this macro is a no-op -- localtime_r is always declared there. +# Verified against x86_64-w64-mingw32-gcc 9.2.0; older MinGW-w64 +# versions (pre-v4.0, ~2015) will fail loudly with +# "undefined reference to localtime_r" on the first cross-build. +add_definitions(-D_POSIX_THREAD_SAFE_FUNCTIONS=1) set (PREFIX ${CMAKE_INSTALL_PREFIX}) set (DOLLAR "$") @@ -22,6 +30,18 @@ set (VALA_PACKAGES ${VALA_PACKAGES} zlib) set (DM_LOGGER_SOURCES dm_logger.vala) set (DM_LOGREADER_SOURCES dm_logreader.vala) +# Needed so the C generated by valac finds our private dm_logger_tls.h +# (declares the __thread cache backing format_log_timestamp). +# UseVala copies the .vala source into ${CMAKE_CURRENT_BINARY_DIR} and +# only adds that directory to the include path of the generated C, so +# we mirror the header there too. +include_directories(${CMAKE_CURRENT_SOURCE_DIR}) +configure_file( + ${CMAKE_CURRENT_SOURCE_DIR}/dm_logger_tls.h + ${CMAKE_CURRENT_BINARY_DIR}/dm_logger_tls.h + COPYONLY +) + vala_precompile(DM_LOGGER_VALA_C ${DM_LOGGER_SOURCES} PACKAGES @@ -51,6 +71,7 @@ OPTIONS add_library( ${DM_LOGGER_NAME} SHARED ${DM_LOGGER_VALA_C} + dm_logger_tls.c ) add_executable( dm_logreader diff --git a/src/dm_logger.vala b/src/dm_logger.vala index 4ce2b88..4ed4788 100644 --- a/src/dm_logger.vala +++ b/src/dm_logger.vala @@ -31,6 +31,113 @@ namespace DMLogger public static Logger log; + /* ----- Fast timestamp formatting (perf hot path) ----- + * + * The previous implementation built a fresh GTimeZone + GDateTime + * for every log entry. Profiling (callgrind.out.61062) showed that + * this single line was responsible for ~30 % of total docTYPE + * runtime (9.7 G of 28.8 G instructions), because + * g_time_zone_new("local") parses /etc/localtime on every call. + * + * We replace it with libc's localtime_r + strftime, and cache the + * formatted "YYYY-MM-DD HH:MM:SS" prefix per whole second so that + * bursts of log entries in the same second skip strftime entirely. + * + * Thread-safety: in threaded mode this helper runs only on the + * dedicated writer thread (Logger.run). In not-threaded mode it is + * called directly from whichever application thread invoked + * Logger.debug/info/warning/error/..., so two threads can enter + * concurrently. To avoid a torn/wrong cache without adding a mutex + * on the hot path, the cache is held in thread-local storage via + * the __thread storage-class specifier (supported by GCC, Clang and + * MinGW, which are the only compilers we build with). + */ + + [CCode (cname = "localtime_r", cheader_filename = "time.h")] + private extern unowned Posix.tm? _dm_logger_localtime_r( ref time_t timep, out Posix.tm result ); + + [CCode (cname = "strftime", cheader_filename = "time.h")] + private extern size_t _dm_logger_strftime( char* s, size_t max, string format, Posix.tm* tm ); + + /* Per-second cache backing format_log_timestamp(), held in + * thread-local storage so concurrent callers (not-threaded mode) + * never race on it. + * + * The actual storage lives in dm_logger_tls.c, declared with the + * __thread storage-class specifier. We can't declare __thread + * variables directly in Vala: a [CCode (cname = "__thread ...")] + * trick fails because Vala still emits its own type in front of + * the cname ("gint64 __thread int64 foo;" -> C syntax error). + * Pulling them in as plain externs via cheader_filename sidesteps + * that: Vala just emits references, not declarations. */ + [CCode (cname = "_dm_logger_ts_cached_seconds", cheader_filename = "dm_logger_tls.h")] + private extern int64 _dm_logger_ts_cached_seconds; + + [CCode (cname = "_dm_logger_ts_cached_prefix", cheader_filename = "dm_logger_tls.h", array_length = false)] + private extern char _dm_logger_ts_cached_prefix[20]; + + [CCode (cname = "_dm_logger_ts_cached_valid", cheader_filename = "dm_logger_tls.h")] + private extern bool _dm_logger_ts_cached_valid; + + /** + * Formats the timestamp portion of a log line into the caller-supplied + * buffer as "YYYY-MM-DD HH:MM:SS" (19 chars + trailing NUL). + * + * @param tstamp_usec Wall-clock time in microseconds since the UNIX epoch + * (same units as LogEntry.tstamp). + * @param buf Caller-allocated buffer; must be at least 20 bytes. + * On success it contains a NUL-terminated string. + * + * Thread-safe via per-thread cache; see comment block above. + */ + public void format_log_timestamp( int64 tstamp_usec, char[] buf ) + { + if ( buf.length < 20 ) + { + stderr.printf( "format_log_timestamp requires a buffer with at least 20 bytes, but only %d were allocated!\n", buf.length ); + return; + } + + _format_log_timestamp( tstamp_usec, buf ); + } + + private void _format_log_timestamp( int64 tstamp_usec, char[] buf ) + { + int64 seconds = tstamp_usec / (int64)1000000; + + if ( !_dm_logger_ts_cached_valid || seconds != _dm_logger_ts_cached_seconds ) + { + time_t t = (time_t)seconds; + Posix.tm tm_local = Posix.tm(); + if ( _dm_logger_localtime_r( ref t, out tm_local ) != null ) + { + size_t n = _dm_logger_strftime( (char*)_dm_logger_ts_cached_prefix, 20, + "%Y-%m-%d %H:%M:%S", &tm_local ); + if ( n == 0 ) + { + /* Cold fallback: strftime ran out of room (impossible with + * our 20-byte buffer for this format, but be safe). */ + GLib.Memory.copy( _dm_logger_ts_cached_prefix, "????-??-?? ??:??:??\0".data, 20 ); + } + } + else + { + /* localtime_r failed (only happens for absurd time_t values + * on 32-bit builds). Emit a placeholder but do not cache it + * so the next call retries. */ + GLib.Memory.copy( _dm_logger_ts_cached_prefix, "????-??-?? ??:??:??\0".data, 20 ); + _dm_logger_ts_cached_seconds = seconds; + /* _dm_logger_ts_cached_valid intentionally left false */ + GLib.Memory.copy( buf, _dm_logger_ts_cached_prefix, 20 ); + return; + } + _dm_logger_ts_cached_seconds = seconds; + _dm_logger_ts_cached_valid = true; + } + + GLib.Memory.copy( buf, _dm_logger_ts_cached_prefix, 20 ); + } + /* Ab diesem Trace-Level soll geloggt werden */ public int log_trace_level = 0; @@ -434,8 +541,9 @@ namespace DMLogger out_stream.printf( "INFO " ); } - DMDateTime dt = new DMDateTime.from_unix_local( (int64)( this.tstamp / (int64)1000000 ) ); - out_stream.printf( "[%s.%06lld] ", dt.format( "%F %H:%M:%S" ), (int64)( this.tstamp % (int64)1000000 ) ); + char ts_buf[20]; + _format_log_timestamp( this.tstamp, ts_buf ); + out_stream.printf( "[%s.%06lld] ", (string)ts_buf, (int64)( this.tstamp % (int64)1000000 ) ); if ( debug_mode == true ) { diff --git a/src/dm_logger_tls.c b/src/dm_logger_tls.c new file mode 100644 index 0000000..6adcedf --- /dev/null +++ b/src/dm_logger_tls.c @@ -0,0 +1,7 @@ +/* Definitions for the TLS variables declared in dm_logger_tls.h. + * See that header for rationale. */ +#include "dm_logger_tls.h" + +__thread int64_t _dm_logger_ts_cached_seconds = 0; +__thread char _dm_logger_ts_cached_prefix[20] = { 0 }; +__thread bool _dm_logger_ts_cached_valid = false; diff --git a/src/dm_logger_tls.h b/src/dm_logger_tls.h new file mode 100644 index 0000000..e2348ef --- /dev/null +++ b/src/dm_logger_tls.h @@ -0,0 +1,35 @@ +/* + * Thread-local storage backing the per-second timestamp cache in + * dm_logger.vala. Defined in C because Vala has no native syntax for + * the __thread storage-class specifier, and attaching it via a + * [CCode (cname = "__thread ...")] hack collides with the type that + * Vala still emits in front of the cname. + * + * One copy of these variables exists per thread, so concurrent + * callers of DMLogger.format_log_timestamp() in not-threaded mode can + * never tear each other's cache. __thread zero-initialises, so the + * _valid flag starts out false and the first call in each thread + * always runs strftime. + * + * Supported by GCC, Clang and MinGW-w64 -- the only toolchains this + * library is built with. + */ +#ifndef DM_LOGGER_TLS_H +#define DM_LOGGER_TLS_H + +#include +#include + +#ifdef __cplusplus +extern "C" { +#endif + +extern __thread int64_t _dm_logger_ts_cached_seconds; +extern __thread char _dm_logger_ts_cached_prefix[20]; +extern __thread bool _dm_logger_ts_cached_valid; + +#ifdef __cplusplus +} +#endif + +#endif /* DM_LOGGER_TLS_H */ diff --git a/tests/test_dm_logger.vala b/tests/test_dm_logger.vala index 1f20f80..152c132 100644 --- a/tests/test_dm_logger.vala +++ b/tests/test_dm_logger.vala @@ -33,6 +33,18 @@ public class TestDMLogger ts_dm_logger.add_suite( ts_dm_logger_entry_bin ); + /* timestamp formatting */ + GLib.TestSuite ts_dm_logger_timestamp = new GLib.TestSuite( "timestamp" ); + ts_dm_logger_timestamp.add( + new GLib.TestCase( + "test_f_dm_logger_format_log_timestamp", + TestDMLogger.default_setup, + TestDMLogger.test_dm_logger_format_log_timestamp, + TestDMLogger.default_teardown + ) + ); + ts_dm_logger.add_suite( ts_dm_logger_timestamp ); + GLib.Test.run( ); return 0; @@ -115,6 +127,55 @@ public class TestDMLogger GLib.assert( logger.tid_entry_bin.get( OpenDMLib.gettid( ) ).length == 3 ); GLib.assert( logger.tid_entry_bin.get( thread_id ).length == 1 ); } + + /** + * Tests that format_log_timestamp produces the expected + * "YYYY-MM-DD HH:MM:SS" prefix in the caller-supplied buffer + * and that calls with the same whole-second value reuse the + * cached prefix (correctness check: result must still be right). + * + * The check is timezone-independent: we feed a known epoch-second + * value, call format_log_timestamp twice with that same second + * and once with second+1, and verify all three prefixes are + * well-formed and that the first two are byte-equal. + */ + public static void test_dm_logger_format_log_timestamp( ) + { + char buf_a[20]; + char buf_b[20]; + char buf_c[20]; + + /* 1_700_000_000 seconds == 2023-11-14 22:13:20 UTC. + * Local-time representation depends on TZ, but determinism + * within one run is all we need. */ + int64 base_ts = (int64)1700000000 * (int64)1000000; /* microseconds */ + + DMLogger.format_log_timestamp( base_ts, buf_a ); + DMLogger.format_log_timestamp( base_ts + (int64)500000, buf_b ); /* same second */ + DMLogger.format_log_timestamp( base_ts + (int64)1500000, buf_c ); /* +1 second */ + + string s_a = (string)buf_a; + string s_b = (string)buf_b; + string s_c = (string)buf_c; + + /* Well-formedness: "YYYY-MM-DD HH:MM:SS" => 19 chars. */ + GLib.assert( s_a.length == 19 ); + GLib.assert( s_b.length == 19 ); + GLib.assert( s_c.length == 19 ); + + /* Layout: digits and separators at fixed positions. */ + GLib.assert( s_a[ 4] == '-' ); + GLib.assert( s_a[ 7] == '-' ); + GLib.assert( s_a[10] == ' ' ); + GLib.assert( s_a[13] == ':' ); + GLib.assert( s_a[16] == ':' ); + + /* Same whole-second => identical prefix. */ + GLib.assert( s_a == s_b ); + + /* +1 second => different prefix (last char differs at minimum). */ + GLib.assert( s_a != s_c ); + } } /**