Fix audio loop for long-delay keyboard reads.

BUG=chrome-os-partner:7428
TEST=manual

Switch to dev-mode, turn it on, see how long it takes.

With gbb.flags == 1 (factory mode), it should take 2 seconds.
(You'll see a warning on the screen if gbb.flags is nonzero)

With gbb.flags == 0 (after factory install), it should take 30 seconds.
You should hear two beeps at 20 seconds.

Change-Id: I4f14128b87d3482e291b1b40a11a6d27c72c1ad1
Reviewed-on: https://gerrit.chromium.org/gerrit/14534
Tested-by: Bill Richardson <wfrichar@chromium.org>
Reviewed-by: Stefan Reinauer <reinauer@chromium.org>
Commit-Ready: Bill Richardson <wfrichar@chromium.org>

firmware/lib/include/vboot_audio_private.h

@@ -25,12 +25,19 @@ typedef struct VbDevMusic {
 } __attribute__((packed)) VbDevMusic;
 
 struct VbAudioContext {
-  uint32_t note_count;
+  /* note tracking */
   VbDevMusicNote* music_notes;
-  int free_notes_when_done;
+  uint32_t note_count;
-  uint32_t current_note;
+  uint32_t next_note;
-  uint32_t current_note_loops;
+
+  /* implementation flags */
   int background_beep;
+  int free_notes_when_done;
+
+  /* sound tracking */
+  uint16_t current_frequency;
+  uint64_t play_until;
+  uint64_t last_time;
 };
 
 #ifdef CUSTOM_MUSIC

firmware/lib/vboot_audio.c

@@ -18,7 +18,12 @@
 #define UINT_MAX 4294967295U            /* 0xffffffff */
 #endif
 
-#define DEV_LOOP_TIME 10                /* Minimum note granularity in msecs */
+/* Need one second of noise in the first 22 seconds.
+ * Total delay >= 30 seconds, <= 60 seconds. */
+#define REQUIRED_NOISE_TIME    1000
+#define REQUIRED_NOISE_WITHIN 22000
+#define REQUIRED_TOTAL_DELAY  30000
+#define MAX_CUSTOM_DELAY      60000
 
 /* These are visible externally only to make testing easier */
 VbDevMusicNote default_notes_[] = { {20000, 0}, /* 20 seconds */
@@ -35,9 +40,10 @@ uint32_t short_count_ = sizeof(short_notes_) / sizeof(VbDevMusicNote);
 static VbAudioContext au;
 
 
-/* Arg is 16-bit, but use 32-bit to avoid rollover */
+/* Convert from msecs to VbExGetTimer() units. */
-static uint32_t VbMsecToLoops(uint32_t msec) {
+static uint64_t ticks_per_msec = 0;     /* Initialized by VbAudioOpen() */
-  return (DEV_LOOP_TIME / 2 + msec) / DEV_LOOP_TIME;
+static uint64_t VbMsecToTicks(uint16_t msec) {
+  return ticks_per_msec * msec;
 }
 
 /* Find and return a valid set of note events. We'll use the user's struct
@@ -53,8 +59,7 @@ static void VbGetDevMusicNotes(VbAudioContext *audio, int use_short) {
   VbDevMusic *hdr = CUSTOM_MUSIC_NOTES;
   uint32_t maxsize = CUSTOM_MUSIC_MAXSIZE; /* always <= flash size (8M) */
   uint32_t maxnotes, mysum, mylen, i;
-  uint64_t on_loops, total_loops, min_loops;
+  uint32_t this_msecs, on_msecs, total_msecs;
-  uint32_t this_loops;
   uint32_t count;
 
   VBDEBUG(("VbGetDevMusicNotes: use_short is %d, hdr is %lx, maxsize is %d\n",
@@ -116,32 +121,30 @@ static void VbGetDevMusicNotes(VbAudioContext *audio, int use_short) {
    * avoid rollover. The note time is 16 bits, and the note count is 32 bits.
    * The product should fit in 64 bits.
    */
-  total_loops = 0;
+  total_msecs = 0;
-  on_loops = 0;
+  on_msecs = 0;
-  min_loops = VbMsecToLoops(22000);
   for (i=0; i < hdr->count; i++) {
-    this_loops = VbMsecToLoops(hdr->notes[i].msec);
+    this_msecs = hdr->notes[i].msec ;
-    if (this_loops) {
+    if (this_msecs) {
-      total_loops += this_loops;
+      total_msecs += this_msecs;
-      if (total_loops <= min_loops &&
+      if (total_msecs <= REQUIRED_NOISE_WITHIN &&
           hdr->notes[i].frequency >= 100 && hdr->notes[i].frequency <= 2000)
-        on_loops += this_loops;
+        on_msecs += this_msecs;
     }
   }
 
   /* We require at least one second of noise in the first 22 seconds */
   VBDEBUG(("VbGetDevMusicNotes:   with %ld msecs of sound to begin\n",
-           on_loops * DEV_LOOP_TIME));
+           on_msecs));
-  if (on_loops < VbMsecToLoops(1000)) {
+  if (on_msecs < REQUIRED_NOISE_TIME) {
     goto nope;
   }
 
   /* We'll also require that the total time be less than a minute. No real
    * reason, it just gives us less to worry about.
    */
-  VBDEBUG(("VbGetDevMusicNotes:   lasting %ld msecs\n",
+  VBDEBUG(("VbGetDevMusicNotes:   lasting %ld msecs\n", total_msecs));
-           total_loops * DEV_LOOP_TIME));
+  if (total_msecs > MAX_CUSTOM_DELAY) {
-  if (total_loops > VbMsecToLoops(60000)) {
     goto nope;
   }
 
@@ -157,17 +160,16 @@ static void VbGetDevMusicNotes(VbAudioContext *audio, int use_short) {
   count = hdr->count;
 
   /* We also require at least 30 seconds of delay. */
-  min_loops = VbMsecToLoops(30000);
+  if (total_msecs < REQUIRED_TOTAL_DELAY) {
-  if (total_loops < min_loops) {
     /* If the total time is less than 30 seconds, the needed difference will
      * fit in 16 bits.
      */
-    this_loops = (min_loops - total_loops) & 0xffff;
+    this_msecs = (REQUIRED_TOTAL_DELAY - total_msecs) & 0xffff;
-    notebuf[hdr->count].msec = (uint16_t)(this_loops * DEV_LOOP_TIME);
+    notebuf[hdr->count].msec = this_msecs;
     notebuf[hdr->count].frequency = 0;
     count++;
     VBDEBUG(("VbGetDevMusicNotes:   adding %ld msecs of silence\n",
-             this_loops * DEV_LOOP_TIME));
+             this_msecs));
   }
 
   /* done */
@@ -190,15 +192,21 @@ VbAudioContext* VbAudioOpen(VbCommonParams* cparams) {
   GoogleBinaryBlockHeader* gbb = (GoogleBinaryBlockHeader*)cparams->gbb_data;
   VbAudioContext* audio = &au;
   int use_short = 0;
+  uint64_t a,b;
 
   /* Note: may need to allocate things here in future */
 
-  /* defaults */
+  /* Calibrate audio delay */
-  audio->note_count = 0;
+  a = VbExGetTimer();
-  audio->music_notes = 0;
+  VbExSleepMs(10);
-  audio->current_note = 0;
+  b = VbExGetTimer();
-  audio->current_note_loops = 0;
+  ticks_per_msec = (b - a) / 10ULL ;
+  VBDEBUG(("VbAudioOpen() - ticks_per_msec is %Lu\n", ticks_per_msec));
+
+  /* Initialize */
+  Memset(audio, 0, sizeof(*audio));
   audio->background_beep = 1;
+  audio->play_until = b;                /* "zero" starts now */
 
   /* See if we have full background sound capability or not. */
   if (VBERROR_SUCCESS != VbExBeep(0,0)) {
@@ -223,45 +231,46 @@ VbAudioContext* VbAudioOpen(VbCommonParams* cparams) {
 
 /* Caller should loop without extra delay until this returns false */
 int VbAudioLooping(VbAudioContext* audio) {
+  uint64_t now;
+  uint16_t freq = audio->current_frequency;
+  uint16_t msec = 0;
+  int looping = 1;
 
-    /* Time to play a note? */
+  now = VbExGetTimer();
-    if (!audio->current_note_loops) {
+  VBDEBUG(("VbAudioLooping: now=%Lu, cur=%d, play_until=%Lu, next=%d/[0-%d]\n",
-      VBDEBUG(("VbAudioLooping() - current_note is %d\n", audio->current_note));
+           now, audio->current_frequency, audio->play_until, audio->next_note,
+           audio->note_count-1));
 
-      /* Hooray, out of notes! */
+  while (audio->next_note < audio->note_count && now >= audio->play_until) {
-      if (audio->current_note >= audio->note_count)
+    freq = audio->music_notes[audio->next_note].frequency;
-        return 0;
+    msec = audio->music_notes[audio->next_note].msec;
+    audio->play_until += VbMsecToTicks(msec);
+    audio->next_note++;
+    VBDEBUG(("  freq=%d, play_until=%Lu, next=%d/[0-%d]\n",
+             freq, audio->play_until, audio->next_note, audio->note_count-1));
+  }
 
-      /* For how many loops do we hold this note? */
+  if (now >= audio->play_until) {
-      audio->current_note_loops =
+    looping = 0;
-        VbMsecToLoops(audio->music_notes[audio->current_note].msec);
+    freq = 0;
-      VBDEBUG(("VbAudioLooping() - new current_note_loops == %d\n",
+  }
-               audio->current_note_loops));
 
-      if (audio->background_beep) {
+  // Do action here.
-
+  if (audio->background_beep) {
-        /* start (or stop) the sound */
+    if (audio->current_frequency != freq) {
-        VbExBeep(0, audio->music_notes[audio->current_note].frequency);
+      VbExBeep(0, freq);
-
+      audio->current_frequency = freq;
-      } else if (audio->music_notes[audio->current_note].frequency) {
-
-        /* the sound will block, so don't loop repeatedly */
-        audio->current_note_loops = 1;
-        VbExBeep(audio->music_notes[audio->current_note].msec,
-                 audio->music_notes[audio->current_note].frequency);
-      }
-
-      audio->current_note++;
     }
+  } else if (freq && msec) {
+    VbExBeep(msec, freq);
+    now = VbExGetTimer();
+    VBDEBUG(("    (now=%ul)\n", now));
+  }
 
-    /* Wait a bit. Yes, one extra loop sometimes, but it's only 10msec */
+  VBDEBUG(("DONE: now=%Lu, freq=%d, looping=%d\n", now,
-    VbExSleepMs(DEV_LOOP_TIME);
+           audio->current_frequency, looping));
-
+  audio->last_time = now;
-    /* That's one... */
+  return looping;
-    if (audio->current_note_loops)
-      audio->current_note_loops--;
-
-  return 1;
 }
 
 /* Caller should call this prior to booting */

firmware/stub/vboot_api_stub.c

@@ -19,11 +19,27 @@
 __pragma(warning (disable: 4100))
 
 
+/* U-Boot's printf uses '%L' for uint64_t. gcc uses '%l'. */
+#define MAX_FMT 255
+static char fmtbuf[MAX_FMT+1];
+static const char *fixfmt(const char *format) {
+  int i;
+  for(i=0; i<MAX_FMT && format[i]; i++) {
+    fmtbuf[i] = format[i];
+    if(format[i] == '%' && format[i+1] == 'L') {
+      fmtbuf[i+1] = 'l';
+      i++;
+    }
+  }
+  fmtbuf[i] = '\0';
+  return fmtbuf;
+}
+
 void VbExError(const char* format, ...) {
   va_list ap;
   va_start(ap, format);
   fprintf(stderr, "ERROR: ");
-  vfprintf(stderr, format, ap);
+  vfprintf(stderr, fixfmt(format), ap);
   va_end(ap);
   exit(1);
 }
@@ -31,9 +47,10 @@ void VbExError(const char* format, ...) {
 
 void VbExDebug(const char* format, ...) {
   va_list ap;
+  int i;
   va_start(ap, format);
   fprintf(stderr, "DEBUG: ");
-  vfprintf(stderr, format, ap);
+  vfprintf(stderr, fixfmt(format), ap);
   va_end(ap);
 }
 

tests/vboot_api_devmode_tests.c

@@ -24,11 +24,14 @@
 /* Expected results */
 
 #define MAX_NOTE_EVENTS 10
+#define TICKS_PER_MSEC 1900ULL
+#define TIME_FUZZ 500
+#define KBD_READ_TIME 60
 
 typedef struct {
   uint16_t msec;
   uint16_t freq;
-  uint32_t time;
+  int time;
 } note_event_t;
 
 typedef struct {
@@ -46,20 +49,18 @@ test_case_t test[] = {
   { "VbBootDeveloperSoundTest( fast, background )",
     0x00000001, VBERROR_SUCCESS,
     0, 0,
-    3,
+    2,
     {
       {0, 0, 0},                        // probing for capability
-      {0, 0, 0},                        // starts with no sound
       {0, 0, 2000},                     // off and return at 2 seconds
     }},
 
   { "VbBootDeveloperSoundTest( normal, background )",
     0x00000000, VBERROR_SUCCESS,
     0, 0,
-    7,
+    6,
     {
       {0, 0, 0},                        // probing for capability
-      {0, 0, 0},                        // starts with no sound
       {0, 400, 20000},                  // starts first beep at 20 seconds
       {0, 0, 20250},                    // stops 250ms later
       {0, 400, 20500},                  // starts second beep
@@ -87,16 +88,14 @@ test_case_t test[] = {
       {0, 0, 30020},                    // off and return at 30 seconds
     }},
 
-
   // Now with some keypresses
 
   { "VbBootDeveloperSoundTest( normal, background, Ctrl-D )",
     0x00000000, VBERROR_SUCCESS,
     4, 10000,                           // Ctrl-D at 10 seconds
-    3,
+    2,
     {
       {0, 0, 0},                        // probing for capability
-      {0, 0, 0},                        // starts with no sound
       {0, 0, 10000},                    // sees Ctrl-D, sound off, return
     }},
 
@@ -113,10 +112,9 @@ test_case_t test[] = {
   { "VbBootDeveloperSoundTest( normal, background, Ctrl-U not allowed )",
     0x00000000, VBERROR_SUCCESS,
     21, 10000,                          // Ctrl-U at 10 seconds
-    9,
+    8,
     {
       {0, 0, 0},                        // probing for capability
-      {0, 0, 0},                        // starts with no sound
       {120, 400, 10000},                // complains about Ctrl-U (one beep)
                                         // waits 120ms...
       {120, 400, 10240},                // complains about Ctrl-U (two beeps)
@@ -138,6 +136,7 @@ static uint8_t shared_data[VB_SHARED_DATA_MIN_SIZE];
 static VbSharedDataHeader* shared = (VbSharedDataHeader*)shared_data;
 static GoogleBinaryBlockHeader gbb;
 static int current_time;
+static uint64_t current_ticks;
 static int current_event;
 static int max_events;
 static int matched_events;
@@ -169,7 +168,9 @@ static void ResetMocks(void) {
   gbb.minor_version = GBB_MINOR_VER;
   gbb.flags = 0;
 
+  current_ticks = 0;
   current_time = 0;
+
   current_event = 0;
   kbd_fire_at = 0;
   kbd_fire_key = 0;
@@ -219,18 +220,31 @@ uint32_t VbExIsShutdownRequested(void) {
 
 uint32_t VbExKeyboardRead(void) {
   uint32_t tmp;
-  if (kbd_fire_key && current_time >= kbd_fire_at) {
+  uint32_t now;
+
+  VbExSleepMs(KBD_READ_TIME);
+  now = current_time;
+
+  if (kbd_fire_key && now >= kbd_fire_at) {
     VBDEBUG(("  VbExKeyboardRead() - returning %d at %d msec\n",
-             kbd_fire_key, current_time));
+             kbd_fire_key, now));
     tmp = kbd_fire_key;
     kbd_fire_key = 0;
     return tmp;
   }
+  VBDEBUG(("  VbExKeyboardRead() - returning %d at %d msec\n",
+           0, now));
   return 0;
 }
 
 void VbExSleepMs(uint32_t msec) {
-  current_time += msec;
+  current_ticks += (uint64_t)msec * TICKS_PER_MSEC;
+  current_time = current_ticks / TICKS_PER_MSEC;
+  VBDEBUG(("VbExSleepMs(%d) -> %d\n", msec, current_time));
+}
+
+uint64_t VbExGetTimer(void) {
+  return current_ticks;
 }
 
 VbError_t VbExBeep(uint32_t msec, uint32_t frequency) {
@@ -239,11 +253,12 @@ VbError_t VbExBeep(uint32_t msec, uint32_t frequency) {
   if (current_event < max_events &&
       msec == expected_event[current_event].msec &&
       frequency == expected_event[current_event].freq &&
-      current_time == expected_event[current_event].time ) {
+      abs(current_time - expected_event[current_event].time) < TIME_FUZZ ) {
     matched_events++;
   }
 
-  current_time += msec;
+  if (msec)
+    VbExSleepMs(msec);
   current_event++;
   return beep_return;
 }