Received: by 10.223.176.46 with SMTP id f43csp455011wra; Wed, 24 Jan 2018 00:30:42 -0800 (PST) X-Google-Smtp-Source: AH8x225k6jnMekccMuZ/ZQjT7Drr2TpOGo1T2TbMdvhXY1e2R9X2cz/osjEwmoSlhKVzQrSQoUzu X-Received: by 10.99.110.10 with SMTP id j10mr10098365pgc.72.1516782642760; Wed, 24 Jan 2018 00:30:42 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1516782642; cv=none; d=google.com; s=arc-20160816; b=qKY5gqnLatoJMHoi/1urD5sgRt2ayEsz6+JyoVJrPnRSLtdNWF9L1cZFUiNOGudL5n lSe+/QDCzJQmF4ja8ijANUSW6AEBsKvI9n7uTRoA3CpVqaPbt+lWg6H2WepVmaJJrJdY IfPA9L7gHdYJizIvnuXyMYh+aQFw1Qw1HrbMZo6yiEjwI8daC1FzxVxR1riBhkpDIbbW v4UKOzmpHWQMBT4O8e870ZHcOK4UG2PE7hAVOx2uHbNvPjXctrFeLFS4/273wNhzZc7l IGTpYkJD0hFsowpRnBpBslZH9heNpFe5p6FwLbBhuOQOm9pyO4Dn8gEjAkiYFkzm3Ul/ kydg== 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=RNwl60M3PCdpcemwUrxKQ2tfyGpgZrF8udL+A4wFefI=; b=QAB5tOmmNlLejZpdQZxihSsZsrZUryvU5aL3/WAygeWK/7ZQ3yhF+Sn/yiPft5uWsh Bajxi/uLeBGsH8/+4xMNpnfP9sIQugJPU5aahLuXVMZAZVDDSmvz0HHXi9XY10KUxG3P vjI5417Fn/wrSeinnzrzCBPCKbkLYKqTSqJJmOJ/qozFNgNbW9Kpt7xgBI+igIJc/Ne+ 8dfJWxrGGIcfH+0YFKP3LiwyBJetExY1GLtpFF4neBHkRuIxjL775VQyRNYQuHq8YFlt +LhLkXULwj+XHx9OmOFfldl4DVIcoXub5w1vDwqZ1myndRqMshgzWefVYt1HgTpWw/p6 EZ6w== 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 e24si1239605pgn.116.2018.01.24.00.30.29; Wed, 24 Jan 2018 00:30:42 -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 S932464AbeAXI2j (ORCPT + 99 others); Wed, 24 Jan 2018 03:28:39 -0500 Received: from mx2.suse.de ([195.135.220.15]:36293 "EHLO mx2.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932085AbeAXI2h (ORCPT ); Wed, 24 Jan 2018 03:28:37 -0500 X-Virus-Scanned: by amavisd-new at test-mx.suse.de Received: from relay1.suse.de (charybdis-ext.suse.de [195.135.220.254]) by mx2.suse.de (Postfix) with ESMTP id 82448ACB2; Wed, 24 Jan 2018 08:28:36 +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 v7 0/2] add tracepoints for nvme command submission and completion Date: Wed, 24 Jan 2018 09:28:26 +0100 Message-Id: <20180124082828.364-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. This version is a re-base onto nvme-4.16. 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 | 131 +++++++++++++++++++++++++++++++++++ drivers/nvme/host/trace.h | 167 +++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 311 insertions(+) create mode 100644 drivers/nvme/host/trace.c create mode 100644 drivers/nvme/host/trace.h -- 2.13.6