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 <kris.van.hees@oracle.com>

diff --git a/dtrace/dtrace_buffer.c b/dtrace/dtrace_buffer.c
index 59521673273289040e66f6181221f8edb6366bc4..9722f860b8d4aee702db2d3a2d2f7ca402838131 100644 (file)
--- 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 9040494e1cd2f75af77051b7b5e02ffb9aaacae6..a8cd96972f03ef120656ea69ee59f29bad445199 100644 (file)
--- 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 f681ffe9afe452ab4b6275341a75ee29ad83f155..cb9686c1190061737880edc57019d144ebf433b9 100644 (file)
--- 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 61481f1591325ebf1240e26a37a386f554ddad3b..0a6cb394a61bebbc97a815e4bfde7faade75438b 100644 (file)
--- 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 6d543e527044c35cdf6a125b6ac8c59934ee5fc8..85e954b565cfe80a4fabeba0f12f257ac6cff951 100644 (file)
--- 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);
 }