scsi: fnic: Adding debug IO and Abort latency counter to fnic stats

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

@@ -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: "
 

drivers/scsi/fnic/fnic_scsi.c

@@ -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,

drivers/scsi/fnic/fnic_stats.h

@@ -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 {

drivers/scsi/fnic/fnic_trace.c

@@ -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"