Received: by 10.223.176.46 with SMTP id f43csp448105wra; Fri, 26 Jan 2018 01:18:43 -0800 (PST) X-Google-Smtp-Source: AH8x226SK/mrUSej9NIBFM1BMXCeq4uz4AAZa3oRKXIRBwfSSkKR+voa4n2KgoU+pKh5qeP775cB X-Received: by 10.98.93.157 with SMTP id n29mr18908359pfj.195.1516958323716; Fri, 26 Jan 2018 01:18:43 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1516958323; cv=none; d=google.com; s=arc-20160816; b=N/uQUjMzxPEARdO7PqzDWIG+DEy12hlNExinFIGdEUTyPKPuZfRWni2PJFTljKM6GU TBCQtHZOaV61SbZ6qsgNyJIqEmrm/ozCR97vnkbpVh8b4sncihRyr01UmjAHrNHItG4+ XiUXKtFGIy0NoklVc2s2csK7vzuwclMa4XKBFnPtha3j5ZWQFdCoOb6meh4zF3/c12YC bn7HegtzVX7EaYM9gozjtY/MnIrRfBWWD3V9pc7MBNgTTlDBl1MQYBL6FvXfDL+fZZYJ kd0E4qzUKzM4/JAIx3dc4fZqM41sNRMECSsiaQNaKRI22qQcwavQFD3K59BY+ga9cSuW mV9Q== 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=dRAxQWffN1wYT33PX+F7VwW8idq9kmsUHm/88iZdia0=; b=0u1JPDAFWm0E8LgN9pWjIBzP/eU37n9poxhfrAJBasPQqP1jkjTFiFT2lnQM7YL9DY j+cVS/jHJNW14zVgfAeANuOhN86KE+xAJVcxoyqIhgA5mTHyxRsrazBdZJ+P42z/6ihj HwaeXhhtRnAox+tgrJyvGWT5O7Xfp1YcoDUGXzTrKAS0IObQ01aRFM4FhOvxZfZwuMkr fzJxU/zR4DqwJFek40gi71YZL8wNPZkTTmDFwO2iScsqHNFnZjmlwPy2BXRnfGWwc3bG w5u18dTVQP1vdoR6AbSJc5JXzblWwUwzG8ZYbbbfcz3Q58T70EicHeiXEmu3hijyU1lt NUFA== 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 l21si6009627pff.308.2018.01.26.01.18.28; Fri, 26 Jan 2018 01:18:43 -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 S1752513AbeAZJQ5 (ORCPT + 99 others); Fri, 26 Jan 2018 04:16:57 -0500 Received: from mx2.suse.de ([195.135.220.15]:33801 "EHLO mx2.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752414AbeAZJQi (ORCPT ); Fri, 26 Jan 2018 04:16:38 -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 04095ADE0; Fri, 26 Jan 2018 09:16:35 +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 v8 0/2] add tracepoints for nvme command submission and completion Date: Fri, 26 Jan 2018 10:16:27 +0100 Message-Id: <20180126091629.31829-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 | 127 ++++++++++++++++++++++++++++++++++ drivers/nvme/host/trace.h | 167 +++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 307 insertions(+) create mode 100644 drivers/nvme/host/trace.c create mode 100644 drivers/nvme/host/trace.h -- 2.13.6