scst: Make it possible to inspect commands state

Signed-off-by: Bart Van Assche <bvanassche@acm.org>

with some improvements



git-svn-id: http://svn.code.sf.net/p/scst/svn/trunk@5108 d57e44dd-8a1f-0410-8b47-8ef2f437770f

scst/README

@@ -437,6 +437,12 @@ following entries:
    Those threads used with async. dev handlers, for instance, vdisk
    BLOCKIO or NULLIO.
 
+ - trace_cmds - shows current SCST commands up to size of the sysfs
+   buffer (4KB)
+
+ - trace_mcmds - shows current SCST management commands up to size of
+   the sysfs buffer (4KB)
+
  - trace_level - allows to enable and disable various tracing
    facilities. See content of this file for help how to use it. See also
    section "Dealing with massive logs" for more info how to make correct

scst/README_in-tree

@@ -299,6 +299,12 @@ following entries:
    Those threads used with async. dev handlers, for instance, vdisk
    BLOCKIO or NULLIO.
 
+ - trace_cmds - shows current SCST commands up to size of the sysfs
+   buffer (4KB)
+
+ - trace_mcmds - shows current SCST management commands up to size of
+   the sysfs buffer (4KB)
+
  - trace_level - allows to enable and disable various tracing
    facilities. See content of this file for help how to use it. See also
    section "Dealing with massive logs" for more info how to make correct

scst/include/scst.h

@@ -193,6 +193,9 @@ static inline bool list_entry_in_list(const struct list_head *entry)
  ** "active" states, then - "passive" ones. This is to have
  ** more efficient generated code of the corresponding
  ** "switch" statements.
+ **
+ ** !! Adding new states don't forget to update scst_cmd_state_name
+ ** !! as well!
  *************************************************************/
 enum {
 	/* Dev handler's parse() is going to be called */
@@ -293,6 +296,9 @@ enum {
 
 /*************************************************************
  ** States of mgmt command processing state machine
+ **
+ ** !! Adding new states don't forget to update
+ ** !! scst_mcmd_state_name as well!
  *************************************************************/
 enum {
 	/* LUN translation (mcmd->tgt_dev assignment) */

scst/include/scst_const.h

@@ -98,7 +98,12 @@
 #define SCST_LUN_RESET			4
 #define SCST_TARGET_RESET		5
 
-/** SCST extensions **/
+/**
+ ** SCST extensions
+ **
+ ** !! Adding new extensions don't forget to update
+ ** !! scst_tm_fn_name as well!
+ **/
 
 /*
  * Notifies about I_T nexus loss event in the corresponding session.

scst/src/scst_main.c

@@ -699,6 +699,173 @@ again:
 }
 EXPORT_SYMBOL(scst_unregister_target);
 
+static const char *const scst_cmd_state_name[] = {
+	[SCST_CMD_STATE_PARSE]				= "PARSE",
+	[SCST_CMD_STATE_PREPARE_SPACE]			= "PREPARE_SPACE",
+	[SCST_CMD_STATE_PREPROCESSING_DONE]		= "PREP_DONE",
+	[SCST_CMD_STATE_RDY_TO_XFER]			= "RDY_TO_XFER",
+	[SCST_CMD_STATE_TGT_PRE_EXEC]			= "TGT_PRE_EXEC",
+	[SCST_CMD_STATE_EXEC_CHECK_SN]			= "EXEC_CHECK_SN",
+	[SCST_CMD_STATE_PRE_DEV_DONE]			= "PRE_DEV_DONE",
+	[SCST_CMD_STATE_MODE_SELECT_CHECKS]		= "MODE_SELECT_CHECKS",
+	[SCST_CMD_STATE_DEV_DONE]			= "DEV_DONE",
+	[SCST_CMD_STATE_PRE_XMIT_RESP]			= "PRE_XMIT_RESP",
+	[SCST_CMD_STATE_XMIT_RESP]			= "XMIT_RESP",
+	[SCST_CMD_STATE_FINISHED]			= "FINISHED",
+	[SCST_CMD_STATE_FINISHED_INTERNAL]		= "FINISHED_INTERNAL",
+	[SCST_CMD_STATE_INIT_WAIT]			= "INIT_WAIT",
+	[SCST_CMD_STATE_INIT]				= "INIT",
+	[SCST_CMD_STATE_PREPROCESSING_DONE_CALLED]	= "PREP_DONE_CALLED",
+	[SCST_CMD_STATE_DATA_WAIT]			= "DATA_WAIT",
+	[SCST_CMD_STATE_EXEC_CHECK_BLOCKING]		= "EXEC_CHECK_BLOCKING",
+	[SCST_CMD_STATE_LOCAL_EXEC]			= "LOCAL_EXEC",
+	[SCST_CMD_STATE_REAL_EXEC]			= "REAL_EXEC",
+	[SCST_CMD_STATE_EXEC_WAIT]			= "EXEC_WAIT",
+	[SCST_CMD_STATE_XMIT_WAIT]			= "XMIT_WAIT",
+};
+
+static void scst_get_cmd_state_name(char *name, int len, unsigned state)
+{
+	if (state < ARRAY_SIZE(scst_cmd_state_name) &&
+	    scst_cmd_state_name[state])
+		strlcpy(name, scst_cmd_state_name[state], len);
+	else
+		snprintf(name, len, "%d", state);
+}
+
+static char *scst_dump_cdb(char *buf, int buf_len, struct scst_cmd *cmd)
+{
+	char *p = buf, *end = buf + buf_len;
+	int i;
+
+	for (i = 0; i < cmd->cdb_len && p < end; i++)
+		p += scnprintf(p, end - p, "%s%02x", i ? " " : "", cmd->cdb[i]);
+
+	return buf;
+}
+
+void scst_trace_cmds(scst_show_fn show, void *arg)
+{
+	struct scst_tgt_template *t;
+	struct scst_tgt *tgt;
+	struct scst_session *sess;
+	struct scst_cmd *cmd;
+	struct scst_tgt_dev *tgt_dev;
+	char state_name[32];
+	char cdb[64];
+
+	mutex_lock(&scst_mutex);
+	list_for_each_entry(t, &scst_template_list, scst_template_list_entry) {
+		list_for_each_entry(tgt, &t->tgt_list, tgt_list_entry) {
+			list_for_each_entry(sess, &tgt->sess_list,
+					    sess_list_entry) {
+				spin_lock_irq(&sess->sess_list_lock);
+				list_for_each_entry(cmd, &sess->sess_cmd_list,
+						    sess_cmd_list_entry) {
+					tgt_dev = cmd->tgt_dev;
+					scst_dump_cdb(cdb, sizeof(cdb), cmd);
+					scst_get_cmd_state_name(state_name,
+							    sizeof(state_name),
+							    cmd->state);
+					show(arg, "cmd %p: state %s; tgtt %s; "
+						"tgt %s; session %s; grp %s; "
+						"LUN %lld; ini %s; cdb %s\n",
+						cmd, state_name, t->name,
+						tgt->tgt_name, sess->sess_name,
+						tgt_dev ? (tgt_dev->acg_dev->acg->acg_name ?
+							     	: "(default)") : "?",
+						cmd->lun, sess->initiator_name, cdb);
+				}
+				spin_unlock_irq(&sess->sess_list_lock);
+			}
+		}
+	}
+	mutex_unlock(&scst_mutex);
+	return;
+}
+
+static const char *const scst_tm_fn_name[] = {
+	[SCST_ABORT_TASK]	= "ABORT_TASK",
+	[SCST_ABORT_TASK_SET]	= "ABORT_TASK_SET",
+	[SCST_CLEAR_ACA]	= "CLEAR_ACA",
+	[SCST_CLEAR_TASK_SET]	= "CLEAR_TASK_SET",
+	[SCST_LUN_RESET]	= "LUN_RESET",
+	[SCST_TARGET_RESET]	= "TARGET_RESET",
+	[SCST_NEXUS_LOSS_SESS]	= "NEXUS_LOSS_SESS",
+	[SCST_ABORT_ALL_TASKS_SESS] = "ABORT_ALL_TASKS_SESS",
+	[SCST_NEXUS_LOSS] =	"NEXUS_LOSS",
+	[SCST_ABORT_ALL_TASKS] = "ABORT_ALL_TASKS",
+	[SCST_UNREG_SESS_TM] =	"UNREG_SESS_TM",
+	[SCST_PR_ABORT_ALL] =	"PR_ABORT_ALL",
+};
+
+static void scst_get_tm_fn_name(char *name, int len, unsigned fn)
+{
+	if (fn < ARRAY_SIZE(scst_tm_fn_name) && scst_tm_fn_name[fn])
+		strlcpy(name, scst_tm_fn_name[fn], len);
+	else
+		snprintf(name, len, "%d", fn);
+	return;
+}
+
+static const char *const scst_mcmd_state_name[] = {
+	[SCST_MCMD_STATE_INIT] =	"INIT",
+	[SCST_MCMD_STATE_EXEC] =	"EXEC",
+	[SCST_MCMD_STATE_WAITING_AFFECTED_CMDS_DONE] = "WAITING_AFFECTED_CMDS_DONE",
+	[SCST_MCMD_STATE_AFFECTED_CMDS_DONE] = "AFFECTED_CMDS_DONE",
+	[SCST_MCMD_STATE_WAITING_AFFECTED_CMDS_FINISHED] = "WAITING_AFFECTED_CMDS_FINISHED",
+	[SCST_MCMD_STATE_DONE] =	"DONE",
+	[SCST_MCMD_STATE_FINISHED] =	"FINISHED",
+};
+
+static void scst_get_mcmd_state_name(char *name, int len, unsigned state)
+{
+	if (state < ARRAY_SIZE(scst_mcmd_state_name) &&
+	    scst_mcmd_state_name[state])
+		strlcpy(name, scst_mcmd_state_name[state], len);
+	else
+		snprintf(name, len, "%d", state);
+	return;
+}
+
+void scst_trace_mcmds(scst_show_fn show, void *arg)
+{
+	struct scst_mgmt_cmd *mcmd;
+	char fn_name[16], state_name[32];
+
+	spin_lock_irq(&scst_mcmd_lock);
+	list_for_each_entry(mcmd, &scst_active_mgmt_cmd_list,
+			    mgmt_cmd_list_entry) {
+		scst_get_tm_fn_name(fn_name, sizeof(fn_name), mcmd->fn);
+		scst_get_mcmd_state_name(state_name, sizeof(state_name),
+					 mcmd->state);
+		show(arg, "mcmd %p: state %s; tgtt %s; tgt %s; session %s; fn %s;"
+		     " LUN %lld; tag %lld; cmd_done_wait_count %d\n",
+		     mcmd, state_name, mcmd->sess->tgt->tgtt->name,
+		     mcmd->sess->tgt->tgt_name, mcmd->sess->sess_name, fn_name,
+		     mcmd->lun, mcmd->tag, mcmd->cmd_done_wait_count);
+	}
+	spin_unlock_irq(&scst_mcmd_lock);
+	return;
+}
+
+static void __printf(2, 3) scst_to_syslog(void *arg, const char *fmt, ...)
+{
+	bool *header_printed = arg;
+	va_list args;
+
+	if (!*header_printed) {
+		PRINT_INFO("Pending commands:");
+		*header_printed = true;
+	}
+
+	va_start(args, fmt);
+	printk(KERN_INFO "    ");
+	vprintk(fmt, args);
+	va_end(args);
+	return;
+}
+
 int scst_get_cmd_counter(void)
 {
 	int i, res = 0;
@@ -709,13 +876,32 @@ int scst_get_cmd_counter(void)
 
 static int scst_susp_wait(unsigned long timeout)
 {
-	int res = 0;
+	int res;
+	unsigned long t;
+	bool hp = false;
+#define SCST_SUSP_WAIT_REPORT_TIMEOUT (5UL * HZ)
 
 	TRACE_ENTRY();
 
+	if (timeout == SCST_SUSPEND_TIMEOUT_UNLIMITED)
+		t = SCST_SUSP_WAIT_REPORT_TIMEOUT;
+	else
+		t = min(timeout, SCST_SUSP_WAIT_REPORT_TIMEOUT);
+
+	res = wait_event_interruptible_timeout(scst_dev_cmd_waitQ,
+			(scst_get_cmd_counter() == 0), t);
+	if (res > 0) {
+		res = 0;
+		goto out;
+	} else if ((res < 0) && (timeout != SCST_SUSPEND_TIMEOUT_UNLIMITED))
+		goto out;
+
+	scst_trace_cmds(scst_to_syslog, &hp);
+	scst_trace_mcmds(scst_to_syslog, &hp);
+
 	if (timeout != SCST_SUSPEND_TIMEOUT_UNLIMITED) {
 		res = wait_event_interruptible_timeout(scst_dev_cmd_waitQ,
-			(scst_get_cmd_counter() == 0), timeout);
+			(scst_get_cmd_counter() == 0), timeout - t);
 		if (res == 0)
 			res = -EBUSY;
 		else if (res > 0)
@@ -723,10 +909,12 @@ static int scst_susp_wait(unsigned long timeout)
 	} else
 		wait_event(scst_dev_cmd_waitQ, scst_get_cmd_counter() == 0);
 
+out:
 	TRACE_MGMT_DBG("wait_event() returned %d", res);
 
 	TRACE_EXIT_RES(res);
 	return res;
+#undef SCST_SUSP_WAIT_REPORT_TIMEOUT
 }
 
 /**

scst/src/scst_priv.h

@@ -751,6 +751,10 @@ int gen_relative_target_port_id(uint16_t *id);
 bool scst_is_relative_target_port_id_unique(uint16_t id,
 	const struct scst_tgt *t);
 
+typedef void __printf(2, 3) (*scst_show_fn)(void *arg, const char *fmt, ...);
+void scst_trace_cmds(scst_show_fn show, void *arg);
+void scst_trace_mcmds(scst_show_fn show, void *arg);
+
 #ifdef CONFIG_SCST_MEASURE_LATENCY
 
 void scst_set_start_time(struct scst_cmd *cmd);

scst/src/scst_sysfs.c

@@ -5683,6 +5683,8 @@ static const struct attribute *scst_device_groups_attrs[] = {
  ** SCST sysfs root directory implementation
  **/
 
+static struct kobject scst_sysfs_root_kobj;
+
 static ssize_t scst_threads_show(struct kobject *kobj,
 	struct kobj_attribute *attr, char *buf)
 {
@@ -5909,6 +5911,109 @@ static struct kobj_attribute scst_main_trace_level_attr =
 
 #endif /* defined(CONFIG_SCST_DEBUG) || defined(CONFIG_SCST_TRACING) */
 
+static void __printf(2, 3) scst_append(void *arg, const char *fmt, ...)
+{
+	char *buf = arg;
+	int len = strlen(buf);
+	va_list args;
+
+	va_start(args, fmt);
+	vscnprintf(buf + len, SCST_SYSFS_BLOCK_SIZE - len, fmt, args);
+	va_end(args);
+}
+
+static int scst_process_show_trace_cmds(struct scst_sysfs_work_item *work)
+{
+	int ret = -ENOMEM;
+
+	work->res_buf = kmalloc(SCST_SYSFS_BLOCK_SIZE, GFP_KERNEL);
+	if (!work->res_buf)
+		goto put;
+	work->res_buf[0] = '\0';
+	scst_trace_cmds(scst_append, work->res_buf);
+	ret = 0;
+
+put:
+	kobject_put(&scst_sysfs_root_kobj);
+	return ret;
+}
+
+static ssize_t scst_show_trace_cmds(struct kobject *kobj,
+				    struct kobj_attribute *attr, char *buf)
+{
+	struct scst_sysfs_work_item *work;
+	int res;
+
+	res = scst_alloc_sysfs_work(scst_process_show_trace_cmds, true,
+				    &work);
+	if (res != 0)
+		goto out;
+
+	kobject_get(&scst_sysfs_root_kobj);
+	scst_sysfs_work_get(work);
+	res = scst_sysfs_queue_wait_work(work);
+	if (res != 0)
+		goto put;
+
+	res = scnprintf(buf, SCST_SYSFS_BLOCK_SIZE, "%s", work->res_buf);
+
+put:
+	scst_sysfs_work_put(work);
+
+out:
+	return res;
+
+}
+
+static struct kobj_attribute scst_trace_cmds_attr =
+	__ATTR(trace_cmds, S_IRUGO, scst_show_trace_cmds, NULL);
+
+static int scst_process_show_trace_mcmds(struct scst_sysfs_work_item *work)
+{
+	int ret = -ENOMEM;
+
+	work->res_buf = kmalloc(SCST_SYSFS_BLOCK_SIZE, GFP_KERNEL);
+	if (!work->res_buf)
+		goto put;
+	work->res_buf[0] = '\0';
+	scst_trace_mcmds(scst_append, work->res_buf);
+	ret = 0;
+
+put:
+	kobject_put(&scst_sysfs_root_kobj);
+	return ret;
+}
+
+static ssize_t scst_show_trace_mcmds(struct kobject *kobj,
+				      struct kobj_attribute *attr, char *buf)
+{
+	struct scst_sysfs_work_item *work;
+	int res;
+
+	res = scst_alloc_sysfs_work(scst_process_show_trace_mcmds, true,
+				    &work);
+	if (res != 0)
+		goto out;
+
+	kobject_get(&scst_sysfs_root_kobj);
+	scst_sysfs_work_get(work);
+	res = scst_sysfs_queue_wait_work(work);
+	if (res != 0)
+		goto put;
+
+	res = scnprintf(buf, SCST_SYSFS_BLOCK_SIZE, "%s", work->res_buf);
+
+put:
+	scst_sysfs_work_put(work);
+
+out:
+	return res;
+
+}
+
+static struct kobj_attribute scst_trace_mcmds_attr =
+	__ATTR(trace_mcmds, S_IRUGO, scst_show_trace_mcmds, NULL);
+
 static ssize_t scst_version_show(struct kobject *kobj,
 				 struct kobj_attribute *attr,
 				 char *buf)
@@ -5998,6 +6103,8 @@ static struct attribute *scst_sysfs_root_default_attrs[] = {
 #if defined(CONFIG_SCST_DEBUG) || defined(CONFIG_SCST_TRACING)
 	&scst_main_trace_level_attr.attr,
 #endif
+	&scst_trace_cmds_attr.attr,
+	&scst_trace_mcmds_attr.attr,
 	&scst_version_attr.attr,
 	&scst_last_sysfs_mgmt_res_attr.attr,
 	NULL,
@@ -6226,8 +6333,6 @@ out:
 }
 EXPORT_SYMBOL_GPL(scst_wait_info_completion);
 
-static struct kobject scst_sysfs_root_kobj;
-
 int __init scst_sysfs_init(void)
 {
 	int res = 0;