From 7ab4d3e63815bceb7c042e163a95d4923e56b724 Mon Sep 17 00:00:00 2001 From: Vladislav Bolkhovitin Date: Mon, 14 Jan 2008 18:21:01 +0000 Subject: [PATCH] - Processing latency measurement facility added - README updated - Minor fixes git-svn-id: http://svn.code.sf.net/p/scst/svn/trunk@245 d57e44dd-8a1f-0410-8b47-8ef2f437770f --- iscsi-scst/kernel/conn.c | 2 +- scst/README | 4 + scst/include/scsi_tgt.h | 10 +++ scst/include/scst_debug.h | 2 +- scst/src/Makefile | 2 + scst/src/dev_handlers/scst_vdisk.c | 7 +- scst/src/scst_lib.c | 4 + scst/src/scst_proc.c | 138 +++++++++++++++++++++++++++-- scst/src/scst_targ.c | 71 +++++++++++++++ 9 files changed, 229 insertions(+), 11 deletions(-) diff --git a/iscsi-scst/kernel/conn.c b/iscsi-scst/kernel/conn.c index 1aa206d7f..56a9a054d 100644 --- a/iscsi-scst/kernel/conn.c +++ b/iscsi-scst/kernel/conn.c @@ -402,7 +402,7 @@ void iscsi_extracheck_is_rd_thread(struct iscsi_conn *conn) local_bh_enable(); printk(KERN_EMERG "conn %p rd_task != current %p (pid %d)\n", conn, current, current->pid); - printk(KERN_EMERG "wr_state %x\n", conn->rd_state); + printk(KERN_EMERG "rd_state %x\n", conn->rd_state); printk(KERN_EMERG "rd_task %p\n", conn->rd_task); printk(KERN_EMERG "rd_task->pid %d\n", conn->rd_task->pid); sBUG(); diff --git a/scst/README b/scst/README index aa4177aed..380a4e333 100644 --- a/scst/README +++ b/scst/README @@ -267,6 +267,10 @@ in/out in Makefile: Then sometimes get crazy itself. So, this option is disabled by default. + - MEASURE_LATENCY - if defined, provides in /proc/scsi_tgt/latency file + average commands processing latency. You can clear already measured + results by writing 0 in this file. + HIGHMEM kernel configurations are fully supported, but not recommended for performance reasons, except for scst_user, where they are not supported, because this module deals with user supplied memory on a diff --git a/scst/include/scsi_tgt.h b/scst/include/scsi_tgt.h index c0bd8f27e..148b36f5a 100644 --- a/scst/include/scsi_tgt.h +++ b/scst/include/scsi_tgt.h @@ -946,6 +946,12 @@ struct scst_session void (*init_result_fn) (struct scst_session *sess, void *data, int result); void (*unreg_done_fn) (struct scst_session *sess); + +#ifdef MEASURE_LATENCY + spinlock_t meas_lock; + uint64_t processing_time; + int processed_cmds; +#endif }; struct scst_cmd_lists @@ -1201,6 +1207,10 @@ struct scst_cmd struct list_head blocked_cmd_list_entry; struct scst_cmd *orig_cmd; /* Used to issue REQUEST SENSE */ + +#ifdef MEASURE_LATENCY + uint64_t start, pre_exec_finish, post_exec_start; +#endif }; struct scst_rx_mgmt_params diff --git a/scst/include/scst_debug.h b/scst/include/scst_debug.h index a21dcb385..c5475cc29 100644 --- a/scst/include/scst_debug.h +++ b/scst/include/scst_debug.h @@ -206,7 +206,7 @@ do { \ #define TRACE_MEM(args...) __TRACE(TRACE_MEMORY, args) #define TRACE_SG(args...) __TRACE(TRACE_SG_OP, args) #define TRACE_DBG(args...) __TRACE(TRACE_DEBUG, args) -#define TRACE_DBG_SPECIAL(args...) __TRACE((TRACE_DEBUG|TRACE_SPECIAL, args) +#define TRACE_DBG_SPECIAL(args...) __TRACE(TRACE_DEBUG|TRACE_SPECIAL, args) #define TRACE_MGMT_DBG(args...) __TRACE(TRACE_MGMT_DEBUG, args) #define TRACE_MGMT_DBG_SPECIAL(args...) __TRACE(TRACE_MGMT_DEBUG|TRACE_SPECIAL, args) diff --git a/scst/src/Makefile b/scst/src/Makefile index 9ecb2f719..cbebf264c 100644 --- a/scst/src/Makefile +++ b/scst/src/Makefile @@ -130,6 +130,8 @@ EXTRA_CFLAGS += -DDEBUG -g #EXTRA_CFLAGS += -DDEBUG_OOM #EXTRA_CFLAGS += -DDEBUG_SN +#EXTRA_CFLAGS += -DMEASURE_LATENCY + # If defined, makes SCST zero allocated data buffers. # Undefining it considerably improves performance and eases CPU load, # but could create a security hole (information leakage), so diff --git a/scst/src/dev_handlers/scst_vdisk.c b/scst/src/dev_handlers/scst_vdisk.c index e4976ba6e..67ae1796c 100644 --- a/scst/src/dev_handlers/scst_vdisk.c +++ b/scst/src/dev_handlers/scst_vdisk.c @@ -1007,6 +1007,7 @@ static int vcdrom_parse(struct scst_cmd *cmd) ********************************************************************/ static int vcdrom_exec(struct scst_cmd *cmd) { + int res = SCST_EXEC_COMPLETED; int opcode = cmd->cdb[0]; struct scst_vdisk_dev *virt_dev = (struct scst_vdisk_dev *)cmd->dev->dh_priv; @@ -1039,11 +1040,11 @@ static int vcdrom_exec(struct scst_cmd *cmd) spin_unlock(&virt_dev->flags_lock); } - vdisk_do_job(cmd); + res = vdisk_do_job(cmd); out: - TRACE_EXIT(); - return SCST_EXEC_COMPLETED; + TRACE_EXIT_RES(res); + return res; out_done: cmd->scst_cmd_done(cmd, SCST_CMD_STATE_DEFAULT); diff --git a/scst/src/scst_lib.c b/scst/src/scst_lib.c index 35fd55521..ba995f607 100644 --- a/scst/src/scst_lib.c +++ b/scst/src/scst_lib.c @@ -1123,6 +1123,10 @@ struct scst_session *scst_alloc_session(struct scst_tgt *tgt, int gfp_mask, INIT_LIST_HEAD(&sess->init_deferred_cmd_list); INIT_LIST_HEAD(&sess->init_deferred_mcmd_list); +#ifdef MEASURE_LATENCY + spin_lock_init(&sess->meas_lock); +#endif + len = strlen(initiator_name); nm = kmalloc(len + 1, gfp_mask); if (nm == NULL) { diff --git a/scst/src/scst_proc.c b/scst/src/scst_proc.c index 44a376551..27b519be3 100644 --- a/scst/src/scst_proc.c +++ b/scst/src/scst_proc.c @@ -68,6 +68,10 @@ static struct scst_proc_data scst_dev_handler_proc_data; #define SCST_PROC_GROUPS_DEVICES_ENTRY_NAME "devices" #define SCST_PROC_GROUPS_USERS_ENTRY_NAME "names" +#ifdef MEASURE_LATENCY +#define SCST_PROC_LAT_ENTRY_NAME "latency" +#endif + #define SCST_PROC_ACTION_ALL 1 #define SCST_PROC_ACTION_NONE 2 #define SCST_PROC_ACTION_DEFAULT 3 @@ -376,14 +380,118 @@ out: #endif /* defined(DEBUG) || defined(TRACING) */ -static int __init scst_proc_init_module_log(void) +#ifdef MEASURE_LATENCY + +static int lat_info_show(struct seq_file *seq, void *v) { int res = 0; -#if defined(DEBUG) || defined(TRACING) - struct proc_dir_entry *generic; + struct scst_acg *acg; + struct scst_session *sess; TRACE_ENTRY(); + if (mutex_lock_interruptible(&scst_mutex) != 0) { + res = -EINTR; + goto out; + } + + seq_printf(seq, "%-20s %-45s %-35s\n", "Target name", "Initiator name", + "Processing latency (us)"); + + 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) { + unsigned long lat = 0; + uint64_t processing_time; + uint64_t processed_cmds; + + spin_lock_bh(&sess->meas_lock); + processing_time = sess->processing_time; + processed_cmds = sess->processed_cmds; + spin_unlock_bh(&sess->meas_lock); + + TRACE_DBG("sess %p, processing_time %Ld, " + "processed_cmds %Ld", sess, processing_time, + processed_cmds); + +#if BITS_PER_LONG == 32 + while((processing_time & 0xFFFFFFFF00000000LL) != 0) { + TRACE_DBG("Processing time too big (" + "processing_time %Ld, processed_cmds %Ld", + processing_time, processed_cmds); + processing_time >>= 1; + processed_cmds >>= 1; + } +#endif + + if (sess->processed_cmds != 0) { + lat = (unsigned long)processing_time / + (unsigned long)processed_cmds; + } + + seq_printf(seq, "%-20s %-45s %-15ld\n", + sess->tgt->tgtt->name, + sess->initiator_name, + lat); + } + } + + mutex_unlock(&scst_mutex); + +out: + TRACE_EXIT_RES(res); + return res; +} + +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; + struct scst_acg *acg; + struct scst_session *sess; + + TRACE_ENTRY(); + + if (mutex_lock_interruptible(&scst_mutex) != 0) { + res = -EINTR; + goto out; + } + + 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; + sess->processed_cmds = 0; + spin_unlock_bh(&sess->meas_lock); + } + } + + mutex_unlock(&scst_mutex); + +out: + TRACE_EXIT_RES(res); + return res; +} + +static struct scst_proc_data scst_lat_proc_data = { + SCST_DEF_RW_SEQ_OP(scst_proc_scsi_tgt_gen_write_lat) + .show = lat_info_show, + .data = "scsi_tgt", +}; + +#endif /* MEASURE_LATENCY */ + +static int __init scst_proc_init_module_log(void) +{ + int res = 0; +#if defined(DEBUG) || defined(TRACING) || defined(MEASURE_LATENCY) + struct proc_dir_entry *generic; +#endif + + TRACE_ENTRY(); + +#if defined(DEBUG) || defined(TRACING) generic = scst_create_proc_entry(scst_proc_scsi_tgt, SCST_PROC_LOG_ENTRY_NAME, &scst_log_proc_data); @@ -392,21 +500,39 @@ static int __init scst_proc_init_module_log(void) SCST_PROC_ENTRY_NAME, SCST_PROC_LOG_ENTRY_NAME); res = -ENOMEM; } +#endif + +#ifdef MEASURE_LATENCY + if (res == 0) { + generic = scst_create_proc_entry(scst_proc_scsi_tgt, + SCST_PROC_LAT_ENTRY_NAME, + &scst_lat_proc_data); + if (!generic) { + PRINT_ERROR("cannot init /proc/%s/%s", + SCST_PROC_ENTRY_NAME, SCST_PROC_LAT_ENTRY_NAME); + res = -ENOMEM; + } + } +#endif TRACE_EXIT_RES(res); -#endif return res; } static void __exit scst_proc_cleanup_module_log(void) { -#if defined(DEBUG) || defined(TRACING) TRACE_ENTRY(); +#if defined(DEBUG) || defined(TRACING) remove_proc_entry(SCST_PROC_LOG_ENTRY_NAME, scst_proc_scsi_tgt); +#endif + +#ifdef MEASURE_LATENCY + remove_proc_entry(SCST_PROC_LAT_ENTRY_NAME, scst_proc_scsi_tgt); +#endif TRACE_EXIT(); -#endif + return; } int scst_proc_group_add_tree(struct scst_acg *acg, const char *name) diff --git a/scst/src/scst_targ.c b/scst/src/scst_targ.c index aa6ec1979..ca5e952ea 100644 --- a/scst/src/scst_targ.c +++ b/scst/src/scst_targ.c @@ -162,6 +162,13 @@ out_redirect: goto out; } +#ifdef 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, int pref_context) { unsigned long flags; @@ -169,6 +176,17 @@ void scst_cmd_init_done(struct scst_cmd *cmd, int pref_context) TRACE_ENTRY(); +#ifdef MEASURE_LATENCY + { + struct timespec ts; + getnstimeofday(&ts); + cmd->start = scst_sec_to_nsec(ts.tv_sec) + ts.tv_nsec; + TRACE_DBG("cmd %p (sess %p): start %Ld (tv_sec %ld, " + "tv_nsec %ld)", cmd, sess, cmd->start, ts.tv_sec, + ts.tv_nsec); + } +#endif + TRACE_DBG("Preferred context: %d (cmd %p)", pref_context, cmd); TRACE(TRACE_SCSI, "tag=%llu, lun=%Ld, CDB len=%d", cmd->tag, (uint64_t)cmd->lun, cmd->cdb_len); @@ -1028,6 +1046,17 @@ static void scst_do_cmd_done(struct scst_cmd *cmd, int result, { TRACE_ENTRY(); +#ifdef MEASURE_LATENCY + { + struct timespec ts; + getnstimeofday(&ts); + cmd->post_exec_start = scst_sec_to_nsec(ts.tv_sec) + ts.tv_nsec; + TRACE_DBG("cmd %p (sess %p): post_exec_start %Ld (tv_sec %ld, " + "tv_nsec %ld)", cmd, cmd->sess, cmd->post_exec_start, ts.tv_sec, + ts.tv_nsec); + } +#endif + cmd->status = result & 0xff; cmd->msg_status = msg_byte(result); cmd->host_status = host_byte(result); @@ -1154,6 +1183,17 @@ static void scst_cmd_done_local(struct scst_cmd *cmd, int next_state) { TRACE_ENTRY(); +#ifdef MEASURE_LATENCY + { + struct timespec ts; + getnstimeofday(&ts); + cmd->post_exec_start = scst_sec_to_nsec(ts.tv_sec) + ts.tv_nsec; + TRACE_DBG("cmd %p (sess %p): post_exec_start %Ld (tv_sec %ld, " + "tv_nsec %ld)", cmd, cmd->sess, cmd->post_exec_start, ts.tv_sec, + ts.tv_nsec); + } +#endif + if (next_state == SCST_CMD_STATE_DEFAULT) next_state = SCST_CMD_STATE_PRE_DEV_DONE; @@ -1829,6 +1869,17 @@ static int scst_send_to_midlev(struct scst_cmd **active_cmd) } } +#ifdef MEASURE_LATENCY + if (cmd->pre_exec_finish == 0) { + struct timespec ts; + getnstimeofday(&ts); + cmd->pre_exec_finish = scst_sec_to_nsec(ts.tv_sec) + ts.tv_nsec; + TRACE_DBG("cmd %p (sess %p): pre_exec_finish %Ld (tv_sec %ld, " + "tv_nsec %ld)", cmd, cmd->sess, cmd->pre_exec_finish, ts.tv_sec, + ts.tv_nsec); + } +#endif + if (unlikely(scst_inc_on_dev_cmd(cmd) != 0)) goto out_put; @@ -2421,6 +2472,26 @@ static int scst_pre_xmit_response(struct scst_cmd *cmd) res = SCST_CMD_STATE_RES_CONT_SAME; out: +#ifdef MEASURE_LATENCY + { + struct timespec ts; + uint64_t finish, processing_time; + struct scst_session *sess = cmd->sess; + + getnstimeofday(&ts); + finish = scst_sec_to_nsec(ts.tv_sec) + ts.tv_nsec; + + spin_lock_bh(&sess->meas_lock); + processing_time = cmd->pre_exec_finish - cmd->start; + processing_time += finish - cmd->post_exec_start; + sess->processing_time += processing_time; + sess->processed_cmds++; + TRACE_DBG("cmd %p (sess %p): finish %Ld (tv_sec %ld, " + "tv_nsec %ld), processing_time %Ld", cmd, sess, finish, + ts.tv_sec, ts.tv_nsec, processing_time); + spin_unlock_bh(&sess->meas_lock); + } +#endif TRACE_EXIT_HRES(res); return res; }