Merge pull request #982 from shorepine/fix-49-day-clock-wrap

Fix the 49.7-day millisecond-clock rollover

Author: dpwe

.gitignore

@@ -3,6 +3,7 @@ amy-example
 amy-message
 failed_tests.txt
 tests/tst
+tests/test_clock_wrap
 amy-piano
 src/build/
 *.DS_Store*

Makefile

@@ -45,7 +45,7 @@ EMSCRIPTEN_OPTIONS = -s WASM=1 --bind \
 -s ASYNCIFY -s ASYNCIFY_STACK_SIZE=128000
 PYTHON = python3
 
-.PHONY: default all clean amy-module test web deploy-web godot-api c-api check-c-api
+.PHONY: default all clean amy-module test ctest web deploy-web godot-api c-api check-c-api
 
 default: $(TARGET)
 all: default
@@ -102,6 +102,21 @@ amy-piano: $(OBJECTS) src/amy-piano.o
 amy-message: $(OBJECTS) src/amy-message.o
 	$(CC) $(CFLAGS) $(OBJECTS) src/amy-message.o -Wall $(LIBS) -o $@
 
+# Plain C tests for things the audio-rendering suite can't reach -- e.g. clock
+# rollovers 50 days out, which you can only hit by fast-forwarding the counters.
+CTESTS = tests/test_clock_wrap
+
+# Static pattern rules, so these win over the generic %.o: %.c above (which
+# would compile without -Isrc and fail to find amy.h).
+$(addsuffix .o,$(CTESTS)): %.o: %.c $(HEADERS) src/patches.h
+	$(CC) $(CFLAGS) -Isrc -c $< -o $@
+
+$(CTESTS): %: %.o $(OBJECTS)
+	$(CC) $(CFLAGS) $(OBJECTS) $< -Wall $(LIBS) -o $@
+
+ctest: $(CTESTS)
+	@for t in $(CTESTS); do echo "== $$t"; ./$$t || exit 1; done
+
 amy-module: amy-example
 	${EXTRA_PIP_ENV} ${PYTHON} -m pip install -r requirements.txt; touch src/amy.c; ${EXTRA_PIP_ENV} ${PYTHON} -m pip install . --force-reinstall --no-deps; cd ..
 
@@ -172,3 +187,4 @@ clean:
 	-rm -r src/patches.h
 	-rm -f amy/constants.py
 	-rm -f $(TARGET)
+	-rm -f tests/*.o $(CTESTS)

src/amy.c

@@ -588,9 +588,12 @@ void add_delta_to_queue(struct delta *d, struct delta **queue) {
         return;
     }
 
-    // insert it into the sorted list for fast playback
+    // insert it into the sorted list for fast playback.
+    // Wrap-relative: at the 49.7-day rollover a note_off scheduled a few ms out
+    // has a tiny d->time while its own note_on is still near 2^32, so a plain
+    // `>=` sorted the release ahead of the attack and the note droned forever.
     struct delta **pptr = queue;
-    while(*pptr && d->time >= (*pptr)->time)
+    while(*pptr && AMY_TIME_GEQ(d->time, (*pptr)->time))
         pptr = &(*pptr)->next;
     new_d->next = *pptr;
     *pptr = new_d;
@@ -2009,7 +2012,7 @@ void amy_execute_delta() {
 
     // find any deltas that need to be played from the (in-order) queue
     struct delta *d = amy_global.delta_queue;
-    if(d && sysclock >= d->time) {
+    if(d && AMY_TIME_GEQ(sysclock, d->time)) {
         play_delta(d);
         d = delta_release(d);
         amy_global.delta_qsize--;
@@ -2037,7 +2040,7 @@ void amy_execute_deltas() {
 
     // find any deltas that need to be played from the (in-order) queue
     struct delta *d = amy_global.delta_queue;
-    while(d && sysclock >= d->time) {
+    while(d && AMY_TIME_GEQ(sysclock, d->time)) {
         play_delta(d);
         d = delta_release(d);
         amy_global.delta_qsize--;

src/amy.h

@@ -998,6 +998,15 @@ amy_config_t amy_default_config();
 void amy_clear_event(amy_event *e);
 amy_event amy_default_event();
 uint32_t amy_sysclock();
+uint64_t amy_sysclock64();
+
+// Wrap-relative comparison for the 32-bit millisecond clock. amy_sysclock()
+// rolls over every 2^32 ms (49.7 days), so a plain `now >= then` strands every
+// queued event at the rollover -- and, because the delta queue is time-sorted,
+// misorders a note_off ahead of its own note_on, leaving the note stuck on.
+// Valid as long as the two times are within 2^31 ms (~24.8 days) of each other,
+// which holds for everything AMY schedules.
+#define AMY_TIME_GEQ(a, b)  ((int32_t)((uint32_t)(a) - (uint32_t)(b)) >= 0)
 // CPU overload detection: platform render loops call this once per block.
 void amy_overload_check(uint32_t render_us);
 void amy_overload_failsafe();

src/api.c

@@ -233,12 +233,23 @@ output_sample_type * amy_simple_fill_buffer() {
 
 
 // on all platforms, sysclock is based on total samples played, using audio out (i2s or etc) as system clock
-uint32_t amy_sysclock() {
-    // Time is returned in integer milliseconds; wraps at 2^32 ms = 49.7 days.
+// 64-bit milliseconds since start. total_blocks is u32 and increments once per
+// AMY_BLOCK_SIZE samples, so this does not wrap for ~219 years at 44.1 kHz.
+// Anything that stores an absolute deadline and compares it later must use this
+// rather than amy_sysclock(); see sequencer_check_and_fill().
+uint64_t amy_sysclock64() {
     // Integer math: computing this through float quantizes the clock once
     // total samples exceed the 24-bit mantissa (~6 min at 48 kHz), and the
     // u32 samples-domain multiply wrapped after 2^32 samples (~25 h).
-    return (uint32_t)(((uint64_t)amy_global.total_blocks * (AMY_BLOCK_SIZE * 1000u)) / AMY_SAMPLE_RATE);
+    return ((uint64_t)amy_global.total_blocks * (AMY_BLOCK_SIZE * 1000u)) / AMY_SAMPLE_RATE;
+}
+
+uint32_t amy_sysclock() {
+    // Time is returned in integer milliseconds; wraps at 2^32 ms = 49.7 days.
+    // This is the wire/event-facing clock and stays 32-bit for compatibility.
+    // Consumers compare event times wrap-relative (AMY_TIME_GEQ), so the
+    // rollover is handled rather than avoided.
+    return (uint32_t)amy_sysclock64();
 }
 
 
@@ -290,6 +301,10 @@ void amy_add_event(amy_event *e) {
         uint32_t playback_time = amy_sysclock();
         if(AMY_IS_SET(e->time)) playback_time = e->time;
         playback_time += amy_global.latency_ms;
+        // UINT32_MAX is the "unset" sentinel for a u32 field, and the clock does
+        // land on it for one millisecond every 49.7 days. Nudge by 1ms so the
+        // event doesn't read back as having no time at all.
+        if(AMY_IS_UNSET(playback_time)) playback_time++;
         e->time = playback_time;
         amy_event_to_deltas_queue(e, 0, &amy_global.delta_queue);
     }

src/patches.c

@@ -974,6 +974,8 @@ uint8_t patches_voices_for_event(amy_event *e, uint16_t voices[]) {
             uint32_t playback_time = amy_sysclock();
             if(AMY_IS_SET(e->time)) playback_time = e->time;
             playback_time += instrument_noteon_delay_ms(e->synth);
+            // See amy_process_event(): dodge the u32 "unset" sentinel.
+            if(AMY_IS_UNSET(playback_time)) playback_time++;
             e->time = playback_time;
             //fprintf(stderr, "synth %d note %d delay %d time %d\n", e->synth, (int)roundf(e->midi_note), instrument_noteon_delay_ms(e->synth), e->time);
         }

src/sequencer.c

@@ -71,7 +71,7 @@ void sequencer_recompute() {
     // 60000000 us/min / (bpm * ticks per beat); keep it single-precision -
     // unsuffixed double literals pull in software double emulation on 32-bit.
     amy_global.us_per_tick = (uint32_t) (60000000.0f / (amy_global.tempo * (float)AMY_SEQUENCER_PPQ));
-    amy_global.next_amy_tick_us = (((uint64_t)amy_sysclock()) * 1000L) + (uint64_t)amy_global.us_per_tick;
+    amy_global.next_amy_tick_us = (amy_sysclock64() * 1000ULL) + (uint64_t)amy_global.us_per_tick;
 }
 
 static void sequencer_process_tick(void) {
@@ -145,7 +145,7 @@ void sequencer_midi_start() {
     }
     // Reset the tick timer to now so sequencer_check_and_fill doesn't try to
     // catch up all the ticks that elapsed while stopped.
-    amy_global.next_amy_tick_us = (uint64_t)amy_sysclock() * 1000L;
+    amy_global.next_amy_tick_us = amy_sysclock64() * 1000ULL;
     sequencer_running = true;
     midi_clock_out_start();  // tell downstream slaves, if we're the clock master
 }
@@ -173,7 +173,7 @@ void sequencer_external_clock_disable() {
     sequencer_running = true;
     // Re-anchor the tick timer to now so sequencer_check_and_fill doesn't try to
     // replay every tick that elapsed while we were on external clock.
-    amy_global.next_amy_tick_us = (uint64_t)amy_sysclock() * 1000L;
+    amy_global.next_amy_tick_us = amy_sysclock64() * 1000ULL;
 }
 
 uint8_t sequencer_add_event(amy_event *e) {
@@ -220,7 +220,12 @@ void sequencer_check_and_fill() {
     // If we've fallen behind by more than 1 second (e.g. sequencer was stopped
     // and restarted, or a long blocking operation occurred), skip ahead instead
     // of processing hundreds of backed-up ticks at once.
-    uint64_t now_us = (uint64_t)amy_sysclock() * 1000L;
+    // next_amy_tick_us is a 64-bit accumulator, so it must be anchored to the
+    // 64-bit clock. Seeding it from the 32-bit amy_sysclock() used to kill the
+    // sequencer permanently at the 49.7-day rollover: now_us collapsed to ~0
+    // while next_amy_tick_us stayed at ~4.3e12, and neither the catch-up guard
+    // (which only handles falling behind) nor the tick loop could ever fire.
+    uint64_t now_us = amy_sysclock64() * 1000ULL;
     if (now_us > amy_global.next_amy_tick_us + 1000000ULL) {
         amy_global.next_amy_tick_us = now_us;
     }

tests/test_clock_wrap.c

@@ -0,0 +1,179 @@
+// Regression test for the 49.7-day millisecond-clock rollover.
+//
+// amy_sysclock() is u32 milliseconds, so it wraps every 2^32 ms = 49.71 days.
+// Two things used to break at that instant, and neither is reachable from the
+// audio-rendering test suite because you cannot render 50 days of samples --
+// so this test fast-forwards amy_global.total_blocks instead.
+//
+//   1. sequencer_check_and_fill() anchored its 64-bit next_amy_tick_us
+//      accumulator to the 32-bit clock. At the rollover now_us collapsed to ~0
+//      while next_amy_tick_us stayed at ~4.3e12 us, so the catch-up guard
+//      (which only handles falling *behind*) and the tick loop both went quiet
+//      and the sequencer stopped forever -- taking tulip.defer() and every
+//      seq callback with it.
+//
+//   2. The delta queue is time-sorted with a plain `>=`. A note_off scheduled
+//      a few ms past the rollover has a tiny d->time while its own note_on is
+//      still near 2^32, so the release sorted ahead of the attack, fired
+//      first, and left the note droning forever.
+//
+// Build/run with `make ctest`.
+
+#include <stdio.h>
+#include <stdint.h>
+#include <inttypes.h>
+#include "amy.h"
+#include "sequencer.h"
+
+static int failures = 0;
+
+#define CHECK(cond, fmt, ...) do {                                        \
+    if (cond) { printf("  ok   " fmt "\n", ##__VA_ARGS__); }              \
+    else { printf("  FAIL " fmt "\n", ##__VA_ARGS__); failures++; }       \
+} while (0)
+
+// Blocks per second of synthesized audio.
+static const uint64_t BPS = AMY_SAMPLE_RATE / AMY_BLOCK_SIZE;
+
+static uint32_t ticks_seen = 0;
+static void count_tick(uint32_t t) { (void)t; ticks_seen++; }
+
+// Park the synth clock at an arbitrary uptime without rendering our way there.
+static void set_clock_ms(uint64_t ms) {
+    amy_global.total_blocks = (uint32_t)((ms * AMY_SAMPLE_RATE) / (1000ULL * AMY_BLOCK_SIZE));
+    amy_global.total_samples = amy_global.total_blocks * AMY_BLOCK_SIZE;
+}
+
+// Run the real render loop for `secs` of audio. amy_simple_fill_buffer() does
+// execute_deltas -> render -> fill, and the fill is what advances total_blocks,
+// so this drives the clock exactly the way the audio callback does. Rendering
+// (not delta execution) is also what retires a finished note to SYNTH_OFF.
+static uint32_t advance_secs(double secs) {
+    ticks_seen = 0;
+    uint64_t n = (uint64_t)(BPS * secs);
+    for (uint64_t i = 0; i < n; i++) amy_simple_fill_buffer();
+    return ticks_seen;
+}
+
+static int osc_audible(int osc) {
+    return synth[osc] != NULL && synth[osc]->status == SYNTH_AUDIBLE;
+}
+
+static void note_on(int osc, float midi_note, uint32_t time) {
+    amy_event e = amy_default_event();
+    e.time = time; e.osc = osc; e.wave = SINE; e.velocity = 1.0f; e.midi_note = midi_note;
+    amy_add_event(&e);
+}
+
+static void note_off(int osc, uint32_t time) {
+    amy_event e = amy_default_event();
+    e.time = time; e.osc = osc; e.velocity = 0;
+    amy_add_event(&e);
+}
+
+// 2^32 ms -- the instant amy_sysclock() rolls over.
+#define WRAP_MS 4294967296ULL
+
+static void test_sequencer_survives_wrap(void) {
+    printf("sequencer keeps ticking across the 49.7-day rollover\n");
+    amy_global.config.amy_external_sequencer_hook = count_tick;
+
+    double expected_per_10s = 10.0 * 1000000.0 / amy_global.us_per_tick;
+
+    set_clock_ms(WRAP_MS - 30000);       // 30 s out
+    sequencer_recompute();
+    uint32_t before = advance_secs(10);
+    CHECK(before > expected_per_10s * 0.9,
+          "before wrap: %u ticks/10s (expected ~%.0f)", before, expected_per_10s);
+
+    advance_secs(25);                     // cross it
+    CHECK(amy_sysclock() < 30000, "sysclock rolled over: now %u", amy_sysclock());
+    CHECK(amy_sysclock64() > WRAP_MS, "64-bit clock kept counting: %" PRIu64, amy_sysclock64());
+
+    uint32_t after = advance_secs(10);
+    CHECK(after > expected_per_10s * 0.9,
+          "after wrap:  %u ticks/10s (expected ~%.0f)", after, expected_per_10s);
+
+    uint32_t much_later = advance_secs(60);
+    CHECK(much_later > expected_per_10s * 5.9,
+          "wrap+1min:   %u ticks/60s (expected ~%.0f)", much_later, expected_per_10s * 6);
+
+    amy_global.config.amy_external_sequencer_hook = NULL;
+}
+
+static void test_no_stuck_note_across_wrap(void) {
+    printf("a note whose note_off lands past the rollover still stops\n");
+
+    set_clock_ms(WRAP_MS - 500);
+    uint32_t t = amy_sysclock();
+    note_on(0, 64, t);
+    note_off(0, t + 1000);               // this time value wraps past 2^32
+    CHECK(t + 1000 < t, "note_off time wrapped as intended (on=%u off=%u)", t, t + 1000);
+
+    advance_secs(0.2);
+    CHECK(osc_audible(0), "note is sounding before the wrap");
+
+    advance_secs(2.0);                    // well past both the wrap and the note_off
+    CHECK(!osc_audible(0), "note stopped after the wrap (not stuck on)");
+}
+
+static void test_scheduling_works_after_wrap(void) {
+    printf("scheduling still works once the clock has rolled over\n");
+
+    set_clock_ms(WRAP_MS + 5000);
+    note_on(1, 60, amy_sysclock());
+    advance_secs(0.2);
+    CHECK(osc_audible(1), "immediate note_on sounds");
+
+    note_off(1, amy_sysclock());
+    advance_secs(0.5);
+    CHECK(!osc_audible(1), "immediate note_off stops it");
+
+    note_on(2, 67, amy_sysclock() + 500);
+    advance_secs(0.2);
+    CHECK(!osc_audible(2), "note scheduled +500ms has not fired yet");
+    advance_secs(0.6);
+    CHECK(osc_audible(2), "note scheduled +500ms fired on time");
+}
+
+static void test_sustained_note_across_sample_wrap(void) {
+    // amy_global.total_samples is u32 and wraps every 2^32 samples (27.05 h at
+    // 44.1 kHz). Envelope math is `total_samples - note_on_clock` in u32, which
+    // is modular-correct, so this should be a non-event -- pin that down.
+    printf("held note is unaffected by the 27-hour total_samples wrap\n");
+
+    uint32_t wrap_blocks = (uint32_t)((1ULL << 32) / AMY_BLOCK_SIZE);
+    amy_global.total_blocks = wrap_blocks - (uint32_t)(BPS * 2);
+    amy_global.total_samples = amy_global.total_blocks * AMY_BLOCK_SIZE;
+
+    note_on(3, 69, amy_sysclock());
+    advance_secs(1.0);
+    CHECK(osc_audible(3), "sounding before the sample-counter wrap");
+    advance_secs(3.0);
+    CHECK(amy_global.total_samples < BPS * AMY_BLOCK_SIZE * 4, "total_samples wrapped");
+    CHECK(osc_audible(3), "still sounding after the sample-counter wrap");
+    note_off(3, amy_sysclock());
+    advance_secs(1.0);
+}
+
+// examples.c calls this; the example binaries each define their own. This test
+// drives the clock by hand and never sleeps, so nothing here should reach it.
+void delay_ms(uint32_t ms) { (void)ms; }
+
+int main(void) {
+    amy_config_t c = amy_default_config();
+    c.features.startup_bleep = 0;
+    amy_start(c);
+
+    test_sequencer_survives_wrap();
+    test_no_stuck_note_across_wrap();
+    test_scheduling_works_after_wrap();
+    test_sustained_note_across_sample_wrap();
+
+    if (failures) {
+        printf("\n%d check(s) FAILED\n", failures);
+        return 1;
+    }
+    printf("\nall clock-wrap checks passed\n");
+    return 0;
+}