log: list the number of pending cmds for each device

CMakeLists.txt

@@ -47,6 +47,7 @@ add_library(tcmu
   libtcmu_log.c
   libtcmu_config.c
   libtcmu_time.c
+  libtcmu_timer.c
   )
 set_target_properties(tcmu
   PROPERTIES
@@ -75,6 +76,7 @@ add_library(tcmu_static
   libtcmu_log.c
   libtcmu_config.c
   libtcmu_time.c
+  libtcmu_timer.c
   )
 target_include_directories(tcmu_static
   PUBLIC ${LIBNL_INCLUDE_DIR}

ccan/ccan/list/list.h

@@ -306,6 +306,58 @@ static inline bool list_empty_nocheck(const struct list_head *h)
 	return h->n.next == &h->n;
 }
 
+static inline void __list_splice(struct list_head *list, struct list_head *head)
+{
+    list->n.prev->next = head->n.next;
+    head->n.next->prev = list->n.prev;
+
+    head->n.next = list->n.next;
+    list->n.next->prev = &head->n;
+}
+
+static inline void
+list_splice(struct list_head *list, struct list_head *head)
+{
+    if (list_empty(list))
+        return;
+
+    __list_splice(list, head);
+}
+
+/* Splice moves @list to the head of the list at @head. */
+static inline void
+list_splice_init(struct list_head *list, struct list_head *head)
+{
+    if (list_empty(list))
+        return;
+
+    __list_splice(list, head);
+    list_head_init(list);
+}
+
+/**
+ * list_replace - replace old entry by new one
+ * @old : the element to be replaced
+ * @new : the new element to insert
+ *
+ * If @old was empty, it will be overwritten.
+ */
+static inline void
+list_replace(struct list_head *old, struct list_head *new)
+{
+    new->n.next = old->n.next;
+    new->n.next->prev = &new->n;
+    new->n.prev = old->n.prev;
+    new->n.prev->next = &new->n;
+}
+
+static inline void
+list_replace_init(struct list_head *old, struct list_head *new)
+{
+    list_replace(old, new);
+    list_head_init(old);
+}
+
 /**
  * list_del - delete an entry from an (unknown) linked list.
  * @n: the list_node to delete from the list.

libtcmu.c

@@ -6,6 +6,7 @@
 
 #define _GNU_SOURCE
 #include <memory.h>
+#include <inttypes.h>
 #include <sys/types.h>
 #include <sys/stat.h>
 #include <fcntl.h>
@@ -535,6 +536,9 @@ static int add_device(struct tcmulib_context *ctx, char *dev_name,
 	}
 
 	darray_append(ctx->devices, dev);
+	pthread_mutex_lock(&pending_cmds_lock);
+	list_add_tail(&pending_cmds_head, &dev->entry);
+	pthread_mutex_unlock(&pending_cmds_lock);
 
 	if (reopen && reset_supp)
 		tcmu_cfgfs_dev_exec_action(dev, "block_dev", 0);
@@ -588,6 +592,9 @@ static void remove_device(struct tcmulib_context *ctx, char *dev_name,
 	}
 
 	darray_remove(ctx->devices, i);
+	pthread_mutex_lock(&pending_cmds_lock);
+	list_del_init(&dev->entry);
+	pthread_mutex_unlock(&pending_cmds_lock);
 
 	dev->handler->removed(dev);
 
@@ -964,6 +971,9 @@ struct tcmulib_cmd *tcmulib_get_next_command(struct tcmu_device *dev)
 			if (!cmd)
 				return NULL;
 			cmd->cmd_id = ent->hdr.cmd_id;
+			cmd->dev = dev;
+			cmd->timer = NULL;
+			cmd->timeout = 0;
 
 			/* Convert iovec addrs in-place to not be offsets */
 			cmd->iov_cnt = ent->req.iov_cnt;
@@ -1124,6 +1134,11 @@ void tcmulib_command_complete(
 	struct tcmu_mailbox *mb = dev->map;
 	struct tcmu_cmd_entry *ent = (void *) mb + mb->cmdr_off + mb->cmd_tail;
 
+	if (cmd->timeout) {
+		dev->timeout_cmds[cmd->timeout / CMD_TO_STEP - 1]--;
+		pthread_cond_signal(&pending_cmds_cond);
+	}
+
 	/* current command could be PAD in async case */
 	while (ent != (void *) mb + mb->cmdr_off + mb->cmd_head) {
 		if (tcmu_hdr_get_op(ent->hdr.len_op) == TCMU_OP_CMD)
@@ -1144,6 +1159,9 @@ void tcmulib_command_complete(
 	}
 
 	TCMU_UPDATE_RB_TAIL(mb, ent);
+
+	if (cmd->timer)
+		free(cmd->timer);
 	free(cmd);
 }
 

libtcmu_common.h

@@ -111,6 +111,10 @@ struct tcmulib_cmd {
 
 	/* callback to finish/continue command processing */
 	cmd_done_t done;
+
+	struct tcmu_device *dev;
+	struct tcmu_timer *timer;
+	uint16_t timeout;
 };
 
 /* Set/Get methods for the opaque tcmu_device */

libtcmu_log.c

@@ -220,7 +220,7 @@ log_internal(int pri, struct tcmu_device *dev, const char *funcname,
 	     int linenr, const char *fmt, va_list args)
 {
 	char buf[LOG_MSG_LEN];
-	int n;
+	int n = 0;
 	struct tcmulib_handler *handler;
 
 	if (pri > tcmu_log_level)
@@ -236,13 +236,14 @@ log_internal(int pri, struct tcmu_device *dev, const char *funcname,
 	}
 
 	/* Format the log msg */
+	if (funcname)
+		n = sprintf(buf, "%s:%d: ", funcname, linenr);
+
 	if (dev) {
 		handler = tcmu_dev_get_handler(dev);
-		n = sprintf(buf, "%s:%d %s/%s: ", funcname, linenr,
-		            handler ? handler->subtype: "",
-		            dev ? dev->tcm_dev_name: "");
-	} else {
-		n = sprintf(buf, "%s:%d: ", funcname, linenr);
+		n += sprintf(buf + n, "%s/%s: ",
+		             handler ? handler->subtype: "",
+		             dev ? dev->tcm_dev_name: "");
 	}
 
 	vsnprintf(buf + n, LOG_MSG_LEN - n, fmt, args);
@@ -514,6 +515,34 @@ static bool log_dequeue_msg(struct log_buf *logbuf)
 	return true;
 }
 
+pthread_cond_t pending_cmds_cond = PTHREAD_COND_INITIALIZER;
+pthread_mutex_t pending_cmds_lock = PTHREAD_MUTEX_INITIALIZER;
+struct list_head pending_cmds_head = LIST_HEAD_INIT(pending_cmds_head);
+static pthread_t pending_thread_id;
+static void *log_thread_pending_start(void *arg)
+{
+	struct tcmu_device *dev, *tmp;
+
+	while (1) {
+		pthread_mutex_lock(&pending_cmds_lock);
+		pthread_cond_wait(&pending_cmds_cond, &pending_cmds_lock);
+		list_for_each_safe(&pending_cmds_head, dev, tmp, entry) {
+			tcmu_dev_warn_simple(dev, "Pending cmds: 180(+)s:[%lu],"
+				" 150s:[%lu], 120s:[%lu], 90s:[%lu], 60s:[%lu],"
+				" 30s:[%lu]\n",
+				dev->timeout_cmds[CMD_TO_180SEC / CMD_TO_STEP - 1],
+				dev->timeout_cmds[CMD_TO_150SEC / CMD_TO_STEP - 1],
+				dev->timeout_cmds[CMD_TO_120SEC / CMD_TO_STEP - 1],
+				dev->timeout_cmds[CMD_TO_90SEC / CMD_TO_STEP - 1],
+				dev->timeout_cmds[CMD_TO_60SEC / CMD_TO_STEP - 1],
+				dev->timeout_cmds[CMD_TO_30SEC / CMD_TO_STEP - 1]);
+		}
+		pthread_mutex_unlock(&pending_cmds_lock);
+	}
+
+	return NULL;
+}
+
 static void *log_thread_start(void *arg)
 {
 	tcmu_logbuf = arg;
@@ -694,6 +723,13 @@ int tcmu_setup_log(char *log_dir)
 		return ret;
 	}
 
+	ret = pthread_create(&pending_thread_id, NULL, log_thread_pending_start,
+			     NULL);
+	if (ret) {
+		pthread_cancel(logbuf->thread_id);
+		return ret;
+	}
+
 	return 0;
 
 free_log_dir:

libtcmu_log.h

@@ -26,6 +26,9 @@
 
 struct tcmu_device;
 struct tcmu_config;
+extern struct list_head pending_cmds_head;
+extern pthread_cond_t pending_cmds_cond;
+extern pthread_mutex_t pending_cmds_lock;
 
 void tcmu_set_log_level(int level);
 unsigned int tcmu_get_log_level(void);
@@ -50,6 +53,7 @@ void tcmu_dbg_scsi_cmd_message(struct tcmu_device *dev, const char *funcname, in
 #define tcmu_dev_crit(dev, ...)  do { tcmu_crit_message(dev, __func__, __LINE__, __VA_ARGS__);} while (0)
 #define tcmu_dev_err(dev, ...)  do { tcmu_err_message(dev, __func__, __LINE__, __VA_ARGS__);} while (0)
 #define tcmu_dev_warn(dev, ...) do { tcmu_warn_message(dev, __func__, __LINE__, __VA_ARGS__);} while (0)
+#define tcmu_dev_warn_simple(dev, ...) do { tcmu_warn_message(dev, NULL, 0, __VA_ARGS__);} while (0)
 #define tcmu_dev_info(dev, ...) do { tcmu_info_message(dev, __func__, __LINE__, __VA_ARGS__);} while (0)
 #define tcmu_dev_dbg(dev, ...)  do { tcmu_dbg_message(dev, __func__, __LINE__, __VA_ARGS__);} while (0)
 #define tcmu_dev_dbg_scsi_cmd(dev, ...)  do { tcmu_dbg_scsi_cmd_message(dev, __func__, __LINE__, __VA_ARGS__);} while (0)

libtcmu_priv.h

@@ -20,6 +20,7 @@
 #include <pthread.h>
 
 #include "darray.h"
+#include "ccan/list/list.h"
 
 #define KERN_IFACE_VER 2
 
@@ -35,6 +36,15 @@ struct tcmulib_context {
 	GDBusConnection *connection;
 };
 
+#define	CMD_TO_30SEC	30
+#define	CMD_TO_60SEC	60
+#define	CMD_TO_90SEC	90
+#define	CMD_TO_120SEC	120
+#define	CMD_TO_150SEC	150
+#define	CMD_TO_180SEC	180
+#define	CMD_TO_STEP	30
+#define	CMD_TO_COUNT	6
+
 struct tcmu_device {
 	int fd;
 
@@ -63,6 +73,9 @@ struct tcmu_device {
 	struct tcmulib_handler *handler;
 	struct tcmulib_context *ctx;
 
+	uint64_t timeout_cmds[CMD_TO_COUNT];
+	struct list_node entry;
+
 	void *hm_private; /* private ptr for handler module */
 };