From: Kris Van Hees Date: Tue, 9 Jun 2015 05:09:59 +0000 (-0400) Subject: dtrace: improve debugging output X-Git-Tag: v4.1.12-111.0.20170907_2225~3^2~3^2~69 X-Git-Url: https://www.infradead.org/git/?a=commitdiff_plain;h=a06dbea585d4b50eef09d60113be4d4163a364fa;p=users%2Fjedix%2Flinux-maple.git dtrace: improve debugging output This commit adds debugging output (to be enabled at compile time) for DIF execution. Signed-off-by: Kris Van Hees Acked-by: Nick Alcock --- diff --git a/dtrace/dtrace_debug.h b/dtrace/dtrace_debug.h index 4f6d839900e48..81d04650cbe18 100644 --- 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 33c7e197e975b..d09e17d8b78d4 100644 --- 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 f287f8a6f22f5..4207fcea2b815 100644 --- 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 05c7359525638..854f463b6ad95 100644 --- 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)