Skip to content

Commit

Permalink
Task log (#419)
Browse files Browse the repository at this point in the history 
* Task and scheduler logging
  • Loading branch information
@bretambrose
bretambrose authored Jul 1, 2019
1 parent c2b8f4d commit 970a96e
Show file tree
Hide file tree
Showing 3 changed files with 77 additions and 22 deletions.
21 changes: 15 additions & 6 deletions include/aws/common/task_scheduler.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand All @@ -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.
*/
Expand Down Expand Up @@ -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 */
46 changes: 46 additions & 0 deletions source/task_scheduler.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,8 +15,37 @@

#include <aws/common/task_scheduler.h>

#include <aws/common/logging.h>

#include <inttypes.h>

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 "<Running>";

case AWS_TASK_STATUS_CANCELED:
return "<Canceled>";

default:
return "<Unknown>";
}
}

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;
Expand Down Expand Up @@ -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;
Expand All @@ -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;
Expand Down Expand Up @@ -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);
}
32 changes: 16 additions & 16 deletions tests/task_scheduler_test.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -114,15 +114,15 @@ 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));
ASSERT_UINT_EQUALS(10, next_task_time);

/* 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));
Expand All @@ -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);

Expand Down Expand Up @@ -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;
}
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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;

Expand Down Expand Up @@ -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);
}
Expand Down Expand Up @@ -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,
Expand All @@ -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);

Expand Down

0 comments on commit 970a96e

Please sign in to comment.