Hi Philipp,
Sorry for not getting back to you sooner. I don’t think there’s anything wrong with timebases. Instead, here’s what I believe is going on:
When a task system state finishes executing its actions, it starts testing each of its transitions, in the order given in the experiment file. If one of the tests passes, the state system immediately moves on to the next state. If none of the tests pass, the main experiment thread requests to sleep for 500us, and then the transition testing process repeats.
I say “requests to sleep”, because there’s no guarantee on when the operating system will wake the thread (other than that it will be at least 500us after the request was made). To demonstrate how this works in practice, I made a version of your experiment that, instead of using a task system and timer transition, creates a scheduled action (action/schedule) that updates the variable every millisecond. The attached plot scheduled_action.png is a histogram of the difference between the actual and expected time of each update. The differences range from about 25us up to almost 250us. Since the system was mostly idle when I ran the test, this gives a sense of the best-case scenario for the thread-wakeup delay; if many threads and/or processes were competing for CPU time, the delay could be longer.
The plot scheduled_action_deltas.png uses the same test data but plots the difference in execution time from one update to the next. The deltas are clearly centered at 1ms and extend to +/- 200us, which jibes with the ~200us variability seen in the previous plot. This is probably the plot you expected when you initially ran your test.
To demonstrate what happens when this inherent variability is added to the 500us wait cycle, I created another version of your experiment that, instead of using timer transitions, uses action/wait with a timebase. (Used in this way, wait actions employ the same test-sleep-repeat mechanism as transitions, but they’re simpler because they don’t need to wait for another thread to expire the timer.) The plot direct_wait.png shows the difference between the actual and expected update times for one run, while direct_wait_deltas.png shows the difference in execution time from one update to the next for the same run.
At first glance, the bimodal distribution in the second plot (which looks much like the one you made) seems strange, but I think it makes sense when you consider the time intervals involved (1ms between variable updates, 500us between wait-expiration tests):
-
The second (and larger) grouping, centered around 1200us, represents updates where the wait action waited through two 500us pauses. This is the more typical case, where the wait action starts close to on time, and less than 1ms has elapsed when the first 500us pause completes. The reason the group is centered at 1200us (instead of 1000) is that each 500us pause is subject to the thread-wakeup delay discussed previously, which can extend each pause up to ~700us.
-
The first (and smaller) grouping, centered around ~625us, represents updates where the wait action waited through just one 500us period. This is the less common case where, due to some combination of the previous update finishing late and the 500us pause running long, 1ms has already elapsed when the first 500us pause completes.
As I mentioned above, using a timer transition complicates things a bit more and leads to results like those shown in timer_wait.png and timer_wait_deltas.png. When you start a timer, MWorks creates a new thread, which immediately requests to sleep for the duration of the timer; when the thread wakes up, it marks the timer expired, then terminates. This means that waiting on a timer transition introduces another thread-wakeup delay (in the timer-expiration thread) in addition to the one associated with the 500us pause(s). The plots bear this out: Compared with the “direct wait” ones, the timer waits are similarly distributed, but the time ranges are shifted farther from zero.
To be honest, I’ve had a hard time reasoning through these results and have struggled to explain them clearly. I hope what I’ve written makes sense, but if it doesn’t (or you disagree with my conclusions), please say so.
Also, I think some relatively simple changes to MWorks – namely, shortening the 500us pause to a shorter interval, and adding a “wait” transition that doesn’t rely on a separate thread – can eliminate the strangeness in the “direct” and timer wait results and make both look similar to the scheduled action results. I’ve been experimenting with these changes, and the results look good so far. I’ll let you know if/when they make it in to the nightly build.
Cheers,
Chris
