Menu
▾
▴
[Scst-svn] SF.net SVN: scst: [245] trunk
|
From: <vl...@us...> - 2008-01-14 18:21:06
|
Revision: 245
http://scst.svn.sourceforge.net/scst/?rev=245&view=rev
Author: vlnb
Date: 2008-01-14 10:21:01 -0800 (Mon, 14 Jan 2008)
Log Message:
-----------
- Processing latency measurement facility added
- README updated
- Minor fixes
Modified Paths:
--------------
trunk/iscsi-scst/kernel/conn.c
trunk/scst/README
trunk/scst/include/scsi_tgt.h
trunk/scst/include/scst_debug.h
trunk/scst/src/Makefile
trunk/scst/src/dev_handlers/scst_vdisk.c
trunk/scst/src/scst_lib.c
trunk/scst/src/scst_proc.c
trunk/scst/src/scst_targ.c
Modified: trunk/iscsi-scst/kernel/conn.c
===================================================================
--- trunk/iscsi-scst/kernel/conn.c 2008-01-11 18:09:38 UTC (rev 244)
+++ trunk/iscsi-scst/kernel/conn.c 2008-01-14 18:21:01 UTC (rev 245)
@@ -402,7 +402,7 @@
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();
Modified: trunk/scst/README
===================================================================
--- trunk/scst/README 2008-01-11 18:09:38 UTC (rev 244)
+++ trunk/scst/README 2008-01-14 18:21:01 UTC (rev 245)
@@ -267,6 +267,10 @@
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
Modified: trunk/scst/include/scsi_tgt.h
===================================================================
--- trunk/scst/include/scsi_tgt.h 2008-01-11 18:09:38 UTC (rev 244)
+++ trunk/scst/include/scsi_tgt.h 2008-01-14 18:21:01 UTC (rev 245)
@@ -946,6 +946,12 @@
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 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
Modified: trunk/scst/include/scst_debug.h
===================================================================
--- trunk/scst/include/scst_debug.h 2008-01-11 18:09:38 UTC (rev 244)
+++ trunk/scst/include/scst_debug.h 2008-01-14 18:21:01 UTC (rev 245)
@@ -206,7 +206,7 @@
#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)
Modified: trunk/scst/src/Makefile
===================================================================
--- trunk/scst/src/Makefile 2008-01-11 18:09:38 UTC (rev 244)
+++ trunk/scst/src/Makefile 2008-01-14 18:21:01 UTC (rev 245)
@@ -130,6 +130,8 @@
#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
Modified: trunk/scst/src/dev_handlers/scst_vdisk.c
===================================================================
--- trunk/scst/src/dev_handlers/scst_vdisk.c 2008-01-11 18:09:38 UTC (rev 244)
+++ trunk/scst/src/dev_handlers/scst_vdisk.c 2008-01-14 18:21:01 UTC (rev 245)
@@ -1007,6 +1007,7 @@
********************************************************************/
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 @@
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);
Modified: trunk/scst/src/scst_lib.c
===================================================================
--- trunk/scst/src/scst_lib.c 2008-01-11 18:09:38 UTC (rev 244)
+++ trunk/scst/src/scst_lib.c 2008-01-14 18:21:01 UTC (rev 245)
@@ -1123,6 +1123,10 @@
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) {
Modified: trunk/scst/src/scst_proc.c
===================================================================
--- trunk/scst/src/scst_proc.c 2008-01-11 18:09:38 UTC (rev 244)
+++ trunk/scst/src/scst_proc.c 2008-01-14 18:21:01 UTC (rev 245)
@@ -68,6 +68,10 @@
#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 @@
#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 @@
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)
Modified: trunk/scst/src/scst_targ.c
===================================================================
--- trunk/scst/src/scst_targ.c 2008-01-11 18:09:38 UTC (rev 244)
+++ trunk/scst/src/scst_targ.c 2008-01-14 18:21:01 UTC (rev 245)
@@ -162,6 +162,13 @@
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 @@
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 @@
{
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 @@
{
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 @@
}
}
+#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 @@
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;
}
This was sent by the SourceForge.net collaborative development platform, the world's largest Open Source development site.
|
