From 807836950be1205f26acf2408e68e4aa2db32a8c Mon Sep 17 00:00:00 2001 From: Vladislav Bolkhovitin Date: Tue, 20 Dec 2016 06:17:11 +0000 Subject: [PATCH] scst: improve latency statistics git-svn-id: http://svn.code.sf.net/p/scst/svn/trunk@7074 d57e44dd-8a1f-0410-8b47-8ef2f437770f --- scst/include/scst.h | 10 ++- scst/src/dev_handlers/scst_user.c | 4 +- scst/src/scst_lib.c | 136 ++++++++++++++++++++---------- scst/src/scst_priv.h | 6 +- scst/src/scst_targ.c | 14 +-- 5 files changed, 109 insertions(+), 61 deletions(-) diff --git a/scst/include/scst.h b/scst/include/scst.h index 2dec04a16..d0a696d5e 100644 --- a/scst/include/scst.h +++ b/scst/include/scst.h @@ -2585,11 +2585,13 @@ struct scst_cmd { #endif #ifdef CONFIG_SCST_MEASURE_LATENCY - uint64_t start, curr_start, parse_time, alloc_buf_time; + uint64_t start, curr_start, parse_time; + uint64_t tgt_alloc_buf_time, dev_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; + uint64_t pre_exec_time; bool exec_time_counting; + uint64_t exec_time, dev_done_time; + uint64_t xmit_time; #endif #ifdef CONFIG_SCST_DEBUG_TM @@ -5231,7 +5233,7 @@ void scst_resume_activity(void); void scst_process_active_cmd(struct scst_cmd *cmd, bool atomic); void scst_post_parse(struct scst_cmd *cmd); -void scst_post_alloc_data_buf(struct scst_cmd *cmd); +void scst_post_dev_alloc_data_buf(struct scst_cmd *cmd); int __scst_check_local_events(struct scst_cmd *cmd, bool preempt_tests_only); diff --git a/scst/src/dev_handlers/scst_user.c b/scst/src/dev_handlers/scst_user.c index 055ef1449..21a849372 100644 --- a/scst/src/dev_handlers/scst_user.c +++ b/scst/src/dev_handlers/scst_user.c @@ -1344,7 +1344,7 @@ static int dev_user_process_reply_alloc(struct scst_user_cmd *ucmd, } out_process: - scst_post_alloc_data_buf(cmd); + scst_post_dev_alloc_data_buf(cmd); scst_process_active_cmd(cmd, false); TRACE_DBG("%s", "ALLOC_MEM finished"); @@ -2663,7 +2663,7 @@ static void dev_user_unjam_cmd(struct scst_user_cmd *ucmd, int busy, if (state == UCMD_STATE_PARSING) scst_post_parse(ucmd->cmd); else - scst_post_alloc_data_buf(ucmd->cmd); + scst_post_dev_alloc_data_buf(ucmd->cmd); TRACE_MGMT_DBG("Adding ucmd %p to active list", ucmd); list_add(&ucmd->cmd->cmd_list_entry, diff --git a/scst/src/scst_lib.c b/scst/src/scst_lib.c index 293ff65f4..0372180ee 100644 --- a/scst/src/scst_lib.c +++ b/scst/src/scst_lib.c @@ -15466,22 +15466,28 @@ void scst_check_debug_sn(struct scst_cmd *cmd) #ifdef CONFIG_SCST_MEASURE_LATENCY +#if LINUX_VERSION_CODE < KERNEL_VERSION(2, 6, 16) + static uint64_t scst_get_usec(void) { struct timespec ts; ktime_get_ts(&ts); -#if LINUX_VERSION_CODE < KERNEL_VERSION(2, 6, 16) return ((uint64_t)ts.tv_sec * 1000000000 + ts.tv_nsec) / 1000; -#else -#if (BITS_PER_LONG > 32) - return timespec_to_ns(&ts) / 1000; -#else - return timespec_to_ns(&ts) >> 10; -#endif -#endif } +#else /* LINUX_VERSION_CODE < KERNEL_VERSION(2, 6, 16) */ + +static uint64_t scst_get_usec(void) +{ + ktime_t t; + + t = ktime_get(); + return ktime_to_us(t); +} + +#endif + void scst_set_start_time(struct scst_cmd *cmd) { cmd->start = scst_get_usec(); @@ -15500,10 +15506,16 @@ void scst_set_parse_time(struct scst_cmd *cmd) TRACE_DBG("cmd %p: parse_time %lld", cmd, cmd->parse_time); } -void scst_set_alloc_buf_time(struct scst_cmd *cmd) +void scst_set_dev_alloc_buf_time(struct scst_cmd *cmd) { - cmd->alloc_buf_time += scst_get_usec() - cmd->curr_start; - TRACE_DBG("cmd %p: alloc_buf_time %lld", cmd, cmd->alloc_buf_time); + cmd->dev_alloc_buf_time += scst_get_usec() - cmd->curr_start; + TRACE_DBG("cmd %p: dev_alloc_buf_time %lld", cmd, cmd->dev_alloc_buf_time); +} + +void scst_set_tgt_alloc_buf_time(struct scst_cmd *cmd) +{ + cmd->tgt_alloc_buf_time += scst_get_usec() - cmd->curr_start; + TRACE_DBG("cmd %p: tgt_alloc_buf_time %lld", cmd, cmd->tgt_alloc_buf_time); } void scst_set_restart_waiting_time(struct scst_cmd *cmd) @@ -15533,6 +15545,9 @@ void scst_set_exec_start(struct scst_cmd *cmd) void scst_set_exec_time(struct scst_cmd *cmd) { + if (!cmd->exec_time_counting) + return; + cmd->exec_time_counting = false; cmd->exec_time += scst_get_usec() - cmd->curr_start; TRACE_DBG("cmd %p: exec_time %lld", cmd, cmd->exec_time); } @@ -15551,11 +15566,12 @@ void scst_set_xmit_time(struct scst_cmd *cmd) void scst_update_lat_stats(struct scst_cmd *cmd) { - uint64_t finish, scst_time, tgt_time, dev_time; + int64_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; + bool ignore_max = false; finish = scst_get_usec(); @@ -15578,12 +15594,30 @@ void scst_update_lat_stats(struct scst_cmd *cmd) /* Calculate the latencies */ scst_time = finish - cmd->start - (cmd->parse_time + - cmd->alloc_buf_time + cmd->restart_waiting_time + + cmd->dev_alloc_buf_time + cmd->tgt_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); - tgt_time = cmd->alloc_buf_time + cmd->restart_waiting_time + - cmd->rdy_to_xfer_time + cmd->pre_exec_time; - dev_time = cmd->parse_time + cmd->exec_time + cmd->dev_done_time; + tgt_time = cmd->tgt_alloc_buf_time + cmd->restart_waiting_time + + cmd->rdy_to_xfer_time + cmd->pre_exec_time + cmd->xmit_time; + dev_time = cmd->parse_time + cmd->dev_alloc_buf_time + + cmd->exec_time + cmd->dev_done_time; + + if (unlikely((scst_time < 0) || (tgt_time < 0) || (dev_time < 0))) { + /* It might happen due to small difference in time between CPUs */ + static int q; + if (q++ < 20) { + PRINT_WARNING("Ignoring max latency sample, because time is " + "moving backward (cmd %p, scst %lld, tgt %lld, " + "dev %lld)", cmd, (long long) scst_time, + (long long) tgt_time, (long long) dev_time); + } + ignore_max = true; + /* + * We should not ignore this sample, because the time + * difference mistake can be both negative and positive. + */ + } spin_lock_bh(&sess->lat_lock); @@ -15603,12 +15637,14 @@ void scst_update_lat_stats(struct scst_cmd *cmd) (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; + if (likely(!ignore_max)) { + 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) { @@ -15627,12 +15663,14 @@ void scst_update_lat_stats(struct scst_cmd *cmd) (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; + if (likely(!ignore_max)) { + 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; + } if (dev_latency_stat != NULL) { dev_latency_stat->scst_time_rd += scst_time; @@ -15650,12 +15688,14 @@ void scst_update_lat_stats(struct scst_cmd *cmd) (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; + if (likely(!ignore_max)) { + 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; @@ -15673,12 +15713,14 @@ void scst_update_lat_stats(struct scst_cmd *cmd) (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; + if (likely(!ignore_max)) { + 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; + } if (dev_latency_stat != NULL) { dev_latency_stat->scst_time_wr += scst_time; @@ -15696,12 +15738,14 @@ void scst_update_lat_stats(struct scst_cmd *cmd) (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; + if (likely(!ignore_max)) { + 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; + } } } diff --git a/scst/src/scst_priv.h b/scst/src/scst_priv.h index dabbbbf2f..d64476020 100644 --- a/scst/src/scst_priv.h +++ b/scst/src/scst_priv.h @@ -1024,7 +1024,8 @@ void scst_trace_mcmds(scst_show_fn show, void *arg); 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_dev_alloc_buf_time(struct scst_cmd *cmd); +void scst_set_tgt_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); @@ -1039,7 +1040,8 @@ void scst_update_lat_stats(struct scst_cmd *cmd); 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_dev_alloc_buf_time(struct scst_cmd *cmd) {} +static inline void scst_set_tgt_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) {} diff --git a/scst/src/scst_targ.c b/scst/src/scst_targ.c index c07ce377b..3311b23bb 100644 --- a/scst/src/scst_targ.c +++ b/scst/src/scst_targ.c @@ -60,17 +60,17 @@ void scst_post_parse(struct scst_cmd *cmd) EXPORT_SYMBOL_GPL(scst_post_parse); /** - * scst_post_alloc_data_buf() - do post dev_alloc_data_buf actions + * scst_post_dev_alloc_data_buf() - do post dev_alloc_data_buf actions * * This function must be called by dev handler after its dev_alloc_data_buf() * callback returned SCST_CMD_STATE_STOP before calling * scst_process_active_cmd(). */ -void scst_post_alloc_data_buf(struct scst_cmd *cmd) +void scst_post_dev_alloc_data_buf(struct scst_cmd *cmd) { - scst_set_alloc_buf_time(cmd); + scst_set_dev_alloc_buf_time(cmd); } -EXPORT_SYMBOL_GPL(scst_post_alloc_data_buf); +EXPORT_SYMBOL_GPL(scst_post_dev_alloc_data_buf); static inline void scst_schedule_tasklet(struct scst_cmd *cmd) { @@ -1515,7 +1515,7 @@ static int scst_prepare_space(struct scst_cmd *cmd) switch (state) { case SCST_CMD_STATE_NEED_THREAD_CTX: - scst_set_alloc_buf_time(cmd); + scst_set_dev_alloc_buf_time(cmd); TRACE_DBG("Dev handler %s dev_alloc_data_buf() requested " "thread context, rescheduling", devt->name); res = SCST_CMD_STATE_RES_NEED_THREAD; @@ -1529,7 +1529,7 @@ static int scst_prepare_space(struct scst_cmd *cmd) goto out; } - scst_set_alloc_buf_time(cmd); + scst_set_dev_alloc_buf_time(cmd); if (unlikely(state != SCST_CMD_STATE_DEFAULT)) { cmd->state = state; @@ -1545,7 +1545,7 @@ static int scst_prepare_space(struct scst_cmd *cmd) scst_set_cur_start(cmd); r = cmd->tgtt->tgt_alloc_data_buf(cmd); - scst_set_alloc_buf_time(cmd); + scst_set_tgt_alloc_buf_time(cmd); if (r > 0) goto alloc;