From 18438ade0ea0213b9990e78db27915c9cfee58f3 Mon Sep 17 00:00:00 2001 From: Martin Quinson Date: Mon, 31 Oct 2022 22:41:10 +0100 Subject: [PATCH] Be more verbose on the blocking transition when displaying the actor state on Ctrl-C --- examples/c/actor-exiting/actor-exiting.tesh | 2 +- .../cpp/actor-exiting/s4u-actor-exiting.tesh | 2 +- src/kernel/EngineImpl.cpp | 12 +++- src/kernel/actor/CommObserver.cpp | 69 +++++++++++++++++++ src/kernel/actor/CommObserver.hpp | 6 ++ src/kernel/actor/SimcallObserver.cpp | 12 ++++ src/kernel/actor/SimcallObserver.hpp | 8 ++- src/kernel/actor/SynchroObserver.cpp | 21 ++++++ src/kernel/actor/SynchroObserver.hpp | 4 ++ src/mc/mc_record.cpp | 3 + 10 files changed, 133 insertions(+), 6 deletions(-) diff --git a/examples/c/actor-exiting/actor-exiting.tesh b/examples/c/actor-exiting/actor-exiting.tesh index 2fb10eec44..4bc56ef830 100644 --- a/examples/c/actor-exiting/actor-exiting.tesh +++ b/examples/c/actor-exiting/actor-exiting.tesh @@ -8,6 +8,6 @@ $ ${bindir:=.}/c-actor-exiting ${platfdir}/small_platform.xml "--log=root.fmt:[% > [ 3.000000] (maestro@) Oops! Deadlock detected, some activities are still around but will never complete. This usually happens when the user code is not perfectly clean. > [ 3.000000] (maestro@) 1 actors are still running, waiting for something. > [ 3.000000] (maestro@) Legend of the following listing: "Actor (@): " -> [ 3.000000] (maestro@) Actor 3 (C@Ginette): waiting for communication activity 0xdeadbeef () in state WAITING to finish +> [ 3.000000] (maestro@) Actor 3 (C@Ginette): waiting for communication activity 0xdeadbeef () in state WAITING to finish > [ 3.000000] (C@Ginette) I was killed! > [ 3.000000] (C@Ginette) The backtrace would be displayed here if --log=no_loc would not have been passed diff --git a/examples/cpp/actor-exiting/s4u-actor-exiting.tesh b/examples/cpp/actor-exiting/s4u-actor-exiting.tesh index cb819512b1..660b0839f5 100644 --- a/examples/cpp/actor-exiting/s4u-actor-exiting.tesh +++ b/examples/cpp/actor-exiting/s4u-actor-exiting.tesh @@ -12,7 +12,7 @@ $ ${bindir:=.}/s4u-actor-exiting ${platfdir}/small_platform.xml "--log=root.fmt: > [ 3.000000] (maestro@) Oops! Deadlock detected, some activities are still around but will never complete. This usually happens when the user code is not perfectly clean. > [ 3.000000] (maestro@) 1 actors are still running, waiting for something. > [ 3.000000] (maestro@) Legend of the following listing: "Actor (@): " -> [ 3.000000] (maestro@) Actor 3 (C@Ginette): waiting for communication activity 0xdeadbeef () in state WAITING to finish +> [ 3.000000] (maestro@) Actor 3 (C@Ginette): waiting for communication activity 0xdeadbeef () in state WAITING to finish > [ 3.000000] (C@Ginette) I was killed! > [ 3.000000] (C@Ginette) The backtrace would be displayed here if --log=no_loc would not have been passed > [ 3.000000] (maestro@) Actor C terminates now diff --git a/src/kernel/EngineImpl.cpp b/src/kernel/EngineImpl.cpp index 717e7710d3..99304a9393 100644 --- a/src/kernel/EngineImpl.cpp +++ b/src/kernel/EngineImpl.cpp @@ -26,6 +26,8 @@ #include #endif /* _WIN32 */ +extern int xbt_log_no_loc; + #if SIMGRID_HAVE_MC #include "src/mc/remote/AppSide.hpp" #endif @@ -488,13 +490,17 @@ void EngineImpl::display_all_actor_status() const if (boost::dynamic_pointer_cast(actor->waiting_synchro_) != nullptr) synchro_description = "I/O"; - XBT_INFO("Actor %ld (%s@%s): waiting for %s activity %#zx (%s) in state %s to finish", actor->get_pid(), + XBT_INFO("Actor %ld (%s@%s): waiting for %s activity %#zx (%s) in state %s to finish %s", actor->get_pid(), actor->get_cname(), actor->get_host()->get_cname(), synchro_description, (xbt_log_no_loc ? (size_t)0xDEADBEEF : (size_t)actor->waiting_synchro_.get()), - actor->waiting_synchro_->get_cname(), actor->waiting_synchro_->get_state_str()); + actor->waiting_synchro_->get_cname(), actor->waiting_synchro_->get_state_str(), + (actor->simcall_.observer_ != nullptr && not xbt_log_no_loc + ? actor->simcall_.observer_->to_string().c_str() + : "")); } else { XBT_INFO("Actor %ld (%s@%s) simcall %s", actor->get_pid(), actor->get_cname(), actor->get_host()->get_cname(), - actor->simcall_.get_cname()); + (actor->simcall_.observer_ != nullptr ? actor->simcall_.observer_->to_string().c_str() + : actor->simcall_.get_cname())); } } } diff --git a/src/kernel/actor/CommObserver.cpp b/src/kernel/actor/CommObserver.cpp index 8f86d94cb9..98e0af8381 100644 --- a/src/kernel/actor/CommObserver.cpp +++ b/src/kernel/actor/CommObserver.cpp @@ -51,6 +51,25 @@ static void serialize_activity_test(const activity::ActivityImpl* act, std::stri stream << (short)mc::Transition::Type::UNKNOWN; } } +template static std::string ptr_to_id(A* ptr) +{ + static std::unordered_map map; + if (map.find(ptr) == map.end()) + map.insert(std::make_pair(ptr, std::to_string(map.size() + 1))); + return map[ptr]; +} +static std::string to_string_activity_test(const activity::ActivityImpl* act) +{ + if (auto* comm = dynamic_cast(act)) { + return std::string("CommTest(comm_id:") + ptr_to_id(comm) + + " src:" + std::to_string(comm->src_actor_ != nullptr ? comm->src_actor_->get_pid() : -1) + + " dst:" + std::to_string(comm->dst_actor_ != nullptr ? comm->dst_actor_->get_pid() : -1) + + " mbox:" + std::to_string(comm->get_mailbox_id()) + " srcbuf:" + ptr_to_id(comm->src_buff_) + + " dstbuf:" + ptr_to_id(comm->dst_buff_) + " bufsize:" + std::to_string(comm->src_buff_size_); + } else { + return "TestUnknownType()"; + } +} void ActivityTestanySimcall::serialize(std::stringstream& stream) const { stream << (short)mc::Transition::Type::TESTANY << ' ' << activities_.size() << ' '; @@ -59,10 +78,23 @@ void ActivityTestanySimcall::serialize(std::stringstream& stream) const stream << ' '; } } +std::string ActivityTestanySimcall::to_string() const +{ + std::stringstream buffer("TestAny("); + for (auto const& act : activities_) { + buffer << to_string_activity_test(act); + } + return buffer.str(); +} + void ActivityTestSimcall::serialize(std::stringstream& stream) const { serialize_activity_test(activity_, stream); } +std::string ActivityTestSimcall::to_string() const +{ + return to_string_activity_test(activity_); +} static void serialize_activity_wait(const activity::ActivityImpl* act, bool timeout, std::stringstream& stream) { if (auto* comm = dynamic_cast(act)) { @@ -77,6 +109,19 @@ static void serialize_activity_wait(const activity::ActivityImpl* act, bool time stream << (short)mc::Transition::Type::UNKNOWN; } } +static std::string to_string_activity_wait(const activity::ActivityImpl* act) +{ + if (auto* comm = dynamic_cast(act)) { + return std::string("CommWait(comm_id:") + ptr_to_id(comm) + + " src:" + std::to_string(comm->src_actor_ != nullptr ? comm->src_actor_->get_pid() : -1) + + " dst:" + std::to_string(comm->dst_actor_ != nullptr ? comm->dst_actor_->get_pid() : -1) + + " mbox:" + std::to_string(comm->get_mailbox_id()) + " srcbuf:" + ptr_to_id(comm->src_buff_) + + " dstbuf:" + ptr_to_id(comm->dst_buff_) + " bufsize:" + std::to_string(comm->src_buff_size_) + + ")"; + } else { + return "WaitUnknownType()"; + } +} void ActivityWaitSimcall::serialize(std::stringstream& stream) const { @@ -90,6 +135,18 @@ void ActivityWaitanySimcall::serialize(std::stringstream& stream) const stream << ' '; } } +std::string ActivityWaitSimcall::to_string() const +{ + return to_string_activity_wait(activity_); +} +std::string ActivityWaitanySimcall::to_string() const +{ + std::stringstream buffer("WaitAny("); + for (auto const& act : activities_) { + buffer << to_string_activity_wait(act); + } + return buffer.str(); +} ActivityWaitanySimcall::ActivityWaitanySimcall(ActorImpl* actor, const std::vector& activities, double timeout) : ResultingSimcall(actor, -1), activities_(activities), timeout_(timeout) @@ -149,6 +206,12 @@ void CommIsendSimcall::serialize(std::stringstream& stream) const XBT_DEBUG("SendObserver comm:%p mbox:%u buff:%p size:%zu tag:%d", comm_, mbox_->get_id(), src_buff_, src_buff_size_, tag_); } +std::string CommIsendSimcall::to_string() const +{ + return std::string("CommAsyncSend(comm_id: ") + std::to_string((uintptr_t)comm_) + + " mbox:" + std::to_string(mbox_->get_id()) + " srcbuf:" + ptr_to_id(src_buff_) + + " bufsize:" + std::to_string(src_buff_size_) + " tag: " + std::to_string(tag_) + ")"; +} void CommIrecvSimcall::serialize(std::stringstream& stream) const { @@ -156,5 +219,11 @@ void CommIrecvSimcall::serialize(std::stringstream& stream) const stream << (uintptr_t)comm_ << ' ' << mbox_->get_id() << ' ' << (uintptr_t)dst_buff_ << ' ' << tag_; XBT_DEBUG("RecvObserver comm:%p mbox:%u buff:%p tag:%d", comm_, mbox_->get_id(), dst_buff_, tag_); } +std::string CommIrecvSimcall::to_string() const +{ + return std::string("CommAsyncRecv(comm_id: ") + ptr_to_id(comm_) + + " mbox:" + std::to_string(mbox_->get_id()) + " dstbuf:" + ptr_to_id(dst_buff_) + + " tag: " + std::to_string(tag_) + ")"; +} } // namespace simgrid::kernel::actor diff --git a/src/kernel/actor/CommObserver.hpp b/src/kernel/actor/CommObserver.hpp index 41607aa580..04ed6f3619 100644 --- a/src/kernel/actor/CommObserver.hpp +++ b/src/kernel/actor/CommObserver.hpp @@ -26,6 +26,7 @@ public: bool is_visible() const override { return true; } activity::ActivityImpl* get_activity() const { return activity_; } void serialize(std::stringstream& stream) const override; + std::string to_string() const override; }; class ActivityTestanySimcall final : public ResultingSimcall { @@ -38,6 +39,7 @@ public: bool is_visible() const override { return true; } bool is_enabled() override { return true; /* can return -1 if no activity is ready */ } void serialize(std::stringstream& stream) const override; + std::string to_string() const override; int get_max_consider() const override; void prepare(int times_considered) override; const std::vector& get_activities() const { return activities_; } @@ -54,6 +56,7 @@ public: { } void serialize(std::stringstream& stream) const override; + std::string to_string() const override; bool is_visible() const override { return true; } bool is_enabled() override; activity::ActivityImpl* get_activity() const { return activity_; } @@ -71,6 +74,7 @@ public: ActivityWaitanySimcall(ActorImpl* actor, const std::vector& activities, double timeout); bool is_enabled() override; void serialize(std::stringstream& stream) const override; + std::string to_string() const override; bool is_visible() const override { return true; } void prepare(int times_considered) override; int get_max_consider() const override; @@ -116,6 +120,7 @@ public: { } void serialize(std::stringstream& stream) const override; + std::string to_string() const override; bool is_visible() const override { return true; } activity::MailboxImpl* get_mailbox() const { return mbox_; } double get_payload_size() const { return payload_size_; } @@ -160,6 +165,7 @@ public: { } void serialize(std::stringstream& stream) const override; + std::string to_string() const override; bool is_visible() const override { return true; } activity::MailboxImpl* get_mailbox() const { return mbox_; } double get_rate() const { return rate_; } diff --git a/src/kernel/actor/SimcallObserver.cpp b/src/kernel/actor/SimcallObserver.cpp index 88428f1b0f..c07d073e27 100644 --- a/src/kernel/actor/SimcallObserver.cpp +++ b/src/kernel/actor/SimcallObserver.cpp @@ -21,6 +21,10 @@ void RandomSimcall::serialize(std::stringstream& stream) const stream << (short)mc::Transition::Type::RANDOM << ' '; stream << min_ << ' ' << max_; } +std::string RandomSimcall::to_string() const +{ + return std::string("Random(min:") + std::to_string(min_) + " max:" + std::to_string(max_) + ")"; +} void RandomSimcall::prepare(int times_considered) { @@ -45,6 +49,10 @@ void ConditionWaitSimcall::serialize(std::stringstream& stream) const { THROW_UNIMPLEMENTED; } +std::string ConditionWaitSimcall::to_string() const +{ + THROW_UNIMPLEMENTED; +} ActorJoinSimcall::ActorJoinSimcall(ActorImpl* actor, ActorImpl* other, double timeout) : SimcallObserver(actor), other_(s4u::ActorPtr(other->get_iface())), timeout_(timeout) @@ -59,4 +67,8 @@ void ActorJoinSimcall::serialize(std::stringstream& stream) const stream << (short)mc::Transition::Type::ACTOR_JOIN << ' '; stream << other_->get_pid() << ' ' << (timeout_ > 0); } +std::string ActorJoinSimcall::to_string() const +{ + return std::string("ActorJoin(pid:") + std::to_string(other_->get_pid()) + ")"; +} } // namespace simgrid::kernel::actor diff --git a/src/kernel/actor/SimcallObserver.hpp b/src/kernel/actor/SimcallObserver.hpp index 909ebd1444..5b47b31adb 100644 --- a/src/kernel/actor/SimcallObserver.hpp +++ b/src/kernel/actor/SimcallObserver.hpp @@ -52,9 +52,12 @@ public: { /* Nothing to do by default */ } - /** Serialize to the given string buffer */ + /** Serialize to the given string buffer, to send over the network */ virtual void serialize(std::stringstream& stream) const = 0; + /** Used to debug (to display the simcall on which each actor is blocked when displaying it */ + virtual std::string to_string() const = 0; + /** Whether the MC should see this simcall. * Simcall that don't have an observer (ie, most of them) are not visible from the MC, but if there is an observer, * they are observable by default. */ @@ -84,6 +87,7 @@ public: xbt_assert(min < max); } void serialize(std::stringstream& stream) const override; + std::string to_string() const override; int get_max_consider() const override; void prepare(int times_considered) override; int get_value() const { return next_value_; } @@ -101,6 +105,7 @@ public: { } void serialize(std::stringstream& stream) const override; + std::string to_string() const override; bool is_enabled() override; activity::ConditionVariableImpl* get_cond() const { return cond_; } activity::MutexImpl* get_mutex() const { return mutex_; } @@ -114,6 +119,7 @@ class ActorJoinSimcall final : public SimcallObserver { public: ActorJoinSimcall(ActorImpl* actor, ActorImpl* other, double timeout = -1.0); void serialize(std::stringstream& stream) const override; + std::string to_string() const override; bool is_enabled() override; s4u::ActorPtr get_other_actor() const { return other_; } diff --git a/src/kernel/actor/SynchroObserver.cpp b/src/kernel/actor/SynchroObserver.cpp index 96d75c7c63..8114a5eda2 100644 --- a/src/kernel/actor/SynchroObserver.cpp +++ b/src/kernel/actor/SynchroObserver.cpp @@ -28,6 +28,11 @@ void MutexObserver::serialize(std::stringstream& stream) const const auto* owner = get_mutex()->get_owner(); stream << (short)type_ << ' ' << get_mutex()->get_id() << ' ' << (owner != nullptr ? owner->get_pid() : -1); } +std::string MutexObserver::to_string() const +{ + return std::string(mc::Transition::to_c_str(type_)) + "(mutex_id: " + std::to_string(get_mutex()->get_id()) + + "owner:" + std::to_string(get_mutex()->get_owner()->get_pid()) + ")"; +} bool MutexObserver::is_enabled() { @@ -45,6 +50,10 @@ void SemaphoreObserver::serialize(std::stringstream& stream) const { stream << (short)type_ << ' ' << get_sem()->get_id() << ' ' << false /* Granted is ignored for LOCK/UNLOCK */; } +std::string SemaphoreObserver::to_string() const +{ + return std::string(mc::Transition::to_c_str(type_)) + "(sem_id: " + std::to_string(get_sem()->get_id()) + ")"; +} SemaphoreAcquisitionObserver::SemaphoreAcquisitionObserver(ActorImpl* actor, mc::Transition::Type type, activity::SemAcquisitionImpl* acqui, double timeout) @@ -59,6 +68,12 @@ void SemaphoreAcquisitionObserver::serialize(std::stringstream& stream) const { stream << (short)type_ << ' ' << acquisition_->semaphore_->get_id() << ' ' << acquisition_->granted_; } +std::string SemaphoreAcquisitionObserver::to_string() const +{ + return std::string(mc::Transition::to_c_str(type_)) + + "(sem_id: " + std::to_string(acquisition_->semaphore_->get_id()) + ' ' + + (acquisition_->granted_ ? "granted)" : "not granted)"); +} BarrierObserver::BarrierObserver(ActorImpl* actor, mc::Transition::Type type, activity::BarrierImpl* bar) : ResultingSimcall(actor, false), type_(type), barrier_(bar), timeout_(-1) @@ -76,6 +91,12 @@ void BarrierObserver::serialize(std::stringstream& stream) const xbt_assert(barrier_ != nullptr || (acquisition_ != nullptr && acquisition_->barrier_ != nullptr)); stream << (short)type_ << ' ' << (barrier_ != nullptr ? barrier_->get_id() : acquisition_->barrier_->get_id()); } +std::string BarrierObserver::to_string() const +{ + return std::string(mc::Transition::to_c_str(type_)) + + "(barrier_id: " + std::to_string(barrier_ != nullptr ? barrier_->get_id() : acquisition_->barrier_->get_id()) + + ")"; +} bool BarrierObserver::is_enabled() { return type_ == mc::Transition::Type::BARRIER_ASYNC_LOCK || diff --git a/src/kernel/actor/SynchroObserver.hpp b/src/kernel/actor/SynchroObserver.hpp index 2c2eac378a..90c7335883 100644 --- a/src/kernel/actor/SynchroObserver.hpp +++ b/src/kernel/actor/SynchroObserver.hpp @@ -24,6 +24,7 @@ public: MutexObserver(ActorImpl* actor, mc::Transition::Type type, activity::MutexImpl* mutex); void serialize(std::stringstream& stream) const override; + std::string to_string() const override; bool is_enabled() override; activity::MutexImpl* get_mutex() const { return mutex_; } @@ -38,6 +39,7 @@ public: SemaphoreObserver(ActorImpl* actor, mc::Transition::Type type, activity::SemaphoreImpl* sem); void serialize(std::stringstream& stream) const override; + std::string to_string() const override; activity::SemaphoreImpl* get_sem() const { return sem_; } }; @@ -53,6 +55,7 @@ public: double timeout = -1.0); void serialize(std::stringstream& stream) const override; + std::string to_string() const override; bool is_enabled() override; double get_timeout() const { return timeout_; } @@ -71,6 +74,7 @@ public: double timeout = -1.0); void serialize(std::stringstream& stream) const override; + std::string to_string() const override; bool is_enabled() override; double get_timeout() const { return timeout_; } diff --git a/src/mc/mc_record.cpp b/src/mc/mc_record.cpp index 18f8ec91b1..03d088af6e 100644 --- a/src/mc/mc_record.cpp +++ b/src/mc/mc_record.cpp @@ -33,6 +33,9 @@ void RecordTrace::replay() const const kernel::actor::Simcall* simcall = &(actor->simcall_); xbt_assert(simgrid::mc::request_is_visible(simcall), "Simcall %s of actor %s is not visible.", simcall->get_cname(), actor->get_cname()); + if (not mc::actor_is_enabled(actor)) + simgrid::kernel::EngineImpl::get_instance()->display_all_actor_status(); + xbt_assert(simgrid::mc::actor_is_enabled(actor), "Actor %s (simcall %s) is not enabled.", actor->get_cname(), simcall->get_cname()); -- 2.20.1