From patchwork Wed Feb 27 03:28:35 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steve French X-Patchwork-Id: 1048657 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Authentication-Results: ozlabs.org; spf=none (mailfrom) smtp.mailfrom=vger.kernel.org (client-ip=209.132.180.67; helo=vger.kernel.org; envelope-from=linux-cifs-owner@vger.kernel.org; receiver=) Authentication-Results: ozlabs.org; dmarc=pass (p=none dis=none) header.from=gmail.com Authentication-Results: ozlabs.org; dkim=pass (2048-bit key; unprotected) header.d=gmail.com header.i=@gmail.com header.b="SI1r2Qkw"; dkim-atps=neutral Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by ozlabs.org (Postfix) with ESMTP id 448LkW0ZnYz9s1b for ; Wed, 27 Feb 2019 14:28:51 +1100 (AEDT) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1729291AbfB0D2t (ORCPT ); Tue, 26 Feb 2019 22:28:49 -0500 Received: from mail-pl1-f177.google.com ([209.85.214.177]:34722 "EHLO mail-pl1-f177.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1729128AbfB0D2t (ORCPT ); Tue, 26 Feb 2019 22:28:49 -0500 Received: by mail-pl1-f177.google.com with SMTP id d15so7285183plr.1 for ; Tue, 26 Feb 2019 19:28:48 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:from:date:message-id:subject:to:cc; bh=9x+V0Y+MBnP+xr+Z3KAURtrZoia9c/dZnrGbX/yYHEk=; b=SI1r2QkwfS65+fSpNV6B3AhTDM6ww9oqm18EGCnCAhzjy6wJ8jTW85HR5oxKg88KSZ gYtoym06M1WgziPIDEHiOklSCaD3rLpe5598Jlhp21ykv5K46x+NOqsGbRSJ2Vl2MATL yaNCDLlgtyINPOsZu1QVSwGjWNkDgc73rBfJyOkC/cmHYF56Nu3dEEvElsk8EaR9YMpY vSqPDbb3WfVbRxfBN2qr6nJaiFUCov1tbWkR1ti5br4/t1JfC2u66LCg9XwywX8DagmW yMjVO6bMb8kLCK0TlJ5TisWj4mcJ9S2eJhE37aNOOrnpHyWYhOOPYnjFGsLXOyGK6Cwd p6Rw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:from:date:message-id:subject:to:cc; bh=9x+V0Y+MBnP+xr+Z3KAURtrZoia9c/dZnrGbX/yYHEk=; b=piDn0nhSKOxogOpnKH2gRk+zRfnmalBdXzsSWkKIDgEBEiJueuEzZDbnKdMG8erpIf ShLyZ+Jd4Y6t/oFk7S7qwYozDzN0EuBBPOSjpaGZkoEQoGJsZoXX3Et8XCe0+HIVEkgu RMhnHDKm0UEqDxNg4c5IlEqC/VO7mqxS9f2yo8AOBVUqP8x2waxRRO7UKx4xbjNNLl5E vaQUjSSXT95xlmNvro79uEuwmqqD4Os5thNnfSQDAgSbbR/qG8ft16DKiHFPwYBPYHkS MC4kGk9rlvdnbDSrqe3njI0y76pUOX/acvei4GU/hZ9es0qhfiqVXdjs68jKM79ypWTv NA1g== X-Gm-Message-State: AHQUAuYf9qp+Q1tZHdeWShqCww866Z5Lvn0VNB+KIn8XKNK46INvY9he BCwRD94k3SSQLzdDAMrOkTAhCa4Ur+4RYKB1Fu/ybNYz X-Google-Smtp-Source: AHgI3IbZcQc85q9gdHgj+0bYCUN6Mzy6ke3XN28aIt7TigEl3V6AEt1qLBTGtzKTicX8e4NPi6AzNdG1Pvzqk2BLA8A= X-Received: by 2002:a17:902:e090:: with SMTP id cb16mr28823040plb.32.1551238127172; Tue, 26 Feb 2019 19:28:47 -0800 (PST) MIME-Version: 1.0 From: Steve French Date: Tue, 26 Feb 2019 21:28:35 -0600 Message-ID: Subject: [PATCH] Add a dynamic tracepoint for smb3_cmd_enter To: CIFS Cc: Pavel Shilovsky Sender: linux-cifs-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-cifs@vger.kernel.org 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 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 Reviewed-by: Pavel Shilovsky From 59a164b25656d009d942325e1aba4074a97592f3 Mon Sep 17 00:00:00 2001 From: Steve French Date: Tue, 26 Feb 2019 21:26:20 -0600 Subject: [PATCH] smb3: add dynamic trace point for smb3_cmd_enter Add tracepoint before sending an SMB3 command on the wire (ie add an smb3_cmd_enter tracepoint). This allows us to look in much more detail at response times (between request and response). Signed-off-by: Steve French --- fs/cifs/smb2transport.c | 3 +++ fs/cifs/trace.h | 1 + 2 files changed, 4 insertions(+) diff --git a/fs/cifs/smb2transport.c b/fs/cifs/smb2transport.c index 5609c0b8d5fe..9b1cfd3ed52d 100644 --- a/fs/cifs/smb2transport.c +++ b/fs/cifs/smb2transport.c @@ -600,6 +600,8 @@ smb2_mid_entry_alloc(const struct smb2_sync_hdr *shdr, atomic_inc(&midCount); temp->mid_state = MID_REQUEST_ALLOCATED; + trace_smb3_cmd_enter(shdr->TreeId, shdr->SessionId, + le16_to_cpu(shdr->Command), temp->mid); return temp; } @@ -634,6 +636,7 @@ smb2_get_mid_entry(struct cifs_ses *ses, struct smb2_sync_hdr *shdr, spin_lock(&GlobalMid_Lock); list_add_tail(&(*mid)->qhead, &ses->server->pending_mid_q); spin_unlock(&GlobalMid_Lock); + return 0; } diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h index b6352b68f18b..2a0be3e1927f 100644 --- a/fs/cifs/trace.h +++ b/fs/cifs/trace.h @@ -275,6 +275,7 @@ DEFINE_EVENT(smb3_cmd_done_class, smb3_##name, \ __u64 mid), \ TP_ARGS(tid, sesid, cmd, mid)) +DEFINE_SMB3_CMD_DONE_EVENT(cmd_enter); DEFINE_SMB3_CMD_DONE_EVENT(cmd_done); DEFINE_SMB3_CMD_DONE_EVENT(ses_expired); -- 2.17.1