From 3cf5539b9f531295db29401d0b9346881a4b08a0 Mon Sep 17 00:00:00 2001 From: Wenchao Hao Date: Tue, 1 Feb 2022 23:30:35 +0800 Subject: actor: add name to struct actor and init it with function name Previous actor log makes it hard to figure out what is going on in the thread, such as: "deleting a scheduled/waiting thread!" We only know a thread is deleted, while no other info like what this thread is about to do and which thread it is. Logs like following seems better: "deleting a scheduled/waiting thread 01111e48: session_conn_error !" It tells thread with id 01111e48, which is going to executed function "session_conn_error" is deleted. The commit tries to give name to each thread, the name is going to be printed with previous messages to make the log easy to read. Signed-off-by: Wenchao Hao --- usr/actor.c | 6 +++--- usr/actor.h | 20 ++++++++++++++++++-- 2 files changed, 21 insertions(+), 5 deletions(-) (limited to 'usr') diff --git a/usr/actor.c b/usr/actor.c index 000e66a..283d92b 100644 --- a/usr/actor.c +++ b/usr/actor.c @@ -43,7 +43,7 @@ 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) { INIT_LIST_HEAD(&thread->list); thread->state = ACTOR_NOTSCHEDULED; @@ -188,10 +188,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); } 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 #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 */ -- cgit v1.2.1 From 1ae939da124a44ee23690c8e6b76df777d98e8aa Mon Sep 17 00:00:00 2001 From: Wenchao Hao Date: Wed, 2 Feb 2022 00:32:36 +0800 Subject: actor: print thread name in log This commit is append of 3cf5539 which just print the thread name in log. Signed-off-by: Wenchao Hao --- usr/actor.c | 58 +++++++++++++++++++++++++++++++-------------------------- usr/initiator.c | 3 ++- 2 files changed, 34 insertions(+), 27 deletions(-) (limited to 'usr') diff --git a/usr/actor.c b/usr/actor.c index 283d92b..dc008a7 100644 --- a/usr/actor.c +++ b/usr/actor.c @@ -54,7 +54,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 +63,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 +95,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 +107,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 +142,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 +171,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; } @@ -238,8 +242,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 +253,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 +278,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/initiator.c b/usr/initiator.c index 684647c..fdbe8ea 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; } -- cgit v1.2.1 From 0b9675a2263174060b11e459fcfd554b10f9ca1e Mon Sep 17 00:00:00 2001 From: Wenchao Hao Date: Wed, 2 Feb 2022 12:13:16 +0800 Subject: actor: enhanced: print error log when init a initilized thread This is only a enhance, do not change origin logic Signed-off-by: Wenchao Hao --- usr/actor.c | 4 ++++ 1 file changed, 4 insertions(+) (limited to 'usr') diff --git a/usr/actor.c b/usr/actor.c index dc008a7..a6bb02f 100644 --- a/usr/actor.c +++ b/usr/actor.c @@ -45,6 +45,10 @@ actor_time_left(actor_t *thread, time_t current_time) void __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; -- cgit v1.2.1 From d4a13200efd215d5b115db60f075921c5e67cc57 Mon Sep 17 00:00:00 2001 From: Wenchao Hao Date: Wed, 2 Feb 2022 16:09:05 +0800 Subject: initiator_common: make set operational parameter log easy to read iscsid would print log like following if debug level is larger than 3: iscsid: set operational parameter 35 to: iscsid: 30 iscsid: set operational parameter 30 to: iscsid: 5 which is not friendly to read, this commit makes it easy to read, like this: iscsid: set operational parameter 35 to: 30 iscsid: set operational parameter 30 to: 5 Signed-off-by: Wenchao Hao --- usr/initiator_common.c | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) (limited to 'usr') 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 -- cgit v1.2.1