<html xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40"><head><meta http-equiv=Content-Type content="text/html; charset=utf-8"><meta name=Generator content="Microsoft Word 15 (filtered medium)"><style><!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0in;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri",sans-serif;}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:blue;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:purple;
text-decoration:underline;}
p.msonormal0, li.msonormal0, div.msonormal0
{mso-style-name:msonormal;
mso-margin-top-alt:auto;
margin-right:0in;
mso-margin-bottom-alt:auto;
margin-left:0in;
font-size:11.0pt;
font-family:"Calibri",sans-serif;}
span.EmailStyle18
{mso-style-type:personal-reply;
font-family:"Calibri",sans-serif;
color:windowtext;}
.MsoChpDefault
{mso-style-type:export-only;
font-size:10.0pt;}
@page WordSection1
{size:8.5in 11.0in;
margin:1.0in 1.0in 1.0in 1.0in;}
div.WordSection1
{page:WordSection1;}
--></style></head><body lang=EN-US link=blue vlink=purple><div class=WordSection1><p class=MsoNormal>If you run it on the client, it includes local queuing, network as well as NSD Server processing and the actual device I/O time. <o:p></o:p></p><p class=MsoNormal>if issued on the NSD Server it contains processing and I/O time, the processing shouldn\u2019t really add any overhead but in some cases I have seen it contributing. <o:p></o:p></p><p class=MsoNormal>If you corelate the client and server iohist outputs you can find the server entry based on the tags in the iohist output, this allows you to see exactly how much time was spend on network vs on the server to rule out network as the problem.<o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal>Sven<o:p></o:p></p><p class=MsoNormal><o:p> </o:p></p><p class=MsoNormal><o:p> </o:p></p><div style='border:none;border-top:solid #B5C4DF 1.0pt;padding:3.0pt 0in 0in 0in'><p class=MsoNormal style='margin-left:.5in'><b><span style='font-size:12.0pt;color:black'>From: </span></b><span style='font-size:12.0pt;color:black'><gpfsug-discuss-bounces@spectrumscale.org> on behalf of Aaron Knister <aaron.knister@gmail.com><br><b>Reply-To: </b>gpfsug main discussion list <gpfsug-discuss@spectrumscale.org><br><b>Date: </b>Sunday, February 17, 2019 at 6:26 AM<br><b>To: </b>gpfsug main discussion list <gpfsug-discuss@spectrumscale.org><br><b>Subject: </b>Re: [gpfsug-discuss] Clarification of mmdiag --iohist output<o:p></o:p></span></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><div><div><p class=MsoNormal style='margin-left:.5in'>Hi Kevin,<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>It's funny you bring this up because I was looking at this yesterday. My belief is that it's the time the from when the I/O request was queued internally by the client to when the I/O response was received from the NSD server which means it absolutely includes the network RTT. It would be great to get formal confirmation of this from someone who knows the code.<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>Here's some trace data showing a single 4K read from an NSD client. I've stripped out a bunch of uninteresting stuff. It's my belief that the TRACE_IO indicates the point at which the "i/o timer" reported on by mmdiag --iohist begins ticking. The testing data seems to support this. If I'm correct, the testing data shows that the RDMA I/O to the NSD server occurs within the TRACE_IO timing window. The other thing that makes me believe this, is in my testing the mmdiag --iohist on the client shows an average latency of ~230us for a 4K read whereas mmdiag --iohist on the NSD server appears to show an average latency of ~170us when servicing those 4K reads from the back-end disk (a DDN SFA14KX).<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>0.000218276 37005 TRACE_DISK: doReplicatedRead: da 34:490710888<br>0.000218424 37005 TRACE_IO: QIO: read data tag 743942 108137 ioVecSize 1 1st buf 0x122F000 nsdName S01_DMD_NSD_034 da 34:490710888 nSectors 8 align 0 by iocMBHandler (DioHandlerThread)<br>0.000218566 37005 TRACE_DLEASE: checkLeaseForIO: rc 0<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>0.000218628 37005 TRACE_IO: SIO: ioVecSize 1 1st buf 0x122F000 nsdId 0A011103:5C59DBAC da 34:490710888 nSectors 8 doioP 0x1806994D300 isDaemonAddr 0<br>0.000218672 37005 TRACE_FS: verify4KIO exit: code 4 err 0<br>0.000219106 37005 TRACE_NSD: nsdDoIO enter: read ioVecSize 1 1st bufAddr 0x122F000 nsdId 0A011103:5C59DBAC da 34:490710888 nBytes 4096 isDaemonAddr 0<br>0.000219408 37005 TRACE_GCRYPTO: EncBufPool::getTmpBuf(): bsize=4096 code=205 err=0 bufP=0x180656C1058 outBufP=0x180656C1058 index=0<br>0.000220105 37005 TRACE_TS: sendMessage msg_id 22993695: dest <c0n2> 10.3.17.3 sto03<br>0.000220436 37005 TRACE_RDMA: verbs::verbsSend_i: enter: index 11 cookie 12 node <c0n2> msg_id 22993695 len 92<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>0.000221111 37005 TRACE_RDMA: verbsConn::postSend: currRpcHeadP 0x7F6D7FA106E8 sendType SEND_BUFFER_RPC index 11 cookie 12 threadId 37005 bufferId.index 11<br>0.000221662 37005 TRACE_MUTEX: Waiting on fast condvar for signal 0x7F6D7FA106F8 RdmaSend_NSD_SVC<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><br>0.000426716 16691 TRACE_RDMA: handleRecvComp: success 1 of 1 nWrSuccess 1 index 11 cookie 12 wr_id 0xB0E6E00000000 bufferP 0x7F6D7EEE1700 byte_len 4144<br><br>0.000432140 37005 TRACE_NSD: nsdDoIO_ReadAndCheck: read complete, len 0 status 6 err 0 bufP 0x180656C1058 dioIsOverRdma 1 ioDataP 0x200000BC000 ckSumType NsdCksum_None<br>0.000432163 37005 TRACE_NSD: nsdDoIO_ReadAndCheck: exit err 0<br>0.000433707 37005 TRACE_GCRYPTO: EncBufPool::releaseTmpBuf(): exit bsize=8192 err=0 inBufP=0x180656C1058 bufP=0x180656C1058 index=0<br>0.000433777 37005 TRACE_NSD: nsdDoIO exit: err 0 0<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>0.000433844 37005 TRACE_IO: FIO: read data tag 743942 108137 ioVecSize 1 1st buf 0x122F000 nsdId 0A011103:5C59DBAC da 34:490710888 nSectors 8 err 0<br>0.000434236 37005 TRACE_DISK: postIO: qosid A00D91E read data disk FFFFFFFF ioVecSize 1 1st buf 0x122F000 err 0 duration 0.000215000 by iocMBHandler (DioHandlerThread)<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>I'd suggest looking at "mmdiag --iohist" on the NSD server itself and see if/how that differs from the client. The other thing you could do is see if your NSD server queues are backing up (e.g. "mmfsadm saferdump nsd" and look for "requests pending" on queues where the "active" field is > 0). That doesn't necessarily mean you need to tune your queues but I'd suggest that if the disk I/O on your NSD server looks healthy (e.g. low latency, not overly-taxed) that you could benefit from queue tuning.<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>-Aaron<o:p></o:p></p></div></div></div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p><div><div><p class=MsoNormal style='margin-left:.5in'>On Sat, Feb 16, 2019 at 9:47 AM Buterbaugh, Kevin L <<a href="mailto:Kevin.Buterbaugh@vanderbilt.edu">Kevin.Buterbaugh@vanderbilt.edu</a>> wrote:<o:p></o:p></p></div><blockquote style='border:none;border-left:solid #CCCCCC 1.0pt;padding:0in 0in 0in 6.0pt;margin-left:4.8pt;margin-right:0in'><div><p class=MsoNormal style='margin-left:.5in'>Hi All, <o:p></o:p></p><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>Been reading man pages, docs, and Googling, and haven\u2019t found a definitive answer to this question, so I knew exactly where to turn\u2026 ;-)<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>I\u2019m dealing with some slow I/O\u2019s to certain storage arrays in our environments \u2026 like really, really slow I/O\u2019s \u2026 here\u2019s just one example from one of my NSD servers of a 10 second I/O:<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>08:49:34.943186 W data 30:41615622144 2048 10115.192 srv dm-92 <client IP redacted><o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>So here\u2019s my question \u2026 when mmdiag \u2014iohist tells me that that I/O took slightly over 10 seconds, is that:<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>1. The time from when the NSD server received the I/O request from the client until it shipped the data back onto the wire towards the client?<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>2. The time from when the client issued the I/O request until it received the data back from the NSD server?<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>3. Something else?<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>I\u2019m thinking it\u2019s #1, but want to confirm. Which one it is has very obvious implications for our troubleshooting steps. Thanks in advance\u2026<o:p></o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div><div><p class=MsoNormal style='margin-left:.5in'>Kevin<o:p></o:p></p></div><div><div><div><div><p class=MsoNormal style='margin-left:.5in'><span style='color:black'>\u2014<o:p></o:p></span></p></div><div><p class=MsoNormal style='margin-left:.5in'><span style='color:black'>Kevin Buterbaugh - Senior System Administrator<o:p></o:p></span></p></div><div><p class=MsoNormal style='margin-left:.5in'><span style='color:black'>Vanderbilt University - Advanced Computing Center for Research and Education<o:p></o:p></span></p></div><div><p class=MsoNormal style='margin-left:.5in'><span style='color:black'><a href="mailto:Kevin.Buterbaugh@vanderbilt.edu" target="_blank">Kevin.Buterbaugh@vanderbilt.edu</a> - (615)875-9633<o:p></o:p></span></p></div></div></div><p class=MsoNormal style='margin-left:.5in'><o:p> </o:p></p></div></div><p class=MsoNormal style='margin-left:.5in'>_______________________________________________<br>gpfsug-discuss mailing list<br>gpfsug-discuss at <a href="http://spectrumscale.org" target="_blank">spectrumscale.org</a><br><a href="http://gpfsug.org/mailman/listinfo/gpfsug-discuss" target="_blank">http://gpfsug.org/mailman/listinfo/gpfsug-discuss</a><o:p></o:p></p></blockquote></div><p class=MsoNormal style='margin-left:.5in'>_______________________________________________ gpfsug-discuss mailing list gpfsug-discuss at spectrumscale.org http://gpfsug.org/mailman/listinfo/gpfsug-discuss <o:p></o:p></p></div></body></html>