Serialize multiline printks
authorBarret Rhoden <brho@cs.berkeley.edu>
Thu, 19 Jul 2018 19:59:48 +0000 (15:59 -0400)
committerBarret Rhoden <brho@cs.berkeley.edu>
Thu, 19 Jul 2018 19:59:48 +0000 (15:59 -0400)
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>
22 files changed:
kern/arch/x86/bitmask.h
kern/arch/x86/ioapic.c
kern/arch/x86/kdebug.c
kern/arch/x86/pmap64.c
kern/arch/x86/trap.c
kern/arch/x86/trap.h
kern/arch/x86/vmm/intel/vmx.c
kern/drivers/dev/kfs.c
kern/drivers/net/mlx4/en_main.c
kern/drivers/net/r8169.c
kern/src/hexdump.c
kern/src/kdebug.c
kern/src/mm.c
kern/src/monitor.c
kern/src/ns/allocb.c
kern/src/ns/convM2D.c
kern/src/ns/sysfile.c
kern/src/ns/tree_file.c
kern/src/process.c
kern/src/rcu_tree_helper.c
kern/src/smp.c
kern/src/syscall.c

index be6e6be..f3c8798 100644 (file)
@@ -91,6 +91,7 @@ static inline bool BITMASK_IS_FULL(volatile uint8_t *map, size_t size)
 #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 @@ static inline bool BITMASK_IS_FULL(volatile uint8_t *map, size_t size)
                } \
        } \
        printk("\n"); \
+       print_unlock(); \
 }
index 31df9cf..c4d760c 100644 (file)
@@ -450,14 +450,14 @@ static struct Rdt *ioapic_vector2rdt(int apic_vector)
 {
        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 @@ int bus_irq_setup(struct irq_handler *irq_h)
                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)
index 7042d26..3b740f8 100644 (file)
@@ -400,6 +400,7 @@ size_t backtrace_user_list(uintptr_t pc, uintptr_t fp, uintptr_t *pcs,
 /* 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 @@ void print_fpu_state(struct ancillary_state *fpu)
                printk("%02x ", *((uint8_t*)fpu + i));
        }
        printk("\n");
+       print_unlock();
 }
index 69a653f..ea1924a 100644 (file)
@@ -561,7 +561,7 @@ static kpte_t __guest_pml_walk(struct proc *p, kpte_t *u_pml, uintptr_t gva,
 
        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 @@ static int print_pte(kpte_t *kpte, uintptr_t kva, int shift, bool visited_subs,
 {
        if (kpte_is_unmapped(kpte))
                return 0;
+       print_lock();
        switch (shift) {
                case (PML1_SHIFT):
                        printk("\t");
@@ -733,6 +734,7 @@ static int print_pte(kpte_t *kpte, uintptr_t kva, int shift, bool visited_subs,
        }
        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;
 }
 
index 82089b4..01b0dd5 100644 (file)
@@ -209,9 +209,11 @@ static void print_fperr(struct hw_trapframe *hw_tf)
 {
        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 @@ static void print_fperr(struct hw_trapframe *hw_tf)
                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,
index e8820b6..0f9a7a8 100644 (file)
@@ -270,7 +270,7 @@ static inline void restore_fp_state(struct ancillary_state *silly)
 
 
        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();
index b925d6d..abe3b2f 100644 (file)
@@ -212,6 +212,8 @@ show_cr_access(uint64_t val)
        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 @@ show_cr_access(uint64_t val)
                }
        }
        printk("\n");
+       print_unlock();
 }
 
 void
index b701a1d..3a5541e 100644 (file)
@@ -224,8 +224,8 @@ static int add_kfs_entry(struct cpio_bin_hdr *c_bhdr, void *cb_arg)
                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)
index f1c7911..f8667c0 100644 (file)
@@ -95,6 +95,7 @@ void en_print(const char *level, const struct mlx4_en_priv *priv,
 #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 @@ void en_print(const char *level, const struct mlx4_en_priv *priv,
                       dev_name(&priv->mdev->pdev->dev), priv->port);
        vcprintf(format, args);
        va_end(args);
+       print_unlock();
 #endif
 }
 
index 52844a2..93f0113 100644 (file)
@@ -8664,7 +8664,7 @@ static void rtl8169_attach(struct ether *edev)
        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 */
index 6b81d42..547979a 100644 (file)
@@ -39,6 +39,7 @@ void hexdump(void *v, int length)
        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 @@ void hexdump(void *v, int length)
                        printk("...\n");
                }
        }
+       print_unlock();
 }
 
 /* easier in monitor */
index 6937d6d..9841484 100644 (file)
@@ -95,8 +95,6 @@ void reset_print_func_depth(void)
        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 @@ void __print_func_entry(const char *func, const char *file)
 {
        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 @@ void __print_func_exit(const char *func, const char *file)
 {
        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 @@ static void printk_func(void *opaque, const char *str)
 
 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 @@ void backtrace_frame(uintptr_t eip, uintptr_t ebp)
        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_frame(uintptr_t eip, uintptr_t ebp)
 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 @@ void backtrace_user_frame(uintptr_t eip, uintptr_t ebp)
                /* 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 @@ void backtrace_user_ctx(struct proc *p, struct user_context *ctx)
                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);
 }
 
index fc5dc4f..8d51536 100644 (file)
@@ -602,6 +602,8 @@ void print_vmrs(struct proc *p)
 {
        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 @@ void print_vmrs(struct proc *p)
                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,
index 6a5fcaf..be56b11 100644 (file)
@@ -120,8 +120,10 @@ static int __backtrace(int argc, char **argv, struct hw_trapframe *hw_tf)
        }
        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 @@ int mon_sm(int argc, char **argv, struct hw_trapframe *hw_tf)
        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 @@ static void print_info_handler(struct hw_trapframe *hw_tf, void *data)
                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 @@ int mon_nanwan(int argc, char **argv, struct hw_trapframe *hw_tf)
        /* 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 @@ int mon_nanwan(int argc, char **argv, struct hw_trapframe *hw_tf)
        printk("                                \\'   .\\#\n");
        printk("                             jgs \\   ::\\#\n");
        printk("                                  \\      \n");
+       print_unlock();
        return 0;
 }
 
@@ -681,6 +683,7 @@ static DEFINE_PERCPU(bool, mon_nmi_trace);
 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_hwtf_backtrace(struct hw_trapframe *hw_tf)
 
 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 @@ static void emit_vmtf_backtrace(struct vm_trapframe *vm_tf)
  * 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();
 }
 
 
index 427cd13..f02ae7a 100644 (file)
@@ -312,6 +312,7 @@ void printblock(struct block *b)
                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 @@ void printblock(struct block *b)
                }
        }
        printk("\n");
+       print_unlock();
 }
index 1492751..bbc027c 100644 (file)
@@ -48,10 +48,8 @@ int statcheck(uint8_t * buf, unsigned int nbuf)
        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;
        }
 
index dc6cf1f..af8340a 100644 (file)
@@ -1393,6 +1393,7 @@ void print_chaninfo(struct chan *c)
        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 @@ void print_chaninfo(struct chan *c)
        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
index be21d2b..14e5f8d 100644 (file)
@@ -1176,6 +1176,7 @@ static void dump_tf(struct tree_file *tf, int tabs)
            !!(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 @@ static void dump_tf(struct tree_file *tf, int tabs)
                list_for_each_entry(child, &tf->children, siblings)
                        dump_tf(child, tabs + 1);
        }
+       print_unlock();
 }
 
 void __tfs_dump(struct tree_filesystem *tfs)
index 336eeba..7c69f77 100644 (file)
@@ -2390,6 +2390,7 @@ void print_proc_info(pid_t pid, int verbosity)
                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 @@ void print_proc_info(pid_t pid, int verbosity)
        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 @@ void print_proc_info(pid_t pid, int verbosity)
        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);
index 4ba1db0..5c99032 100644 (file)
@@ -249,6 +249,7 @@ void rcu_dump_rcu_node_tree(struct rcu_state *rsp)
        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 @@ void rcu_dump_rcu_node_tree(struct rcu_state *rsp)
                printk("%d:%d ^%d ", rnp->grplo, rnp->grphi, rnp->grpnum);
        }
        printk("\n");
+       print_unlock();
 }
index 43ba748..55beb2f 100644 (file)
@@ -191,9 +191,11 @@ static void pcpui_trace_locks_handler(void *event, void *data)
                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: */
index 27e770a..0b63102 100644 (file)
@@ -2534,7 +2534,7 @@ intreg_t syscall(struct proc *p, uintreg_t sc_num, uintreg_t a0, uintreg_t a1,
                       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;
 }