scsi: lpfc: Make debugfs ktime stats generic for NVME and SCSI

Currently driver ktime stats, measuring code paths, is NVME-specific.

Convert the stats routines such that the code paths are generic, providing
status for NVME and SCSI. Added ktime stat calls in SCSI queuecommand and
cmpl routines.

Link: https://lore.kernel.org/r/20200322181304.37655-11-jsmart2021@gmail.com
Signed-off-by: James Smart <jsmart2021@gmail.com>
Signed-off-by: Dick Kennedy <dick.kennedy@broadcom.com>
Signed-off-by: Martin K. Petersen <martin.petersen@oracle.com>

diff --git a/drivers/scsi/lpfc/lpfc.h b/drivers/scsi/lpfc/lpfc.h
index e4924b9..747eda6 100644 (file)
--- a/drivers/scsi/lpfc/lpfc.h
+++ b/drivers/scsi/lpfc/lpfc.h
@@ -480,7 +480,7 @@ struct lpfc_vport {
        struct dentry *debug_nodelist;
        struct dentry *debug_nvmestat;
        struct dentry *debug_scsistat;
-       struct dentry *debug_nvmektime;
+       struct dentry *debug_ioktime;
        struct dentry *debug_hdwqstat;
        struct dentry *vport_debugfs_root;
        struct lpfc_debugfs_trc *disc_trc;

diff --git a/drivers/scsi/lpfc/lpfc_crtn.h b/drivers/scsi/lpfc/lpfc_crtn.h
index a0ef3ba..76dc8d9 100644 (file)
--- a/drivers/scsi/lpfc/lpfc_crtn.h
+++ b/drivers/scsi/lpfc/lpfc_crtn.h
@@ -588,6 +588,7 @@ struct lpfc_io_buf *lpfc_get_io_buf(struct lpfc_hba *phba,
                                int);
 void lpfc_release_io_buf(struct lpfc_hba *phba, struct lpfc_io_buf *ncmd,
                         struct lpfc_sli4_hdw_queue *qp);
+void lpfc_io_ktime(struct lpfc_hba *phba, struct lpfc_io_buf *ncmd);
 void lpfc_nvme_cmd_template(void);
 void lpfc_nvmet_cmd_template(void);
 void lpfc_nvme_cancel_iocb(struct lpfc_hba *phba, struct lpfc_iocbq *pwqeIn);

diff --git a/drivers/scsi/lpfc/lpfc_debugfs.c b/drivers/scsi/lpfc/lpfc_debugfs.c
index 1b8be10..8a6e02a 100644 (file)
--- a/drivers/scsi/lpfc/lpfc_debugfs.c
+++ b/drivers/scsi/lpfc/lpfc_debugfs.c
@@ -1300,8 +1300,88 @@ buffer_done:
        return len;
 }
 
+void
+lpfc_io_ktime(struct lpfc_hba *phba, struct lpfc_io_buf *lpfc_cmd)
+{
+       uint64_t seg1, seg2, seg3, seg4;
+       uint64_t segsum;
+
+       if (!lpfc_cmd->ts_last_cmd ||
+           !lpfc_cmd->ts_cmd_start ||
+           !lpfc_cmd->ts_cmd_wqput ||
+           !lpfc_cmd->ts_isr_cmpl ||
+           !lpfc_cmd->ts_data_io)
+               return;
+
+       if (lpfc_cmd->ts_data_io < lpfc_cmd->ts_cmd_start)
+               return;
+       if (lpfc_cmd->ts_cmd_start < lpfc_cmd->ts_last_cmd)
+               return;
+       if (lpfc_cmd->ts_cmd_wqput < lpfc_cmd->ts_cmd_start)
+               return;
+       if (lpfc_cmd->ts_isr_cmpl < lpfc_cmd->ts_cmd_wqput)
+               return;
+       if (lpfc_cmd->ts_data_io < lpfc_cmd->ts_isr_cmpl)
+               return;
+       /*
+        * Segment 1 - Time from Last FCP command cmpl is handed
+        * off to NVME Layer to start of next command.
+        * Segment 2 - Time from Driver receives a IO cmd start
+        * from NVME Layer to WQ put is done on IO cmd.
+        * Segment 3 - Time from Driver WQ put is done on IO cmd
+        * to MSI-X ISR for IO cmpl.
+        * Segment 4 - Time from MSI-X ISR for IO cmpl to when
+        * cmpl is handled off to the NVME Layer.
+        */
+       seg1 = lpfc_cmd->ts_cmd_start - lpfc_cmd->ts_last_cmd;
+       if (seg1 > 5000000)  /* 5 ms - for sequential IOs only */
+               seg1 = 0;
+
+       /* Calculate times relative to start of IO */
+       seg2 = (lpfc_cmd->ts_cmd_wqput - lpfc_cmd->ts_cmd_start);
+       segsum = seg2;
+       seg3 = lpfc_cmd->ts_isr_cmpl - lpfc_cmd->ts_cmd_start;
+       if (segsum > seg3)
+               return;
+       seg3 -= segsum;
+       segsum += seg3;
+
+       seg4 = lpfc_cmd->ts_data_io - lpfc_cmd->ts_cmd_start;
+       if (segsum > seg4)
+               return;
+       seg4 -= segsum;
+
+       phba->ktime_data_samples++;
+       phba->ktime_seg1_total += seg1;
+       if (seg1 < phba->ktime_seg1_min)
+               phba->ktime_seg1_min = seg1;
+       else if (seg1 > phba->ktime_seg1_max)
+               phba->ktime_seg1_max = seg1;
+       phba->ktime_seg2_total += seg2;
+       if (seg2 < phba->ktime_seg2_min)
+               phba->ktime_seg2_min = seg2;
+       else if (seg2 > phba->ktime_seg2_max)
+               phba->ktime_seg2_max = seg2;
+       phba->ktime_seg3_total += seg3;
+       if (seg3 < phba->ktime_seg3_min)
+               phba->ktime_seg3_min = seg3;
+       else if (seg3 > phba->ktime_seg3_max)
+               phba->ktime_seg3_max = seg3;
+       phba->ktime_seg4_total += seg4;
+       if (seg4 < phba->ktime_seg4_min)
+               phba->ktime_seg4_min = seg4;
+       else if (seg4 > phba->ktime_seg4_max)
+               phba->ktime_seg4_max = seg4;
+
+       lpfc_cmd->ts_last_cmd = 0;
+       lpfc_cmd->ts_cmd_start = 0;
+       lpfc_cmd->ts_cmd_wqput  = 0;
+       lpfc_cmd->ts_isr_cmpl = 0;
+       lpfc_cmd->ts_data_io = 0;
+}
+
 /**
- * lpfc_debugfs_nvmektime_data - Dump target node list to a buffer
+ * lpfc_debugfs_ioktime_data - Dump target node list to a buffer
  * @vport: The vport to gather target node info from.
  * @buf: The buffer to dump log into.
  * @size: The maximum amount of data to process.
@@ -1314,13 +1394,13 @@ buffer_done:
  * not exceed @size.
  **/
 static int
-lpfc_debugfs_nvmektime_data(struct lpfc_vport *vport, char *buf, int size)
+lpfc_debugfs_ioktime_data(struct lpfc_vport *vport, char *buf, int size)
 {
        struct lpfc_hba   *phba = vport->phba;
        int len = 0;
 
        if (phba->nvmet_support == 0) {
-               /* NVME Initiator */
+               /* Initiator */
                len += scnprintf(buf + len, PAGE_SIZE - len,
                                "ktime %s: Total Samples: %lld\n",
                                (phba->ktime_on ?  "Enabled" : "Disabled"),
@@ -1330,8 +1410,8 @@ lpfc_debugfs_nvmektime_data(struct lpfc_vport *vport, char *buf, int size)
 
                len += scnprintf(
                        buf + len, PAGE_SIZE - len,
-                       "Segment 1: Last NVME Cmd cmpl "
-                       "done -to- Start of next NVME cnd (in driver)\n");
+                       "Segment 1: Last Cmd cmpl "
+                       "done -to- Start of next Cmd (in driver)\n");
                len += scnprintf(
                        buf + len, PAGE_SIZE - len,
                        "avg:%08lld min:%08lld max %08lld\n",
@@ -1341,7 +1421,7 @@ lpfc_debugfs_nvmektime_data(struct lpfc_vport *vport, char *buf, int size)
                        phba->ktime_seg1_max);
                len += scnprintf(
                        buf + len, PAGE_SIZE - len,
-                       "Segment 2: Driver start of NVME cmd "
+                       "Segment 2: Driver start of Cmd "
                        "-to- Firmware WQ doorbell\n");
                len += scnprintf(
                        buf + len, PAGE_SIZE - len,
@@ -1364,7 +1444,7 @@ lpfc_debugfs_nvmektime_data(struct lpfc_vport *vport, char *buf, int size)
                len += scnprintf(
                        buf + len, PAGE_SIZE - len,
                        "Segment 4: MSI-X ISR cmpl -to- "
-                       "NVME cmpl done\n");
+                       "Cmd cmpl done\n");
                len += scnprintf(
                        buf + len, PAGE_SIZE - len,
                        "avg:%08lld min:%08lld max %08lld\n",
@@ -2727,7 +2807,7 @@ lpfc_debugfs_scsistat_write(struct file *file, const char __user *buf,
 }
 
 static int
-lpfc_debugfs_nvmektime_open(struct inode *inode, struct file *file)
+lpfc_debugfs_ioktime_open(struct inode *inode, struct file *file)
 {
        struct lpfc_vport *vport = inode->i_private;
        struct lpfc_debug *debug;
@@ -2738,14 +2818,14 @@ lpfc_debugfs_nvmektime_open(struct inode *inode, struct file *file)
                goto out;
 
         /* Round to page boundary */
-       debug->buffer = kmalloc(LPFC_NVMEKTIME_SIZE, GFP_KERNEL);
+       debug->buffer = kmalloc(LPFC_IOKTIME_SIZE, GFP_KERNEL);
        if (!debug->buffer) {
                kfree(debug);
                goto out;
        }
 
-       debug->len = lpfc_debugfs_nvmektime_data(vport, debug->buffer,
-               LPFC_NVMEKTIME_SIZE);
+       debug->len = lpfc_debugfs_ioktime_data(vport, debug->buffer,
+               LPFC_IOKTIME_SIZE);
 
        debug->i_private = inode->i_private;
        file->private_data = debug;
@@ -2756,8 +2836,8 @@ out:
 }
 
 static ssize_t
-lpfc_debugfs_nvmektime_write(struct file *file, const char __user *buf,
-                            size_t nbytes, loff_t *ppos)
+lpfc_debugfs_ioktime_write(struct file *file, const char __user *buf,
+                          size_t nbytes, loff_t *ppos)
 {
        struct lpfc_debug *debug = file->private_data;
        struct lpfc_vport *vport = (struct lpfc_vport *)debug->i_private;
@@ -5467,13 +5547,13 @@ static const struct file_operations lpfc_debugfs_op_scsistat = {
        .release =      lpfc_debugfs_release,
 };
 
-#undef lpfc_debugfs_op_nvmektime
-static const struct file_operations lpfc_debugfs_op_nvmektime = {
+#undef lpfc_debugfs_op_ioktime
+static const struct file_operations lpfc_debugfs_op_ioktime = {
        .owner =        THIS_MODULE,
-       .open =         lpfc_debugfs_nvmektime_open,
+       .open =         lpfc_debugfs_ioktime_open,
        .llseek =       lpfc_debugfs_lseek,
        .read =         lpfc_debugfs_read,
-       .write =        lpfc_debugfs_nvmektime_write,
+       .write =        lpfc_debugfs_ioktime_write,
        .release =      lpfc_debugfs_release,
 };
 
@@ -6111,11 +6191,16 @@ nvmeio_off:
                goto debug_failed;
        }
 
-       snprintf(name, sizeof(name), "nvmektime");
-       vport->debug_nvmektime =
+       snprintf(name, sizeof(name), "ioktime");
+       vport->debug_ioktime =
                debugfs_create_file(name, 0644,
                                    vport->vport_debugfs_root,
-                                   vport, &lpfc_debugfs_op_nvmektime);
+                                   vport, &lpfc_debugfs_op_ioktime);
+       if (!vport->debug_ioktime) {
+               lpfc_printf_vlog(vport, KERN_ERR, LOG_INIT,
+                                "0815 Cannot create debugfs ioktime\n");
+               goto debug_failed;
+       }
 
        snprintf(name, sizeof(name), "hdwqstat");
        vport->debug_hdwqstat =
@@ -6252,8 +6337,8 @@ lpfc_debugfs_terminate(struct lpfc_vport *vport)
        debugfs_remove(vport->debug_scsistat); /* scsistat */
        vport->debug_scsistat = NULL;
 
-       debugfs_remove(vport->debug_nvmektime); /* nvmektime */
-       vport->debug_nvmektime = NULL;
+       debugfs_remove(vport->debug_ioktime); /* ioktime */
+       vport->debug_ioktime = NULL;
 
        debugfs_remove(vport->debug_hdwqstat); /* hdwqstat */
        vport->debug_hdwqstat = NULL;

diff --git a/drivers/scsi/lpfc/lpfc_debugfs.h b/drivers/scsi/lpfc/lpfc_debugfs.h
index 6643b9b..7ab6d3b 100644 (file)
--- a/drivers/scsi/lpfc/lpfc_debugfs.h
+++ b/drivers/scsi/lpfc/lpfc_debugfs.h
@@ -46,7 +46,7 @@
 
 /* nvmestat output buffer size */
 #define LPFC_NVMESTAT_SIZE 8192
-#define LPFC_NVMEKTIME_SIZE 8192
+#define LPFC_IOKTIME_SIZE 8192
 #define LPFC_NVMEIO_TRC_SIZE 8192
 
 /* scsistat output buffer size */

diff --git a/drivers/scsi/lpfc/lpfc_nvme.c b/drivers/scsi/lpfc/lpfc_nvme.c
index 38936b7..0db052a 100644 (file)
--- a/drivers/scsi/lpfc/lpfc_nvme.c
+++ b/drivers/scsi/lpfc/lpfc_nvme.c
@@ -899,88 +899,6 @@ lpfc_nvme_adj_fcp_sgls(struct lpfc_vport *vport,
        sgl->sge_len = cpu_to_le32(nCmd->rsplen);
 }
 
-#ifdef CONFIG_SCSI_LPFC_DEBUG_FS
-static void
-lpfc_nvme_ktime(struct lpfc_hba *phba,
-               struct lpfc_io_buf *lpfc_ncmd)
-{
-       uint64_t seg1, seg2, seg3, seg4;
-       uint64_t segsum;
-
-       if (!lpfc_ncmd->ts_last_cmd ||
-           !lpfc_ncmd->ts_cmd_start ||
-           !lpfc_ncmd->ts_cmd_wqput ||
-           !lpfc_ncmd->ts_isr_cmpl ||
-           !lpfc_ncmd->ts_data_nvme)
-               return;
-
-       if (lpfc_ncmd->ts_data_nvme < lpfc_ncmd->ts_cmd_start)
-               return;
-       if (lpfc_ncmd->ts_cmd_start < lpfc_ncmd->ts_last_cmd)
-               return;
-       if (lpfc_ncmd->ts_cmd_wqput < lpfc_ncmd->ts_cmd_start)
-               return;
-       if (lpfc_ncmd->ts_isr_cmpl < lpfc_ncmd->ts_cmd_wqput)
-               return;
-       if (lpfc_ncmd->ts_data_nvme < lpfc_ncmd->ts_isr_cmpl)
-               return;
-       /*
-        * Segment 1 - Time from Last FCP command cmpl is handed
-        * off to NVME Layer to start of next command.
-        * Segment 2 - Time from Driver receives a IO cmd start
-        * from NVME Layer to WQ put is done on IO cmd.
-        * Segment 3 - Time from Driver WQ put is done on IO cmd
-        * to MSI-X ISR for IO cmpl.
-        * Segment 4 - Time from MSI-X ISR for IO cmpl to when
-        * cmpl is handled off to the NVME Layer.
-        */
-       seg1 = lpfc_ncmd->ts_cmd_start - lpfc_ncmd->ts_last_cmd;
-       if (seg1 > 5000000)  /* 5 ms - for sequential IOs only */
-               seg1 = 0;
-
-       /* Calculate times relative to start of IO */
-       seg2 = (lpfc_ncmd->ts_cmd_wqput - lpfc_ncmd->ts_cmd_start);
-       segsum = seg2;
-       seg3 = lpfc_ncmd->ts_isr_cmpl - lpfc_ncmd->ts_cmd_start;
-       if (segsum > seg3)
-               return;
-       seg3 -= segsum;
-       segsum += seg3;
-
-       seg4 = lpfc_ncmd->ts_data_nvme - lpfc_ncmd->ts_cmd_start;
-       if (segsum > seg4)
-               return;
-       seg4 -= segsum;
-
-       phba->ktime_data_samples++;
-       phba->ktime_seg1_total += seg1;
-       if (seg1 < phba->ktime_seg1_min)
-               phba->ktime_seg1_min = seg1;
-       else if (seg1 > phba->ktime_seg1_max)
-               phba->ktime_seg1_max = seg1;
-       phba->ktime_seg2_total += seg2;
-       if (seg2 < phba->ktime_seg2_min)
-               phba->ktime_seg2_min = seg2;
-       else if (seg2 > phba->ktime_seg2_max)
-               phba->ktime_seg2_max = seg2;
-       phba->ktime_seg3_total += seg3;
-       if (seg3 < phba->ktime_seg3_min)
-               phba->ktime_seg3_min = seg3;
-       else if (seg3 > phba->ktime_seg3_max)
-               phba->ktime_seg3_max = seg3;
-       phba->ktime_seg4_total += seg4;
-       if (seg4 < phba->ktime_seg4_min)
-               phba->ktime_seg4_min = seg4;
-       else if (seg4 > phba->ktime_seg4_max)
-               phba->ktime_seg4_max = seg4;
-
-       lpfc_ncmd->ts_last_cmd = 0;
-       lpfc_ncmd->ts_cmd_start = 0;
-       lpfc_ncmd->ts_cmd_wqput  = 0;
-       lpfc_ncmd->ts_isr_cmpl = 0;
-       lpfc_ncmd->ts_data_nvme = 0;
-}
-#endif
 
 /**
  * lpfc_nvme_io_cmd_wqe_cmpl - Complete an NVME-over-FCP IO
@@ -1183,9 +1101,9 @@ out_err:
 #ifdef CONFIG_SCSI_LPFC_DEBUG_FS
        if (lpfc_ncmd->ts_cmd_start) {
                lpfc_ncmd->ts_isr_cmpl = pwqeIn->isr_timestamp;
-               lpfc_ncmd->ts_data_nvme = ktime_get_ns();
-               phba->ktime_last_cmd = lpfc_ncmd->ts_data_nvme;
-               lpfc_nvme_ktime(phba, lpfc_ncmd);
+               lpfc_ncmd->ts_data_io = ktime_get_ns();
+               phba->ktime_last_cmd = lpfc_ncmd->ts_data_io;
+               lpfc_io_ktime(phba, lpfc_ncmd);
        }
        if (unlikely(phba->hdwqstat_on & LPFC_CHECK_NVME_IO)) {
                cpu = raw_smp_processor_id();

diff --git a/drivers/scsi/lpfc/lpfc_scsi.c b/drivers/scsi/lpfc/lpfc_scsi.c
index 3caa4fd..ad62fb3 100644 (file)
--- a/drivers/scsi/lpfc/lpfc_scsi.c
+++ b/drivers/scsi/lpfc/lpfc_scsi.c
@@ -4025,6 +4025,14 @@ lpfc_scsi_cmd_iocb_cmpl(struct lpfc_hba *phba, struct lpfc_iocbq *pIocbIn,
        lpfc_cmd->pCmd = NULL;
        spin_unlock(&lpfc_cmd->buf_lock);
 
+#ifdef CONFIG_SCSI_LPFC_DEBUG_FS
+       if (lpfc_cmd->ts_cmd_start) {
+               lpfc_cmd->ts_isr_cmpl = pIocbIn->isr_timestamp;
+               lpfc_cmd->ts_data_io = ktime_get_ns();
+               phba->ktime_last_cmd = lpfc_cmd->ts_data_io;
+               lpfc_io_ktime(phba, lpfc_cmd);
+       }
+#endif
        /* The sdev is not guaranteed to be valid post scsi_done upcall. */
        cmd->scsi_done(cmd);
 
@@ -4497,6 +4505,12 @@ lpfc_queuecommand(struct Scsi_Host *shost, struct scsi_cmnd *cmnd)
        struct lpfc_io_buf *lpfc_cmd;
        struct fc_rport *rport = starget_to_rport(scsi_target(cmnd->device));
        int err, idx;
+#ifdef CONFIG_SCSI_LPFC_DEBUG_FS
+       uint64_t start = 0L;
+
+       if (phba->ktime_on)
+               start = ktime_get_ns();
+#endif
 
        rdata = lpfc_rport_data_from_scsi_device(cmnd->device);
 
@@ -4622,6 +4636,15 @@ lpfc_queuecommand(struct Scsi_Host *shost, struct scsi_cmnd *cmnd)
 #endif
        err = lpfc_sli_issue_iocb(phba, LPFC_FCP_RING,
                                  &lpfc_cmd->cur_iocbq, SLI_IOCB_RET_IOCB);
+#ifdef CONFIG_SCSI_LPFC_DEBUG_FS
+       if (start) {
+               lpfc_cmd->ts_cmd_start = start;
+               lpfc_cmd->ts_last_cmd = phba->ktime_last_cmd;
+               lpfc_cmd->ts_cmd_wqput = ktime_get_ns();
+       } else {
+               lpfc_cmd->ts_cmd_start = 0;
+       }
+#endif
        if (err) {
                lpfc_printf_vlog(vport, KERN_INFO, LOG_FCP,
                                 "3376 FCP could not issue IOCB err %x"

diff --git a/drivers/scsi/lpfc/lpfc_sli.h b/drivers/scsi/lpfc/lpfc_sli.h
index 7bcf922..93d976e 100644 (file)
--- a/drivers/scsi/lpfc/lpfc_sli.h
+++ b/drivers/scsi/lpfc/lpfc_sli.h
@@ -446,6 +446,6 @@ struct lpfc_io_buf {
        uint64_t ts_last_cmd;
        uint64_t ts_cmd_wqput;
        uint64_t ts_isr_cmpl;
-       uint64_t ts_data_nvme;
+       uint64_t ts_data_io;
 #endif
 };