вт, 26 февр. 2019 г. в 19:28, Steve French <smfrench@xxxxxxxxx>: > > Allow tracing before sending a command (add an smb3_cmd_enter) > on the wire - this allows us to look in much more detail at response > times (between request and response). > > See below sample output from doing > > trace-cmd record -e smb3*cmd* > > in one window and then "trace-cmd show" in another > > # TASK-PID CPU# |||| TIMESTAMP FUNCTION > # | | | |||| | | > mkdir-22002 [001] .... 25557.965367: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=28 > mkdir-22002 [001] .... 25557.965370: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=29 > mkdir-22002 [001] .... 25557.965371: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=30 > mkdir-22002 [002] .... 25557.972623: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=28 > mkdir-22002 [002] .... 25557.972625: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=29 > mkdir-22002 [002] .... 25557.972626: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=30 > rm-22003 [001] .... 25563.125131: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=31 > rm-22003 [001] .... 25563.125134: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=32 > rm-22003 [001] .... 25563.125135: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=33 > rm-22003 [001] .... 25563.134590: smb3_cmd_err: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=31 status=0xc0000034 rc=-2 > rm-22003 [001] .... 25563.134643: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=34 smb3_cmd_enter trace point is called 3 times for mids 31, 32 and 33 and only mid 31 is logged with smb3_cmd_err. This is happening because we skip processing mids in compound_send_recv() once the hit a failure. We need to fix compound_send_recv() to be able to log all the mids in the compounded chain in a case of error but this is out of scope of this patch. > rm-22003 [001] .... 25563.134645: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=35 > rm-22003 [001] .... 25563.134646: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=36 > rm-22003 [001] .... 25563.138544: smb3_cmd_err: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=34 status=0xc0000034 rc=-2 > dd-22004 [005] .... 25567.863084: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=37 > dd-22004 [005] .... 25567.869415: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=37 > dd-22004 [005] .... 25567.869424: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=38 > dd-22004 [005] .... 25567.870319: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=38 > dd-22004 [005] .... 25567.870369: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=17 mid=39 > dd-22004 [005] .... 25567.871073: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=17 mid=39 > dd-22004 [005] .... 25567.871094: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=40 > dd-22004 [005] .... 25567.871095: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=17 mid=41 > dd-22004 [005] .... 25567.871096: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=42 > dd-22004 [006] .... 25567.882760: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=40 > dd-22004 [006] .... 25567.882763: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=17 mid=41 > dd-22004 [006] .... 25567.882764: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=42 > dd-22004 [006] .... 25567.882876: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=43 > cifsd-21979 [007] .... 25567.884150: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=43 > dd-22004 [006] .... 25567.884278: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=44 > cifsd-21979 [007] .... 25567.885189: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=44 > dd-22004 [006] .... 25567.885299: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=45 > cifsd-21979 [007] .... 25567.886174: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=45 > dd-22004 [006] .... 25567.886283: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=46 > cifsd-21979 [007] .... 25567.887145: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=46 > dd-22004 [006] .... 25567.887269: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=47 > dd-22004 [006] .... 25567.889631: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=47 > ls-22009 [005] .... 25613.476023: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=48 > ls-22009 [005] .... 25613.477997: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=48 > ls-22009 [005] .... 25613.478067: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=49 > ls-22009 [006] .... 25613.485037: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=49 > ls-22009 [006] .... 25613.485048: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=14 mid=50 > ls-22009 [006] .... 25613.490983: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=14 mid=50 > ls-22009 [006] .... 25613.491151: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=14 mid=51 > ls-22009 [006] .... 25613.491898: smb3_cmd_err: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=14 mid=51 status=0x80000006 rc=-61 > ls-22009 [006] .... 25613.491947: smb3_cmd_enter: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=52 > ls-22009 [006] .... 25613.494271: smb3_cmd_done: > sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=52 > Thanks, now we have a great tool to start analyzing client latency. The more advanced step would be to start aggregate latency numbers and count percentiles (especially for specific commands). Reviewed-by: Pavel Shilovsky <pshilov@xxxxxxxxxxxxx> -- Best regards, Pavel Shilovsky
