IOSim scheduling bug

[coot]

trafficstars

The prop_timeouts_sim withTimeoutSerialAlternative test fails in SimM; This looks like a scheduling bug in SimM. This test executes something like:

tr :: Trace
tr = runSimTrace runSeriesOfTimeoutsExperiment withTimeoutSerialAlternative [(0.005,0), (0.001, 0.005)]

which basically runs runs the following computation:

do 
  a <- timeout 0.005 (threadDealy 0 $> True)
  b <- timeout 0.001 (threadDealy 0.005 $> False)
  pure (a, b)

And it generates the folloging trace (hand annotated, with some extra debugging say commands). ThreadId 0 is the application thread which excutes the threadDealy commands, and ThreadId 1 is the monitoring thread.

(Time 0s,ThreadId 0,Just "main",EventTxCommitted [] [TVarId 0])                        -- thread0 is the thread that runs two timedout dealys, thread1 is the monitoring thread
(Time 0s,ThreadId 0,Just "main",EventTxCommitted [] [TVarId 1])
(Time 0s,ThreadId 0,Just "main",EventThreadForked (ThreadId 1))
(Time 0s,ThreadId 0,Just "main",EventTxCommitted [] [TVarId 2])
(Time 0s,ThreadId 1,Nothing,EventTxBlocked [TVarId 0])
(Time 0s,ThreadId 0,Just "main",EventTxCommitted [TVarId 0] [])
(Time 0s,ThreadId 1,Nothing,EventTxWakeup [TVarId 0])
(Time 0s,ThreadId 1,Nothing,EventTxCommitted [TVarId 0] [])
(Time 0s,ThreadId 0,Just "main",EventSay "TIMEOUT: OVERWRITE_MONITOR_CHAN")               -- first timeout notifies the monitor thread
(Time 0s,ThreadId 0,Just "main",EventTimerCreated (TimeoutId 0) (TVarId 3) (Time 0s))     -- it creates its timer (for `threadDelay`)
(Time 0s,ThreadId 0,Just "main",EventTxBlocked [TVarId 3])
(Time 0s,ThreadId 1,Nothing,EventSay "MONITOR: READ CHAN")                                -- montior wakes up
(Time 0s,ThreadId 1,Nothing,EventTimerCreated (TimeoutId 1) (TVarId 4) (Time 0.005s))     -- and creates its timer
(Time 0s,ThreadId 1,Nothing,EventTxBlocked [TVarId 4])
(Time 0s,ThreadId (-1),Just "timer",EventTimerExpired (TimeoutId 0))                      -- threadDelays timer expires (`Time 0s`)
(Time 0s,ThreadId 0,Just "main",EventTxWakeup [TVarId 3])
(Time 0s,ThreadId 0,Just "main",EventTxCommitted [] [])
(Time 0s,ThreadId 0,Just "main",EventSay "TIMEOUT: ACTION DONE")                          -- action is done
(Time 0s,ThreadId 0,Just "main",EventTxCommitted [TVarId 2] [])
(Time 0s,ThreadId 0,Just "main",EventSay "TIMEOUT: FIRED False")                          -- timeout not fired
(Time 0s,ThreadId 0,Just "main",EventSay "((0.005s,0s),True)")
(Time 0s,ThreadId 0,Just "main",EventTxCommitted [] [TVarId 5])
(Time 0s,ThreadId 0,Just "main",EventTxCommitted [TVarId 0] [])
(Time 0s,ThreadId 0,Just "main",EventSay "TIMEOUT: OVERWRITE_MONITOR_CHAN")               -- next experiment starts
(Time 0s,ThreadId 0,Just "main",EventTimerCreated (TimeoutId 2) (TVarId 6) (Time 0.005s)) -- creates its own timer
(Time 0s,ThreadId 0,Just "main",EventTxBlocked [TVarId 6])
                                                                                          -- time advances, but the monitoring thread was not woken up!
                                                                                          -- when we will wake up, the action timer will fire (since it's the next registered timer's timer) 
                                                                                          -- instead the montoring thread should wake up here
(Time 0.005s,ThreadId (-1),Just "timer",EventTimerExpired (TimeoutId 1))
(Time 0.005s,ThreadId (-1),Just "timer",EventTimerExpired (TimeoutId 2))
(Time 0.005s,ThreadId 1,Nothing,EventTxWakeup [TVarId 4])
(Time 0.005s,ThreadId 0,Just "main",EventTxWakeup [TVarId 6])
(Time 0.005s,ThreadId 1,Nothing,EventTxCommitted [] [])
(Time 0.005s,ThreadId 0,Just "main",EventTxCommitted [] [])
(Time 0.005s,ThreadId 1,Nothing,EventTxCommitted [] [])
(Time 0.005s,ThreadId 0,Just "main",EventSay "TIMEOUT: ACTION DONE")
(Time 0.005s,ThreadId 0,Just "main",EventTxCommitted [TVarId 5] [])
(Time 0.005s,ThreadId 1,Nothing,EventSay "MONITOR: CANCELLED True")
(Time 0.005s,ThreadId 1,Nothing,EventTxCommitted [TVarId 0] [])
(Time 0.005s,ThreadId 0,Just "main",EventSay "TIMEOUT: FIRED False")
(Time 0.005s,ThreadId 0,Just "main",EventSay "((0.001s,0.005s),False)")
(Time 0.005s,ThreadId 0,Just "main",EventThrowTo AsyncCancelled (ThreadId 1))
(Time 0.005s,ThreadId 0,Just "main",EventTxBlocked [TVarId 1])
(Time 0.005s,ThreadId 1,Nothing,EventThrow AsyncCancelled)
(Time 0.005s,ThreadId 1,Nothing,EventTxCommitted [TVarId 1] [])
(Time 0.005s,ThreadId 0,Just "main",EventTxWakeup [TVarId 1])
(Time 0.005s,ThreadId 0,Just "main",EventTxCommitted [] [])
(Time 0.005s,ThreadId 1,Nothing,EventThreadFinished)
(Time 0.005s,ThreadId 0,Just "main",EventThreadFinished)