From: Martin Quinson Date: Tue, 7 Nov 2023 22:16:42 +0000 (+0100) Subject: Improve the debug messages X-Git-Tag: v3.35~87^2~3 X-Git-Url: http://bilbo.iut-bm.univ-fcomte.fr/pub/gitweb/simgrid.git/commitdiff_plain/14bddad6ad3fcf94b0bcdeb69ef68350efb5b213 Improve the debug messages --- diff --git a/examples/cpp/synchro-barrier/s4u-mc-synchro-barrier.tesh b/examples/cpp/synchro-barrier/s4u-mc-synchro-barrier.tesh index 9ed6eb7f45..a9ee7cea4d 100644 --- a/examples/cpp/synchro-barrier/s4u-mc-synchro-barrier.tesh +++ b/examples/cpp/synchro-barrier/s4u-mc-synchro-barrier.tesh @@ -3,9 +3,9 @@ $ $VALGRIND_NO_TRACE_CHILDREN ${bindir:=.}/../../../bin/simgrid-mc --log=mc_dfs.thres:verbose --log=root.fmt="[Checker]%e%m%n" -- ${bindir:=.}/s4u-synchro-barrier 1 --log=s4u_test.thres:critical --log=root.fmt="[App%e%e%e%e]%e%m%n" > [Checker] Start a DFS exploration. Reduction is: dpor. > [Checker] Sleep set actually containing: -> [Checker] Execute 1: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 1, state: 1, 0 interleaves) +> [Checker] Executed 1: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 1, state: 1, 0 interleaves) > [Checker] Sleep set actually containing: -> [Checker] Execute 1: BARRIER_WAIT(barrier: 0) (stack depth: 2, state: 2, 0 interleaves) +> [Checker] Executed 1: BARRIER_WAIT(barrier: 0) (stack depth: 2, state: 2, 0 interleaves) > [Checker] 0 actors remain, but none of them need to be interleaved (depth 4). > [Checker] Execution came to an end at 1;1 (state: 3, depth: 3) > [Checker] Backtracking from 1;1 @@ -14,19 +14,19 @@ $ $VALGRIND_NO_TRACE_CHILDREN ${bindir:=.}/../../../bin/simgrid-mc --log=mc_dfs. $ $VALGRIND_NO_TRACE_CHILDREN ${bindir:=.}/../../../bin/simgrid-mc --log=mc_dfs.thres:verbose --log=root.fmt="[Checker]%e%m%n" -- ${bindir:=.}/s4u-synchro-barrier 2 --log=s4u_test.thres:critical --log=root.fmt="[App%e%e%e%e]%e%m%n" > [Checker] Start a DFS exploration. Reduction is: dpor. > [Checker] Sleep set actually containing: -> [Checker] Execute 1: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 1, state: 1, 0 interleaves) +> [Checker] Executed 1: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 1, state: 1, 0 interleaves) > [Checker] Sleep set actually containing: -> [Checker] Execute 2: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 2, state: 2, 0 interleaves) +> [Checker] Executed 2: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 2, state: 2, 0 interleaves) > [Checker] INDEPENDENT Transitions: > [Checker] #1 BARRIER_ASYNC_LOCK(barrier: 0) (state=1) > [Checker] #2 BARRIER_ASYNC_LOCK(barrier: 0) (state=2) > [Checker] Sleep set actually containing: -> [Checker] Execute 1: BARRIER_WAIT(barrier: 0) (stack depth: 3, state: 3, 0 interleaves) +> [Checker] Executed 1: BARRIER_WAIT(barrier: 0) (stack depth: 3, state: 3, 0 interleaves) > [Checker] Dependent Transitions: > [Checker] #2 BARRIER_ASYNC_LOCK(barrier: 0) (state=2) > [Checker] #1 BARRIER_WAIT(barrier: 0) (state=3) > [Checker] Sleep set actually containing: -> [Checker] Execute 2: BARRIER_WAIT(barrier: 0) (stack depth: 4, state: 4, 0 interleaves) +> [Checker] Executed 2: BARRIER_WAIT(barrier: 0) (stack depth: 4, state: 4, 0 interleaves) > [Checker] INDEPENDENT Transitions: > [Checker] #1 BARRIER_WAIT(barrier: 0) (state=3) > [Checker] #2 BARRIER_WAIT(barrier: 0) (state=4) @@ -38,7 +38,7 @@ $ $VALGRIND_NO_TRACE_CHILDREN ${bindir:=.}/../../../bin/simgrid-mc --log=mc_dfs. > [Checker] Backtracking from 1;2;1;2 > [Checker] Sleep set actually containing: > [Checker] <1,BARRIER_ASYNC_LOCK(barrier: 0)> -> [Checker] Execute 2: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 1, state: 1, 0 interleaves) +> [Checker] Executed 2: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 1, state: 1, 0 interleaves) > [Checker] 2 actors remain, but none of them need to be interleaved (depth 3). > [Checker] Backtracking from 2 > [Checker] DFS exploration ended. 6 unique states visited; 1 backtracks (0 transition replays, 7 states visited overall) @@ -46,14 +46,14 @@ $ $VALGRIND_NO_TRACE_CHILDREN ${bindir:=.}/../../../bin/simgrid-mc --log=mc_dfs. $ $VALGRIND_NO_TRACE_CHILDREN ${bindir:=.}/../../../bin/simgrid-mc --log=mc_dfs.thres:verbose --log=root.fmt="[Checker]%e%m%n" -- ${bindir:=.}/s4u-synchro-barrier 3 --log=s4u_test.thres:critical --log=root.fmt="[App%e%e%e%e]%e%m%n" > [Checker] Start a DFS exploration. Reduction is: dpor. > [Checker] Sleep set actually containing: -> [Checker] Execute 1: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 1, state: 1, 0 interleaves) +> [Checker] Executed 1: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 1, state: 1, 0 interleaves) > [Checker] Sleep set actually containing: -> [Checker] Execute 2: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 2, state: 2, 0 interleaves) +> [Checker] Executed 2: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 2, state: 2, 0 interleaves) > [Checker] INDEPENDENT Transitions: > [Checker] #1 BARRIER_ASYNC_LOCK(barrier: 0) (state=1) > [Checker] #2 BARRIER_ASYNC_LOCK(barrier: 0) (state=2) > [Checker] Sleep set actually containing: -> [Checker] Execute 3: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 3, state: 3, 0 interleaves) +> [Checker] Executed 3: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 3, state: 3, 0 interleaves) > [Checker] INDEPENDENT Transitions: > [Checker] #2 BARRIER_ASYNC_LOCK(barrier: 0) (state=2) > [Checker] #3 BARRIER_ASYNC_LOCK(barrier: 0) (state=3) @@ -61,12 +61,12 @@ $ $VALGRIND_NO_TRACE_CHILDREN ${bindir:=.}/../../../bin/simgrid-mc --log=mc_dfs. > [Checker] #1 BARRIER_ASYNC_LOCK(barrier: 0) (state=1) > [Checker] #3 BARRIER_ASYNC_LOCK(barrier: 0) (state=3) > [Checker] Sleep set actually containing: -> [Checker] Execute 1: BARRIER_WAIT(barrier: 0) (stack depth: 4, state: 4, 0 interleaves) +> [Checker] Executed 1: BARRIER_WAIT(barrier: 0) (stack depth: 4, state: 4, 0 interleaves) > [Checker] Dependent Transitions: > [Checker] #3 BARRIER_ASYNC_LOCK(barrier: 0) (state=3) > [Checker] #1 BARRIER_WAIT(barrier: 0) (state=4) > [Checker] Sleep set actually containing: -> [Checker] Execute 2: BARRIER_WAIT(barrier: 0) (stack depth: 5, state: 5, 0 interleaves) +> [Checker] Executed 2: BARRIER_WAIT(barrier: 0) (stack depth: 5, state: 5, 0 interleaves) > [Checker] INDEPENDENT Transitions: > [Checker] #1 BARRIER_WAIT(barrier: 0) (state=4) > [Checker] #2 BARRIER_WAIT(barrier: 0) (state=5) @@ -74,7 +74,7 @@ $ $VALGRIND_NO_TRACE_CHILDREN ${bindir:=.}/../../../bin/simgrid-mc --log=mc_dfs. > [Checker] #3 BARRIER_ASYNC_LOCK(barrier: 0) (state=3) > [Checker] #2 BARRIER_WAIT(barrier: 0) (state=5) > [Checker] Sleep set actually containing: -> [Checker] Execute 3: BARRIER_WAIT(barrier: 0) (stack depth: 6, state: 6, 0 interleaves) +> [Checker] Executed 3: BARRIER_WAIT(barrier: 0) (stack depth: 6, state: 6, 0 interleaves) > [Checker] INDEPENDENT Transitions: > [Checker] #2 BARRIER_WAIT(barrier: 0) (state=5) > [Checker] #3 BARRIER_WAIT(barrier: 0) (state=6) @@ -89,7 +89,7 @@ $ $VALGRIND_NO_TRACE_CHILDREN ${bindir:=.}/../../../bin/simgrid-mc --log=mc_dfs. > [Checker] Backtracking from 1;2;3;1;2;3 > [Checker] Sleep set actually containing: > [Checker] <2,BARRIER_ASYNC_LOCK(barrier: 0)> -> [Checker] Execute 3: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 2, state: 2, 0 interleaves) +> [Checker] Executed 3: BARRIER_ASYNC_LOCK(barrier: 0) (stack depth: 2, state: 2, 0 interleaves) > [Checker] INDEPENDENT Transitions: > [Checker] #1 BARRIER_ASYNC_LOCK(barrier: 0) (state=1) > [Checker] #3 BARRIER_ASYNC_LOCK(barrier: 0) (state=2) diff --git a/examples/cpp/synchro-mutex/s4u-mc-synchro-mutex.tesh b/examples/cpp/synchro-mutex/s4u-mc-synchro-mutex.tesh index 5f726fec70..26f7e203c4 100644 --- a/examples/cpp/synchro-mutex/s4u-mc-synchro-mutex.tesh +++ b/examples/cpp/synchro-mutex/s4u-mc-synchro-mutex.tesh @@ -6,13 +6,13 @@ $ $VALGRIND_NO_TRACE_CHILDREN ${bindir:=.}/../../../bin/simgrid-mc --log=mc_dfs. > [App ] Configuration change: Set 'actors' to '1' > [Checker] Start a DFS exploration. Reduction is: dpor. > [Checker] Sleep set actually containing: -> [Checker] Execute 1: MUTEX_ASYNC_LOCK(mutex: 0, owner: 1) (stack depth: 1, state: 1, 0 interleaves) +> [Checker] Executed 1: MUTEX_ASYNC_LOCK(mutex: 0, owner: 1) (stack depth: 1, state: 1, 0 interleaves) > [Checker] Sleep set actually containing: -> [Checker] Execute 1: MUTEX_WAIT(mutex: 0, owner: 1) (stack depth: 2, state: 2, 0 interleaves) +> [Checker] Executed 1: MUTEX_WAIT(mutex: 0, owner: 1) (stack depth: 2, state: 2, 0 interleaves) > [Checker] Sleep set actually containing: -> [Checker] Execute 1: MUTEX_UNLOCK(mutex: 0, owner: -1) (stack depth: 3, state: 3, 0 interleaves) +> [Checker] Executed 1: MUTEX_UNLOCK(mutex: 0, owner: -1) (stack depth: 3, state: 3, 0 interleaves) > [Checker] Sleep set actually containing: -> [Checker] Execute 2: MUTEX_ASYNC_LOCK(mutex: 0, owner: 2) (stack depth: 4, state: 4, 0 interleaves) +> [Checker] Executed 2: MUTEX_ASYNC_LOCK(mutex: 0, owner: 2) (stack depth: 4, state: 4, 0 interleaves) > [Checker] INDEPENDENT Transitions: > [Checker] #1 MUTEX_UNLOCK(mutex: 0, owner: -1) (state=3) > [Checker] #2 MUTEX_ASYNC_LOCK(mutex: 0, owner: 2) (state=4) @@ -23,12 +23,12 @@ $ $VALGRIND_NO_TRACE_CHILDREN ${bindir:=.}/../../../bin/simgrid-mc --log=mc_dfs. > [Checker] #1 MUTEX_ASYNC_LOCK(mutex: 0, owner: 1) (state=1) > [Checker] #2 MUTEX_ASYNC_LOCK(mutex: 0, owner: 2) (state=4) > [Checker] Sleep set actually containing: -> [Checker] Execute 2: MUTEX_WAIT(mutex: 0, owner: 2) (stack depth: 5, state: 5, 0 interleaves) +> [Checker] Executed 2: MUTEX_WAIT(mutex: 0, owner: 2) (stack depth: 5, state: 5, 0 interleaves) > [Checker] Dependent Transitions: > [Checker] #1 MUTEX_UNLOCK(mutex: 0, owner: -1) (state=3) > [Checker] #2 MUTEX_WAIT(mutex: 0, owner: 2) (state=5) > [Checker] Sleep set actually containing: -> [Checker] Execute 2: MUTEX_UNLOCK(mutex: 0, owner: -1) (stack depth: 6, state: 6, 0 interleaves) +> [Checker] Executed 2: MUTEX_UNLOCK(mutex: 0, owner: -1) (stack depth: 6, state: 6, 0 interleaves) > [Checker] Dependent Transitions: > [Checker] #1 MUTEX_UNLOCK(mutex: 0, owner: -1) (state=3) > [Checker] #2 MUTEX_UNLOCK(mutex: 0, owner: -1) (state=6) @@ -37,7 +37,7 @@ $ $VALGRIND_NO_TRACE_CHILDREN ${bindir:=.}/../../../bin/simgrid-mc --log=mc_dfs. > [Checker] Backtracking from 1;1;1;2;2;2 > [Checker] Sleep set actually containing: > [Checker] <1,MUTEX_UNLOCK(mutex: 0, owner: -1)> -> [Checker] Execute 2: MUTEX_ASYNC_LOCK(mutex: 0, owner: 1) (stack depth: 3, state: 3, 0 interleaves) +> [Checker] Executed 2: MUTEX_ASYNC_LOCK(mutex: 0, owner: 1) (stack depth: 3, state: 3, 0 interleaves) > [Checker] INDEPENDENT Transitions: > [Checker] #1 MUTEX_WAIT(mutex: 0, owner: 1) (state=2) > [Checker] #2 MUTEX_ASYNC_LOCK(mutex: 0, owner: 1) (state=3) @@ -48,29 +48,29 @@ $ $VALGRIND_NO_TRACE_CHILDREN ${bindir:=.}/../../../bin/simgrid-mc --log=mc_dfs. > [Checker] Backtracking from 1;1;2 > [Checker] Sleep set actually containing: > [Checker] <1,MUTEX_ASYNC_LOCK(mutex: 0, owner: 1)> -> [Checker] Execute 2: MUTEX_ASYNC_LOCK(mutex: 0, owner: 2) (stack depth: 1, state: 1, 0 interleaves) +> [Checker] Executed 2: MUTEX_ASYNC_LOCK(mutex: 0, owner: 2) (stack depth: 1, state: 1, 0 interleaves) > [Checker] Sleep set actually containing: -> [Checker] Execute 1: MUTEX_ASYNC_LOCK(mutex: 0, owner: 2) (stack depth: 2, state: 9, 0 interleaves) +> [Checker] Executed 1: MUTEX_ASYNC_LOCK(mutex: 0, owner: 2) (stack depth: 2, state: 9, 0 interleaves) > [Checker] Dependent Transitions: > [Checker] #2 MUTEX_ASYNC_LOCK(mutex: 0, owner: 2) (state=1) > [Checker] #1 MUTEX_ASYNC_LOCK(mutex: 0, owner: 2) (state=9) > [Checker] Sleep set actually containing: -> [Checker] Execute 2: MUTEX_WAIT(mutex: 0, owner: 2) (stack depth: 3, state: 10, 0 interleaves) +> [Checker] Executed 2: MUTEX_WAIT(mutex: 0, owner: 2) (stack depth: 3, state: 10, 0 interleaves) > [Checker] INDEPENDENT Transitions: > [Checker] #1 MUTEX_ASYNC_LOCK(mutex: 0, owner: 2) (state=9) > [Checker] #2 MUTEX_WAIT(mutex: 0, owner: 2) (state=10) > [Checker] Sleep set actually containing: -> [Checker] Execute 2: MUTEX_UNLOCK(mutex: 0, owner: 1) (stack depth: 4, state: 11, 0 interleaves) +> [Checker] Executed 2: MUTEX_UNLOCK(mutex: 0, owner: 1) (stack depth: 4, state: 11, 0 interleaves) > [Checker] INDEPENDENT Transitions: > [Checker] #1 MUTEX_ASYNC_LOCK(mutex: 0, owner: 2) (state=9) > [Checker] #2 MUTEX_UNLOCK(mutex: 0, owner: 1) (state=11) > [Checker] Sleep set actually containing: -> [Checker] Execute 1: MUTEX_WAIT(mutex: 0, owner: 1) (stack depth: 5, state: 12, 0 interleaves) +> [Checker] Executed 1: MUTEX_WAIT(mutex: 0, owner: 1) (stack depth: 5, state: 12, 0 interleaves) > [Checker] Dependent Transitions: > [Checker] #2 MUTEX_UNLOCK(mutex: 0, owner: 1) (state=11) > [Checker] #1 MUTEX_WAIT(mutex: 0, owner: 1) (state=12) > [Checker] Sleep set actually containing: -> [Checker] Execute 1: MUTEX_UNLOCK(mutex: 0, owner: -1) (stack depth: 6, state: 13, 0 interleaves) +> [Checker] Executed 1: MUTEX_UNLOCK(mutex: 0, owner: -1) (stack depth: 6, state: 13, 0 interleaves) > [Checker] Dependent Transitions: > [Checker] #2 MUTEX_UNLOCK(mutex: 0, owner: 1) (state=11) > [Checker] #1 MUTEX_UNLOCK(mutex: 0, owner: -1) (state=13) diff --git a/src/kernel/actor/ActorImpl.cpp b/src/kernel/actor/ActorImpl.cpp index 013ad5b217..61e0479325 100644 --- a/src/kernel/actor/ActorImpl.cpp +++ b/src/kernel/actor/ActorImpl.cpp @@ -509,8 +509,10 @@ void create_maestro(const std::function& code) /** (in kernel mode) unpack the simcall and activate the handler */ void ActorImpl::simcall_handle(int times_considered) { - XBT_DEBUG("Handling simcall %p: %s(%ld) %s", &simcall_, simcall_.issuer_->get_cname(), simcall_.issuer_->get_pid(), - (simcall_.observer_ != nullptr ? simcall_.observer_->to_string().c_str() : simcall_.get_cname())); + XBT_DEBUG("Handling simcall %p: %s(%ld) %s (times_considered:%d)", &simcall_, simcall_.issuer_->get_cname(), + simcall_.issuer_->get_pid(), + (simcall_.observer_ != nullptr ? simcall_.observer_->to_string().c_str() : simcall_.get_cname()), + times_considered); if (simcall_.observer_ != nullptr) simcall_.observer_->prepare(times_considered); if (wannadie()) diff --git a/src/mc/explo/DFSExplorer.cpp b/src/mc/explo/DFSExplorer.cpp index ffa682f2da..304130173f 100644 --- a/src/mc/explo/DFSExplorer.cpp +++ b/src/mc/explo/DFSExplorer.cpp @@ -163,13 +163,16 @@ void DFSExplorer::run() XBT_VERB(" <%ld,%s>", aid, transition->to_string().c_str()); } + auto todo = state->get_actors_list().at(next).get_transition(); + XBT_DEBUG("wanna execute %ld: %.60s", next, todo->to_string().c_str()); + /* Actually answer the request: let's execute the selected request (MCed does one step) */ auto executed_transition = state->execute_next(next, get_remote_app()); on_transition_execute_signal(state->get_transition_out().get(), get_remote_app()); // If there are processes to interleave and the maximum depth has not been // reached then perform one step of the exploration algorithm. - XBT_VERB("Execute %ld: %.60s (stack depth: %zu, state: %ld, %zu interleaves)", state->get_transition_out()->aid_, + XBT_VERB("Executed %ld: %.60s (stack depth: %zu, state: %ld, %zu interleaves)", state->get_transition_out()->aid_, state->get_transition_out()->to_string().c_str(), stack_.size(), state->get_num(), state->count_todo()); /* Create the new expanded state (copy the state of MCed into our MCer data) */