diff --git a/scst/include/scst.h b/scst/include/scst.h index 303285b33..7027c38fb 100644 --- a/scst/include/scst.h +++ b/scst/include/scst.h @@ -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 diff --git a/scst/src/dev_handlers/scst_user.c b/scst/src/dev_handlers/scst_user.c index 4eb7a656c..b60760d95 100644 --- a/scst/src/dev_handlers/scst_user.c +++ b/scst/src/dev_handlers/scst_user.c @@ -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; diff --git a/scst/src/scst_lib.c b/scst/src/scst_lib.c index 70a0bfd4b..646e04621 100644 --- a/scst/src/scst_lib.c +++ b/scst/src/scst_lib.c @@ -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 */ diff --git a/scst/src/scst_priv.h b/scst/src/scst_priv.h index 154466a7c..305a59ea0 100644 --- a/scst/src/scst_priv.h +++ b/scst/src/scst_priv.h @@ -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 */ diff --git a/scst/src/scst_proc.c b/scst/src/scst_proc.c index ca0598d2d..df7d8296b 100644 --- a/scst/src/scst_proc.c +++ b/scst/src/scst_proc.c @@ -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; - seq_printf(seq, - "Target name: %s \nInitiator name: %s\n", + 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", 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; + spin_lock_bh(&sess->lat_lock); - 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); + 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 - proc_time = sess->processing_time; + + 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); + } + } + } + scst_time = sess->scst_time; + tgt_time = sess->tgt_time; + dev_time = sess->dev_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); + seq_printf(seq, "%-15s %-16d", "Overall ", + 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; - } -#endif + if (processed_cmds == 0) + processed_cmds = 1; - if (processed_cmds != 0) { - proc_lat = (unsigned long)proc_time / - processed_cmds; - scst_lat = (unsigned long)scst_time / - processed_cmds; - } + 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); - seq_printf(seq, - "%-30s %-15d %-15ld %-15ld\n\n", - "Average", - processed_cmds, - scst_lat, - proc_lat); + 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); } } diff --git a/scst/src/scst_targ.c b/scst/src/scst_targ.c index 6b955f09b..7a791aea8 100644 --- a/scst/src/scst_targ.c +++ b/scst/src/scst_targ.c @@ -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)