Received: by 10.223.176.46 with SMTP id f43csp505108wra; Fri, 26 Jan 2018 02:22:48 -0800 (PST) X-Google-Smtp-Source: AH8x225sPkvWbqA2rZkvPU/DjzbNm3uQCP03OGHb6Me9VQzTWixe1FJB5KATdPmN5bW+lj+0xsZF X-Received: by 2002:a17:902:2bc3:: with SMTP id l61-v6mr8608083plb.62.1516962168667; Fri, 26 Jan 2018 02:22:48 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1516962168; cv=none; d=google.com; s=arc-20160816; b=QZDIenauEvio+nTXHE7+rurQTCR+cKSLLDO6K25JZccMOGjzQsyN5Cf9QP+yfE7Gs1 NDJ3RI7D0Za9t7ve5mT+fO70tR/JUNjdq4T6TDUC3leAEECClPLSqK/FdouGl93UqOvE F8kRcA10uG0Hajlx3/y0Y16CaMXhL40HoueycUSDYb29e2jKGrCIpp+6ARnJTAZqsr6H g1t9KfT+quzBb7hXxs7R17N9Ubuqy0luylQeYbiOcs98TH6gTt5UtLGk5/IbRu+FTBeQ 07IvhyrasdNH4qFeb0c5JMfqEQtXes9+4UQJRs7oe+8/6Cit9YH2MTzAzxgaxTHlmFbb TLog== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:sender:message-id:date:subject:cc:to:from :arc-authentication-results; bh=W77rHjeXKvXwfi4NnWOmL8w9bLdCsbBqrImsC+6FFPA=; b=Gu4tBb60OEBNdAccggeDsuyXIcu3gzJWgmNW0XLiKyFipC7vC/FdK9VrQ1ZEAw50uC VSSSdZrGd5MnFPrhohYWdkJ75g/smF20wt61NHYv7RKHv0wA9+yFJ14ARQbrSxsLz4k7 LilVnx8lgQzDBQWGPR0/J3+dvSwt37WmLRwucTA6FiqthaSV3CBWlgkSoFuxJcm3LdNL 6QziBn2bjWpv4nOzpTxmnfkkh6FKlpp5R+JVMJo7iVpjFCmx/4PEFg5tJrFnbqYxR1BU NHEwyip0tFUh0hm5QmpbPtri3CghBJtG8iGafp0GfMGYva71ToJo19xgbCZbX5BifLy1 TPHg== ARC-Authentication-Results: i=1; mx.google.com; spf=pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Return-Path: Received: from vger.kernel.org (vger.kernel.org. [209.132.180.67]) by mx.google.com with ESMTP id s14si2827401pgf.748.2018.01.26.02.22.34; Fri, 26 Jan 2018 02:22:48 -0800 (PST) Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67; Authentication-Results: mx.google.com; spf=pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753159AbeAZKVw (ORCPT + 99 others); Fri, 26 Jan 2018 05:21:52 -0500 Received: from mx2.suse.de ([195.135.220.15]:39119 "EHLO mx2.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752167AbeAZKVu (ORCPT ); Fri, 26 Jan 2018 05:21:50 -0500 X-Virus-Scanned: by amavisd-new at test-mx.suse.de Received: from relay2.suse.de (charybdis-ext.suse.de [195.135.220.254]) by mx2.suse.de (Postfix) with ESMTP id 59915B2FA; Fri, 26 Jan 2018 10:21:48 +0000 (UTC) From: Johannes Thumshirn To: Christoph Hellwig Cc: Sagi Grimberg , Keith Busch , Linux Kernel Mailinglist , Hannes Reinecke , Linux NVMe Mailinglist , "Martin K . Petersen" , Johannes Thumshirn Subject: [PATCH v9 0/2] add tracepoints for nvme command submission and completion Date: Fri, 26 Jan 2018 11:21:36 +0100 Message-Id: <20180126102138.15529-1-jthumshirn@suse.de> X-Mailer: git-send-email 2.13.6 Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Add tracepoints for nvme command submission and completion. The tracepoints are modeled after SCSI's trace_scsi_dispatch_cmd_start() and trace_scsi_dispatch_cmd_done() tracepoints and fulfil a similar purpose, namely a fast way to check which command is going to be queued into the HW or Fabric driver and which command is completed again. Here's an example output using the qemu emulated pci nvme: # tracer: nop # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | kworker/u8:0-5 [003] .... 9.158541: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_cq cqid=1, qsize=1023, cq_flags=0x3, irq_vector=0) -0 [003] d.h. 9.158705: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0 kworker/u8:0-5 [003] .... 9.158712: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_sq sqid=1, qsize=1023, sq_flags=0x1, cqid=1) -0 [003] d.h. 9.159214: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0 kworker/u8:0-5 [003] .... 9.159236: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_cq cqid=2, qsize=1023, cq_flags=0x3, irq_vector=1) -0 [003] d.h. 9.159288: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0 kworker/u8:0-5 [003] .... 9.159293: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_sq sqid=2, qsize=1023, sq_flags=0x1, cqid=2) -0 [003] d.h. 9.159479: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0 kworker/u8:0-5 [003] .... 9.159525: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_cq cqid=3, qsize=1023, cq_flags=0x3, irq_vector=2) -0 [003] d.h. 9.159565: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0 kworker/u8:0-5 [003] .... 9.159569: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_sq sqid=3, qsize=1023, sq_flags=0x1, cqid=3) -0 [003] d.h. 9.159726: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0 kworker/u8:0-5 [003] .... 9.159769: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_cq cqid=4, qsize=1023, cq_flags=0x3, irq_vector=3) -0 [003] d.h. 9.159795: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0 kworker/u8:0-5 [003] .... 9.159799: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_create_sq sqid=4, qsize=1023, sq_flags=0x1, cqid=4) -0 [003] d.h. 9.159957: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0 kworker/u8:0-5 [003] .... 9.160971: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_identify cns=0, ctrlid=1) -0 [003] d.h. 9.161059: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0 kworker/u8:0-5 [003] .... 9.161101: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_identify cns=0, ctrlid=0) -0 [003] d.h. 9.161160: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0 kworker/u8:0-5 [003] .... 9.161305: nvme_setup_admin_cmd: cmdid=14, flags=0x0, meta=0x0, cmd=(nvme_admin_identify cns=0, ctrlid=0) -0 [003] d.h. 9.161344: nvme_complete_rq: cmdid=14, qid=0, res=0, retries=0, flags=0x0, status=0 kworker/u8:0-5 [003] .... 9.161390: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=718, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=0, len=7, ctrl=0x0, dsmgmt=0, reftag=0) -0 [003] d.h. 9.161578: nvme_complete_rq: cmdid=718, qid=1, res=0, retries=0, flags=0x0, status=0 kworker/u8:0-5 [003] .... 9.161608: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=718, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=24, len=7, ctrl=0x0, dsmgmt=0, reftag=0) -0 [003] d.h. 9.161681: nvme_complete_rq: cmdid=718, qid=1, res=0, retries=0, flags=0x0, status=0 dd-205 [001] .... 9.662909: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=1011, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=0, len=2559, ctrl=0x0, dsmgmt=0, reftag=0) dd-205 [001] .... 9.662967: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=1012, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=2560, len=1535, ctrl=0x0, dsmgmt=0, reftag=0) -0 [001] d.h. 9.664413: nvme_complete_rq: cmdid=1011, qid=1, res=0, retries=0, flags=0x0, status=0 -0 [001] d.h. 9.664835: nvme_complete_rq: cmdid=1012, qid=1, res=0, retries=0, flags=0x0, status=0 dd-205 [001] .... 9.666396: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=1012, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=4096, len=2047, ctrl=0x0, dsmgmt=0, reftag=0) dd-205 [001] .... 9.667914: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=1013, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=6144, len=2047, ctrl=0x0, dsmgmt=0, reftag=0) -0 [001] d.h. 9.676720: nvme_complete_rq: cmdid=1012, qid=1, res=0, retries=0, flags=0x0, status=0 dd-205 [001] d.h. 9.676905: nvme_complete_rq: cmdid=1013, qid=1, res=0, retries=0, flags=0x0, status=0 dd-205 [001] .... 9.677552: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=1013, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=8192, len=2047, ctrl=0x0, dsmgmt=0, reftag=0) dd-205 [001] .... 9.678201: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=1014, flags=0x0, meta=0x0, cmd=(nvme_cmd_read slba=10240, len=2047, ctrl=0x0, dsmgmt=0, reftag=0) -0 [001] d.h. 9.678699: nvme_complete_rq: cmdid=1013, qid=1, res=0, retries=0, flags=0x0, status=0 dd-205 [001] d.h. 9.679330: nvme_complete_rq: cmdid=1014, qid=1, res=0, retries=0, flags=0x0, status=0 dd-206 [002] .... 9.687920: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=366, flags=0x0, meta=0x0, cmd=(nvme_cmd_write slba=0, len=2559, ctrl=0x0, dsmgmt=0, reftag=0) dd-206 [002] .... 9.688396: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=367, flags=0x0, meta=0x0, cmd=(nvme_cmd_write slba=2560, len=2559, ctrl=0x0, dsmgmt=0, reftag=0) dd-206 [002] .... 9.689290: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=368, flags=0x0, meta=0x0, cmd=(nvme_cmd_write slba=5120, len=2559, ctrl=0x0, dsmgmt=0, reftag=0) dd-206 [002] .... 9.689759: nvme_setup_nvm_cmd: qid=1, nsid=1, cmdid=369, flags=0x0, meta=0x0, cmd=(nvme_cmd_write slba=7680, len=2559, ctrl=0x0, dsmgmt=0, reftag=0) -0 [002] d.h. 9.690222: nvme_complete_rq: cmdid=366, qid=1, res=0, retries=0, flags=0x0, status=0 -0 [002] d.h. 9.691086: nvme_complete_rq: cmdid=367, qid=1, res=0, retries=0, flags=0x0, status=0 -0 [002] d.h. 9.691935: nvme_complete_rq: cmdid=368, qid=1, res=0, retries=0, flags=0x0, status=0 -0 [002] d.h. 9.692852: nvme_complete_rq: cmdid=369, qid=1, res=0, retries=0, flags=0x0, status=0 Johannes Thumshirn (2): nvme: add tracepoint for nvme_setup_cmd nvme: add tracepoint for nvme_complete_rq drivers/nvme/host/Makefile | 4 ++ drivers/nvme/host/core.c | 9 +++ drivers/nvme/host/trace.c | 130 +++++++++++++++++++++++++++++++++++ drivers/nvme/host/trace.h | 165 +++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 308 insertions(+) create mode 100644 drivers/nvme/host/trace.c create mode 100644 drivers/nvme/host/trace.h -- 2.13.6