I believe clients are expected to always return the full number of frames. I.e. if 512 are requested, you return 512 or we'll automatically fill with silence. The next callback should proceed as normal though, so I'm not clear on if you're saying that no further calls arrive?

I could see a series of the log messages shown above when WebAudio underflows. Now I don't get anything even when it happens. So I was wondering if there has been any change in the call stack or how the infra handles the glitches.

We have not changed anything in FIFO or AudioDestination a while, so I am simply speculating the infra change and asking around before investigating further.

> I.e. if 512 are requested, you return 512 or we'll automatically fill with silence.

Our FIFO always fills up the insufficient frames with zero.

Ray confirmed this happens on Linux ToT as well.

Well, I figured out a part of the problem:

https://chromium-review.googlesource.com/c/chromium/src/+/840001

This CL adds the autoplay policy, and I was testing with the "localhost". The localhost is somehow recognized as "non-secure" domain, so AudioContext couldn't boot up at all.

If I refresh the page, then the context actually starts to run and I can see 2 FIFO underflow warning at the beginning which is a correctly behavior.

But the problem still remains that I can't get the rest of FIFO underflow warning message. All I can see is:

[25080:125471:0116/101243.621182:WARNING:audio_sync_reader.cc(195)] AudioSyncReader::Read timed out, audio glitch count=20
[25080:125471:0116/101243.674578:WARNING:audio_sync_reader.cc(195)] AudioSyncReader::Read timed out, audio glitch count=30
[25080:125471:0116/101243.728141:WARNING:audio_sync_reader.cc(195)] AudioSyncReader::Read timed out, audio glitch count=40
[25080:125471:0116/101243.781166:WARNING:audio_sync_reader.cc(195)] AudioSyncReader::Read timed out, audio glitch count=50
[25080:125471:0116/101243.834429:WARNING:audio_sync_reader.cc(195)] AudioSyncReader::Read timed out, audio glitch count=60
[25080:125471:0116/101243.887785:WARNING:audio_sync_reader.cc(195)] AudioSyncReader::Read timed out, audio glitch count=70
[25080:125471:0116/101243.941148:WARNING:audio_sync_reader.cc(195)] AudioSyncReader::Read timed out, audio glitch count=80
[25080:125471:0116/101243.994458:WARNING:audio_sync_reader.cc(195)] AudioSyncReader::Read timed out, audio glitch count=90
[25080:125471:0116/101244.047800:WARNING:audio_sync_reader.cc(195)] AudioSyncReader::Read timed out, audio glitch count=100
[25080:125471:0116/101244.047864:WARNING:audio_sync_reader.cc(198)] (log cap reached, suppressing further logs)

FWIW, the render call itself is correctly invoked by AudioDeviceThread, because I can see AudioContext.currentTime is advancing. Somehow the frames with glitches are silenced by the audio infra. So I don't hear anything after any glitch starts.

Read timeout means the browser side did not receive the audio buffer in a timely manner and gave up,
So it renders silence.
Renderer side does not fulfill render requests fast enough.
You may want to pull in that recent CL with additional tracing and record traces for audio and WebAudio.
In general, trace recording is my first recommendations for all these situations.

I'll do another tracing to confirm that, but actually it is how I found this problem in the first place.

I added a trace in PushPullFIFO::Pull() but the trace call was not invoked correctly, so I could not see any record of it in the tracing.

You can also add new traces locally for debug purpose and commit important traces which are missing.
We find them very helpful for debugging.

Great! :)

Re #7:

That is actually a very good practice. Would love to try that. Thanks, Olga!

Now I understand what's going on here:

On OSX, the callback buffer size is 256. So when the AudioRenderSink requests 256 frames out of AudioDestination, it always finishes it's job no matter what rendering 2 render quanta (128 * 2) in a row.

Since it does always finishes it's job, there can be no "underflow" in this case.

On the other hand, AudioSyncReader raises flag on "Timeout" after it waits for AudioRenderSink/AudioDestination's rendered content because it does not get the requested buffer in time. That makes the audio output silence.

I find that this is a bit weird you get the silence because rendering buffer is too slow, but you can't detect the underflow within WebAudio's domain.

Perhaps I need to re-shape the FIFO and AudioDestination so we can catch the meaningful underflow from the WebAudio's view point. IIUC, AudioRenderSink also does not know about the timeout that is enforced by AudioSyncReader. Then how can we incorporate the notion of deadline in WebAudio?

How did it work before all the recent FIFO changes?

This is actually a problem for WebAudio because we can't collect the underflow count anymore:
https://cs.chromium.org/chromium/src/third_party/WebKit/Source/platform/audio/PushPullFIFO.cpp?l=46

I guess I have to check if other platforms have the similar issue.

Re #11:

Anytime WebAudio can't render the content in time we'd get this warning in the terminal:
```
[50445:38935:0112/123248.392814:WARNING:PushPullFIFO.cpp(182)] PushPullFIFO: underflow while pulling (underflowCount=1, availableFrames=0, requestedFrames=256, fifoLength=12288)
```

I mean, how was it working that it was detecting underflow? And what has changed?

Re #14:

That's what I am asking here in this issue. Nothing has changed in WebAudio side. We're able to see FIFO underflow warning messages when we ran the stress test, but now they are gone.

I wanted to try the manual bisect of debug build, but it has been broken since June 2017:
https://bugs.chromium.org/p/chromium/issues/detail?id=733644
https://chromium-review.googlesource.com/c/chromium/src/+/555892

Weird. I did a bisect-builds last week. No problems with it.

The only changes I can remember were WebAudio ones around latency hint.
You could probably take a revision where it works "as before" and trace there
(Patching with additional traces locally), and see how behavior differs.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/1b42aab70c61b09bb2d3c6881222dc8df4b98bc2

commit 1b42aab70c61b09bb2d3c6881222dc8df4b98bc2
Author: Hongchan Choi <hongchan@chromium.org>
Date: Mon Jan 22 20:34:33 2018

Add TRACE_EVENT in PushPullFIFO

It might be helpful to have TRACEs in Push() and Pull() method.

Bug: 801685
Change-Id: I33a0f23e2d60d5062dd4de26728fa2a566f3b21b
Reviewed-on: https://chromium-review.googlesource.com/879262
Reviewed-by: Raymond Toy <rtoy@chromium.org>
Commit-Queue: Hongchan Choi <hongchan@chromium.org>
Cr-Commit-Position: refs/heads/master@{#530978}
[modify] https://crrev.com/1b42aab70c61b09bb2d3c6881222dc8df4b98bc2/third_party/WebKit/Source/platform/audio/PushPullFIFO.cpp