dtrace: improve debugging output

This commit adds debugging output (to be enabled at compile time) for
DIF execution.

Signed-off-by: Kris Van Hees <kris.van.hees@oracle.com>
Acked-by: Nick Alcock <nick.alcock@oracle.com>

diff --git a/dtrace/dtrace_debug.h b/dtrace/dtrace_debug.h
index 4f6d839900e48343fd1a3718df764159108ee840..81d04650cbe187e84e058017ad525c1986decfd5 100644 (file)
--- a/dtrace/dtrace_debug.h
+++ b/dtrace/dtrace_debug.h
@@ -5,6 +5,7 @@
 
 # undef DT_DBG_AGG
 # undef DT_DBG_BUF
+# undef DT_DBG_DIF
 # undef DT_DBG_DOF
 # undef DT_DBG_ENABLE
 # undef DT_DBG_IOCTL
@@ -15,6 +16,7 @@
 
 # undef DT_DBG_AGG
 # undef DT_DBG_BUF
+# undef DT_DBG_DIF
 # undef DT_DBG_DOF
 # undef DT_DBG_ENABLE
 # undef DT_DBG_IOCTL
@@ -38,6 +40,12 @@
 # define dt_dbg_buf(fmt, ...)
 #endif
 
+#ifdef DT_DBG_DIF
+# define dt_dbg_dif(fmt, ...)          pr_info(fmt, ## __VA_ARGS__)
+#else
+# define dt_dbg_dif(fmt, ...)
+#endif
+
 #ifdef DT_DBG_DOF
 # define dt_dbg_dof(fmt, ...)          pr_info(fmt, ## __VA_ARGS__)
 #else

diff --git a/dtrace/dtrace_dif.c b/dtrace/dtrace_dif.c
index 33c7e197e975b607fe8da350eff9f0e1d91b1432..d09e17d8b78d4a9bab6e98c2d2d8edb825038475 100644 (file)
--- a/dtrace/dtrace_dif.c
+++ b/dtrace/dtrace_dif.c
@@ -2378,6 +2378,8 @@ static void dtrace_dif_subr(uint_t subr, uint_t rd, uint64_t *regs,
                uintptr_t rw;
        } r;
 
+       dt_dbg_dif("        Subroutine %d\n", subr);
+
        switch (subr) {
        case DIF_SUBR_RAND:
                regs[rd] = ktime_to_ns(dtrace_gethrtime()) * 2416 + 374441;
@@ -3927,6 +3929,9 @@ uint64_t dtrace_dif_emulate(dtrace_difo_t *difo, dtrace_mstate_t *mstate,
        dif_instr_t             instr;
        uint_t                  r1, r2, rd;
 
+       dt_dbg_dif("    DIF %p emulation (text %p, %d instructions)...\n",
+                  difo, text, textlen);
+
        /*
         * We stash the current DIF object into the machine state: we need it
         * for subsequent access checking.
@@ -3943,6 +3948,9 @@ uint64_t dtrace_dif_emulate(dtrace_difo_t *difo, dtrace_mstate_t *mstate,
                r2 = DIF_INSTR_R2(instr);
                rd = DIF_INSTR_RD(instr);
 
+               dt_dbg_dif("      Executing opcode %d (%d, %d, %d)\n",
+                          DIF_INSTR_OP(instr), r1, r2, rd);
+
                switch (DIF_INSTR_OP(instr)) {
                case DIF_OP_OR:
                        regs[rd] = regs[r1] | regs[r2];
@@ -4749,8 +4757,14 @@ uint64_t dtrace_dif_emulate(dtrace_difo_t *difo, dtrace_mstate_t *mstate,
                }
        }
 
-       if (!(*flags & CPU_DTRACE_FAULT))
+
+       if (!(*flags & CPU_DTRACE_FAULT)) {
+               dt_dbg_dif("    DIF %p completed, rval = %llx (flags %x)\n",
+                          difo, rval, *flags);
                return rval;
+       }
+
+       dt_dbg_dif("    DIF %p emulation failed (flags %x)\n",  difo, *flags);
 
        mstate->dtms_fltoffs = opc * sizeof(dif_instr_t);
        mstate->dtms_present |= DTRACE_MSTATE_FLTOFFS;

diff --git a/dtrace/dtrace_dof.c b/dtrace/dtrace_dof.c
index f287f8a6f22f563c9120d57c7ad507f741a8433c..4207fcea2b8154956953a1f6d09bf998ac5a4197 100644 (file)
--- a/dtrace/dtrace_dof.c
+++ b/dtrace/dtrace_dof.c
@@ -338,7 +338,7 @@ static dtrace_probedesc_t *dtrace_dof_probedesc(dof_hdr_t *dof, dof_sec_t *sec,
        strncpy(desc->dtpd_name, (char *)(str + probe->dofp_name),
                min((size_t)DTRACE_NAMELEN - 1, size - probe->dofp_name));
 
-       dt_dbg_dof("    ECB Probe %s:%s:%s:%s\n",
+       dt_dbg_dof("      ECB Probe %s:%s:%s:%s\n",
                   desc->dtpd_provider, desc->dtpd_mod, desc->dtpd_func,
                   desc->dtpd_name);
 
@@ -1053,8 +1053,10 @@ int dtrace_dof_slurp(dof_hdr_t *dof, dtrace_vstate_t *vstate, const cred_t *cr,
        if ((enab = *enabp) == NULL)
                enab = *enabp = dtrace_enabling_create(vstate);
 
-       if (enab == NULL)
+       if (enab == NULL) {
+               dt_dbg_dof("  DOF 0x%p Done slurping - no enablings\n", dof);
                return -1;
+       }
 
        for (i = 0; i < dof->dofh_secnum; i++) {
                dof_sec_t       *sec =
@@ -1066,6 +1068,8 @@ int dtrace_dof_slurp(dof_hdr_t *dof, dtrace_vstate_t *vstate, const cred_t *cr,
                        continue;
 
                if ((ep = dtrace_dof_ecbdesc(dof, sec, vstate, cr)) == NULL) {
+                       dt_dbg_dof("  DOF 0x%p Done slurping - ECB problem\n",
+                                  dof);
                        dtrace_enabling_destroy(enab);
                        *enabp = NULL;
                        return -1;
@@ -1074,6 +1078,9 @@ int dtrace_dof_slurp(dof_hdr_t *dof, dtrace_vstate_t *vstate, const cred_t *cr,
                dtrace_enabling_add(enab, ep);
        }
 
+       dt_dbg_dof("    DOF 0x%p Enablings processed\n", dof);
+       dt_dbg_dof("  DOF 0x%p Done slurping\n", dof);
+
        return 0;
 }
 

diff --git a/dtrace/dtrace_probe.c b/dtrace/dtrace_probe.c
index 05c7359525638af10e703ac31c0e909a6271bee2..854f463b6ad9570fa2a1cec1c30b5bf20352d687 100644 (file)
--- a/dtrace/dtrace_probe.c
+++ b/dtrace/dtrace_probe.c
@@ -791,6 +791,8 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1,
                        dtrace_difo_t   *dp = pred->dtp_difo;
                        int             rval;
 
+                       dt_dbg_probe("  Evaluating predicate...\n");
+
                        rval = dtrace_dif_emulate(dp, &mstate, vstate, state);
 
                        if (!(*flags & CPU_DTRACE_ERROR) && !rval) {
@@ -805,11 +807,12 @@ 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);
+                               dt_dbg_probe("  Predicate not met (%d)\n",
+                                            rval);
                                continue;
                        }
+
+                       dt_dbg_probe("  Predicate met (%d)\n", rval);
                }
 
                for (act = ecb->dte_action;
@@ -819,8 +822,8 @@ 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);
+                       dt_dbg_probe("  Evaluating action %p (kind %d)...\n",
+                                   act, act->dta_kind);
 
                        size = rec->dtrd_size;
                        valoffs = offs + rec->dtrd_offset;
@@ -1199,8 +1202,7 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1,
                }
 
                if (*flags & CPU_DTRACE_DROP) {
-                       dt_dbg_probe("Probe (ID %d EPID %d) Dropped\n",
-                                    id, ecb->dte_epid);
+                       dt_dbg_probe("  -> Dropped\n");
                        continue;
                }
 
@@ -1208,6 +1210,8 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1,
                        int             ndx;
                        dtrace_action_t *err;
 
+                       dt_dbg_probe("  -> Failed (%x)\n", *flags);
+
                        buf->dtb_errors++;
 
                        if (probe->dtpr_id == dtrace_probeid_error) {
@@ -1258,6 +1262,9 @@ void dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1,
                        dt_dbg_buf("  Consume: %p[%ld .. %lld]\n",
                                   buf, offs, buf->dtb_offset);
                }
+
+               dt_dbg_probe("Probe (ID %d EPID %d) Done\n",
+                            id, ecb->dte_epid);
        }
 
        if (vtime)