[chuck-users] release 1.2.1.3: time (still) goes backwards

[Robert Poor]

Ge (and everyone):

I'm very excited about the new 1.2.1.3 release, and will dig more  
deeply into it this week.  And like everyone else, I threw my favorite  
bug tests at it.  One bug -- "time goes backwards" -- lingers.

But the new release goaded me into creating a minimal test case that  
shows the problem.  The real issue is that the scheduler gets confused  
about durations (or times) with fractional samples.

So below is the test file.  It's heavily commented, but the actual  
number of lines of code is small.  Does anyone want to test this on a  
Windows or Linux build?

Enjoy...

- Rob Poor

// ================================================================
// File: fractional_time_test.ck
//
// Summary: test file to demonstrate ChucK timing bug.
// Applies to: chuck version: 1.2.1.3 (and earlier)
// Submitted by: Robert Poor <rdpoor at gmail.com>
//
// Details: Chuck's scheduler does not properly handle times with
// non-zero fractional parts.  In general, a shred that waking from an
// event always sees 'now' with a fractional part of 0.  This has two
// distinct manifestations: if 'now' had a fractional part of less
// than or equal to 0.5 sample, in a waking shred, now is truncated to
// the nearest integer sample.  If now had a fractional part greater
// than 0.5 sample, then the shred will fail to run until now advances
// to the next higher sample, even if yield() is called in the
// triggering shred.
//
// Executing this file following code produces this output:
// ================================================================
// bsh% chuck --version
//
// chuck version: 1.2.1.3 (dracula)
//    exe target: mac os x : powerpc
//    http://chuck.cs.princeton.edu/
//
// bsh% chuck --audio fractional_time_test.ck
// 1.000000 0x5e7160 waiter: okay
// 1.000000 0x5e5fd0 step: okay
// 2.000000 0x5e7160 waiter time: expected 2.300000 but found 2.000000
// 2.300000 0x5e5fd0 step: okay
// 3.600000 0x5e5fd0 step trigger count: expected 3 but found 2
// 4.000000 0x5e7160 waiter time: expected 3.600000 but found 4.000000
// bsh%
// ================================================================

Event trigger;                  // trigger to signal waiter()
int triggered_count;            // # of times waiter() has run
time triggered_time;            // time at which trigger.broadcast()  
called

spork ~ waiter();               // start the waiter shred

// save some preset times.
now + 1.0::samp => time t0;
now + 2.3::samp => time t1;
now + 3.6::samp => time t2;

// t0 = 1.0 sample.  this works normally: step() waits until now==1.0,
// broadcasts on the trigger event and yields.  waiter() then runs at
// the expected time.
step(t0);

// t1 = 2.3 sample.  this fails: step() waits until now==2.3,
// broadcasts on the trigger event and yields.  waiter() then runs,
// but when it runs, 'now' is set to 2.0: time has gone backwards.
step(t1);

// t2 = 3.6 sample.  this fails: step() waits until now==3.6,
// broadcasts on the trigger event and yields.  however, waiter()
// fails to run until now has advanced past 4.0
step(t2);

// make sure everything runs before we quit
1::second => now;

fun void step(time t) {
     t => now;                   // wait for the designated time
     now => triggered_time;      // record wake time
     triggered_count+1 => int i; // record expected trigger count
     trigger.broadcast();        // trigger the waiter() shred
     me.yield();                 // ... and give it time to run
     // verify that the waiter() shred actually ran
     if (triggered_count != i) {
         <<< now, me, "step trigger count: expected", i, "but found",  
triggered_count >>>;
     } else {
         <<< now, me, "step: okay" >>>;
     }
}

fun void waiter() {
     while (true) {
         trigger => now;         // wait for trigger.broadcast() /  
me.yield()
         triggered_count++;      // prove that this shred has run
         // verify that 'now' agrees with expected wake time
         if (now != triggered_time) {
             <<< now, me, "waiter time: expected", triggered_time,  
"but found", now >>>;
         } else {
             <<< now, me, "waiter: okay" >>>;
         }
     }
}

// EOF