Skip site navigation (1)Skip section navigation (2)
Date:      Mon, 26 Oct 2015 21:08:42 -0600
From:      Scott Long <scott4long@yahoo.com>
To:        "Pokala, Ravi" <rpokala@panasas.com>
Cc:        "freebsd-geom@freebsd.org" <freebsd-geom@freebsd.org>, "freebsd-scsi@freebsd.org" <freebsd-scsi@freebsd.org>, "freebsd-hackers@freebsd.org" <freebsd-hackers@freebsd.org>, "ken@freebsd.org" <ken@freebsd.org>, "imp@freebsd.org" <imp@freebsd.org>, "scottl@freebsd.org" <scottl@freebsd.org>
Subject:   Re: Low-level trace-buffers in CAM
Message-ID:  <2C9653BA-CC10-497B-ACEF-0C76AAE2FF44@yahoo.com>
In-Reply-To: <A760883F-317D-46C9-AD7C-B8F5D96A49DA@panasas.com>
References:  <A760883F-317D-46C9-AD7C-B8F5D96A49DA@panasas.com>

next in thread | previous in thread | raw e-mail | index | archive | help
Hi Ravi,

Yes I was one of the people who never followed up.  I'll be at the vendor su=
mmit next week, let's chat some more.

Scott

Sent from my iPhone

> On Oct 26, 2015, at 8:22 PM, Pokala, Ravi <rpokala@panasas.com> wrote:
>=20
> Hi folks,
>=20
> ----------------------------------------------------------------
> This is an updated re-send of a message I originally sent about a year ago=
, during MeetBSD 2014. A few people expressed interest in person, but no one=
 ever followed up on the lists. I'm bringing this up again, in the hopes tha=
t I can get some feedback before / during next week's Dev/Vendor Summit. I'm=
 CCing some folks who expressed interest at that time, and some folks that I=
 was told would be interested.
> ----------------------------------------------------------------
>=20
> At Panasas, we found it useful to have a trace buffer for each ATA drive i=
n the system, for gathering information about command sequences and latency.=
 I implemented that functionality for our old 7-ish ATA driver, and it works=
 quite well, with fairly low overhead. (I ran our usual suite of performance=
 tests, and any differences were lost in the noise.) These traces allowed us=
 to capture and replay access patterns (though obviously not with the same d=
ata), analyze and compare latency, etc.
>=20
> As Panasas moves toward a more modern base, we want to re-implement this f=
unctionality for ATA, SCSI, NVMe, etc. And push it upstream, of course! :-)
>=20
> First, some example output; I wrote code for three different formats:
>  - The binary trace buffer dump
>    Useful for manipulating in C; the other two formats are post-processed o=
ut of this, and I also wrote a replay utility and a basic stats analyzer whi=
ch operated on the binary dump.
>  - Tabular hex
>    Useful for parsing with scripts; I never actually used this format, but=
 it was trivial so I just went ahead and wrote it.
>  - Human-readable
>    Useful for eyeballing; on more than one occasion, I was able to see tha=
t I had mis-assembled a command in userspace, etc.
>=20
> These examples are actually really long lines; I've broken them up and ind=
ented for the sake of email:
>=20
>    # Tabular hex format, for use w/ scripts
>    # Request time       ATA request information   Response time       =20
>        ATA response information  sts/err  flags
>    1445839793003737     c8 0000 0004 000000002fa8 1445839793003806    =20
>        c8 0000 0004 000000002fa8 50 00 0000007d
>    1445839793003874     c8 0000 0020 000000113ac8 1445839793011541    =20
>        c8 0000 0020 000000113ac8 50 00 0000007d
>    1445839793011795     c8 0000 0008 000000118ca8 1445839793017702    =20
>        c8 0000 0008 000000118ca8 50 00 0000007d
>    1445839793017808     c8 0000 0080 000000117628 1445839793018975    =20
>        c8 0000 0080 000000117628 50 00 0000007d
>    1445839793019079     c8 0000 0020 0000001177a8 1445839793019686    =20
>        c8 0000 0020 0000001177a8 50 00 0000007d
>=20
>    # Human-readable
>    FLAGS       REQUEST TIME         RESPONSE TIME        ELAPSED TIME     =
   =20
>        REQUEST COMMAND                          STATUS   ERROR   =20
>        RESPONSE COMMAND                       =20
>    ----------- -------------------- -------------------- -----------------=
---=20
>        ---------------------------------------- -------- --------=20
>        ----------------------------------------
>    ____C...._V 1445839793003737     1445839793003806     69               =
   =20
>        READ DMA (LBA 12200 + 4 sectors)         _R_S____ ________=20
>        ----                                   =20
>    ____C...._V 1445839793003874     1445839793011541     7667             =
   =20
>        READ DMA (LBA 1129160 + 32 sectors)      _R_S____ ________=20
>        ----                                   =20
>    ____C...._V 1445839793011795     1445839793017702     5907             =
   =20
>        READ DMA (LBA 1150120 + 8 sectors)       _R_S____ ________=20
>        ----                                   =20
>    ____C...._V 1445839793017808     1445839793018975     1167             =
   =20
>        READ DMA (LBA 1144360 + 128 sectors)     _R_S____ ________=20
>        ----                                   =20
>    ____C...._V 1445839793019079     1445839793019686     607              =
   =20
>        READ DMA (LBA 1144744 + 32 sectors)      _R_S____ ________=20
>        ----                                   =20
>=20
> The obvious place to put this sort of tracing would be in GEOM, but that a=
ctually isn't what I want, for a few reasons. First of all, I'm primarily in=
terested in the exact register / taskfile / CDB values sent to the drive - o=
pcode, feature codes, LBAs, etc. Second, I'm interested in hardware-level la=
tency - how long does a request stay in the controller and device. Both of t=
hose pretty much require working below GEOM.
>=20
> Therefore, I think I want to do it in the CAM stack; ideally, I'd put the h=
ooks in the SIM drivers, to get as close to the metal as possible, to get th=
e most accurate latency. However, even a light touch to every SIM driver is g=
oing to be painful, and since I don't have access to every controller in the=
 world, testing would be difficult. Adding the hooks to da(4) and ada(4) wou=
ld still be pretty close to the metal, and would require much smaller change=
s. Or maybe they belong in the XPT layer? (I don't know nearly as much about=
 CAM as I should. :-/)
>=20
> --------
> NOTE: When I mentioned this idea at a (San Francisco) Bay Area FreeBSD Use=
r Group (BAFUG) meeting, there were suggestions about integrating this with D=
Trace or KTrace instead. I'm happy to consider either of those, but I know e=
ven less about those than I do about CAM. If that's really the best way to d=
o this sort of thing, I'm happy to learn, if someone is willing to teach.
> --------
>=20
> I took the Panasas / 7.x implementation, and pseudo-coded what it might lo=
ok like in CAM. (I could probably make diffs against the old ATA stack avail=
able for comparison, but I figured no one would care anymore.) A huge caveat=
 is that I've never really poked in CAM before, so I fully expect I'm doing s=
everal things wrong. Please educate me. :-)
>=20
> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D
>=20
> Create a circular buffer of trace records for each CAM PERIPH. Each record=
 will contain the full CDB for the request as sent to the device, the timest=
amp (in usec) of the request, the CDB as returned by the device, the timesta=
mp of the response, and the status and error code. Additionally, flags are p=
rovided to track the state of the trace record, and to indicate which type o=
f periph the record is associated with.
>=20
> --------
>=20
> typedef struct {
>    u_int32_t    flags;
> #define CAM_TRACE_F_VALID    0x00000001    /* valid record */
> #define CAM_TRACE_F_INPROGRESS    0x00000002    /* request in progress */
> #define CAM_TRACE_F_REQ_VALID    0x00000004    /* request data valid */
> #define CAM_TRACE_F_RESP_VALID    0x00000008    /* response data valid */
> #define CAM_TRACE_F_COMPLETE    0x00000010    /* response gathered */
> #define CAM_TRACE_F_TIMEDOUT    0x00000020    /* request timed out */
> #define CAM_TRACE_F_ABANDONED    0x00000040    /* cancelled, etc. */
> #define CAM_TRACE_F_RETRIED    0x00000080    /* retry in later record */
> #define CAM_TRACE_F_IS_RETRY    0x00000100    /* retry of earlier req. */
> #define CAM_TRACE_F_PERIPH_MASK    0xf0000000    /* up to 16 PERIPH types *=
/
> #define CAM_TRACE_F_PERIPH_DA    0x0
> #define CAM_TRACE_F_PERIPH_ADA    0x1
> #define CAM_TRACE_F_PERIPH_NVD    0x2
>    u_int64_t    req_usec;
>    cdb_t        req_cdb;
>    u_int64_t    resp_usec;
>    cdb_t        resp_cdb;
>    u_int8_t    resp_status;
>    u_int8_t    resp_error;
>    u_int8_t    resp_asc;    /* Needed for SCSI? */
>    u_int8_t    resp_asq;    /* Needed for SCSI? */
>    u_int8_t    padding[8];    /* Pad to 64 bytes */
> /* There's going to be a large-ish array of these in the kernel; make sure=

> * they're packed to minimize space usage, and keep things aligned. It may
> * make sense to re-order the fields for alignment as well.
> */
> } cam_trace_record_t __attribute__((packed, aligned(8)));
>=20
> typedef struct {
>    u_int32_t        trace_buf_record_count;
>    cam_trace_record_t    *trace_buf;
> } cam_trace_buffer_t;
>=20
> /* This is settable via a tunable; for Panasas' purposes, 100K entries was=

> * enough to provide a good amount of history even on a busy system, while
> * not taking up much space (< 5MB/drive).
> */
> #define CAM_TRACE_BUFFER_DEFAULT_COUNT 100000
>=20
> ----------------
>=20
> ioctl interfaces are used to get the trace buffer size, to retrieve the bu=
ffer contents, or to clear the buffer. The buffer can then be analyzed from u=
serspace, or written to a file for post-processing.
>=20
> --------
>=20
> #define CAM_GET_TRACE_RECORD_COUNT    _IOR(???, ???, u_int32_t)
> #define CAM_GET_TRACE_BUFFER        _IOWR(???, ???, cam_trace_buffer_t)
> #define CAM_CLEAR_TRACE_BUFFER        _IOW(???, ???, u_int32_t)
>=20
> ----------------
>=20
> To get the buffer:
>=20
> --------
>=20
>    cam_trace_buffer_t trace =3D NULL;
>    fd =3D open(periph_name, O_RDONLY);
>    error =3D ioctl(fd, CAM_GET_TRACE_RECORD_COUNT,
>        &trace.trace_buf_record_count);
>    trace.trace_buf =3D malloc(trace.trace_buf_record_count *
>        sizeof(cam_trace_record_t));
>    error =3D ioctl(fd, CAM_GET_TRACE_BUFFER, &trace);
>=20
> ----------------
>=20
> By including the full CDB, the entire command can be decoded by analysis t=
ools. Tools can be written to parse the buffer and translate command data in=
to human-readable descriptions, calculate elapsed times for requests, perfor=
m statistical analysis based on opcode, command type, transfer size, etc. Co=
mmand decoders would need to be written for each PERIPH type (i.e. one for A=
TA, one for SCSI, one for NVMe, etc.).
>=20
> ----------------
>=20
> Each PERIPH's softc needs to include some information about the per-device=

> buffer.
>=20
> --------
>=20
>    u_int32_t        trace_buf_record_count;
>    u_int64_t        trace_buf_request_count;
>    cam_trace_record_t    *trace_buf;
>=20
> ----------------
>=20
> In each SIM, there should already be some sort of request structure, which=
 associates the softc and the CDB of the request. To that structure, add a p=
ointer to the trace record associated with the request.
>=20
> --------
>=20
> request structure:
>    cam_trace_record_t    *trace_rec;
>=20
> ----------------
>=20
> When initializing the per-device softc, allocate a trace buffer. The numbe=
r of records can be hard-coded, or settable via a tunable.
>=20
> The example below has a global size for everything, but it should be possi=
ble to do it on a per-device or per-PERIPH basis.
>=20
> --------
>=20
>    /** Initialize per-drive command tracing buffer. **/
>    /* Get the buffer size from the tunable. Sanity check it. */
>    sc->trace_buf_record_count =3D CAM_TRACE_BUFFER_DEFAULT_COUNT;
>    TUNABLE_ULONG_FETCH("cam.trace_buf_record_count",
>        &trace_buf_record_count_tunable);
>    if (trace_buf_record_count_tunable) {
>        /* Less than 1K records is unusably few; more than 1M
>         * records is unusably many.
>         */
>        if ((trace_buf_record_count_tunable < (1 << 10)) ||
>            (trace_buf_record_count_tunable > (1 << 20))) {
>            device_printf(dev, "cam.trace_buf_record_count=3D%lu"
>                " out of range; should be between %u and %u\n",
>                trace_buf_record_count_tunable, (1 << 10),
>                (1 << 20));
>        } else {
>            sc->trace_buf_record_count =3D (u_int32_t)
>                trace_buf_record_count_tunable;
>        }
>    }
>    /* Allocate the buffer. */
>    trace_buf_bytes =3D sc->trace_buf_record_count *
>        sizeof(cam_trace_record_t);
>    sc->trace_buf =3D malloc(trace_buf_bytes, M_AD, M_NOWAIT | M_ZERO);
>    if (sc->trace_buf =3D=3D NULL) {
>        device_printf(dev, "unable to allocate %zd for trace_buf\n",
>            trace_buf_bytes);
>        sc->trace_buf_record_count =3D 0;
>    } else {
>        device_printf(dev, "allocated %zd @ %p for trace_buf\n",
>            trace_buf_bytes, sc->trace_buf);
>    }
>    /* Request counter, used for indexing */
>    sc->trace_buf_request_count =3D 0;
>=20
>=20
> ----------------
>=20
> /* Initial setup of the trace record for a new request.
> *
> *  Locate the circular per-device trace buffer in the drive's softc.
> *  Populate the pointer to the next record in the trace buffer; this is
> *  done atomically to prevent concurrent requests from getting the same
> *  index. That could get a bit weird if/when 'trace_buf_request_count'
> *  rolls over, if the maximum counter value is not a multiple of
> *  'trace_buf_record_count' (i.e. the request counter recycles in the
> *  middle of the buffer). By using a 64-bit request counter, we're pretty
> *  safe - even at one transaction per nanosecond, that will still last
> *  about 585 years.
> *
> *  Initialize the record by zeroing it and then setting the VALID flag.
> *
> *  This could be done at any point before sending the request to the
> *  hardware; neither the CDB data nor the timestamps are involved yet.
> */
> void
> trace_rec_init(cam_request_t req) {
>    ada_softc *sc =3D (request->...->softc)
>    u_int64_t tmp =3D 0;
>    if (sc && sc->trace_buf) {
>        tmp =3D atomic_fetchadd_log(&sc->trace_buf_request_count, 1);
>        req->trace_rec =3D &sc->trace_buf[tmp %
>            sc->trace_buf_record_count];
>        bzero(req->trace_rec, sizeof(*req->trace_rec));
>        req->trace_rec->flags =3D (CAM_TRACE_F_PERIPH_XXX << 28);
>        req->trace_rec->flags |=3D CAM_TRACE_F_VALID;
>    } else {
>        req->trace_rec =3D NULL;
>    }
> }
>=20
> ----------------
>=20
> /* Stuff the request data into the trace record.
> *
> *  If the trace record is present and valid, copy the CDB into the
> *  record. Set CAM_TRACE_F_REQ_VALID to indicate that the request data is
> *  valid, and INPROGRESS to show that the request is in-progress.
> *
> *  This should be done just before sending the request to the hardware.
> *  This should *not* be fused into trace_rec_init(), because
> *  trace_rec_init() is also used in the retry case, where it is not
> * correct to immediately start the timer.
> */
> void
> trace_rec_req(cam_request_t req) {
>    struct timeval tv;
>    if (req->trace_rec && (req->trace_rec->flags & CAM_TRACE_F_VALID)) {
>        bcopy(req->cdb, req->trace_rec->req_cdb, sizeof(req->cdb));
>        microuptime(&tv);
>        req->trace_rec->req_usec =3D ((uint64_t) tv->tv_sec * 1000000)
>            + tv->tv_usec;
>        req->trace_rec->flags |=3D
>            (CAM_TRACE_F_REQ_VALID | CAM_TRACE_F_INPROGRESS);
>    }
> }
>=20
> ----------------
>=20
> /* Stuff the response data into the trace record.
> *
> *  If the trace record is present and valid, copy the CDB **as returned by=

> *  the drive** into the record. At this point, we also have the result fro=
m
> *  the command (status, error, (asc? ascq?)), so save them too. Set
> *  CAM_TRACE_F_RESP_VALID to indicate that the response data is valid.
> *  Clear INPROGRESS and set COMPLETE instead.
> *
> *  This should be done just after getting the response information from th=
e
> *  hardware.
> */
> void
> trace_rec_resp(cam_request_t req) {
>    struct timeval tv;
>    if (req->trace_rec && (req->trace_rec->flags & CAM_TRACE_F_VALID)) {
>        microuptime(&tv);
>        bcopy(req->cdb, req->trace_rec->resp_cdb, sizeof(req->cdb));
>        req->trace_rec->resp_usec =3D ((uint64_t) tv->tv_sec *
>            1000000) + tv->tv_usec;
>        req->trace_rec->flags |=3D
>            (CAM_TRACE_F_RESP_VALID | CAM_TRACE_F_COMPLETE);
>        req->trace_rec->flags &=3D ~CAM_TRACE_F_INPROGRESS;
>    }
> }
>=20
> ----------------
>=20
> /* Update the trace record if there was a timeout.
> *
> *  If the trace record is present and valid, set TIMEDOUT to indicate
> *  that the request associated with the record exceeded its timeout.
> *  Since this attempt is complete, clear INPROGRESS and set COMPLETE.
> *
> *  This should be done along with other timeout handling.
> */
> void
> trace_rec_timeout(cam_request_t req) {
>    if (req->trace_rec && (req->trace_rec->flags & CAM_TRACE_F_VALID)) {
>        req->trace_rec->flags |=3D
>            (CAM_TRACE_F_TIMEDOUT | CAM_TRACE_F_COMPLETE);
>        req->trace_rec->flags &=3D ~CAM_TRACE_F_INPROGRESS;
>    }
> }
>=20
> ----------------
>=20
> /* Update the trace record if the request is being retried.
> * =20
> *  If the trace record is present and valid, set RETRIED to indicate
> *  that the request associated with the record is going to be retried.
> *  Since this attempt is complete, clear INPROGRESS and set COMPLETE.
> *  Then get a new trace record for the new attempt, copy the request
> *  command data to the new record, and set IS_RETRY to show that this
> *  is a retry of an earlier request.
> *
> *  This should be done at the time the retry is queued.
> */
> void
> trace_rec_retry(cam_request_t req) {
>    if (req->trace_rec && (req->trace_rec->flags & CAM_TRACE_F_VALID)) {
>        /* First, mark the original request as being requeued. */
>        req->trace_rec->flags |=3D
>            (CAM_TRACE_F_RETRIED | CAM_TRACE_F_COMPLETE);
>        req->trace_rec->flags &=3D ~CAM_TRACE_F_INPROGRESS;
>        /* Get a new record for the retry. */
>        trace_rec_init(req);
>        /* Mark the new record as being a retry. */
>        req->trace_rec->flags |=3D CAM_TRACE_F_IS_RETRY;
>    }
> }
>=20
> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D
>=20
> I'd appreciate feedback, both on the implementation details and on the ide=
a as a whole. Some open questions are:
>=20
> - My assumption is that each SIM has a structure that associates a PERIPH'=
s softc with the CDB that's being processed. It might require dereferencing a=
 chain of pointers, but it should be there in some fashion.
>=20
> - The current implementation adds a few ioctls to the old ad(4) disk-devic=
e driver. I would expect to add the new ioctls to da(4) and ada(4); is that t=
he right thing to do?
>=20
> Again, any feedback would be greatly appreciated. I'll be at the Dev/Vendo=
r Summit next week, if anyone wants to discuss this with me in person.
>=20
> Thanks,
>=20
> Ravi
> _______________________________________________
> freebsd-scsi@freebsd.org mailing list
> https://lists.freebsd.org/mailman/listinfo/freebsd-scsi
> To unsubscribe, send any mail to "freebsd-scsi-unsubscribe@freebsd.org"



Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?2C9653BA-CC10-497B-ACEF-0C76AAE2FF44>