When trying to assign wallclock timestamps to recorded audio from the simple API, I noticed that latencies from pa_simple_get_latency() seemed behaving more oddly than expected. The issue was solved/worked around by using the "not simple" API.
From looking at simple.c it seems that the p->read_data / p->read_length buffer used in pa_simple_read() isnt considered in pa_simple_get_latency(). Which would explain the issue ive seen with latencies
Created attachment 102473 [details] [review]
Your analysis seems correct. I attached a fix. It's untested - could you test it?
Ive done a quick test by patching the old pulseaudio (1:1.1-0ubuntu15.4) thats used on that ubuntu box. And it does not seem to fix it completely but i wouldnt be surprised if that old version had other issues. I know i should test the patch with latest pulse but for that i have too many other things to do ATM.
But its really easy to test this, you just need to run pa_simple_read(), pa_simple_get_latency() and something like gettimeofday() in a loop and check if the values appear matching up, that is big jumps in the wallclock should matchup with big jumps in the latency values, and the other way around too
Created attachment 102705 [details]
I wrote a test program, it's attached.
Created attachment 102706 [details]
Output from the test program, before patching
Created attachment 102707 [details]
Output from the test program, after patching
Created attachment 102708 [details]
Graph for before.csv
Created attachment 102709 [details]
Graph for after.csv
I attached before/after output from the test program (both were about one minute runs), as well as graphs generated from those outputs.
What does the test program do, and how to interpret the output files? The program calls pa_simple_read() in an infinite loop, reading 10000 bytes at a time. After each read, the program prints "x,y" to stdout, where x is usecs since the first read (wall clock time) and y is the difference between x and the cumulative amount of audio that has been read plus the current latency as reported by pa_simple_get_latency(). I believe that if the latency reporting is perfect, y should be constant (or change slowly and steadily if there's drift between the wall clock and the sound card clock).
The patch seems to improve things, but the graph after patching is still far from a straight line. I don't have time to dig in deeper at this time, so I think it's best if I apply the patch to master and leave this bug open.
Created attachment 131661 [details] [review]
Change latency estimation to account for already-read data in pa_simple_get_latency().
Small change to the previous patch to account for the fact that read_index + read_length may change over time, to make the latency estimate more consistent.
Created attachment 131662 [details]
Test program output after patch 102473 and before patch 131661
Created attachment 131663 [details]
Test program output after both patch 102473 and patch 131661
Created attachment 131664 [details]
Output graph after patch 102473 and before patch 131661
Ran for 60 seconds on e3b64d8fd394fdd0b70dfd14a4a9b90c27369a99
Created attachment 131665 [details]
Output graph after both patch 102473 and patch 131661
Ran for 60 seconds
I noticed that pa_simple_get_latency() was reporting that the audio was being recorded out of order. I've attached a patch that makes it report (approximately) monotonically increasing recording time.
Awesome, thanks for the fix! I applied it to the "next" branch, so it won't be in the next release (we're in the freeze phase), but it will be in PA 12.0.
There's a problem with integer overflowing, though. pa_usec_t is an unsigned type, so I don't think it's a good idea to store negative values in it (even if it seems to work pretty well). I tried to fix it, but when I tested my fix, the results were worse. My fix included changing the code so that if the latency is negative, pa_simple_get_latency() returns zero (because it doesn't have a mechanism for reporting negative latencies), and it looks like pa_stream_get_latency() is reporting negative latencies even when it should have no reason to do so, and I'm trying to figure what's going on.
Created attachment 132024 [details] [review]
"Fix" integer overflow and negative latency issues and add comments (seems to actually make things worse)
Here's the fixup patch I currently have.
Thanks. I suppose the right way to handle negative latency would be to use the full API instead of the simple API?
With the full API you can get the negative latencies in your application, yes, but I'm not sure if that's any more "right", unless you're recording from monitor sources that really can have negative latencies (negative latency means "seeing in the future", and with monitor sources that's possible, because you may sometimes get the audio to your application before the sound goes to the speakers).
If you're not using a monitor source, a negative latency means that there's a bug in PulseAudio. I think my patch is ok, even though changing negative latencies to zero makes the latency calculations jumpy. The root cause seems to be in pa_stream_get_latency(), more specifically in the smoother that estimates how much audio has been played in total based on the current time and the past timing information updates from the server. The smoother is consistently estimating the played amount to be too low, and that makes the calculated latency negative.
I found a bug at the server end of the native protocol implementation. Now the latency reports are rather stable, at least in my experiments.
I submitted the native protocol fix here:
I also submitted the patch regarding negative latency reporting in pa_simple_get_latency() that I already attached to this bug. Here's the submission:
All patches are now in master, so I'm closing this bug.