Logo AND Algorithmique Numérique Distribuée

Public GIT Repository
Be more verbose on the blocking transition when displaying the actor state on Ctrl-C
authorMartin Quinson <martin.quinson@ens-rennes.fr>
Mon, 31 Oct 2022 21:41:10 +0000 (22:41 +0100)
committerMartin Quinson <martin.quinson@ens-rennes.fr>
Mon, 31 Oct 2022 21:41:10 +0000 (22:41 +0100)
examples/c/actor-exiting/actor-exiting.tesh
examples/cpp/actor-exiting/s4u-actor-exiting.tesh
src/kernel/EngineImpl.cpp
src/kernel/actor/CommObserver.cpp
src/kernel/actor/CommObserver.hpp
src/kernel/actor/SimcallObserver.cpp
src/kernel/actor/SimcallObserver.hpp
src/kernel/actor/SynchroObserver.cpp
src/kernel/actor/SynchroObserver.hpp
src/mc/mc_record.cpp

index 2fb10ee..4bc56ef 100644 (file)
@@ -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 <pid> (<name>@<host>): <status>"
-> [  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
index cb81951..660b083 100644 (file)
@@ -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 <pid> (<name>@<host>): <status>"
-> [  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
index 717e771..99304a9 100644 (file)
@@ -26,6 +26,8 @@
 #include <dlfcn.h>
 #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<kernel::activity::IoImpl>(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()));
     }
   }
 }
index 8f86d94..98e0af8 100644 (file)
@@ -51,6 +51,25 @@ static void serialize_activity_test(const activity::ActivityImpl* act, std::stri
     stream << (short)mc::Transition::Type::UNKNOWN;
   }
 }
+template <typename A> static std::string ptr_to_id(A* ptr)
+{
+  static std::unordered_map<A*, std::string> 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<activity::CommImpl const*>(act)) {
+    return std::string("CommTest(comm_id:") + ptr_to_id<activity::CommImpl const>(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<unsigned char>(comm->src_buff_) +
+           " dstbuf:" + ptr_to_id<unsigned char>(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<activity::CommImpl const*>(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<activity::CommImpl const*>(act)) {
+    return std::string("CommWait(comm_id:") + ptr_to_id<activity::CommImpl const>(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<unsigned char>(comm->src_buff_) +
+           " dstbuf:" + ptr_to_id<unsigned char>(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<activity::ActivityImpl*>& 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<unsigned char>(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<activity::CommImpl const>(comm_) +
+         " mbox:" + std::to_string(mbox_->get_id()) + " dstbuf:" + ptr_to_id<unsigned char>(dst_buff_) +
+         " tag: " + std::to_string(tag_) + ")";
+}
 
 } // namespace simgrid::kernel::actor
index 41607aa..04ed6f3 100644 (file)
@@ -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<ssize_t> {
@@ -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<activity::ActivityImpl*>& 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<activity::ActivityImpl*>& 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_; }
index 88428f1..c07d073 100644 (file)
@@ -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
index 909ebd1..5b47b31 100644 (file)
@@ -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_; }
index 96d75c7..8114a5e 100644 (file)
@@ -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 ||
index 2c2eac3..90c7335 100644 (file)
@@ -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_; }
index 18f8ec9..03d088a 100644 (file)
@@ -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());