From 44c3b222761132fd890689ff3e28c4c0da3b4d95 Mon Sep 17 00:00:00 2001 From: Dipin Hora Date: Sat, 16 Jul 2022 14:51:13 -0400 Subject: [PATCH] Systematic testing enhancements Update SYSTEMATIC_TESTING_PRINTF to take a level argument. Add cli argument for controlling output level of systematic testing printf's. Add SYSTEMATIC_TESTING_YIELD and SYSTEMATIC_TESTING_PRINTF in a lot more places. --- src/libponyrt/actor/actor.c | 45 ++++++++++++++++++++++++ src/libponyrt/actor/messageq.c | 45 ++++++++++++++++++++++++ src/libponyrt/options/options.h | 5 +++ src/libponyrt/sched/mpmcq.c | 40 +++++++++++++++++++++ src/libponyrt/sched/scheduler.c | 29 +++++++++++++-- src/libponyrt/sched/scheduler.h | 2 +- src/libponyrt/sched/start.c | 8 +++-- src/libponyrt/sched/systematic_testing.c | 33 ++++++++++------- src/libponyrt/sched/systematic_testing.h | 12 +++---- 9 files changed, 196 insertions(+), 23 deletions(-) diff --git a/src/libponyrt/actor/actor.c b/src/libponyrt/actor/actor.c index 4cde62da357..088034924db 100644 --- a/src/libponyrt/actor/actor.c +++ b/src/libponyrt/actor/actor.c @@ -1,6 +1,7 @@ #define PONY_WANT_ATOMIC_DEFS #include "actor.h" +#include "../sched/systematic_testing.h" #include "../sched/scheduler.h" #include "../sched/cpu.h" #include "../mem/pool.h" @@ -57,12 +58,14 @@ static bool has_sync_flag(pony_actor_t* actor, uint8_t flag) static void set_sync_flag(pony_actor_t* actor, uint8_t flag) { uint8_t flags = atomic_load_explicit(&actor->sync_flags, memory_order_acquire); + SYSTEMATIC_TESTING_YIELD(); atomic_store_explicit(&actor->sync_flags, flags | flag, memory_order_release); } static void unset_sync_flag(pony_actor_t* actor, uint8_t flag) { uint8_t flags = atomic_load_explicit(&actor->sync_flags, memory_order_acquire); + SYSTEMATIC_TESTING_YIELD(); atomic_store_explicit(&actor->sync_flags, flags & (uint8_t)~flag, memory_order_release); } @@ -109,12 +112,14 @@ static void unset_internal_flag(pony_actor_t* actor, uint8_t flag) static void mute_actor(pony_actor_t* actor) { + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu muted...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); set_sync_flag(actor, SYNC_FLAG_MUTED); DTRACE1(ACTOR_MUTED, (uintptr_t)actor); } void ponyint_unmute_actor(pony_actor_t* actor) { + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu unmuted...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); unset_sync_flag(actor, SYNC_FLAG_MUTED); DTRACE1(ACTOR_UNMUTED, (uintptr_t)actor); } @@ -127,6 +132,7 @@ static bool triggers_muting(pony_actor_t* actor) static void actor_setoverloaded(pony_actor_t* actor) { + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu overloaded...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); pony_assert(!ponyint_is_cycle(actor)); set_sync_flag(actor, SYNC_FLAG_OVERLOADED); DTRACE1(ACTOR_OVERLOADED, (uintptr_t)actor); @@ -135,6 +141,7 @@ static void actor_setoverloaded(pony_actor_t* actor) static void actor_unsetoverloaded(pony_actor_t* actor) { pony_ctx_t* ctx = pony_ctx(); + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu unoverloaded...\n", ctx->scheduler->tid, (uintptr_t)actor); unset_sync_flag(actor, SYNC_FLAG_OVERLOADED); DTRACE1(ACTOR_OVERLOADED_CLEARED, (uintptr_t)actor); if (!has_sync_flag(actor, SYNC_FLAG_UNDER_PRESSURE)) @@ -223,6 +230,7 @@ static bool handle_message(pony_ctx_t* ctx, pony_actor_t* actor, ctx->mem_allocated_messages -= POOL_ALLOC_SIZE(pony_msgp_t); #endif + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu handled message ACTORMSG_ACQUIRE...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); pony_assert(!ponyint_is_cycle(actor)); pony_msgp_t* m = (pony_msgp_t*)msg; @@ -250,6 +258,7 @@ static bool handle_message(pony_ctx_t* ctx, pony_actor_t* actor, ctx->mem_allocated_messages -= POOL_ALLOC_SIZE(pony_msgp_t); #endif + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu handled message ACTORMSG_RELEASE...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); pony_assert(!ponyint_is_cycle(actor)); pony_msgp_t* m = (pony_msgp_t*)msg; @@ -277,6 +286,7 @@ static bool handle_message(pony_ctx_t* ctx, pony_actor_t* actor, ctx->mem_allocated_messages -= POOL_ALLOC_SIZE(pony_msgi_t); #endif + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: CD actor %lu handled message ACTORMSG_ACK...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); pony_assert(ponyint_is_cycle(actor)); DTRACE3(ACTOR_MSG_RUN, (uintptr_t)ctx->scheduler, (uintptr_t)actor, msg->id); actor->type->dispatch(ctx, actor, msg); @@ -290,6 +300,7 @@ static bool handle_message(pony_ctx_t* ctx, pony_actor_t* actor, ctx->mem_allocated_messages -= POOL_ALLOC_SIZE(pony_msgi_t); #endif + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu handled message ACTORMSG_CONF...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); pony_assert(!ponyint_is_cycle(actor)); if(has_internal_flag(actor, FLAG_BLOCKED_SENT)) { @@ -308,6 +319,8 @@ static bool handle_message(pony_ctx_t* ctx, pony_actor_t* actor, ctx->mem_allocated_messages -= POOL_ALLOC_SIZE(pony_msg_t); #endif + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu handled message ACTORMSG_ISBLOCKED...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); + // this actor should not already be marked as pendingdestroy // or else we could end up double freeing it // this assertion is to ensure this invariant is not @@ -337,6 +350,7 @@ static bool handle_message(pony_ctx_t* ctx, pony_actor_t* actor, { // memtrack messages tracked in cycle detector + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: CD actor %lu handled message ACTORMSG_BLOCK...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); pony_assert(ponyint_is_cycle(actor)); DTRACE3(ACTOR_MSG_RUN, (uintptr_t)ctx->scheduler, (uintptr_t)actor, msg->id); actor->type->dispatch(ctx, actor, msg); @@ -350,6 +364,7 @@ static bool handle_message(pony_ctx_t* ctx, pony_actor_t* actor, ctx->mem_allocated_messages -= POOL_ALLOC_SIZE(pony_msgp_t); #endif + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: CD actor %lu handled message ACTORMSG_UNBLOCK...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); pony_assert(ponyint_is_cycle(actor)); DTRACE3(ACTOR_MSG_RUN, (uintptr_t)ctx->scheduler, (uintptr_t)actor, msg->id); actor->type->dispatch(ctx, actor, msg); @@ -363,6 +378,7 @@ static bool handle_message(pony_ctx_t* ctx, pony_actor_t* actor, ctx->mem_allocated_messages -= POOL_ALLOC_SIZE(pony_msgp_t); #endif + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: CD actor %lu handled message ACTORMSG_DESTROYED...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); pony_assert(ponyint_is_cycle(actor)); DTRACE3(ACTOR_MSG_RUN, (uintptr_t)ctx->scheduler, (uintptr_t)actor, msg->id); actor->type->dispatch(ctx, actor, msg); @@ -376,6 +392,7 @@ static bool handle_message(pony_ctx_t* ctx, pony_actor_t* actor, ctx->mem_allocated_messages -= POOL_ALLOC_SIZE(pony_msg_t); #endif + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: CD actor %lu handled message ACTORMSG_CHECKBLOCKED...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); pony_assert(ponyint_is_cycle(actor)); DTRACE3(ACTOR_MSG_RUN, (uintptr_t)ctx->scheduler, (uintptr_t)actor, msg->id); actor->type->dispatch(ctx, actor, msg); @@ -389,6 +406,7 @@ static bool handle_message(pony_ctx_t* ctx, pony_actor_t* actor, ctx->mem_allocated_messages -= POOL_SIZE(msg->index); #endif + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu handled APP message...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); pony_assert(!ponyint_is_cycle(actor)); if(has_internal_flag(actor, FLAG_BLOCKED_SENT)) { @@ -408,6 +426,7 @@ static void try_gc(pony_ctx_t* ctx, pony_actor_t* actor) if(!ponyint_heap_startgc(&actor->heap)) return; + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: GC'ing actor %lu...\n", ctx->scheduler->tid, (uintptr_t)actor); DTRACE1(GC_START, (uintptr_t)ctx->scheduler); ponyint_gc_mark(ctx); @@ -418,6 +437,7 @@ static void try_gc(pony_ctx_t* ctx, pony_actor_t* actor) ponyint_mark_done(ctx); ponyint_heap_endgc(&actor->heap); + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: finished GC'ing actor %lu...\n", ctx->scheduler->tid, (uintptr_t)actor); DTRACE1(GC_END, (uintptr_t)ctx->scheduler); } @@ -462,6 +482,8 @@ static bool batch_limit_reached(pony_actor_t* actor, bool polling) actor_setoverloaded(actor); } + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu reached batch limit...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); + return true; } @@ -483,10 +505,12 @@ bool ponyint_actor_run(pony_ctx_t* ctx, pony_actor_t* actor, bool polling) #endif )) != NULL) { + SYSTEMATIC_TESTING_YIELD(); if(handle_message(ctx, actor, msg)) { // If we handle an application message, try to gc. app++; + SYSTEMATIC_TESTING_YIELD(); try_gc(ctx, actor); // maybe mute actor; returns true if mute occurs @@ -502,7 +526,10 @@ bool ponyint_actor_run(pony_ctx_t* ctx, pony_actor_t* actor, bool polling) // Stop handling a batch if we reach the head we found when we were // scheduled. if(msg == head) + { + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu handled all messages...\n", ctx->scheduler->tid, (uintptr_t)actor); break; + } } // We didn't hit our app message batch limit. We now believe our queue to be @@ -544,6 +571,7 @@ bool ponyint_actor_run(pony_ctx_t* ctx, pony_actor_t* actor, bool polling) set_internal_flag(actor, FLAG_BLOCKED_SENT); set_internal_flag(actor, FLAG_CD_CONTACTED); ponyint_cycle_block(actor, &actor->gc); + SYSTEMATIC_TESTING_YIELD(); } } @@ -560,6 +588,7 @@ bool ponyint_actor_run(pony_ctx_t* ctx, pony_actor_t* actor, bool polling) // check if the actors queue is empty or not if(ponyint_messageq_isempty(&actor->q)) { + SYSTEMATIC_TESTING_YIELD(); // The actors queue is empty which means this actor is a zombie // and can be reaped. // If the cycle detector is disabled (or it doesn't know about this actor), @@ -592,6 +621,8 @@ bool ponyint_actor_run(pony_ctx_t* ctx, pony_actor_t* actor, bool polling) // make sure the queue is actually empty as expected pony_assert(empty); + SYSTEMATIC_TESTING_YIELD(); + // "Locally delete" the actor. ponyint_actor_setpendingdestroy(actor); ponyint_actor_final(ctx, actor); @@ -613,6 +644,7 @@ bool ponyint_actor_run(pony_ctx_t* ctx, pony_actor_t* actor, bool polling) // and the cycle detector didn't send a message in the meantime if(!ponyint_messageq_isempty(&actor->q)) { + SYSTEMATIC_TESTING_YIELD(); // need to undo set pending destroy because the cycle detector // sent the actor a message and it is not safe to destroy this // actor as a result. @@ -656,9 +688,11 @@ bool ponyint_actor_run(pony_ctx_t* ctx, pony_actor_t* actor, bool polling) // messages (which would also create a race condition). set_internal_flag(actor, FLAG_BLOCKED_SENT); ponyint_cycle_block(actor, &actor->gc); + SYSTEMATIC_TESTING_YIELD(); // mark the queue as empty or else destroy will hang bool empty = ponyint_messageq_markempty(&actor->q); + SYSTEMATIC_TESTING_YIELD(); // make sure the queue is actually empty as expected pony_assert(empty); @@ -678,6 +712,7 @@ bool ponyint_actor_run(pony_ctx_t* ctx, pony_actor_t* actor, bool polling) void ponyint_actor_destroy(pony_actor_t* actor) { + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu destroyed...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); pony_assert(has_sync_flag(actor, SYNC_FLAG_PENDINGDESTROY)); // Make sure the actor being destroyed has finished marking its queue @@ -782,6 +817,8 @@ PONY_API pony_actor_t* pony_create(pony_ctx_t* ctx, pony_type_t* type, memset(actor, 0, type->size); actor->type = type; + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu created...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); + #ifdef USE_MEMTRACK ctx->mem_used_actors += type->size; ctx->mem_allocated_actors += ponyint_pool_used_size(type->size); @@ -879,12 +916,15 @@ PONY_API void pony_sendv(pony_ctx_t* ctx, pony_actor_t* to, pony_msg_t* first, if(has_app_msg) maybe_mark_should_mute(ctx, to); + SYSTEMATIC_TESTING_YIELD(); + if(ponyint_actor_messageq_push(&to->q, first, last #ifdef USE_DYNAMIC_TRACE , ctx->scheduler, ctx->current, to #endif )) { + SYSTEMATIC_TESTING_YIELD(); if(!has_sync_flag(to, SYNC_FLAG_MUTED)) { ponyint_sched_add(ctx, to); @@ -922,12 +962,15 @@ PONY_API void pony_sendv_single(pony_ctx_t* ctx, pony_actor_t* to, if(has_app_msg) maybe_mark_should_mute(ctx, to); + SYSTEMATIC_TESTING_YIELD(); + if(ponyint_actor_messageq_push_single(&to->q, first, last #ifdef USE_DYNAMIC_TRACE , ctx->scheduler, ctx->current, to #endif )) { + SYSTEMATIC_TESTING_YIELD(); if(!has_sync_flag(to, SYNC_FLAG_MUTED)) { // if the receiving actor is currently not unscheduled AND it's not @@ -1068,6 +1111,7 @@ PONY_API void pony_poll(pony_ctx_t* ctx) PONY_API void pony_apply_backpressure() { pony_ctx_t* ctx = pony_ctx(); + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu under pressure...\n", ctx->scheduler->tid, (uintptr_t)ctx->current); set_sync_flag(ctx->current, SYNC_FLAG_UNDER_PRESSURE); DTRACE1(ACTOR_UNDER_PRESSURE, (uintptr_t)ctx->current); } @@ -1075,6 +1119,7 @@ PONY_API void pony_apply_backpressure() PONY_API void pony_release_backpressure() { pony_ctx_t* ctx = pony_ctx(); + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: actor %lu not under pressure...\n", ctx->scheduler->tid, (uintptr_t)ctx->current); unset_sync_flag(ctx->current, SYNC_FLAG_UNDER_PRESSURE); DTRACE1(ACTOR_PRESSURE_RELEASED, (uintptr_t)ctx->current); if (!has_sync_flag(ctx->current, SYNC_FLAG_OVERLOADED)) diff --git a/src/libponyrt/actor/messageq.c b/src/libponyrt/actor/messageq.c index 6ed6b1e4a30..697debef059 100644 --- a/src/libponyrt/actor/messageq.c +++ b/src/libponyrt/actor/messageq.c @@ -2,6 +2,7 @@ #include "messageq.h" #include "../mem/pool.h" +#include "../sched/systematic_testing.h" #include "ponyassert.h" #include #include @@ -32,6 +33,8 @@ static bool messageq_push(messageq_t* q, pony_msg_t* first, pony_msg_t* last) { atomic_store_explicit(&last->next, NULL, memory_order_relaxed); + SYSTEMATIC_TESTING_YIELD(); + // Without that fence, the store to last->next above could be reordered after // the exchange on the head and after the store to prev->next done by the // next push, which would result in the pop incorrectly seeing the queue as @@ -39,6 +42,8 @@ static bool messageq_push(messageq_t* q, pony_msg_t* first, pony_msg_t* last) // Also synchronise with the pop on prev->next. atomic_thread_fence(memory_order_release); + SYSTEMATIC_TESTING_YIELD(); + pony_msg_t* prev = atomic_exchange_explicit(&q->head, last, memory_order_relaxed); @@ -51,8 +56,13 @@ static bool messageq_push(messageq_t* q, pony_msg_t* first, pony_msg_t* last) ANNOTATE_HAPPENS_BEFORE(&prev->next); atomic_thread_fence(memory_order_release); #endif + + SYSTEMATIC_TESTING_YIELD(); + atomic_store_explicit(&prev->next, first, memory_order_relaxed); + SYSTEMATIC_TESTING_YIELD(); + return was_empty; } @@ -61,8 +71,13 @@ static bool messageq_push_single(messageq_t* q, { atomic_store_explicit(&last->next, NULL, memory_order_relaxed); + SYSTEMATIC_TESTING_YIELD(); + // If we have a single producer, the swap of the head need not be atomic RMW. pony_msg_t* prev = atomic_load_explicit(&q->head, memory_order_relaxed); + + SYSTEMATIC_TESTING_YIELD(); + atomic_store_explicit(&q->head, last, memory_order_relaxed); bool was_empty = ((uintptr_t)prev & 1) != 0; @@ -73,8 +88,13 @@ static bool messageq_push_single(messageq_t* q, #ifdef USE_VALGRIND ANNOTATE_HAPPENS_BEFORE(&prev->next); #endif + + SYSTEMATIC_TESTING_YIELD(); + atomic_store_explicit(&prev->next, first, memory_order_release); + SYSTEMATIC_TESTING_YIELD(); + return was_empty; } @@ -240,13 +260,24 @@ pony_msg_t* ponyint_actor_messageq_pop(messageq_t* q ) { pony_msg_t* tail = q->tail; + + SYSTEMATIC_TESTING_YIELD(); + pony_msg_t* next = atomic_load_explicit(&tail->next, memory_order_acquire); + SYSTEMATIC_TESTING_YIELD(); + if(next != NULL) { DTRACE3(ACTOR_MSG_POP, sched->index, (uint32_t) next->id, (uintptr_t) actor); q->tail = next; + + SYSTEMATIC_TESTING_YIELD(); + atomic_thread_fence(memory_order_acquire); + + SYSTEMATIC_TESTING_YIELD(); + #ifdef USE_VALGRIND ANNOTATE_HAPPENS_AFTER(&tail->next); ANNOTATE_HAPPENS_BEFORE_FORGET_ALL(tail); @@ -264,12 +295,20 @@ pony_msg_t* ponyint_thread_messageq_pop(messageq_t* q ) { pony_msg_t* tail = q->tail; + + SYSTEMATIC_TESTING_YIELD(); + pony_msg_t* next = atomic_load_explicit(&tail->next, memory_order_relaxed); + SYSTEMATIC_TESTING_YIELD(); + if(next != NULL) { DTRACE2(THREAD_MSG_POP, (uint32_t) next->id, (uintptr_t) thr); q->tail = next; + + SYSTEMATIC_TESTING_YIELD(); + atomic_thread_fence(memory_order_acquire); #ifdef USE_VALGRIND ANNOTATE_HAPPENS_AFTER(&tail->next); @@ -284,6 +323,9 @@ pony_msg_t* ponyint_thread_messageq_pop(messageq_t* q bool ponyint_messageq_markempty(messageq_t* q) { pony_msg_t* tail = q->tail; + + SYSTEMATIC_TESTING_YIELD(); + pony_msg_t* head = atomic_load_explicit(&q->head, memory_order_acquire); if(((uintptr_t)head & 1) != 0) @@ -297,6 +339,9 @@ bool ponyint_messageq_markempty(messageq_t* q) #ifdef USE_VALGRIND ANNOTATE_HAPPENS_BEFORE(&q->head); #endif + + SYSTEMATIC_TESTING_YIELD(); + return atomic_compare_exchange_strong_explicit(&q->head, &tail, head, memory_order_acq_rel, memory_order_acquire); } diff --git a/src/libponyrt/options/options.h b/src/libponyrt/options/options.h index e28097c72ed..26d2ac9daf8 100644 --- a/src/libponyrt/options/options.h +++ b/src/libponyrt/options/options.h @@ -45,6 +45,11 @@ " be set to have any effect.\n" \ " --ponyversion Print the version of the compiler and exit.\n" \ " --ponyhelp Print the runtime usage options and exit.\n" \ + " --ponysystematictestingseed\n" \ + " Use a specific seed value for systematic testing.\n" \ + " --ponysystematictestingverbosity\n" \ + " Control verbosity of systematic testing output.\n" \ + " 0 is least verbose; greater is more details.\n" \ "\n" \ "NOTE: These can be programmatically overridden. See the docstring in the\n" \ " `RuntimeOptions` struct in the `builtin` package.\n" diff --git a/src/libponyrt/sched/mpmcq.c b/src/libponyrt/sched/mpmcq.c index 890b71e3bb6..605b11b39db 100644 --- a/src/libponyrt/sched/mpmcq.c +++ b/src/libponyrt/sched/mpmcq.c @@ -1,6 +1,7 @@ #define PONY_WANT_ATOMIC_DEFS #include "mpmcq.h" +#include "systematic_testing.h" #include "../mem/pool.h" #include "../sched/cpu.h" @@ -77,6 +78,8 @@ void ponyint_mpmcq_push(mpmcq_t* q, void* data) { mpmcq_node_t* node = node_alloc(data); + SYSTEMATIC_TESTING_YIELD(); + // Without that fence, the store to node->next in node_alloc could be // reordered after the exchange on the head and after the store to prev->next // done by the next push, which would result in the pop incorrectly seeing @@ -84,6 +87,8 @@ void ponyint_mpmcq_push(mpmcq_t* q, void* data) // Also synchronise with the pop on prev->next. atomic_thread_fence(memory_order_release); + SYSTEMATIC_TESTING_YIELD(); + mpmcq_node_t* prev = atomic_exchange_explicit(&q->head, node, memory_order_relaxed); @@ -93,15 +98,25 @@ void ponyint_mpmcq_push(mpmcq_t* q, void* data) ANNOTATE_HAPPENS_BEFORE(&prev->next); atomic_thread_fence(memory_order_release); #endif + + SYSTEMATIC_TESTING_YIELD(); + atomic_store_explicit(&prev->next, node, memory_order_relaxed); + + SYSTEMATIC_TESTING_YIELD(); } void ponyint_mpmcq_push_single(mpmcq_t* q, void* data) { mpmcq_node_t* node = node_alloc(data); + SYSTEMATIC_TESTING_YIELD(); + // If we have a single producer, the swap of the head need not be atomic RMW. mpmcq_node_t* prev = atomic_load_explicit(&q->head, memory_order_relaxed); + + SYSTEMATIC_TESTING_YIELD(); + atomic_store_explicit(&q->head, node, memory_order_relaxed); // If we have a single producer, the fence can be replaced with a store @@ -109,7 +124,12 @@ void ponyint_mpmcq_push_single(mpmcq_t* q, void* data) #ifdef USE_VALGRIND ANNOTATE_HAPPENS_BEFORE(&prev->next); #endif + + SYSTEMATIC_TESTING_YIELD(); + atomic_store_explicit(&prev->next, node, memory_order_release); + + SYSTEMATIC_TESTING_YIELD(); } void* ponyint_mpmcq_pop(mpmcq_t* q) @@ -128,10 +148,15 @@ void* ponyint_mpmcq_pop(mpmcq_t* q) do { tail = cmp.object; + + SYSTEMATIC_TESTING_YIELD(); + // Get the next node rather than the tail. The tail is either a stub or has // already been consumed. next = atomic_load_explicit(&tail->next, memory_order_relaxed); + SYSTEMATIC_TESTING_YIELD(); + if(next == NULL) return NULL; @@ -152,11 +177,16 @@ void* ponyint_mpmcq_pop(mpmcq_t* q) ANNOTATE_HAPPENS_BEFORE(&next->data); atomic_thread_fence(memory_order_release); #else + SYSTEMATIC_TESTING_YIELD(); atomic_thread_fence(memory_order_acq_rel); #endif + SYSTEMATIC_TESTING_YIELD(); + void* data = atomic_load_explicit(&next->data, memory_order_acquire); + SYSTEMATIC_TESTING_YIELD(); + // Since we will be freeing the old tail, we need to be sure no other // consumer is still reading the old tail. To do this, we set the data // pointer of our new tail to NULL, and we wait until the data pointer of @@ -166,8 +196,16 @@ void* ponyint_mpmcq_pop(mpmcq_t* q) // freeing it. atomic_store_explicit(&next->data, NULL, memory_order_release); + SYSTEMATIC_TESTING_YIELD(); + while(atomic_load_explicit(&tail->data, memory_order_acquire) != NULL) +#if defined(USE_SYSTEMATIC_TESTING) + SYSTEMATIC_TESTING_YIELD(); +#else ponyint_cpu_relax(); +#endif + + SYSTEMATIC_TESTING_YIELD(); // Synchronise on tail->data to make sure we see every previous write to the // old tail before freeing it. This is a standalone fence to avoid @@ -177,6 +215,8 @@ void* ponyint_mpmcq_pop(mpmcq_t* q) ANNOTATE_HAPPENS_AFTER(&tail->data); #endif + SYSTEMATIC_TESTING_YIELD(); + node_free(tail); return data; diff --git a/src/libponyrt/sched/scheduler.c b/src/libponyrt/sched/scheduler.c index 8d04019dab8..60317de0c0e 100644 --- a/src/libponyrt/sched/scheduler.c +++ b/src/libponyrt/sched/scheduler.c @@ -319,18 +319,21 @@ static bool read_msg(scheduler_t* sched) { case SCHED_SUSPEND: { + SYSTEMATIC_TESTING_PRINTF(5, "thread %lu: handled SCHED_SUSPEND...\n", sched->tid); maybe_start_cnf_ack_cycle(sched); break; } case SCHED_BLOCK: { + SYSTEMATIC_TESTING_PRINTF(5, "thread %lu: handled SCHED_BLOCK...\n", sched->tid); handle_sched_block(sched); break; } case SCHED_UNBLOCK: { + SYSTEMATIC_TESTING_PRINTF(5, "thread %lu: handled SCHED_UNBLOCK...\n", sched->tid); handle_sched_unblock(sched); break; } @@ -338,12 +341,14 @@ static bool read_msg(scheduler_t* sched) case SCHED_CNF: { // Echo the token back as ACK(token). + SYSTEMATIC_TESTING_PRINTF(5, "thread %lu: handled SCHED_CNF...\n", sched->tid); send_msg(sched->index, 0, SCHED_ACK, m->i); break; } case SCHED_ACK: { + SYSTEMATIC_TESTING_PRINTF(5, "thread %lu: handled SCHED_ACK...\n", sched->tid); // If it's the current token, increment the ack count. if(m->i == sched->ack_token) sched->ack_count++; @@ -352,12 +357,14 @@ static bool read_msg(scheduler_t* sched) case SCHED_TERMINATE: { + SYSTEMATIC_TESTING_PRINTF(5, "thread %lu: handled SCHED_TERMINATE...\n", sched->tid); sched->terminate = true; break; } case SCHED_UNMUTE_ACTOR: { + SYSTEMATIC_TESTING_PRINTF(5, "thread %lu: handled SCHED_UNMUTE_ACTOR...\n", sched->tid); if (ponyint_sched_unmute_senders(&sched->ctx, (pony_actor_t*)m->i)) run_queue_changed = true; @@ -366,6 +373,7 @@ static bool read_msg(scheduler_t* sched) case SCHED_NOISY_ASIO: { + SYSTEMATIC_TESTING_PRINTF(5, "thread %lu: handled SCHED_NOISY_ASIO...\n", sched->tid); // mark asio as being noisy sched->asio_noisy = true; break; @@ -373,6 +381,7 @@ static bool read_msg(scheduler_t* sched) case SCHED_UNNOISY_ASIO: { + SYSTEMATIC_TESTING_PRINTF(5, "thread %lu: handled SCHED_UNNOISY_ASIO...\n", sched->tid); // mark asio as not being noisy sched->asio_noisy = false; break; @@ -571,6 +580,7 @@ static pony_actor_t* suspend_scheduler(scheduler_t* sched, // popping succeeded (actor != NULL) as some other scheduler might have // stolen the newly scheduled actor from us already. Schedulers, what a // bunch of thieving bastards! + SYSTEMATIC_TESTING_YIELD(); actor = pop_global(sched); if(actor != NULL) break; @@ -756,6 +766,7 @@ static pony_actor_t* steal(scheduler_t* sched) // popping succeeded (actor != NULL) as some other scheduler might have // stolen the newly scheduled actor from us already. Schedulers, what a // bunch of thieving bastards! + SYSTEMATIC_TESTING_YIELD(); actor = pop_global(sched); if(actor != NULL) break; @@ -870,6 +881,8 @@ static pony_actor_t* steal(scheduler_t* sched) { last_cd_tsc = current_tsc; + SYSTEMATIC_TESTING_YIELD(); + // cycle detector should now be on the queue actor = pop_global(sched); if(actor != NULL) @@ -925,9 +938,14 @@ static void run(scheduler_t* sched) { last_cd_tsc = current_tsc; + SYSTEMATIC_TESTING_PRINTF(5, "thread %lu: Cycle Detector scheduled...\n", sched->tid); + // cycle detector should now be on the queue if(actor == NULL) + { + SYSTEMATIC_TESTING_YIELD(); actor = pop_global(sched); + } } } } @@ -950,13 +968,16 @@ static void run(scheduler_t* sched) // to pop from our queue to check for a recently unmuted actor if(read_msg(sched) && actor == NULL) { + SYSTEMATIC_TESTING_YIELD(); actor = pop_global(sched); } if(actor == NULL) { // We had an empty queue and no rescheduled actor. + SYSTEMATIC_TESTING_PRINTF(5, "thread %lu: empty queue... trying to steal...\n", sched->tid); actor = steal(sched); + SYSTEMATIC_TESTING_YIELD(); if(actor == NULL) { @@ -981,12 +1002,14 @@ static void run(scheduler_t* sched) ponyint_sched_maybe_wakeup(sched->index); // Run the current actor and get the next actor. + SYSTEMATIC_TESTING_PRINTF(5, "thread %lu: running actor %lu...\n", sched->tid, (uintptr_t)actor); bool reschedule = ponyint_actor_run(&sched->ctx, actor, false); SYSTEMATIC_TESTING_YIELD(); pony_actor_t* next = pop_global(sched); if(reschedule) { + SYSTEMATIC_TESTING_PRINTF(5, "thread %lu: rescheduling actor %lu...\n", sched->tid, (uintptr_t)actor); if(next != NULL) { // If we have a next actor, we go on the back of the queue. Otherwise, @@ -1093,7 +1116,7 @@ static void ponyint_sched_shutdown() pony_ctx_t* ponyint_sched_init(uint32_t threads, bool noyield, bool pin, bool pinasio, uint32_t min_threads, uint32_t thread_suspend_threshold #if defined(USE_SYSTEMATIC_TESTING) - , uint64_t systematic_testing_seed) + , uint64_t systematic_testing_seed, uint32_t systematic_testing_verbosity) #else ) #endif @@ -1177,7 +1200,7 @@ pony_ctx_t* ponyint_sched_init(uint32_t threads, bool noyield, bool pin, } // initialize systematic testing - SYSTEMATIC_TESTING_INIT(systematic_testing_seed, scheduler_count); + SYSTEMATIC_TESTING_INIT(systematic_testing_seed, scheduler_count, systematic_testing_verbosity); ponyint_mpmcq_init(&inject); ponyint_asio_init(asio_cpu); @@ -1411,6 +1434,7 @@ void ponyint_sched_maybe_wakeup(int32_t current_scheduler_id) void ponyint_sched_mute(pony_ctx_t* ctx, pony_actor_t* sender, pony_actor_t* recv) { + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: sender %lu added to mutemap of receiver %lu...\n", ctx->scheduler->tid, (uintptr_t)sender, (uintptr_t)recv); pony_assert(sender != recv); scheduler_t* sched = ctx->scheduler; size_t index = HASHMAP_UNKNOWN; @@ -1469,6 +1493,7 @@ void ponyint_sched_mute(pony_ctx_t* ctx, pony_actor_t* sender, pony_actor_t* rec void ponyint_sched_start_global_unmute(uint32_t from, pony_actor_t* actor) { + SYSTEMATIC_TESTING_PRINTF(8, "thread %lu: globally unmuting actor %lu...\n", pony_ctx()->scheduler->tid, (uintptr_t)actor); send_msg_all_active(from, SCHED_UNMUTE_ACTOR, (intptr_t)actor); } diff --git a/src/libponyrt/sched/scheduler.h b/src/libponyrt/sched/scheduler.h index 0d9a95913ce..efa42b0c11d 100644 --- a/src/libponyrt/sched/scheduler.h +++ b/src/libponyrt/sched/scheduler.h @@ -96,7 +96,7 @@ struct scheduler_t pony_ctx_t* ponyint_sched_init(uint32_t threads, bool noyield, bool nopin, bool pinasio, uint32_t min_threads, uint32_t thread_suspend_threshold #if defined(USE_SYSTEMATIC_TESTING) - , uint64_t systematic_testing_seed); + , uint64_t systematic_testing_seed, uint32_t systematic_testing_verbosity); #else ); #endif diff --git a/src/libponyrt/sched/start.c b/src/libponyrt/sched/start.c index 548cf3559ed..18c12fffa94 100644 --- a/src/libponyrt/sched/start.c +++ b/src/libponyrt/sched/start.c @@ -34,10 +34,11 @@ typedef struct options_t bool pin; bool pinasio; bool version; + bool ponyhelp; #if defined(USE_SYSTEMATIC_TESTING) uint64_t systematic_testing_seed; + uint32_t systematic_testing_verbosity; #endif - bool ponyhelp; } options_t; typedef enum running_kind_t @@ -70,6 +71,7 @@ enum OPT_VERSION, #if defined(USE_SYSTEMATIC_TESTING) OPT_SYSTEMATIC_TESTING_SEED, + OPT_SYSTEMATIC_TESTING_VERBOSITY, #endif OPT_PONYHELP }; @@ -90,6 +92,7 @@ static opt_arg_t args[] = {"ponyversion", 0, OPT_ARG_NONE, OPT_VERSION}, #if defined(USE_SYSTEMATIC_TESTING) {"ponysystematictestingseed", 0, OPT_ARG_REQUIRED, OPT_SYSTEMATIC_TESTING_SEED}, + {"ponysystematictestingverbosity", 0, OPT_ARG_REQUIRED, OPT_SYSTEMATIC_TESTING_VERBOSITY}, #endif {"ponyhelp", 0, OPT_ARG_NONE, OPT_PONYHELP}, @@ -181,6 +184,7 @@ static int parse_opts(int argc, char** argv, options_t* opt) case OPT_VERSION: opt->version = true; break; #if defined(USE_SYSTEMATIC_TESTING) case OPT_SYSTEMATIC_TESTING_SEED: if(parse_uint64(&opt->systematic_testing_seed, 1, s.arg_val)) err_out(id, "can't be less than 1"); break; + case OPT_SYSTEMATIC_TESTING_VERBOSITY: if(parse_uint(&opt->systematic_testing_verbosity, 0, s.arg_val)) err_out(id, "can't be less than 0"); break; #endif case OPT_PONYHELP: opt->ponyhelp = true; break; @@ -285,7 +289,7 @@ PONY_API int pony_init(int argc, char** argv) pony_ctx_t* ctx = ponyint_sched_init(opt.threads, opt.noyield, opt.pin, opt.pinasio, opt.min_threads, opt.thread_suspend_threshold #if defined(USE_SYSTEMATIC_TESTING) - , opt.systematic_testing_seed); + , opt.systematic_testing_seed, opt.systematic_testing_verbosity); #else ); #endif diff --git a/src/libponyrt/sched/systematic_testing.c b/src/libponyrt/sched/systematic_testing.c index 95b71662077..e395513748f 100644 --- a/src/libponyrt/sched/systematic_testing.c +++ b/src/libponyrt/sched/systematic_testing.c @@ -19,6 +19,7 @@ static systematic_testing_thread_t* threads_to_track = NULL; static uint32_t total_threads = 0; static uint32_t stopped_threads = 0; static PONY_ATOMIC(uint32_t) waiting_to_start_count; +static uint32_t verbose_level = 0; #if defined(USE_SCHEDULER_SCALING_PTHREADS) static pthread_mutex_t systematic_testing_mut; @@ -51,9 +52,12 @@ size_t ponyint_systematic_testing_static_alloc_size() } #endif -void ponyint_systematic_testing_init(uint64_t random_seed, uint32_t max_threads) +void ponyint_systematic_testing_init(uint64_t random_seed, uint32_t max_threads, + uint32_t verbosity) { - #if defined(USE_SCHEDULER_SCALING_PTHREADS) + verbose_level = verbosity; + +#if defined(USE_SCHEDULER_SCALING_PTHREADS) pthread_once(&systematic_testing_mut_once, systematic_testing_mut_init); #endif @@ -62,8 +66,8 @@ void ponyint_systematic_testing_init(uint64_t random_seed, uint32_t max_threads) if(0 == random_seed) random_seed = ponyint_cpu_tick(); - SYSTEMATIC_TESTING_PRINTF("Systematic testing using seed: %lu...\n", random_seed); - SYSTEMATIC_TESTING_PRINTF("(rerun with ` --ponysystematictestingseed %lu` to reproduce)\n", random_seed); + SYSTEMATIC_TESTING_PRINTF(0, "Systematic testing using seed: %lu...\n", random_seed); + SYSTEMATIC_TESTING_PRINTF(0, "(rerun with ` --ponysystematictestingseed %lu` to reproduce)\n", random_seed); // TODO systematic testing: maybe replace with better RNG? // probably best to replace this with a RNG that has the exact same behavior @@ -88,7 +92,7 @@ void ponyint_systematic_testing_init(uint64_t random_seed, uint32_t max_threads) void ponyint_systematic_testing_wait_start(pony_thread_id_t thread, pony_signal_event_t signal) { - SYSTEMATIC_TESTING_PRINTF("thread %lu: waiting to start...\n", thread); + SYSTEMATIC_TESTING_PRINTF(10, "thread %lu: waiting to start...\n", thread); atomic_fetch_add_explicit(&waiting_to_start_count, 1, memory_order_relaxed); @@ -99,7 +103,7 @@ void ponyint_systematic_testing_wait_start(pony_thread_id_t thread, pony_signal_ while(0 == pthread_equal(active_thread->tid, thread)) #endif { - SYSTEMATIC_TESTING_PRINTF("thread %lu: still waiting for it's turn... active thread: %lu\n", thread, active_thread->tid); + SYSTEMATIC_TESTING_PRINTF(10, "thread %lu: still waiting for it's turn... active thread: %lu\n", thread, active_thread->tid); #if defined(USE_SCHEDULER_SCALING_PTHREADS) ponyint_thread_suspend(signal, &systematic_testing_mut); #else @@ -107,7 +111,7 @@ void ponyint_systematic_testing_wait_start(pony_thread_id_t thread, pony_signal_ #endif } - SYSTEMATIC_TESTING_PRINTF("thread %lu: started...\n", thread); + SYSTEMATIC_TESTING_PRINTF(10, "thread %lu: started...\n", thread); } void ponyint_systematic_testing_start(scheduler_t* schedulers, pony_thread_id_t asio_thread, pony_signal_event_t asio_signal) @@ -128,11 +132,11 @@ void ponyint_systematic_testing_start(scheduler_t* schedulers, pony_thread_id_t while(total_threads != atomic_load_explicit(&waiting_to_start_count, memory_order_relaxed)) { - SYSTEMATIC_TESTING_PRINTF("Waiting for all threads to be ready before starting execution..\n"); + SYSTEMATIC_TESTING_PRINTF(1, "Waiting for all threads to be ready before starting execution..\n"); ponyint_cpu_core_pause(1, 10000002, true); } - SYSTEMATIC_TESTING_PRINTF("Starting systematic testing with thread %lu...\n", active_thread->tid); + SYSTEMATIC_TESTING_PRINTF(10, "Starting systematic testing with thread %lu...\n", active_thread->tid); ponyint_thread_wake(active_thread->tid, active_thread->sleep_object); } @@ -173,7 +177,7 @@ void ponyint_systematic_testing_yield() pthread_mutex_unlock(&systematic_testing_mut); #endif - SYSTEMATIC_TESTING_PRINTF("Systematic testing successfully finished!\n"); + SYSTEMATIC_TESTING_PRINTF(1, "Systematic testing successfully finished!\n"); return; } @@ -191,7 +195,7 @@ void ponyint_systematic_testing_yield() { active_thread = next_thread; - SYSTEMATIC_TESTING_PRINTF("thread %lu: yielding to thread: %lu.. next_index: %u\n", current_thread->tid, active_thread->tid, next_index); + SYSTEMATIC_TESTING_PRINTF(10, "thread %lu: yielding to thread: %lu.. next_index: %u\n", current_thread->tid, active_thread->tid, next_index); ponyint_thread_wake(active_thread->tid, active_thread->sleep_object); @@ -241,7 +245,12 @@ void ponyint_systematic_testing_stop_thread() { active_thread->stopped = true; stopped_threads++; - SYSTEMATIC_TESTING_PRINTF("thread %lu: stopped...\n", active_thread->tid); + SYSTEMATIC_TESTING_PRINTF(10, "thread %lu: stopped...\n", active_thread->tid); ponyint_systematic_testing_yield(); } + +uint32_t ponyint_systematic_testing_verbose_level() +{ + return verbose_level; +} diff --git a/src/libponyrt/sched/systematic_testing.h b/src/libponyrt/sched/systematic_testing.h index 2e1f7967c9e..d5ff810f1ad 100644 --- a/src/libponyrt/sched/systematic_testing.h +++ b/src/libponyrt/sched/systematic_testing.h @@ -23,7 +23,7 @@ size_t ponyint_systematic_testing_static_mem_size(); size_t ponyint_systematic_testing_static_alloc_size(); #endif -void ponyint_systematic_testing_init(uint64_t random_seed, uint32_t max_threads); +void ponyint_systematic_testing_init(uint64_t random_seed, uint32_t max_threads, uint32_t verbosity); void ponyint_systematic_testing_start(scheduler_t* schedulers, pony_thread_id_t asio_thread, pony_signal_event_t asio_signal); void ponyint_systematic_testing_wait_start(pony_thread_id_t thread, pony_signal_event_t signal); void ponyint_systematic_testing_yield(); @@ -34,10 +34,10 @@ void ponyint_systematic_testing_suspend(pthread_mutex_t* mut); #else void ponyint_systematic_testing_suspend(); #endif +uint32_t ponyint_systematic_testing_verbose_level(); -// TODO systematic testing: maybe make output conditional based on a `verbosity` argument that is CLI driven? -#define SYSTEMATIC_TESTING_PRINTF(f_, ...) fprintf(stderr, (f_), ##__VA_ARGS__) -#define SYSTEMATIC_TESTING_INIT(RANDOM_SEED, MAX_THREADS) ponyint_systematic_testing_init(RANDOM_SEED, MAX_THREADS) +#define SYSTEMATIC_TESTING_PRINTF(level, f_, ...) if((uint32_t)level <= ponyint_systematic_testing_verbose_level()) fprintf(stderr, (f_), ##__VA_ARGS__) +#define SYSTEMATIC_TESTING_INIT(RANDOM_SEED, MAX_THREADS, VERBOSITY) ponyint_systematic_testing_init(RANDOM_SEED, MAX_THREADS, VERBOSITY) #define SYSTEMATIC_TESTING_START(SCHEDULERS, ASIO_THREAD, ASIO_SLEEP_OBJECT) ponyint_systematic_testing_start(SCHEDULERS, ASIO_THREAD, ASIO_SLEEP_OBJECT) #define SYSTEMATIC_TESTING_WAIT_START(THREAD, SIGNAL) ponyint_systematic_testing_wait_start(THREAD, SIGNAL) #define SYSTEMATIC_TESTING_YIELD() ponyint_systematic_testing_yield() @@ -53,8 +53,8 @@ PONY_EXTERN_C_END #else -#define SYSTEMATIC_TESTING_PRINTF(f_, ...) -#define SYSTEMATIC_TESTING_INIT(RANDOM_SEED, MAX_THREADS) +#define SYSTEMATIC_TESTING_PRINTF(level, f_, ...) +#define SYSTEMATIC_TESTING_INIT(RANDOM_SEED, MAX_THREADS, VERBOSITY) #define SYSTEMATIC_TESTING_START(SCHEDULERS, ASIO_THREAD, ASIO_SLEEP_OBJECT) #define SYSTEMATIC_TESTING_WAIT_START(THREAD, SIGNAL) #define SYSTEMATIC_TESTING_YIELD()