Merge pull request #300 from wenchao-hao/actor_log

actor: introduce thread name which would be printed to log.

4 files changed, 61 insertions, 36 deletions

diff --git a/usr/actor.c b/usr/actor.c
index 000e66a..a6bb02f 100644
--- a/usr/actor.c
+++ b/usr/actor.c
@@ -43,8 +43,12 @@ actor_time_left(actor_t *thread, time_t current_time)
 	((int64_t)(b) - (int64_t)(a) < 0)
 
 void
-actor_init(actor_t *thread, void (*callback)(void *), void *data)
+__actor_init(actor_t *thread, void (*callback)(void *), void *data)
 {
+	if (thread->state != ACTOR_INVALID)
+		log_error("bug:thread %p:%s has already been initialized",
+			  thread, thread->name);
+
 	INIT_LIST_HEAD(&thread->list);
 	thread->state = ACTOR_NOTSCHEDULED;
 	thread->callback = callback;
@@ -54,7 +58,8 @@ actor_init(actor_t *thread, void (*callback)(void *), void *data)
 void
 actor_delete(actor_t *thread)
 {
-	log_debug(7, "thread %08lx delete: state %d", (long)thread,
+	log_debug(7, "thread %p:%s delete: state %d",
+			thread, thread->name,
 			thread->state);
 	switch(thread->state) {
 	case ACTOR_WAITING:
@@ -62,7 +67,8 @@ actor_delete(actor_t *thread)
 		/* priority: low */
 		/* fallthrough */
 	case ACTOR_SCHEDULED:
-		log_debug(1, "deleting a scheduled/waiting thread!");
+		log_debug(1, "deleting a scheduled/waiting thread %p:%s!",
+			 thread, thread->name);
 		list_del_init(&thread->list);
 		if (list_empty(&pend_list)) {
 			log_debug(7, "nothing left on pend_list, deactivating alarm");
@@ -93,10 +99,10 @@ actor_insert_on_pend_list(actor_t *thread, uint32_t delay_secs)
 	/* insert new entry in sort order */
 	list_for_each_entry(next_thread, &pend_list, list) {
 		if (time_after(next_thread->ttschedule, thread->ttschedule)) {
-			log_debug(7, "next thread %p due %lld", next_thread,
-			  (long long)next_thread->ttschedule);
-			log_debug(7, "new thread %p is before (%lld), inserting", thread,
-			  (long long)thread->ttschedule);
+			log_debug(7, "next thread %p:%s due %lld", next_thread,
+			  next_thread->name, (long long)next_thread->ttschedule);
+			log_debug(7, "new thread %p:%s is before (%lld), inserting",
+			  thread, next_thread->name, (long long)thread->ttschedule);
 
 			/* insert new thread before the next thread */
 			__list_add(&thread->list, next_thread->list.prev, &next_thread->list);
@@ -105,14 +111,14 @@ actor_insert_on_pend_list(actor_t *thread, uint32_t delay_secs)
 	}
 
 	if (orig_head) {
-		log_debug(7, "last thread %p due %lld", next_thread,
-			  (long long)next_thread->ttschedule);
-		log_debug(7, "new thread %p is after (%lld), inserting at tail", thread,
-			  (long long)thread->ttschedule);
+		log_debug(7, "last thread %p:%s due %lld", next_thread,
+			  next_thread->name, (long long)next_thread->ttschedule);
+		log_debug(7, "new thread %p:%s is after (%lld), inserting at tail",
+			  thread, thread->name, (long long)thread->ttschedule);
 	}
 	else
-		log_debug(7, "new thread %p due %lld is first item on pend_list", thread,
-			  (long long)thread->ttschedule);
+		log_debug(7, "new thread %p:%s due %lld is first item on pend_list",
+			  thread, thread->name, (long long)thread->ttschedule);
 
 	/* Not before any existing entries */
 	list_add_tail(&thread->list, &pend_list);
@@ -140,12 +146,13 @@ actor_schedule_private(actor_t *thread, uint32_t delay_secs, int head)
 
 	current_time = tv.tv_sec;
 
-	log_debug(7, "thread %p schedule: delay %u state %d",
-		thread, delay_secs, thread->state);
+	log_debug(7, "thread %p:%s schedule: delay %u state %d",
+		thread, thread->name, delay_secs, thread->state);
 
 	switch(thread->state) {
 	case ACTOR_WAITING:
-		log_error("rescheduling a waiting thread!");
+		log_error("rescheduling a waiting thread %p:%s !",
+			  thread, thread->name);
 		list_del(&thread->list);
 		/* fall-through */
 	case ACTOR_NOTSCHEDULED:
@@ -168,8 +175,9 @@ actor_schedule_private(actor_t *thread, uint32_t delay_secs, int head)
 		// don't do anything
 		break;
 	case ACTOR_INVALID:
-		log_error("BUG: Trying to schedule a thread that has not been "
-			  "setup. Ignoring sched.");
+		log_error("BUG: Trying to schedule a thread %p"
+			  "that has not been setup. Ignoring sched.",
+			  thread);
 		break;
 	}
 
@@ -188,10 +196,10 @@ actor_schedule(actor_t *thread)
 }
 
 void
-actor_timer(actor_t *thread, uint32_t timeout_secs, void (*callback)(void *),
+__actor_timer(actor_t *thread, uint32_t timeout_secs, void (*callback)(void *),
 	    void *data)
 {
-	actor_init(thread, callback, data);
+	__actor_init(thread, callback, data);
 	actor_schedule_private(thread, timeout_secs, 0);
 }
 
@@ -238,8 +246,8 @@ actor_poll(void)
 	list_for_each_entry_safe(thread, tmp, &pend_list, list) {
 		uint64_t time_left = actor_time_left(thread, current_time);
 		if (time_left) {
-			log_debug(7, "thread %08lx due %" PRIu64 ", wait %" PRIu64 " more",
-				  (long)thread,
+			log_debug(7, "thread %p:%s due %" PRIu64 ", wait %" PRIu64 " more",
+				  thread, thread->name,
 				  (uint64_t)thread->ttschedule, time_left);
 
 			alarm(time_left);
@@ -249,17 +257,17 @@ actor_poll(void)
 		/* This entry can be run now */
 		list_del_init(&thread->list);
 
-		log_debug(2, "thread %08lx was scheduled for "
+		log_debug(2, "thread %p:%s was scheduled for "
 			  "%" PRIu64 ", curtime %" PRIu64 " q_forw %p "
 			  "&pend_list %p",
-			  (long)thread, (uint64_t)thread->ttschedule,
+			  thread, thread->name, (uint64_t)thread->ttschedule,
 			  current_time, pend_list.next, &pend_list);
 
 		list_add_tail(&thread->list, &ready_list);
 		assert(thread->state == ACTOR_WAITING);
 		thread->state = ACTOR_SCHEDULED;
-		log_debug(7, "thread %08lx now in ready_list",
-			  (long)thread);
+		log_debug(7, "thread %p:%s now in ready_list",
+			  thread, thread->name);
 	}
 
 	/* Disable alarm if nothing else pending */
@@ -274,13 +282,15 @@ actor_poll(void)
 		list_del_init(&thread->list);
 
 		if (thread->state != ACTOR_SCHEDULED)
-			log_error("ready_list: thread state corrupted! "
+			log_error("ready_list: thread %p:%s state corrupted! "
 				  "Thread with state %d in actor list.",
+				  thread, thread->name,
 				  thread->state);
 		thread->state = ACTOR_NOTSCHEDULED;
-		log_debug(7, "exec thread %08lx callback", (long)thread);
+		log_debug(7, "exec thread %p:%s",
+			  thread, thread->name);
 		thread->callback(thread->data);
-		log_debug(7, "thread %08lx done", (long)thread);
+		log_debug(7, "thread %p:%s done", thread, thread->name);
 	}
 	poll_in_progress = 0;
 }
diff --git a/usr/actor.h b/usr/actor.h
index f572f2e..a67eb36 100644
--- a/usr/actor.h
+++ b/usr/actor.h
@@ -19,9 +19,12 @@
 #ifndef ACTOR_H
 #define ACTOR_H
 
+#include <stdio.h>
 #include "types.h"
 #include "list.h"
 
+#define ACTOR_NAME_LEN 128
+
 typedef enum actor_state_e {
     ACTOR_INVALID,
     ACTOR_WAITING,
@@ -30,6 +33,7 @@ typedef enum actor_state_e {
 } actor_state_e;
 
 typedef struct actor {
+	char name[ACTOR_NAME_LEN];
 	struct list_head list;
 	actor_state_e state;
 	void *data;
@@ -37,14 +41,26 @@ typedef struct actor {
 	time_t ttschedule;
 } actor_t;
 
-extern void actor_init(actor_t *thread, void (*callback)(void *), void * data);
+extern void __actor_init(actor_t *thread, void (*callback)(void *), void * data);
 extern void actor_delete(actor_t *thread);
 extern void actor_schedule_head(actor_t *thread);
 extern void actor_schedule(actor_t *thread);
-extern void actor_timer(actor_t *thread, uint32_t delay_secs,
+extern void __actor_timer(actor_t *thread, uint32_t delay_secs,
 			void (*callback)(void *), void *data);
 extern void actor_timer_mod(actor_t *thread, uint32_t new_delay_secs,
 			    void *data);
 extern void actor_poll(void);
 
+#define actor_init(thread, callback, data) \
+do { \
+	snprintf((thread)->name, ACTOR_NAME_LEN, #callback); \
+	__actor_init(thread, callback, data); \
+} while (0)
+
+#define actor_timer(thread, timeout_secs, callback, data) \
+do { \
+	snprintf((thread)->name, ACTOR_NAME_LEN, #callback); \
+	__actor_timer(thread, timeout_secs, callback, data); \
+} while (0)
+
 #endif /* ACTOR_H */
diff --git a/usr/initiator.c b/usr/initiator.c
index 4ec00b0..40d297f 100644
--- a/usr/initiator.c
+++ b/usr/initiator.c
@@ -137,7 +137,8 @@ iscsi_ev_context_get(iscsi_conn_t *conn, int ev_size)
 
 static void iscsi_ev_context_put(struct iscsi_ev_context *ev_context)
 {
-	log_debug(7, "put ev context %p", &ev_context->actor);
+	log_debug(7, "put ev context %p:%s", &ev_context->actor,
+		  (&ev_context->actor)->name);
 	ev_context->allocated = 0;
 }
 
diff --git a/usr/initiator_common.c b/usr/initiator_common.c
index 6cf26c1..bc69fbd 100644
--- a/usr/initiator_common.c
+++ b/usr/initiator_common.c
@@ -273,12 +273,10 @@ static int host_set_param(struct iscsi_transport *t,
 
 static void print_param_value(enum iscsi_param param, void *value, int type)
 {
-	log_debug(3, "set operational parameter %d to:", param);
-
 	if (type == ISCSI_STRING)
-		log_debug(3, "%s", value ? (char *)value : "NULL");
+		log_debug(3, "set operational parameter %d to %s", param, value ? (char *)value : "NULL");
 	else
-		log_debug(3, "%u", *(uint32_t *)value);
+		log_debug(3, "set operational parameter %d to %u", param, *(uint32_t *)value);
 }
 
 #define MAX_HOST_PARAMS 2