d/freebsd-dev
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Add BUF_TRACKING and FULL_BUF_TRACKING buffer debugging

Browse Source 
Upstream the BUF_TRACKING and FULL_BUF_TRACKING buffer debugging code.
This can be handy in tracking down what code touched hung bios and bufs
last. The full history is especially useful, but adds enough bloat that
it shouldn't be enabled in release builds.

Function names (or arbitrary string constants) are tracked in a
fixed-size ring in bufs. Bios gain a pointer to the upper buf for
tracking. SCSI CCBs gain a pointer to the upper bio for tracking.

Reviewed by:	markj
Sponsored by:	Dell EMC Isilon
Differential Revision:	https://reviews.freebsd.org/D8366
This commit is contained in:
Conrad Meyer 2016-10-31 23:09:52 +00:00
parent 2d5386cc2c
commit 8532d381a9
Notes: svn2git 2020-12-20 02:59:44 +00:00 
svn path=/head/; revision=308155
19 changed files with 157 additions and 0 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
sys/amd64/conf/GENERIC
View File

@ -83,7 +83,9 @@ options RCTL # Resource limits
options KDB # Enable kernel debugger support.
options KDB_TRACE # Print a stack trace for a panic.
# For full debugger support use (turn off in stable branch):
options BUF_TRACKING # Track buffer history
options DDB # Support DDB.
options FULL_BUF_TRACKING # Track more buffer history
options GDB # Support remote GDB.
options DEADLKRES # Enable the deadlock resolver
options INVARIANTS # Enable calls of extra sanity checking

2
sys/amd64/conf/GENERIC-NODEBUG
View File

@ -34,5 +34,7 @@ nooptions INVARIANTS
nooptions INVARIANT_SUPPORT
nooptions WITNESS
nooptions WITNESS_SKIPSPIN
nooptions BUF_TRACKING
nooptions DEADLKRES
nooptions FULL_BUF_TRACKING

6
sys/cam/cam_ccb.h
View File

@ -744,6 +744,9 @@ struct ccb_scsiio {
#define CAM_TAG_ACTION_NONE 0x00
u_int tag_id; /* tag id from initator (target mode) */
u_int init_id; /* initiator id of who selected */
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
struct bio *bio; /* Associated bio */
#endif
};
static __inline uint8_t *
@ -1335,6 +1338,9 @@ cam_fill_csio(struct ccb_scsiio *csio, u_int32_t retries,
csio->sense_len = sense_len;
csio->cdb_len = cdb_len;
csio->tag_action = tag_action;
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
csio->bio = NULL;
#endif
}
static __inline void

5
sys/cam/cam_periph.c
View File

@ -1427,6 +1427,11 @@ camperiphscsisenseerror(union ccb *ccb, union ccb **orig,
union ccb *orig_ccb = ccb;
int error, recoveryccb;
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
if (ccb->ccb_h.func_code == XPT_SCSI_IO && ccb->csio.bio != NULL)
biotrack(ccb->csio.bio, __func__);
#endif
periph = xpt_path_periph(ccb->ccb_h.path);
recoveryccb = (ccb->ccb_h.cbfcnp == camperiphdone);
if ((periph->flags & CAM_PERIPH_RECOVERY_INPROG) && !recoveryccb) {

17
sys/cam/cam_xpt.c
View File

@ -31,6 +31,7 @@
__FBSDID("$FreeBSD$");
#include <sys/param.h>
#include <sys/bio.h>
#include <sys/bus.h>
#include <sys/systm.h>
#include <sys/types.h>
@ -4471,6 +4472,12 @@ xpt_done(union ccb *done_ccb)
struct cam_doneq *queue;
int run, hash;
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
if (done_ccb->ccb_h.func_code == XPT_SCSI_IO &&
done_ccb->csio.bio != NULL)
biotrack(done_ccb->csio.bio, __func__);
#endif
CAM_DEBUG(done_ccb->ccb_h.path, CAM_DEBUG_TRACE,
("xpt_done: func= %#x %s status %#x\n",
done_ccb->ccb_h.func_code,
@ -5189,6 +5196,16 @@ xpt_done_process(struct ccb_hdr *ccb_h)
struct cam_devq *devq;
struct mtx *mtx = NULL;
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
struct ccb_scsiio *csio;
if (ccb_h->func_code == XPT_SCSI_IO) {
csio = &((union ccb *)ccb_h)->csio;
if (csio->bio != NULL)
biotrack(csio->bio, __func__);
}
#endif
if (ccb_h->flags & CAM_HIGH_POWER) {
struct highpowerlist *hphead;
struct cam_ed *device;

15
sys/cam/scsi/scsi_da.c
View File

@ -2949,6 +2949,8 @@ dastart(struct cam_periph *periph, union ccb *start_ccb)
void *data_ptr;
int rw_op;
biotrack(bp, __func__);
if (bp->bio_cmd == BIO_WRITE) {
softc->flags |= DA_FLAG_DIRTY;
rw_op = SCSI_RW_WRITE;
@ -2976,6 +2978,9 @@ dastart(struct cam_periph *periph, union ccb *start_ccb)
/*dxfer_len*/ bp->bio_bcount,
/*sense_len*/SSD_FULL_SIZE,
da_default_timeout * 1000);
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
start_ccb->csio.bio = bp;
#endif
break;
}
case BIO_FLUSH:
@ -4008,6 +4013,10 @@ dadone(struct cam_periph *periph, union ccb *done_ccb)
CAM_DEBUG(periph->path, CAM_DEBUG_TRACE, ("dadone\n"));
csio = &done_ccb->csio;
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
if (csio->bio != NULL)
biotrack(csio->bio, __func__);
#endif
state = csio->ccb_h.ccb_state & DA_CCB_TYPE_MASK;
switch (state) {
case DA_CCB_BUFFER_IO:
@ -4106,6 +4115,7 @@ dadone(struct cam_periph *periph, union ccb *done_ccb)
}
}
biotrack(bp, __func__);
LIST_REMOVE(&done_ccb->ccb_h, periph_links.le);
if (LIST_EMPTY(&softc->pending_ccbs))
softc->flags |= DA_FLAG_WAS_OTAG;
@ -5219,6 +5229,11 @@ daerror(union ccb *ccb, u_int32_t cam_flags, u_int32_t sense_flags)
struct cam_periph *periph;
int error, error_code, sense_key, asc, ascq;
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
if (ccb->csio.bio != NULL)
biotrack(ccb->csio.bio, __func__);
#endif
periph = xpt_path_periph(ccb->ccb_h.path);
softc = (struct da_softc *)periph->softc;

2
sys/conf/options
View File

@ -50,12 +50,14 @@ TWA_FLASH_FIRMWARE opt_twa.h
# Debugging options.
ALT_BREAK_TO_DEBUGGER opt_kdb.h
BREAK_TO_DEBUGGER opt_kdb.h
BUF_TRACKING opt_global.h
DDB
DDB_BUFR_SIZE opt_ddb.h
DDB_CAPTURE_DEFAULTBUFSIZE opt_ddb.h
DDB_CAPTURE_MAXBUFSIZE opt_ddb.h
DDB_CTF opt_ddb.h
DDB_NUMSYM opt_ddb.h
FULL_BUF_TRACKING opt_global.h
GDB
KDB opt_global.h
KDB_TRACE opt_kdb.h

9
sys/dev/mps/mps_sas.c
View File

@ -1872,6 +1872,10 @@ mpssas_action_scsiio(struct mpssas_softc *sassc, union ccb *ccb)
}
}
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
if (csio->bio != NULL)
biotrack(csio->bio, __func__);
#endif
callout_reset_sbt(&cm->cm_callout, SBT_1MS * ccb->ccb_h.timeout, 0,
mpssas_scsiio_timeout, cm, 0);
@ -2125,6 +2129,11 @@ mpssas_scsiio_complete(struct mps_softc *sc, struct mps_command *cm)
TAILQ_REMOVE(&cm->cm_targ->commands, cm, cm_link);
ccb->ccb_h.status &= ~(CAM_STATUS_MASK | CAM_SIM_QUEUED);
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
if (ccb->csio.bio != NULL)
biotrack(ccb->csio.bio, __func__);
#endif
if (cm->cm_state == MPS_CM_STATE_TIMEDOUT) {
TAILQ_REMOVE(&cm->cm_targ->timedout_commands, cm, cm_recovery);
if (cm->cm_reply != NULL)

1
sys/geom/geom_dev.c
View File

@ -668,6 +668,7 @@ g_dev_strategy(struct bio *bp)
sc = cp->private;
KASSERT(cp->acr || cp->acw,
("Consumer with zero access count in g_dev_strategy"));
biotrack(bp, __func__);
#ifdef INVARIANTS
if ((bp->bio_offset % cp->provider->sectorsize) != 0 ||
(bp->bio_bcount % cp->provider->sectorsize) != 0) {

2
sys/geom/geom_disk.c
View File

@ -421,6 +421,8 @@ g_disk_start(struct bio *bp)
int error;
off_t off;
biotrack(bp, __func__);
sc = bp->bio_to->private;
if (sc == NULL || (dp = sc->dp) == NULL || dp->d_destroyed) {
g_io_deliver(bp, ENXIO);

12
sys/geom/geom_io.c
View File

@ -223,6 +223,9 @@ g_clone_bio(struct bio *bp)
/* Inherit classification info from the parent */
bp2->bio_classifier1 = bp->bio_classifier1;
bp2->bio_classifier2 = bp->bio_classifier2;
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
bp2->bio_track_bp = bp->bio_track_bp;
#endif
bp->bio_children++;
}
#ifdef KTR
@ -362,6 +365,8 @@ g_io_check(struct bio *bp)
off_t excess;
int error;
biotrack(bp, __func__);
cp = bp->bio_from;
pp = bp->bio_to;
@ -503,6 +508,8 @@ g_run_classifiers(struct bio *bp)
struct g_classifier_hook *hook;
int classified = 0;
biotrack(bp, __func__);
TAILQ_FOREACH(hook, &g_classifier_tailq, link)
classified |= hook->func(hook->arg, bp);
@ -518,6 +525,8 @@ g_io_request(struct bio *bp, struct g_consumer *cp)
int direct, error, first;
uint8_t cmd;
biotrack(bp, __func__);
KASSERT(cp != NULL, ("NULL cp in g_io_request"));
KASSERT(bp != NULL, ("NULL bp in g_io_request"));
pp = cp->provider;
@ -644,6 +653,8 @@ g_io_deliver(struct bio *bp, int error)
struct mtx *mtxp;
int direct, first;
biotrack(bp, __func__);
KASSERT(bp != NULL, ("NULL bp in g_io_deliver"));
pp = bp->bio_to;
KASSERT(pp != NULL, ("NULL bio_to in g_io_deliver"));
@ -835,6 +846,7 @@ g_io_schedule_down(struct thread *tp __unused)
}
CTR0(KTR_GEOM, "g_down has work to do");
g_bioq_unlock(&g_bio_run_down);
biotrack(bp, __func__);
if (pace != 0) {
/*
* There has been at least one memory allocation

4
sys/geom/geom_subr.c
View File

@ -1531,6 +1531,10 @@ DB_SHOW_COMMAND(bio, db_show_bio)
db_printf(" caller2: %p\n", bp->bio_caller2);
db_printf(" bio_from: %p\n", bp->bio_from);
db_printf(" bio_to: %p\n", bp->bio_to);
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
db_printf(" bio_track_bp: %p\n", bp->bio_track_bp);
#endif
}
}

4
sys/geom/geom_vfs.c
View File

@ -192,6 +192,10 @@ g_vfs_strategy(struct bufobj *bo, struct buf *bp)
}
bip->bio_done = g_vfs_done;
bip->bio_caller2 = bp;
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
buf_track(bp, __func__);
bip->bio_track_bp = bp;
#endif
g_io_request(bip, cp);
}

2
sys/geom/part/g_part.c
View File

@ -2154,6 +2154,8 @@ g_part_start(struct bio *bp)
struct g_provider *pp;
char buf[64];
biotrack(bp, __func__);
pp = bp->bio_to;
gp = pp->geom;
table = gp->softc;

31
sys/kern/vfs_bio.c
View File

@ -1952,6 +1952,7 @@ bufwrite(struct buf *bp)
if (oldflags & B_ASYNC)
BUF_KERNPROC(bp);
bp->b_iooffset = dbtob(bp->b_blkno);
buf_track(bp, __func__);
bstrategy(bp);
if ((oldflags & B_ASYNC) == 0) {
@ -2078,6 +2079,8 @@ bdwrite(struct buf *bp)
VOP_BMAP(vp, bp->b_lblkno, NULL, &bp->b_blkno, NULL, NULL);
}
buf_track(bp, __func__);
/*
* Set the *dirty* buffer range based upon the VM system dirty
* pages.
@ -2386,6 +2389,8 @@ brelse(struct buf *bp)
brelvp(bp);
}
buf_track(bp, __func__);
/* buffers with no memory */
if (bp->b_bufsize == 0) {
buf_free(bp);
@ -2470,6 +2475,7 @@ bqrelse(struct buf *bp)
binsfree(bp, qindex);
out:
buf_track(bp, __func__);
/* unlock */
BUF_UNLOCK(bp);
if (qindex == QUEUE_CLEAN)
@ -3716,6 +3722,7 @@ getblk(struct vnode *vp, daddr_t blkno, int size, int slpflag, int slptimeo,
CTR4(KTR_BUF, "getblk(%p, %ld, %d) = %p", vp, (long)blkno, size, bp);
BUF_ASSERT_HELD(bp);
end:
buf_track(bp, __func__);
KASSERT(bp->b_bufobj == bo,
("bp %p wrong b_bufobj %p should be %p", bp, bp->b_bufobj, bo));
return (bp);
@ -3892,6 +3899,7 @@ biodone(struct bio *bp)
void (*done)(struct bio *);
vm_offset_t start, end;
biotrack(bp, __func__);
if ((bp->bio_flags & BIO_TRANSIENT_MAPPING) != 0) {
bp->bio_flags &= ~BIO_TRANSIENT_MAPPING;
bp->bio_flags |= BIO_UNMAPPED;
@ -3948,6 +3956,15 @@ biofinish(struct bio *bp, struct devstat *stat, int error)
biodone(bp);
}
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
void
biotrack_buf(struct bio *bp, const char *location)
{
buf_track(bp->bio_track_bp, location);
}
#endif
/*
* bufwait:
*
@ -3998,6 +4015,7 @@ bufdone(struct buf *bp)
struct bufobj *dropobj;
void (*biodone)(struct buf *);
buf_track(bp, __func__);
CTR3(KTR_BUF, "bufdone(%p) vp %p flags %X", bp, bp->b_vp, bp->b_flags);
dropobj = NULL;
@ -4801,6 +4819,9 @@ DB_SHOW_COMMAND(buffer, db_show_buffer)
{
/* get args */
struct buf *bp = (struct buf *)addr;
#ifdef FULL_BUF_TRACKING
uint32_t i, j;
#endif
if (!have_addr) {
db_printf("usage: show buffer <addr>\n");
@ -4837,6 +4858,16 @@ DB_SHOW_COMMAND(buffer, db_show_buffer)
}
db_printf("\n");
}
#if defined(FULL_BUF_TRACKING)
db_printf("b_io_tracking: b_io_tcnt = %u\n", bp->b_io_tcnt);
i = bp->b_io_tcnt % BUF_TRACKING_SIZE;
for (j = 1; j <= BUF_TRACKING_SIZE; j++)
db_printf(" %2u: %s\n", j,
bp->b_io_tracking[BUF_TRACKING_ENTRY(i - j)]);
#elif defined(BUF_TRACKING)
db_printf("b_io_tracking: %s\n", bp->b_io_tracking);
#endif
db_printf(" ");
BUF_LOCKPRINTINFO(bp);
}

1
sys/kern/vfs_cluster.c
View File

@ -1008,6 +1008,7 @@ cluster_wbuild(struct vnode *vp, long size, daddr_t start_lbn, int len,
reassignbuf(tbp); /* put on clean list */
bufobj_wref(tbp->b_bufobj);
BUF_KERNPROC(tbp);
buf_track(tbp, __func__);
TAILQ_INSERT_TAIL(&bp->b_cluster.cluster_head,
tbp, b_cluster.cluster_entry);
}

20
sys/sys/bio.h
View File

@ -121,6 +121,9 @@ struct bio {
void *_bio_caller2;
uint8_t _bio_cflags;
#endif
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
struct buf *bio_track_bp; /* Parent buf for tracking */
#endif
/* XXX: these go away when bio chaining is introduced */
daddr_t bio_pblkno; /* physical block number */
@ -142,6 +145,23 @@ void biodone(struct bio *bp);
void biofinish(struct bio *bp, struct devstat *stat, int error);
int biowait(struct bio *bp, const char *wchan);
#if defined(BUF_TRACKING) || defined(FULL_BUF_TRACKING)
void biotrack_buf(struct bio *bp, const char *location);
static __inline void
biotrack(struct bio *bp, const char *location)
{
if (bp->bio_track_bp != NULL)
biotrack_buf(bp, location);
}
#else
static __inline void
biotrack(struct bio *bp __unused, const char *location __unused)
{
}
#endif
void bioq_disksort(struct bio_queue_head *ap, struct bio *bp);
struct bio *bioq_first(struct bio_queue_head *head);
struct bio *bioq_takefirst(struct bio_queue_head *head);

20
sys/sys/buf.h
View File

@ -140,6 +140,15 @@ struct buf {
void *b_fsprivate1;
void *b_fsprivate2;
void *b_fsprivate3;
#if defined(FULL_BUF_TRACKING)
#define BUF_TRACKING_SIZE 32
#define BUF_TRACKING_ENTRY(x) ((x) & (BUF_TRACKING_SIZE - 1))
const char *b_io_tracking[BUF_TRACKING_SIZE];
uint32_t b_io_tcnt;
#elif defined(BUF_TRACKING)
const char *b_io_tracking;
#endif
};
#define b_object b_bufobj->bo_object
@ -429,6 +438,17 @@ buf_countdeps(struct buf *bp, int i)
return (0);
}
static __inline void
buf_track(struct buf *bp, const char *location)
{
#if defined(FULL_BUF_TRACKING)
bp->b_io_tracking[BUF_TRACKING_ENTRY(bp->b_io_tcnt++)] = location;
#elif defined(BUF_TRACKING)
bp->b_io_tracking = location;
#endif
}
#endif /* _KERNEL */
/*

2
sys/vm/vm_pager.c
View File

@ -376,6 +376,7 @@ initpbuf(struct buf *bp)
bp->b_iodone = NULL;
bp->b_error = 0;
BUF_LOCK(bp, LK_EXCLUSIVE, NULL);
buf_track(bp, __func__);
}
/*
@ -473,6 +474,7 @@ relpbuf(struct buf *bp, int *pfreecnt)
KASSERT(bp->b_vp == NULL, ("relpbuf with vp"));
KASSERT(bp->b_bufobj == NULL, ("relpbuf with bufobj"));
buf_track(bp, __func__);
BUF_UNLOCK(bp);
mtx_lock(&pbuf_mtx);