Skip to content

Commit dd64d3e

Browse files
zbelinskzbelinsk
committed
log: full severity/once/throttle API with per-module level control
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<id>][LEVEL][<pcycles>][<file>:<line>] 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 <zbelinsk@qti.qualcomm.com>
1 parent 628edd8 commit dd64d3e

10 files changed

Lines changed: 1438 additions & 98 deletions

File tree

‎kernel/Makefile‎

Lines changed: 13 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -135,18 +135,26 @@ $(foreach MODPATH,$(MKINCLUDES),$(eval $(DO_INCLUDE)))
135135
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)
136136

137137
ifdef LOGBUF
138-
ifeq ($(LOGBUF),1)
138+
_logbuf_one_mod := $(word 1,$(subst [, ,$(LOGBUF)))
139+
_logbuf_one_level := $(subst ],,$(word 2,$(subst [, ,$(LOGBUF))))
140+
ifeq ($(_logbuf_one_mod),1)
139141
CFLAGS += -DH2K_LOGBUF
142+
ifneq ($(_logbuf_one_level),)
143+
CFLAGS += -DH2K_LOG_LEVEL=$(_logbuf_one_level)
144+
endif
140145
else
141146
_logbuf_comma := ,
142147

143148
$(foreach _tok,$(subst $(_logbuf_comma), ,$(LOGBUF)),\
144-
$(eval _logbuf_hits := $(filter %/$(basename $(_tok)).o,$(ALL_OFILES))) \
149+
$(eval _ll_mod := $(word 1,$(subst [, ,$(_tok))))\
150+
$(eval _ll_level := $(subst ],,$(word 2,$(subst [, ,$(_tok)))))\
151+
$(eval _logbuf_hits := $(filter %/$(basename $(_ll_mod)).o,$(ALL_OFILES)))\
145152
$(if $(_logbuf_hits),,\
146-
$(eval _logbuf_hits := $(foreach _o,$(ALL_OFILES),$(if $(findstring /$(_tok)/,$(_o)),$(_o))))) \
153+
$(eval _logbuf_hits := $(foreach _o,$(ALL_OFILES),$(if $(findstring /$(_ll_mod)/,$(_o)),$(_o)))))\
147154
$(if $(_logbuf_hits),\
148-
$(eval $(_logbuf_hits) : CFLAGS += -DH2K_LOGBUF),\
149-
$(warning LOGBUF: token '$(_tok)' matched no kernel sources)))
155+
$(eval $(_logbuf_hits) : CFLAGS += -DH2K_LOGBUF)\
156+
$(if $(_ll_level),$(eval $(_logbuf_hits) : CFLAGS += -DH2K_LOG_LEVEL=$(_ll_level))),\
157+
$(warning LOGBUF: token '$(_ll_mod)' matched no kernel sources)))
150158

151159
$(foreach _o,$(ALL_OFILES),\
152160
$(if $(findstring /util/log/,$(_o)),$(eval $(_o) : CFLAGS += -DH2K_LOGBUF)) \

‎kernel/data/readylist/readylist.h‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -95,7 +95,7 @@ static inline void H2K_update_coprocs(u32_t hthread, u32_t hthread_xe, u32_t hth
9595
}
9696
} else {
9797
if (head_xe) {
98-
H2K_log_once_ht(H2K_LOG_CH_COPROC, "hthread %d update_coprocs: add xe\n", hthread);
98+
H2K_log_once_ht("hthread %d update_coprocs: add xe\n", hthread);
9999
}
100100
}
101101
if (hthread_xe2) {
@@ -220,7 +220,7 @@ static inline H2K_thread_context *H2K_ready_getbest(u32_t hthread)
220220
H2K_thread_context *ret;
221221
u32_t prio;
222222

223-
H2K_log_throttle_ht(H2K_LOG_CH_RESCHED, 1000000, "hthread %d getbest\n", hthread);
223+
H2K_log_throttle_ht(1000000, "hthread %d getbest\n", hthread);
224224
prio = H2K_ready_best_prio();
225225
if (prio >= MAX_PRIOS) { // !H2K_ready_any_valid(), go to sleep
226226
#ifdef CLUSTER_SCHED

‎kernel/data/readylist/test/Makefile‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
1+
22
OBJS+=test.o
33
RECOMPILE_DIRS += $(H2DIR)/kernel/data/readylist
44
RECOMPILE_SRCS_PREFS += readylist

‎kernel/init/setup/setup.ref.c‎

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -92,13 +92,13 @@ IN_SECTION(".text.init.setup") static H2K_vmblock_t *H2K_init_setup(u32_t multic
9292
H2K_l2cache_init();
9393
H2K_tcm_copy(last_tlb_index);
9494
H2K_trace_init();
95-
H2K_runlist_init(); //fix
96-
H2K_readylist_init(); //fix
97-
H2K_lowprio_init(); //fix
98-
H2K_futex_init(); //fix
99-
H2K_intconfig_init(ssbase); //fix
100-
H2K_thread_init();
101-
H2K_asid_table_init(); //fix
95+
H2K_runlist_init();
96+
H2K_readylist_init();
97+
H2K_lowprio_init();
98+
H2K_futex_init();
99+
H2K_intconfig_init(ssbase);
100+
H2K_thread_init();
101+
H2K_asid_table_init();
102102

103103
#ifdef CRASH_DEBUG
104104
H2K_stlb_tcmcrash_init();

‎kernel/traps/hwconfig/hwconfig.ref.c‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -273,7 +273,7 @@ u32_t H2K_trap_hwconfig_hlxbits(u32_t unused, void *unusedp, u32_t xa3, u32_t x
273273
BKL_LOCK();
274274
if (xe3 && !(me->ccr & CCR_XE3_BIT_MASK)) { // turning xe3 on
275275
// block as if we got resched interrupt
276-
H2K_log("hthread %d hlxbits: task 0x%08x setting xe3\n", me->hthread, me);
276+
H2K_log("hthread %d hlxbits: task 0x%08x setting xe3\n", me->hthread, (u32_t)me);
277277
me->ccr = Q6_R_insert_RII(me->ccr, xa3, CCR_XA3_NBITS, CCR_XA3_BITS);
278278
me->ccr = Q6_R_insert_RII(me->ccr, xe3, 1, CCR_XE3_BIT);
279279
me->r00 = 0;
@@ -286,7 +286,7 @@ u32_t H2K_trap_hwconfig_hlxbits(u32_t unused, void *unusedp, u32_t xa3, u32_t x
286286
u32_t hthread_xe2 = ((me->ssr & SSR_XE2_BIT_MASK) ? 1 : 0);
287287

288288
xex(me->hthread, hthread_xe, hthread_xe2, 0, hthread_xe, hthread_xe2, 1);
289-
H2K_log("hthread %d hlxbits: task 0x%08x clearing xe3\n", me->hthread, me);
289+
H2K_log("hthread %d hlxbits: task 0x%08x clearing xe3\n", me->hthread, (u32_t)me);
290290
}
291291
BKL_UNLOCK();
292292
}
@@ -309,7 +309,7 @@ u32_t H2K_trap_hwconfig_hmxbits(u32_t unused, void *unusedp, u32_t xe2, u32_t un
309309
BKL_LOCK();
310310
if (xe2 && !(me->ssr & SSR_XE2_BIT_MASK)) { // turning xe2 on
311311
// block as if we got resched interrupt
312-
H2K_log("hthread %d hmxbits: task 0x%08x setting xe2\n", me->hthread, me);
312+
H2K_log("hthread %d hmxbits: task 0x%08x setting xe2\n", me->hthread, (u32_t)me);
313313
// me->ccr = Q6_R_insert_RII(me->ccr, xa2, CCR_XA2_NBITS, CCR_XA2_BITS);
314314
me->ssr = Q6_R_insert_RII(me->ssr, xe2, 1, SSR_XE2_BIT);
315315
me->r00 = 0;
@@ -322,7 +322,7 @@ u32_t H2K_trap_hwconfig_hmxbits(u32_t unused, void *unusedp, u32_t xe2, u32_t un
322322
u32_t hthread_xe3 = ((me->ccr & CCR_XE3_BIT_MASK) ? 1 : 0);
323323

324324
xex(me->hthread, hthread_xe, 0, hthread_xe3, hthread_xe, 1, hthread_xe3);
325-
H2K_log("hthread %d hmxbits: task 0x%08x clearing xe2\n", me->hthread, me);
325+
H2K_log("hthread %d hmxbits: task 0x%08x clearing xe2\n", me->hthread, (u32_t)me);
326326
}
327327
BKL_UNLOCK();
328328
}
@@ -346,7 +346,7 @@ u32_t H2K_trap_hwconfig_extbits(u32_t unused, void *unusedp, u32_t xa, u32_t xe,
346346
BKL_LOCK();
347347
if (xe && !(me->ssr & SSR_XE_BIT_MASK)) { // turning xe on
348348
// block as if we got resched interrupt
349-
H2K_log("hthread %d extbits: task 0x%08x setting xe\n", me->hthread, me);
349+
H2K_log("hthread %d extbits: task 0x%08x setting xe\n", me->hthread, (u32_t)me);
350350

351351
if ((xa < EXT_HVX_XA_START || xa >= EXT_HVX_XA_START + H2K_gp->coproc_contexts) // not in HVX range
352352
#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,
368368
u32_t hthread_xe3 = ((me->ccr & CCR_XE3_BIT_MASK) ? 1 : 0);
369369

370370
xex(me->hthread, 0, hthread_xe2, hthread_xe3, 1, hthread_xe2, hthread_xe3);
371-
H2K_log("hthread %d extbits: task 0x%08x clearing xe\n", me->hthread, me);
371+
H2K_log("hthread %d extbits: task 0x%08x clearing xe\n", me->hthread, (u32_t)me);
372372
}
373373
BKL_UNLOCK();
374374
}

0 commit comments

Comments
 (0)