Extended latency statistics
authorvlnb <vlnb@d57e44dd-8a1f-0410-8b47-8ef2f437770f>
Tue, 29 Sep 2009 20:35:22 +0000 (20:35 +0000)
committervlnb <vlnb@d57e44dd-8a1f-0410-8b47-8ef2f437770f>
Tue, 29 Sep 2009 20:35:22 +0000 (20:35 +0000)
git-svn-id: https://scst.svn.sourceforge.net/svnroot/scst/trunk@1157 d57e44dd-8a1f-0410-8b47-8ef2f437770f

scst/include/scst.h
scst/src/dev_handlers/scst_user.c
scst/src/scst_lib.c
scst/src/scst_priv.h
scst/src/scst_proc.c
scst/src/scst_targ.c

index 303285b..7027c38 100644 (file)
@@ -1029,30 +1029,34 @@ struct scst_tgt {
 #define        TGT_DEV_HASH_SIZE       (1 << TGT_DEV_HASH_SHIFT)
 #define        HASH_VAL(_val)          (_val & (TGT_DEV_HASH_SIZE - 1))
 
-#ifdef CONFIG_SCST_MEASURE_LATENCY_EXT
-/*define the structure for extended latency statistics*/
-struct scst_latency_stat {
-       uint64_t scst_time_wr;
-       uint64_t scst_time_rd;
-       uint64_t processing_time_wr;
-       uint64_t processing_time_rd;
-       unsigned int processed_cmds_wr;
+#ifdef CONFIG_SCST_MEASURE_LATENCY
+
+/* Defines extended latency statistics */
+struct scst_ext_latency_stat {
+       uint64_t scst_time_rd, tgt_time_rd, dev_time_rd;
        unsigned int processed_cmds_rd;
+       uint64_t min_scst_time_rd, min_tgt_time_rd, min_dev_time_rd;
+       uint64_t max_scst_time_rd, max_tgt_time_rd, max_dev_time_rd;
+
+       uint64_t scst_time_wr, tgt_time_wr, dev_time_wr;
+       unsigned int processed_cmds_wr;
+       uint64_t min_scst_time_wr, min_tgt_time_wr, min_dev_time_wr;
+       uint64_t max_scst_time_wr, max_tgt_time_wr, max_dev_time_wr;
 };
 
-#define SCST_IO_SIZE_THRESHOLD_SMALL (8*1024)
-#define SCST_IO_SIZE_THRESHOLD_MEDIUM (32*1024)
-#define SCST_IO_SIZE_THRESHOLD_LARGE (128*1024)
-#define SCST_IO_SIZE_THRESHOLD_VERY_LARGE (512*1024)
+#define SCST_IO_SIZE_THRESHOLD_SMALL           (8*1024)
+#define SCST_IO_SIZE_THRESHOLD_MEDIUM          (32*1024)
+#define SCST_IO_SIZE_THRESHOLD_LARGE           (128*1024)
+#define SCST_IO_SIZE_THRESHOLD_VERY_LARGE      (512*1024)
 
-#define SCST_LATENCY_STAT_INDEX_SMALL 0
-#define SCST_LATENCY_STAT_INDEX_MEDIUM 1
-#define SCST_LATENCY_STAT_INDEX_LARGE 2
-#define SCST_LATENCY_STAT_INDEX_VERY_LARGE 3
-#define SCST_LATENCY_STAT_INDEX_OTHER 4
-#define SCST_LATENCY_NUM_OF_THRESHOLDS 5
+#define SCST_LATENCY_STAT_INDEX_SMALL          0
+#define SCST_LATENCY_STAT_INDEX_MEDIUM         1
+#define SCST_LATENCY_STAT_INDEX_LARGE          2
+#define SCST_LATENCY_STAT_INDEX_VERY_LARGE     3
+#define SCST_LATENCY_STAT_INDEX_OTHER          4
+#define SCST_LATENCY_STATS_NUM         (SCST_LATENCY_STAT_INDEX_OTHER + 1)
 
-#endif
+#endif /* CONFIG_SCST_MEASURE_LATENCY */
 
 struct scst_session {
        /*
@@ -1149,13 +1153,17 @@ struct scst_session {
                                int result);
        void (*unreg_done_fn) (struct scst_session *sess);
 
-#ifdef CONFIG_SCST_MEASURE_LATENCY /* must be last */
-       spinlock_t meas_lock;
-       uint64_t scst_time, processing_time;
+#ifdef CONFIG_SCST_MEASURE_LATENCY
+       /*
+        * Must be the last to allow to work with drivers who don't know
+        * about this config time option.
+        */
+       spinlock_t lat_lock;
+       uint64_t scst_time, tgt_time, dev_time;
        unsigned int processed_cmds;
-#ifdef CONFIG_SCST_MEASURE_LATENCY_EXT
-       struct scst_latency_stat latency_stat[SCST_LATENCY_NUM_OF_THRESHOLDS];
-#endif
+       uint64_t min_scst_time, min_tgt_time, min_dev_time;
+       uint64_t max_scst_time, max_tgt_time, max_dev_time;
+       struct scst_ext_latency_stat sess_latency_stat[SCST_LATENCY_STATS_NUM];
 #endif
 };
 
@@ -1449,8 +1457,15 @@ struct scst_cmd {
 
        struct scst_cmd *orig_cmd; /* Used to issue REQUEST SENSE */
 
-#ifdef CONFIG_SCST_MEASURE_LATENCY /* must be last */
-       uint64_t start, pre_exec_finish, post_exec_start;
+#ifdef CONFIG_SCST_MEASURE_LATENCY
+       /*
+        * Must be the last to allow to work with drivers who don't know
+        * about this config time option.
+        */
+       uint64_t start, curr_start, parse_time, alloc_buf_time;
+       uint64_t restart_waiting_time, rdy_to_xfer_time;
+       uint64_t pre_exec_time, exec_time, dev_done_time;
+       uint64_t xmit_time, tgt_on_free_time, dev_on_free_time;
 #endif
 };
 
@@ -1732,6 +1747,18 @@ struct scst_tgt_dev {
         */
        unsigned short tgt_dev_valid_sense_len;
        uint8_t tgt_dev_sense[SCST_SENSE_BUFFERSIZE];
+
+#ifdef CONFIG_SCST_MEASURE_LATENCY
+       /*
+        * Must be the last to allow to work with drivers who don't know
+        * about this config time option.
+        *
+        * Protected by sess->lat_lock.
+        */
+       uint64_t scst_time, tgt_time, dev_time;
+       unsigned int processed_cmds;
+       struct scst_ext_latency_stat dev_latency_stat[SCST_LATENCY_STATS_NUM];
+#endif
 };
 
 /*
@@ -2955,6 +2982,13 @@ void scst_resume_activity(void);
  */
 void scst_process_active_cmd(struct scst_cmd *cmd, bool atomic);
 
+/*
+ * SCST commands processing routine, which should be called by dev handler
+ * after its parse() callback returned SCST_CMD_STATE_STOP. Arguments
+ * the same as for scst_process_active_cmd().
+ */
+void scst_post_parse_process_active_cmd(struct scst_cmd *cmd, bool atomic);
+
 /*
  * Checks if command can be executed (reservations, etc.) or there are local
  * events, like pending UAs. Returns < 0 if command must be aborted, > 0 if
index 4eb7a65..b60760d 100644 (file)
@@ -1190,7 +1190,7 @@ static int dev_user_process_reply_alloc(struct scst_user_cmd *ucmd,
        }
 
 out_process:
-       scst_process_active_cmd(cmd, false);
+       scst_post_parse_process_active_cmd(cmd, false);
 
        TRACE_EXIT_RES(res);
        return res;
@@ -1240,7 +1240,7 @@ static int dev_user_process_reply_parse(struct scst_user_cmd *ucmd,
                cmd->op_flags |= SCST_WRITE_MEDIUM;
 
 out_process:
-       scst_process_active_cmd(cmd, false);
+       scst_post_parse_process_active_cmd(cmd, false);
 
        TRACE_EXIT_RES(res);
        return res;
index 70a0bfd..646e046 100644 (file)
@@ -2311,7 +2311,7 @@ struct scst_session *scst_alloc_session(struct scst_tgt *tgt, gfp_t gfp_mask,
 #endif
 
 #ifdef CONFIG_SCST_MEASURE_LATENCY
-       spin_lock_init(&sess->meas_lock);
+       spin_lock_init(&sess->lat_lock);
 #endif
 
        len = strlen(initiator_name);
@@ -2509,7 +2509,9 @@ void scst_free_cmd(struct scst_cmd *cmd)
 
        if (cmd->tgtt->on_free_cmd != NULL) {
                TRACE_DBG("Calling target's on_free_cmd(%p)", cmd);
+               scst_set_cur_start(cmd);
                cmd->tgtt->on_free_cmd(cmd);
+               scst_set_tgt_on_free_time(cmd);
                TRACE_DBG("%s", "Target's on_free_cmd() returned");
        }
 
@@ -2517,8 +2519,10 @@ void scst_free_cmd(struct scst_cmd *cmd)
                struct scst_dev_type *handler = cmd->dev->handler;
                if (handler->on_free_cmd != NULL) {
                        TRACE_DBG("Calling dev handler %s on_free_cmd(%p)",
-                             handler->name, cmd);
+                               handler->name, cmd);
+                       scst_set_cur_start(cmd);
                        handler->on_free_cmd(cmd);
+                       scst_set_dev_on_free_time(cmd);
                        TRACE_DBG("Dev handler %s on_free_cmd() returned",
                                handler->name);
                }
@@ -5748,3 +5752,247 @@ out_unlock:
        return;
 }
 #endif /* CONFIG_SCST_DEBUG_SN */
+
+#ifdef CONFIG_SCST_MEASURE_LATENCY
+
+static uint64_t scst_get_nsec(void)
+{
+       struct timespec ts;
+       ktime_get_ts(&ts);
+       return (uint64_t)ts.tv_sec * 1000000000 + ts.tv_nsec;
+}
+
+void scst_set_start_time(struct scst_cmd *cmd)
+{
+       cmd->start = scst_get_nsec();
+       TRACE_DBG("cmd %p: start %lld", cmd, cmd->start);
+}
+
+void scst_set_cur_start(struct scst_cmd *cmd)
+{
+       cmd->curr_start = scst_get_nsec();
+       TRACE_DBG("cmd %p: cur_start %lld", cmd, cmd->curr_start);
+}
+
+void scst_set_parse_time(struct scst_cmd *cmd)
+{
+       cmd->parse_time += scst_get_nsec() - cmd->curr_start;
+       TRACE_DBG("cmd %p: parse_time %lld", cmd, cmd->parse_time);
+}
+
+void scst_set_alloc_buf_time(struct scst_cmd *cmd)
+{
+       cmd->alloc_buf_time += scst_get_nsec() - cmd->curr_start;
+       TRACE_DBG("cmd %p: alloc_buf_time %lld", cmd, cmd->alloc_buf_time);
+}
+
+void scst_set_restart_waiting_time(struct scst_cmd *cmd)
+{
+       cmd->restart_waiting_time += scst_get_nsec() - cmd->curr_start;
+       TRACE_DBG("cmd %p: restart_waiting_time %lld", cmd,
+               cmd->restart_waiting_time);
+}
+
+void scst_set_rdy_to_xfer_time(struct scst_cmd *cmd)
+{
+       cmd->rdy_to_xfer_time += scst_get_nsec() - cmd->curr_start;
+       TRACE_DBG("cmd %p: rdy_to_xfer_time %lld", cmd, cmd->rdy_to_xfer_time);
+}
+
+void scst_set_pre_exec_time(struct scst_cmd *cmd)
+{
+       cmd->pre_exec_time += scst_get_nsec() - cmd->curr_start;
+       TRACE_DBG("cmd %p: pre_exec_time %lld", cmd, cmd->pre_exec_time);
+}
+
+void scst_set_exec_time(struct scst_cmd *cmd)
+{
+       cmd->exec_time += scst_get_nsec() - cmd->curr_start;
+       TRACE_DBG("cmd %p: exec_time %lld", cmd, cmd->exec_time);
+}
+
+void scst_set_dev_done_time(struct scst_cmd *cmd)
+{
+       cmd->dev_done_time += scst_get_nsec() - cmd->curr_start;
+       TRACE_DBG("cmd %p: dev_done_time %lld", cmd, cmd->dev_done_time);
+}
+
+void scst_set_xmit_time(struct scst_cmd *cmd)
+{
+       cmd->xmit_time += scst_get_nsec() - cmd->curr_start;
+       TRACE_DBG("cmd %p: xmit_time %lld", cmd, cmd->xmit_time);
+}
+
+void scst_set_tgt_on_free_time(struct scst_cmd *cmd)
+{
+       cmd->tgt_on_free_time += scst_get_nsec() - cmd->curr_start;
+       TRACE_DBG("cmd %p: tgt_on_free_time %lld", cmd, cmd->tgt_on_free_time);
+}
+
+void scst_set_dev_on_free_time(struct scst_cmd *cmd)
+{
+       cmd->dev_on_free_time += scst_get_nsec() - cmd->curr_start;
+       TRACE_DBG("cmd %p: dev_on_free_time %lld", cmd, cmd->dev_on_free_time);
+}
+
+void scst_update_lat_stats(struct scst_cmd *cmd)
+{
+       uint64_t finish, scst_time, tgt_time, dev_time;
+       struct scst_session *sess = cmd->sess;
+       int data_len;
+       int i;
+       struct scst_ext_latency_stat *latency_stat, *dev_latency_stat;
+
+       finish = scst_get_nsec();
+
+       /* Determine the IO size for extended latency statistics */
+       data_len = cmd->bufflen;
+       i = SCST_LATENCY_STAT_INDEX_OTHER;
+       if (data_len <= SCST_IO_SIZE_THRESHOLD_SMALL)
+               i = SCST_LATENCY_STAT_INDEX_SMALL;
+       else if (data_len <= SCST_IO_SIZE_THRESHOLD_MEDIUM)
+               i = SCST_LATENCY_STAT_INDEX_MEDIUM;
+       else if (data_len <= SCST_IO_SIZE_THRESHOLD_LARGE)
+               i = SCST_LATENCY_STAT_INDEX_LARGE;
+       else if (data_len <= SCST_IO_SIZE_THRESHOLD_VERY_LARGE)
+               i = SCST_LATENCY_STAT_INDEX_VERY_LARGE;
+       latency_stat = &sess->sess_latency_stat[i];
+       dev_latency_stat = &cmd->tgt_dev->dev_latency_stat[i];
+
+       spin_lock_bh(&sess->lat_lock);
+
+       /* Calculate the latencies */
+       scst_time = finish - cmd->start - (cmd->parse_time +
+               cmd->alloc_buf_time + cmd->restart_waiting_time +
+               cmd->rdy_to_xfer_time + cmd->pre_exec_time +
+               cmd->exec_time + cmd->dev_done_time + cmd->xmit_time +
+               cmd->tgt_on_free_time + cmd->dev_on_free_time);
+       tgt_time = cmd->alloc_buf_time + cmd->restart_waiting_time +
+               cmd->rdy_to_xfer_time + cmd->pre_exec_time +
+               cmd->xmit_time + cmd->tgt_on_free_time;
+       dev_time = cmd->parse_time + cmd->exec_time + cmd->dev_done_time +
+               cmd->dev_on_free_time;
+
+       /* Save the basic latency information */
+       sess->scst_time += scst_time;
+       sess->tgt_time += tgt_time;
+       sess->dev_time += dev_time;
+       sess->processed_cmds++;
+
+       if ((sess->min_scst_time == 0) ||
+           (sess->min_scst_time > scst_time))
+               sess->min_scst_time = scst_time;
+       if ((sess->min_tgt_time == 0) ||
+           (sess->min_tgt_time > tgt_time))
+               sess->min_tgt_time = tgt_time;
+       if ((sess->min_dev_time == 0) ||
+           (sess->min_dev_time > dev_time))
+               sess->min_dev_time = dev_time;
+
+       if (sess->max_scst_time < scst_time)
+               sess->max_scst_time = scst_time;
+       if (sess->max_tgt_time < tgt_time)
+               sess->max_tgt_time = tgt_time;
+       if (sess->max_dev_time < dev_time)
+               sess->max_dev_time = dev_time;
+
+       /* Save the extended latency information */
+       if (cmd->data_direction == SCST_DATA_READ) {
+               latency_stat->scst_time_rd += scst_time;
+               latency_stat->tgt_time_rd += tgt_time;
+               latency_stat->dev_time_rd += dev_time;
+               latency_stat->processed_cmds_rd++;
+
+               if ((latency_stat->min_scst_time_rd == 0) ||
+                   (latency_stat->min_scst_time_rd > scst_time))
+                       latency_stat->min_scst_time_rd = scst_time;
+               if ((latency_stat->min_tgt_time_rd == 0) ||
+                   (latency_stat->min_tgt_time_rd > tgt_time))
+                       latency_stat->min_tgt_time_rd = tgt_time;
+               if ((latency_stat->min_dev_time_rd == 0) ||
+                   (latency_stat->min_dev_time_rd > dev_time))
+                       latency_stat->min_dev_time_rd = dev_time;
+
+               if (latency_stat->max_scst_time_rd < scst_time)
+                       latency_stat->max_scst_time_rd = scst_time;
+               if (latency_stat->max_tgt_time_rd < tgt_time)
+                       latency_stat->max_tgt_time_rd = tgt_time;
+               if (latency_stat->max_dev_time_rd < dev_time)
+                       latency_stat->max_dev_time_rd = dev_time;
+
+               dev_latency_stat->scst_time_rd += scst_time;
+               dev_latency_stat->tgt_time_rd += tgt_time;
+               dev_latency_stat->dev_time_rd += dev_time;
+               dev_latency_stat->processed_cmds_rd++;
+
+               if ((dev_latency_stat->min_scst_time_rd == 0) ||
+                   (dev_latency_stat->min_scst_time_rd > scst_time))
+                       dev_latency_stat->min_scst_time_rd = scst_time;
+               if ((dev_latency_stat->min_tgt_time_rd == 0) ||
+                   (dev_latency_stat->min_tgt_time_rd > tgt_time))
+                       dev_latency_stat->min_tgt_time_rd = tgt_time;
+               if ((dev_latency_stat->min_dev_time_rd == 0) ||
+                   (dev_latency_stat->min_dev_time_rd > dev_time))
+                       dev_latency_stat->min_dev_time_rd = dev_time;
+
+               if (dev_latency_stat->max_scst_time_rd < scst_time)
+                       dev_latency_stat->max_scst_time_rd = scst_time;
+               if (dev_latency_stat->max_tgt_time_rd < tgt_time)
+                       dev_latency_stat->max_tgt_time_rd = tgt_time;
+               if (dev_latency_stat->max_dev_time_rd < dev_time)
+                       dev_latency_stat->max_dev_time_rd = dev_time;
+       } else if (cmd->data_direction == SCST_DATA_WRITE) {
+               latency_stat->scst_time_wr += scst_time;
+               latency_stat->tgt_time_wr += tgt_time;
+               latency_stat->dev_time_wr += dev_time;
+               latency_stat->processed_cmds_wr++;
+
+               if ((latency_stat->min_scst_time_wr == 0) ||
+                   (latency_stat->min_scst_time_wr > scst_time))
+                       latency_stat->min_scst_time_wr = scst_time;
+               if ((latency_stat->min_tgt_time_wr == 0) ||
+                   (latency_stat->min_tgt_time_wr > tgt_time))
+                       latency_stat->min_tgt_time_wr = tgt_time;
+               if ((latency_stat->min_dev_time_wr == 0) ||
+                   (latency_stat->min_dev_time_wr > dev_time))
+                       latency_stat->min_dev_time_wr = dev_time;
+
+               if (latency_stat->max_scst_time_wr < scst_time)
+                       latency_stat->max_scst_time_wr = scst_time;
+               if (latency_stat->max_tgt_time_wr < tgt_time)
+                       latency_stat->max_tgt_time_wr = tgt_time;
+               if (latency_stat->max_dev_time_wr < dev_time)
+                       latency_stat->max_dev_time_wr = dev_time;
+
+               dev_latency_stat->scst_time_wr += scst_time;
+               dev_latency_stat->tgt_time_wr += tgt_time;
+               dev_latency_stat->dev_time_wr += dev_time;
+               dev_latency_stat->processed_cmds_wr++;
+
+               if ((dev_latency_stat->min_scst_time_wr == 0) ||
+                   (dev_latency_stat->min_scst_time_wr > scst_time))
+                       dev_latency_stat->min_scst_time_wr = scst_time;
+               if ((dev_latency_stat->min_tgt_time_wr == 0) ||
+                   (dev_latency_stat->min_tgt_time_wr > tgt_time))
+                       dev_latency_stat->min_tgt_time_wr = tgt_time;
+               if ((dev_latency_stat->min_dev_time_wr == 0) ||
+                   (dev_latency_stat->min_dev_time_wr > dev_time))
+                       dev_latency_stat->min_dev_time_wr = dev_time;
+
+               if (dev_latency_stat->max_scst_time_wr < scst_time)
+                       dev_latency_stat->max_scst_time_wr = scst_time;
+               if (dev_latency_stat->max_tgt_time_wr < tgt_time)
+                       dev_latency_stat->max_tgt_time_wr = tgt_time;
+               if (dev_latency_stat->max_dev_time_wr < dev_time)
+                       dev_latency_stat->max_dev_time_wr = dev_time;
+       }
+
+       spin_unlock_bh(&sess->lat_lock);
+
+       TRACE_DBG("cmd %p: finish %lld, scst_time %lld, "
+               "tgt_time %lld, dev_time %lld", cmd, finish, scst_time,
+               tgt_time, dev_time);
+       return;
+}
+
+#endif /* CONFIG_SCST_MEASURE_LATENCY */
index 154466a..305a59e 100644 (file)
@@ -594,4 +594,38 @@ static inline int scst_sn_before(__u32 seq1, __u32 seq2)
        return (__s32)(seq1-seq2) < 0;
 }
 
+#ifdef CONFIG_SCST_MEASURE_LATENCY
+
+void scst_set_start_time(struct scst_cmd *cmd);
+void scst_set_cur_start(struct scst_cmd *cmd);
+void scst_set_parse_time(struct scst_cmd *cmd);
+void scst_set_alloc_buf_time(struct scst_cmd *cmd);
+void scst_set_restart_waiting_time(struct scst_cmd *cmd);
+void scst_set_rdy_to_xfer_time(struct scst_cmd *cmd);
+void scst_set_pre_exec_time(struct scst_cmd *cmd);
+void scst_set_exec_time(struct scst_cmd *cmd);
+void scst_set_dev_done_time(struct scst_cmd *cmd);
+void scst_set_xmit_time(struct scst_cmd *cmd);
+void scst_set_tgt_on_free_time(struct scst_cmd *cmd);
+void scst_set_dev_on_free_time(struct scst_cmd *cmd);
+void scst_update_lat_stats(struct scst_cmd *cmd);
+
+#else
+
+static inline void scst_set_start_time(struct scst_cmd *cmd) {}
+static inline void scst_set_cur_start(struct scst_cmd *cmd) {}
+static inline void scst_set_parse_time(struct scst_cmd *cmd) {}
+static inline void scst_set_alloc_buf_time(struct scst_cmd *cmd) {}
+static inline void scst_set_restart_waiting_time(struct scst_cmd *cmd) {}
+static inline void scst_set_rdy_to_xfer_time(struct scst_cmd *cmd) {}
+static inline void scst_set_pre_exec_time(struct scst_cmd *cmd) {}
+static inline void scst_set_exec_time(struct scst_cmd *cmd) {}
+static inline void scst_set_dev_done_time(struct scst_cmd *cmd) {}
+static inline void scst_set_xmit_time(struct scst_cmd *cmd) {}
+static inline void scst_set_tgt_on_free_time(struct scst_cmd *cmd) {}
+static inline void scst_set_dev_on_free_time(struct scst_cmd *cmd) {}
+static inline void scst_update_lat_stats(struct scst_cmd *cmd) {}
+
+#endif /* CONFIG_SCST_MEASURE_LATENCY */
+
 #endif /* __SCST_PRIV_H */
index ca0598d..df7d829 100644 (file)
@@ -412,117 +412,240 @@ out:
 
 #ifdef CONFIG_SCST_MEASURE_LATENCY
 
-#ifdef CONFIG_SCST_MEASURE_LATENCY_EXT
 static char *scst_io_size_names[] = { "<=8K  ",
                                      "<=32K ",
                                      "<=128K",
                                      "<=512K",
                                      ">512K " };
-#endif
 
 static int lat_info_show(struct seq_file *seq, void *v)
 {
        int res = 0;
        struct scst_acg *acg;
        struct scst_session *sess;
+       char buf[50];
 
        TRACE_ENTRY();
 
+       BUILD_BUG_ON(SCST_LATENCY_STATS_NUM != ARRAY_SIZE(scst_io_size_names));
+       BUILD_BUG_ON(SCST_LATENCY_STATS_NUM != ARRAY_SIZE(sess->sess_latency_stat));
+
        if (mutex_lock_interruptible(&scst_mutex) != 0) {
                res = -EINTR;
                goto out;
        }
 
-       seq_printf(seq, "%-30s %-15s %-15s %-15s\n",
-                  "T-L names",
-                  "Total commands",
-                  "SCST latenct",
-                  "Processing latency (ns)");
-
        list_for_each_entry(acg, &scst_acg_list, scst_acg_list_entry) {
+               bool header_printed = false;
+
                list_for_each_entry(sess, &acg->acg_sess_list,
                                acg_sess_list_entry) {
-                       unsigned long proc_lat = 0, scst_lat = 0;
-                       uint64_t proc_time, scst_time;
-                       unsigned int processed_cmds;
-#ifdef CONFIG_SCST_MEASURE_LATENCY_EXT
-                       uint64_t proc_time_rd, scst_time_rd;
-                       unsigned int processed_cmds_rd;
                        unsigned int i;
-                       struct scst_latency_stat *latency_stat;
-#endif
+                       int t;
+                       uint64_t scst_time, tgt_time, dev_time;
+                       unsigned int processed_cmds;
+
+                       if (!header_printed) {
+                               seq_printf(seq, "%-15s %-15s %-34s %-34s %-34s\n",
+                                       "T-L names", "Total commands", "SCST latency",
+                                       "Target latency", "Dev latency (min/avg/max ns)");
+                               header_printed = true;
+                       }
 
-                       seq_printf(seq,
-                                  "Target name: %s \nInitiator name: %s\n",
+                       seq_printf(seq, "Target name: %s\nInitiator name: %s\n",
                                   sess->tgt->tgtt->name,
                                   sess->initiator_name);
 
-                       spin_lock_bh(&sess->meas_lock);
-#ifdef CONFIG_SCST_MEASURE_LATENCY_EXT
-                       for (i = 0; i <= SCST_LATENCY_STAT_INDEX_OTHER ; i++) {
-                               latency_stat = &sess->latency_stat[i];
-                               proc_time =
-                                       latency_stat->processing_time_wr;
-                               proc_time_rd =
-                                       latency_stat->processing_time_rd;
-                               scst_time =
-                                       latency_stat->scst_time_wr;
-                               scst_time_rd =
-                                       latency_stat->scst_time_rd;
-                               processed_cmds =
-                                       latency_stat->processed_cmds_wr;
-                               processed_cmds_rd =
-                                       latency_stat->processed_cmds_rd;
-
-                               seq_printf(seq,
-                                          "%-5s %-24s %-15ld %-15ld %-15ld\n",
-                                          "Write",
-                                          scst_io_size_names[i],
-                                          (unsigned long)processed_cmds,
-                                          (unsigned long)scst_time,
-                                          (unsigned long)proc_time);
-                               seq_printf(seq,
-                                          "%-5s %-24s %-15ld %-15ld %-15ld\n",
-                                          "Read",
-                                          scst_io_size_names[i],
-                                          (unsigned long)processed_cmds_rd,
-                                          (unsigned long)scst_time_rd,
-                                          (unsigned long)proc_time_rd);
-                       }
-#endif
-                       proc_time = sess->processing_time;
-                       scst_time = sess->scst_time;
-                       processed_cmds = sess->processed_cmds;
-                       spin_unlock_bh(&sess->meas_lock);
-
-                       TRACE_DBG("sess %p, scst_time %lld, proc_time %lld, "
-                               "processed_cmds %d", sess, scst_time,
-                               proc_time, processed_cmds);
-
-#if BITS_PER_LONG == 32
-                       /* Unfortunately, do_div() doesn't work too well */
-                       while (((proc_time & 0xFFFFFFFF00000000LL) != 0) ||
-                              ((scst_time & 0xFFFFFFFF00000000LL) != 0)) {
-                               TRACE_DBG("%s", "Gathered time too big");
-                               proc_time >>= 1;
-                               scst_time >>= 1;
-                               processed_cmds >>= 1;
+                       spin_lock_bh(&sess->lat_lock);
+
+                       for (i = 0; i < SCST_LATENCY_STATS_NUM ; i++) {
+                               uint64_t scst_time_wr, tgt_time_wr, dev_time_wr;
+                               unsigned int processed_cmds_wr;
+                               uint64_t scst_time_rd, tgt_time_rd, dev_time_rd;
+                               unsigned int processed_cmds_rd;
+                               struct scst_ext_latency_stat *latency_stat;
+
+                               latency_stat = &sess->sess_latency_stat[i];
+                               scst_time_wr = latency_stat->scst_time_wr;
+                               scst_time_rd = latency_stat->scst_time_rd;
+                               tgt_time_wr = latency_stat->tgt_time_wr;
+                               tgt_time_rd = latency_stat->tgt_time_rd;
+                               dev_time_wr = latency_stat->dev_time_wr;
+                               dev_time_rd = latency_stat->dev_time_rd;
+                               processed_cmds_wr = latency_stat->processed_cmds_wr;
+                               processed_cmds_rd = latency_stat->processed_cmds_rd;
+
+                               seq_printf(seq, "%-5s %-9s %-15lu ",
+                                       "Write", scst_io_size_names[i],
+                                       (unsigned long)processed_cmds_wr);
+                               if (processed_cmds_wr == 0)
+                                       processed_cmds_wr = 1;
+
+                               do_div(scst_time_wr, processed_cmds_wr);
+                               snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                                       (unsigned long)latency_stat->min_scst_time_wr,
+                                       (unsigned long)scst_time_wr,
+                                       (unsigned long)latency_stat->max_scst_time_wr);
+                               seq_printf(seq, "%-35s", buf);
+
+                               do_div(tgt_time_wr, processed_cmds_wr);
+                               snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                                       (unsigned long)latency_stat->min_tgt_time_wr,
+                                       (unsigned long)tgt_time_wr,
+                                       (unsigned long)latency_stat->max_tgt_time_wr);
+                               seq_printf(seq, "%-35s", buf);
+
+                               do_div(dev_time_wr, processed_cmds_wr);
+                               snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                                       (unsigned long)latency_stat->min_dev_time_wr,
+                                       (unsigned long)dev_time_wr,
+                                       (unsigned long)latency_stat->max_dev_time_wr);
+                               seq_printf(seq, "%-35s\n", buf);
+
+                               seq_printf(seq, "%-5s %-9s %-15lu ",
+                                       "Read", scst_io_size_names[i],
+                                       (unsigned long)processed_cmds_rd);
+                               if (processed_cmds_rd == 0)
+                                       processed_cmds_rd = 1;
+
+                               do_div(scst_time_rd, processed_cmds_rd);
+                               snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                                       (unsigned long)latency_stat->min_scst_time_rd,
+                                       (unsigned long)scst_time_rd,
+                                       (unsigned long)latency_stat->max_scst_time_rd);
+                               seq_printf(seq, "%-35s", buf);
+
+                               do_div(tgt_time_rd, processed_cmds_rd);
+                               snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                                       (unsigned long)latency_stat->min_tgt_time_rd,
+                                       (unsigned long)tgt_time_rd,
+                                       (unsigned long)latency_stat->max_tgt_time_rd);
+                               seq_printf(seq, "%-35s", buf);
+
+                               do_div(dev_time_rd, processed_cmds_rd);
+                               snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                                       (unsigned long)latency_stat->min_dev_time_rd,
+                                       (unsigned long)dev_time_rd,
+                                       (unsigned long)latency_stat->max_dev_time_rd);
+                               seq_printf(seq, "%-35s\n", buf);
                        }
-#endif
 
-                       if (processed_cmds != 0) {
-                               proc_lat = (unsigned long)proc_time /
-                                               processed_cmds;
-                               scst_lat = (unsigned long)scst_time /
-                                               processed_cmds;
+                       for (t = TGT_DEV_HASH_SIZE-1; t >= 0; t--) {
+                               struct list_head *sess_tgt_dev_list_head =
+                                       &sess->sess_tgt_dev_list_hash[t];
+                               struct scst_tgt_dev *tgt_dev;
+                               list_for_each_entry(tgt_dev, sess_tgt_dev_list_head,
+                                               sess_tgt_dev_list_entry) {
+
+                                       seq_printf(seq, "\nLUN: %llu\n", tgt_dev->lun);
+
+                                       for (i = 0; i < SCST_LATENCY_STATS_NUM ; i++) {
+                                               uint64_t scst_time_wr, tgt_time_wr, dev_time_wr;
+                                               unsigned int processed_cmds_wr;
+                                               uint64_t scst_time_rd, tgt_time_rd, dev_time_rd;
+                                               unsigned int processed_cmds_rd;
+                                               struct scst_ext_latency_stat *latency_stat;
+
+                                               latency_stat = &tgt_dev->dev_latency_stat[i];
+                                               scst_time_wr = latency_stat->scst_time_wr;
+                                               scst_time_rd = latency_stat->scst_time_rd;
+                                               tgt_time_wr = latency_stat->tgt_time_wr;
+                                               tgt_time_rd = latency_stat->tgt_time_rd;
+                                               dev_time_wr = latency_stat->dev_time_wr;
+                                               dev_time_rd = latency_stat->dev_time_rd;
+                                               processed_cmds_wr = latency_stat->processed_cmds_wr;
+                                               processed_cmds_rd = latency_stat->processed_cmds_rd;
+
+                                               seq_printf(seq, "%-5s %-9s %-15lu ",
+                                                       "Write", scst_io_size_names[i],
+                                                       (unsigned long)processed_cmds_wr);
+                                               if (processed_cmds_wr == 0)
+                                                       processed_cmds_wr = 1;
+
+                                               do_div(scst_time_wr, processed_cmds_wr);
+                                               snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                                                       (unsigned long)latency_stat->min_scst_time_wr,
+                                                       (unsigned long)scst_time_wr,
+                                                       (unsigned long)latency_stat->max_scst_time_wr);
+                                               seq_printf(seq, "%-35s", buf);
+
+                                               do_div(tgt_time_wr, processed_cmds_wr);
+                                               snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                                                       (unsigned long)latency_stat->min_tgt_time_wr,
+                                                       (unsigned long)tgt_time_wr,
+                                                       (unsigned long)latency_stat->max_tgt_time_wr);
+                                               seq_printf(seq, "%-35s", buf);
+
+                                               do_div(dev_time_wr, processed_cmds_wr);
+                                               snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                                                       (unsigned long)latency_stat->min_dev_time_wr,
+                                                       (unsigned long)dev_time_wr,
+                                                       (unsigned long)latency_stat->max_dev_time_wr);
+                                               seq_printf(seq, "%-35s\n", buf);
+
+                                               seq_printf(seq, "%-5s %-9s %-15lu ",
+                                                       "Read", scst_io_size_names[i],
+                                                       (unsigned long)processed_cmds_rd);
+                                               if (processed_cmds_rd == 0)
+                                                       processed_cmds_rd = 1;
+
+                                               do_div(scst_time_rd, processed_cmds_rd);
+                                               snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                                                       (unsigned long)latency_stat->min_scst_time_rd,
+                                                       (unsigned long)scst_time_rd,
+                                                       (unsigned long)latency_stat->max_scst_time_rd);
+                                               seq_printf(seq, "%-35s", buf);
+
+                                               do_div(tgt_time_rd, processed_cmds_rd);
+                                               snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                                                       (unsigned long)latency_stat->min_tgt_time_rd,
+                                                       (unsigned long)tgt_time_rd,
+                                                       (unsigned long)latency_stat->max_tgt_time_rd);
+                                               seq_printf(seq, "%-35s", buf);
+
+                                               do_div(dev_time_rd, processed_cmds_rd);
+                                               snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                                                       (unsigned long)latency_stat->min_dev_time_rd,
+                                                       (unsigned long)dev_time_rd,
+                                                       (unsigned long)latency_stat->max_dev_time_rd);
+                                               seq_printf(seq, "%-35s\n", buf);
+                                       }
+                               }
                        }
 
-                       seq_printf(seq,
-                                  "%-30s %-15d %-15ld %-15ld\n\n",
-                                  "Average",
-                                  processed_cmds,
-                                  scst_lat,
-                                  proc_lat);
+                       scst_time = sess->scst_time;
+                       tgt_time = sess->tgt_time;
+                       dev_time = sess->dev_time;
+                       processed_cmds = sess->processed_cmds;
+
+                       seq_printf(seq, "%-15s %-16d", "Overall ",
+                               processed_cmds);
+
+                       if (processed_cmds == 0)
+                               processed_cmds = 1;
+
+                       do_div(scst_time, processed_cmds);
+                       snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                               (unsigned long)sess->min_scst_time,
+                               (unsigned long)scst_time,
+                               (unsigned long)sess->max_scst_time);
+                       seq_printf(seq, "%-35s", buf);
+
+                       do_div(tgt_time, processed_cmds);
+                       snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                               (unsigned long)sess->min_tgt_time,
+                               (unsigned long)tgt_time,
+                               (unsigned long)sess->max_tgt_time);
+                       seq_printf(seq, "%-35s", buf);
+
+                       do_div(dev_time, processed_cmds);
+                       snprintf(buf, sizeof(buf), "%lu/%lu/%lu",
+                               (unsigned long)sess->min_dev_time,
+                               (unsigned long)dev_time,
+                               (unsigned long)sess->max_dev_time);
+                       seq_printf(seq, "%-35s\n\n", buf);
+
+                       spin_unlock_bh(&sess->lat_lock);
                }
        }
 
@@ -537,7 +660,7 @@ static ssize_t scst_proc_scsi_tgt_gen_write_lat(struct file *file,
                                        const char __user *buf,
                                        size_t length, loff_t *off)
 {
-       int res = length;
+       int res = length, t;
        struct scst_acg *acg;
        struct scst_session *sess;
 
@@ -551,19 +674,39 @@ static ssize_t scst_proc_scsi_tgt_gen_write_lat(struct file *file,
        list_for_each_entry(acg, &scst_acg_list, scst_acg_list_entry) {
                list_for_each_entry(sess, &acg->acg_sess_list,
                                acg_sess_list_entry) {
-                       PRINT_INFO("Zeroing latency statistics for initiator"
-                               " %s",
-                               sess->initiator_name);
-                       spin_lock_bh(&sess->meas_lock);
-                       sess->processing_time = 0;
+                       PRINT_INFO("Zeroing latency statistics for initiator "
+                               "%s", sess->initiator_name);
+                       spin_lock_bh(&sess->lat_lock);
+
                        sess->scst_time = 0;
+                       sess->tgt_time = 0;
+                       sess->dev_time = 0;
+                       sess->min_scst_time = 0;
+                       sess->min_tgt_time = 0;
+                       sess->min_dev_time = 0;
+                       sess->max_scst_time = 0;
+                       sess->max_tgt_time = 0;
+                       sess->max_dev_time = 0;
                        sess->processed_cmds = 0;
-#ifdef CONFIG_SCST_MEASURE_LATENCY_EXT
-                       memset(sess->latency_stat,
-                               0,
-                               sizeof(sess->latency_stat));
-#endif
-                       spin_unlock_bh(&sess->meas_lock);
+                       memset(sess->sess_latency_stat, 0,
+                               sizeof(sess->sess_latency_stat));
+
+                       for (t = TGT_DEV_HASH_SIZE-1; t >= 0; t--) {
+                               struct list_head *sess_tgt_dev_list_head =
+                                       &sess->sess_tgt_dev_list_hash[t];
+                               struct scst_tgt_dev *tgt_dev;
+                               list_for_each_entry(tgt_dev, sess_tgt_dev_list_head,
+                                               sess_tgt_dev_list_entry) {
+                                       tgt_dev->scst_time = 0;
+                                       tgt_dev->tgt_time = 0;
+                                       tgt_dev->dev_time = 0;
+                                       tgt_dev->processed_cmds = 0;
+                                       memset(tgt_dev->dev_latency_stat, 0,
+                                               sizeof(tgt_dev->dev_latency_stat));
+                               }
+                       }
+
+                       spin_unlock_bh(&sess->lat_lock);
                }
        }
 
index 6b955f0..7a791ae 100644 (file)
@@ -180,13 +180,6 @@ out_redirect:
        goto out;
 }
 
-#ifdef CONFIG_SCST_MEASURE_LATENCY
-static inline uint64_t scst_sec_to_nsec(time_t sec)
-{
-       return (uint64_t)sec * 1000000000;
-}
-#endif
-
 void scst_cmd_init_done(struct scst_cmd *cmd,
        enum scst_exec_context pref_context)
 {
@@ -196,16 +189,7 @@ void scst_cmd_init_done(struct scst_cmd *cmd,
 
        TRACE_ENTRY();
 
-#ifdef CONFIG_SCST_MEASURE_LATENCY
-       {
-               struct timespec ts;
-               ktime_get_ts(&ts);
-               cmd->start = scst_sec_to_nsec(ts.tv_sec) + ts.tv_nsec;
-               TRACE_DBG("cmd %p (sess %p): start %lld (tv_sec %ld, "
-                       "tv_nsec %ld)", cmd, sess, cmd->start, ts.tv_sec,
-                       ts.tv_nsec);
-       }
-#endif
+       scst_set_start_time(cmd);
 
        TRACE_DBG("Preferred context: %d (cmd %p)", pref_context, cmd);
        TRACE(TRACE_SCSI, "tag=%llu, lun=%lld, CDB len=%d, queue_type=%x "
@@ -513,6 +497,7 @@ static int scst_parse_cmd(struct scst_cmd *cmd)
                      dev->handler->name, cmd);
                TRACE_BUFF_FLAG(TRACE_SND_BOT, "Parsing: ",
                                cmd->cdb, cmd->cdb_len);
+               scst_set_cur_start(cmd);
                state = dev->handler->parse(cmd);
                /* Caution: cmd can be already dead here */
                TRACE_DBG("Dev handler %s parse() returned %d",
@@ -520,6 +505,7 @@ static int scst_parse_cmd(struct scst_cmd *cmd)
 
                switch (state) {
                case SCST_CMD_STATE_NEED_THREAD_CTX:
+                       scst_set_parse_time(cmd);
                        TRACE_DBG("Dev handler %s parse() requested thread "
                              "context, rescheduling", dev->handler->name);
                        res = SCST_CMD_STATE_RES_NEED_THREAD;
@@ -532,6 +518,8 @@ static int scst_parse_cmd(struct scst_cmd *cmd)
                        goto out;
                }
 
+               scst_set_parse_time(cmd);
+
                if (state == SCST_CMD_STATE_DEFAULT)
                        state = SCST_CMD_STATE_PREPARE_SPACE;
        } else
@@ -715,7 +703,10 @@ static int scst_prepare_space(struct scst_cmd *cmd)
                TRACE_MEM("Custom tgt data buf allocation requested (cmd %p)",
                        cmd);
 
+               scst_set_cur_start(cmd);
                r = cmd->tgtt->alloc_data_buf(cmd);
+               scst_set_alloc_buf_time(cmd);
+
                if (r > 0)
                        goto alloc;
                else if (r == 0) {
@@ -786,6 +777,7 @@ prep_done:
                cmd->state = SCST_CMD_STATE_PREPROCESS_DONE;
 
                TRACE_DBG("Calling preprocessing_done(cmd %p)", cmd);
+               scst_set_cur_start(cmd);
                cmd->tgtt->preprocessing_done(cmd);
                TRACE_DBG("%s", "preprocessing_done() returned");
                goto out;
@@ -821,6 +813,8 @@ void scst_restart_cmd(struct scst_cmd *cmd, int status,
 {
        TRACE_ENTRY();
 
+       scst_set_restart_waiting_time(cmd);
+
        TRACE_DBG("Preferred context: %d", pref_context);
        TRACE_DBG("tag=%llu, status=%#x",
                  (long long unsigned int)scst_cmd_get_tag(cmd),
@@ -940,6 +934,8 @@ static int scst_rdy_to_xfer(struct scst_cmd *cmd)
                        }
                }
 
+               scst_set_cur_start(cmd);
+
                TRACE_DBG("Calling rdy_to_xfer(%p)", cmd);
 #ifdef CONFIG_SCST_DEBUG_RETRY
                if (((scst_random() % 100) == 75))
@@ -952,6 +948,8 @@ static int scst_rdy_to_xfer(struct scst_cmd *cmd)
                if (likely(rc == SCST_TGT_RES_SUCCESS))
                        goto out;
 
+               scst_set_rdy_to_xfer_time(cmd);
+
                cmd->cmd_hw_pending = 0;
 
                /* Restore the previous state */
@@ -1058,6 +1056,8 @@ void scst_rx_data(struct scst_cmd *cmd, int status,
 {
        TRACE_ENTRY();
 
+       scst_set_rdy_to_xfer_time(cmd);
+
        TRACE_DBG("Preferred context: %d", pref_context);
        TRACE(TRACE_SCSI, "cmd %p, status %#x", cmd, status);
 
@@ -1151,7 +1151,9 @@ static int scst_tgt_pre_exec(struct scst_cmd *cmd)
                goto out;
 
        TRACE_DBG("Calling pre_exec(%p)", cmd);
+       scst_set_cur_start(cmd);
        rc = cmd->tgtt->pre_exec(cmd);
+       scst_set_pre_exec_time(cmd);
        TRACE_DBG("pre_exec() returned %d", rc);
 
        if (unlikely(rc != SCST_PREPROCESS_STATUS_SUCCESS)) {
@@ -1190,16 +1192,7 @@ static void scst_do_cmd_done(struct scst_cmd *cmd, int result,
 {
        TRACE_ENTRY();
 
-#ifdef CONFIG_SCST_MEASURE_LATENCY
-       {
-               struct timespec ts;
-               ktime_get_ts(&ts);
-               cmd->post_exec_start = scst_sec_to_nsec(ts.tv_sec) + ts.tv_nsec;
-               TRACE_DBG("cmd %p (sess %p): post_exec_start %lld (tv_sec %ld, "
-                       "tv_nsec %ld)", cmd, cmd->sess, cmd->post_exec_start,
-                       ts.tv_sec, ts.tv_nsec);
-       }
-#endif
+       scst_set_exec_time(cmd);
 
        cmd->status = result & 0xff;
        cmd->msg_status = msg_byte(result);
@@ -1333,16 +1326,7 @@ static void scst_cmd_done_local(struct scst_cmd *cmd, int next_state,
 {
        TRACE_ENTRY();
 
-#ifdef CONFIG_SCST_MEASURE_LATENCY
-       {
-               struct timespec ts;
-               ktime_get_ts(&ts);
-               cmd->post_exec_start = scst_sec_to_nsec(ts.tv_sec) + ts.tv_nsec;
-               TRACE_DBG("cmd %p (sess %p): post_exec_start %lld (tv_sec %ld, "
-                       "tv_nsec %ld)", cmd, cmd->sess, cmd->post_exec_start,
-                       ts.tv_sec, ts.tv_nsec);
-       }
-#endif
+       scst_set_exec_time(cmd);
 
        if (next_state == SCST_CMD_STATE_DEFAULT)
                next_state = SCST_CMD_STATE_PRE_DEV_DONE;
@@ -1991,6 +1975,7 @@ static int scst_do_real_exec(struct scst_cmd *cmd)
                      handler->name, cmd);
                TRACE_BUFF_FLAG(TRACE_SND_TOP, "Execing: ", cmd->cdb,
                        cmd->cdb_len);
+               scst_set_cur_start(cmd);
                res = handler->exec(cmd);
                TRACE_DBG("Dev handler %s exec() returned %d",
                      handler->name, res);
@@ -2000,6 +1985,8 @@ static int scst_do_real_exec(struct scst_cmd *cmd)
                else if (res == SCST_EXEC_NEED_THREAD)
                        goto out_restore;
 
+               scst_set_exec_time(cmd);
+
                sBUG_ON(res != SCST_EXEC_NOT_COMPLETED);
        }
 
@@ -2026,6 +2013,8 @@ static int scst_do_real_exec(struct scst_cmd *cmd)
        }
 #endif
 
+       scst_set_cur_start(cmd);
+
 #if LINUX_VERSION_CODE < KERNEL_VERSION(2, 6, 18)
        if (unlikely(scst_alloc_request(cmd) != 0)) {
                if (atomic) {
@@ -2073,6 +2062,7 @@ out_reset_ctx:
        return res;
 
 out_restore:
+       scst_set_exec_time(cmd);
        /* Restore the state */
        cmd->state = SCST_CMD_STATE_REAL_EXEC;
        goto out_reset_ctx;
@@ -2321,17 +2311,6 @@ static int scst_send_for_exec(struct scst_cmd **active_cmd)
 
        TRACE_ENTRY();
 
-#ifdef CONFIG_SCST_MEASURE_LATENCY
-       if (cmd->pre_exec_finish == 0) {
-               struct timespec ts;
-               ktime_get_ts(&ts);
-               cmd->pre_exec_finish = scst_sec_to_nsec(ts.tv_sec) + ts.tv_nsec;
-               TRACE_DBG("cmd %p (sess %p): pre_exec_finish %lld (tv_sec %ld, "
-                       "tv_nsec %ld)", cmd, cmd->sess, cmd->pre_exec_finish,
-                       ts.tv_sec, ts.tv_nsec);
-       }
-#endif
-
        if (unlikely(cmd->internal))
                goto exec;
 
@@ -2787,8 +2766,10 @@ static int scst_dev_done(struct scst_cmd *cmd)
                }
 
                TRACE_DBG("Calling dev handler %s dev_done(%p)",
-                     dev->handler->name, cmd);
+                       dev->handler->name, cmd);
+               scst_set_cur_start(cmd);
                rc = dev->handler->dev_done(cmd);
+               scst_set_dev_done_time(cmd);
                TRACE_DBG("Dev handler %s dev_done() returned %d",
                      dev->handler->name, rc);
                if (rc != SCST_CMD_STATE_DEFAULT)
@@ -2934,77 +2915,6 @@ static int scst_pre_xmit_response(struct scst_cmd *cmd)
        res = SCST_CMD_STATE_RES_CONT_SAME;
 
 out:
-#ifdef CONFIG_SCST_MEASURE_LATENCY
-       {
-               struct timespec ts;
-               uint64_t finish, scst_time, proc_time;
-               struct scst_session *sess = cmd->sess;
-
-#ifdef CONFIG_SCST_MEASURE_LATENCY_EXT
-               int data_len;
-               int i;
-               struct scst_latency_stat *latency_stat;
-#endif
-               ktime_get_ts(&ts);
-               finish = scst_sec_to_nsec(ts.tv_sec) + ts.tv_nsec;
-
-#ifdef CONFIG_SCST_MEASURE_LATENCY_EXT
-               /* Determine the IO size for extended latency statistics*/
-               data_len = cmd->data_len;
-               i = SCST_LATENCY_STAT_INDEX_OTHER;
-               if (data_len <= SCST_IO_SIZE_THRESHOLD_SMALL)
-                       i = SCST_LATENCY_STAT_INDEX_SMALL;
-               else if (data_len <= SCST_IO_SIZE_THRESHOLD_MEDIUM)
-                       i = SCST_LATENCY_STAT_INDEX_MEDIUM;
-               else if (data_len <= SCST_IO_SIZE_THRESHOLD_LARGE)
-                       i = SCST_LATENCY_STAT_INDEX_LARGE;
-               else if (data_len <= SCST_IO_SIZE_THRESHOLD_VERY_LARGE)
-                       i = SCST_LATENCY_STAT_INDEX_VERY_LARGE;
-               latency_stat = &sess->latency_stat[i];
-#endif
-
-               spin_lock_bh(&sess->meas_lock);
-               /* Calculate the latencies */
-               scst_time = cmd->pre_exec_finish - cmd->start;
-               scst_time += finish - cmd->post_exec_start;
-               proc_time = finish - cmd->start;
-
-               /* Save the basic latency information */
-               sess->scst_time += scst_time;
-               sess->processing_time += proc_time;
-               sess->processed_cmds++;
-
-#ifdef CONFIG_SCST_MEASURE_LATENCY_EXT
-               /* Save the extended latency information */
-               switch (cmd->cdb[0]) {
-               case READ_6:
-               case READ_10:
-               case READ_12:
-                      latency_stat->scst_time_rd += scst_time;
-                      latency_stat->processing_time_rd += proc_time;
-                      latency_stat->processed_cmds_rd++;
-                      break;
-               case WRITE_6:
-               case WRITE_10:
-               case WRITE_12:
-               case WRITE_VERIFY:
-               case WRITE_VERIFY_12:
-                      latency_stat->scst_time_wr += scst_time;
-                      latency_stat->processing_time_wr += proc_time;
-                      latency_stat->processed_cmds_wr++;
-                      break;
-               default:
-                      break;
-               }
-#endif
-               spin_unlock_bh(&sess->meas_lock);
-
-               TRACE_DBG("cmd %p (sess %p): finish %lld (tv_sec %ld, "
-                       "tv_nsec %ld), scst_time %lld, proc_time %lld",
-                       cmd, sess, finish, ts.tv_sec, ts.tv_nsec, scst_time,
-                       proc_time);
-       }
-#endif
        TRACE_EXIT_HRES(res);
        return res;
 }
@@ -3075,6 +2985,8 @@ static int scst_xmit_response(struct scst_cmd *cmd)
                        }
                }
 
+               scst_set_cur_start(cmd);
+
 #ifdef CONFIG_SCST_DEBUG_RETRY
                if (((scst_random() % 100) == 77))
                        rc = SCST_TGT_RES_QUEUE_FULL;
@@ -3086,6 +2998,8 @@ static int scst_xmit_response(struct scst_cmd *cmd)
                if (likely(rc == SCST_TGT_RES_SUCCESS))
                        goto out;
 
+               scst_set_xmit_time(cmd);
+
                cmd->cmd_hw_pending = 0;
 
                /* Restore the previous state */
@@ -3137,6 +3051,8 @@ void scst_tgt_cmd_done(struct scst_cmd *cmd,
 
        sBUG_ON(cmd->state != SCST_CMD_STATE_XMIT_WAIT);
 
+       scst_set_xmit_time(cmd);
+
        cmd->cmd_hw_pending = 0;
 
        cmd->state = SCST_CMD_STATE_FINISHED;
@@ -3154,6 +3070,8 @@ static int scst_finish_cmd(struct scst_cmd *cmd)
 
        TRACE_ENTRY();
 
+       scst_update_lat_stats(cmd);
+
        if (unlikely(cmd->delivery_status != SCST_CMD_DELIVERY_SUCCESS)) {
                if ((cmd->tgt_dev != NULL) &&
                    scst_is_ua_sense(cmd->sense, cmd->sense_valid_len)) {
@@ -3745,6 +3663,13 @@ void scst_process_active_cmd(struct scst_cmd *cmd, bool atomic)
 }
 EXPORT_SYMBOL(scst_process_active_cmd);
 
+void scst_post_parse_process_active_cmd(struct scst_cmd *cmd, bool atomic)
+{
+       scst_set_parse_time(cmd);
+       scst_process_active_cmd(cmd, atomic);
+}
+EXPORT_SYMBOL(scst_post_parse_process_active_cmd);
+
 /* Called under cmd_list_lock and IRQs disabled */
 static void scst_do_job_active(struct list_head *cmd_list,
        spinlock_t *cmd_list_lock, bool atomic)