From 40eeb6a8254f6763be1b480bad84bc499822a055 Mon Sep 17 00:00:00 2001 From: Gerhard Gruber Date: Wed, 27 May 2026 10:19:13 +0200 Subject: [PATCH 1/6] test(dm_logger): add timestamp-formatter test (currently fails to build) --- tests/test_dm_logger.vala | 61 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 61 insertions(+) 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 ); + } } /** From fe462b10c5b14ac1de3b6b24223aff5fc06601f2 Mon Sep 17 00:00:00 2001 From: Gerhard Gruber Date: Wed, 27 May 2026 10:19:39 +0200 Subject: [PATCH 2/6] build(dm_logger): expose POSIX thread-safe time funcs on MinGW Adds -D_POSIX_THREAD_SAFE_FUNCTIONS=1 so that MinGW's declares localtime_r/gmtime_r. Required for the upcoming fast timestamp formatter. No-op on glibc. --- src/CMakeLists.txt | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index b7795ab..349c1dd 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 "$") From ab5c198ca7a1ed0f5184d6c84ecbbf09cabc28ca Mon Sep 17 00:00:00 2001 From: Gerhard Gruber Date: Wed, 27 May 2026 10:20:44 +0200 Subject: [PATCH 3/6] perf(dm_logger): add fast format_log_timestamp helper Adds a libc-backed timestamp formatter with a per-second cache. Replaces the GTimeZone+GDateTime path that callgrind showed consuming ~30 % of docTYPE total runtime. Helper not yet wired into LogEntry.print_out (next commit). --- src/dm_logger.vala | 79 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 79 insertions(+) diff --git a/src/dm_logger.vala b/src/dm_logger.vala index 4ce2b88..83a2b59 100644 --- a/src/dm_logger.vala +++ b/src/dm_logger.vala @@ -31,6 +31,85 @@ 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: this helper is only called from + * LogEntry.print_out, which in turn runs from the single dedicated + * logger writer thread (Logger.run) and from the not-threaded + * fallback path. Both contexts are single-threaded, so the + * function-local statics need no locking. + */ + + [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(). + * int64.MIN is impossible for a real timestamp (would be the year + * ~-292277, far before the UNIX epoch), so it is a safe + * "never matched yet" sentinel. + * + * These are namespace-private globals because Vala does not support + * function-local static variables. Their single-threaded use is + * documented in the comment block above format_log_timestamp(). */ + private int64 _dm_logger_ts_cached_seconds = int64.MIN; + private char _dm_logger_ts_cached_prefix[20]; + + /** + * 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. + * + * Single-threaded use only; see comment block above. + */ + public void format_log_timestamp( int64 tstamp_usec, char[] buf ) + { + int64 seconds = tstamp_usec / (int64)1000000; + + if ( 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 so the logger never + * blocks the writer thread on this. */ + GLib.Memory.copy( _dm_logger_ts_cached_prefix, "????-??-?? ??:??:??\0".data, 20 ); + } + _dm_logger_ts_cached_seconds = seconds; + } + + GLib.Memory.copy( buf, _dm_logger_ts_cached_prefix, 20 ); + } + /* Ab diesem Trace-Level soll geloggt werden */ public int log_trace_level = 0; From d912461520e036d886c81349edba0b4f55ca0497 Mon Sep 17 00:00:00 2001 From: Gerhard Gruber Date: Wed, 27 May 2026 10:21:50 +0200 Subject: [PATCH 4/6] perf(dm_logger): use fast timestamp formatter in print_out Replaces the per-call DMDateTime/GTimeZone construction with the new format_log_timestamp helper. Output format is byte-identical: [YYYY-MM-DD HH:MM:SS.uuuuuu]. Expected ~30 % wall-clock speedup for log-heavy docTYPE runs (see callgrind.out.61062 analysis). --- src/dm_logger.vala | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/dm_logger.vala b/src/dm_logger.vala index 83a2b59..f75850c 100644 --- a/src/dm_logger.vala +++ b/src/dm_logger.vala @@ -513,8 +513,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 ) { From 5c3562bb8eca7aba26a98cd62868c34e18b3759f Mon Sep 17 00:00:00 2001 From: Gerhard Gruber Date: Wed, 27 May 2026 12:07:17 +0200 Subject: [PATCH 5/6] Fix review findings --- src/CMakeLists.txt | 13 ++++++++++ src/dm_logger.vala | 58 ++++++++++++++++++++++++++++++++------------- src/dm_logger_tls.c | 7 ++++++ src/dm_logger_tls.h | 35 +++++++++++++++++++++++++++ 4 files changed, 96 insertions(+), 17 deletions(-) create mode 100644 src/dm_logger_tls.c create mode 100644 src/dm_logger_tls.h diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index 349c1dd..08e3088 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -30,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 @@ -59,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 f75850c..b403a9c 100644 --- a/src/dm_logger.vala +++ b/src/dm_logger.vala @@ -43,11 +43,14 @@ namespace DMLogger * 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: this helper is only called from - * LogEntry.print_out, which in turn runs from the single dedicated - * logger writer thread (Logger.run) and from the not-threaded - * fallback path. Both contexts are single-threaded, so the - * function-local statics need no locking. + * 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")] @@ -56,16 +59,25 @@ namespace DMLogger [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(). - * int64.MIN is impossible for a real timestamp (would be the year - * ~-292277, far before the UNIX epoch), so it is a safe - * "never matched yet" sentinel. + /* Per-second cache backing format_log_timestamp(), held in + * thread-local storage so concurrent callers (not-threaded mode) + * never race on it. * - * These are namespace-private globals because Vala does not support - * function-local static variables. Their single-threaded use is - * documented in the comment block above format_log_timestamp(). */ - private int64 _dm_logger_ts_cached_seconds = int64.MIN; - private char _dm_logger_ts_cached_prefix[20]; + * 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 @@ -76,13 +88,24 @@ namespace DMLogger * @param buf Caller-allocated buffer; must be at least 20 bytes. * On success it contains a NUL-terminated string. * - * Single-threaded use only; see comment block above. + * 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 ( seconds != _dm_logger_ts_cached_seconds ) + if ( !_dm_logger_ts_cached_valid || seconds != _dm_logger_ts_cached_seconds ) { time_t t = (time_t)seconds; Posix.tm tm_local = Posix.tm(); @@ -105,6 +128,7 @@ namespace DMLogger GLib.Memory.copy( _dm_logger_ts_cached_prefix, "????-??-?? ??:??:??\0".data, 20 ); } _dm_logger_ts_cached_seconds = seconds; + _dm_logger_ts_cached_valid = true; } GLib.Memory.copy( buf, _dm_logger_ts_cached_prefix, 20 ); @@ -514,7 +538,7 @@ namespace DMLogger } char ts_buf[20]; - format_log_timestamp( this.tstamp, ts_buf ); + _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 */ From 9263f13c6db8a83af2ce66f4c30411146b729f45 Mon Sep 17 00:00:00 2001 From: Gerhard Gruber Date: Wed, 27 May 2026 12:13:58 +0200 Subject: [PATCH 6/6] do not cache invalid values --- src/dm_logger.vala | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/src/dm_logger.vala b/src/dm_logger.vala index b403a9c..4ed4788 100644 --- a/src/dm_logger.vala +++ b/src/dm_logger.vala @@ -123,9 +123,13 @@ namespace DMLogger else { /* localtime_r failed (only happens for absurd time_t values - * on 32-bit builds). Emit a placeholder so the logger never - * blocks the writer thread on this. */ + * 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;