From 1db5d376901b2c1b225f0424a40f99bd456da8bc Mon Sep 17 00:00:00 2001 From: Kris Van Hees Date: Thu, 7 Feb 2013 16:30:08 -0500 Subject: [PATCH] Adding more compile time debugging for development. This patch expands the developer debugging coverage, adding more (compile time enabled) debugging statements that can help during DTrace kernel side bug hunting. Signed-off-by: Kris Van Hees --- dtrace/dtrace_buffer.c | 28 +++++++++++-- dtrace/dtrace_debug.h | 4 +- dtrace/dtrace_dev.c | 2 + dtrace/dtrace_probe.c | 87 ++++++++++++++++++++++++++++++++++++--- dtrace/dtrace_probe_ctx.c | 10 +++++ 5 files changed, 120 insertions(+), 11 deletions(-) diff --git a/dtrace/dtrace_buffer.c b/dtrace/dtrace_buffer.c index 595216732732..9722f860b8d4 100644 --- a/dtrace/dtrace_buffer.c +++ b/dtrace/dtrace_buffer.c @@ -49,6 +49,10 @@ void dtrace_buffer_switch(dtrace_buffer_t *buf) local_irq_save(cookie); + dt_dbg_buf("Switch (CPU %d): tomax %p (%lld) <-> xamot %p (%lld)\n", + smp_processor_id(), tomax, buf->dtb_offset, + xamot, buf->dtb_xamot_offset ); + buf->dtb_tomax = xamot; buf->dtb_xamot = tomax; buf->dtb_xamot_drops = buf->dtb_drops; @@ -197,6 +201,10 @@ intptr_t dtrace_buffer_reserve(dtrace_buffer_t *buf, size_t needed, ASSERT(!((align - (offs & (align - 1))) & (sizeof (uint32_t) - 1))); DTRACE_STORE(uint32_t, tomax, offs, DTRACE_EPIDNONE); + dt_dbg_buf(" Store: %p[%ld .. %ld] <- EPIDNONE " + "(from %s::%d)\n", + buf, offs, offs + sizeof(uint32_t) - 1, + __FUNCTION__, __LINE__); offs += sizeof (uint32_t); } @@ -205,13 +213,18 @@ intptr_t dtrace_buffer_reserve(dtrace_buffer_t *buf, size_t needed, return -1; } - if (mstate == NULL) - return (offs); + if (mstate == NULL) { + dt_dbg_buf(" Reserve: %p[%ld .. %ld]\n", + buf, offs, offs + needed - 1); + return offs; + } mstate->dtms_scratch_base = (uintptr_t)tomax + soffs; mstate->dtms_scratch_size = buf->dtb_size - soffs; mstate->dtms_scratch_ptr = mstate->dtms_scratch_base; + dt_dbg_buf(" Reserve: %p[%ld .. %ld]\n", + buf, offs, offs + needed - 1); return offs; } @@ -378,6 +391,10 @@ out: ASSERT(!((align - (offs & (align - 1))) & (sizeof (uint32_t) - 1))); DTRACE_STORE(uint32_t, tomax, offs, DTRACE_EPIDNONE); + dt_dbg_buf(" Store: %p[%ld .. %ld] <- EPIDNONE " + "(from %s::%d)\n", + buf, offs, offs + sizeof(uint32_t) - 1, + __FUNCTION__, __LINE__); offs += sizeof (uint32_t); } @@ -388,8 +405,11 @@ out: } } - if (mstate == NULL) + if (mstate == NULL) { + dt_dbg_buf(" Reserve: %p[%ld .. %ld]\n", + buf, offs, offs + needed - 1); return offs; + } /* * For ring buffers and fill buffers, the scratch space is always @@ -399,6 +419,8 @@ out: mstate->dtms_scratch_size = buf->dtb_size; mstate->dtms_scratch_ptr = mstate->dtms_scratch_base; + dt_dbg_buf(" Reserve: %p[%ld .. %ld]\n", + buf, offs, offs + needed - 1); return offs; } diff --git a/dtrace/dtrace_debug.h b/dtrace/dtrace_debug.h index 9040494e1cd2..a8cd96972f03 100644 --- a/dtrace/dtrace_debug.h +++ b/dtrace/dtrace_debug.h @@ -5,8 +5,8 @@ # undef DT_DBG_AGG # undef DT_DBG_BUF -# define DT_DBG_DOF -# define DT_DBG_IOCTL +# undef DT_DBG_DOF +# undef DT_DBG_IOCTL # undef DT_DBG_PROBE #else /* CONFIG_DT_DEBUG */ diff --git a/dtrace/dtrace_dev.c b/dtrace/dtrace_dev.c index f681ffe9afe4..cb9686c11900 100644 --- a/dtrace/dtrace_dev.c +++ b/dtrace/dtrace_dev.c @@ -166,6 +166,8 @@ static long dtrace_ioctl(struct file *file, state = state->dts_anon; } + dt_dbg_ioctl("IOCTL (%#x, argp %p) ...\n", cmd, argp); + switch (cmd) { case DTRACEIOC_PROVIDER: { dtrace_providerdesc_t pvd; diff --git a/dtrace/dtrace_probe.c b/dtrace/dtrace_probe.c index 61481f159132..0a6cb394a61b 100644 --- a/dtrace/dtrace_probe.c +++ b/dtrace/dtrace_probe.c @@ -663,6 +663,8 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1, } } + dt_dbg_probe("Probe (ID %d EPID %d) on CPU %d...\n", + id, ecb->dte_epid, cpuid); if (ecb->dte_cond) { /* * If the dte_cond bits indicate that this @@ -742,8 +744,13 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1, tomax = buf->dtb_tomax; ASSERT(tomax != NULL); - if (ecb->dte_size != 0) + if (ecb->dte_size != 0) { DTRACE_STORE(uint32_t, tomax, offs, ecb->dte_epid); + dt_dbg_buf(" Store: %p[%ld .. %ld] <- %d [EPID] " + "(from %s::%d)\n", + buf, offs, offs + sizeof(uint32_t) - 1, + ecb->dte_epid, __FUNCTION__, __LINE__); + } mstate.dtms_epid = ecb->dte_epid; mstate.dtms_present |= DTRACE_MSTATE_EPID; @@ -771,6 +778,9 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1, current->predcache = cid; } + dt_dbg_probe("Probe (ID %d EPID %d) " + "Predicate not satisfied (%d)\n", + id, ecb->dte_epid, rval); continue; } } @@ -782,6 +792,9 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1, dtrace_difo_t *dp; dtrace_recdesc_t *rec = &act->dta_rec; + dt_dbg_probe("Probe (ID %d EPID %d) Action %d...\n", + id, ecb->dte_epid, act->dta_kind); + size = rec->dtrd_size; valoffs = offs + rec->dtrd_offset; @@ -922,9 +935,17 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1, tomax = buf->dtb_tomax; ASSERT(tomax != NULL); - if (ecb->dte_size != 0) + if (ecb->dte_size != 0) { DTRACE_STORE(uint32_t, tomax, offs, ecb->dte_epid); + dt_dbg_buf(" Store: %p[%ld .. %ld] " + "<- %d [EPID] " + "(from %s::%d)\n", + buf, offs, + offs + sizeof(uint32_t) - 1, + ecb->dte_epid, + __FUNCTION__, __LINE__); + } continue; @@ -947,8 +968,13 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1, /* * We need to commit our buffer state. */ - if (ecb->dte_size) + if (ecb->dte_size) { buf->dtb_offset = offs + ecb->dte_size; + dt_dbg_buf(" Consume: %p[%ld .. " + "%lld]\n", + buf, offs, + buf->dtb_offset - 1); + } buf = &state->dts_buffer[cpuid]; dtrace_speculation_commit(state, cpuid, val); @@ -983,8 +1009,19 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1, DTRACE_STORE(uint64_t, tomax, valoffs, (uint64_t)pid); + dt_dbg_buf(" Store: %p[%ld .. %ld] <- %lld " + "[PID] (from %s::%d)\n", + buf, valoffs, + valoffs + sizeof(uint64_t) - 1, + (uint64_t)pid, + __FUNCTION__, __LINE__); DTRACE_STORE(uint64_t, tomax, valoffs + sizeof(uint64_t), val); + dt_dbg_buf(" Store: %p[%ld .. %ld] <- %lld " + "(from %s::%d)\n", + buf, valoffs + sizeof(uint64_t), + valoffs + 2 * sizeof(uint64_t) - 1, + val, __FUNCTION__, __LINE__); continue; } @@ -1054,6 +1091,12 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1, DTRACE_STORE(uint8_t, tomax, valoffs++, c); + dt_dbg_buf(" Store: %p[%ld]" + " <- %d (from " + "%s::%d)\n", + buf, valoffs, c, + __FUNCTION__, + __LINE__); if (c == '\0' && intuple) break; @@ -1062,9 +1105,14 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1, continue; } - while (valoffs < end) + while (valoffs < end) { DTRACE_STORE(uint8_t, tomax, valoffs++, dtrace_load8(val++)); + dt_dbg_buf(" Store: %p[%ld] <- ??? " + "(from %s::%d)\n", + buf, valoffs, + __FUNCTION__, __LINE__); + } continue; } @@ -1074,15 +1122,36 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1, break; case sizeof(uint8_t): DTRACE_STORE(uint8_t, tomax, valoffs, val); + dt_dbg_buf(" Store: %p[%ld] <- %d " + "(from %s::%d)\n", + buf, valoffs, (uint8_t)val, + __FUNCTION__, __LINE__); break; case sizeof(uint16_t): DTRACE_STORE(uint16_t, tomax, valoffs, val); + dt_dbg_buf(" Store: %p[%ld .. %ld] <- %d " + "(from %s::%d)\n", + buf, valoffs, + valoffs + sizeof(uint16_t) - 1, + (uint16_t)val, + __FUNCTION__, __LINE__); break; case sizeof(uint32_t): DTRACE_STORE(uint32_t, tomax, valoffs, val); + dt_dbg_buf(" Store: %p[%ld] <- %d " + "(from %s::%d)\n", + buf, valoffs, + valoffs + sizeof(uint32_t) - 1, + (uint32_t)val, + __FUNCTION__, __LINE__); break; case sizeof(uint64_t): DTRACE_STORE(uint64_t, tomax, valoffs, val); + dt_dbg_buf(" Store: %p[%ld] <- %d " + "(from %s::%d)\n", + buf, valoffs, + valoffs + sizeof(uint64_t) - 1, val, + __FUNCTION__, __LINE__); break; default: /* @@ -1094,8 +1163,11 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1, } } - if (*flags & CPU_DTRACE_DROP) + if (*flags & CPU_DTRACE_DROP) { + dt_dbg_probe("Probe (ID %d EPID %d) Dropped\n", + id, ecb->dte_epid); continue; + } if (*flags & CPU_DTRACE_FAULT) { int ndx; @@ -1146,8 +1218,11 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1, continue; } - if (!committed) + if (!committed) { buf->dtb_offset = offs + ecb->dte_size; + dt_dbg_buf(" Consume: %p[%ld .. %lld]\n", + buf, offs, buf->dtb_offset); + } } if (vtime) diff --git a/dtrace/dtrace_probe_ctx.c b/dtrace/dtrace_probe_ctx.c index 6d543e527044..85e954b565cf 100644 --- a/dtrace/dtrace_probe_ctx.c +++ b/dtrace/dtrace_probe_ctx.c @@ -475,6 +475,11 @@ void dtrace_aggregate(dtrace_aggregation_t *agg, dtrace_buffer_t *dbuf, * This is a hit: we need to apply the aggregator to * the value at this key. */ + dt_dbg_agg(" Aggregate [accum]: Buf %p, offs %lld, act %d, " + "%lld (%lld, %lld)\n", + buf, size, + agg->dtag_action.dta_kind - DTRACEACT_AGGREGATION, + *(uint64_t *)(kdata + size), expr, arg); agg->dtag_aggregate((uint64_t *)(kdata + size), expr, arg); return; next: @@ -556,5 +561,10 @@ next: * Finally, apply the aggregator. */ *((uint64_t *)(key->dtak_data + size)) = agg->dtag_initial; + dt_dbg_agg(" Aggregate [initial]: Buf %p, offs %lld, act %d, " + "%lld (%lld, %lld)\n", + buf, size, + agg->dtag_action.dta_kind - DTRACEACT_AGGREGATION, + *(uint64_t *)(key->dtak_data + size), expr, arg); agg->dtag_aggregate((uint64_t *)(key->dtak_data + size), expr, arg); } -- 2.50.1