mirror of
https://github.com/SCST-project/scst.git
synced 2026-05-17 10:41:26 +00:00
Extended latency statistics
git-svn-id: http://svn.code.sf.net/p/scst/svn/trunk@1157 d57e44dd-8a1f-0410-8b47-8ef2f437770f
This commit is contained in:
@@ -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
|
||||
|
||||
@@ -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;
|
||||
|
||||
@@ -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 */
|
||||
|
||||
@@ -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 */
|
||||
|
||||
@@ -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);
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -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)
|
||||
|
||||
Reference in New Issue
Block a user