diff --git a/kernel/Makefile b/kernel/Makefile index 621ff3af1..a2c5d545b 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,34 @@ $(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 +_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 _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 /$(_ll_mod)/,$(_o)),$(_o)))))\ + $(if $(_logbuf_hits),\ + $(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)) \ + $(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..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("hthread %d update_coprocs: add xe\n", hthread); + H2K_log_once_ht("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(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/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 52ff5d919..6cc517269 100644 --- a/kernel/util/log/log.h +++ b/kernel/util/log/log.h @@ -6,25 +6,268 @@ #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"); -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_write(u32_t fd, const u8_t *buf, u32_t len) 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"); 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_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) +#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_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(...) \ + 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_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, ...) \ + 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_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, ...) \ + 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) +#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 -#define H2K_log(...) printf(__VA_ARGS__) -#define H2K_log_string(S) puts(S) +#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_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(...) +#define H2K_log_info(...) +#define H2K_log_dbg(...) #define H2K_log(...) #define H2K_log_string(S) +#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 11193cc7e..9b5084f63 100644 --- a/kernel/util/log/log.ref.c +++ b/kernel/util/log/log.ref.c @@ -10,39 +10,27 @@ #include #include #include +#include +#include +#include #ifdef H2K_LOGBUF -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; -} +/* 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 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 +58,80 @@ 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) { +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 len = strlen(string); - s32_t ret = len; +u32_t H2K_do_log_string_at(u32_t level, const char *file, u32_t line, const char *string) { - H2K_spinlock_lock(&H2K_gp->logbuf_lock); + u32_t htid = get_hwtnum(); + char *buf; + u32_t start; + u32_t len = 0; - if (H2K_gp->logbuf_enable) { - strcpy(H2K_logbuf_alloc(len + 1), string); - } + if (!H2K_gp->logbuf_enable && !H2K_gp->log_enable) + return 0; - if (H2K_gp->log_enable) { - ret = H2K_write(1, (const u8_t *)"H2K: ", 5); - if (ret < 0) goto out; + if (level > log_level) + return 0; + + buf = H2K_gp->logbuf[htid]; + start = H2K_gp->logbuf_pos[htid]; - ret = H2K_write(1, (const u8_t *)string, len); + len += emit_prefix(htid, level, file, line); + len += emit_string(htid, string); + + if (H2K_gp->log_enable) { + H2K_spinlock_lock(&H2K_gp->logbuf_lock); + 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); } - out: - H2K_spinlock_unlock(&H2K_gp->logbuf_lock); - return ret; + return len; } -/* 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 +157,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_str[] = { "ERROR", "WARN", "INFO", "DEBUG" }; - 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; + 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) { + if ('/' == *p) base = p + 1; + p++; + } + + len += emit_string(htid, "[ht"); + len += num(htid, (u64_t)htid, 10, 0, 0); + len += emit_string(htid, "]["); + len += emit_string(htid, sev); + 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 +210,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 +243,7 @@ s32_t H2K_log_print(const char *fmt, ...) { break; case '%': - emit_char(*fmt); + emit_char(htid, *fmt); len++; break; @@ -216,9 +266,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 +279,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 +298,119 @@ 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). */ +/* 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); +} + +/* 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 + +#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/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/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/notes.md b/notes.md index 58042d3b8..5581b7450 100644 --- a/notes.md +++ b/notes.md @@ -810,3 +810,23 @@ 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 + 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 + +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). 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