From 970a96e688259307c51684d81eb2a71a40324514 Mon Sep 17 00:00:00 2001 From: Bret Ambrose Date: Mon, 1 Jul 2019 10:31:55 -0700 Subject: [PATCH] Task log (#419) * Task and scheduler logging --- include/aws/common/task_scheduler.h | 21 +++++++++---- source/task_scheduler.c | 46 +++++++++++++++++++++++++++++ tests/task_scheduler_test.c | 32 ++++++++++---------- 3 files changed, 77 insertions(+), 22 deletions(-) diff --git a/include/aws/common/task_scheduler.h b/include/aws/common/task_scheduler.h index ec1bb1565..135d56a98 100644 --- a/include/aws/common/task_scheduler.h +++ b/include/aws/common/task_scheduler.h @@ -42,18 +42,15 @@ struct aws_task { uint64_t timestamp; struct aws_linked_list_node node; struct aws_priority_queue_node priority_queue_node; + const char *type_tag; size_t reserved; }; -AWS_STATIC_IMPL void aws_task_init(struct aws_task *task, aws_task_fn *fn, void *arg) { +AWS_STATIC_IMPL void aws_task_init(struct aws_task *task, aws_task_fn *fn, void *arg, const char *type_tag) { AWS_ZERO_STRUCT(*task); task->fn = fn; task->arg = arg; -} - -AWS_STATIC_IMPL void aws_task_run(struct aws_task *task, enum aws_task_status status) { - AWS_ASSERT(task->fn); - task->fn(task, task->arg, status); + task->type_tag = type_tag; } struct aws_task_scheduler { @@ -65,6 +62,12 @@ struct aws_task_scheduler { AWS_EXTERN_C_BEGIN +/* + * Runs or cancels a task + */ +AWS_COMMON_API +void aws_task_run(struct aws_task *task, enum aws_task_status status); + /** * Initializes a task scheduler instance. */ @@ -118,6 +121,12 @@ void aws_task_scheduler_cancel_task(struct aws_task_scheduler *scheduler, struct AWS_COMMON_API void aws_task_scheduler_run_all(struct aws_task_scheduler *scheduler, uint64_t current_time); +/** + * Convert a status value to a c-string suitable for logging + */ +AWS_COMMON_API +const char *aws_task_status_to_c_str(enum aws_task_status status); + AWS_EXTERN_C_END #endif /* AWS_COMMON_TASK_SCHEDULER_H */ diff --git a/source/task_scheduler.c b/source/task_scheduler.c index e3949cf32..05b492863 100644 --- a/source/task_scheduler.c +++ b/source/task_scheduler.c @@ -15,8 +15,37 @@ #include +#include + +#include + static const size_t DEFAULT_QUEUE_SIZE = 7; +const char *aws_task_status_to_c_str(enum aws_task_status status) { + switch (status) { + case AWS_TASK_STATUS_RUN_READY: + return ""; + + case AWS_TASK_STATUS_CANCELED: + return ""; + + default: + return ""; + } +} + +void aws_task_run(struct aws_task *task, enum aws_task_status status) { + AWS_ASSERT(task->fn); + AWS_LOGF_DEBUG( + AWS_LS_COMMON_TASK_SCHEDULER, + "id=%p: Running %s task with %s status", + (void *)task, + task->type_tag, + aws_task_status_to_c_str(status)); + + task->fn(task, task->arg, status); +} + static int s_compare_timestamps(const void *a, const void *b) { uint64_t a_time = (*(struct aws_task **)a)->timestamp; uint64_t b_time = (*(struct aws_task **)b)->timestamp; @@ -87,6 +116,12 @@ void aws_task_scheduler_schedule_now(struct aws_task_scheduler *scheduler, struc AWS_ASSERT(task); AWS_ASSERT(task->fn); + AWS_LOGF_DEBUG( + AWS_LS_COMMON_TASK_SCHEDULER, + "id=%p: Scheduling %s task for immediate execution", + (void *)task, + task->type_tag); + task->priority_queue_node.current_index = SIZE_MAX; aws_linked_list_node_reset(&task->node); task->timestamp = 0; @@ -103,6 +138,13 @@ void aws_task_scheduler_schedule_future( AWS_ASSERT(task); AWS_ASSERT(task->fn); + AWS_LOGF_DEBUG( + AWS_LS_COMMON_TASK_SCHEDULER, + "id=%p: Scheduling %s task for future execution at time %" PRIu64, + (void *)task, + task->type_tag, + time_to_run); + task->timestamp = time_to_run; task->priority_queue_node.current_index = SIZE_MAX; @@ -202,5 +244,9 @@ void aws_task_scheduler_cancel_task(struct aws_task_scheduler *scheduler, struct } else { aws_priority_queue_remove(&scheduler->timed_queue, &task, &task->priority_queue_node); } + + /* + * No need to log cancellation specially; it will get logged during the run call with the canceled status + */ aws_task_run(task, AWS_TASK_STATUS_CANCELED); } diff --git a/tests/task_scheduler_test.c b/tests/task_scheduler_test.c index e5c51eb30..48e4ef4f1 100644 --- a/tests/task_scheduler_test.c +++ b/tests/task_scheduler_test.c @@ -47,20 +47,20 @@ static int s_test_scheduler_ordering(struct aws_allocator *allocator, void *ctx) aws_task_scheduler_init(&scheduler, allocator); struct aws_task task2; - aws_task_init(&task2, s_task_n_fn, (void *)2); + aws_task_init(&task2, s_task_n_fn, (void *)2, "scheduler_ordering_1"); /* schedule 250 ns in the future. */ uint64_t task2_timestamp = 250; aws_task_scheduler_schedule_future(&scheduler, &task2, task2_timestamp); struct aws_task task1; - aws_task_init(&task1, s_task_n_fn, (void *)1); + aws_task_init(&task1, s_task_n_fn, (void *)1, "scheduler_ordering_2"); /* schedule now. */ aws_task_scheduler_schedule_now(&scheduler, &task1); struct aws_task task3; - aws_task_init(&task3, s_task_n_fn, (void *)3); + aws_task_init(&task3, s_task_n_fn, (void *)3, "scheduler_ordering_3"); /* schedule 500 ns in the future. */ uint64_t task3_timestamp = 500; @@ -114,7 +114,7 @@ static int s_test_scheduler_has_tasks(struct aws_allocator *allocator, void *ctx /* Check when a task is scheduled for the future */ struct aws_task timed_task; - aws_task_init(&timed_task, s_null_fn, (void *)1); + aws_task_init(&timed_task, s_null_fn, (void *)1, "scheduler_has_tasks_1"); aws_task_scheduler_schedule_future(&scheduler, &timed_task, 10); ASSERT_TRUE(aws_task_scheduler_has_tasks(&scheduler, &next_task_time)); @@ -122,7 +122,7 @@ static int s_test_scheduler_has_tasks(struct aws_allocator *allocator, void *ctx /* Check when a task is scheduled for now */ struct aws_task now_task; - aws_task_init(&now_task, s_null_fn, (void *)2); + aws_task_init(&now_task, s_null_fn, (void *)2, "scheduler_has_tasks_2"); aws_task_scheduler_schedule_now(&scheduler, &now_task); ASSERT_TRUE(aws_task_scheduler_has_tasks(&scheduler, &next_task_time)); @@ -140,7 +140,7 @@ static int s_test_scheduler_pops_task_fashionably_late(struct aws_allocator *all aws_task_scheduler_init(&scheduler, allocator); struct aws_task task; - aws_task_init(&task, s_task_n_fn, (void *)0); + aws_task_init(&task, s_task_n_fn, (void *)0, "scheduler_pops_task_fashionably_late"); aws_task_scheduler_schedule_future(&scheduler, &task, 10); @@ -190,7 +190,7 @@ static void s_reentrancy_args_init( AWS_ZERO_STRUCT(*args); args->scheduler = scheduler; - aws_task_init(&args->task, s_reentrancy_fn, args); + aws_task_init(&args->task, s_reentrancy_fn, args, "scheduler_reentrancy"); args->status = -1; args->next_task_args = next_task_args; } @@ -248,12 +248,12 @@ static int s_test_scheduler_cleanup_cancellation(struct aws_allocator *allocator struct cancellation_args now_task_args = {.status = 100000}; struct aws_task now_task; - aws_task_init(&now_task, s_cancellation_fn, &now_task_args); + aws_task_init(&now_task, s_cancellation_fn, &now_task_args, "scheduler_cleanup_cancellation_1"); aws_task_scheduler_schedule_now(&scheduler, &now_task); struct cancellation_args future_task_args = {.status = 100000}; struct aws_task future_task; - aws_task_init(&future_task, s_cancellation_fn, &future_task_args); + aws_task_init(&future_task, s_cancellation_fn, &future_task_args, "scheduler_cleanup_cancellation_2"); aws_task_scheduler_schedule_future(&scheduler, &future_task, 9999999999999); aws_task_scheduler_clean_up(&scheduler); @@ -377,7 +377,7 @@ static int s_test_scheduler_oom_still_works(struct aws_allocator *allocator, voi do { struct aws_task *task = aws_mem_acquire(allocator, sizeof(struct aws_task)); ASSERT_NOT_NULL(task); - aws_task_init(task, s_oom_task_fn, &done_tasks); + aws_task_init(task, s_oom_task_fn, &done_tasks, "scheduler_oom_still_works1"); size_t prev_rejects = oom_impl->num_allocations_rejected; @@ -406,7 +406,7 @@ static int s_test_scheduler_oom_still_works(struct aws_allocator *allocator, voi for (now_count = 0; now_count < 10; ++now_count) { struct aws_task *task = aws_mem_acquire(allocator, sizeof(struct aws_task)); ASSERT_NOT_NULL(task); - aws_task_init(task, s_oom_task_fn, &done_tasks); + aws_task_init(task, s_oom_task_fn, &done_tasks, "scheduler_oom_still_works2"); aws_task_scheduler_schedule_now(&scheduler, task); } @@ -463,27 +463,27 @@ static int s_test_scheduler_schedule_cancellation(struct aws_allocator *allocato aws_task_scheduler_init(&scheduler, allocator); struct aws_task task2; - aws_task_init(&task2, s_task_n_fn, (void *)2); + aws_task_init(&task2, s_task_n_fn, (void *)2, "scheduler_schedule_cancellation1"); /* schedule 250 ns in the future. */ uint64_t task2_timestamp = 250; aws_task_scheduler_schedule_future(&scheduler, &task2, task2_timestamp); struct aws_task task1; - aws_task_init(&task1, s_task_n_fn, (void *)1); + aws_task_init(&task1, s_task_n_fn, (void *)1, "scheduler_schedule_cancellation2"); /* schedule now. */ aws_task_scheduler_schedule_now(&scheduler, &task1); struct aws_task task5; - aws_task_init(&task5, s_task_n_fn, (void *)3); + aws_task_init(&task5, s_task_n_fn, (void *)3, "scheduler_schedule_cancellation5"); /* schedule 500 ns in the future. */ uint64_t task5_timestamp = 500; aws_task_scheduler_schedule_future(&scheduler, &task5, task5_timestamp); struct aws_task task4; - aws_task_init(&task4, s_task_n_fn, (void *)5); + aws_task_init(&task4, s_task_n_fn, (void *)5, "scheduler_schedule_cancellation4"); struct task_cancelling_task_data task_cancel_data = { .scheduler = &scheduler, @@ -492,7 +492,7 @@ static int s_test_scheduler_schedule_cancellation(struct aws_allocator *allocato struct aws_task task3; - aws_task_init(&task3, s_task_cancelling_task, &task_cancel_data); + aws_task_init(&task3, s_task_cancelling_task, &task_cancel_data, "scheduler_schedule_cancellation3"); aws_task_scheduler_schedule_now(&scheduler, &task3); aws_task_scheduler_schedule_now(&scheduler, &task4);