From owner-freebsd-scsi@freebsd.org Tue Oct 27 03:15:47 2015 Return-Path: Delivered-To: freebsd-scsi@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 72FC1A1E49C for ; Tue, 27 Oct 2015 03:15:47 +0000 (UTC) (envelope-from scott4long@yahoo.com) Received: from nm30-vm8.bullet.mail.gq1.yahoo.com (nm30-vm8.bullet.mail.gq1.yahoo.com [98.136.216.199]) (using TLSv1 with cipher ECDHE-RSA-RC4-SHA (128/128 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 3E8C61F5F for ; Tue, 27 Oct 2015 03:15:46 +0000 (UTC) (envelope-from scott4long@yahoo.com) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=yahoo.com; s=s2048; t=1445915324; bh=EQOsczGewNEODH9UYzy6zp7RenazxJBTgd8Xi9dCsyA=; h=Subject:From:In-Reply-To:Date:Cc:References:To:From:Subject; b=AGViYa2Cy3pWx1CnEU9yQsSgP4pm6dzPKMKz/zY0yLlidB03WVxt9TECMqpPBK4GBhT+fxh7jN75S/b25BRJmba5tXF155m8uhEgF0PRVNeTmt3OGxwy+5K3enzcQq9iyt/FYCGkI0hYfDCn5BE4zxs5jqCdcDzZo1LiV8Yfqm/n/qNAtBUwa8wssT7p5uCfkW2JdafPsvyNlhRGOTV9ZHLSVqSiIoT0ElfJJ3HzFCqo3tjLeKgghZjyyIiiPz5kqcMaGCruQwpKPPjKnut3aXN47kWDE/3t2he9a3I/KVYEpqNPaFrPeSDr6dujhKxh3OGS9SocY8cGc6oNPQv6hQ== Received: from [98.137.12.55] by nm30.bullet.mail.gq1.yahoo.com with NNFMP; 27 Oct 2015 03:08:44 -0000 Received: from [208.71.42.198] by tm15.bullet.mail.gq1.yahoo.com with NNFMP; 27 Oct 2015 03:08:44 -0000 Received: from [127.0.0.1] by smtp209.mail.gq1.yahoo.com with NNFMP; 27 Oct 2015 03:08:44 -0000 X-Yahoo-Newman-Id: 651161.7604.bm@smtp209.mail.gq1.yahoo.com X-Yahoo-Newman-Property: ymail-3 X-YMail-OSG: CO37JK4VM1nFIy7Qa8nbeXEOF9VtrnHzSFncdrpMNP8Tgdg YQ8keMmIC2Nz5Oc3t8jQ4oiN2et05cQ7QWwwpu9pSR01PHJINhqR9WZAaAq9 aFjWMLa5_wcxTmTBzFwULDRemrxPawOzexZa.PROmjSv3NjdhQMrgXuaMPK3 EIbgcmAPnxcBIinCP6nlo_Eb5zmcJg5rES56fDqFPsLl7ADvHTvcTWrE2bBP zSbIItr86dPnmIaBNBnvwTJ49pSCVp9dm1sd57g5OMhS7FyCKcrVQAE6S60b GSM5M5bi3AVgyxWWwGF8U96Om08tFo3e0eMf2yuX_zbv1vzxB.Pr71qh4G5p p.lZfvMMtFpruoY2xe4cXQ8HjJZJACn_VqwZsekcvNDogt2mMamHRd7eXbX8 oWOtTUuvywFgSNR3SuVZhOxqTa0vGKsWv5s0ZY0zSDLRtToEwHwsHeJ0BYps 0a_j2OIHNdfObetFyhwfE3FdMCJGN2kRllio3oodVbHnJS5GoWQeO.Se3Gnt sfSpXfvPJaNxpyTR7mHOucq4V0LFEwsnDPcIBXeY- X-Yahoo-SMTP: clhABp.swBB7fs.LwIJpv3jkWgo2NU8- Content-Type: text/plain; charset=us-ascii Mime-Version: 1.0 (1.0) Subject: Re: Low-level trace-buffers in CAM From: Scott Long X-Mailer: iPhone Mail (13B143) In-Reply-To: Date: Mon, 26 Oct 2015 21:08:42 -0600 Cc: "freebsd-geom@freebsd.org" , "freebsd-scsi@freebsd.org" , "freebsd-hackers@freebsd.org" , "ken@freebsd.org" , "imp@freebsd.org" , "scottl@freebsd.org" Content-Transfer-Encoding: quoted-printable Message-Id: <2C9653BA-CC10-497B-ACEF-0C76AAE2FF44@yahoo.com> References: To: "Pokala, Ravi" X-BeenThere: freebsd-scsi@freebsd.org X-Mailman-Version: 2.1.20 Precedence: list List-Id: SCSI subsystem List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 27 Oct 2015 03:15:47 -0000 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 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"