scsi: fnic: Adding debug IO and Abort latency counter to fnic stats
authorSatish Kharat <satishkh@cisco.com>
Wed, 1 Mar 2017 00:15:59 +0000 (16:15 -0800)
committerMartin K. Petersen <martin.petersen@oracle.com>
Thu, 23 Mar 2017 13:57:23 +0000 (09:57 -0400)
The IO and Abort latency counter counts the time taken to complete the
IO and abort command into broad buckets. This is not intended for
performance measurement, just a debug statistic.  current_max_io_time
tries to keep track of the maximum time an IO has taken to complete if
it is > 30sec.

Signed-off-by: Satish Kharat <satishkh@cisco.com>
Signed-off-by: Sesidhar Baddela <sebaddel@cisco.com>
Signed-off-by: Martin K. Petersen <martin.petersen@oracle.com>
drivers/scsi/fnic/fnic.h
drivers/scsi/fnic/fnic_scsi.c
drivers/scsi/fnic/fnic_stats.h
drivers/scsi/fnic/fnic_trace.c

index 7d5739e437d25d79ac43500ccb071e450cbe00df..67aab965c0f4ff59b247e8e6d88e0a0d08674efe 100644 (file)
@@ -39,7 +39,7 @@
 
 #define DRV_NAME               "fnic"
 #define DRV_DESCRIPTION                "Cisco FCoE HBA Driver"
-#define DRV_VERSION            "1.6.0.21"
+#define DRV_VERSION            "1.6.0.34"
 #define PFX                    DRV_NAME ": "
 #define DFX                     DRV_NAME "%d: "
 
index 190c0663aaf4217ba4596d313368f100304f0686..d048f3b5006f4bccc305087238be4ed7bf49fd33 100644 (file)
@@ -823,6 +823,7 @@ static void fnic_fcpio_icmnd_cmpl_handler(struct fnic *fnic,
        spinlock_t *io_lock;
        u64 cmd_trace;
        unsigned long start_time;
+       unsigned long io_duration_time;
 
        /* Decode the cmpl description to get the io_req id */
        fcpio_header_dec(&desc->hdr, &type, &hdr_status, &tag);
@@ -1016,6 +1017,28 @@ static void fnic_fcpio_icmnd_cmpl_handler(struct fnic *fnic,
        else
                atomic64_inc(&fnic_stats->io_stats.io_completions);
 
+
+       io_duration_time = jiffies_to_msecs(jiffies) - jiffies_to_msecs(io_req->start_time);
+
+       if(io_duration_time <= 10)
+               atomic64_inc(&fnic_stats->io_stats.io_btw_0_to_10_msec);
+       else if(io_duration_time <= 100)
+               atomic64_inc(&fnic_stats->io_stats.io_btw_10_to_100_msec);
+       else if(io_duration_time <= 500)
+               atomic64_inc(&fnic_stats->io_stats.io_btw_100_to_500_msec);
+       else if(io_duration_time <= 5000)
+               atomic64_inc(&fnic_stats->io_stats.io_btw_500_to_5000_msec);
+       else if(io_duration_time <= 10000)
+               atomic64_inc(&fnic_stats->io_stats.io_btw_5000_to_10000_msec);
+       else if(io_duration_time <= 30000)
+               atomic64_inc(&fnic_stats->io_stats.io_btw_10000_to_30000_msec);
+       else {
+               atomic64_inc(&fnic_stats->io_stats.io_greater_than_30000_msec);
+
+               if(io_duration_time > atomic64_read(&fnic_stats->io_stats.current_max_io_time))
+                       atomic64_set(&fnic_stats->io_stats.current_max_io_time, io_duration_time);
+       }
+
        /* Call SCSI completion function to complete the IO */
        if (sc->scsi_done)
                sc->scsi_done(sc);
@@ -1790,6 +1813,7 @@ int fnic_abort_cmd(struct scsi_cmnd *sc)
        struct terminate_stats *term_stats;
        enum fnic_ioreq_state old_ioreq_state;
        int tag;
+       unsigned long abt_issued_time;
        DECLARE_COMPLETION_ONSTACK(tm_done);
 
        /* Wait for rport to unblock */
@@ -1843,6 +1867,25 @@ int fnic_abort_cmd(struct scsi_cmnd *sc)
                spin_unlock_irqrestore(io_lock, flags);
                goto wait_pending;
        }
+
+       abt_issued_time = jiffies_to_msecs(jiffies) - jiffies_to_msecs(io_req->start_time);
+       if (abt_issued_time <= 6000)
+               atomic64_inc(&abts_stats->abort_issued_btw_0_to_6_sec);
+       else if (abt_issued_time > 6000 && abt_issued_time <= 20000)
+               atomic64_inc(&abts_stats->abort_issued_btw_6_to_20_sec);
+       else if (abt_issued_time > 20000 && abt_issued_time <= 30000)
+               atomic64_inc(&abts_stats->abort_issued_btw_20_to_30_sec);
+       else if (abt_issued_time > 30000 && abt_issued_time <= 40000)
+               atomic64_inc(&abts_stats->abort_issued_btw_30_to_40_sec);
+       else if (abt_issued_time > 40000 && abt_issued_time <= 50000)
+               atomic64_inc(&abts_stats->abort_issued_btw_40_to_50_sec);
+       else if (abt_issued_time > 50000 && abt_issued_time <= 60000)
+               atomic64_inc(&abts_stats->abort_issued_btw_50_to_60_sec);
+       else
+               atomic64_inc(&abts_stats->abort_issued_greater_than_60_sec);
+
+       FNIC_SCSI_DBG(KERN_INFO, fnic->lport->host,
+               "CBD Opcode: %02x Abort issued time: %lu msec\n", sc->cmnd[0], abt_issued_time);
        /*
         * Command is still pending, need to abort it
         * If the firmware completes the command after this point,
index 69acdac7fe535932637b5685b5753a2199bd35ce..88c73cccb01511a403a6374b703c4e6263e6d483 100644 (file)
@@ -26,6 +26,14 @@ struct io_path_stats {
        atomic64_t sc_null;
        atomic64_t io_not_found;
        atomic64_t num_ios;
+       atomic64_t io_btw_0_to_10_msec;
+       atomic64_t io_btw_10_to_100_msec;
+       atomic64_t io_btw_100_to_500_msec;
+       atomic64_t io_btw_500_to_5000_msec;
+       atomic64_t io_btw_5000_to_10000_msec;
+       atomic64_t io_btw_10000_to_30000_msec;
+       atomic64_t io_greater_than_30000_msec;
+       atomic64_t current_max_io_time;
 };
 
 struct abort_stats {
@@ -34,6 +42,13 @@ struct abort_stats {
        atomic64_t abort_drv_timeouts;
        atomic64_t abort_fw_timeouts;
        atomic64_t abort_io_not_found;
+       atomic64_t abort_issued_btw_0_to_6_sec;
+       atomic64_t abort_issued_btw_6_to_20_sec;
+       atomic64_t abort_issued_btw_20_to_30_sec;
+       atomic64_t abort_issued_btw_30_to_40_sec;
+       atomic64_t abort_issued_btw_40_to_50_sec;
+       atomic64_t abort_issued_btw_50_to_60_sec;
+       atomic64_t abort_issued_greater_than_60_sec;
 };
 
 struct terminate_stats {
index ec20b3e5784415cfdef7eef712fb4df8db3ce71b..b5ac5381a0d788537f0437cafbe4e5dd7dafe3bd 100644 (file)
@@ -229,7 +229,16 @@ int fnic_get_stats_data(struct stats_debug_info *debug,
                  "Number of IO Failures: %lld\nNumber of IO NOT Found: %lld\n"
                  "Number of Memory alloc Failures: %lld\n"
                  "Number of IOREQ Null: %lld\n"
-                 "Number of SCSI cmd pointer Null: %lld\n",
+                 "Number of SCSI cmd pointer Null: %lld\n"
+
+                 "\nIO completion times: \n"
+                 "            < 10 ms : %lld\n"
+                 "     10 ms - 100 ms : %lld\n"
+                 "    100 ms - 500 ms : %lld\n"
+                 "    500 ms -   5 sec: %lld\n"
+                 "     5 sec -  10 sec: %lld\n"
+                 "    10 sec -  30 sec: %lld\n"
+                 "            > 30 sec: %lld\n",
                  (u64)atomic64_read(&stats->io_stats.active_ios),
                  (u64)atomic64_read(&stats->io_stats.max_active_ios),
                  (u64)atomic64_read(&stats->io_stats.num_ios),
@@ -238,28 +247,58 @@ int fnic_get_stats_data(struct stats_debug_info *debug,
                  (u64)atomic64_read(&stats->io_stats.io_not_found),
                  (u64)atomic64_read(&stats->io_stats.alloc_failures),
                  (u64)atomic64_read(&stats->io_stats.ioreq_null),
-                 (u64)atomic64_read(&stats->io_stats.sc_null));
+                 (u64)atomic64_read(&stats->io_stats.sc_null),
+                 (u64)atomic64_read(&stats->io_stats.io_btw_0_to_10_msec),
+                 (u64)atomic64_read(&stats->io_stats.io_btw_10_to_100_msec),
+                 (u64)atomic64_read(&stats->io_stats.io_btw_100_to_500_msec),
+                 (u64)atomic64_read(&stats->io_stats.io_btw_500_to_5000_msec),
+                 (u64)atomic64_read(&stats->io_stats.io_btw_5000_to_10000_msec),
+                 (u64)atomic64_read(&stats->io_stats.io_btw_10000_to_30000_msec),
+                 (u64)atomic64_read(&stats->io_stats.io_greater_than_30000_msec));
+
+       len += snprintf(debug->debug_buffer + len, buf_size - len,
+                 "\nCurrent Max IO time : %lld\n",
+                 (u64)atomic64_read(&stats->io_stats.current_max_io_time));
 
        len += snprintf(debug->debug_buffer + len, buf_size - len,
                  "\n------------------------------------------\n"
                  "\t\tAbort Statistics\n"
                  "------------------------------------------\n");
+
        len += snprintf(debug->debug_buffer + len, buf_size - len,
                  "Number of Aborts: %lld\n"
                  "Number of Abort Failures: %lld\n"
                  "Number of Abort Driver Timeouts: %lld\n"
                  "Number of Abort FW Timeouts: %lld\n"
-                 "Number of Abort IO NOT Found: %lld\n",
+                 "Number of Abort IO NOT Found: %lld\n"
+
+                 "Abord issued times: \n"
+                 "            < 6 sec : %lld\n"
+                 "     6 sec - 20 sec : %lld\n"
+                 "    20 sec - 30 sec : %lld\n"
+                 "    30 sec - 40 sec : %lld\n"
+                 "    40 sec - 50 sec : %lld\n"
+                 "    50 sec - 60 sec : %lld\n"
+                 "            > 60 sec: %lld\n",
+
                  (u64)atomic64_read(&stats->abts_stats.aborts),
                  (u64)atomic64_read(&stats->abts_stats.abort_failures),
                  (u64)atomic64_read(&stats->abts_stats.abort_drv_timeouts),
                  (u64)atomic64_read(&stats->abts_stats.abort_fw_timeouts),
-                 (u64)atomic64_read(&stats->abts_stats.abort_io_not_found));
+                 (u64)atomic64_read(&stats->abts_stats.abort_io_not_found),
+                 (u64)atomic64_read(&stats->abts_stats.abort_issued_btw_0_to_6_sec),
+                 (u64)atomic64_read(&stats->abts_stats.abort_issued_btw_6_to_20_sec),
+                 (u64)atomic64_read(&stats->abts_stats.abort_issued_btw_20_to_30_sec),
+                 (u64)atomic64_read(&stats->abts_stats.abort_issued_btw_30_to_40_sec),
+                 (u64)atomic64_read(&stats->abts_stats.abort_issued_btw_40_to_50_sec),
+                 (u64)atomic64_read(&stats->abts_stats.abort_issued_btw_50_to_60_sec),
+                 (u64)atomic64_read(&stats->abts_stats.abort_issued_greater_than_60_sec));
 
        len += snprintf(debug->debug_buffer + len, buf_size - len,
                  "\n------------------------------------------\n"
                  "\t\tTerminate Statistics\n"
                  "------------------------------------------\n");
+
        len += snprintf(debug->debug_buffer + len, buf_size - len,
                  "Number of Terminates: %lld\n"
                  "Maximum Terminates: %lld\n"