Serialize multiline printks
A lot of times the kernel will do a series of printks as part of a larger
call. Backtraces, tabs for formatting, ASCII giraffes, you name it.
To prevent these prints from interleaving with other (atomic) printks, we
can use the print_lock(). There were at least two cases where the
print_lock() replaced an already-existing spinlock that served a similar
purpose.
Additionally, there were a few places that just lacked a \n, which would be
hard to read. Those usually needed to be warn() anyway. And of course
there was a printk("YOU SHOULD PANIC (stuff)"), which is now a panic.
Signed-off-by: Barret Rhoden <brho@cs.berkeley.edu>
diff --git a/kern/arch/x86/bitmask.h b/kern/arch/x86/bitmask.h
index be6e6be..f3c8798 100644
--- a/kern/arch/x86/bitmask.h
+++ b/kern/arch/x86/bitmask.h
@@ -91,6 +91,7 @@
#define PRINT_BITMASK(name, size) { \
int i; \
int _size = size; \
+ print_lock(); \
for (i = 0; i < BYTES_FOR_BITMASK(size); i++) { \
int j; \
for (j = 0; j < MIN(8, _size); j++) { \
@@ -99,4 +100,5 @@
} \
} \
printk("\n"); \
+ print_unlock(); \
}
diff --git a/kern/arch/x86/ioapic.c b/kern/arch/x86/ioapic.c
index 31df9cf..c4d760c 100644
--- a/kern/arch/x86/ioapic.c
+++ b/kern/arch/x86/ioapic.c
@@ -450,14 +450,14 @@
{
struct Rdt *rdt;
if (apic_vector < IdtIOAPIC || apic_vector > MaxIdtIOAPIC) {
- printk("ioapic vector %d out of range", apic_vector);
+ warn("ioapic vector %d out of range", apic_vector);
return 0;
}
/* Fortunately rdtvecno[vecno] is static once assigned. o/w, we'll need some
* global sync for the callers, both for lookup and keeping rdt valid. */
rdt = rdtvecno[apic_vector];
if (!rdt) {
- printk("vector %d has no RDT! (did you enable it?)", apic_vector);
+ warn("vector %d has no RDT! (did you enable it?)", apic_vector);
return 0;
}
return rdt;
@@ -588,7 +588,7 @@
case BusPCI:
pcidev = pci_match_tbdf(irq_h->tbdf);
if (!pcidev) {
- printk("No PCI dev for tbdf %p!", irq_h->tbdf);
+ warn("No PCI dev for tbdf %p!", irq_h->tbdf);
return -1;
}
if ((vecno = msi_irq_enable(irq_h, pcidev)) != -1)
diff --git a/kern/arch/x86/kdebug.c b/kern/arch/x86/kdebug.c
index 7042d26..3b740f8 100644
--- a/kern/arch/x86/kdebug.c
+++ b/kern/arch/x86/kdebug.c
@@ -400,6 +400,7 @@
/* Assumes 32-bit header */
void print_fpu_state(struct ancillary_state *fpu)
{
+ print_lock();
printk("fcw: 0x%04x\n", fpu->fp_head_n64.fcw);
printk("fsw: 0x%04x\n", fpu->fp_head_n64.fsw);
printk("ftw: 0x%02x\n", fpu->fp_head_n64.ftw);
@@ -417,4 +418,5 @@
printk("%02x ", *((uint8_t*)fpu + i));
}
printk("\n");
+ print_unlock();
}
diff --git a/kern/arch/x86/pmap64.c b/kern/arch/x86/pmap64.c
index 69a653f..ea1924a 100644
--- a/kern/arch/x86/pmap64.c
+++ b/kern/arch/x86/pmap64.c
@@ -561,7 +561,7 @@
if (memcpy_from_user(p, &pte, &u_pml[PMLx(gva, pml_shift)],
sizeof(kpte_t))) {
- printk("Buggy pml %p, tried %p\n", u_pml, &u_pml[PMLx(gva, pml_shift)]);
+ warn("Buggy pml %p, tried %p\n", u_pml, &u_pml[PMLx(gva, pml_shift)]);
return 0;
}
if (walk_is_complete(&pte, pml_shift, flags))
@@ -721,6 +721,7 @@
{
if (kpte_is_unmapped(kpte))
return 0;
+ print_lock();
switch (shift) {
case (PML1_SHIFT):
printk("\t");
@@ -733,6 +734,7 @@
}
printk("KVA: %p, PTE val %p, shift %d, visit %d%s\n", kva, *kpte, shift,
visited_subs, (*kpte & PTE_PS ? " (jumbo)" : ""));
+ print_unlock();
return 0;
}
diff --git a/kern/arch/x86/trap.c b/kern/arch/x86/trap.c
index 82089b4..01b0dd5 100644
--- a/kern/arch/x86/trap.c
+++ b/kern/arch/x86/trap.c
@@ -209,9 +209,11 @@
{
uint16_t fpcw, fpsw;
uint32_t mxcsr;
+
asm volatile ("fnstcw %0" : "=m"(fpcw));
asm volatile ("fnstsw %0" : "=m"(fpsw));
asm volatile ("stmxcsr %0" : "=m"(mxcsr));
+ print_lock();
print_trapframe(hw_tf);
printk("Core %d: FP ERR, CW: 0x%04x, SW: 0x%04x, MXCSR 0x%08x\n", core_id(),
fpcw, fpsw, mxcsr);
@@ -237,6 +239,7 @@
printk("\tNumeric Underflow\n");
if (fpsw & ~fpcw & FP_EXCP_PE)
printk("\tInexact result (precision)\n");
+ print_unlock();
}
static bool __handler_user_page_fault(struct hw_trapframe *hw_tf,
diff --git a/kern/arch/x86/trap.h b/kern/arch/x86/trap.h
index e8820b6..0f9a7a8 100644
--- a/kern/arch/x86/trap.h
+++ b/kern/arch/x86/trap.h
@@ -270,7 +270,7 @@
if (err) {
- printk("Error restoring fp state!");
+ printk("Error restoring fp state!\n");
printk("Likely a bad ancillary_state argument.\n");
printk("Re-initializing fp state to default due to error.\n");
init_fp_state();
diff --git a/kern/arch/x86/vmm/intel/vmx.c b/kern/arch/x86/vmm/intel/vmx.c
index b925d6d..abe3b2f 100644
--- a/kern/arch/x86/vmm/intel/vmx.c
+++ b/kern/arch/x86/vmm/intel/vmx.c
@@ -212,6 +212,8 @@
int crnr = val & 0xf;
int type = (val >> 4) & 3;
int reg = (val >> 11) & 0xf;
+
+ print_lock();
printk("%s: %d: ", cr_access_type[type], crnr);
if (type < 2) {
printk("%s", cr_gpr[reg]);
@@ -220,6 +222,7 @@
}
}
printk("\n");
+ print_unlock();
}
void
diff --git a/kern/drivers/dev/kfs.c b/kern/drivers/dev/kfs.c
index b701a1d..3a5541e 100644
--- a/kern/drivers/dev/kfs.c
+++ b/kern/drivers/dev/kfs.c
@@ -224,8 +224,8 @@
break;
default:
cclose(c);
- printk("Unknown file type %d in the CPIO!",
- c_bhdr->c_mode & CPIO_FILE_MASK);
+ warn("Unknown file type %d in the CPIO!",
+ c_bhdr->c_mode & CPIO_FILE_MASK);
return -1;
}
if (!c)
diff --git a/kern/drivers/net/mlx4/en_main.c b/kern/drivers/net/mlx4/en_main.c
index f1c7911..f8667c0 100644
--- a/kern/drivers/net/mlx4/en_main.c
+++ b/kern/drivers/net/mlx4/en_main.c
@@ -95,6 +95,7 @@
#else
va_list args;
+ print_lock();
va_start(args, format);
if (priv->registered)
printk("%s%s: %s: ", level, DRV_NAME, priv->dev->name);
@@ -103,6 +104,7 @@
dev_name(&priv->mdev->pdev->dev), priv->port);
vcprintf(format, args);
va_end(args);
+ print_unlock();
#endif
}
diff --git a/kern/drivers/net/r8169.c b/kern/drivers/net/r8169.c
index 52844a2..93f0113 100644
--- a/kern/drivers/net/r8169.c
+++ b/kern/drivers/net/r8169.c
@@ -8664,7 +8664,7 @@
spin_unlock(&rtl_9ns_lock);
if (rtl_open(edev)) {
- printk("Unable to attach rtl8169!");
+ warn("Unable to attach rtl8169!");
return;
}
/* If we want an rproc, nows the time to ktask it */
diff --git a/kern/src/hexdump.c b/kern/src/hexdump.c
index 6b81d42..547979a 100644
--- a/kern/src/hexdump.c
+++ b/kern/src/hexdump.c
@@ -39,6 +39,7 @@
uintptr_t memory = (uintptr_t) v;
int all_zero = 0;
+ print_lock();
for (i = 0; i < length; i += 16) {
int j;
@@ -62,6 +63,7 @@
printk("...\n");
}
}
+ print_unlock();
}
/* easier in monitor */
diff --git a/kern/src/kdebug.c b/kern/src/kdebug.c
index 6937d6d..9841484 100644
--- a/kern/src/kdebug.c
+++ b/kern/src/kdebug.c
@@ -95,8 +95,6 @@
tab_depth = 0;
}
-static spinlock_t lock = SPINLOCK_INITIALIZER_IRQSAVE;
-
static void __print_hdr(void)
{
struct per_cpu_info *pcpui = &per_cpu_info[core_id()];
@@ -117,14 +115,15 @@
{
char tentabs[] = "\t\t\t\t\t\t\t\t\t\t"; // ten tabs and a \0
char *ourtabs = &tentabs[10 - MIN(tab_depth, 10)];
+
if (!printx_on)
return;
if (is_blacklisted(func))
return;
- spin_lock_irqsave(&lock);
+ print_lock();
__print_hdr();
printk("%s%s() in %s\n", ourtabs, func, file);
- spin_unlock_irqsave(&lock);
+ print_unlock();
tab_depth++;
}
@@ -132,16 +131,17 @@
{
char tentabs[] = "\t\t\t\t\t\t\t\t\t\t"; // ten tabs and a \0
char *ourtabs;
+
if (!printx_on)
return;
if (is_blacklisted(func))
return;
tab_depth--;
ourtabs = &tentabs[10 - MIN(tab_depth, 10)];
- spin_lock_irqsave(&lock);
+ print_lock();
__print_hdr();
printk("%s---- %s()\n", ourtabs, func);
- spin_unlock_irqsave(&lock);
+ print_unlock();
}
bool printx_on = FALSE;
@@ -215,8 +215,10 @@
void backtrace(void)
{
+ print_lock();
printk("Stack Backtrace on Core %d:\n", core_id());
gen_backtrace(&printk_func, NULL);
+ print_unlock();
}
void backtrace_frame(uintptr_t eip, uintptr_t ebp)
@@ -224,8 +226,10 @@
uintptr_t pcs[MAX_BT_DEPTH];
size_t nr_pcs = backtrace_list(eip, ebp, pcs, MAX_BT_DEPTH);
+ print_lock();
printk("\nBacktrace of kernel context on Core %d:\n", core_id());
print_backtrace_list(pcs, nr_pcs, &printk_func, NULL);
+ print_unlock();
}
/* TODO: change debug_addr_proc() to allow print redirection like
@@ -233,8 +237,10 @@
void backtrace_user_frame(uintptr_t eip, uintptr_t ebp)
{
uintptr_t pcs[MAX_BT_DEPTH];
+ /* TODO: this assumes we have the user's address space loaded (current). */
size_t nr_pcs = backtrace_user_list(eip, ebp, pcs, MAX_BT_DEPTH);
+ print_lock();
printk("\nBacktrace of user context on Core %d:\n", core_id());
printk("\tOffsets only matter for shared libraries\n");
/* This formatting is consumed by scripts/bt-akaros.sh. */
@@ -243,23 +249,19 @@
/* TODO: user backtraces all assume we're working on 'current' */
debug_addr_proc(current, pcs[i]);
}
+ print_unlock();
}
void backtrace_hwtf(struct hw_trapframe *hw_tf)
{
- struct per_cpu_info *pcpui = &per_cpu_info[core_id()];
-
- pcpui->__lock_checking_enabled--;
if (in_kernel(hw_tf))
backtrace_frame(get_hwtf_pc(hw_tf), get_hwtf_fp(hw_tf));
else
backtrace_user_frame(get_hwtf_pc(hw_tf), get_hwtf_fp(hw_tf));
- pcpui->__lock_checking_enabled++;
}
void backtrace_user_ctx(struct proc *p, struct user_context *ctx)
{
- struct per_cpu_info *pcpui = &per_cpu_info[core_id()];
uintptr_t st_save;
if (!ctx) {
@@ -267,9 +269,7 @@
return;
}
st_save = switch_to(p);
- pcpui->__lock_checking_enabled--;
backtrace_user_frame(get_user_ctx_pc(ctx), get_user_ctx_fp(ctx));
- pcpui->__lock_checking_enabled++;
switch_back(p, st_save);
}
diff --git a/kern/src/mm.c b/kern/src/mm.c
index fc5dc4f..8d51536 100644
--- a/kern/src/mm.c
+++ b/kern/src/mm.c
@@ -602,6 +602,8 @@
{
int count = 0;
struct vm_region *vmr;
+
+ print_lock();
printk("VM Regions for proc %d\n", p->pid);
printk("NR:"
" Range:"
@@ -613,6 +615,7 @@
printk("%02d: (%p - %p): 0x%08x, 0x%08x, %p, %p\n", count++,
vmr->vm_base, vmr->vm_end, vmr->vm_prot, vmr->vm_flags,
foc_pointer(vmr->__vm_foc), vmr->vm_foff);
+ print_unlock();
}
void enumerate_vmrs(struct proc *p,
diff --git a/kern/src/monitor.c b/kern/src/monitor.c
index 6a5fcaf..be56b11 100644
--- a/kern/src/monitor.c
+++ b/kern/src/monitor.c
@@ -120,8 +120,10 @@
}
pc = strtol(argv[1], 0, 16);
fp = strtol(argv[2], 0, 16);
+ print_lock();
printk("Backtrace from instruction %p, with frame pointer %p\n", pc, fp);
backtrace_frame(pc, fp);
+ print_unlock();
return 0;
}
@@ -187,13 +189,11 @@
return __showmapping(argc, argv, hw_tf);
}
-static spinlock_t print_info_lock = SPINLOCK_INITIALIZER_IRQSAVE;
-
static void print_info_handler(struct hw_trapframe *hw_tf, void *data)
{
uint64_t tsc = read_tsc();
- spin_lock_irqsave(&print_info_lock);
+ print_lock();
cprintf("----------------------------\n");
cprintf("This is Core %d\n", core_id());
cprintf("Timestamp = %lld\n", tsc);
@@ -218,7 +218,7 @@
read_msr(0x20e), read_msr(0x20f));
#endif // CONFIG_X86
cprintf("----------------------------\n");
- spin_unlock_irqsave(&print_info_lock);
+ print_unlock();
}
static bool print_all_info(void)
@@ -254,6 +254,7 @@
/* Borrowed with love from http://www.geocities.com/SoHo/7373/zoo.htm
* (http://www.ascii-art.com/). Slightly modified to make it 25 lines tall.
*/
+ print_lock();
printk("\n");
printk(" .-. .-.\n");
printk(" | \\/ |\n");
@@ -278,6 +279,7 @@
printk(" \\' .\\#\n");
printk(" jgs \\ ::\\#\n");
printk(" \\ \n");
+ print_unlock();
return 0;
}
@@ -681,6 +683,7 @@
static void emit_hwtf_backtrace(struct hw_trapframe *hw_tf)
{
if (mon_verbose_trace) {
+ printk("\n");
print_trapframe(hw_tf);
backtrace_hwtf(hw_tf);
}
@@ -690,8 +693,10 @@
static void emit_vmtf_backtrace(struct vm_trapframe *vm_tf)
{
- if (mon_verbose_trace)
+ if (mon_verbose_trace) {
+ printk("\n");
print_vmtrapframe(vm_tf);
+ }
printk("Core %d is at %p\n", core_id(), get_vmtf_pc(vm_tf));
}
@@ -700,22 +705,18 @@
* doesn't deal in contexts (yet) */
void emit_monitor_backtrace(int type, void *tf)
{
- struct per_cpu_info *pcpui = &per_cpu_info[core_id()];
-
if (!PERCPU_VAR(mon_nmi_trace))
return;
/* To prevent a spew of output during a lot of perf NMIs, we'll turn off the
* monitor output as soon as any NMI hits our core. */
PERCPU_VAR(mon_nmi_trace) = FALSE;
- /* Temporarily disable deadlock detection when we print. We could
- * deadlock if we were printing when we NMIed. */
- pcpui->__lock_checking_enabled--;
+ print_lock();
if (type == ROS_HW_CTX)
emit_hwtf_backtrace((struct hw_trapframe*)tf);
else
emit_vmtf_backtrace((struct vm_trapframe*)tf);
print_kmsgs(core_id());
- pcpui->__lock_checking_enabled++;
+ print_unlock();
}
diff --git a/kern/src/ns/allocb.c b/kern/src/ns/allocb.c
index 427cd13..f02ae7a 100644
--- a/kern/src/ns/allocb.c
+++ b/kern/src/ns/allocb.c
@@ -312,6 +312,7 @@
return;
}
+ print_lock();
printk("block of BLEN = %d, with %d header and %d data in %d extras\n",
BLEN(b), BHLEN(b), b->extra_len, b->nr_extra_bufs);
@@ -345,4 +346,5 @@
}
}
printk("\n");
+ print_unlock();
}
diff --git a/kern/src/ns/convM2D.c b/kern/src/ns/convM2D.c
index 1492751..bbc027c 100644
--- a/kern/src/ns/convM2D.c
+++ b/kern/src/ns/convM2D.c
@@ -48,10 +48,8 @@
ebuf = buf + nbuf;
if (nbuf < STAT_FIX_LEN_9P || nbuf != BIT16SZ + GBIT16(buf)) {
- printk("nbuf %d, STAT_FIX_LEN_9P %d ", nbuf, STAT_FIX_LEN_9P);
- printk("BIT16SZ %d, GBIT16(buf) %d ",
- BIT16SZ, GBIT16(buf));
- printk("This is bad!\n");
+ warn("nbuf %d, STAT_FIX_LEN_9P %d BIT16SZ %d, GBIT16(buf) %d ",
+ nbuf, STAT_FIX_LEN_9P, BIT16SZ, GBIT16(buf));
return -1;
}
diff --git a/kern/src/ns/sysfile.c b/kern/src/ns/sysfile.c
index dc6cf1f..af8340a 100644
--- a/kern/src/ns/sysfile.c
+++ b/kern/src/ns/sysfile.c
@@ -1393,6 +1393,7 @@
bool has_dev = c->type != -1;
bool has_chaninfo = has_dev && devtab[c->type].chaninfo;
+ print_lock();
printk("Chan flags: %p, pathname: %s, ref: %d, Dev: %s, Devinfo: %s",
c->flag,
c->name ? c->name->s : "no cname",
@@ -1402,6 +1403,7 @@
if (!has_chaninfo)
printk("qid.path: %p\n", c->qid.path);
printk("\n");
+ print_unlock();
}
/* TODO: 9ns ns inheritance flags: Shared, copied, or empty. The old fgrp is
diff --git a/kern/src/ns/tree_file.c b/kern/src/ns/tree_file.c
index be21d2b..14e5f8d 100644
--- a/kern/src/ns/tree_file.c
+++ b/kern/src/ns/tree_file.c
@@ -1176,6 +1176,7 @@
!!(tf->file.dir.qid.type & QTSYMLINK))
warn("%s has differing symlink bits", tree_file_to_name(tf));
+ print_lock();
for (int i = 0; i < tabs; i++)
printk(" ");
print_tf(tf);
@@ -1186,6 +1187,7 @@
list_for_each_entry(child, &tf->children, siblings)
dump_tf(child, tabs + 1);
}
+ print_unlock();
}
void __tfs_dump(struct tree_filesystem *tfs)
diff --git a/kern/src/process.c b/kern/src/process.c
index 336eeba..7c69f77 100644
--- a/kern/src/process.c
+++ b/kern/src/process.c
@@ -2390,6 +2390,7 @@
return;
}
vcpd = &p->procdata->vcore_preempt_data[0];
+ print_lock();
spinlock_debug(&p->proc_lock);
//spin_lock(&p->proc_lock); // No locking!!
printk("struct proc: %p\n", p);
@@ -2441,6 +2442,7 @@
if (spin_locked(&files->lock)) {
spinlock_debug(&files->lock);
printk("FILE LOCK HELD, ABORTING\n");
+ print_unlock();
proc_decref(p);
return;
}
@@ -2456,6 +2458,7 @@
printk("Children: (PID (struct proc *))\n");
TAILQ_FOREACH(child, &p->children, sibling_link)
printk("\t%d (%p)\n", child->pid, child);
+ print_unlock();
/* no locking / unlocking or refcnting */
// spin_unlock(&p->proc_lock);
proc_decref(p);
diff --git a/kern/src/rcu_tree_helper.c b/kern/src/rcu_tree_helper.c
index 4ba1db0..5c99032 100644
--- a/kern/src/rcu_tree_helper.c
+++ b/kern/src/rcu_tree_helper.c
@@ -249,6 +249,7 @@
int level = 0;
struct rcu_node *rnp;
+ print_lock();
printk("rcu_node tree layout dump\n");
printk(" ");
rcu_for_each_node_breadth_first(rsp, rnp) {
@@ -260,4 +261,5 @@
printk("%d:%d ^%d ", rnp->grplo, rnp->grphi, rnp->grpnum);
}
printk("\n");
+ print_unlock();
}
diff --git a/kern/src/smp.c b/kern/src/smp.c
index 43ba748..55beb2f 100644
--- a/kern/src/smp.c
+++ b/kern/src/smp.c
@@ -191,9 +191,11 @@
func_name = get_fn_name(lock_addr);
else
func_name = "Dynamic lock";
+ print_lock();
printk("Time %uus, lock %p (%s)\n", te->arg0, lock_addr, func_name);
printk("\t");
spinlock_debug((spinlock_t*)lock_addr);
+ print_unlock();
}
/* Add specific trace handlers here: */
diff --git a/kern/src/syscall.c b/kern/src/syscall.c
index 27e770a..0b63102 100644
--- a/kern/src/syscall.c
+++ b/kern/src/syscall.c
@@ -2534,7 +2534,7 @@
sc_num, syscall_table[sc_num].name, a0, a1, a2, a3,
a4, a5, p->pid);
if (sc_num != SYS_fork)
- printk("YOU SHOULD PANIC: errstack mismatch");
+ panic("errstack mismatch");
}
return ret;
}
