Modify ktr(4) to be typesafe
authorAggelos Economopoulos <aoiko@cc.ece.ntua.gr>
Fri, 30 Dec 2011 13:38:34 +0000 (05:38 -0800)
committerAggelos Economopoulos <aggelos@pearl.nodomain>
Fri, 30 Dec 2011 17:22:03 +0000 (18:22 +0100)
- Use a struct copy to place the logged values directly into the
  destination buffer without forcing a memcpy.
- This also fixes event logging on x86_64, as we no longer rely
  on the i386 calling convention for functions with a variable
  number of arguments.
- Verify that the arguments match the specified format.
- Update callsites.

Note that this requires userspace changes! ktrdump(8) needs to be
adjusted even on i386 (%c and %hd are no longer promoted as per the
C rules). We need very special handling on x86_64 too.

19 files changed:
sys/bus/usb/usb_mem.c
sys/dev/disk/dm/targets/crypt/dm_target_crypt.c
sys/dev/netif/bge/if_bge.c
sys/dev/netif/em/if_em.c
sys/dev/netif/emx/if_emx.c
sys/kern/dsched/bfq/bfq_ktr.h
sys/kern/kern_ktr.c
sys/kern/kern_poll.c
sys/kern/kern_slaballoc.c
sys/kern/kern_synch.c
sys/kern/lwkt_ipiq.c
sys/kern/lwkt_serialize.c
sys/kern/lwkt_thread.c
sys/kern/lwkt_token.c
sys/net/if.c
sys/net/if_ethersubr.c
sys/platform/pc32/i386/trap.c
sys/platform/pc64/x86_64/trap.c
sys/sys/ktr.h

index 8e3b4c4..ee42e4e 100644 (file)
 #include <bus/usb/usbdivar.h>  /* just for usb_dma_t */
 #include <bus/usb/usb_mem.h>
 
-#define USBKTR_STRING   "ptr=%p bus=%p size=%d align=%d"
-#define USBKTR_ARG_SIZE (sizeof(void *) * 2 + sizeof(int) * 2)
+#define USBKTR_STRING   "ptr=%p bus=%p size=%zu align=%zu"
+#define USBKTR_ARGS    void  *p, usbd_bus_handle bus, size_t size, size_t align
 
 #if !defined(KTR_USB_MEMORY)
 #define KTR_USB_MEMORY KTR_ALL
 #endif
 KTR_INFO_MASTER(usbmem);
-KTR_INFO(KTR_USB_MEMORY, usbmem, alloc_full, 0, USBKTR_STRING, USBKTR_ARG_SIZE);
-KTR_INFO(KTR_USB_MEMORY, usbmem, alloc_frag, 0, USBKTR_STRING, USBKTR_ARG_SIZE);
-KTR_INFO(KTR_USB_MEMORY, usbmem, free_full, 0, USBKTR_STRING, USBKTR_ARG_SIZE);
-KTR_INFO(KTR_USB_MEMORY, usbmem, free_frag, 0, USBKTR_STRING, USBKTR_ARG_SIZE);
-KTR_INFO(KTR_USB_MEMORY, usbmem, blkalloc, 0, USBKTR_STRING, USBKTR_ARG_SIZE);
-KTR_INFO(KTR_USB_MEMORY, usbmem, blkalloc2, 0, USBKTR_STRING, USBKTR_ARG_SIZE);
-KTR_INFO(KTR_USB_MEMORY, usbmem, blkfree, 0, USBKTR_STRING, USBKTR_ARG_SIZE);
+KTR_INFO(KTR_USB_MEMORY, usbmem, alloc_full, 0, USBKTR_STRING, USBKTR_ARGS);
+KTR_INFO(KTR_USB_MEMORY, usbmem, alloc_frag, 0, USBKTR_STRING, USBKTR_ARGS);
+KTR_INFO(KTR_USB_MEMORY, usbmem, free_full, 0, USBKTR_STRING, USBKTR_ARGS);
+KTR_INFO(KTR_USB_MEMORY, usbmem, free_frag, 0, USBKTR_STRING, USBKTR_ARGS);
+KTR_INFO(KTR_USB_MEMORY, usbmem, blkalloc, 0, USBKTR_STRING, USBKTR_ARGS);
+KTR_INFO(KTR_USB_MEMORY, usbmem, blkalloc2, 0, USBKTR_STRING, USBKTR_ARGS);
+KTR_INFO(KTR_USB_MEMORY, usbmem, blkfree, 0, USBKTR_STRING, USBKTR_ARGS);
 
 #define logmemory(name, ptr, bus, size, align)         \
-       KTR_LOG(usbmem_ ## name, ptr, bus, (int)size, (int)align);
+       KTR_LOG(usbmem_ ## name, ptr, bus, size, align);
 
 #ifdef USB_DEBUG
 #define DPRINTF(x)     if (usbdebug) kprintf x
@@ -283,10 +283,10 @@ usb_freemem(usbd_bus_handle bus, usb_dma_t *p)
        if (p->block->fullblock) {
                DPRINTFN(1, ("usb_freemem: large free\n"));
                usb_block_freemem(p->block);
-               logmemory(free_full, p, bus, 0, 0);
+               logmemory(free_full, p, bus, (size_t)0, (size_t)0);
                return;
        }
-       logmemory(free_frag, p, bus, 0, 0);
+       logmemory(free_frag, p, bus, (size_t)0, (size_t)0);
        f = KERNADDR(p, 0);
        f->block = p->block;
        f->offs = p->offs;
index aa489ea..d583c93 100644 (file)
@@ -66,27 +66,27 @@ KTR_INFO_MASTER(dmcrypt);
 #endif
 
 KTR_INFO(KTR_DMCRYPT, dmcrypt, crypto_dispatch, 0,
-    "crypto_dispatch(%p)", sizeof(void *));
+    "crypto_dispatch(%p)", struct cryptop *crp);
 KTR_INFO(KTR_DMCRYPT, dmcrypt, crypt_strategy, 0,
-    "crypt_strategy(b_cmd = %d, bp = %p)", sizeof(int) + sizeof(void *));
+    "crypt_strategy(b_cmd = %d, bp = %p)", int cmd, struct buf *bp);
 KTR_INFO(KTR_DMCRYPT, dmcrypt, crypto_write_start, 1,
     "crypto_write_start(crp = %p, bp = %p, sector = %d/%d)",
-    sizeof(void *) + sizeof(void *) + sizeof(int) + sizeof(int));
+    struct cryptop *crp, struct buf *bp, int i, int sectors);
 KTR_INFO(KTR_DMCRYPT, dmcrypt, crypto_cb_write_done, 1,
     "crypto_cb_write_done(crp = %p, bp = %p, n = %d)",
-    sizeof(void *) + sizeof(void *) + sizeof(int));
+    struct cryptop *crp, struct buf *bp, int n);
 KTR_INFO(KTR_DMCRYPT, dmcrypt, bio_write_done, 1,
-    "bio_write_done(bp = %p)", sizeof(void *));
+    "bio_write_done(bp = %p)", struct buf *bp);
 KTR_INFO(KTR_DMCRYPT, dmcrypt, crypto_write_retry, 1,
-    "crypto_write_retry(crp = %p)", sizeof(void *));
+    "crypto_write_retry(crp = %p)", struct buf *bp);
 KTR_INFO(KTR_DMCRYPT, dmcrypt, bio_read_done, 2,
-    "bio_read_done(bp = %p)", sizeof(void *));
+    "bio_read_done(bp = %p)", struct buf *bp);
 KTR_INFO(KTR_DMCRYPT, dmcrypt, crypto_read_start, 2,
     "crypto_read_start(crp = %p, bp = %p, sector = %d/%d)",
-    sizeof(void *) + sizeof(void *) + sizeof(int) + sizeof(int));
+    struct cryptop *crp, struct buf *bp, int i, int sectors);
 KTR_INFO(KTR_DMCRYPT, dmcrypt, crypto_cb_read_done, 2,
     "crypto_cb_read_done(crp = %p, bp = %p, n = %d)",
-    sizeof(void *) + sizeof(void *) + sizeof(int));
+    struct cryptop *crp, struct buf *bp, int n);
 
 struct target_crypt_config;
 
index e1a65d4..4a2154b 100644 (file)
@@ -396,9 +396,9 @@ TUNABLE_INT("hw.bge.tx_max_coal_bds", &bge_tx_max_coal_bds);
 #define KTR_IF_BGE     KTR_ALL
 #endif
 KTR_INFO_MASTER(if_bge);
-KTR_INFO(KTR_IF_BGE, if_bge, intr, 0, "intr", 0);
-KTR_INFO(KTR_IF_BGE, if_bge, rx_pkt, 1, "rx_pkt", 0);
-KTR_INFO(KTR_IF_BGE, if_bge, tx_pkt, 2, "tx_pkt", 0);
+KTR_INFO(KTR_IF_BGE, if_bge, intr, 0, "intr");
+KTR_INFO(KTR_IF_BGE, if_bge, rx_pkt, 1, "rx_pkt");
+KTR_INFO(KTR_IF_BGE, if_bge, tx_pkt, 2, "tx_pkt");
 #define logif(name)    KTR_LOG(if_bge_ ## name)
 
 static device_method_t bge_methods[] = {
index 73f81e6..7aa5d56 100644 (file)
@@ -396,11 +396,11 @@ static int        em_display_debug_stats = 0;
 #define KTR_IF_EM      KTR_ALL
 #endif
 KTR_INFO_MASTER(if_em);
-KTR_INFO(KTR_IF_EM, if_em, intr_beg, 0, "intr begin", 0);
-KTR_INFO(KTR_IF_EM, if_em, intr_end, 1, "intr end", 0);
-KTR_INFO(KTR_IF_EM, if_em, pkt_receive, 4, "rx packet", 0);
-KTR_INFO(KTR_IF_EM, if_em, pkt_txqueue, 5, "tx packet", 0);
-KTR_INFO(KTR_IF_EM, if_em, pkt_txclean, 6, "tx clean", 0);
+KTR_INFO(KTR_IF_EM, if_em, intr_beg, 0, "intr begin");
+KTR_INFO(KTR_IF_EM, if_em, intr_end, 1, "intr end");
+KTR_INFO(KTR_IF_EM, if_em, pkt_receive, 4, "rx packet");
+KTR_INFO(KTR_IF_EM, if_em, pkt_txqueue, 5, "tx packet");
+KTR_INFO(KTR_IF_EM, if_em, pkt_txclean, 6, "tx clean");
 #define logif(name)    KTR_LOG(if_em_ ## name)
 
 static int
index 1c57f61..e741f04 100644 (file)
@@ -302,11 +302,11 @@ static int        emx_display_debug_stats = 0;
 #define KTR_IF_EMX     KTR_ALL
 #endif
 KTR_INFO_MASTER(if_emx);
-KTR_INFO(KTR_IF_EMX, if_emx, intr_beg, 0, "intr begin", 0);
-KTR_INFO(KTR_IF_EMX, if_emx, intr_end, 1, "intr end", 0);
-KTR_INFO(KTR_IF_EMX, if_emx, pkt_receive, 4, "rx packet", 0);
-KTR_INFO(KTR_IF_EMX, if_emx, pkt_txqueue, 5, "tx packet", 0);
-KTR_INFO(KTR_IF_EMX, if_emx, pkt_txclean, 6, "tx clean", 0);
+KTR_INFO(KTR_IF_EMX, if_emx, intr_beg, 0, "intr begin");
+KTR_INFO(KTR_IF_EMX, if_emx, intr_end, 1, "intr end");
+KTR_INFO(KTR_IF_EMX, if_emx, pkt_receive, 4, "rx packet");
+KTR_INFO(KTR_IF_EMX, if_emx, pkt_txqueue, 5, "tx packet");
+KTR_INFO(KTR_IF_EMX, if_emx, pkt_txclean, 6, "tx clean");
 #define logif(name)    KTR_LOG(if_emx_ ## name)
 
 static __inline void
index 6941e68..54f6f13 100644 (file)
 KTR_INFO_MASTER(dsched_bfq);
 
 /* thread created */
-KTR_INFO(KTR_DSCHED_BFQ, dsched_bfq, thread_created, 0, "%p", sizeof(void *));
+KTR_INFO(KTR_DSCHED_BFQ, dsched_bfq, thread_created, 0, "%p",
+    struct bfq_thread_io *bfq_tdio);
 
 /* average seek distance per thread */
-KTR_INFO(KTR_DSCHED_BFQ, dsched_bfq, thread_seek_avg, 0, "%p: %" PRIu64, sizeof(off_t) + sizeof(void *));
+KTR_INFO(KTR_DSCHED_BFQ, dsched_bfq, thread_seek_avg, 0, "%p: %" PRIu64,
+    struct bfq_thread_io *bfq_tdio, off_t seek_avg);
 
 /* average thinking time per thread */
-KTR_INFO(KTR_DSCHED_BFQ, dsched_bfq, thread_ttime_avg, 0, "%p: %" PRIu64, sizeof(off_t) + sizeof(void *));
+KTR_INFO(KTR_DSCHED_BFQ, dsched_bfq, thread_ttime_avg, 0, "%p: %" PRIu64,
+    struct bfq_thread_io *bfq_tdio, off_t ttime_avg);
 
 #endif
 
index 10a207a..e4c819c 100644 (file)
 #endif
 KTR_INFO_MASTER(testlog);
 #if KTR_TESTLOG
-KTR_INFO(KTR_TESTLOG, testlog, test1, 0, "test1", sizeof(void *) * 4);
-KTR_INFO(KTR_TESTLOG, testlog, test2, 1, "test2", sizeof(void *) * 4);
-KTR_INFO(KTR_TESTLOG, testlog, test3, 2, "test3", sizeof(void *) * 4);
-KTR_INFO(KTR_TESTLOG, testlog, test4, 3, "test4", 0);
-KTR_INFO(KTR_TESTLOG, testlog, test5, 4, "test5", 0);
-KTR_INFO(KTR_TESTLOG, testlog, test6, 5, "test6", 0);
+KTR_INFO(KTR_TESTLOG, testlog, test1, 0, "test1 %d %d %d %d", int dummy1, int dummy2, int dummy3, int dummy4);
+KTR_INFO(KTR_TESTLOG, testlog, test2, 1, "test2 %d %d %d %d", int dummy1, int dummy2, int dummy3, int dummy4);
+KTR_INFO(KTR_TESTLOG, testlog, test3, 2, "test3 %d %d %d %d", int dummy1, int dummy2, int dummy3, int dummy4);
+KTR_INFO(KTR_TESTLOG, testlog, test4, 3, "test4");
+KTR_INFO(KTR_TESTLOG, testlog, test5, 4, "test5");
+KTR_INFO(KTR_TESTLOG, testlog, test6, 5, "test6");
 #ifdef SMP
-KTR_INFO(KTR_TESTLOG, testlog, pingpong, 6, "pingpong", 0);
-KTR_INFO(KTR_TESTLOG, testlog, pipeline, 7, "pipeline", 0);
-KTR_INFO(KTR_TESTLOG, testlog, crit_beg, 8, "crit_beg", 0);
-KTR_INFO(KTR_TESTLOG, testlog, crit_end, 9, "crit_end", 0);
-KTR_INFO(KTR_TESTLOG, testlog, spin_beg, 10, "spin_beg", 0);
-KTR_INFO(KTR_TESTLOG, testlog, spin_end, 11, "spin_end", 0);
+KTR_INFO(KTR_TESTLOG, testlog, pingpong, 6, "pingpong");
+KTR_INFO(KTR_TESTLOG, testlog, pipeline, 7, "pipeline");
+KTR_INFO(KTR_TESTLOG, testlog, crit_beg, 8, "crit_beg");
+KTR_INFO(KTR_TESTLOG, testlog, crit_end, 9, "crit_end");
+KTR_INFO(KTR_TESTLOG, testlog, spin_beg, 10, "spin_beg");
+KTR_INFO(KTR_TESTLOG, testlog, spin_end, 11, "spin_end");
 #endif
 #define logtest(name)  KTR_LOG(testlog_ ## name, 0, 0, 0, 0)
 #define logtest_noargs(name)   KTR_LOG(testlog_ ## name)
@@ -407,12 +407,11 @@ ktr_resync_callback(void *dummy __unused)
 #endif
 
 /*
- * KTR_WRITE_ENTRY - Primary entry point for kernel trace logging
+ * Setup the next empty slot and return it to the caller to store the data
+ * directly.
  */
-
-static __inline
-void
-ktr_write_entry(struct ktr_info *info, const char *file, int line, __va_list va)
+struct ktr_entry *
+ktr_begin_write_entry(struct ktr_info *info, const char *file, int line)
 {
        struct ktr_cpu_core *kcpu;
        struct ktr_entry *entry;
@@ -421,7 +420,7 @@ ktr_write_entry(struct ktr_info *info, const char *file, int line, __va_list va)
        cpu = mycpu->gd_cpuid;
        kcpu = &ktr_cpu[cpu].core;
        if (kcpu->ktr_buf == NULL)
-               return;
+               return NULL;
 
        crit_enter();
        entry = kcpu->ktr_buf + (kcpu->ktr_idx & KTR_ENTRIES_MASK);
@@ -442,36 +441,26 @@ ktr_write_entry(struct ktr_info *info, const char *file, int line, __va_list va)
        entry->ktr_file = file;
        entry->ktr_line = line;
        crit_exit();
-       if (info->kf_data_size > KTR_BUFSIZE)
-               bcopy(va, entry->ktr_data, KTR_BUFSIZE);
-       else if (info->kf_data_size)
-               bcopy(va, entry->ktr_data, info->kf_data_size);
+       return entry;
+}
+
+int
+ktr_finish_write_entry(struct ktr_info *info, struct ktr_entry *entry)
+{
        if (ktr_stacktrace)
                cpu_ktr_caller(entry);
 #ifdef KTR_VERBOSE
        if (ktr_verbose && info->kf_format) {
 #ifdef SMP
-               kprintf("cpu%d ", cpu);
+               kprintf("cpu%d ", mycpu->gd_cpuid);
 #endif
                if (ktr_verbose > 1) {
                        kprintf("%s.%d\t", entry->ktr_file, entry->ktr_line);
                }
-               kvprintf(info->kf_format, va);
-               kprintf("\n");
+               return !0;
        }
 #endif
-}
-
-void
-ktr_log(struct ktr_info *info, const char *file, int line, ...)
-{
-       __va_list va;
-
-       if (panicstr == NULL) {
-               __va_start(va, line);
-               ktr_write_entry(info, file, line, va);
-               __va_end(va);
-       }
+       return 0;
 }
 
 #ifdef DDB
index ae00c5b..a873f96 100644 (file)
@@ -200,8 +200,8 @@ void                init_device_poll_pcpu(int);     /* per-cpu init routine */
 #define KTR_POLLING    KTR_ALL
 #endif
 KTR_INFO_MASTER(poll);
-KTR_INFO(KTR_POLLING, poll, beg, 0, POLL_KTR_STRING, POLL_KTR_ARG_SIZE);
-KTR_INFO(KTR_POLLING, poll, end, 1, POLL_KTR_STRING, POLL_KTR_ARG_SIZE);
+KTR_INFO(KTR_POLLING, poll, beg, 0, "ifp=%p", void *ifp);
+KTR_INFO(KTR_POLLING, poll, end, 1, "ifp=%p", void *ifp);
 
 #define logpoll(name, arg)     KTR_LOG(poll_ ## name, arg)
 
index 747ecc3..d9fdc88 100644 (file)
 
 #define btokup(z)      (&pmap_kvtom((vm_offset_t)(z))->ku_pagecnt)
 
-#define MEMORY_STRING  "ptr=%p type=%p size=%d flags=%04x"
-#define MEMORY_ARG_SIZE        (sizeof(void *) * 2 + sizeof(unsigned long) +   \
-                       sizeof(int))
+#define MEMORY_STRING  "ptr=%p type=%p size=%lu flags=%04x"
+#define MEMORY_ARGS    void *ptr, void *type, unsigned long size, int flags
 
 #if !defined(KTR_MEMORY)
 #define KTR_MEMORY     KTR_ALL
 #endif
 KTR_INFO_MASTER(memory);
-KTR_INFO(KTR_MEMORY, memory, malloc_beg, 0, "malloc begin", 0);
-KTR_INFO(KTR_MEMORY, memory, malloc_end, 1, MEMORY_STRING, MEMORY_ARG_SIZE);
-KTR_INFO(KTR_MEMORY, memory, free_zero, 2, MEMORY_STRING, MEMORY_ARG_SIZE);
-KTR_INFO(KTR_MEMORY, memory, free_ovsz, 3, MEMORY_STRING, MEMORY_ARG_SIZE);
-KTR_INFO(KTR_MEMORY, memory, free_ovsz_delayed, 4, MEMORY_STRING, MEMORY_ARG_SIZE);
-KTR_INFO(KTR_MEMORY, memory, free_chunk, 5, MEMORY_STRING, MEMORY_ARG_SIZE);
+KTR_INFO(KTR_MEMORY, memory, malloc_beg, 0, "malloc begin");
+KTR_INFO(KTR_MEMORY, memory, malloc_end, 1, MEMORY_STRING, MEMORY_ARGS);
+KTR_INFO(KTR_MEMORY, memory, free_zero, 2, MEMORY_STRING, MEMORY_ARGS);
+KTR_INFO(KTR_MEMORY, memory, free_ovsz, 3, MEMORY_STRING, MEMORY_ARGS);
+KTR_INFO(KTR_MEMORY, memory, free_ovsz_delayed, 4, MEMORY_STRING, MEMORY_ARGS);
+KTR_INFO(KTR_MEMORY, memory, free_chunk, 5, MEMORY_STRING, MEMORY_ARGS);
 #ifdef SMP
-KTR_INFO(KTR_MEMORY, memory, free_request, 6, MEMORY_STRING, MEMORY_ARG_SIZE);
-KTR_INFO(KTR_MEMORY, memory, free_rem_beg, 7, MEMORY_STRING, MEMORY_ARG_SIZE);
-KTR_INFO(KTR_MEMORY, memory, free_rem_end, 8, MEMORY_STRING, MEMORY_ARG_SIZE);
+KTR_INFO(KTR_MEMORY, memory, free_request, 6, MEMORY_STRING, MEMORY_ARGS);
+KTR_INFO(KTR_MEMORY, memory, free_rem_beg, 7, MEMORY_STRING, MEMORY_ARGS);
+KTR_INFO(KTR_MEMORY, memory, free_rem_end, 8, MEMORY_STRING, MEMORY_ARGS);
 #endif
-KTR_INFO(KTR_MEMORY, memory, free_beg, 9, "free begin", 0);
-KTR_INFO(KTR_MEMORY, memory, free_end, 10, "free end", 0);
+KTR_INFO(KTR_MEMORY, memory, free_beg, 9, "free begin");
+KTR_INFO(KTR_MEMORY, memory, free_end, 10, "free end");
 
 #define logmemory(name, ptr, type, size, flags)                                \
        KTR_LOG(memory_ ## name, ptr, type, size, flags)
@@ -1011,7 +1010,7 @@ kfree_remote(void *ptr)
     KKASSERT(z->z_RCount > 0);
     atomic_subtract_int(&z->z_RCount, 1);
 
-    logmemory(free_rem_beg, z, NULL, 0, 0);
+    logmemory(free_rem_beg, z, NULL, 0L, 0);
     KKASSERT(z->z_Magic == ZALLOC_SLAB_MAGIC);
     KKASSERT(z->z_Cpu  == mycpu->gd_cpuid);
     nfree = z->z_NFree;
@@ -1078,7 +1077,7 @@ kfree_remote(void *ptr)
        kup = btokup(z);
        *kup = 0;
     }
-    logmemory(free_rem_end, z, bchunk, 0, 0);
+    logmemory(free_rem_end, z, bchunk, 0L, 0);
 }
 
 #endif
@@ -1117,7 +1116,7 @@ kfree(void *ptr, struct malloc_type *type)
      * Handle special 0-byte allocations
      */
     if (ptr == ZERO_LENGTH_PTR) {
-       logmemory(free_zero, ptr, type, -1, 0);
+       logmemory(free_zero, ptr, type, -1UL, 0);
        logmemory_quick(free_end);
        return;
     }
@@ -1245,7 +1244,7 @@ kfree(void *ptr, struct malloc_type *type)
         * We can use a passive IPI to reduce overhead even further.
         */
        if (bchunk == NULL && rsignal) {
-           logmemory(free_request, ptr, type, z->z_ChunkSize, 0);
+               logmemory(free_request, ptr, type, (unsigned long)z->z_ChunkSize, 0);
            lwkt_send_ipiq_passive(z->z_CpuGd, kfree_remote, z);
            /* z can get ripped out from under us from this point on */
        } else if (rsignal) {
@@ -1262,7 +1261,7 @@ kfree(void *ptr, struct malloc_type *type)
     /*
      * kfree locally
      */
-    logmemory(free_chunk, ptr, type, z->z_ChunkSize, 0);
+    logmemory(free_chunk, ptr, type, (unsigned long)z->z_ChunkSize, 0);
 
     crit_enter();
     chunk = ptr;
index 959a514..4378085 100644 (file)
@@ -93,11 +93,11 @@ MALLOC_DEFINE(M_TSLEEP, "tslpque", "tsleep queues");
 #define KTR_TSLEEP     KTR_ALL
 #endif
 KTR_INFO_MASTER(tsleep);
-KTR_INFO(KTR_TSLEEP, tsleep, tsleep_beg, 0, "tsleep enter %p", sizeof(void *));
-KTR_INFO(KTR_TSLEEP, tsleep, tsleep_end, 1, "tsleep exit", 0);
-KTR_INFO(KTR_TSLEEP, tsleep, wakeup_beg, 2, "wakeup enter %p", sizeof(void *));
-KTR_INFO(KTR_TSLEEP, tsleep, wakeup_end, 3, "wakeup exit", 0);
-KTR_INFO(KTR_TSLEEP, tsleep, ilockfail,  4, "interlock failed %p", sizeof(void *));
+KTR_INFO(KTR_TSLEEP, tsleep, tsleep_beg, 0, "tsleep enter %p", const volatile void *ident);
+KTR_INFO(KTR_TSLEEP, tsleep, tsleep_end, 1, "tsleep exit");
+KTR_INFO(KTR_TSLEEP, tsleep, wakeup_beg, 2, "wakeup enter %p", const volatile void *ident);
+KTR_INFO(KTR_TSLEEP, tsleep, wakeup_end, 3, "wakeup exit");
+KTR_INFO(KTR_TSLEEP, tsleep, ilockfail,  4, "interlock failed %p", const volatile void *ident);
 
 #define logtsleep1(name)       KTR_LOG(tsleep_ ## name)
 #define logtsleep2(name, val)  KTR_LOG(tsleep_ ## name, val)
index a2580aa..972458e 100644 (file)
@@ -99,21 +99,21 @@ SYSCTL_INT(_lwkt, OID_AUTO, panic_ipiq_count, CTLFLAG_RW, &panic_ipiq_count, 0,
 #endif
 
 #define IPIQ_STRING    "func=%p arg1=%p arg2=%d scpu=%d dcpu=%d"
-#define IPIQ_ARG_SIZE  (sizeof(void *) * 2 + sizeof(int) * 3)
+#define IPIQ_ARGS      void *func, void *arg1, int arg2, int scpu, int dcpu
 
 #if !defined(KTR_IPIQ)
 #define KTR_IPIQ       KTR_ALL
 #endif
 KTR_INFO_MASTER(ipiq);
-KTR_INFO(KTR_IPIQ, ipiq, send_norm, 0, IPIQ_STRING, IPIQ_ARG_SIZE);
-KTR_INFO(KTR_IPIQ, ipiq, send_pasv, 1, IPIQ_STRING, IPIQ_ARG_SIZE);
-KTR_INFO(KTR_IPIQ, ipiq, send_nbio, 2, IPIQ_STRING, IPIQ_ARG_SIZE);
-KTR_INFO(KTR_IPIQ, ipiq, send_fail, 3, IPIQ_STRING, IPIQ_ARG_SIZE);
-KTR_INFO(KTR_IPIQ, ipiq, receive, 4, IPIQ_STRING, IPIQ_ARG_SIZE);
-KTR_INFO(KTR_IPIQ, ipiq, sync_start, 5, "cpumask=%08x", sizeof(cpumask_t));
-KTR_INFO(KTR_IPIQ, ipiq, sync_end, 6, "cpumask=%08x", sizeof(cpumask_t));
-KTR_INFO(KTR_IPIQ, ipiq, cpu_send, 7, IPIQ_STRING, IPIQ_ARG_SIZE);
-KTR_INFO(KTR_IPIQ, ipiq, send_end, 8, IPIQ_STRING, IPIQ_ARG_SIZE);
+KTR_INFO(KTR_IPIQ, ipiq, send_norm, 0, IPIQ_STRING, IPIQ_ARGS);
+KTR_INFO(KTR_IPIQ, ipiq, send_pasv, 1, IPIQ_STRING, IPIQ_ARGS);
+KTR_INFO(KTR_IPIQ, ipiq, send_nbio, 2, IPIQ_STRING, IPIQ_ARGS);
+KTR_INFO(KTR_IPIQ, ipiq, send_fail, 3, IPIQ_STRING, IPIQ_ARGS);
+KTR_INFO(KTR_IPIQ, ipiq, receive, 4, IPIQ_STRING, IPIQ_ARGS);
+KTR_INFO(KTR_IPIQ, ipiq, sync_start, 5, "cpumask=%08lx", unsigned long mask);
+KTR_INFO(KTR_IPIQ, ipiq, sync_end, 6, "cpumask=%08lx", unsigned long mask);
+KTR_INFO(KTR_IPIQ, ipiq, cpu_send, 7, IPIQ_STRING, IPIQ_ARGS);
+KTR_INFO(KTR_IPIQ, ipiq, send_end, 8, IPIQ_STRING, IPIQ_ARGS);
 
 #define logipiq(name, func, arg1, arg2, sgd, dgd)      \
        KTR_LOG(ipiq_ ## name, func, arg1, arg2, sgd->gd_cpuid, dgd->gd_cpuid)
@@ -773,7 +773,7 @@ lwkt_cpusync_interlock(lwkt_cpusync_t cs)
        ++ipiq_cscount;
        ++gd->gd_curthread->td_cscount;
        lwkt_send_ipiq_mask(mask, (ipifunc1_t)lwkt_cpusync_remote1, cs);
-       logipiq2(sync_start, mask);
+       logipiq2(sync_start, (long)mask);
 #if 0
        if (gd->gd_curthread->td_wmesg == NULL)
                gd->gd_curthread->td_wmesg = smsg;
@@ -845,7 +845,7 @@ lwkt_cpusync_deinterlock(lwkt_cpusync_t cs)
         */
        --gd->gd_curthread->td_cscount;
        lwkt_process_ipiq();
-       logipiq2(sync_end, mask);
+       logipiq2(sync_end, (long)mask);
     }
     crit_exit_id("cpusync");
 #else
index e1e39b9..4e4b8ae 100644 (file)
@@ -68,28 +68,28 @@ struct exp_backoff {
 };
 
 #define SLZ_KTR_STRING         "slz=%p"
-#define SLZ_KTR_ARG_SIZE       (sizeof(void *))
+#define SLZ_KTR_ARGS           lwkt_serialize_t slz
 
 #ifndef KTR_SERIALIZER
 #define KTR_SERIALIZER KTR_ALL
 #endif
 
 KTR_INFO_MASTER(slz);
-KTR_INFO(KTR_SERIALIZER, slz, enter_beg, 0, SLZ_KTR_STRING, SLZ_KTR_ARG_SIZE);
-KTR_INFO(KTR_SERIALIZER, slz, sleep_beg, 1, SLZ_KTR_STRING, SLZ_KTR_ARG_SIZE);
-KTR_INFO(KTR_SERIALIZER, slz, sleep_end, 2, SLZ_KTR_STRING, SLZ_KTR_ARG_SIZE);
-KTR_INFO(KTR_SERIALIZER, slz, exit_end, 3, SLZ_KTR_STRING, SLZ_KTR_ARG_SIZE);
-KTR_INFO(KTR_SERIALIZER, slz, wakeup_beg, 4, SLZ_KTR_STRING, SLZ_KTR_ARG_SIZE);
-KTR_INFO(KTR_SERIALIZER, slz, wakeup_end, 5, SLZ_KTR_STRING, SLZ_KTR_ARG_SIZE);
-KTR_INFO(KTR_SERIALIZER, slz, try, 6, SLZ_KTR_STRING, SLZ_KTR_ARG_SIZE);
-KTR_INFO(KTR_SERIALIZER, slz, tryfail, 7, SLZ_KTR_STRING, SLZ_KTR_ARG_SIZE);
-KTR_INFO(KTR_SERIALIZER, slz, tryok, 8, SLZ_KTR_STRING, SLZ_KTR_ARG_SIZE);
+KTR_INFO(KTR_SERIALIZER, slz, enter_beg, 0, SLZ_KTR_STRING, SLZ_KTR_ARGS);
+KTR_INFO(KTR_SERIALIZER, slz, sleep_beg, 1, SLZ_KTR_STRING, SLZ_KTR_ARGS);
+KTR_INFO(KTR_SERIALIZER, slz, sleep_end, 2, SLZ_KTR_STRING, SLZ_KTR_ARGS);
+KTR_INFO(KTR_SERIALIZER, slz, exit_end, 3, SLZ_KTR_STRING, SLZ_KTR_ARGS);
+KTR_INFO(KTR_SERIALIZER, slz, wakeup_beg, 4, SLZ_KTR_STRING, SLZ_KTR_ARGS);
+KTR_INFO(KTR_SERIALIZER, slz, wakeup_end, 5, SLZ_KTR_STRING, SLZ_KTR_ARGS);
+KTR_INFO(KTR_SERIALIZER, slz, try, 6, SLZ_KTR_STRING, SLZ_KTR_ARGS);
+KTR_INFO(KTR_SERIALIZER, slz, tryfail, 7, SLZ_KTR_STRING, SLZ_KTR_ARGS);
+KTR_INFO(KTR_SERIALIZER, slz, tryok, 8, SLZ_KTR_STRING, SLZ_KTR_ARGS);
 #ifdef SMP
 KTR_INFO(KTR_SERIALIZER, slz, spinbo, 9,
-        "slz=%p bo1=%d bo=%d", (sizeof(void *) + (2 * sizeof(int))));
+        "slz=%p bo1=%d bo=%d", lwkt_serialize_t slz, int backoff1, int backoff);
 #endif
-KTR_INFO(KTR_SERIALIZER, slz, enter_end, 10, SLZ_KTR_STRING, SLZ_KTR_ARG_SIZE);
-KTR_INFO(KTR_SERIALIZER, slz, exit_beg, 11, SLZ_KTR_STRING, SLZ_KTR_ARG_SIZE);
+KTR_INFO(KTR_SERIALIZER, slz, enter_end, 10, SLZ_KTR_STRING, SLZ_KTR_ARGS);
+KTR_INFO(KTR_SERIALIZER, slz, exit_beg, 11, SLZ_KTR_STRING, SLZ_KTR_ARGS);
 
 #define logslz(name, slz)              KTR_LOG(slz_ ## name, slz)
 #ifdef SMP
index 7ebfcb2..389d1f0 100644 (file)
 #define KTR_CTXSW KTR_ALL
 #endif
 KTR_INFO_MASTER(ctxsw);
-KTR_INFO(KTR_CTXSW, ctxsw, sw, 0, "#cpu[%d].td = %p",
-        sizeof(int) + sizeof(struct thread *));
-KTR_INFO(KTR_CTXSW, ctxsw, pre, 1, "#cpu[%d].td = %p",
-        sizeof(int) + sizeof(struct thread *));
-KTR_INFO(KTR_CTXSW, ctxsw, newtd, 2, "#threads[%p].name = %s",
-        sizeof (struct thread *) + sizeof(char *));
-KTR_INFO(KTR_CTXSW, ctxsw, deadtd, 3, "#threads[%p].name = <dead>", sizeof (struct thread *));
+KTR_INFO(KTR_CTXSW, ctxsw, sw, 0, "#cpu[%d].td = %p", int cpu, struct thread *td);
+KTR_INFO(KTR_CTXSW, ctxsw, pre, 1, "#cpu[%d].td = %p", int cpu, struct thread *td);
+KTR_INFO(KTR_CTXSW, ctxsw, newtd, 2, "#threads[%p].name = %s", struct thread *td, char *comm);
+KTR_INFO(KTR_CTXSW, ctxsw, deadtd, 3, "#threads[%p].name = <dead>", struct thread *td);
 
 static MALLOC_DEFINE(M_THREAD, "thread", "lwkt threads");
 
@@ -523,7 +520,7 @@ lwkt_set_comm(thread_t td, const char *ctl, ...)
     __va_start(va, ctl);
     kvsnprintf(td->td_comm, sizeof(td->td_comm), ctl, va);
     __va_end(va);
-    KTR_LOG(ctxsw_newtd, td, &td->td_comm[0]);
+    KTR_LOG(ctxsw_newtd, td, td->td_comm);
 }
 
 /*
index 3149450..37ae5b9 100644 (file)
@@ -85,23 +85,24 @@ extern int lwkt_sched_debug;
 static lwkt_token      pool_tokens[LWKT_NUM_POOL_TOKENS];
 
 #define TOKEN_STRING   "REF=%p TOK=%p TD=%p"
-#define CONTENDED_STRING       "REF=%p TOK=%p TD=%p (contention started)"
-#define UNCONTENDED_STRING     "REF=%p TOK=%p TD=%p (contention stopped)"
+#define TOKEN_ARGS     lwkt_tokref_t ref, lwkt_token_t tok, struct thread *td
+#define CONTENDED_STRING       TOKEN_STRING " (contention started)"
+#define UNCONTENDED_STRING     TOKEN_STRING " (contention stopped)"
 #if !defined(KTR_TOKENS)
 #define        KTR_TOKENS      KTR_ALL
 #endif
 
 KTR_INFO_MASTER(tokens);
-KTR_INFO(KTR_TOKENS, tokens, fail, 0, TOKEN_STRING, sizeof(void *) * 3);
-KTR_INFO(KTR_TOKENS, tokens, succ, 1, TOKEN_STRING, sizeof(void *) * 3);
+KTR_INFO(KTR_TOKENS, tokens, fail, 0, TOKEN_STRING, TOKEN_ARGS);
+KTR_INFO(KTR_TOKENS, tokens, succ, 1, TOKEN_STRING, TOKEN_ARGS);
 #if 0
-KTR_INFO(KTR_TOKENS, tokens, release, 2, TOKEN_STRING, sizeof(void *) * 3);
-KTR_INFO(KTR_TOKENS, tokens, remote, 3, TOKEN_STRING, sizeof(void *) * 3);
-KTR_INFO(KTR_TOKENS, tokens, reqremote, 4, TOKEN_STRING, sizeof(void *) * 3);
-KTR_INFO(KTR_TOKENS, tokens, reqfail, 5, TOKEN_STRING, sizeof(void *) * 3);
-KTR_INFO(KTR_TOKENS, tokens, drain, 6, TOKEN_STRING, sizeof(void *) * 3);
-KTR_INFO(KTR_TOKENS, tokens, contention_start, 7, CONTENDED_STRING, sizeof(void *) * 3);
-KTR_INFO(KTR_TOKENS, tokens, contention_stop, 7, UNCONTENDED_STRING, sizeof(void *) * 3);
+KTR_INFO(KTR_TOKENS, tokens, release, 2, TOKEN_STRING, TOKEN_ARGS);
+KTR_INFO(KTR_TOKENS, tokens, remote, 3, TOKEN_STRING, TOKEN_ARGS);
+KTR_INFO(KTR_TOKENS, tokens, reqremote, 4, TOKEN_STRING, TOKEN_ARGS);
+KTR_INFO(KTR_TOKENS, tokens, reqfail, 5, TOKEN_STRING, TOKEN_ARGS);
+KTR_INFO(KTR_TOKENS, tokens, drain, 6, TOKEN_STRING, TOKEN_ARGS);
+KTR_INFO(KTR_TOKENS, tokens, contention_start, 7, CONTENDED_STRING, TOKEN_ARGS);
+KTR_INFO(KTR_TOKENS, tokens, contention_stop, 7, UNCONTENDED_STRING, TOKEN_ARGS);
 #endif
 
 #define logtoken(name, ref)                                            \
index 967a2af..07cfc6c 100644 (file)
@@ -175,32 +175,32 @@ struct ifnet              **ifindex2ifnet = NULL;
 static struct thread   ifnet_threads[MAXCPU];
 
 #define IFQ_KTR_STRING         "ifq=%p"
-#define IFQ_KTR_ARG_SIZE       (sizeof(void *))
+#define IFQ_KTR_ARGS   struct ifaltq *ifq
 #ifndef KTR_IFQ
 #define KTR_IFQ                        KTR_ALL
 #endif
 KTR_INFO_MASTER(ifq);
-KTR_INFO(KTR_IFQ, ifq, enqueue, 0, IFQ_KTR_STRING, IFQ_KTR_ARG_SIZE);
-KTR_INFO(KTR_IFQ, ifq, dequeue, 1, IFQ_KTR_STRING, IFQ_KTR_ARG_SIZE);
+KTR_INFO(KTR_IFQ, ifq, enqueue, 0, IFQ_KTR_STRING, IFQ_KTR_ARGS);
+KTR_INFO(KTR_IFQ, ifq, dequeue, 1, IFQ_KTR_STRING, IFQ_KTR_ARGS);
 #define logifq(name, arg)      KTR_LOG(ifq_ ## name, arg)
 
 #define IF_START_KTR_STRING    "ifp=%p"
-#define IF_START_KTR_ARG_SIZE  (sizeof(void *))
+#define IF_START_KTR_ARGS      struct ifnet *ifp
 #ifndef KTR_IF_START
 #define KTR_IF_START           KTR_ALL
 #endif
 KTR_INFO_MASTER(if_start);
 KTR_INFO(KTR_IF_START, if_start, run, 0,
-        IF_START_KTR_STRING, IF_START_KTR_ARG_SIZE);
+        IF_START_KTR_STRING, IF_START_KTR_ARGS);
 KTR_INFO(KTR_IF_START, if_start, sched, 1,
-        IF_START_KTR_STRING, IF_START_KTR_ARG_SIZE);
+        IF_START_KTR_STRING, IF_START_KTR_ARGS);
 KTR_INFO(KTR_IF_START, if_start, avoid, 2,
-        IF_START_KTR_STRING, IF_START_KTR_ARG_SIZE);
+        IF_START_KTR_STRING, IF_START_KTR_ARGS);
 KTR_INFO(KTR_IF_START, if_start, contend_sched, 3,
-        IF_START_KTR_STRING, IF_START_KTR_ARG_SIZE);
+        IF_START_KTR_STRING, IF_START_KTR_ARGS);
 #ifdef SMP
 KTR_INFO(KTR_IF_START, if_start, chase_sched, 4,
-        IF_START_KTR_STRING, IF_START_KTR_ARG_SIZE);
+        IF_START_KTR_STRING, IF_START_KTR_ARGS);
 #endif
 #define logifstart(name, arg)  KTR_LOG(if_start_ ## name, arg)
 
index 4c5a652..7103289 100644 (file)
@@ -180,15 +180,15 @@ SYSCTL_ULONG(_net_link_ether, OID_AUTO, input_requeue, CTLFLAG_RW,
 #endif
 
 #define ETHER_KTR_STR          "ifp=%p"
-#define ETHER_KTR_ARG_SIZE     (sizeof(void *))
+#define ETHER_KTR_ARGS struct ifnet *ifp
 #ifndef KTR_ETHERNET
 #define KTR_ETHERNET           KTR_ALL
 #endif
 KTR_INFO_MASTER(ether);
-KTR_INFO(KTR_ETHERNET, ether, chain_beg, 0, ETHER_KTR_STR, ETHER_KTR_ARG_SIZE);
-KTR_INFO(KTR_ETHERNET, ether, chain_end, 1, ETHER_KTR_STR, ETHER_KTR_ARG_SIZE);
-KTR_INFO(KTR_ETHERNET, ether, disp_beg, 2, ETHER_KTR_STR, ETHER_KTR_ARG_SIZE);
-KTR_INFO(KTR_ETHERNET, ether, disp_end, 3, ETHER_KTR_STR, ETHER_KTR_ARG_SIZE);
+KTR_INFO(KTR_ETHERNET, ether, chain_beg, 0, ETHER_KTR_STR, ETHER_KTR_ARGS);
+KTR_INFO(KTR_ETHERNET, ether, chain_end, 1, ETHER_KTR_STR, ETHER_KTR_ARGS);
+KTR_INFO(KTR_ETHERNET, ether, disp_beg, 2, ETHER_KTR_STR, ETHER_KTR_ARGS);
+KTR_INFO(KTR_ETHERNET, ether, disp_end, 3, ETHER_KTR_STR, ETHER_KTR_ARGS);
 #define logether(name, arg)    KTR_LOG(ether_ ## name, arg)
 
 /*
index 35d1e24..724806f 100644 (file)
@@ -370,16 +370,17 @@ userexit(struct lwp *lp)
 #define        KTR_KERNENTRY   KTR_ALL
 #endif
 KTR_INFO_MASTER(kernentry);
-KTR_INFO(KTR_KERNENTRY, kernentry, trap, 0, "pid=%d, tid=%d, trapno=%d, eva=%p",
-        sizeof(int) + sizeof(int) + sizeof(int) + sizeof(vm_offset_t));
-KTR_INFO(KTR_KERNENTRY, kernentry, trap_ret, 0, "pid=%d, tid=%d",
-        sizeof(int) + sizeof(int));
-KTR_INFO(KTR_KERNENTRY, kernentry, syscall, 0, "pid=%d, tid=%d, call=%d",
-        sizeof(int) + sizeof(int) + sizeof(int));
-KTR_INFO(KTR_KERNENTRY, kernentry, syscall_ret, 0, "pid=%d, tid=%d, err=%d",
-        sizeof(int) + sizeof(int) + sizeof(int));
-KTR_INFO(KTR_KERNENTRY, kernentry, fork_ret, 0, "pid=%d, tid=%d",
-        sizeof(int) + sizeof(int));
+KTR_INFO(KTR_KERNENTRY, kernentry, trap, 0,
+        "TRAP(pid %d, tid %d, trapno %d, eva %lu)",
+        pid_t pid, lwpid_t tid,  register_t trapno, vm_offset_t eva);
+KTR_INFO(KTR_KERNENTRY, kernentry, trap_ret, 0, "TRAP_RET(pid %d, tid %d)",
+        pid_t pid, lwpid_t tid);
+KTR_INFO(KTR_KERNENTRY, kernentry, syscall, 0, "SYSC(pid %d, tid %d, nr %d)",
+        pid_t pid, lwpid_t tid,  register_t trapno);
+KTR_INFO(KTR_KERNENTRY, kernentry, syscall_ret, 0, "SYSRET(pid %d, tid %d, err %d)",
+        pid_t pid, lwpid_t tid,  int err);
+KTR_INFO(KTR_KERNENTRY, kernentry, fork_ret, 0, "FORKRET(pid %d, tid %d)",
+        pid_t pid, lwpid_t tid);
 
 /*
  * Exception, fault, and trap interface to the kernel.
index 70c48c1..f74bc24 100644 (file)
@@ -356,16 +356,17 @@ userexit(struct lwp *lp)
 #define        KTR_KERNENTRY   KTR_ALL
 #endif
 KTR_INFO_MASTER(kernentry);
-KTR_INFO(KTR_KERNENTRY, kernentry, trap, 0, "STR",
-        sizeof(long) + sizeof(long) + sizeof(long) + sizeof(vm_offset_t));
-KTR_INFO(KTR_KERNENTRY, kernentry, trap_ret, 0, "STR",
-        sizeof(long) + sizeof(long));
-KTR_INFO(KTR_KERNENTRY, kernentry, syscall, 0, "STR",
-        sizeof(long) + sizeof(long) + sizeof(long));
-KTR_INFO(KTR_KERNENTRY, kernentry, syscall_ret, 0, "STR",
-        sizeof(long) + sizeof(long) + sizeof(long));
-KTR_INFO(KTR_KERNENTRY, kernentry, fork_ret, 0, "STR",
-        sizeof(long) + sizeof(long));
+KTR_INFO(KTR_KERNENTRY, kernentry, trap, 0,
+        "TRAP(pid %hd, tid %hd, trapno %ld, eva %lu)",
+        pid_t pid, lwpid_t tid,  register_t trapno, vm_offset_t eva);
+KTR_INFO(KTR_KERNENTRY, kernentry, trap_ret, 0, "TRAP_RET(pid %hd, tid %hd)",
+        pid_t pid, lwpid_t tid);
+KTR_INFO(KTR_KERNENTRY, kernentry, syscall, 0, "SYSC(pid %hd, tid %hd, nr %ld)",
+        pid_t pid, lwpid_t tid,  register_t trapno);
+KTR_INFO(KTR_KERNENTRY, kernentry, syscall_ret, 0, "SYSRET(pid %hd, tid %hd, err %d)",
+        pid_t pid, lwpid_t tid,  int err);
+KTR_INFO(KTR_KERNENTRY, kernentry, fork_ret, 0, "FORKRET(pid %hd, tid %hd)",
+        pid_t pid, lwpid_t tid);
 
 /*
  * Exception, fault, and trap interface to the kernel.
index 48b1ad3..8becde3 100644 (file)
 #ifndef _SYS_KTR_H_
 #define        _SYS_KTR_H_
 
-#ifndef _SYS_TYPES_H_
 #include <sys/types.h>
-#endif
-#ifndef _SYS_SYSCTL_H_
 #include <sys/sysctl.h>
-#endif
+#include <sys/cpputil.h>
 
 #ifdef _KERNEL
 #include "opt_ktr.h"
@@ -74,7 +71,7 @@
 struct ktr_info {
        const char *kf_name;    /* human-interpreted subsystem name */
        int32_t *kf_master_enable; /* the master enable variable */
-       const char *kf_format;  /* data format */
+       const char * const kf_format;   /* data format */
        int kf_data_size;       /* relevance of the data buffer */
 };
 
@@ -101,7 +98,9 @@ struct ktr_cpu {
 
 #ifdef _KERNEL
 
-void   ktr_log(struct ktr_info *info, const char *file, int line, ...);
+struct ktr_entry * ktr_begin_write_entry(struct ktr_info *,
+                                        const char *, int);
+int ktr_finish_write_entry(struct ktr_info *, struct ktr_entry *);
 void    cpu_ktr_caller(struct ktr_entry *ktr);
 
 #endif
@@ -132,27 +131,71 @@ SYSCTL_DECL(_debug_ktr);
  * definitions are and a number of static const int's which are used
  * by the compiler to optimize the trace logging at compile-time and
  * run-time.
+ * You're supposed to specify any arguments to the format as you would in
+ * a function prototype.
+ * We automagically create a struct for the arguments and a throwaway
+ * function that will be called with the format and the actual arguments
+ * at the KTR_LOG site. This makes sure that the compiler will typecheck
+ * the arguments against the format string. On gcc, this requires -Wformat
+ * (which is included in -Wall) and -O1 at least. Note that using
+ * ktr_info.kf_format will not work, hence we need to define another
+ * throwaway const wariable for the format.
  */
-#define KTR_INFO(compile, master, name, maskbit, format, datasize)     \
-           static const int ktr_ ## master ## _ ## name ## _mask =     \
-               1 << maskbit;                                           \
-           static const int ktr_ ## master ## _ ## name ## _enable =   \
+#define KTR_INFO(compile, master, name, maskbit, format, ...)          \
+       static const int ktr_ ## master ## _ ## name ## _mask =         \
+               1 << (maskbit);                                         \
+       static const int ktr_ ## master ## _ ##name ## _enable =        \
                compile;                                                \
-           static int ktr_ ## master ## _ ## name ## _mask_ro =        \
-               1 << maskbit;                                           \
-           SYSCTL_INT(_debug_ktr_ ## master, OID_AUTO, name ## _mask,  \
-               CTLFLAG_RD, &ktr_ ## master ## _ ## name ## _mask_ro,   \
-               0, "Value of the " __XSTRING(name) " event in " __XSTRING(master) "'s mask"); \
-           static struct ktr_info ktr_info_ ## master ## _ ## name = { \
-               #master "_" #name,                                      \
-               &ktr_ ## master ## _enable,                             \
-               format,                                                 \
-               datasize }
-
-#define KTR_LOG(name, args...)                                         \
-           if (ktr_ ## name ## _enable &&                              \
-             (ktr_ ## name ## _mask & *ktr_info_ ## name .kf_master_enable)) \
-           ktr_log(&ktr_info_ ## name, __FILE__, __LINE__, ##args)
+       static int ktr_ ## master ## _ ## name ## _mask_ro =            \
+               1 << (maskbit);                                         \
+       SYSCTL_INT(_debug_ktr_ ## master, OID_AUTO, name ## _mask,      \
+                  CTLFLAG_RD, &ktr_ ## master ## _ ## name ## _mask_ro, \
+                  0, "Value of the " __XSTRING(name) " event in " __XSTRING(master) "'s mask"); \
+       __GENSTRUCT(ktr_info_ ## master ## _ ## name ## _args, __VA_ARGS__) \
+               __packed;                                               \
+       CTASSERT(sizeof(struct ktr_info_ ## master ## _ ## name ## _args) <= KTR_BUFSIZE); \
+       static inline void                                              \
+       __ktr_info_ ## master ## _ ## name ## _fmtcheck(const char *fmt, \
+                                                       ...) __printf0like(1, 2); \
+       static inline void                                              \
+       __ktr_info_ ## master ## _ ## name ## _fmtcheck(const char *fmt __unused, \
+                                                       ...)            \
+       {}                                                              \
+       static const char * const __ktr_ ## master ## _ ## name ## _fmt = format; \
+       static struct ktr_info ktr_info_ ## master ## _ ## name = {     \
+               .kf_name = #master "_" #name,                           \
+               .kf_master_enable = &ktr_ ## master ## _enable,         \
+               .kf_format = format,                                    \
+               .kf_data_size = sizeof(struct ktr_info_ ## master ## _ ## name ## _args), \
+       }
+
+
+
+
+/*
+ * Call ktr_begin_write_entry() that sets up the entry for us; use
+ * a struct copy to give as max flexibility as possible to the compiler.
+ * In higher optimization levels, it will copy the arguments directly from
+ * registers to the destination buffer. Call our dummy function that will
+ * typecheck the arguments against the format string.
+ */
+#define KTR_LOG(name, ...)                                             \
+       do {                                                            \
+               __ktr_info_ ## name ## _fmtcheck (__ktr_ ## name ## _fmt, ##__VA_ARGS__);       \
+               if (ktr_ ## name ## _enable &&                          \
+                   (ktr_ ## name ## _mask & *ktr_info_ ## name .kf_master_enable)) { \
+                       struct ktr_entry *entry;                        \
+                       entry = ktr_begin_write_entry(&ktr_info_ ## name, __FILE__, __LINE__); \
+                       if (!entry)                                     \
+                               break;                                  \
+                       *(struct ktr_info_  ## name ## _args *)&entry->ktr_data[0] = \
+                               (struct ktr_info_  ## name ## _args){ __VA_ARGS__}; \
+                       if (ktr_finish_write_entry(&ktr_info_ ## name, entry)) { \
+                               kprintf(ktr_info_ ## name .kf_format, ##__VA_ARGS__); \
+                               kprintf("\n");                          \
+                       }                                               \
+               }                                                       \
+       }  while(0)
 
 #else
 
@@ -162,9 +205,9 @@ SYSCTL_DECL(_debug_ktr);
 #define KTR_INFO_MASTER_EXTERN(master)                                 \
            static const int ktr_ ## master ## _enable
 
-#define KTR_INFO(compile, master, name, maskbit, format, datasize)     \
+#define KTR_INFO(compile, master, name, maskbit, format, ...)          \
            static const int ktr_ ## master ## _ ## name ## _mask =     \
-               1 << maskbit
+                   (1 << maskbit)
 
 #define KTR_LOG(info, args...)