From f190e1fb66b9066202a90b05612e88769a42f96c Mon Sep 17 00:00:00 2001 From: Antoine Date: Wed, 30 Jul 2025 10:38:32 +0200 Subject: [PATCH 1/3] Add structured logging and eval macros --- include/blackmagic/log.h | 25 +++++++++++++++++++++++++ 1 file changed, 25 insertions(+) diff --git a/include/blackmagic/log.h b/include/blackmagic/log.h index b37a211..38b44a3 100644 --- a/include/blackmagic/log.h +++ b/include/blackmagic/log.h @@ -68,6 +68,8 @@ * So if you want to have a run-time threshold in your custom function, * be sure to set the compile-time threshold high enough, * possibly to @ref LOG_LEVEL_ALL + * + * @since 0.4 */ typedef void(*logging_callback)(unsigned level, const char* level_name, const char* file, const char* function, int line, const char* message, ...); @@ -204,3 +206,26 @@ void LOG_FUNCTION (unsigned level, const char* level_name, const char* file, con #define log_force(MESSAGE, ...) \ log__log(LOG_LEVEL_NONE, "FORCE", COLOR(BOLD, WHITE, BG_GREEN), \ MESSAGE __VA_OPT__(, ) __VA_ARGS__) + +///@cond +#define _log_value(NAME, FLAG, VALUE) VALUE, +///@endcond + +/** To be used with @ref log_structured */ +#define eval(FLAG, EXPRESSION) (#EXPRESSION, FLAG, EXPRESSION) + +#if LOG_FORMAT == LOG_FORMAT_JSON +#define _log_name(NAME, FLAG, VALUE) "\""NAME "\": %" FLAG ", " +#define log_structured(LEVEL, MESSAGE, ...) log_ ## LEVEL (MESSAGE "\", " FOR(EACH(__VA_ARGS__), PAIR_FLATTEN, _log_name) "\"bruh\":\"%i", FOR(EACH(__VA_ARGS__), PAIR_FLATTEN, _log_value) 0) +#else +///@cond +#define _log_name(NAME, FLAG, VALUE) NAME " = %" FLAG ", " +///@endcond +/** + * Structured logging. + * + * Provide a list of fields of the form (name, flag, value), where flag is the printf format to be used. + * The @ref eval macro can be used to have the name be the expression itself + */ +#define log_structured(LEVEL, MESSAGE, ...) log_ ## LEVEL (MESSAGE "; " FOR(EACH(__VA_ARGS__), PAIR_FLATTEN, _log_name) , FOR(EACH(__VA_ARGS__), PAIR_FLATTEN, _log_value) 0) +#endif From 53d64ee422806ea47d87cfba7971e4680d61c294 Mon Sep 17 00:00:00 2001 From: Antoine GAGNIERE Date: Mon, 22 Dec 2025 13:52:41 +0100 Subject: [PATCH 2/3] Put structured log macro in a dedicated file --- include/blackmagic/log.h | 23 --------------------- include/blackmagic/log_structured.h | 31 +++++++++++++++++++++++++++++ 2 files changed, 31 insertions(+), 23 deletions(-) create mode 100644 include/blackmagic/log_structured.h diff --git a/include/blackmagic/log.h b/include/blackmagic/log.h index 38b44a3..2ebf57b 100644 --- a/include/blackmagic/log.h +++ b/include/blackmagic/log.h @@ -206,26 +206,3 @@ void LOG_FUNCTION (unsigned level, const char* level_name, const char* file, con #define log_force(MESSAGE, ...) \ log__log(LOG_LEVEL_NONE, "FORCE", COLOR(BOLD, WHITE, BG_GREEN), \ MESSAGE __VA_OPT__(, ) __VA_ARGS__) - -///@cond -#define _log_value(NAME, FLAG, VALUE) VALUE, -///@endcond - -/** To be used with @ref log_structured */ -#define eval(FLAG, EXPRESSION) (#EXPRESSION, FLAG, EXPRESSION) - -#if LOG_FORMAT == LOG_FORMAT_JSON -#define _log_name(NAME, FLAG, VALUE) "\""NAME "\": %" FLAG ", " -#define log_structured(LEVEL, MESSAGE, ...) log_ ## LEVEL (MESSAGE "\", " FOR(EACH(__VA_ARGS__), PAIR_FLATTEN, _log_name) "\"bruh\":\"%i", FOR(EACH(__VA_ARGS__), PAIR_FLATTEN, _log_value) 0) -#else -///@cond -#define _log_name(NAME, FLAG, VALUE) NAME " = %" FLAG ", " -///@endcond -/** - * Structured logging. - * - * Provide a list of fields of the form (name, flag, value), where flag is the printf format to be used. - * The @ref eval macro can be used to have the name be the expression itself - */ -#define log_structured(LEVEL, MESSAGE, ...) log_ ## LEVEL (MESSAGE "; " FOR(EACH(__VA_ARGS__), PAIR_FLATTEN, _log_name) , FOR(EACH(__VA_ARGS__), PAIR_FLATTEN, _log_value) 0) -#endif diff --git a/include/blackmagic/log_structured.h b/include/blackmagic/log_structured.h new file mode 100644 index 0000000..84724cc --- /dev/null +++ b/include/blackmagic/log_structured.h @@ -0,0 +1,31 @@ +#include "blackmagic/for.h" +#include "blackmagic/log.h" +#include "blackmagic/pair.h" + + +/** + * To be used with @ref log_structured. + */ +#define eval(FLAG, EXPRESSION) (#EXPRESSION, FLAG, EXPRESSION) + +///@cond +#define _log_value(NAME, FLAG, VALUE) VALUE, + +#if LOG_FORMAT == LOG_FORMAT_JSON +#define _log_name(NAME, FLAG, VALUE) "\""NAME "\": %" FLAG ", " +#define log_structured(LEVEL, MESSAGE, ...) log_ ## LEVEL (MESSAGE "\", " FOR(EACH(__VA_ARGS__), PAIR_FLATTEN, _log_name) "\"\":\"%.0u", FOR(EACH(__VA_ARGS__), PAIR_FLATTEN, _log_value) 0) +#else +#define _log_name(NAME, FLAG, VALUE) NAME " = %" FLAG ", " +///@endcond + +/** + * Structured logging. + * + * Provide a list of fields of the form (name, flag, value), where flag is the printf format to be used. + * The @ref eval macro can be used to have the name be the expression itself + */ +#define log_structured(LEVEL, MESSAGE, ...) log_ ## LEVEL (MESSAGE "; " FOR(EACH(__VA_ARGS__), PAIR_FLATTEN, _log_name) "%.0u", FOR(EACH(__VA_ARGS__), PAIR_FLATTEN, _log_value) 0) + +///@cond +#endif +///@endcond From ee7b3176eefcaff14d10fa1f5cd0bdfea139db54 Mon Sep 17 00:00:00 2001 From: Antoine GAGNIERE Date: Mon, 22 Dec 2025 14:43:22 +0100 Subject: [PATCH 3/3] Add a trace that logs scope duration --- include/blackmagic/trace.h | 72 ++++++++++++++++++++++++++++++++++++++ 1 file changed, 72 insertions(+) create mode 100644 include/blackmagic/trace.h diff --git a/include/blackmagic/trace.h b/include/blackmagic/trace.h new file mode 100644 index 0000000..c085c6e --- /dev/null +++ b/include/blackmagic/trace.h @@ -0,0 +1,72 @@ +#pragma once + +#include "blackmagic/log.h" +#include "blackmagic/log_structured.h" + +#include // strerror +#include + +#define BLACKMAGIC_ScopedTrace struct blackmagic_trace __attribute__((cleanup(blackmagic_trace_scopeend))) + +#define BLACKMAGIC_timespec_diff(A, B) ((B.tv_sec - A.tv_sec) * 1000000000UL + B.tv_nsec - A.tv_nsec) + +#define BLACKMAGIC_Scope(NAME) blackmagic_trace_scopestart(NAME, __FILE__, __func__, __LINE__) + +struct blackmagic_trace +{ + struct timespec start; + const char* scope_name; + const char* file_name; + const char* function_name; + unsigned line_number; +}; + +static inline struct blackmagic_trace +blackmagic_trace_scopestart(const char* scope_name, + const char* file_name, + const char* function_name, + unsigned line_number) +{ + struct timespec start = {0}; + int status = clock_gettime(CLOCK_MONOTONIC_RAW, &start); + +#ifndef NDEBUG + if (status != 0) + log_error("Unable to get time: %s", strerror(status)); +#endif + return (struct blackmagic_trace){ + start = start, + scope_name = scope_name, + file_name = file_name, + function_name = function_name, + line_number = line_number, + }; +} + +#ifndef LOG_LEVEL_SPAN +# define LOG_LEVEL_SPAN 5 +#endif + +#if LOG_LEVEL >= LOG_LEVEL_SPAN +#define log_span(MESSAGE, ...) \ + log__log(LOG_LEVEL_SPAN, "SPAN", COLOR(PURPLE), MESSAGE __VA_OPT__(, ) __VA_ARGS__) +#else +#define log_span(M, ...) +#endif + +static inline void blackmagic_trace_scopeend(struct blackmagic_trace* self) { + struct timespec end = {0}; + int status = clock_gettime(CLOCK_MONOTONIC_RAW, &end); + +#ifndef NDEBUG + if (status != 0) + log_error("Unable to get time: %s", strerror(status)); +#endif + log_structured(span, + "", + ("trace_scope", "s", self->scope_name), + ("trace_file", "s", self->file_name), + ("trace_function", "s", self->function_name), + ("trace_line", "u", self->line_number), + ("duration_ns", "lu", BLACKMAGIC_timespec_diff(self->start, end))); +}