- 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

@@ -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();

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

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

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)
 

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 

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);

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) {

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)

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;
 }