- Processing latency measurement facility added
authorvlnb <vlnb@d57e44dd-8a1f-0410-8b47-8ef2f437770f>
Mon, 14 Jan 2008 18:21:01 +0000 (18:21 +0000)
committervlnb <vlnb@d57e44dd-8a1f-0410-8b47-8ef2f437770f>
Mon, 14 Jan 2008 18:21:01 +0000 (18:21 +0000)
 - README updated
 - Minor fixes

git-svn-id: https://scst.svn.sourceforge.net/svnroot/scst/trunk@245 d57e44dd-8a1f-0410-8b47-8ef2f437770f

iscsi-scst/kernel/conn.c
scst/README
scst/include/scsi_tgt.h
scst/include/scst_debug.h
scst/src/Makefile
scst/src/dev_handlers/scst_vdisk.c
scst/src/scst_lib.c
scst/src/scst_proc.c
scst/src/scst_targ.c

index 1aa206d..56a9a05 100644 (file)
@@ -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();
index aa4177a..380a4e3 100644 (file)
@@ -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
index c0bd8f2..148b36f 100644 (file)
@@ -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
index a21dcb3..c5475cc 100644 (file)
@@ -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)
 
index 9ecb2f7..cbebf26 100644 (file)
@@ -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 
index e4976ba..67ae179 100644 (file)
@@ -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);
index 35fd555..ba995f6 100644 (file)
@@ -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) {
index 44a3765..27b519b 100644 (file)
@@ -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) */
 
+#ifdef MEASURE_LATENCY
+
+static int lat_info_show(struct seq_file *seq, void *v)
+{
+       int res = 0;
+       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)
+#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
 
-       TRACE_EXIT_RES(res);
+#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);
        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
 
-       TRACE_EXIT();
+#ifdef MEASURE_LATENCY
+       remove_proc_entry(SCST_PROC_LAT_ENTRY_NAME, scst_proc_scsi_tgt);
 #endif
+
+       TRACE_EXIT();
+       return;
 }
 
 int scst_proc_group_add_tree(struct scst_acg *acg, const char *name)
index aa6ec19..ca5e952 100644 (file)
@@ -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;
 }