TestGlobalModuleCache.py test is flaky on 32 bit Arm Linux

[DavidSpickett]

This test was added by #74894 and was flaky on Arm and AArch64, though I have only since seen it fail on Arm. I assume it's just a lot more common there.

The failure looks like:

intern-state     ^^^^^^^^ Thread::ShouldStop Begin ^^^^^^^^
intern-state     Plan stack initial state:
  thread #1: tid = 0x1213e8:
    Active plan stack:
      Element 0: Base thread plan.
      Element 1: Single stepping past breakpoint site 11 at 0xf7fc0c14

python3.10       Discarding thread plans for thread (tid = 0x1213e8, force 1)
intern-state     Plan Step over breakpoint trap should stop: 0.
intern-state     Completed step over breakpoint plan.
intern-state     Plan Step over breakpoint trap auto-continue: true.
intern-state     ^^^^^^^^ Thread::ShouldStop plan stack before PopPlan ^^^^^^^^
intern-state       thread #1: tid = 0x1213e8:
    Active plan stack:
      Element 0: Base thread plan.
    Discarded plan stack:
      Element 0: Single stepping past breakpoint site 11 at 0xf7fc0c14

python3.10: /home/david.spickett/llvm-project/lldb/source/Target/ThreadPlanStack.cpp:151: lldb::ThreadPlanSP lldb_private::ThreadPlanStack::PopPlan(): Assertion `m_plans.size() > 1 && "Can't pop the base thread plan"' failed.
PLEASE submit a bug report to https://github.com/llvm/llvm-project/issues/ and include the crash backtrace.
#0 0xf174a0c0 llvm::sys::PrintStackTrace(llvm::raw_ostream&, int) Signals.cpp:0:0
#1 0xf1747b24 llvm::sys::RunSignalHandlers() Signals.cpp:0:0
#2 0xf174a968 SignalHandler(int) Signals.cpp:0:0
#3 0xf774d6e0 __default_sa_restorer ./signal/../sysdeps/unix/sysv/linux/arm/sigrestorer.S:67:0
#4 0xf773db06 ./csu/../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47:0
#5 0xf777d2ca __pthread_kill_implementation ./nptl/pthread_kill.c:44:76
#6 0xf774c840 gsignal ./signal/../sysdeps/posix/raise.c:27:6

Note that this build included the logging I added in d14d521, after narrowing down the crash to one particular call to PopPlan.

Initially I could not reproduce it but have now been able to do so, though it takes a long time to fail.

The basic problem is that somehow Thread::ShouldStop asks for the current plan when the stack consists of the base plan and the single step plan. Before it can decide that the step has finished and should be popped, a call is made in the test to destroy the debugger.

This follows this call chain:

• Debugger::Destroy
• Debugger::Clear
• Process::Finalize
• Process::DestroyImpl
• ThreadList::DiscardThreadPlans
• Thread::DiscardThreadPlans

Which is why we see Discarding thread plans for thread (tid = 0x1213e8, force 1) in the log output.

Discarding the thread plans leaves only the base plan on the stack (the stack always has the base plan no matter what). So when thread::ShouldStop decides to pop the single step plan, it's no longer on the stack. It's a time of read/time of use issue, except ShouldStop wasn't written with it in mind that the plan stack would change during it at all.

This means that PopPlan tries to pop the base plan, which asserts to tell us we can't do that.

intern-state     ^^^^^^^^ Thread::ShouldStop Begin ^^^^^^^^
intern-state     Plan stack initial state:
  thread #1: tid = 0x1213e8:
    Active plan stack:
      Element 0: Base thread plan.
      Element 1: Single stepping past breakpoint site 11 at 0xf7fc0c14

Thread::ShouldStop sees that the current plan is the single step plan.

python3.10       Discarding thread plans for thread (tid = 0x1213e8, force 1)

Destroying the debugger discards the single step plan.

intern-state     Completed step over breakpoint plan.

Thread::ShouldStop works out that the single step is finished and so the plan should be discarded.

intern-state     ^^^^^^^^ Thread::ShouldStop plan stack before PopPlan ^^^^^^^^
intern-state       thread #1: tid = 0x1213e8:
    Active plan stack:
      Element 0: Base thread plan.
    Discarded plan stack:
      Element 0: Single stepping past breakpoint site 11 at 0xf7fc0c14

Whoops, it already was and we certainly can't pop the base plan!

The overall issue seems to be one of destruction order. Or at least, something isn't telling the threads to stop before we start destroying the process. The threads I think are destroyed later in Process::Finalize, and I think there's a potential bug there too.

  m_thread_plans.Clear();
  m_thread_list_real.Destroy();
  m_thread_list.Destroy();
  m_extended_thread_list.Destroy();

The thread plans are cleared before the threads that would be looking at them are destroyed. That's not the cause of this particular assert, but it's suspicious to me at least.

The underlying problem is probably whatever is letting thread::ShouldStop run, even though we're in the process of destroying the Process that contains them.

[llvmbot]

@llvm/issue-subscribers-lldb

Author: David Spickett (DavidSpickett)

This test was added by https://github.com//pull/74894 and was flaky on Arm and AArch64, though I have only since seen it fail on Arm. So I assume it's just a lot more common there.

The failure looks like:

intern-state     ^^^^^^^^ Thread::ShouldStop Begin ^^^^^^^^
intern-state     Plan stack initial state:
  thread #<!-- -->1: tid = 0x1213e8:
    Active plan stack:
      Element 0: Base thread plan.
      Element 1: Single stepping past breakpoint site 11 at 0xf7fc0c14

python3.10       Discarding thread plans for thread (tid = 0x1213e8, force 1)
intern-state     Plan Step over breakpoint trap should stop: 0.
intern-state     Completed step over breakpoint plan.
intern-state     Plan Step over breakpoint trap auto-continue: true.
intern-state     ^^^^^^^^ Thread::ShouldStop plan stack before PopPlan ^^^^^^^^
intern-state       thread #<!-- -->1: tid = 0x1213e8:
    Active plan stack:
      Element 0: Base thread plan.
    Discarded plan stack:
      Element 0: Single stepping past breakpoint site 11 at 0xf7fc0c14

python3.10: /home/david.spickett/llvm-project/lldb/source/Target/ThreadPlanStack.cpp:151: lldb::ThreadPlanSP lldb_private::ThreadPlanStack::PopPlan(): Assertion `m_plans.size() &gt; 1 &amp;&amp; "Can't pop the base thread plan"' failed.
PLEASE submit a bug report to https://github.com/llvm/llvm-project/issues/ and include the crash backtrace.
#<!-- -->0 0xf174a0c0 llvm::sys::PrintStackTrace(llvm::raw_ostream&amp;, int) Signals.cpp:0:0
#<!-- -->1 0xf1747b24 llvm::sys::RunSignalHandlers() Signals.cpp:0:0
#<!-- -->2 0xf174a968 SignalHandler(int) Signals.cpp:0:0
#<!-- -->3 0xf774d6e0 __default_sa_restorer ./signal/../sysdeps/unix/sysv/linux/arm/sigrestorer.S:67:0
#<!-- -->4 0xf773db06 ./csu/../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47:0
#<!-- -->5 0xf777d2ca __pthread_kill_implementation ./nptl/pthread_kill.c:44:76
#<!-- -->6 0xf774c840 gsignal ./signal/../sysdeps/posix/raise.c:27:6

Note that this build included the logging I added in d14d521, after narrowing down the crash to one particular call to PopPlan.

Initially I could not reproduce it but have now been able to do so, though it takes a long time to fail.

The basic problem is that somehow Thread::ShouldStop asks for the current plan when the stack consists of the base plan and the single step plan. Before it can decide that the step has finished and should be popped, a call is made in the test to destroy the debugger.

This follows this call chain:

• Debugger::Destroy
• Debugger::Clear
• Process::Finalize
• Process::DestroyImpl
• ThreadList::DiscardThreadPlans
• Thread::DiscardThreadPlans

Which is why we see Discarding thread plans for thread (tid = 0x1213e8, force 1) in the log output.

Discarding the thread plans leaves only the base plan on the stack (the stack always has the base plan no matter what). So when thread::ShouldStop decides to pop the single step plan, it's no longer on the stack. It's a time of read/time of use issue, except ShouldStop wasn't written with it in mind that the plan stack would change during it at all.

This means that PopPlan tries to pop the base plan, which asserts to tell us we can't do that.

The overall issue seems to be one of destruction order. Or at least, something isn't telling the threads to stop before we start destroying the process. The threads I think are destroyed later in Process::Finalize, and I think there's a potential bug there too.

  m_thread_plans.Clear();
  m_thread_list_real.Destroy();
  m_thread_list.Destroy();
  m_extended_thread_list.Destroy();

The thread plans are cleared before the threads that would be looking at them are destroyed. That's not the cause of this particular assert, but it's suspicious to me at least.

The underlying problem is probably whatever is letting thread::ShouldStop run, even though we're in the process of destroying the Process that contains them.

[DavidSpickett]

a8af51d skips the test again.

I also found that it's a lot easier to reproduce without logging enabled.

[DavidSpickett]

One of the failure log files: arm fail log

[DavidSpickett]

You could have some ugly checks that the current plan is in fact in the plan stack when you come to pop from it. Maybe PopPlan(plan *) that would check it actually is the top of the stack. That feels like papering over the issue but at least you could use the mutex that the plan stack has to protect that check.

[DavidSpickett]

Based on @jimingham's reply on #74894, I went digging.

This can happen if you don't succeed in shutting down the private state thread as part of exiting, so that it is still trying to operate on a process that has been finalized.

Not sure why the shutdown ordering seems wrong in the Linux case, however.

And it certainly looks like that's the problem.

Process::DestroyImpl has the following code:

Status error(WillDestroy());
  if (error.Success()) {
    EventSP exit_event_sp;
    if (DestroyRequiresHalt()) {
      error = StopForDestroyOrDetach(exit_event_sp);
    }

    if (m_public_state.GetValue() == eStateStopped) {
      // Ditch all thread plans, and remove all our breakpoints: in case we
      // have to restart the target to kill it, we don't want it hitting a
      // breakpoint... Only do this if we've stopped, however, since if we
      // didn't manage to halt it above, then we're not going to have much luck
      // doing this now.
      m_thread_list.DiscardThreadPlans();
      DisableAllBreakpointSites();
    }

    error = DoDestroy();
    if (error.Success()) {
      DidDestroy();
      StopPrivateStateThread();
    }
    <...>

I think that StopForDestroyOrDetach is sending an interrupt which is stopping the process and means that Thread::ShouldStop runs. I assume in the private thread, but not sure.

Thread::ShouldStop starts with:

ThreadPlan *current_plan = GetCurrentPlan();

Which does use a mutex to lock the thread plan stack, but only for the duration of GetCurrentPlan. So at the time the current plan is the top of the stack.

Meanwhile, the main thread calls m_thread_list.DiscardThreadPlans() which deletes that plan, then when Thread::ShouldStop tries to pop a plan, we crash.

Which we already knew but this is the exact point it happens.

On to solutions, I haven't found one. I've tried a few.

1. Adding a way to lock the thread plan stack without calling a method. So the whole of Thread::ShouldStop would lock the plan stack, and unlock it when it was done.

This seems to be what you'd want, but it will deadlock in some scenario. I think that scenario is the very situation we're trying to fix.

It feels like the correct fix given that the thread plan stack locking is, shall we say, patchy, as it is. But I can't say exactly what causes the deadlock so it could be my mistake here.

2. Stopping the private thread before clearing the thread plans.

This is in fact what Process::Detach does, but when I tried a simple port of it to Process::DestroyImpl it did not make a difference. Eventually the test would crash in the same way. It's possible that it makes it more rare, but hard to tell given that I have to hammer the test sometimes, and sometimes it fails right away.

--- a/lldb/source/Target/Process.cpp
+++ b/lldb/source/Target/Process.cpp
@@ -3337,6 +3337,16 @@ Status Process::DestroyImpl(bool force_kill) {
       // breakpoint... Only do this if we've stopped, however, since if we
       // didn't manage to halt it above, then we're not going to have much luck
       // doing this now.
+
+      if (exit_event_sp) {
+        // We're about to remove thread plans that the private state thread
+        // may be in the middle of using to handle the interrupt that StopForDestroyOrAttach just sent.
+        StopPrivateStateThread();
+        // For the private thread to respond to the request to stop it, it must
+        // have got back into its main loop and will not be using the thread plans
+        // any more.
+      }
+
       m_thread_list.DiscardThreadPlans();
       DisableAllBreakpointSites();
     }

As far as I can tell, when we return from StopPrivateStateThread, the private thread should be closed. We send it a message to stop, it will find that in its main loop and then we join on it to make sure it's stopped.

Meaning, if the private thread was busy dealing with thread plans, it would have to finish that work to acknowledge our message to it. So StopPrivateThread functions as "wait until the private thread is done doing stuff".

Though why this doesn't fix the test I'm not sure.

Possibly there is a scenario where there is no exit_event_sp, but the crash scenario still happens. I tried always stopping the private thread (regardless of exit_event_sp value), but this failed 2 tests that deal with exit events.

I'm currently looping the test case with this version to see if it is a partial fix.

Failed Tests (2):
  lldb-api :: functionalities/gdb_remote_client/TestProcessConnect.py
  lldb-api :: functionalities/gdb_remote_client/TestPty.py

This happened on Arm and Arm64 so this isn't an Arm specific event timing issue. Otherwise, I wasn't able to explain it.

[jimingham]

If you just change the test to explicitly kill the processes, does that remove this flakiness? Given what you're seeing, I'm guessing it will. You could do something like:

--- a/lldb/test/API/python_api/global_module_cache/TestGlobalModuleCache.py
+++ b/lldb/test/API/python_api/global_module_cache/TestGlobalModuleCache.py
@@ -97,6 +97,11 @@ class GlobalModuleCacheTestCase(TestBase):
         self.copy_to_main(two_print_path, main_c_path)
 
         self.build(dictionary={"C_SOURCES": main_c_path, "EXE": "a.out"})
+
+        # Keep track of the processes so we can kill them at the end.
+        process = None
+        process2 = None
+        
         error = lldb.SBError()
         if one_debugger:
             if one_target:
@@ -140,6 +145,13 @@ class GlobalModuleCacheTestCase(TestBase):
         # Even if this fails, MemoryPressureDetected should fix this.
         lldb.SBDebugger.MemoryPressureDetected()
         error_after_mpd = self.check_image_list_result(num_a_dot_out_entries, 1)
+
+        # We aren't using the processes anymore, so get rid of them here:
+        if process:
+            process.Kill()
+        if process2:
+            process2.Kill()
+
         fail_msg = ""
         if error != "":
             fail_msg = "Error before MPD: " + error
@@ -148,6 +160,7 @@ class GlobalModuleCacheTestCase(TestBase):
             fail_msg = fail_msg + "\nError after MPD: " + error_after_mpd
         if fail_msg != "":
             self.fail(fail_msg)
+        
 
     def check_image_list_result(self, num_a_dot_out, num_main_dot_o):
         # Check the global module list, there should only be one a.out, and if we are

If that makes the test stable again, that would be an interesting datapoint. After all, there are lots of tests that make processes and then just exit the test and let the test suite tear down the debugger and the processes in the process. So what's different about the teardown of this test compared to the others that don't explicitly kill off their processes before exiting...

[DavidSpickett]

If you just change the test to explicitly kill the processes, does that remove this flakiness? Given what you're seeing, I'm guessing it will.

I will try this.

On the subject of the fixes I tried before, this version crashes quite often:

+      if (exit_event_sp) {
+        // We're about to remove thread plans that the private state thread
+        // may be in the middle of using to handle the interrupt that StopForDestroyOrAttach just sent.
+        StopPrivateStateThread();
+        // For the private thread to respond to the request to stop it, it must
+        // have got back into its main loop and will not be using the thread plans
+        // any more.
+      }

But does not fail any tests.

If instead, exit_event_sp is not checked, the test does not crash (did not crash in 2 days of running in a loop). It does however fail those 2 test suite tests that expect an exit event.

So the way forward there would be to find out what specific event is being dropped, and whether it can be saved and replayed or delayed in some way to keep the existing behaviour.