Intermittent sst-core test failures on very fast systems

[kpgriesser]

Our newer macOS/clang20+ platforms are significantly faster than our other test platforms and occasionally fail for these two tests:

sst-test-core -e test_RealTime_SIGALRM_multiaction
sst-test-core -e test_RealTime_heartbeat

While currently this is a minor annoyance it could become a bigger problem as more tests are added that follow the same design pattern. We haven't found a way to make this repeatable. We could spend time trying to instrument the code to capture a failure but decided it's not a priority at this point.

Maybe Gwen can figure it out through inspection :)

[kpgriesser]

I was able to reproduce a failure by running the following script for about 20 minutes:

#!/bin/bash -x

while true; do
  sst-test-core -f -w "*_R*" | tee log
  grep -q FAILED log
  if [ $? -eq 0 ]; then
   echo FAILED
   exit 1
  else
   echo PASSED
  fi
done

Note: I'm running suites starting with *_R*. I wasn't able to reproduce the failure by running the individual test repeatedly.

The detailed test command is
sst --exit-after=6s --sigalrm=sst.rt.heartbeat(interval=1s);sst.rt.status.core(interval=2s) /Users/dev/kgriesser/work/sst-core/tests/test_RealTime.py

A side by side diff follows:

#  right side passing, left side failing 
$ diff  -y -W 200 passes/sst_test_outputs/run_data/test_RealTime_SIGALRM_multiaction.out failures/sst_test_outputs/run_data/test_RealTime_SIGALRM_multiaction.out > test_RealTime_SIGALRM_multiaction.notes

        CurrentSimCycle:  23810000								   |		CurrentSimCycle:  10619000
	CurrentSimCycle:  46904000								   |		CurrentSimCycle:  19421000
	CurrentSimCycle:  70545000								   |	# Simulation Heartbeat: Simulated Time 5.347 us (Real CPU time since last period 1.00965 seconds
# Simulation Heartbeat: Simulated Time 11.447 us (Real CPU time since last period 1.00478 second   <	
	Max mempool usage:               11.6654 MB								Max mempool usage:               11.6654 MB
	Global mempool usage:            11.6654 MB								Global mempool usage:            11.6654 MB
	Global active activities         5 activities								Global active activities         5 activities
	Max TimeVortex depth:            102 entries								Max TimeVortex depth:            102 entries
# Simulation Heartbeat: Simulated Time 23.81 us (Real CPU time since last period 1.00782 seconds   |	# Simulation Heartbeat: Simulated Time 10.619 us (Real CPU time since last period 1.00542 second
	Max mempool usage:               11.6654 MB								Max mempool usage:               11.6654 MB
	Global mempool usage:            11.6654 MB								Global mempool usage:            11.6654 MB
	Global active activities         5 activities								Global active activities         5 activities
	Max TimeVortex depth:            102 entries								Max TimeVortex depth:            102 entries
# Simulation Heartbeat: Simulated Time 35.298 us (Real CPU time since last period 1.00885 second   |	# Simulation Heartbeat: Simulated Time 15.883 us (Real CPU time since last period 1.00784 second
	Max mempool usage:               11.6654 MB								Max mempool usage:               11.6654 MB
	Global mempool usage:            11.6654 MB								Global mempool usage:            11.6654 MB
	Global active activities         5 activities								Global active activities         5 activities
	Max TimeVortex depth:            102 entries								Max TimeVortex depth:            102 entries
# Simulation Heartbeat: Simulated Time 46.904 us (Real CPU time since last period 1.00783 second   <	
	Max mempool usage:               11.6654 MB						   <	
	Global mempool usage:            11.6654 MB						   <	
	Global active activities         5 activities						   <	
	Max TimeVortex depth:            102 entries						   <	
# Simulation Heartbeat: Simulated Time 58.603 us (Real CPU time since last period 1.00883 second   <	
	Max mempool usage:               11.6654 MB						   <	
	Global mempool usage:            11.6654 MB						   <	
	Global active activities         5 activities						   <	
	Max TimeVortex depth:            102 entries						   <	
EXIT-AFTER TIME REACHED; SHUTDOWN (0,0)!								EXIT-AFTER TIME REACHED; SHUTDOWN (0,0)!
# Simulated time:                  70.545 us							   |	# Simulated time:                  19.421 us
# Simulation Heartbeat: Simulated Time 70.545 us (Real CPU time since last period 1.00786 second   |	# Simulation Heartbeat: Simulated Time 19.421 us (Real CPU time since last period 13.33412 secon
	Max mempool usage:               11.6654 MB								Max mempool usage:               11.6654 MB
	Global mempool usage:            11.6654 MB								Global mempool usage:            11.6654 MB
	Global active activities         105 activities						   |		Global active activities         5 activities
	Max TimeVortex depth:            102 entries								Max TimeVortex depth:            102 entries

Observations:

• more time is simulated between each 1s heartbeat for the passing case than in the failing case.
• The total time before shutdown for the passing case is 70us vs 19us for the failing case.

This suggests, contrary to the title, that the failing case is due to a suddenly very slow simulation.
The passing simulation is almost 4x faster than the failing one.

Looking at a known slower system the test passes with 31us simulated which is more than 2x faster than the failing case.

@gvoskuilen (1) Is there any reason not to change this test to exit after 30s instead of 6s ( --exit-after=30s )? The check is only looking for 5 heartbeats. 30s should give us margin for outliers. (2) Thoughts on this: Perhaps a test feature to exit after a certain number of heartbeats would allow us to exit the test quickly most of the time and provide a very long timeout. This would keep test times down and reduce the time spent looking at false fails.

I will test the change to the timeout to see if it fixes the problem for the target systems.

[kpgriesser]

oh wait, let's step back.... setting 6s for 5 heartbeats at 1s intervals seems a very reasonable method to test the 'realtime' timer.

So this may be a real bug. Since we are running single threaded mode we should not have a problem with synchronization points being spread too far apart, right?

Running now with a 30s exit time. Let's see if the failure rears its ugly head. I will likely have to put more instrumentation in the code to figure out what's going on.

For the --exit-after option, does this include the time for the init and setup phases? If so, then I'll place my bets on those phases consuming that time budget. If that's the case, the proposed fix should also help to increase the margin for slow simulation outliers.

[feldergast]

Looking at the code, I believe the exit-after time would start right before the run loop starts. So graph creation, component construction, init() and setup() would have already run before the "clock starts" on the exit.

Also, the timing of the real-time actions with a wall time interval are dependent on the OS, since SST just calls into the OS and the OS returns a SIGALM after the designated time. Any delays would likely be due to the OS.

The biggest reason not to just increase the exit-after time to 30s is that is causes the whole test suite to run longer. Which may or may not be a big deal.

[kpgriesser]

I agree that extending the test time is using a sledge hammer to drive a thumbtack. If the tests suites run in parallel I doubt it will be noticed. If they run serialized, then it is a 48 second hit (2 tests at 30 seconds instead of 6s each).

I think if more tests like this go in I would propose providing some kind of real-time event counter that can be used to exit the test. Then an arbitrarily long timeout wouldn't affect the time for a passing regression.