From 628edd8e95f64ea85fc7b6f840b8048d86dda8c2 Mon Sep 17 00:00:00 2001 From: Zeev Belinsky Date: Thu, 25 Jun 2026 07:46:27 -0700 Subject: [PATCH 1/4] =?UTF-8?q?wip:=20log=20spam=20control=20=E2=80=94=20o?= =?UTF-8?q?nce/throttle=20macros=20with=20severity=20variants?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Zeev Belinsky --- kernel/Makefile | 24 +- kernel/data/globals/globals.h | 4 +- kernel/data/readylist/readylist.h | 8 +- kernel/init/setup/setup.ref.c | 14 +- kernel/util/log/log.h | 111 +++- kernel/util/log/log.ref.c | 211 ++++++-- kernel/util/max/max.h | 5 +- log_diagram.excalidraw | 825 ++++++++++++++++++++++++++++++ notes.md | 44 ++ wip_notes.md | 50 ++ 10 files changed, 1219 insertions(+), 77 deletions(-) create mode 100644 log_diagram.excalidraw create mode 100644 wip_notes.md diff --git a/kernel/Makefile b/kernel/Makefile index 621ff3af1..60386c03d 100644 --- a/kernel/Makefile +++ b/kernel/Makefile @@ -50,10 +50,6 @@ ifdef NO_DEVICES CFLAGS += -DNO_DEVICES endif -ifdef LOGBUF -CFLAGS += -DH2K_LOGBUF -endif - ifdef MULTICORE CFLAGS += -DMULTICORE endif @@ -138,6 +134,26 @@ $(foreach MODPATH,$(MKINCLUDES),$(eval $(DO_INCLUDE))) ALL_OFILES := $(REF_OFILES) $(CHECK_OFILES) $(OPT_V2_OFILES) $(OPT_V3_OFILES) $(OPT_V4_OFILES) $(OPT_V5_OFILES) $(OPT_V60_OFILES) $(OPT_V65_OFILES) $(OPT_V68_OFILES) $(OPT_V73_OFILES) $(OPT_V81_OFILES) +ifdef LOGBUF +ifeq ($(LOGBUF),1) +CFLAGS += -DH2K_LOGBUF +else +_logbuf_comma := , + +$(foreach _tok,$(subst $(_logbuf_comma), ,$(LOGBUF)),\ + $(eval _logbuf_hits := $(filter %/$(basename $(_tok)).o,$(ALL_OFILES))) \ + $(if $(_logbuf_hits),,\ + $(eval _logbuf_hits := $(foreach _o,$(ALL_OFILES),$(if $(findstring /$(_tok)/,$(_o)),$(_o))))) \ + $(if $(_logbuf_hits),\ + $(eval $(_logbuf_hits) : CFLAGS += -DH2K_LOGBUF),\ + $(warning LOGBUF: token '$(_tok)' matched no kernel sources))) + +$(foreach _o,$(ALL_OFILES),\ + $(if $(findstring /util/log/,$(_o)),$(eval $(_o) : CFLAGS += -DH2K_LOGBUF)) \ + $(if $(findstring /init/setup/,$(_o)),$(eval $(_o) : CFLAGS += -DH2K_LOGBUF))) +endif +endif + $(ALL_OFILES): $(DEST_HFILES) ifeq ($(ARCHV),3) diff --git a/kernel/data/globals/globals.h b/kernel/data/globals/globals.h index c034daf3b..c6cfd8d1a 100644 --- a/kernel/data/globals/globals.h +++ b/kernel/data/globals/globals.h @@ -170,8 +170,8 @@ typedef struct { u32_t noc_sbase; // 4k pages H2K_spinlock_t logbuf_lock; - char *logbuf; - u32_t logbuf_pos; // first free byte + char *logbuf[MAX_HTHREADS]; + u32_t logbuf_pos[MAX_HTHREADS]; u32_t logbuf_enable; u32_t log_enable; H2K_spinlock_t angel_lock; diff --git a/kernel/data/readylist/readylist.h b/kernel/data/readylist/readylist.h index 5b6d8ca37..108fee079 100644 --- a/kernel/data/readylist/readylist.h +++ b/kernel/data/readylist/readylist.h @@ -95,7 +95,7 @@ static inline void H2K_update_coprocs(u32_t hthread, u32_t hthread_xe, u32_t hth } } else { if (head_xe) { - H2K_log("hthread %d update_coprocs: add xe\n", hthread); + H2K_log_once_ht(H2K_LOG_CH_COPROC, "hthread %d update_coprocs: add xe\n", hthread); } } if (hthread_xe2) { @@ -148,7 +148,7 @@ static inline H2K_thread_context *H2K_ready_head(u32_t prio, u32_t hthread) { u32_t need_tmp = need; // save # needed coprocs when walking ready list u32_t i; - H2K_log("hthread %d have %d need %d head_xe %d head_xe2 %d head_xe3 %d counts %d %d %d %d \n\tcheck task 0x%08x\n", hthread, have, need, head_xe, head_xe2, head_xe3,H2K_gp->coproc_count[0], H2K_gp->coproc_count[1], H2K_gp->coproc_count[2], H2K_gp->coproc_count[3], ret); + H2K_log("hthread %d have %d need %d head_xe %d head_xe2 %d head_xe3 %d counts %d %d %d %d \n\tcheck task 0x%08x\n", hthread, have, need, head_xe, head_xe2, head_xe3,H2K_gp->coproc_count[0], H2K_gp->coproc_count[1], H2K_gp->coproc_count[2], H2K_gp->coproc_count[3], (u32_t)ret); if (H2K_gp->coproc_count[cluster] + (need - have) <= H2K_gp->coproc_max) { // within limit @@ -201,7 +201,7 @@ static inline H2K_thread_context *H2K_ready_head(u32_t prio, u32_t hthread) { } while (ret != NULL && (need_tmp = (((ret->ssr_xe || ret->ccr_xe3) ? 1 : 0) + ((ret->ssr_xe2) ? 1 : 0)) + min_coprocs) > H2K_gp->coproc_max); - H2K_log("hthread %d try new task 0x%08x\n", ret); + H2K_log("hthread %d try new task 0x%08x\n", hthread, (u32_t)ret); } while (ret != NULL); /* Didn't find another task to schedule, so pick up the head task even though this unbalances the coprocs */ @@ -220,7 +220,7 @@ static inline H2K_thread_context *H2K_ready_getbest(u32_t hthread) H2K_thread_context *ret; u32_t prio; - H2K_log("hthread %d getbest\n", hthread); + H2K_log_throttle_ht(H2K_LOG_CH_RESCHED, 1000000, "hthread %d getbest\n", hthread); prio = H2K_ready_best_prio(); if (prio >= MAX_PRIOS) { // !H2K_ready_any_valid(), go to sleep #ifdef CLUSTER_SCHED diff --git a/kernel/init/setup/setup.ref.c b/kernel/init/setup/setup.ref.c index 5a1b213cf..98b0f5339 100644 --- a/kernel/init/setup/setup.ref.c +++ b/kernel/init/setup/setup.ref.c @@ -92,13 +92,13 @@ IN_SECTION(".text.init.setup") static H2K_vmblock_t *H2K_init_setup(u32_t multic H2K_l2cache_init(); H2K_tcm_copy(last_tlb_index); H2K_trace_init(); - H2K_runlist_init(); - H2K_readylist_init(); - H2K_lowprio_init(); - H2K_futex_init(); - H2K_intconfig_init(ssbase); - H2K_thread_init(); - H2K_asid_table_init(); + H2K_runlist_init(); //fix + H2K_readylist_init(); //fix + H2K_lowprio_init(); //fix + H2K_futex_init(); //fix + H2K_intconfig_init(ssbase); //fix + H2K_thread_init(); + H2K_asid_table_init(); //fix #ifdef CRASH_DEBUG H2K_stlb_tcmcrash_init(); diff --git a/kernel/util/log/log.h b/kernel/util/log/log.h index 52ff5d919..3ef16654e 100644 --- a/kernel/util/log/log.h +++ b/kernel/util/log/log.h @@ -6,25 +6,122 @@ #ifndef H2K_LOG_H #define H2K_LOG_H 1 +#define H2K_LOG_ERR 0 +#define H2K_LOG_WARN 1 +#define H2K_LOG_INFO 2 +#define H2K_LOG_DBG 3 + +/* Override at build time with -DH2K_LOG_LEVEL=H2K_LOG_WARN etc. */ +#ifndef H2K_LOG_LEVEL +#define H2K_LOG_LEVEL H2K_LOG_DBG +#endif + #ifdef H2K_LOGBUF -#define H2K_log(...) H2K_log_print(__VA_ARGS__) -#define H2K_log_string(S) H2K_do_log_string(S) -u32_t H2K_write(u32_t fd, const u8_t *buf, u32_t len) IN_SECTION(".text.util.log"); +s32_t H2K_write(u32_t fd, const u8_t *buf, u32_t len) IN_SECTION(".text.util.log"); u32_t H2K_do_log_string(const char *string) IN_SECTION(".text.util.log"); -u32_t H2K_log_print(const char *format, ...) IN_SECTION(".text.util.log"); -char *H2K_logbuf_alloc(u32_t count) IN_SECTION(".text.util.log"); +s32_t H2K_log_print(u32_t level, const char *file, u32_t line, const char *format, ...) + IN_SECTION(".text.util.log") __attribute__((format(printf, 4, 5))); +char *H2K_logbuf_alloc(u32_t htid, u32_t count) IN_SECTION(".text.util.log"); char *H2K_log_init(void) IN_SECTION(".text.util.log"); +u32_t H2K_log_once(u32_t *flag) IN_SECTION(".text.util.log"); +u32_t H2K_log_once_ht(u32_t *flags) IN_SECTION(".text.util.log"); +u32_t H2K_log_throttle(u64_t *last, u64_t interval) IN_SECTION(".text.util.log"); +u32_t H2K_log_throttle_ht(u64_t *last, u64_t interval) IN_SECTION(".text.util.log"); + +#define H2K_log_at(level, ...) H2K_log_print((level), __FILE__, __LINE__, __VA_ARGS__) +#define H2K_log_err(...) H2K_log_at(H2K_LOG_ERR, __VA_ARGS__) +#define H2K_log_warn(...) H2K_log_at(H2K_LOG_WARN, __VA_ARGS__) +#define H2K_log_info(...) H2K_log_at(H2K_LOG_INFO, __VA_ARGS__) +#define H2K_log_dbg(...) H2K_log_at(H2K_LOG_DBG, __VA_ARGS__) +#define H2K_log(...) H2K_log_dbg(__VA_ARGS__) +#define H2K_log_string(S) H2K_do_log_string(S) + +#define H2K_log_once(...) \ + do { static u32_t __f = 0; if ((H2K_log_once)(&__f)) H2K_log(__VA_ARGS__); } while (0) +#define H2K_log_once_err(...) \ + do { static u32_t __f = 0; if ((H2K_log_once)(&__f)) H2K_log_err(__VA_ARGS__); } while (0) +#define H2K_log_once_warn(...) \ + do { static u32_t __f = 0; if ((H2K_log_once)(&__f)) H2K_log_warn(__VA_ARGS__); } while (0) +#define H2K_log_once_info(...) \ + do { static u32_t __f = 0; if ((H2K_log_once)(&__f)) H2K_log_info(__VA_ARGS__); } while (0) +#define H2K_log_once_ht(...) \ + do { static u32_t __f[MAX_HTHREADS] = {0}; if ((H2K_log_once_ht)(__f)) H2K_log(__VA_ARGS__); } while (0) +#define H2K_log_once_ht_err(...) \ + do { static u32_t __f[MAX_HTHREADS] = {0}; if ((H2K_log_once_ht)(__f)) H2K_log_err(__VA_ARGS__); } while (0) +#define H2K_log_once_ht_warn(...) \ + do { static u32_t __f[MAX_HTHREADS] = {0}; if ((H2K_log_once_ht)(__f)) H2K_log_warn(__VA_ARGS__); } while (0) +#define H2K_log_once_ht_info(...) \ + do { static u32_t __f[MAX_HTHREADS] = {0}; if ((H2K_log_once_ht)(__f)) H2K_log_info(__VA_ARGS__); } while (0) +#define H2K_log_throttle(interval, ...) \ + do { static u64_t __t = 0; if ((H2K_log_throttle)(&__t, (interval))) H2K_log(__VA_ARGS__); } while (0) +#define H2K_log_throttle_err(interval, ...) \ + do { static u64_t __t = 0; if ((H2K_log_throttle)(&__t, (interval))) H2K_log_err(__VA_ARGS__); } while (0) +#define H2K_log_throttle_warn(interval, ...) \ + do { static u64_t __t = 0; if ((H2K_log_throttle)(&__t, (interval))) H2K_log_warn(__VA_ARGS__); } while (0) +#define H2K_log_throttle_info(interval, ...) \ + do { static u64_t __t = 0; if ((H2K_log_throttle)(&__t, (interval))) H2K_log_info(__VA_ARGS__); } while (0) +#define H2K_log_throttle_ht(interval, ...) \ + do { static u64_t __t[MAX_HTHREADS] = {0}; if ((H2K_log_throttle_ht)(__t, (interval))) H2K_log(__VA_ARGS__); } while (0) +#define H2K_log_throttle_ht_err(interval, ...) \ + do { static u64_t __t[MAX_HTHREADS] = {0}; if ((H2K_log_throttle_ht)(__t, (interval))) H2K_log_err(__VA_ARGS__); } while (0) +#define H2K_log_throttle_ht_warn(interval, ...) \ + do { static u64_t __t[MAX_HTHREADS] = {0}; if ((H2K_log_throttle_ht)(__t, (interval))) H2K_log_warn(__VA_ARGS__); } while (0) +#define H2K_log_throttle_ht_info(interval, ...) \ + do { static u64_t __t[MAX_HTHREADS] = {0}; if ((H2K_log_throttle_ht)(__t, (interval))) H2K_log_info(__VA_ARGS__); } while (0) + #else #ifdef H2K_LOG_PRINTF #include #include -#define H2K_log(...) printf(__VA_ARGS__) -#define H2K_log_string(S) puts(S) + +#define H2K_log_err(fmt, ...) printf("[E] " fmt, ##__VA_ARGS__) +#define H2K_log_warn(fmt, ...) printf("[W] " fmt, ##__VA_ARGS__) +#define H2K_log_info(fmt, ...) printf("[I] " fmt, ##__VA_ARGS__) +#define H2K_log_dbg(fmt, ...) printf("[D] " fmt, ##__VA_ARGS__) +#define H2K_log(...) H2K_log_dbg(__VA_ARGS__) +#define H2K_log_string(S) puts(S) + +#define H2K_log_once(...) H2K_log(__VA_ARGS__) +#define H2K_log_once_err(...) H2K_log_err(__VA_ARGS__) +#define H2K_log_once_warn(...) H2K_log_warn(__VA_ARGS__) +#define H2K_log_once_info(...) H2K_log_info(__VA_ARGS__) +#define H2K_log_once_ht(...) H2K_log(__VA_ARGS__) +#define H2K_log_once_ht_err(...) H2K_log_err(__VA_ARGS__) +#define H2K_log_once_ht_warn(...) H2K_log_warn(__VA_ARGS__) +#define H2K_log_once_ht_info(...) H2K_log_info(__VA_ARGS__) +#define H2K_log_throttle(interval, ...) H2K_log(__VA_ARGS__) +#define H2K_log_throttle_err(interval, ...) H2K_log_err(__VA_ARGS__) +#define H2K_log_throttle_warn(interval, ...) H2K_log_warn(__VA_ARGS__) +#define H2K_log_throttle_info(interval, ...) H2K_log_info(__VA_ARGS__) +#define H2K_log_throttle_ht(interval, ...) H2K_log(__VA_ARGS__) +#define H2K_log_throttle_ht_err(interval, ...) H2K_log_err(__VA_ARGS__) +#define H2K_log_throttle_ht_warn(interval, ...) H2K_log_warn(__VA_ARGS__) +#define H2K_log_throttle_ht_info(interval, ...) H2K_log_info(__VA_ARGS__) #else +#define H2K_log_err(...) +#define H2K_log_warn(...) +#define H2K_log_info(...) +#define H2K_log_dbg(...) #define H2K_log(...) #define H2K_log_string(S) +#define H2K_log_once(...) do {} while (0) +#define H2K_log_once_err(...) do {} while (0) +#define H2K_log_once_warn(...) do {} while (0) +#define H2K_log_once_info(...) do {} while (0) +#define H2K_log_once_ht(...) do {} while (0) +#define H2K_log_once_ht_err(...) do {} while (0) +#define H2K_log_once_ht_warn(...) do {} while (0) +#define H2K_log_once_ht_info(...) do {} while (0) +#define H2K_log_throttle(interval, ...) do {} while (0) +#define H2K_log_throttle_err(interval, ...) do {} while (0) +#define H2K_log_throttle_warn(interval, ...) do {} while (0) +#define H2K_log_throttle_info(interval, ...) do {} while (0) +#define H2K_log_throttle_ht(interval, ...) do {} while (0) +#define H2K_log_throttle_ht_err(interval, ...) do {} while (0) +#define H2K_log_throttle_ht_warn(interval, ...) do {} while (0) +#define H2K_log_throttle_ht_info(interval, ...) do {} while (0) #endif #endif diff --git a/kernel/util/log/log.ref.c b/kernel/util/log/log.ref.c index 11193cc7e..466590830 100644 --- a/kernel/util/log/log.ref.c +++ b/kernel/util/log/log.ref.c @@ -10,9 +10,19 @@ #include #include #include +#include +#include +#include #ifdef H2K_LOGBUF +/* log_level lives here rather than in H2K_gp to avoid perturbing the global + * struct layout in no-logging builds. */ +#ifndef H2K_LOG_LEVEL +#define H2K_LOG_LEVEL H2K_LOG_DBG +#endif +static u32_t log_level = H2K_LOG_LEVEL; + static u32_t strcpy(char *dest, const char *src) { u32_t count = 1; @@ -35,14 +45,14 @@ static u32_t strlen(const char *src) return count; } -static u32_t logbuf_space() { +static u32_t logbuf_space(u32_t htid) { - return LOGBUF_SIZE - H2K_gp->logbuf_pos - 1; + return LOGBUF_PER_HT_SIZE - H2K_gp->logbuf_pos[htid] - 1; } -static void logbuf_wrap() { +static void logbuf_wrap(u32_t htid) { - H2K_gp->logbuf_pos = 0; + H2K_gp->logbuf_pos[htid] = 0; } s32_t H2K_write(u32_t fd, const u8_t *buf, u32_t len) { @@ -70,62 +80,66 @@ s32_t H2K_write(u32_t fd, const u8_t *buf, u32_t len) { return len; } -char *H2K_logbuf_alloc(u32_t count) { +/* + * Allocate count bytes in the calling hthread's own ring. Lockless: only the + * owning hthread (identified by htid) ever writes its ring. + */ +char *H2K_logbuf_alloc(u32_t htid, u32_t count) { char *ret; - if (count > logbuf_space()) { - logbuf_wrap(); + if (count > logbuf_space(htid)) { + logbuf_wrap(htid); } - ret = H2K_gp->logbuf + H2K_gp->logbuf_pos; - H2K_gp->logbuf_pos += count; + ret = H2K_gp->logbuf[htid] + H2K_gp->logbuf_pos[htid]; + H2K_gp->logbuf_pos[htid] += count; return ret; } u32_t H2K_do_log_string(const char *string) { + u32_t htid = get_hwtnum(); u32_t len = strlen(string); s32_t ret = len; - H2K_spinlock_lock(&H2K_gp->logbuf_lock); - if (H2K_gp->logbuf_enable) { - strcpy(H2K_logbuf_alloc(len + 1), string); + strcpy(H2K_logbuf_alloc(htid, len + 1), string); } if (H2K_gp->log_enable) { + /* the angel SYS_WRITE channel is shared hardware: serialize it */ + H2K_spinlock_lock(&H2K_gp->logbuf_lock); ret = H2K_write(1, (const u8_t *)"H2K: ", 5); - if (ret < 0) goto out; - - ret = H2K_write(1, (const u8_t *)string, len); + if (ret >= 0) { + ret = H2K_write(1, (const u8_t *)string, len); + } + H2K_spinlock_unlock(&H2K_gp->logbuf_lock); } - out: - H2K_spinlock_unlock(&H2K_gp->logbuf_lock); return ret; } -/* Call with logbuf_lock held */ -static void emit_char(char c) { - char *logbuf_ptr = H2K_logbuf_alloc(1); +/* Append one char to htid's ring, keeping a trailing NUL for string reads. */ +static void emit_char(u32_t htid, char c) { + char *logbuf_ptr = H2K_logbuf_alloc(htid, 1); *logbuf_ptr = c; *(logbuf_ptr + 1) = '\0'; // next char will overwrite } -static u32_t emit_string(const char *s) { +static u32_t emit_string(u32_t htid, const char *s) { u32_t len = 0; while ('\0' != *s) { - emit_char(*s++); + emit_char(htid, *s++); len++; } return len; } #define BUF_SIZE 32 -u32_t num(u64_t n, u32_t base, u32_t width, u32_t neg) { +u32_t num(u32_t htid, u64_t n, u32_t base, u32_t width, u32_t neg) { char buf[BUF_SIZE]; char *p = buf + BUF_SIZE; u32_t len = 0; @@ -151,16 +165,50 @@ u32_t num(u64_t n, u32_t base, u32_t width, u32_t neg) { *(--p) = '-'; len++; } - emit_string((const char *)p); + emit_string(htid, (const char *)p); return len; } -s32_t H2K_log_print(const char *fmt, ...) { +/* Indexed by H2K_LOG_* severity level. */ +static const char level_char[] = { 'E', 'W', 'I', 'D' }; - H2K_spinlock_lock(&H2K_gp->logbuf_lock); +/* + * Emit prefix into htid's ring and return its length: + * [ht][][][:] + */ +static u32_t emit_prefix(u32_t htid, u32_t level, const char *file, u32_t line) { + const char *base = file; + const char *p = file; + u32_t len = 0; + char sev = (level < sizeof(level_char)) ? level_char[level] : '?'; + + /* keep the basename only, dropping any leading directory path */ + while ('\0' != *p) { + if ('/' == *p) base = p + 1; + p++; + } + + len += emit_string(htid, "[ht"); + len += num(htid, (u64_t)htid, 10, 0, 0); + len += emit_string(htid, "]["); + emit_char(htid, sev); len++; + len += emit_string(htid, "]["); + len += num(htid, H2K_get_pcycle_reg(), 10, 0, 0); + len += emit_string(htid, "]["); + len += emit_string(htid, base); + emit_char(htid, ':'); len++; + len += num(htid, (u64_t)line, 10, 0, 0); + len += emit_string(htid, "] "); + + return len; +} + +s32_t H2K_log_print(u32_t level, const char *file, u32_t line, const char *fmt, ...) { + u32_t htid = get_hwtnum(); va_list args; - u32_t start = H2K_gp->logbuf_pos; + char *buf; + u32_t start; u32_t width; s64_t dec; s32_t ret; @@ -170,15 +218,25 @@ s32_t H2K_log_print(const char *fmt, ...) { /* if either is enabled we need logbuf to hold the output */ if (!H2K_gp->logbuf_enable && !H2K_gp->log_enable) { - H2K_spinlock_unlock(&H2K_gp->logbuf_lock); return 0; } + /* drop messages below the active runtime verbosity threshold */ + if (level > log_level) { + return 0; + } + + /* lockless: format directly into this hthread's own ring */ + buf = H2K_gp->logbuf[htid]; + start = H2K_gp->logbuf_pos[htid]; + + len += emit_prefix(htid, level, file, line); + va_start(args, fmt); while (*fmt != '\0') { if (!parsing && '%' != *fmt) { - emit_char(*fmt); + emit_char(htid, *fmt); len++; } else { if (!parsing) { @@ -193,7 +251,7 @@ s32_t H2K_log_print(const char *fmt, ...) { break; case '%': - emit_char(*fmt); + emit_char(htid, *fmt); len++; break; @@ -216,9 +274,9 @@ s32_t H2K_log_print(const char *fmt, ...) { break; case 'x': if (longlong) { - len += num((u64_t)va_arg(args, u64_t), 16, width, 0); + len += num(htid, (u64_t)va_arg(args, u64_t), 16, width, 0); } else { - len += num((u64_t)va_arg(args, u32_t), 16, width, 0); + len += num(htid, (u64_t)va_arg(args, u32_t), 16, width, 0); } break; @@ -229,13 +287,13 @@ s32_t H2K_log_print(const char *fmt, ...) { dec = (s64_t)va_arg(args, s32_t); } if (0 > dec) { - len += num((u64_t)(-dec), 10, width, 1); + len += num(htid, (u64_t)(-dec), 10, width, 1); } else { - len += num((u64_t)dec, 10, width, 0); + len += num(htid, (u64_t)dec, 10, width, 0); } break; case 's': - len += emit_string((const char *)va_arg(args, char *)); + len += emit_string(htid, (const char *)va_arg(args, char *)); break; default: @@ -248,39 +306,88 @@ s32_t H2K_log_print(const char *fmt, ...) { va_end(args); ret = len; + /* optional live streaming: serialize the shared angel channel */ if (H2K_gp->log_enable) { - ret = H2K_write(1, (const u8_t *)"H2K: ", 5); - if (ret < 0) goto out; - - if (H2K_gp->logbuf_pos < start) { // wrapped - ret = H2K_write(1, (const u8_t *)(H2K_gp->logbuf + start), LOGBUF_SIZE - start - 1); - if (ret < 0) goto out; - ret = H2K_write(1, (const u8_t *)(H2K_gp->logbuf), len - (LOGBUF_SIZE - start - 1)); - if (ret < 0) goto out; + H2K_spinlock_lock(&H2K_gp->logbuf_lock); + if (H2K_gp->logbuf_pos[htid] < start) { // wrapped mid-message + ret = H2K_write(1, (const u8_t *)(buf + start), LOGBUF_PER_HT_SIZE - start - 1); + if (ret >= 0) { + ret = H2K_write(1, (const u8_t *)buf, len - (LOGBUF_PER_HT_SIZE - start - 1)); + } } else { - ret = H2K_write(1, (const u8_t *)(H2K_gp->logbuf + start), len); - if (ret < 0) goto out; + ret = H2K_write(1, (const u8_t *)(buf + start), len); } + H2K_spinlock_unlock(&H2K_gp->logbuf_lock); } - out: - H2K_spinlock_unlock(&H2K_gp->logbuf_lock); return ret; } +/* + * once/throttle gating. State lives in a static local at each callsite + * (via the macros in log.h) and is passed in by pointer. + * Each function returns 1 when the guarded message should emit. + */ + +/* GLOBAL once: atomic test-and-set on the callsite flag. + * H2K_atomic_setbit returns 1 when the bit was clear (first setter wins). */ +u32_t H2K_log_once(u32_t *flag) { + return H2K_atomic_setbit(flag, 0); +} + +/* PER-HT once: caller passes flag[MAX_HTHREADS]; only this ht touches its + * slot so a plain test+set is race-free. */ +u32_t H2K_log_once_ht(u32_t *flags) { + u32_t htid = get_hwtnum(); + if (flags[htid]) return 0; + flags[htid] = 1; + return 1; +} + +/* GLOBAL throttle: caller passes a shared last-fired timestamp. + * Serialized with logbuf_lock since two hthreads may race on it. */ +u32_t H2K_log_throttle(u64_t *last, u64_t interval) { + u64_t now = H2K_get_pcycle_reg(); + u32_t go = 0; + + H2K_spinlock_lock(&H2K_gp->logbuf_lock); + if (now - *last >= interval) { + *last = now; + go = 1; + } + H2K_spinlock_unlock(&H2K_gp->logbuf_lock); + return go; +} + +/* PER-HT throttle: caller passes last[MAX_HTHREADS]; only this ht touches + * its slot so no lock is needed. */ +u32_t H2K_log_throttle_ht(u64_t *last, u64_t interval) { + u32_t htid = get_hwtnum(); + u64_t now = H2K_get_pcycle_reg(); + + if (now - last[htid] < interval) return 0; + last[htid] = now; + return 1; +} + char *H2K_log_init() { + u32_t htid; - if (NULL == (H2K_gp->logbuf = (char *)H2K_mem_alloc(LOGBUF_SIZE))) { - return NULL; + for (htid = 0; htid < MAX_HTHREADS; htid++) { + if (NULL == (H2K_gp->logbuf[htid] = (char *)H2K_mem_alloc(LOGBUF_PER_HT_SIZE))) { + return NULL; + } + H2K_bzero(H2K_gp->logbuf[htid], LOGBUF_PER_HT_SIZE); + H2K_gp->logbuf_pos[htid] = 0; } - H2K_bzero(H2K_gp->logbuf, LOGBUF_SIZE); - H2K_gp->logbuf_pos = 0; + H2K_gp->logbuf_enable = 1; H2K_gp->log_enable = 1; + log_level = H2K_LOG_LEVEL; H2K_spinlock_init(&H2K_gp->logbuf_lock); - return H2K_gp->logbuf; + return H2K_gp->logbuf[0]; } #endif diff --git a/kernel/util/max/max.h b/kernel/util/max/max.h index 9c187bf9b..f0e1e4c62 100644 --- a/kernel/util/max/max.h +++ b/kernel/util/max/max.h @@ -450,4 +450,7 @@ #define CORECFG_PRESENT_STRIDE_PREFETCHER_MASK 0x4 #define CORECFG_PRESENT_DPM_VOLTLMTMGMT_MASK 0x8 -#define LOGBUF_SIZE (32 * 1024) // bytes + +#ifndef LOGBUF_PER_HT_SIZE +#define LOGBUF_PER_HT_SIZE (4 * 1024) // bytes, per hardware thread +#endif diff --git a/log_diagram.excalidraw b/log_diagram.excalidraw new file mode 100644 index 000000000..e63909791 --- /dev/null +++ b/log_diagram.excalidraw @@ -0,0 +1,825 @@ +{ + "type": "excalidraw", + "version": 2, + "source": "https://marketplace.visualstudio.com/items?itemName=pomdtr.excalidraw-editor", + "elements": [ + { + "id": "t_title", + "type": "text", + "x": 260, + "y": 16, + "width": 480, + "height": 30, + "text": "H2K Log System", + "fontSize": 22, + "fontFamily": 1, + "textAlign": "center", + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 1127152591, + "index": "a0", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false, + "verticalAlign": "top", + "containerId": null, + "originalText": "H2K Log System", + "autoResize": true, + "lineHeight": 1.3636363636363635 + }, + { + "id": "box_build", + "type": "rectangle", + "x": 10, + "y": 60, + "width": 220, + "height": 200, + "strokeColor": "#364fc7", + "backgroundColor": "#e7f5ff", + "fillStyle": "solid", + "roundness": { + "type": 3 + }, + "version": 2, + "versionNonce": 137014433, + "index": "a1", + "isDeleted": false, + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false + }, + { + "id": "lbl_build", + "type": "text", + "x": 20, + "y": 68, + "width": 200, + "height": 20, + "text": "compile-time flags", + "fontSize": 13, + "fontFamily": 1, + "fontStyle": 1, + "strokeColor": "#364fc7", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 1721543151, + "index": "a2", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "compile-time flags", + "autoResize": true, + "lineHeight": 1.5384615384615385 + }, + { + "id": "txt_build", + "type": "text", + "x": 20.24713429252742, + "y": 94, + "width": 210.9375, + "height": 147.69230769230774, + "text": "(nothing)\n all macros → zero\n\n-DH2K_LOG_LEVEL=N\n ERR=0 WARN=1\n INFO=2 DBG=3 (default)\n\nmake LOGBUF=1: \nfull log system on\nmake LOGBUF=sched\nmake LOGBUF=sched,data/globals\n per-subsystem logging", + "fontSize": 12, + "fontFamily": 3, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 51, + "versionNonce": 918293055, + "index": "a3", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782395690551, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "(nothing)\n all macros → zero\n\n-DH2K_LOG_LEVEL=N\n ERR=0 WARN=1\n INFO=2 DBG=3 (default)\n\nmake LOGBUF=1: \nfull log system on\nmake LOGBUF=sched\nmake LOGBUF=sched,data/globals\n per-subsystem logging", + "autoResize": true, + "lineHeight": 1.0256410256410258 + }, + { + "id": "arr_build", + "type": "arrow", + "x": 230, + "y": 155, + "width": 60, + "height": 0, + "points": [ + [ + 0, + 0 + ], + [ + 60, + 0 + ] + ], + "strokeColor": "#1e1e1e", + "endArrowhead": "arrow", + "lastCommittedPoint": null, + "version": 2, + "versionNonce": 1215271951, + "index": "a4", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "backgroundColor": "transparent", + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false, + "startBinding": null, + "endBinding": null, + "startArrowhead": null + }, + { + "id": "box_api", + "type": "rectangle", + "x": 290, + "y": 60, + "width": 220, + "height": 200, + "strokeColor": "#1971c2", + "backgroundColor": "#d0ebff", + "fillStyle": "solid", + "roundness": { + "type": 3 + }, + "version": 2, + "versionNonce": 1729017953, + "index": "a5", + "isDeleted": false, + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false + }, + { + "id": "lbl_api", + "type": "text", + "x": 300, + "y": 68, + "width": 200, + "height": 20, + "text": "log macros", + "fontSize": 13, + "fontFamily": 1, + "fontStyle": 1, + "strokeColor": "#1971c2", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 1621113391, + "index": "a6", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "log macros", + "autoResize": true, + "lineHeight": 1.5384615384615385 + }, + { + "id": "txt_api", + "type": "text", + "x": 300, + "y": 94, + "width": 232.03125, + "height": 160, + "text": "H2K_log_err(fmt, ...)\nH2K_log_warn(fmt, ...)\nH2K_log_info(fmt, ...)\nH2K_log_dbg(fmt, ...)\nH2K_log(fmt, ...) ← dbg\n\nH2K_log_once(fmt, ...)\nH2K_log_once_ht(fmt, ...)\n\nH2K_log_throttle(iv, fmt, ...)\nH2K_log_throttle_ht(iv, fmt, ...)", + "fontSize": 12, + "fontFamily": 3, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 3, + "versionNonce": 1398558433, + "index": "a7", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392953296, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "H2K_log_err(fmt, ...)\nH2K_log_warn(fmt, ...)\nH2K_log_info(fmt, ...)\nH2K_log_dbg(fmt, ...)\nH2K_log(fmt, ...) ← dbg\n\nH2K_log_once(fmt, ...)\nH2K_log_once_ht(fmt, ...)\n\nH2K_log_throttle(iv, fmt, ...)\nH2K_log_throttle_ht(iv, fmt, ...)", + "autoResize": true, + "lineHeight": 1.2121212121212122 + }, + { + "id": "arr_api", + "type": "arrow", + "x": 510, + "y": 155, + "width": 60, + "height": 0, + "points": [ + [ + 0, + 0 + ], + [ + 60, + 0 + ] + ], + "strokeColor": "#1e1e1e", + "endArrowhead": "arrow", + "lastCommittedPoint": null, + "version": 2, + "versionNonce": 337058895, + "index": "a8", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "backgroundColor": "transparent", + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false, + "startBinding": null, + "endBinding": null, + "startArrowhead": null + }, + { + "id": "box_filter", + "type": "rectangle", + "x": 570, + "y": 60, + "width": 200, + "height": 200, + "strokeColor": "#862e9c", + "backgroundColor": "#f3d9fa", + "fillStyle": "solid", + "roundness": { + "type": 3 + }, + "version": 2, + "versionNonce": 833803297, + "index": "a9", + "isDeleted": false, + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false + }, + { + "id": "lbl_filter", + "type": "text", + "x": 580, + "y": 68, + "width": 180, + "height": 20, + "text": "level filter", + "fontSize": 13, + "fontFamily": 1, + "fontStyle": 1, + "strokeColor": "#862e9c", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 380418671, + "index": "aA", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "level filter", + "autoResize": true, + "lineHeight": 1.5384615384615385 + }, + { + "id": "txt_filter", + "type": "text", + "x": 580, + "y": 94, + "width": 147.65625, + "height": 80, + "text": "level ≤ log_level?\n\nlog_level set at boot\nfrom H2K_LOG_LEVEL\n(compile-time)", + "fontSize": 12, + "fontFamily": 3, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 11, + "versionNonce": 1807756351, + "index": "aB", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782396756274, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "level ≤ log_level?\n\nlog_level set at boot\nfrom H2K_LOG_LEVEL\n(compile-time)", + "autoResize": true, + "lineHeight": 1.3333333333333333 + }, + { + "id": "txt_drop", + "type": "text", + "x": 580, + "y": 185, + "width": 180, + "height": 20, + "text": "no → dropped silently", + "fontSize": 12, + "fontFamily": 3, + "strokeColor": "#c92a2a", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 220828815, + "index": "aC", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "no → dropped silently", + "autoResize": true, + "lineHeight": 1.6666666666666667 + }, + { + "id": "txt_pass", + "type": "text", + "x": 580, + "y": 210, + "width": 180, + "height": 20, + "text": "yes → emit path ↓", + "fontSize": 12, + "fontFamily": 3, + "strokeColor": "#2f9e44", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 1666383841, + "index": "aD", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "yes → emit path ↓", + "autoResize": true, + "lineHeight": 1.6666666666666667 + }, + { + "id": "arr_emit", + "type": "arrow", + "x": 670, + "y": 260, + "width": 0, + "height": 50, + "points": [ + [ + 0, + 0 + ], + [ + 0, + 50 + ] + ], + "strokeColor": "#2f9e44", + "endArrowhead": "arrow", + "lastCommittedPoint": null, + "version": 2, + "versionNonce": 1866869423, + "index": "aE", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "backgroundColor": "transparent", + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false, + "startBinding": null, + "endBinding": null, + "startArrowhead": null + }, + { + "id": "box_emit", + "type": "rectangle", + "x": 570, + "y": 310, + "width": 200, + "height": 90, + "strokeColor": "#2f9e44", + "backgroundColor": "#ebfbee", + "fillStyle": "solid", + "roundness": { + "type": 3 + }, + "version": 2, + "versionNonce": 797596609, + "index": "aF", + "isDeleted": false, + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false + }, + { + "id": "lbl_emit", + "type": "text", + "x": 580, + "y": 318, + "width": 180, + "height": 20, + "text": "emit", + "fontSize": 13, + "fontFamily": 1, + "fontStyle": 1, + "strokeColor": "#2f9e44", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 699071695, + "index": "aG", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "emit", + "autoResize": true, + "lineHeight": 1.5384615384615385 + }, + { + "id": "txt_emit", + "type": "text", + "x": 587.5208275645167, + "y": 336.58144201612873, + "width": 154.6875, + "height": 55, + "text": "ring buf per ht (4KB, \nlockless)", + "fontSize": 12, + "fontFamily": 3, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 81, + "versionNonce": 32509663, + "index": "aH", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782396809609, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "ring buf per ht (4KB, \nlockless)", + "autoResize": true, + "lineHeight": 2.2916666666666665 + }, + { + "id": "box_spam", + "type": "rectangle", + "x": 290, + "y": 280, + "width": 220, + "height": 130, + "strokeColor": "#e67700", + "backgroundColor": "#fff9db", + "fillStyle": "solid", + "roundness": { + "type": 3 + }, + "version": 2, + "versionNonce": 2146470639, + "index": "aI", + "isDeleted": false, + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false + }, + { + "id": "lbl_spam", + "type": "text", + "x": 300, + "y": 288, + "width": 200, + "height": 20, + "text": "spam control (callsite static)", + "fontSize": 13, + "fontFamily": 1, + "fontStyle": 1, + "strokeColor": "#e67700", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 493166465, + "index": "aJ", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "spam control (callsite static)", + "autoResize": true, + "lineHeight": 1.5384615384615385 + }, + { + "id": "txt_spam", + "type": "text", + "x": 300, + "y": 312, + "width": 200, + "height": 90, + "text": "once: static u32_t __f = 0\n atomic set → fires once\n\nonce_ht: static u32_t __f[HT]\n per-hthread, lockless\n\nthrottle: static u64_t __t = 0\n pcycle delta ≥ interval", + "fontSize": 12, + "fontFamily": 3, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 782193935, + "index": "aK", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "once: static u32_t __f = 0\n atomic set → fires once\n\nonce_ht: static u32_t __f[HT]\n per-hthread, lockless\n\nthrottle: static u64_t __t = 0\n pcycle delta ≥ interval", + "autoResize": true, + "lineHeight": 0.9375 + }, + { + "id": "arr_spam", + "type": "arrow", + "x": 510, + "y": 345, + "width": 60, + "height": 0, + "points": [ + [ + 0, + 0 + ], + [ + 60, + 0 + ] + ], + "strokeColor": "#e67700", + "endArrowhead": "arrow", + "label": { + "text": "gate passes" + }, + "lastCommittedPoint": null, + "version": 2, + "versionNonce": 225937249, + "index": "aL", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "backgroundColor": "transparent", + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782392810695, + "link": null, + "locked": false, + "startBinding": null, + "endBinding": null, + "startArrowhead": null + } + ], + "appState": { + "gridSize": 20, + "gridStep": 5, + "gridModeEnabled": false, + "viewBackgroundColor": "#ffffff" + }, + "files": {} +} \ No newline at end of file diff --git a/notes.md b/notes.md index 58042d3b8..c85ef7e05 100644 --- a/notes.md +++ b/notes.md @@ -810,3 +810,47 @@ Qualcomm-internal tool wrapper infrastructure. A symlink named after each tool (e.g., `hexagon-clang`) points to PKW, which reads environment variables or config files to locate the correct tool installation. Set `USE_PKW=1` in the build to enable it. + +### Selective logging (LOGBUF) + log severity levels +`H2K_log` is gated per-translation-unit by the `LOGBUF` make variable: +- `make LOGBUF=1` -- enable logging everywhere (legacy) +- `make LOGBUF=sched` -- whole subtree (dir token) +- `make LOGBUF=sched/resched/resched.ref.c` -- single file (file token) +- `make LOGBUF=data/globals,sched/dosched` -- comma-separated mix +Util/log/ and init/setup/ are always force-flagged when LOGBUF is +set, because they hold H2K_log_print (the impl) and H2K_log_init (the bootstrap); +without them the selected callsites fail to link / the logbuf is never allocated. +A token matching no sources emits a $(warning). + +Severity levels (kernel/util/log/log.h): H2K_log_err/warn/info/dbg map to +H2K_LOG_ERR/WARN/INFO/DBG (0..3). Plain `H2K_log` is an alias for `_dbg`. +Runtime threshold `log_level` (static in log.ref.c, default +H2K_LOG_DBG) drops messages with level > threshold. Each line gets a +prefix assembled in H2K_log_print: `[ht][][][file:line] msg`, +using get_hwtnum() and H2K_get_pcycle_reg(). + +### Per-hthread lockless log rings (Phase 2, done) +globals.h now holds `logbuf[MAX_HTHREADS]`, `logbuf_pos[MAX_HTHREADS]`, +`logbuf_enable`, `log_enable` instead of a single buffer. Each hthread writes +ONLY its own ring (indexed by get_hwtnum()), so H2K_log_print takes NO lock on +the buffering path -- fixes the self-deadlock risk when logging from the +scheduler/interrupt path (logbuf_lock was non-reentrant). Ring size is +`LOGBUF_PER_HT_SIZE` (max.h, default 4KB, override with -D). +- `logbuf_lock` is RETAINED but now serializes only the shared angel SYS_WRITE + console channel (live streaming), not buffering. +- `log_enable=1` in H2K_log_init enables live per-call streaming via angel SYS_WRITE + (serialized by logbuf_lock); `logbuf_enable=1` enables ring buffering. Both are + set by default in H2K_log_init. +- emit_char/emit_string/num/emit_prefix all take htid as first arg now. +- H2K_logbuf_alloc signature changed to (htid, count). +Verified: make all_clean && make test_variant TARGET=ref ARCHV=81 -> 99/0; +make build LOGBUF=sched compiles + links. + +### Log spam control (Phase 3, DONE) +Four log-filtering primitives added; state lives in local statics in log.ref.c. +- `H2K_log_once(ch, ...)` — fires once globally (atomic test-and-set via H2K_atomic_setbit) +- `H2K_log_once_ht(ch, ...)` — fires once per hardware thread (lockless, per-ht only) +- `H2K_log_throttle(ch, iv, ...)` — global rate limit (serialized by logbuf_lock) +- `H2K_log_throttle_ht(ch, iv, ...)` — per-ht rate limit (lockless) +Channel IDs (H2K_LOG_CH_RESCHED, H2K_LOG_CH_COPROC, H2K_LOG_CH_N) declared in +max.h under #ifdef H2K_LOGBUF (alongside LOGBUF_PER_HT_SIZE). diff --git a/wip_notes.md b/wip_notes.md new file mode 100644 index 000000000..9af3b3eaa --- /dev/null +++ b/wip_notes.md @@ -0,0 +1,50 @@ +# WIP: Log Spam Control (Phase 3) + +## Branch: wip/log-spam-control + +## What's done + +### log.h +- `H2K_log_once(fmt, ...)` — fires once globally per callsite (callsite-static `u32_t __f`) +- `H2K_log_once_ht(fmt, ...)` — fires once per hardware thread (callsite-static `u32_t __f[MAX_HTHREADS]`) +- `H2K_log_throttle(interval, fmt, ...)` — rate-limit globally (callsite-static `u64_t __t`) +- `H2K_log_throttle_ht(interval, fmt, ...)` — rate-limit per hardware thread +- Severity variants for all four: `_err`, `_warn`, `_info` suffixes + - e.g. `H2K_log_once_err(...)`, `H2K_log_throttle_ht_warn(interval, ...)` +- All three build branches consistent: `H2K_LOGBUF` (full), `H2K_LOG_PRINTF` (pass-through), off (no-op) + +### log.ref.c +- `H2K_log_once(u32_t *flag)` — `H2K_atomic_setbit`, returns 1 on first call +- `H2K_log_once_ht(u32_t *flags)` — per-ht slot, lockless +- `H2K_log_throttle(u64_t *last, u64_t interval)` — pcycle delta, uses `logbuf_lock` +- `H2K_log_throttle_ht(u64_t *last, u64_t interval)` — per-ht slot, lockless + +### log_diagram.excalidraw +- Updated compile-time flags box: removed `H2K_LOG_PRINTF`, added `make LOGBUF=sched` examples + +## Known issues / TODO + +1. **`H2K_LOG_PRINTF` inconsistency** — removed from diagram but still in `log.h` code. + Decision needed: remove from code too, or restore in diagram? + +2. **Global throttle deadlock risk** — `H2K_log_throttle` takes `logbuf_lock`. + Safe today (never called while lock is held), but fragile. Document or enforce. + +3. **`MAX_HTHREADS` hidden dependency** — `_ht` macros require `max.h` included + before `log.h`. Works in kernel, but not obvious from the header alone. + +4. **Inline header problem (deferred)** — callsite-static `__f` is duplicated + per translation unit for `static inline` functions in headers (e.g. `readylist.h`). + Workaround: channel-ID design using `H2K_gp` state (see plan file). Deferred. + +## How spam control works + +Each macro expansion creates its own `static` local variable at that point in source: +- `once`: `static u32_t __f = 0` — atomically set on first call, suppressed after +- `throttle`: `static u64_t __t = 0` — timestamp of last fire, checked against interval + +Per-function independence: each expansion site has its own `__f`/`__t`, so two +`H2K_log_once()` calls in different functions fire independently (once each). + +Time unit for throttle: CPU pcycles via `H2K_get_pcycle_reg()` — same concept as +Linux `printk_ratelimited` but cycle-based instead of wall-clock milliseconds. From dd64d3eda952934a2ff9ccd539f450a1a0e6a281 Mon Sep 17 00:00:00 2001 From: Zeev Belinsky Date: Mon, 29 Jun 2026 12:08:30 -0700 Subject: [PATCH 2/4] log: full severity/once/throttle API with per-module level control MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Expands the logging system from a simple H2K_log() macro into a complete structured logging API with severity levels, spam control, and build-time filtering. ## New API (all three build modes: LOGBUF, LOG_PRINTF, silent) Severity variants: H2K_log_err/warn/info/dbg(fmt, ...) H2K_log_string_at(level, S), H2K_log_string_err/warn/info/dbg(S) Spam control — log once per callsite: H2K_log_once[_err/warn/info/dbg](...) H2K_log_once_ht[_err/warn/info/dbg](...) per hardware thread Spam control — rate limited by PCycle interval: H2K_log_throttle[_err/warn/info/dbg](interval, ...) H2K_log_throttle_ht[_err/warn/info/dbg](interval, ...) per hardware thread All string variants (_string_once, _string_throttle, _ht) follow the same pattern, giving a full NxM matrix of combinations. ## Log prefix format (same in both LOGBUF and LOG_PRINTF) [ht][LEVEL][][:] message ## Build-time level filtering make LOGBUF=1[2] whole kernel, INFO and above only make LOGBUF=sched[1] sched directory, WARN and above make LOGBUF=dosched.ref.c[0] single file, ERROR only make LOGBUF=sched,futex[2] mixed, no level = default (DBG) The [level] syntax works for both kernel (LOGBUF) and standalone test (LOG_PRINTF) builds via Makefile.inc.test. ## Implementation notes - LOGBUF: lockless per-htid ring buffer; spinlock only for Angel flush. Formatting (emit_prefix + format parse) happens outside the lock. H2K_log_once uses H2K_atomic_setbit; H2K_log_throttle uses logbuf_lock. H2K_log_throttle_ht / H2K_log_once_ht are lockless (per-slot ownership). - LOG_PRINTF: static inline helpers (H2K_printf_now via H2K_get_pcycle_reg, H2K_printf_basename via strrchr) give full prefix with zero link deps. H2K_printf_log_once (atomic) and H2K_printf_log_throttle (spinlock) live in log.ref.c under #ifdef H2K_LOG_PRINTF. - H2K_log_string now has identical semantics in both modes (full prefix + level check), replacing the previous puts() shortcut in LOG_PRINTF. Signed-off-by: Zeev Belinsky --- kernel/Makefile | 18 +- kernel/data/readylist/readylist.h | 4 +- kernel/data/readylist/test/Makefile | 2 +- kernel/init/setup/setup.ref.c | 14 +- kernel/traps/hwconfig/hwconfig.ref.c | 12 +- kernel/util/log/log.h | 228 ++++++-- kernel/util/log/log.ref.c | 95 ++-- logging-api.excalidraw | 809 +++++++++++++++++++++++++++ logging-arch.excalidraw | 350 ++++++++++++ scripts/Makefile.inc.test | 4 + 10 files changed, 1438 insertions(+), 98 deletions(-) create mode 100644 logging-api.excalidraw create mode 100644 logging-arch.excalidraw diff --git a/kernel/Makefile b/kernel/Makefile index 60386c03d..a2c5d545b 100644 --- a/kernel/Makefile +++ b/kernel/Makefile @@ -135,18 +135,26 @@ $(foreach MODPATH,$(MKINCLUDES),$(eval $(DO_INCLUDE))) ALL_OFILES := $(REF_OFILES) $(CHECK_OFILES) $(OPT_V2_OFILES) $(OPT_V3_OFILES) $(OPT_V4_OFILES) $(OPT_V5_OFILES) $(OPT_V60_OFILES) $(OPT_V65_OFILES) $(OPT_V68_OFILES) $(OPT_V73_OFILES) $(OPT_V81_OFILES) ifdef LOGBUF -ifeq ($(LOGBUF),1) +_logbuf_one_mod := $(word 1,$(subst [, ,$(LOGBUF))) +_logbuf_one_level := $(subst ],,$(word 2,$(subst [, ,$(LOGBUF)))) +ifeq ($(_logbuf_one_mod),1) CFLAGS += -DH2K_LOGBUF +ifneq ($(_logbuf_one_level),) +CFLAGS += -DH2K_LOG_LEVEL=$(_logbuf_one_level) +endif else _logbuf_comma := , $(foreach _tok,$(subst $(_logbuf_comma), ,$(LOGBUF)),\ - $(eval _logbuf_hits := $(filter %/$(basename $(_tok)).o,$(ALL_OFILES))) \ + $(eval _ll_mod := $(word 1,$(subst [, ,$(_tok))))\ + $(eval _ll_level := $(subst ],,$(word 2,$(subst [, ,$(_tok)))))\ + $(eval _logbuf_hits := $(filter %/$(basename $(_ll_mod)).o,$(ALL_OFILES)))\ $(if $(_logbuf_hits),,\ - $(eval _logbuf_hits := $(foreach _o,$(ALL_OFILES),$(if $(findstring /$(_tok)/,$(_o)),$(_o))))) \ + $(eval _logbuf_hits := $(foreach _o,$(ALL_OFILES),$(if $(findstring /$(_ll_mod)/,$(_o)),$(_o)))))\ $(if $(_logbuf_hits),\ - $(eval $(_logbuf_hits) : CFLAGS += -DH2K_LOGBUF),\ - $(warning LOGBUF: token '$(_tok)' matched no kernel sources))) + $(eval $(_logbuf_hits) : CFLAGS += -DH2K_LOGBUF)\ + $(if $(_ll_level),$(eval $(_logbuf_hits) : CFLAGS += -DH2K_LOG_LEVEL=$(_ll_level))),\ + $(warning LOGBUF: token '$(_ll_mod)' matched no kernel sources))) $(foreach _o,$(ALL_OFILES),\ $(if $(findstring /util/log/,$(_o)),$(eval $(_o) : CFLAGS += -DH2K_LOGBUF)) \ diff --git a/kernel/data/readylist/readylist.h b/kernel/data/readylist/readylist.h index 108fee079..133f219c5 100644 --- a/kernel/data/readylist/readylist.h +++ b/kernel/data/readylist/readylist.h @@ -95,7 +95,7 @@ static inline void H2K_update_coprocs(u32_t hthread, u32_t hthread_xe, u32_t hth } } else { if (head_xe) { - H2K_log_once_ht(H2K_LOG_CH_COPROC, "hthread %d update_coprocs: add xe\n", hthread); + H2K_log_once_ht("hthread %d update_coprocs: add xe\n", hthread); } } if (hthread_xe2) { @@ -220,7 +220,7 @@ static inline H2K_thread_context *H2K_ready_getbest(u32_t hthread) H2K_thread_context *ret; u32_t prio; - H2K_log_throttle_ht(H2K_LOG_CH_RESCHED, 1000000, "hthread %d getbest\n", hthread); + H2K_log_throttle_ht(1000000, "hthread %d getbest\n", hthread); prio = H2K_ready_best_prio(); if (prio >= MAX_PRIOS) { // !H2K_ready_any_valid(), go to sleep #ifdef CLUSTER_SCHED diff --git a/kernel/data/readylist/test/Makefile b/kernel/data/readylist/test/Makefile index a70f970d7..25c1786f7 100644 --- a/kernel/data/readylist/test/Makefile +++ b/kernel/data/readylist/test/Makefile @@ -1,4 +1,4 @@ - + OBJS+=test.o RECOMPILE_DIRS += $(H2DIR)/kernel/data/readylist RECOMPILE_SRCS_PREFS += readylist diff --git a/kernel/init/setup/setup.ref.c b/kernel/init/setup/setup.ref.c index 98b0f5339..5a1b213cf 100644 --- a/kernel/init/setup/setup.ref.c +++ b/kernel/init/setup/setup.ref.c @@ -92,13 +92,13 @@ IN_SECTION(".text.init.setup") static H2K_vmblock_t *H2K_init_setup(u32_t multic H2K_l2cache_init(); H2K_tcm_copy(last_tlb_index); H2K_trace_init(); - H2K_runlist_init(); //fix - H2K_readylist_init(); //fix - H2K_lowprio_init(); //fix - H2K_futex_init(); //fix - H2K_intconfig_init(ssbase); //fix - H2K_thread_init(); - H2K_asid_table_init(); //fix + H2K_runlist_init(); + H2K_readylist_init(); + H2K_lowprio_init(); + H2K_futex_init(); + H2K_intconfig_init(ssbase); + H2K_thread_init(); + H2K_asid_table_init(); #ifdef CRASH_DEBUG H2K_stlb_tcmcrash_init(); diff --git a/kernel/traps/hwconfig/hwconfig.ref.c b/kernel/traps/hwconfig/hwconfig.ref.c index 2c8d01dac..830622f41 100644 --- a/kernel/traps/hwconfig/hwconfig.ref.c +++ b/kernel/traps/hwconfig/hwconfig.ref.c @@ -273,7 +273,7 @@ u32_t H2K_trap_hwconfig_hlxbits(u32_t unused, void *unusedp, u32_t xa3, u32_t x BKL_LOCK(); if (xe3 && !(me->ccr & CCR_XE3_BIT_MASK)) { // turning xe3 on // block as if we got resched interrupt - H2K_log("hthread %d hlxbits: task 0x%08x setting xe3\n", me->hthread, me); + H2K_log("hthread %d hlxbits: task 0x%08x setting xe3\n", me->hthread, (u32_t)me); me->ccr = Q6_R_insert_RII(me->ccr, xa3, CCR_XA3_NBITS, CCR_XA3_BITS); me->ccr = Q6_R_insert_RII(me->ccr, xe3, 1, CCR_XE3_BIT); me->r00 = 0; @@ -286,7 +286,7 @@ u32_t H2K_trap_hwconfig_hlxbits(u32_t unused, void *unusedp, u32_t xa3, u32_t x u32_t hthread_xe2 = ((me->ssr & SSR_XE2_BIT_MASK) ? 1 : 0); xex(me->hthread, hthread_xe, hthread_xe2, 0, hthread_xe, hthread_xe2, 1); - H2K_log("hthread %d hlxbits: task 0x%08x clearing xe3\n", me->hthread, me); + H2K_log("hthread %d hlxbits: task 0x%08x clearing xe3\n", me->hthread, (u32_t)me); } BKL_UNLOCK(); } @@ -309,7 +309,7 @@ u32_t H2K_trap_hwconfig_hmxbits(u32_t unused, void *unusedp, u32_t xe2, u32_t un BKL_LOCK(); if (xe2 && !(me->ssr & SSR_XE2_BIT_MASK)) { // turning xe2 on // block as if we got resched interrupt - H2K_log("hthread %d hmxbits: task 0x%08x setting xe2\n", me->hthread, me); + H2K_log("hthread %d hmxbits: task 0x%08x setting xe2\n", me->hthread, (u32_t)me); // me->ccr = Q6_R_insert_RII(me->ccr, xa2, CCR_XA2_NBITS, CCR_XA2_BITS); me->ssr = Q6_R_insert_RII(me->ssr, xe2, 1, SSR_XE2_BIT); me->r00 = 0; @@ -322,7 +322,7 @@ u32_t H2K_trap_hwconfig_hmxbits(u32_t unused, void *unusedp, u32_t xe2, u32_t un u32_t hthread_xe3 = ((me->ccr & CCR_XE3_BIT_MASK) ? 1 : 0); xex(me->hthread, hthread_xe, 0, hthread_xe3, hthread_xe, 1, hthread_xe3); - H2K_log("hthread %d hmxbits: task 0x%08x clearing xe2\n", me->hthread, me); + H2K_log("hthread %d hmxbits: task 0x%08x clearing xe2\n", me->hthread, (u32_t)me); } BKL_UNLOCK(); } @@ -346,7 +346,7 @@ u32_t H2K_trap_hwconfig_extbits(u32_t unused, void *unusedp, u32_t xa, u32_t xe, BKL_LOCK(); if (xe && !(me->ssr & SSR_XE_BIT_MASK)) { // turning xe on // block as if we got resched interrupt - H2K_log("hthread %d extbits: task 0x%08x setting xe\n", me->hthread, me); + H2K_log("hthread %d extbits: task 0x%08x setting xe\n", me->hthread, (u32_t)me); if ((xa < EXT_HVX_XA_START || xa >= EXT_HVX_XA_START + H2K_gp->coproc_contexts) // not in HVX range #ifdef DO_EXT_SWITCH @@ -368,7 +368,7 @@ u32_t H2K_trap_hwconfig_extbits(u32_t unused, void *unusedp, u32_t xa, u32_t xe, u32_t hthread_xe3 = ((me->ccr & CCR_XE3_BIT_MASK) ? 1 : 0); xex(me->hthread, 0, hthread_xe2, hthread_xe3, 1, hthread_xe2, hthread_xe3); - H2K_log("hthread %d extbits: task 0x%08x clearing xe\n", me->hthread, me); + H2K_log("hthread %d extbits: task 0x%08x clearing xe\n", me->hthread, (u32_t)me); } BKL_UNLOCK(); } diff --git a/kernel/util/log/log.h b/kernel/util/log/log.h index 3ef16654e..6cc517269 100644 --- a/kernel/util/log/log.h +++ b/kernel/util/log/log.h @@ -19,7 +19,7 @@ #ifdef H2K_LOGBUF s32_t H2K_write(u32_t fd, const u8_t *buf, u32_t len) IN_SECTION(".text.util.log"); -u32_t H2K_do_log_string(const char *string) IN_SECTION(".text.util.log"); +u32_t H2K_do_log_string_at(u32_t level, const char *file, u32_t line, const char *string) IN_SECTION(".text.util.log"); s32_t H2K_log_print(u32_t level, const char *file, u32_t line, const char *format, ...) IN_SECTION(".text.util.log") __attribute__((format(printf, 4, 5))); char *H2K_logbuf_alloc(u32_t htid, u32_t count) IN_SECTION(".text.util.log"); @@ -36,7 +36,12 @@ u32_t H2K_log_throttle_ht(u64_t *last, u64_t interval) IN_SECTION(".text.util.lo #define H2K_log_info(...) H2K_log_at(H2K_LOG_INFO, __VA_ARGS__) #define H2K_log_dbg(...) H2K_log_at(H2K_LOG_DBG, __VA_ARGS__) #define H2K_log(...) H2K_log_dbg(__VA_ARGS__) -#define H2K_log_string(S) H2K_do_log_string(S) +#define H2K_log_string(S) H2K_do_log_string_at(H2K_LOG_DBG, __FILE__, __LINE__, S) +#define H2K_log_string_at(level, S) H2K_do_log_string_at((level), __FILE__, __LINE__, (S)) +#define H2K_log_string_err(S) H2K_log_string_at(H2K_LOG_ERR, S) +#define H2K_log_string_warn(S) H2K_log_string_at(H2K_LOG_WARN, S) +#define H2K_log_string_info(S) H2K_log_string_at(H2K_LOG_INFO, S) +#define H2K_log_string_dbg(S) H2K_log_string_at(H2K_LOG_DBG, S) #define H2K_log_once(...) \ do { static u32_t __f = 0; if ((H2K_log_once)(&__f)) H2K_log(__VA_ARGS__); } while (0) @@ -46,6 +51,8 @@ u32_t H2K_log_throttle_ht(u64_t *last, u64_t interval) IN_SECTION(".text.util.lo do { static u32_t __f = 0; if ((H2K_log_once)(&__f)) H2K_log_warn(__VA_ARGS__); } while (0) #define H2K_log_once_info(...) \ do { static u32_t __f = 0; if ((H2K_log_once)(&__f)) H2K_log_info(__VA_ARGS__); } while (0) +#define H2K_log_once_dbg(...) \ + do { static u32_t __f = 0; if ((H2K_log_once)(&__f)) H2K_log_dbg(__VA_ARGS__); } while (0) #define H2K_log_once_ht(...) \ do { static u32_t __f[MAX_HTHREADS] = {0}; if ((H2K_log_once_ht)(__f)) H2K_log(__VA_ARGS__); } while (0) #define H2K_log_once_ht_err(...) \ @@ -54,6 +61,8 @@ u32_t H2K_log_throttle_ht(u64_t *last, u64_t interval) IN_SECTION(".text.util.lo do { static u32_t __f[MAX_HTHREADS] = {0}; if ((H2K_log_once_ht)(__f)) H2K_log_warn(__VA_ARGS__); } while (0) #define H2K_log_once_ht_info(...) \ do { static u32_t __f[MAX_HTHREADS] = {0}; if ((H2K_log_once_ht)(__f)) H2K_log_info(__VA_ARGS__); } while (0) +#define H2K_log_once_ht_dbg(...) \ + do { static u32_t __f[MAX_HTHREADS] = {0}; if ((H2K_log_once_ht)(__f)) H2K_log_dbg(__VA_ARGS__); } while (0) #define H2K_log_throttle(interval, ...) \ do { static u64_t __t = 0; if ((H2K_log_throttle)(&__t, (interval))) H2K_log(__VA_ARGS__); } while (0) #define H2K_log_throttle_err(interval, ...) \ @@ -62,6 +71,8 @@ u32_t H2K_log_throttle_ht(u64_t *last, u64_t interval) IN_SECTION(".text.util.lo do { static u64_t __t = 0; if ((H2K_log_throttle)(&__t, (interval))) H2K_log_warn(__VA_ARGS__); } while (0) #define H2K_log_throttle_info(interval, ...) \ do { static u64_t __t = 0; if ((H2K_log_throttle)(&__t, (interval))) H2K_log_info(__VA_ARGS__); } while (0) +#define H2K_log_throttle_dbg(interval, ...) \ + do { static u64_t __t = 0; if ((H2K_log_throttle)(&__t, (interval))) H2K_log_dbg(__VA_ARGS__); } while (0) #define H2K_log_throttle_ht(interval, ...) \ do { static u64_t __t[MAX_HTHREADS] = {0}; if ((H2K_log_throttle_ht)(__t, (interval))) H2K_log(__VA_ARGS__); } while (0) #define H2K_log_throttle_ht_err(interval, ...) \ @@ -70,35 +81,141 @@ u32_t H2K_log_throttle_ht(u64_t *last, u64_t interval) IN_SECTION(".text.util.lo do { static u64_t __t[MAX_HTHREADS] = {0}; if ((H2K_log_throttle_ht)(__t, (interval))) H2K_log_warn(__VA_ARGS__); } while (0) #define H2K_log_throttle_ht_info(interval, ...) \ do { static u64_t __t[MAX_HTHREADS] = {0}; if ((H2K_log_throttle_ht)(__t, (interval))) H2K_log_info(__VA_ARGS__); } while (0) +#define H2K_log_throttle_ht_dbg(interval, ...) \ + do { static u64_t __t[MAX_HTHREADS] = {0}; if ((H2K_log_throttle_ht)(__t, (interval))) H2K_log_dbg(__VA_ARGS__); } while (0) + +#define H2K_log_string_once(S) \ + do { static u32_t __f = 0; if ((H2K_log_once)(&__f)) H2K_log_string(S); } while (0) +#define H2K_log_string_once_err(S) \ + do { static u32_t __f = 0; if ((H2K_log_once)(&__f)) H2K_log_string_err(S); } while (0) +#define H2K_log_string_once_warn(S) \ + do { static u32_t __f = 0; if ((H2K_log_once)(&__f)) H2K_log_string_warn(S); } while (0) +#define H2K_log_string_once_info(S) \ + do { static u32_t __f = 0; if ((H2K_log_once)(&__f)) H2K_log_string_info(S); } while (0) +#define H2K_log_string_once_dbg(S) \ + do { static u32_t __f = 0; if ((H2K_log_once)(&__f)) H2K_log_string_dbg(S); } while (0) +#define H2K_log_string_once_ht(S) \ + do { static u32_t __f[MAX_HTHREADS] = {0}; if ((H2K_log_once_ht)(__f)) H2K_log_string(S); } while (0) +#define H2K_log_string_once_ht_err(S) \ + do { static u32_t __f[MAX_HTHREADS] = {0}; if ((H2K_log_once_ht)(__f)) H2K_log_string_err(S); } while (0) +#define H2K_log_string_once_ht_warn(S) \ + do { static u32_t __f[MAX_HTHREADS] = {0}; if ((H2K_log_once_ht)(__f)) H2K_log_string_warn(S); } while (0) +#define H2K_log_string_once_ht_info(S) \ + do { static u32_t __f[MAX_HTHREADS] = {0}; if ((H2K_log_once_ht)(__f)) H2K_log_string_info(S); } while (0) +#define H2K_log_string_once_ht_dbg(S) \ + do { static u32_t __f[MAX_HTHREADS] = {0}; if ((H2K_log_once_ht)(__f)) H2K_log_string_dbg(S); } while (0) +#define H2K_log_string_throttle(interval, S) \ + do { static u64_t __t = 0; if ((H2K_log_throttle)(&__t, (interval))) H2K_log_string(S); } while (0) +#define H2K_log_string_throttle_err(interval, S) \ + do { static u64_t __t = 0; if ((H2K_log_throttle)(&__t, (interval))) H2K_log_string_err(S); } while (0) +#define H2K_log_string_throttle_warn(interval, S) \ + do { static u64_t __t = 0; if ((H2K_log_throttle)(&__t, (interval))) H2K_log_string_warn(S); } while (0) +#define H2K_log_string_throttle_info(interval, S) \ + do { static u64_t __t = 0; if ((H2K_log_throttle)(&__t, (interval))) H2K_log_string_info(S); } while (0) +#define H2K_log_string_throttle_dbg(interval, S) \ + do { static u64_t __t = 0; if ((H2K_log_throttle)(&__t, (interval))) H2K_log_string_dbg(S); } while (0) +#define H2K_log_string_throttle_ht(interval, S) \ + do { static u64_t __t[MAX_HTHREADS] = {0}; if ((H2K_log_throttle_ht)(__t, (interval))) H2K_log_string(S); } while (0) +#define H2K_log_string_throttle_ht_err(interval, S) \ + do { static u64_t __t[MAX_HTHREADS] = {0}; if ((H2K_log_throttle_ht)(__t, (interval))) H2K_log_string_err(S); } while (0) +#define H2K_log_string_throttle_ht_warn(interval, S) \ + do { static u64_t __t[MAX_HTHREADS] = {0}; if ((H2K_log_throttle_ht)(__t, (interval))) H2K_log_string_warn(S); } while (0) +#define H2K_log_string_throttle_ht_info(interval, S) \ + do { static u64_t __t[MAX_HTHREADS] = {0}; if ((H2K_log_throttle_ht)(__t, (interval))) H2K_log_string_info(S); } while (0) +#define H2K_log_string_throttle_ht_dbg(interval, S) \ + do { static u64_t __t[MAX_HTHREADS] = {0}; if ((H2K_log_throttle_ht)(__t, (interval))) H2K_log_string_dbg(S); } while (0) #else #ifdef H2K_LOG_PRINTF #include #include +#include +#include + +static inline u64_t H2K_printf_now(void) { return H2K_get_pcycle_reg(); } +static inline const char *H2K_printf_basename(const char *p) { + const char *s = strrchr(p, '/'); return s ? s + 1 : p; +} +static inline u32_t H2K_printf_log_once_ht(u32_t *flags) { + u32_t htid = get_hwtnum(); + if (flags[htid]) return 0; + flags[htid] = 1; + return 1; +} +static inline u32_t H2K_printf_log_throttle_ht(u64_t *last, u64_t interval) { + u32_t htid = get_hwtnum(); + u64_t now = H2K_get_pcycle_reg(); + if (now - last[htid] < interval) return 0; + last[htid] = now; + return 1; +} + +u32_t H2K_printf_log_once(int *flag); +u32_t H2K_printf_log_throttle(u64_t *last, u64_t interval); + +static const char * const H2K_printf_level_str[] = { "ERROR", "WARN", "INFO", "DEBUG" }; + +#define H2K_log_at(level, file, line, fmt, ...) \ + do { if ((level) <= H2K_LOG_LEVEL) \ + printf("[ht-][%s][%llu][%s:%u] " fmt, H2K_printf_level_str[level], \ + (unsigned long long)H2K_printf_now(), \ + H2K_printf_basename(file), (unsigned int)(line), ##__VA_ARGS__); \ + } while (0) + +#define H2K_log_err(fmt, ...) H2K_log_at(H2K_LOG_ERR, __FILE__, __LINE__, fmt, ##__VA_ARGS__) +#define H2K_log_warn(fmt, ...) H2K_log_at(H2K_LOG_WARN, __FILE__, __LINE__, fmt, ##__VA_ARGS__) +#define H2K_log_info(fmt, ...) H2K_log_at(H2K_LOG_INFO, __FILE__, __LINE__, fmt, ##__VA_ARGS__) +#define H2K_log_dbg(fmt, ...) H2K_log_at(H2K_LOG_DBG, __FILE__, __LINE__, fmt, ##__VA_ARGS__) +#define H2K_log(...) H2K_log_dbg(__VA_ARGS__) +#define H2K_log_string(S) H2K_log_at(H2K_LOG_DBG, __FILE__, __LINE__, "%s", S) +#define H2K_log_string_at(level, S) H2K_log_at((level), __FILE__, __LINE__, "%s", S) +#define H2K_log_string_err(S) H2K_log_at(H2K_LOG_ERR, __FILE__, __LINE__, "%s", S) +#define H2K_log_string_warn(S) H2K_log_at(H2K_LOG_WARN, __FILE__, __LINE__, "%s", S) +#define H2K_log_string_info(S) H2K_log_at(H2K_LOG_INFO, __FILE__, __LINE__, "%s", S) +#define H2K_log_string_dbg(S) H2K_log_at(H2K_LOG_DBG, __FILE__, __LINE__, "%s", S) + +#define H2K_log_once(...) do { static int __f = 0; if (H2K_printf_log_once(&__f)) H2K_log(__VA_ARGS__); } while (0) +#define H2K_log_once_err(...) do { static int __f = 0; if (H2K_printf_log_once(&__f)) H2K_log_err(__VA_ARGS__); } while (0) +#define H2K_log_once_warn(...) do { static int __f = 0; if (H2K_printf_log_once(&__f)) H2K_log_warn(__VA_ARGS__); } while (0) +#define H2K_log_once_info(...) do { static int __f = 0; if (H2K_printf_log_once(&__f)) H2K_log_info(__VA_ARGS__); } while (0) +#define H2K_log_once_dbg(...) do { static int __f = 0; if (H2K_printf_log_once(&__f)) H2K_log_dbg(__VA_ARGS__); } while (0) +#define H2K_log_once_ht(...) do { static u32_t __f[MAX_HTHREADS] = {0}; if (H2K_printf_log_once_ht(__f)) H2K_log(__VA_ARGS__); } while (0) +#define H2K_log_once_ht_err(...) do { static u32_t __f[MAX_HTHREADS] = {0}; if (H2K_printf_log_once_ht(__f)) H2K_log_err(__VA_ARGS__); } while (0) +#define H2K_log_once_ht_warn(...) do { static u32_t __f[MAX_HTHREADS] = {0}; if (H2K_printf_log_once_ht(__f)) H2K_log_warn(__VA_ARGS__); } while (0) +#define H2K_log_once_ht_info(...) do { static u32_t __f[MAX_HTHREADS] = {0}; if (H2K_printf_log_once_ht(__f)) H2K_log_info(__VA_ARGS__); } while (0) +#define H2K_log_once_ht_dbg(...) do { static u32_t __f[MAX_HTHREADS] = {0}; if (H2K_printf_log_once_ht(__f)) H2K_log_dbg(__VA_ARGS__); } while (0) + +#define H2K_log_throttle(interval, ...) do { static u64_t __t = 0; if (H2K_printf_log_throttle(&__t, (interval))) H2K_log(__VA_ARGS__); } while (0) +#define H2K_log_throttle_err(interval, ...) do { static u64_t __t = 0; if (H2K_printf_log_throttle(&__t, (interval))) H2K_log_err(__VA_ARGS__); } while (0) +#define H2K_log_throttle_warn(interval, ...) do { static u64_t __t = 0; if (H2K_printf_log_throttle(&__t, (interval))) H2K_log_warn(__VA_ARGS__); } while (0) +#define H2K_log_throttle_info(interval, ...) do { static u64_t __t = 0; if (H2K_printf_log_throttle(&__t, (interval))) H2K_log_info(__VA_ARGS__); } while (0) +#define H2K_log_throttle_dbg(interval, ...) do { static u64_t __t = 0; if (H2K_printf_log_throttle(&__t, (interval))) H2K_log_dbg(__VA_ARGS__); } while (0) +#define H2K_log_throttle_ht(interval, ...) do { static u64_t __t[MAX_HTHREADS] = {0}; if (H2K_printf_log_throttle_ht(__t, (interval))) H2K_log(__VA_ARGS__); } while (0) +#define H2K_log_throttle_ht_err(interval, ...) do { static u64_t __t[MAX_HTHREADS] = {0}; if (H2K_printf_log_throttle_ht(__t, (interval))) H2K_log_err(__VA_ARGS__); } while (0) +#define H2K_log_throttle_ht_warn(interval, ...) do { static u64_t __t[MAX_HTHREADS] = {0}; if (H2K_printf_log_throttle_ht(__t, (interval))) H2K_log_warn(__VA_ARGS__); } while (0) +#define H2K_log_throttle_ht_info(interval, ...) do { static u64_t __t[MAX_HTHREADS] = {0}; if (H2K_printf_log_throttle_ht(__t, (interval))) H2K_log_info(__VA_ARGS__); } while (0) +#define H2K_log_throttle_ht_dbg(interval, ...) do { static u64_t __t[MAX_HTHREADS] = {0}; if (H2K_printf_log_throttle_ht(__t, (interval))) H2K_log_dbg(__VA_ARGS__); } while (0) -#define H2K_log_err(fmt, ...) printf("[E] " fmt, ##__VA_ARGS__) -#define H2K_log_warn(fmt, ...) printf("[W] " fmt, ##__VA_ARGS__) -#define H2K_log_info(fmt, ...) printf("[I] " fmt, ##__VA_ARGS__) -#define H2K_log_dbg(fmt, ...) printf("[D] " fmt, ##__VA_ARGS__) -#define H2K_log(...) H2K_log_dbg(__VA_ARGS__) -#define H2K_log_string(S) puts(S) - -#define H2K_log_once(...) H2K_log(__VA_ARGS__) -#define H2K_log_once_err(...) H2K_log_err(__VA_ARGS__) -#define H2K_log_once_warn(...) H2K_log_warn(__VA_ARGS__) -#define H2K_log_once_info(...) H2K_log_info(__VA_ARGS__) -#define H2K_log_once_ht(...) H2K_log(__VA_ARGS__) -#define H2K_log_once_ht_err(...) H2K_log_err(__VA_ARGS__) -#define H2K_log_once_ht_warn(...) H2K_log_warn(__VA_ARGS__) -#define H2K_log_once_ht_info(...) H2K_log_info(__VA_ARGS__) -#define H2K_log_throttle(interval, ...) H2K_log(__VA_ARGS__) -#define H2K_log_throttle_err(interval, ...) H2K_log_err(__VA_ARGS__) -#define H2K_log_throttle_warn(interval, ...) H2K_log_warn(__VA_ARGS__) -#define H2K_log_throttle_info(interval, ...) H2K_log_info(__VA_ARGS__) -#define H2K_log_throttle_ht(interval, ...) H2K_log(__VA_ARGS__) -#define H2K_log_throttle_ht_err(interval, ...) H2K_log_err(__VA_ARGS__) -#define H2K_log_throttle_ht_warn(interval, ...) H2K_log_warn(__VA_ARGS__) -#define H2K_log_throttle_ht_info(interval, ...) H2K_log_info(__VA_ARGS__) +#define H2K_log_string_once(S) do { static int __f = 0; if (H2K_printf_log_once(&__f)) H2K_log_string(S); } while (0) +#define H2K_log_string_once_err(S) do { static int __f = 0; if (H2K_printf_log_once(&__f)) H2K_log_string_err(S); } while (0) +#define H2K_log_string_once_warn(S) do { static int __f = 0; if (H2K_printf_log_once(&__f)) H2K_log_string_warn(S); } while (0) +#define H2K_log_string_once_info(S) do { static int __f = 0; if (H2K_printf_log_once(&__f)) H2K_log_string_info(S); } while (0) +#define H2K_log_string_once_dbg(S) do { static int __f = 0; if (H2K_printf_log_once(&__f)) H2K_log_string_dbg(S); } while (0) +#define H2K_log_string_once_ht(S) do { static u32_t __f[MAX_HTHREADS] = {0}; if (H2K_printf_log_once_ht(__f)) H2K_log_string(S); } while (0) +#define H2K_log_string_once_ht_err(S) do { static u32_t __f[MAX_HTHREADS] = {0}; if (H2K_printf_log_once_ht(__f)) H2K_log_string_err(S); } while (0) +#define H2K_log_string_once_ht_warn(S) do { static u32_t __f[MAX_HTHREADS] = {0}; if (H2K_printf_log_once_ht(__f)) H2K_log_string_warn(S); } while (0) +#define H2K_log_string_once_ht_info(S) do { static u32_t __f[MAX_HTHREADS] = {0}; if (H2K_printf_log_once_ht(__f)) H2K_log_string_info(S); } while (0) +#define H2K_log_string_once_ht_dbg(S) do { static u32_t __f[MAX_HTHREADS] = {0}; if (H2K_printf_log_once_ht(__f)) H2K_log_string_dbg(S); } while (0) +#define H2K_log_string_throttle(interval, S) do { static u64_t __t = 0; if (H2K_printf_log_throttle(&__t, (interval))) H2K_log_string(S); } while (0) +#define H2K_log_string_throttle_err(interval, S) do { static u64_t __t = 0; if (H2K_printf_log_throttle(&__t, (interval))) H2K_log_string_err(S); } while (0) +#define H2K_log_string_throttle_warn(interval, S) do { static u64_t __t = 0; if (H2K_printf_log_throttle(&__t, (interval))) H2K_log_string_warn(S); } while (0) +#define H2K_log_string_throttle_info(interval, S) do { static u64_t __t = 0; if (H2K_printf_log_throttle(&__t, (interval))) H2K_log_string_info(S); } while (0) +#define H2K_log_string_throttle_dbg(interval, S) do { static u64_t __t = 0; if (H2K_printf_log_throttle(&__t, (interval))) H2K_log_string_dbg(S); } while (0) +#define H2K_log_string_throttle_ht(interval, S) do { static u64_t __t[MAX_HTHREADS] = {0}; if (H2K_printf_log_throttle_ht(__t, (interval))) H2K_log_string(S); } while (0) +#define H2K_log_string_throttle_ht_err(interval, S) do { static u64_t __t[MAX_HTHREADS] = {0}; if (H2K_printf_log_throttle_ht(__t, (interval))) H2K_log_string_err(S); } while (0) +#define H2K_log_string_throttle_ht_warn(interval, S) do { static u64_t __t[MAX_HTHREADS] = {0}; if (H2K_printf_log_throttle_ht(__t, (interval))) H2K_log_string_warn(S); } while (0) +#define H2K_log_string_throttle_ht_info(interval, S) do { static u64_t __t[MAX_HTHREADS] = {0}; if (H2K_printf_log_throttle_ht(__t, (interval))) H2K_log_string_info(S); } while (0) +#define H2K_log_string_throttle_ht_dbg(interval, S) do { static u64_t __t[MAX_HTHREADS] = {0}; if (H2K_printf_log_throttle_ht(__t, (interval))) H2K_log_string_dbg(S); } while (0) #else #define H2K_log_err(...) #define H2K_log_warn(...) @@ -106,22 +223,51 @@ u32_t H2K_log_throttle_ht(u64_t *last, u64_t interval) IN_SECTION(".text.util.lo #define H2K_log_dbg(...) #define H2K_log(...) #define H2K_log_string(S) -#define H2K_log_once(...) do {} while (0) -#define H2K_log_once_err(...) do {} while (0) -#define H2K_log_once_warn(...) do {} while (0) -#define H2K_log_once_info(...) do {} while (0) -#define H2K_log_once_ht(...) do {} while (0) -#define H2K_log_once_ht_err(...) do {} while (0) -#define H2K_log_once_ht_warn(...) do {} while (0) -#define H2K_log_once_ht_info(...) do {} while (0) -#define H2K_log_throttle(interval, ...) do {} while (0) -#define H2K_log_throttle_err(interval, ...) do {} while (0) -#define H2K_log_throttle_warn(interval, ...) do {} while (0) -#define H2K_log_throttle_info(interval, ...) do {} while (0) -#define H2K_log_throttle_ht(interval, ...) do {} while (0) -#define H2K_log_throttle_ht_err(interval, ...) do {} while (0) -#define H2K_log_throttle_ht_warn(interval, ...) do {} while (0) -#define H2K_log_throttle_ht_info(interval, ...) do {} while (0) +#define H2K_log_string_at(level, S) +#define H2K_log_string_err(S) +#define H2K_log_string_warn(S) +#define H2K_log_string_info(S) +#define H2K_log_string_dbg(S) +#define H2K_log_once(...) +#define H2K_log_once_err(...) +#define H2K_log_once_warn(...) +#define H2K_log_once_info(...) +#define H2K_log_once_dbg(...) +#define H2K_log_once_ht(...) +#define H2K_log_once_ht_err(...) +#define H2K_log_once_ht_warn(...) +#define H2K_log_once_ht_info(...) +#define H2K_log_once_ht_dbg(...) +#define H2K_log_throttle(interval, ...) +#define H2K_log_throttle_err(interval, ...) +#define H2K_log_throttle_warn(interval, ...) +#define H2K_log_throttle_info(interval, ...) +#define H2K_log_throttle_dbg(interval, ...) +#define H2K_log_throttle_ht(interval, ...) +#define H2K_log_throttle_ht_err(interval, ...) +#define H2K_log_throttle_ht_warn(interval, ...) +#define H2K_log_throttle_ht_info(interval, ...) +#define H2K_log_throttle_ht_dbg(interval, ...) +#define H2K_log_string_once(S) +#define H2K_log_string_once_err(S) +#define H2K_log_string_once_warn(S) +#define H2K_log_string_once_info(S) +#define H2K_log_string_once_dbg(S) +#define H2K_log_string_once_ht(S) +#define H2K_log_string_once_ht_err(S) +#define H2K_log_string_once_ht_warn(S) +#define H2K_log_string_once_ht_info(S) +#define H2K_log_string_once_ht_dbg(S) +#define H2K_log_string_throttle(interval, S) +#define H2K_log_string_throttle_err(interval, S) +#define H2K_log_string_throttle_warn(interval, S) +#define H2K_log_string_throttle_info(interval, S) +#define H2K_log_string_throttle_dbg(interval, S) +#define H2K_log_string_throttle_ht(interval, S) +#define H2K_log_string_throttle_ht_err(interval, S) +#define H2K_log_string_throttle_ht_warn(interval, S) +#define H2K_log_string_throttle_ht_info(interval, S) +#define H2K_log_string_throttle_ht_dbg(interval, S) #endif #endif diff --git a/kernel/util/log/log.ref.c b/kernel/util/log/log.ref.c index 466590830..9b5084f63 100644 --- a/kernel/util/log/log.ref.c +++ b/kernel/util/log/log.ref.c @@ -23,28 +23,6 @@ #endif static u32_t log_level = H2K_LOG_LEVEL; -static u32_t strcpy(char *dest, const char *src) -{ - u32_t count = 1; - - while ('\0' != (*dest++ = *src++)) { - count++; - } - - return count; -} - -static u32_t strlen(const char *src) -{ - u32_t count = 0; - - while ('\0' != (*src++)) { - count++; - } - - return count; -} - static u32_t logbuf_space(u32_t htid) { return LOGBUF_PER_HT_SIZE - H2K_gp->logbuf_pos[htid] - 1; @@ -97,27 +75,41 @@ char *H2K_logbuf_alloc(u32_t htid, u32_t count) { return ret; } -u32_t H2K_do_log_string(const char *string) { +static u32_t emit_string(u32_t htid, const char *s); +static u32_t emit_prefix(u32_t htid, u32_t level, const char *file, u32_t line); + +u32_t H2K_do_log_string_at(u32_t level, const char *file, u32_t line, const char *string) { u32_t htid = get_hwtnum(); - u32_t len = strlen(string); - s32_t ret = len; + char *buf; + u32_t start; + u32_t len = 0; - if (H2K_gp->logbuf_enable) { - strcpy(H2K_logbuf_alloc(htid, len + 1), string); - } + if (!H2K_gp->logbuf_enable && !H2K_gp->log_enable) + return 0; + + if (level > log_level) + return 0; + + buf = H2K_gp->logbuf[htid]; + start = H2K_gp->logbuf_pos[htid]; + + len += emit_prefix(htid, level, file, line); + len += emit_string(htid, string); if (H2K_gp->log_enable) { - /* the angel SYS_WRITE channel is shared hardware: serialize it */ H2K_spinlock_lock(&H2K_gp->logbuf_lock); - ret = H2K_write(1, (const u8_t *)"H2K: ", 5); - if (ret >= 0) { - ret = H2K_write(1, (const u8_t *)string, len); + if (H2K_gp->logbuf_pos[htid] < start) { + s32_t ret = H2K_write(1, (const u8_t *)(buf + start), LOGBUF_PER_HT_SIZE - start - 1); + if (ret >= 0) + H2K_write(1, (const u8_t *)buf, len - (LOGBUF_PER_HT_SIZE - start - 1)); + } else { + H2K_write(1, (const u8_t *)(buf + start), len); } H2K_spinlock_unlock(&H2K_gp->logbuf_lock); } - return ret; + return len; } /* Append one char to htid's ring, keeping a trailing NUL for string reads. */ @@ -170,7 +162,7 @@ u32_t num(u32_t htid, u64_t n, u32_t base, u32_t width, u32_t neg) { } /* Indexed by H2K_LOG_* severity level. */ -static const char level_char[] = { 'E', 'W', 'I', 'D' }; +static const char *level_str[] = { "ERROR", "WARN", "INFO", "DEBUG" }; /* * Emit prefix into htid's ring and return its length: @@ -180,7 +172,7 @@ static u32_t emit_prefix(u32_t htid, u32_t level, const char *file, u32_t line) const char *base = file; const char *p = file; u32_t len = 0; - char sev = (level < sizeof(level_char)) ? level_char[level] : '?'; + const char *sev = (level < sizeof(level_str) / sizeof(level_str[0])) ? level_str[level] : "?"; /* keep the basename only, dropping any leading directory path */ while ('\0' != *p) { @@ -191,7 +183,7 @@ static u32_t emit_prefix(u32_t htid, u32_t level, const char *file, u32_t line) len += emit_string(htid, "[ht"); len += num(htid, (u64_t)htid, 10, 0, 0); len += emit_string(htid, "]["); - emit_char(htid, sev); len++; + len += emit_string(htid, sev); len += emit_string(htid, "]["); len += num(htid, H2K_get_pcycle_reg(), 10, 0, 0); len += emit_string(htid, "]["); @@ -331,6 +323,15 @@ s32_t H2K_log_print(u32_t level, const char *file, u32_t line, const char *fmt, /* GLOBAL once: atomic test-and-set on the callsite flag. * H2K_atomic_setbit returns 1 when the bit was clear (first setter wins). */ +/* Undefine the once/throttle macros so the function definitions below are not + * expanded by the preprocessor — the macros use parenthesized calls like + * (H2K_log_once)() to call through, but the definitions themselves must not + * be subject to macro substitution. */ +#undef H2K_log_once +#undef H2K_log_once_ht +#undef H2K_log_throttle +#undef H2K_log_throttle_ht + u32_t H2K_log_once(u32_t *flag) { return H2K_atomic_setbit(flag, 0); } @@ -391,3 +392,25 @@ char *H2K_log_init() { } #endif + +#ifdef H2K_LOG_PRINTF + +u32_t H2K_printf_log_once(int *flag) { + return H2K_atomic_setbit((u32_t *)flag, 0); +} + +u32_t H2K_printf_log_throttle(u64_t *last, u64_t interval) { + static H2K_spinlock_t lock = 0; + u64_t now = H2K_get_pcycle_reg(); + u32_t go = 0; + + H2K_spinlock_lock(&lock); + if (now - *last >= interval) { + *last = now; + go = 1; + } + H2K_spinlock_unlock(&lock); + return go; +} + +#endif diff --git a/logging-api.excalidraw b/logging-api.excalidraw new file mode 100644 index 000000000..7fc017467 --- /dev/null +++ b/logging-api.excalidraw @@ -0,0 +1,809 @@ +{ + "type": "excalidraw", + "version": 2, + "source": "https://marketplace.visualstudio.com/items?itemName=pomdtr.excalidraw-editor", + "elements": [ + { + "type": "text", + "id": "title", + "x": 300, + "y": 10, + "width": 500, + "height": 35, + "text": "H2K Logging — Makefile & Code API", + "fontSize": 24, + "fontFamily": 1, + "textAlign": "center", + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 147791773, + "index": "a0", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "verticalAlign": "top", + "containerId": null, + "originalText": "H2K Logging — Makefile & Code API", + "autoResize": true, + "lineHeight": 1.4583333333333333 + }, + { + "type": "text", + "id": "makefile-title", + "x": 40, + "y": 60, + "width": 300, + "height": 25, + "text": "① Makefile — what gets compiled", + "fontSize": 16, + "fontFamily": 1, + "strokeColor": "#1971c2", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 115995827, + "index": "a1", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "① Makefile — what gets compiled", + "autoResize": true, + "lineHeight": 1.5625 + }, + { + "type": "rectangle", + "id": "mk-whole", + "x": 40, + "y": 90, + "width": 320, + "height": 50, + "strokeColor": "#1971c2", + "backgroundColor": "#d0ebff", + "fillStyle": "solid", + "roundness": { + "type": 3 + }, + "version": 2, + "versionNonce": 744694781, + "index": "a2", + "isDeleted": false, + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false + }, + { + "type": "text", + "id": "mk-whole-label", + "x": 50, + "y": 100, + "width": 196.5107421875, + "height": 29.999999999999996, + "text": "make LOGBUF=1\n→ whole kernel: -DH2K_LOGBUF", + "fontSize": 13, + "fontFamily": 2, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 3, + "versionNonce": 1812833149, + "index": "a3", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728084480, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "make LOGBUF=1\n→ whole kernel: -DH2K_LOGBUF", + "autoResize": true, + "lineHeight": 1.1538461538461537 + }, + { + "type": "rectangle", + "id": "mk-dir", + "x": 40, + "y": 155, + "width": 320, + "height": 50, + "strokeColor": "#1971c2", + "backgroundColor": "#d0ebff", + "fillStyle": "solid", + "roundness": { + "type": 3 + }, + "version": 2, + "versionNonce": 1538759773, + "index": "a4", + "isDeleted": false, + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false + }, + { + "type": "text", + "id": "mk-dir-label", + "x": 50, + "y": 165, + "width": 300, + "height": 30, + "text": "make LOGBUF=sched\n→ all files under /sched/", + "fontSize": 13, + "fontFamily": 2, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 308585459, + "index": "a5", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "make LOGBUF=sched\n→ all files under /sched/", + "autoResize": true, + "lineHeight": 1.1538461538461537 + }, + { + "type": "rectangle", + "id": "mk-file", + "x": 40, + "y": 220, + "width": 320, + "height": 50, + "strokeColor": "#1971c2", + "backgroundColor": "#d0ebff", + "fillStyle": "solid", + "roundness": { + "type": 3 + }, + "version": 2, + "versionNonce": 782108861, + "index": "a6", + "isDeleted": false, + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false + }, + { + "type": "text", + "id": "mk-file-label", + "x": 50, + "y": 230, + "width": 300, + "height": 30, + "text": "make LOGBUF=dosched.ref.c\n→ single file only", + "fontSize": 13, + "fontFamily": 2, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 414297491, + "index": "a7", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "make LOGBUF=dosched.ref.c\n→ single file only", + "autoResize": true, + "lineHeight": 1.1538461538461537 + }, + { + "type": "rectangle", + "id": "mk-level", + "x": 40, + "y": 285, + "width": 320, + "height": 65, + "strokeColor": "#1971c2", + "backgroundColor": "#d0ebff", + "fillStyle": "solid", + "roundness": { + "type": 3 + }, + "version": 2, + "versionNonce": 1186457885, + "index": "a8", + "isDeleted": false, + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false + }, + { + "type": "text", + "id": "mk-level-label", + "x": 50, + "y": 293, + "width": 300, + "height": 50, + "text": "make LOGBUF=sched[2],futex[3]\n→ sched: ERR+WARN+INFO\n→ futex: ERR+WARN+INFO+DBG", + "fontSize": 13, + "fontFamily": 2, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 267158323, + "index": "a9", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "make LOGBUF=sched[2],futex[3]\n→ sched: ERR+WARN+INFO\n→ futex: ERR+WARN+INFO+DBG", + "autoResize": true, + "lineHeight": 1.2820512820512822 + }, + { + "type": "text", + "id": "code-title", + "x": 430, + "y": 60, + "width": 700, + "height": 25, + "text": "② Code — macro API (same interface across all 3 build modes)", + "fontSize": 16, + "fontFamily": 1, + "strokeColor": "#2f9e44", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 1646003677, + "index": "aC", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "② Code — macro API (same interface across all 3 build modes)", + "autoResize": true, + "lineHeight": 1.5625 + }, + { + "type": "rectangle", + "id": "basic-box", + "x": 430, + "y": 90, + "width": 220, + "height": 130, + "strokeColor": "#2f9e44", + "backgroundColor": "#d3f9d8", + "fillStyle": "solid", + "roundness": { + "type": 3 + }, + "version": 2, + "versionNonce": 1643483763, + "index": "aD", + "isDeleted": false, + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false + }, + { + "type": "text", + "id": "basic-title", + "x": 440, + "y": 97, + "width": 200, + "height": 20, + "text": "Basic (severity)", + "fontSize": 14, + "fontFamily": 1, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 263799357, + "index": "aE", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "Basic (severity)", + "autoResize": true, + "lineHeight": 1.4285714285714286 + }, + { + "type": "text", + "id": "basic-label", + "x": 440, + "y": 118, + "width": 200, + "height": 95, + "text": "H2K_log(fmt, ...)\nH2K_log_err(fmt, ...)\nH2K_log_warn(fmt, ...)\nH2K_log_info(fmt, ...)\nH2K_log_dbg(fmt, ...)", + "fontSize": 13, + "fontFamily": 2, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 1428212755, + "index": "aF", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "H2K_log(fmt, ...)\nH2K_log_err(fmt, ...)\nH2K_log_warn(fmt, ...)\nH2K_log_info(fmt, ...)\nH2K_log_dbg(fmt, ...)", + "autoResize": true, + "lineHeight": 1.4615384615384615 + }, + { + "type": "rectangle", + "id": "string-box", + "x": 430, + "y": 235, + "width": 220, + "height": 130, + "strokeColor": "#2f9e44", + "backgroundColor": "#d3f9d8", + "fillStyle": "solid", + "roundness": { + "type": 3 + }, + "version": 2, + "versionNonce": 590344861, + "index": "aG", + "isDeleted": false, + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false + }, + { + "type": "text", + "id": "string-title", + "x": 440, + "y": 242, + "width": 200, + "height": 20, + "text": "String (no format parsing)", + "fontSize": 14, + "fontFamily": 1, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 1576260019, + "index": "aH", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "String (no format parsing)", + "autoResize": true, + "lineHeight": 1.4285714285714286 + }, + { + "type": "text", + "id": "string-label", + "x": 440, + "y": 263, + "width": 200, + "height": 95, + "text": "H2K_log_string(S)\nH2K_log_string_err(S)\nH2K_log_string_warn(S)\nH2K_log_string_info(S)\nH2K_log_string_dbg(S)", + "fontSize": 13, + "fontFamily": 2, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 154244861, + "index": "aI", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "H2K_log_string(S)\nH2K_log_string_err(S)\nH2K_log_string_warn(S)\nH2K_log_string_info(S)\nH2K_log_string_dbg(S)", + "autoResize": true, + "lineHeight": 1.4615384615384615 + }, + { + "type": "rectangle", + "id": "once-box", + "x": 670, + "y": 90, + "width": 230, + "height": 275, + "strokeColor": "#862e9c", + "backgroundColor": "#f3d9fa", + "fillStyle": "solid", + "roundness": { + "type": 3 + }, + "version": 2, + "versionNonce": 227877715, + "index": "aJ", + "isDeleted": false, + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false + }, + { + "type": "text", + "id": "once-title", + "x": 680, + "y": 97, + "width": 210, + "height": 20, + "text": "Once (global / per-ht)", + "fontSize": 14, + "fontFamily": 1, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 473935709, + "index": "aK", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "Once (global / per-ht)", + "autoResize": true, + "lineHeight": 1.4285714285714286 + }, + { + "type": "text", + "id": "once-label", + "x": 680, + "y": 118, + "width": 210, + "height": 240, + "text": "H2K_log_once(...)\nH2K_log_once_err(...)\nH2K_log_once_warn(...)\nH2K_log_once_info(...)\nH2K_log_once_dbg(...)\n\nH2K_log_once_ht(...)\nH2K_log_once_ht_err(...)\nH2K_log_once_ht_warn(...)\nH2K_log_once_ht_info(...)\nH2K_log_once_ht_dbg(...)", + "fontSize": 13, + "fontFamily": 2, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 207306995, + "index": "aL", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "H2K_log_once(...)\nH2K_log_once_err(...)\nH2K_log_once_warn(...)\nH2K_log_once_info(...)\nH2K_log_once_dbg(...)\n\nH2K_log_once_ht(...)\nH2K_log_once_ht_err(...)\nH2K_log_once_ht_warn(...)\nH2K_log_once_ht_info(...)\nH2K_log_once_ht_dbg(...)", + "autoResize": true, + "lineHeight": 1.6783216783216781 + }, + { + "type": "rectangle", + "id": "throttle-box", + "x": 920, + "y": 90, + "width": 260, + "height": 275, + "strokeColor": "#c92a2a", + "backgroundColor": "#ffe3e3", + "fillStyle": "solid", + "roundness": { + "type": 3 + }, + "version": 2, + "versionNonce": 1789639613, + "index": "aM", + "isDeleted": false, + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false + }, + { + "type": "text", + "id": "throttle-title", + "x": 930, + "y": 97, + "width": 240, + "height": 20, + "text": "Throttle (global / per-ht)", + "fontSize": 14, + "fontFamily": 1, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 869051027, + "index": "aN", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "Throttle (global / per-ht)", + "autoResize": true, + "lineHeight": 1.4285714285714286 + }, + { + "type": "text", + "id": "throttle-label", + "x": 930, + "y": 118, + "width": 240, + "height": 240, + "text": "H2K_log_throttle(iv, ...)\nH2K_log_throttle_err(iv, ...)\nH2K_log_throttle_warn(iv, ...)\nH2K_log_throttle_info(iv, ...)\nH2K_log_throttle_dbg(iv, ...)\n\nH2K_log_throttle_ht(iv, ...)\nH2K_log_throttle_ht_err(iv, ...)\nH2K_log_throttle_ht_warn(iv, ...)\nH2K_log_throttle_ht_info(iv, ...)\nH2K_log_throttle_ht_dbg(iv, ...)", + "fontSize": 13, + "fontFamily": 2, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "version": 2, + "versionNonce": 1016544285, + "index": "aO", + "isDeleted": false, + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "angle": 0, + "seed": 1, + "groupIds": [], + "frameId": null, + "roundness": null, + "boundElements": [], + "updated": 1782728052507, + "link": null, + "locked": false, + "textAlign": "left", + "verticalAlign": "top", + "containerId": null, + "originalText": "H2K_log_throttle(iv, ...)\nH2K_log_throttle_err(iv, ...)\nH2K_log_throttle_warn(iv, ...)\nH2K_log_throttle_info(iv, ...)\nH2K_log_throttle_dbg(iv, ...)\n\nH2K_log_throttle_ht(iv, ...)\nH2K_log_throttle_ht_err(iv, ...)\nH2K_log_throttle_ht_warn(iv, ...)\nH2K_log_throttle_ht_info(iv, ...)\nH2K_log_throttle_ht_dbg(iv, ...)", + "autoResize": true, + "lineHeight": 1.6783216783216781 + } + ], + "appState": { + "gridSize": 20, + "gridStep": 5, + "gridModeEnabled": false, + "viewBackgroundColor": "#ffffff" + }, + "files": {} +} \ No newline at end of file diff --git a/logging-arch.excalidraw b/logging-arch.excalidraw new file mode 100644 index 000000000..00c606350 --- /dev/null +++ b/logging-arch.excalidraw @@ -0,0 +1,350 @@ +{ + "type": "excalidraw", + "version": 2, + "source": "https://excalidraw.com", + "elements": [ + { + "type": "text", + "id": "title", + "x": 320, + "y": 20, + "width": 300, + "height": 35, + "text": "H2K Logging Architecture", + "fontSize": 24, + "fontFamily": 1, + "textAlign": "center", + "verticalAlign": "top", + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "fillStyle": "solid" + }, + { + "type": "rectangle", + "id": "ht0-box", + "x": 40, + "y": 100, + "width": 140, + "height": 60, + "strokeColor": "#1971c2", + "backgroundColor": "#d0ebff", + "fillStyle": "solid", + "roundness": { "type": 3 } + }, + { + "type": "text", + "id": "ht0-label", + "x": 60, + "y": 118, + "width": 100, + "height": 25, + "text": "HW Thread 0", + "fontSize": 16, + "fontFamily": 1, + "textAlign": "center", + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent" + }, + { + "type": "rectangle", + "id": "ht1-box", + "x": 40, + "y": 220, + "width": 140, + "height": 60, + "strokeColor": "#1971c2", + "backgroundColor": "#d0ebff", + "fillStyle": "solid", + "roundness": { "type": 3 } + }, + { + "type": "text", + "id": "ht1-label", + "x": 60, + "y": 238, + "width": 100, + "height": 25, + "text": "HW Thread 1", + "fontSize": 16, + "fontFamily": 1, + "textAlign": "center", + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent" + }, + { + "type": "rectangle", + "id": "ring0-box", + "x": 260, + "y": 90, + "width": 160, + "height": 80, + "strokeColor": "#2f9e44", + "backgroundColor": "#d3f9d8", + "fillStyle": "solid", + "roundness": { "type": 3 } + }, + { + "type": "text", + "id": "ring0-label", + "x": 270, + "y": 103, + "width": 140, + "height": 45, + "text": "logbuf[0]\n(ring buffer)", + "fontSize": 15, + "fontFamily": 1, + "textAlign": "center", + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent" + }, + { + "type": "rectangle", + "id": "ring1-box", + "x": 260, + "y": 210, + "width": 160, + "height": 80, + "strokeColor": "#2f9e44", + "backgroundColor": "#d3f9d8", + "fillStyle": "solid", + "roundness": { "type": 3 } + }, + { + "type": "text", + "id": "ring1-label", + "x": 270, + "y": 223, + "width": 140, + "height": 45, + "text": "logbuf[1]\n(ring buffer)", + "fontSize": 15, + "fontFamily": 1, + "textAlign": "center", + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent" + }, + { + "type": "text", + "id": "lockless-note", + "x": 250, + "y": 300, + "width": 180, + "height": 20, + "text": "lockless: each ht owns its ring", + "fontSize": 12, + "fontFamily": 1, + "textAlign": "center", + "strokeColor": "#868e96", + "backgroundColor": "transparent" + }, + { + "type": "rectangle", + "id": "spinlock-box", + "x": 500, + "y": 140, + "width": 140, + "height": 60, + "strokeColor": "#e67700", + "backgroundColor": "#fff3bf", + "fillStyle": "solid", + "roundness": { "type": 3 } + }, + { + "type": "text", + "id": "spinlock-label", + "x": 510, + "y": 153, + "width": 120, + "height": 35, + "text": "logbuf_lock\n(spinlock)", + "fontSize": 14, + "fontFamily": 1, + "textAlign": "center", + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent" + }, + { + "type": "rectangle", + "id": "write-box", + "x": 700, + "y": 140, + "width": 120, + "height": 60, + "strokeColor": "#862e9c", + "backgroundColor": "#f3d9fa", + "fillStyle": "solid", + "roundness": { "type": 3 } + }, + { + "type": "text", + "id": "write-label", + "x": 710, + "y": 158, + "width": 100, + "height": 25, + "text": "H2K_write()", + "fontSize": 14, + "fontFamily": 1, + "textAlign": "center", + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent" + }, + { + "type": "rectangle", + "id": "angel-box", + "x": 880, + "y": 130, + "width": 130, + "height": 80, + "strokeColor": "#c92a2a", + "backgroundColor": "#ffe3e3", + "fillStyle": "solid", + "roundness": { "type": 3 } + }, + { + "type": "text", + "id": "angel-label", + "x": 885, + "y": 148, + "width": 120, + "height": 45, + "text": "Angel\ntransactor\n(semihosting)", + "fontSize": 13, + "fontFamily": 1, + "textAlign": "center", + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent" + }, + { + "type": "rectangle", + "id": "stdout-box", + "x": 1070, + "y": 140, + "width": 120, + "height": 60, + "strokeColor": "#1e1e1e", + "backgroundColor": "#f1f3f5", + "fillStyle": "solid", + "roundness": { "type": 3 } + }, + { + "type": "text", + "id": "stdout-label", + "x": 1080, + "y": 158, + "width": 100, + "height": 25, + "text": "Host stdout", + "fontSize": 14, + "fontFamily": 1, + "textAlign": "center", + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent" + }, + { + "type": "arrow", + "id": "ht0-to-ring0", + "x": 180, + "y": 130, + "width": 80, + "height": 0, + "points": [[0,0],[80,0]], + "strokeColor": "#1971c2", + "label": { "text": "emit_prefix\n+emit_string" } + }, + { + "type": "arrow", + "id": "ht1-to-ring1", + "x": 180, + "y": 250, + "width": 80, + "height": 0, + "points": [[0,0],[80,0]], + "strokeColor": "#1971c2", + "label": { "text": "emit_prefix\n+emit_string" } + }, + { + "type": "arrow", + "id": "ring0-to-lock", + "x": 420, + "y": 130, + "width": 80, + "height": 40, + "points": [[0,0],[80,40]], + "strokeColor": "#2f9e44" + }, + { + "type": "arrow", + "id": "ring1-to-lock", + "x": 420, + "y": 250, + "width": 80, + "height": -80, + "points": [[0,0],[80,-80]], + "strokeColor": "#2f9e44" + }, + { + "type": "arrow", + "id": "lock-to-write", + "x": 640, + "y": 170, + "width": 60, + "height": 0, + "points": [[0,0],[60,0]], + "strokeColor": "#e67700" + }, + { + "type": "arrow", + "id": "write-to-angel", + "x": 820, + "y": 170, + "width": 60, + "height": 0, + "points": [[0,0],[60,0]], + "strokeColor": "#862e9c", + "label": { "text": "phys addr\n+cache flush" } + }, + { + "type": "arrow", + "id": "angel-to-stdout", + "x": 1010, + "y": 170, + "width": 60, + "height": 0, + "points": [[0,0],[60,0]], + "strokeColor": "#c92a2a" + }, + { + "type": "text", + "id": "log-enable-note", + "x": 480, + "y": 220, + "width": 200, + "height": 40, + "text": "only if log_enable=1\n(optional live streaming)", + "fontSize": 12, + "fontFamily": 1, + "textAlign": "center", + "strokeColor": "#868e96", + "backgroundColor": "transparent" + }, + { + "type": "text", + "id": "logbuf-enable-note", + "x": 240, + "y": 60, + "width": 200, + "height": 20, + "text": "only if logbuf_enable=1", + "fontSize": 12, + "fontFamily": 1, + "textAlign": "center", + "strokeColor": "#868e96", + "backgroundColor": "transparent" + } + ], + "appState": { + "viewBackgroundColor": "#ffffff", + "gridSize": 20 + } +} diff --git a/scripts/Makefile.inc.test b/scripts/Makefile.inc.test index 43545e40d..ce231e2ba 100644 --- a/scripts/Makefile.inc.test +++ b/scripts/Makefile.inc.test @@ -185,6 +185,10 @@ LDFLAGS += ${LLVM_COV_LDFLAGS} endif ifdef LOGBUF CFLAGS += -DH2K_LOG_PRINTF +_logbuf_one_level := $(subst ],,$(word 2,$(subst [, ,$(LOGBUF)))) +ifneq ($(_logbuf_one_level),) +CFLAGS += -DH2K_LOG_LEVEL=$(_logbuf_one_level) +endif endif else # non-STANDALONE From 5f0098bac195adfc64b594a40408a18113722747 Mon Sep 17 00:00:00 2001 From: Zeev Belinsky Date: Tue, 7 Jul 2026 15:49:38 -0700 Subject: [PATCH 3/4] log: symbolic levels, H2K_LOG_NO_SPAM mode, and bitmask once_ht Three improvements to the logging system: 1. Accept symbolic level names in LOGBUF syntax (err, warn, info, dbg) in addition to numeric values (0, 1, 2, 3): make LOGBUF=1[warn] whole kernel, WARN and above make LOGBUF=sched[info] sched directory, INFO and above make LOGBUF=futex[err],sched[dbg] mixed symbolic and numeric 2. Add H2K_LOG_NO_SPAM mode to strip spam-control macros (once/throttle) and make them no-ops. Eliminates static state bloat: make LOGBUF=1[warn] H2K_LOG_NO_SPAM=1 In this mode, H2K_log_once/throttle macros become empty (no-op), while base H2K_log/err/warn/info/dbg macros still emit normally. 3. Optimize H2K_log_once_ht to use a single u32 bitmask instead of an array. Each hardware thread's once-flag is now a single bit in a shared u32, reducing per-callsite memory from MAX_HTHREADS*4 bytes to 4 bytes. Uses H2K_atomic_setbit for race-free per-bit access. Works in both H2K_LOGBUF and H2K_LOG_PRINTF modes. Implemented via Makefile function for level mapping, conditional macro redefinition in log.h, and bitmask logic in log.ref.c. Works in both kernel (LOGBUF) and standalone test (LOG_PRINTF) builds. Signed-off-by: Zeev Belinsky --- kernel/util/log/log.spec | 86 ++++ log_diagram.excalidraw | 825 --------------------------------------- logging-api.excalidraw | 809 -------------------------------------- logging-arch.excalidraw | 350 ----------------- wip_notes.md | 50 --- 5 files changed, 86 insertions(+), 2034 deletions(-) create mode 100644 kernel/util/log/log.spec delete mode 100644 log_diagram.excalidraw delete mode 100644 logging-api.excalidraw delete mode 100644 logging-arch.excalidraw delete mode 100644 wip_notes.md diff --git a/kernel/util/log/log.spec b/kernel/util/log/log.spec new file mode 100644 index 000000000..8cc640e50 --- /dev/null +++ b/kernel/util/log/log.spec @@ -0,0 +1,86 @@ +/* + * Copyright (c) Qualcomm Technologies, Inc. and/or its subsidiaries. + * SPDX-License-Identifier: BSD-3-Clause-Clear + */ + +# H2K Logging Specification + +## Build Configuration + +### LOGBUF Syntax + +``` +make LOGBUF=[] +``` + +- ``: `1` (all), `` (dir), `` (filename), or comma-separated list +- ``: `0`/`err`, `1`/`warn`, `2`/`info`, `3`/`dbg` (default: `3`) + +Examples: +``` +make LOGBUF=1[warn] # whole kernel, WARN+ +make LOGBUF=sched[info] # sched module, INFO+ +make LOGBUF=sched[warn],futex[err] # mixed levels +``` + +### H2K_LOG_NO_SPAM + +Disables spam-control macros (once/throttle) to eliminate static state: +``` +make LOGBUF=1[warn] H2K_LOG_NO_SPAM=1 +``` + +When enabled, `H2K_log_once*()` and `H2K_log_throttle*()` become no-ops. + +## API + +### Base Logging +```c +H2K_log(fmt, ...) // DEBUG +H2K_log_err(fmt, ...) // ERROR +H2K_log_warn(fmt, ...) // WARN +H2K_log_info(fmt, ...) // INFO +H2K_log_dbg(fmt, ...) // DEBUG +``` + +### Spam Control +```c +H2K_log_once*(fmt, ...) // emit once per callsite (4 bytes) +H2K_log_once_ht*(fmt, ...) // emit once per HT (4 bytes, bitmask) +H2K_log_throttle*(interval, ...) // rate-limited (8 bytes) +H2K_log_throttle_ht*(interval, ...) // per-HT rate-limited (8×MAX_HTHREADS bytes) +``` + +All combinations of severity (`_err`, `_warn`, `_info`, `_dbg`) available. + +### String Variants +```c +H2K_log_string*(S) // pre-formatted string +H2K_log_string_once*(S) // with spam control +H2K_log_string_throttle*(interval, S) +``` + +## Output Format + +``` +[ht][][][:] message +``` + +Example: `[ht0][WARN][12345678][sched.c:42] reschedule timeout` + +## Memory + +| Macro | Storage | +|-------|---------| +| `H2K_log_once()` | 4 bytes (u32 flag) | +| `H2K_log_once_ht()` | 4 bytes (u32 bitmask, 1 bit per HT) | +| `H2K_log_throttle()` | 8 bytes (u64 timestamp) | +| `H2K_log_throttle_ht()` | 8 × MAX_HTHREADS bytes | + +With `H2K_LOG_NO_SPAM=1`: no static state for spam-control macros. + +## Implementation + +- **H2K_LOGBUF**: lockless per-HT ring buffers, atomic setbit for once, spinlock for throttle +- **H2K_LOG_PRINTF**: printf-based, static inline prefix helpers, same spam-control logic +- **Silent**: all macros are no-ops (default when neither flag set) diff --git a/log_diagram.excalidraw b/log_diagram.excalidraw deleted file mode 100644 index e63909791..000000000 --- a/log_diagram.excalidraw +++ /dev/null @@ -1,825 +0,0 @@ -{ - "type": "excalidraw", - "version": 2, - "source": "https://marketplace.visualstudio.com/items?itemName=pomdtr.excalidraw-editor", - "elements": [ - { - "id": "t_title", - "type": "text", - "x": 260, - "y": 16, - "width": 480, - "height": 30, - "text": "H2K Log System", - "fontSize": 22, - "fontFamily": 1, - "textAlign": "center", - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 1127152591, - "index": "a0", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false, - "verticalAlign": "top", - "containerId": null, - "originalText": "H2K Log System", - "autoResize": true, - "lineHeight": 1.3636363636363635 - }, - { - "id": "box_build", - "type": "rectangle", - "x": 10, - "y": 60, - "width": 220, - "height": 200, - "strokeColor": "#364fc7", - "backgroundColor": "#e7f5ff", - "fillStyle": "solid", - "roundness": { - "type": 3 - }, - "version": 2, - "versionNonce": 137014433, - "index": "a1", - "isDeleted": false, - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false - }, - { - "id": "lbl_build", - "type": "text", - "x": 20, - "y": 68, - "width": 200, - "height": 20, - "text": "compile-time flags", - "fontSize": 13, - "fontFamily": 1, - "fontStyle": 1, - "strokeColor": "#364fc7", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 1721543151, - "index": "a2", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "compile-time flags", - "autoResize": true, - "lineHeight": 1.5384615384615385 - }, - { - "id": "txt_build", - "type": "text", - "x": 20.24713429252742, - "y": 94, - "width": 210.9375, - "height": 147.69230769230774, - "text": "(nothing)\n all macros → zero\n\n-DH2K_LOG_LEVEL=N\n ERR=0 WARN=1\n INFO=2 DBG=3 (default)\n\nmake LOGBUF=1: \nfull log system on\nmake LOGBUF=sched\nmake LOGBUF=sched,data/globals\n per-subsystem logging", - "fontSize": 12, - "fontFamily": 3, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 51, - "versionNonce": 918293055, - "index": "a3", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782395690551, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "(nothing)\n all macros → zero\n\n-DH2K_LOG_LEVEL=N\n ERR=0 WARN=1\n INFO=2 DBG=3 (default)\n\nmake LOGBUF=1: \nfull log system on\nmake LOGBUF=sched\nmake LOGBUF=sched,data/globals\n per-subsystem logging", - "autoResize": true, - "lineHeight": 1.0256410256410258 - }, - { - "id": "arr_build", - "type": "arrow", - "x": 230, - "y": 155, - "width": 60, - "height": 0, - "points": [ - [ - 0, - 0 - ], - [ - 60, - 0 - ] - ], - "strokeColor": "#1e1e1e", - "endArrowhead": "arrow", - "lastCommittedPoint": null, - "version": 2, - "versionNonce": 1215271951, - "index": "a4", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "backgroundColor": "transparent", - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false, - "startBinding": null, - "endBinding": null, - "startArrowhead": null - }, - { - "id": "box_api", - "type": "rectangle", - "x": 290, - "y": 60, - "width": 220, - "height": 200, - "strokeColor": "#1971c2", - "backgroundColor": "#d0ebff", - "fillStyle": "solid", - "roundness": { - "type": 3 - }, - "version": 2, - "versionNonce": 1729017953, - "index": "a5", - "isDeleted": false, - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false - }, - { - "id": "lbl_api", - "type": "text", - "x": 300, - "y": 68, - "width": 200, - "height": 20, - "text": "log macros", - "fontSize": 13, - "fontFamily": 1, - "fontStyle": 1, - "strokeColor": "#1971c2", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 1621113391, - "index": "a6", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "log macros", - "autoResize": true, - "lineHeight": 1.5384615384615385 - }, - { - "id": "txt_api", - "type": "text", - "x": 300, - "y": 94, - "width": 232.03125, - "height": 160, - "text": "H2K_log_err(fmt, ...)\nH2K_log_warn(fmt, ...)\nH2K_log_info(fmt, ...)\nH2K_log_dbg(fmt, ...)\nH2K_log(fmt, ...) ← dbg\n\nH2K_log_once(fmt, ...)\nH2K_log_once_ht(fmt, ...)\n\nH2K_log_throttle(iv, fmt, ...)\nH2K_log_throttle_ht(iv, fmt, ...)", - "fontSize": 12, - "fontFamily": 3, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 3, - "versionNonce": 1398558433, - "index": "a7", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392953296, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "H2K_log_err(fmt, ...)\nH2K_log_warn(fmt, ...)\nH2K_log_info(fmt, ...)\nH2K_log_dbg(fmt, ...)\nH2K_log(fmt, ...) ← dbg\n\nH2K_log_once(fmt, ...)\nH2K_log_once_ht(fmt, ...)\n\nH2K_log_throttle(iv, fmt, ...)\nH2K_log_throttle_ht(iv, fmt, ...)", - "autoResize": true, - "lineHeight": 1.2121212121212122 - }, - { - "id": "arr_api", - "type": "arrow", - "x": 510, - "y": 155, - "width": 60, - "height": 0, - "points": [ - [ - 0, - 0 - ], - [ - 60, - 0 - ] - ], - "strokeColor": "#1e1e1e", - "endArrowhead": "arrow", - "lastCommittedPoint": null, - "version": 2, - "versionNonce": 337058895, - "index": "a8", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "backgroundColor": "transparent", - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false, - "startBinding": null, - "endBinding": null, - "startArrowhead": null - }, - { - "id": "box_filter", - "type": "rectangle", - "x": 570, - "y": 60, - "width": 200, - "height": 200, - "strokeColor": "#862e9c", - "backgroundColor": "#f3d9fa", - "fillStyle": "solid", - "roundness": { - "type": 3 - }, - "version": 2, - "versionNonce": 833803297, - "index": "a9", - "isDeleted": false, - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false - }, - { - "id": "lbl_filter", - "type": "text", - "x": 580, - "y": 68, - "width": 180, - "height": 20, - "text": "level filter", - "fontSize": 13, - "fontFamily": 1, - "fontStyle": 1, - "strokeColor": "#862e9c", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 380418671, - "index": "aA", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "level filter", - "autoResize": true, - "lineHeight": 1.5384615384615385 - }, - { - "id": "txt_filter", - "type": "text", - "x": 580, - "y": 94, - "width": 147.65625, - "height": 80, - "text": "level ≤ log_level?\n\nlog_level set at boot\nfrom H2K_LOG_LEVEL\n(compile-time)", - "fontSize": 12, - "fontFamily": 3, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 11, - "versionNonce": 1807756351, - "index": "aB", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782396756274, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "level ≤ log_level?\n\nlog_level set at boot\nfrom H2K_LOG_LEVEL\n(compile-time)", - "autoResize": true, - "lineHeight": 1.3333333333333333 - }, - { - "id": "txt_drop", - "type": "text", - "x": 580, - "y": 185, - "width": 180, - "height": 20, - "text": "no → dropped silently", - "fontSize": 12, - "fontFamily": 3, - "strokeColor": "#c92a2a", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 220828815, - "index": "aC", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "no → dropped silently", - "autoResize": true, - "lineHeight": 1.6666666666666667 - }, - { - "id": "txt_pass", - "type": "text", - "x": 580, - "y": 210, - "width": 180, - "height": 20, - "text": "yes → emit path ↓", - "fontSize": 12, - "fontFamily": 3, - "strokeColor": "#2f9e44", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 1666383841, - "index": "aD", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "yes → emit path ↓", - "autoResize": true, - "lineHeight": 1.6666666666666667 - }, - { - "id": "arr_emit", - "type": "arrow", - "x": 670, - "y": 260, - "width": 0, - "height": 50, - "points": [ - [ - 0, - 0 - ], - [ - 0, - 50 - ] - ], - "strokeColor": "#2f9e44", - "endArrowhead": "arrow", - "lastCommittedPoint": null, - "version": 2, - "versionNonce": 1866869423, - "index": "aE", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "backgroundColor": "transparent", - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false, - "startBinding": null, - "endBinding": null, - "startArrowhead": null - }, - { - "id": "box_emit", - "type": "rectangle", - "x": 570, - "y": 310, - "width": 200, - "height": 90, - "strokeColor": "#2f9e44", - "backgroundColor": "#ebfbee", - "fillStyle": "solid", - "roundness": { - "type": 3 - }, - "version": 2, - "versionNonce": 797596609, - "index": "aF", - "isDeleted": false, - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false - }, - { - "id": "lbl_emit", - "type": "text", - "x": 580, - "y": 318, - "width": 180, - "height": 20, - "text": "emit", - "fontSize": 13, - "fontFamily": 1, - "fontStyle": 1, - "strokeColor": "#2f9e44", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 699071695, - "index": "aG", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "emit", - "autoResize": true, - "lineHeight": 1.5384615384615385 - }, - { - "id": "txt_emit", - "type": "text", - "x": 587.5208275645167, - "y": 336.58144201612873, - "width": 154.6875, - "height": 55, - "text": "ring buf per ht (4KB, \nlockless)", - "fontSize": 12, - "fontFamily": 3, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 81, - "versionNonce": 32509663, - "index": "aH", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782396809609, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "ring buf per ht (4KB, \nlockless)", - "autoResize": true, - "lineHeight": 2.2916666666666665 - }, - { - "id": "box_spam", - "type": "rectangle", - "x": 290, - "y": 280, - "width": 220, - "height": 130, - "strokeColor": "#e67700", - "backgroundColor": "#fff9db", - "fillStyle": "solid", - "roundness": { - "type": 3 - }, - "version": 2, - "versionNonce": 2146470639, - "index": "aI", - "isDeleted": false, - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false - }, - { - "id": "lbl_spam", - "type": "text", - "x": 300, - "y": 288, - "width": 200, - "height": 20, - "text": "spam control (callsite static)", - "fontSize": 13, - "fontFamily": 1, - "fontStyle": 1, - "strokeColor": "#e67700", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 493166465, - "index": "aJ", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "spam control (callsite static)", - "autoResize": true, - "lineHeight": 1.5384615384615385 - }, - { - "id": "txt_spam", - "type": "text", - "x": 300, - "y": 312, - "width": 200, - "height": 90, - "text": "once: static u32_t __f = 0\n atomic set → fires once\n\nonce_ht: static u32_t __f[HT]\n per-hthread, lockless\n\nthrottle: static u64_t __t = 0\n pcycle delta ≥ interval", - "fontSize": 12, - "fontFamily": 3, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 782193935, - "index": "aK", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "once: static u32_t __f = 0\n atomic set → fires once\n\nonce_ht: static u32_t __f[HT]\n per-hthread, lockless\n\nthrottle: static u64_t __t = 0\n pcycle delta ≥ interval", - "autoResize": true, - "lineHeight": 0.9375 - }, - { - "id": "arr_spam", - "type": "arrow", - "x": 510, - "y": 345, - "width": 60, - "height": 0, - "points": [ - [ - 0, - 0 - ], - [ - 60, - 0 - ] - ], - "strokeColor": "#e67700", - "endArrowhead": "arrow", - "label": { - "text": "gate passes" - }, - "lastCommittedPoint": null, - "version": 2, - "versionNonce": 225937249, - "index": "aL", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "backgroundColor": "transparent", - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782392810695, - "link": null, - "locked": false, - "startBinding": null, - "endBinding": null, - "startArrowhead": null - } - ], - "appState": { - "gridSize": 20, - "gridStep": 5, - "gridModeEnabled": false, - "viewBackgroundColor": "#ffffff" - }, - "files": {} -} \ No newline at end of file diff --git a/logging-api.excalidraw b/logging-api.excalidraw deleted file mode 100644 index 7fc017467..000000000 --- a/logging-api.excalidraw +++ /dev/null @@ -1,809 +0,0 @@ -{ - "type": "excalidraw", - "version": 2, - "source": "https://marketplace.visualstudio.com/items?itemName=pomdtr.excalidraw-editor", - "elements": [ - { - "type": "text", - "id": "title", - "x": 300, - "y": 10, - "width": 500, - "height": 35, - "text": "H2K Logging — Makefile & Code API", - "fontSize": 24, - "fontFamily": 1, - "textAlign": "center", - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 147791773, - "index": "a0", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "verticalAlign": "top", - "containerId": null, - "originalText": "H2K Logging — Makefile & Code API", - "autoResize": true, - "lineHeight": 1.4583333333333333 - }, - { - "type": "text", - "id": "makefile-title", - "x": 40, - "y": 60, - "width": 300, - "height": 25, - "text": "① Makefile — what gets compiled", - "fontSize": 16, - "fontFamily": 1, - "strokeColor": "#1971c2", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 115995827, - "index": "a1", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "① Makefile — what gets compiled", - "autoResize": true, - "lineHeight": 1.5625 - }, - { - "type": "rectangle", - "id": "mk-whole", - "x": 40, - "y": 90, - "width": 320, - "height": 50, - "strokeColor": "#1971c2", - "backgroundColor": "#d0ebff", - "fillStyle": "solid", - "roundness": { - "type": 3 - }, - "version": 2, - "versionNonce": 744694781, - "index": "a2", - "isDeleted": false, - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false - }, - { - "type": "text", - "id": "mk-whole-label", - "x": 50, - "y": 100, - "width": 196.5107421875, - "height": 29.999999999999996, - "text": "make LOGBUF=1\n→ whole kernel: -DH2K_LOGBUF", - "fontSize": 13, - "fontFamily": 2, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 3, - "versionNonce": 1812833149, - "index": "a3", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728084480, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "make LOGBUF=1\n→ whole kernel: -DH2K_LOGBUF", - "autoResize": true, - "lineHeight": 1.1538461538461537 - }, - { - "type": "rectangle", - "id": "mk-dir", - "x": 40, - "y": 155, - "width": 320, - "height": 50, - "strokeColor": "#1971c2", - "backgroundColor": "#d0ebff", - "fillStyle": "solid", - "roundness": { - "type": 3 - }, - "version": 2, - "versionNonce": 1538759773, - "index": "a4", - "isDeleted": false, - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false - }, - { - "type": "text", - "id": "mk-dir-label", - "x": 50, - "y": 165, - "width": 300, - "height": 30, - "text": "make LOGBUF=sched\n→ all files under /sched/", - "fontSize": 13, - "fontFamily": 2, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 308585459, - "index": "a5", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "make LOGBUF=sched\n→ all files under /sched/", - "autoResize": true, - "lineHeight": 1.1538461538461537 - }, - { - "type": "rectangle", - "id": "mk-file", - "x": 40, - "y": 220, - "width": 320, - "height": 50, - "strokeColor": "#1971c2", - "backgroundColor": "#d0ebff", - "fillStyle": "solid", - "roundness": { - "type": 3 - }, - "version": 2, - "versionNonce": 782108861, - "index": "a6", - "isDeleted": false, - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false - }, - { - "type": "text", - "id": "mk-file-label", - "x": 50, - "y": 230, - "width": 300, - "height": 30, - "text": "make LOGBUF=dosched.ref.c\n→ single file only", - "fontSize": 13, - "fontFamily": 2, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 414297491, - "index": "a7", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "make LOGBUF=dosched.ref.c\n→ single file only", - "autoResize": true, - "lineHeight": 1.1538461538461537 - }, - { - "type": "rectangle", - "id": "mk-level", - "x": 40, - "y": 285, - "width": 320, - "height": 65, - "strokeColor": "#1971c2", - "backgroundColor": "#d0ebff", - "fillStyle": "solid", - "roundness": { - "type": 3 - }, - "version": 2, - "versionNonce": 1186457885, - "index": "a8", - "isDeleted": false, - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false - }, - { - "type": "text", - "id": "mk-level-label", - "x": 50, - "y": 293, - "width": 300, - "height": 50, - "text": "make LOGBUF=sched[2],futex[3]\n→ sched: ERR+WARN+INFO\n→ futex: ERR+WARN+INFO+DBG", - "fontSize": 13, - "fontFamily": 2, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 267158323, - "index": "a9", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "make LOGBUF=sched[2],futex[3]\n→ sched: ERR+WARN+INFO\n→ futex: ERR+WARN+INFO+DBG", - "autoResize": true, - "lineHeight": 1.2820512820512822 - }, - { - "type": "text", - "id": "code-title", - "x": 430, - "y": 60, - "width": 700, - "height": 25, - "text": "② Code — macro API (same interface across all 3 build modes)", - "fontSize": 16, - "fontFamily": 1, - "strokeColor": "#2f9e44", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 1646003677, - "index": "aC", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "② Code — macro API (same interface across all 3 build modes)", - "autoResize": true, - "lineHeight": 1.5625 - }, - { - "type": "rectangle", - "id": "basic-box", - "x": 430, - "y": 90, - "width": 220, - "height": 130, - "strokeColor": "#2f9e44", - "backgroundColor": "#d3f9d8", - "fillStyle": "solid", - "roundness": { - "type": 3 - }, - "version": 2, - "versionNonce": 1643483763, - "index": "aD", - "isDeleted": false, - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false - }, - { - "type": "text", - "id": "basic-title", - "x": 440, - "y": 97, - "width": 200, - "height": 20, - "text": "Basic (severity)", - "fontSize": 14, - "fontFamily": 1, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 263799357, - "index": "aE", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "Basic (severity)", - "autoResize": true, - "lineHeight": 1.4285714285714286 - }, - { - "type": "text", - "id": "basic-label", - "x": 440, - "y": 118, - "width": 200, - "height": 95, - "text": "H2K_log(fmt, ...)\nH2K_log_err(fmt, ...)\nH2K_log_warn(fmt, ...)\nH2K_log_info(fmt, ...)\nH2K_log_dbg(fmt, ...)", - "fontSize": 13, - "fontFamily": 2, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 1428212755, - "index": "aF", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "H2K_log(fmt, ...)\nH2K_log_err(fmt, ...)\nH2K_log_warn(fmt, ...)\nH2K_log_info(fmt, ...)\nH2K_log_dbg(fmt, ...)", - "autoResize": true, - "lineHeight": 1.4615384615384615 - }, - { - "type": "rectangle", - "id": "string-box", - "x": 430, - "y": 235, - "width": 220, - "height": 130, - "strokeColor": "#2f9e44", - "backgroundColor": "#d3f9d8", - "fillStyle": "solid", - "roundness": { - "type": 3 - }, - "version": 2, - "versionNonce": 590344861, - "index": "aG", - "isDeleted": false, - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false - }, - { - "type": "text", - "id": "string-title", - "x": 440, - "y": 242, - "width": 200, - "height": 20, - "text": "String (no format parsing)", - "fontSize": 14, - "fontFamily": 1, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 1576260019, - "index": "aH", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "String (no format parsing)", - "autoResize": true, - "lineHeight": 1.4285714285714286 - }, - { - "type": "text", - "id": "string-label", - "x": 440, - "y": 263, - "width": 200, - "height": 95, - "text": "H2K_log_string(S)\nH2K_log_string_err(S)\nH2K_log_string_warn(S)\nH2K_log_string_info(S)\nH2K_log_string_dbg(S)", - "fontSize": 13, - "fontFamily": 2, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 154244861, - "index": "aI", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "H2K_log_string(S)\nH2K_log_string_err(S)\nH2K_log_string_warn(S)\nH2K_log_string_info(S)\nH2K_log_string_dbg(S)", - "autoResize": true, - "lineHeight": 1.4615384615384615 - }, - { - "type": "rectangle", - "id": "once-box", - "x": 670, - "y": 90, - "width": 230, - "height": 275, - "strokeColor": "#862e9c", - "backgroundColor": "#f3d9fa", - "fillStyle": "solid", - "roundness": { - "type": 3 - }, - "version": 2, - "versionNonce": 227877715, - "index": "aJ", - "isDeleted": false, - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false - }, - { - "type": "text", - "id": "once-title", - "x": 680, - "y": 97, - "width": 210, - "height": 20, - "text": "Once (global / per-ht)", - "fontSize": 14, - "fontFamily": 1, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 473935709, - "index": "aK", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "Once (global / per-ht)", - "autoResize": true, - "lineHeight": 1.4285714285714286 - }, - { - "type": "text", - "id": "once-label", - "x": 680, - "y": 118, - "width": 210, - "height": 240, - "text": "H2K_log_once(...)\nH2K_log_once_err(...)\nH2K_log_once_warn(...)\nH2K_log_once_info(...)\nH2K_log_once_dbg(...)\n\nH2K_log_once_ht(...)\nH2K_log_once_ht_err(...)\nH2K_log_once_ht_warn(...)\nH2K_log_once_ht_info(...)\nH2K_log_once_ht_dbg(...)", - "fontSize": 13, - "fontFamily": 2, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 207306995, - "index": "aL", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "H2K_log_once(...)\nH2K_log_once_err(...)\nH2K_log_once_warn(...)\nH2K_log_once_info(...)\nH2K_log_once_dbg(...)\n\nH2K_log_once_ht(...)\nH2K_log_once_ht_err(...)\nH2K_log_once_ht_warn(...)\nH2K_log_once_ht_info(...)\nH2K_log_once_ht_dbg(...)", - "autoResize": true, - "lineHeight": 1.6783216783216781 - }, - { - "type": "rectangle", - "id": "throttle-box", - "x": 920, - "y": 90, - "width": 260, - "height": 275, - "strokeColor": "#c92a2a", - "backgroundColor": "#ffe3e3", - "fillStyle": "solid", - "roundness": { - "type": 3 - }, - "version": 2, - "versionNonce": 1789639613, - "index": "aM", - "isDeleted": false, - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false - }, - { - "type": "text", - "id": "throttle-title", - "x": 930, - "y": 97, - "width": 240, - "height": 20, - "text": "Throttle (global / per-ht)", - "fontSize": 14, - "fontFamily": 1, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 869051027, - "index": "aN", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "Throttle (global / per-ht)", - "autoResize": true, - "lineHeight": 1.4285714285714286 - }, - { - "type": "text", - "id": "throttle-label", - "x": 930, - "y": 118, - "width": 240, - "height": 240, - "text": "H2K_log_throttle(iv, ...)\nH2K_log_throttle_err(iv, ...)\nH2K_log_throttle_warn(iv, ...)\nH2K_log_throttle_info(iv, ...)\nH2K_log_throttle_dbg(iv, ...)\n\nH2K_log_throttle_ht(iv, ...)\nH2K_log_throttle_ht_err(iv, ...)\nH2K_log_throttle_ht_warn(iv, ...)\nH2K_log_throttle_ht_info(iv, ...)\nH2K_log_throttle_ht_dbg(iv, ...)", - "fontSize": 13, - "fontFamily": 2, - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "version": 2, - "versionNonce": 1016544285, - "index": "aO", - "isDeleted": false, - "fillStyle": "solid", - "strokeWidth": 2, - "strokeStyle": "solid", - "roughness": 1, - "opacity": 100, - "angle": 0, - "seed": 1, - "groupIds": [], - "frameId": null, - "roundness": null, - "boundElements": [], - "updated": 1782728052507, - "link": null, - "locked": false, - "textAlign": "left", - "verticalAlign": "top", - "containerId": null, - "originalText": "H2K_log_throttle(iv, ...)\nH2K_log_throttle_err(iv, ...)\nH2K_log_throttle_warn(iv, ...)\nH2K_log_throttle_info(iv, ...)\nH2K_log_throttle_dbg(iv, ...)\n\nH2K_log_throttle_ht(iv, ...)\nH2K_log_throttle_ht_err(iv, ...)\nH2K_log_throttle_ht_warn(iv, ...)\nH2K_log_throttle_ht_info(iv, ...)\nH2K_log_throttle_ht_dbg(iv, ...)", - "autoResize": true, - "lineHeight": 1.6783216783216781 - } - ], - "appState": { - "gridSize": 20, - "gridStep": 5, - "gridModeEnabled": false, - "viewBackgroundColor": "#ffffff" - }, - "files": {} -} \ No newline at end of file diff --git a/logging-arch.excalidraw b/logging-arch.excalidraw deleted file mode 100644 index 00c606350..000000000 --- a/logging-arch.excalidraw +++ /dev/null @@ -1,350 +0,0 @@ -{ - "type": "excalidraw", - "version": 2, - "source": "https://excalidraw.com", - "elements": [ - { - "type": "text", - "id": "title", - "x": 320, - "y": 20, - "width": 300, - "height": 35, - "text": "H2K Logging Architecture", - "fontSize": 24, - "fontFamily": 1, - "textAlign": "center", - "verticalAlign": "top", - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent", - "fillStyle": "solid" - }, - { - "type": "rectangle", - "id": "ht0-box", - "x": 40, - "y": 100, - "width": 140, - "height": 60, - "strokeColor": "#1971c2", - "backgroundColor": "#d0ebff", - "fillStyle": "solid", - "roundness": { "type": 3 } - }, - { - "type": "text", - "id": "ht0-label", - "x": 60, - "y": 118, - "width": 100, - "height": 25, - "text": "HW Thread 0", - "fontSize": 16, - "fontFamily": 1, - "textAlign": "center", - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent" - }, - { - "type": "rectangle", - "id": "ht1-box", - "x": 40, - "y": 220, - "width": 140, - "height": 60, - "strokeColor": "#1971c2", - "backgroundColor": "#d0ebff", - "fillStyle": "solid", - "roundness": { "type": 3 } - }, - { - "type": "text", - "id": "ht1-label", - "x": 60, - "y": 238, - "width": 100, - "height": 25, - "text": "HW Thread 1", - "fontSize": 16, - "fontFamily": 1, - "textAlign": "center", - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent" - }, - { - "type": "rectangle", - "id": "ring0-box", - "x": 260, - "y": 90, - "width": 160, - "height": 80, - "strokeColor": "#2f9e44", - "backgroundColor": "#d3f9d8", - "fillStyle": "solid", - "roundness": { "type": 3 } - }, - { - "type": "text", - "id": "ring0-label", - "x": 270, - "y": 103, - "width": 140, - "height": 45, - "text": "logbuf[0]\n(ring buffer)", - "fontSize": 15, - "fontFamily": 1, - "textAlign": "center", - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent" - }, - { - "type": "rectangle", - "id": "ring1-box", - "x": 260, - "y": 210, - "width": 160, - "height": 80, - "strokeColor": "#2f9e44", - "backgroundColor": "#d3f9d8", - "fillStyle": "solid", - "roundness": { "type": 3 } - }, - { - "type": "text", - "id": "ring1-label", - "x": 270, - "y": 223, - "width": 140, - "height": 45, - "text": "logbuf[1]\n(ring buffer)", - "fontSize": 15, - "fontFamily": 1, - "textAlign": "center", - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent" - }, - { - "type": "text", - "id": "lockless-note", - "x": 250, - "y": 300, - "width": 180, - "height": 20, - "text": "lockless: each ht owns its ring", - "fontSize": 12, - "fontFamily": 1, - "textAlign": "center", - "strokeColor": "#868e96", - "backgroundColor": "transparent" - }, - { - "type": "rectangle", - "id": "spinlock-box", - "x": 500, - "y": 140, - "width": 140, - "height": 60, - "strokeColor": "#e67700", - "backgroundColor": "#fff3bf", - "fillStyle": "solid", - "roundness": { "type": 3 } - }, - { - "type": "text", - "id": "spinlock-label", - "x": 510, - "y": 153, - "width": 120, - "height": 35, - "text": "logbuf_lock\n(spinlock)", - "fontSize": 14, - "fontFamily": 1, - "textAlign": "center", - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent" - }, - { - "type": "rectangle", - "id": "write-box", - "x": 700, - "y": 140, - "width": 120, - "height": 60, - "strokeColor": "#862e9c", - "backgroundColor": "#f3d9fa", - "fillStyle": "solid", - "roundness": { "type": 3 } - }, - { - "type": "text", - "id": "write-label", - "x": 710, - "y": 158, - "width": 100, - "height": 25, - "text": "H2K_write()", - "fontSize": 14, - "fontFamily": 1, - "textAlign": "center", - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent" - }, - { - "type": "rectangle", - "id": "angel-box", - "x": 880, - "y": 130, - "width": 130, - "height": 80, - "strokeColor": "#c92a2a", - "backgroundColor": "#ffe3e3", - "fillStyle": "solid", - "roundness": { "type": 3 } - }, - { - "type": "text", - "id": "angel-label", - "x": 885, - "y": 148, - "width": 120, - "height": 45, - "text": "Angel\ntransactor\n(semihosting)", - "fontSize": 13, - "fontFamily": 1, - "textAlign": "center", - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent" - }, - { - "type": "rectangle", - "id": "stdout-box", - "x": 1070, - "y": 140, - "width": 120, - "height": 60, - "strokeColor": "#1e1e1e", - "backgroundColor": "#f1f3f5", - "fillStyle": "solid", - "roundness": { "type": 3 } - }, - { - "type": "text", - "id": "stdout-label", - "x": 1080, - "y": 158, - "width": 100, - "height": 25, - "text": "Host stdout", - "fontSize": 14, - "fontFamily": 1, - "textAlign": "center", - "strokeColor": "#1e1e1e", - "backgroundColor": "transparent" - }, - { - "type": "arrow", - "id": "ht0-to-ring0", - "x": 180, - "y": 130, - "width": 80, - "height": 0, - "points": [[0,0],[80,0]], - "strokeColor": "#1971c2", - "label": { "text": "emit_prefix\n+emit_string" } - }, - { - "type": "arrow", - "id": "ht1-to-ring1", - "x": 180, - "y": 250, - "width": 80, - "height": 0, - "points": [[0,0],[80,0]], - "strokeColor": "#1971c2", - "label": { "text": "emit_prefix\n+emit_string" } - }, - { - "type": "arrow", - "id": "ring0-to-lock", - "x": 420, - "y": 130, - "width": 80, - "height": 40, - "points": [[0,0],[80,40]], - "strokeColor": "#2f9e44" - }, - { - "type": "arrow", - "id": "ring1-to-lock", - "x": 420, - "y": 250, - "width": 80, - "height": -80, - "points": [[0,0],[80,-80]], - "strokeColor": "#2f9e44" - }, - { - "type": "arrow", - "id": "lock-to-write", - "x": 640, - "y": 170, - "width": 60, - "height": 0, - "points": [[0,0],[60,0]], - "strokeColor": "#e67700" - }, - { - "type": "arrow", - "id": "write-to-angel", - "x": 820, - "y": 170, - "width": 60, - "height": 0, - "points": [[0,0],[60,0]], - "strokeColor": "#862e9c", - "label": { "text": "phys addr\n+cache flush" } - }, - { - "type": "arrow", - "id": "angel-to-stdout", - "x": 1010, - "y": 170, - "width": 60, - "height": 0, - "points": [[0,0],[60,0]], - "strokeColor": "#c92a2a" - }, - { - "type": "text", - "id": "log-enable-note", - "x": 480, - "y": 220, - "width": 200, - "height": 40, - "text": "only if log_enable=1\n(optional live streaming)", - "fontSize": 12, - "fontFamily": 1, - "textAlign": "center", - "strokeColor": "#868e96", - "backgroundColor": "transparent" - }, - { - "type": "text", - "id": "logbuf-enable-note", - "x": 240, - "y": 60, - "width": 200, - "height": 20, - "text": "only if logbuf_enable=1", - "fontSize": 12, - "fontFamily": 1, - "textAlign": "center", - "strokeColor": "#868e96", - "backgroundColor": "transparent" - } - ], - "appState": { - "viewBackgroundColor": "#ffffff", - "gridSize": 20 - } -} diff --git a/wip_notes.md b/wip_notes.md deleted file mode 100644 index 9af3b3eaa..000000000 --- a/wip_notes.md +++ /dev/null @@ -1,50 +0,0 @@ -# WIP: Log Spam Control (Phase 3) - -## Branch: wip/log-spam-control - -## What's done - -### log.h -- `H2K_log_once(fmt, ...)` — fires once globally per callsite (callsite-static `u32_t __f`) -- `H2K_log_once_ht(fmt, ...)` — fires once per hardware thread (callsite-static `u32_t __f[MAX_HTHREADS]`) -- `H2K_log_throttle(interval, fmt, ...)` — rate-limit globally (callsite-static `u64_t __t`) -- `H2K_log_throttle_ht(interval, fmt, ...)` — rate-limit per hardware thread -- Severity variants for all four: `_err`, `_warn`, `_info` suffixes - - e.g. `H2K_log_once_err(...)`, `H2K_log_throttle_ht_warn(interval, ...)` -- All three build branches consistent: `H2K_LOGBUF` (full), `H2K_LOG_PRINTF` (pass-through), off (no-op) - -### log.ref.c -- `H2K_log_once(u32_t *flag)` — `H2K_atomic_setbit`, returns 1 on first call -- `H2K_log_once_ht(u32_t *flags)` — per-ht slot, lockless -- `H2K_log_throttle(u64_t *last, u64_t interval)` — pcycle delta, uses `logbuf_lock` -- `H2K_log_throttle_ht(u64_t *last, u64_t interval)` — per-ht slot, lockless - -### log_diagram.excalidraw -- Updated compile-time flags box: removed `H2K_LOG_PRINTF`, added `make LOGBUF=sched` examples - -## Known issues / TODO - -1. **`H2K_LOG_PRINTF` inconsistency** — removed from diagram but still in `log.h` code. - Decision needed: remove from code too, or restore in diagram? - -2. **Global throttle deadlock risk** — `H2K_log_throttle` takes `logbuf_lock`. - Safe today (never called while lock is held), but fragile. Document or enforce. - -3. **`MAX_HTHREADS` hidden dependency** — `_ht` macros require `max.h` included - before `log.h`. Works in kernel, but not obvious from the header alone. - -4. **Inline header problem (deferred)** — callsite-static `__f` is duplicated - per translation unit for `static inline` functions in headers (e.g. `readylist.h`). - Workaround: channel-ID design using `H2K_gp` state (see plan file). Deferred. - -## How spam control works - -Each macro expansion creates its own `static` local variable at that point in source: -- `once`: `static u32_t __f = 0` — atomically set on first call, suppressed after -- `throttle`: `static u64_t __t = 0` — timestamp of last fire, checked against interval - -Per-function independence: each expansion site has its own `__f`/`__t`, so two -`H2K_log_once()` calls in different functions fire independently (once each). - -Time unit for throttle: CPU pcycles via `H2K_get_pcycle_reg()` — same concept as -Linux `printk_ratelimited` but cycle-based instead of wall-clock milliseconds. From a9720fe0f12212b04f4def0d16abfd4c7678e018 Mon Sep 17 00:00:00 2001 From: Zeev Belinsky Date: Tue, 7 Jul 2026 15:56:54 -0700 Subject: [PATCH 4/4] notes: consolidate logging phases 2-3 with 2026-07-07 improvements Signed-off-by: Zeev Belinsky --- notes.md | 52 ++++++++++++++-------------------------------------- 1 file changed, 14 insertions(+), 38 deletions(-) diff --git a/notes.md b/notes.md index c85ef7e05..5581b7450 100644 --- a/notes.md +++ b/notes.md @@ -811,46 +811,22 @@ Qualcomm-internal tool wrapper infrastructure. A symlink named after each tool files to locate the correct tool installation. Set `USE_PKW=1` in the build to enable it. -### Selective logging (LOGBUF) + log severity levels +### Selective logging (LOGBUF) + log severity levels + spam control + `H2K_log` is gated per-translation-unit by the `LOGBUF` make variable: - `make LOGBUF=1` -- enable logging everywhere (legacy) - `make LOGBUF=sched` -- whole subtree (dir token) - `make LOGBUF=sched/resched/resched.ref.c` -- single file (file token) - `make LOGBUF=data/globals,sched/dosched` -- comma-separated mix -Util/log/ and init/setup/ are always force-flagged when LOGBUF is -set, because they hold H2K_log_print (the impl) and H2K_log_init (the bootstrap); -without them the selected callsites fail to link / the logbuf is never allocated. -A token matching no sources emits a $(warning). - -Severity levels (kernel/util/log/log.h): H2K_log_err/warn/info/dbg map to -H2K_LOG_ERR/WARN/INFO/DBG (0..3). Plain `H2K_log` is an alias for `_dbg`. -Runtime threshold `log_level` (static in log.ref.c, default -H2K_LOG_DBG) drops messages with level > threshold. Each line gets a -prefix assembled in H2K_log_print: `[ht][][][file:line] msg`, -using get_hwtnum() and H2K_get_pcycle_reg(). - -### Per-hthread lockless log rings (Phase 2, done) -globals.h now holds `logbuf[MAX_HTHREADS]`, `logbuf_pos[MAX_HTHREADS]`, -`logbuf_enable`, `log_enable` instead of a single buffer. Each hthread writes -ONLY its own ring (indexed by get_hwtnum()), so H2K_log_print takes NO lock on -the buffering path -- fixes the self-deadlock risk when logging from the -scheduler/interrupt path (logbuf_lock was non-reentrant). Ring size is -`LOGBUF_PER_HT_SIZE` (max.h, default 4KB, override with -D). -- `logbuf_lock` is RETAINED but now serializes only the shared angel SYS_WRITE - console channel (live streaming), not buffering. -- `log_enable=1` in H2K_log_init enables live per-call streaming via angel SYS_WRITE - (serialized by logbuf_lock); `logbuf_enable=1` enables ring buffering. Both are - set by default in H2K_log_init. -- emit_char/emit_string/num/emit_prefix all take htid as first arg now. -- H2K_logbuf_alloc signature changed to (htid, count). -Verified: make all_clean && make test_variant TARGET=ref ARCHV=81 -> 99/0; -make build LOGBUF=sched compiles + links. - -### Log spam control (Phase 3, DONE) -Four log-filtering primitives added; state lives in local statics in log.ref.c. -- `H2K_log_once(ch, ...)` — fires once globally (atomic test-and-set via H2K_atomic_setbit) -- `H2K_log_once_ht(ch, ...)` — fires once per hardware thread (lockless, per-ht only) -- `H2K_log_throttle(ch, iv, ...)` — global rate limit (serialized by logbuf_lock) -- `H2K_log_throttle_ht(ch, iv, ...)` — per-ht rate limit (lockless) -Channel IDs (H2K_LOG_CH_RESCHED, H2K_LOG_CH_COPROC, H2K_LOG_CH_N) declared in -max.h under #ifdef H2K_LOGBUF (alongside LOGBUF_PER_HT_SIZE). + +Severity levels (kernel/util/log/log.h): H2K_log_err/warn/info/dbg map to H2K_LOG_ERR/WARN/INFO/DBG (0..3). Plain `H2K_log` is an alias for `_dbg`. Runtime threshold `log_level` (static in log.ref.c, default H2K_LOG_DBG) drops messages with level > threshold. Each line gets a prefix: `[ht][][][file:line] msg`. + +**Phase 2 (per-hthread lockless log rings):** globals.h holds `logbuf[MAX_HTHREADS]`, `logbuf_pos[MAX_HTHREADS]`, `logbuf_enable`, `log_enable`. Each hthread writes only its own ring (indexed by get_hwtnum()), so H2K_log_print takes NO lock on the buffering path — fixes self-deadlock risk when logging from scheduler/interrupt path. Ring size is `LOGBUF_PER_HT_SIZE` (max.h, default 4KB). `logbuf_lock` now serializes only the shared angel SYS_WRITE console channel (live streaming), not buffering. + +**Phase 3 (spam control + improvements, 2026-07-07):** +- Four log-filtering primitives: `H2K_log_once()` (global, atomic test-and-set), `H2K_log_once_ht()` (per-HT, lockless), `H2K_log_throttle()` (global rate limit), `H2K_log_throttle_ht()` (per-HT rate limit). +- **Symbolic level names:** `LOGBUF=sched[warn]` now accepts symbolic names (`err`/`warn`/`info`/`dbg`) instead of numeric (0–3). Kernel/Makefile and scripts/Makefile.inc.test map names to levels. +- **H2K_LOG_NO_SPAM flag:** New build flag disables spam-control macros (once/throttle) to eliminate static state. When set, `H2K_log_once*()` and `H2K_log_throttle*()` become no-ops. +- **Per-HT once-flag optimization:** `H2K_log_once_ht()` now uses a single u32 bitmask (1 bit per HT) instead of an array, reducing per-callsite storage from 4×MAX_HTHREADS to 4 bytes. + +**Files changed:** kernel/Makefile (level mapping), kernel/util/log/log.h (H2K_LOG_NO_SPAM conditional), kernel/util/log/log.ref.c (bitmask-based once_ht), scripts/Makefile.inc.test (level mapping for standalone tests), kernel/util/log/log.spec (new API reference and build configuration documentation).