pw_time queued/buffered information is incorrect with respect to the documentation
I was recently trying to write an audio playback stream implementation, using pw_stream
, that required precise timing information for network sync and I found some odd thing about what information is reported in pw_time
(and pw_buffer->requested
).
To reproduce the issue I was seeing, I modified the audio-src
example here. The following output was all generated using this modified example. Here is how streaming begins:
[I][96531.420719] pw.node | [ impl-node.c: 407 node_update_state()] (node-63) suspended -> running
[I][96531.472547] pw.node | [ impl-node.c: 1911 node_xrun()] (node-63) XRun! rate:0/0 count:1 time:0 delay:0 max:0 (0 missed)
[I][96531.472602] default | [ audio-src.c: 87 on_process()] XRun! resync, data->outputSample += 940
[I][96531.472627] default | [ audio-src.c: 92 on_process()] process, b.req 973, s.ticks 1024, sample(our) 940, sample(dr) 940,
s.buf 32, s.queued 0, queued (real) 0, s.delay 5120
[I][96531.579713] default | [ audio-src.c: 92 on_process()] process, b.req 150, s.ticks 2048, sample(our) 2704, sample(dr) 1881,
s.buf 32, s.queued 0, queued (real) 823, s.delay 5120
[I][96531.622102] default | [ audio-src.c: 92 on_process()] process, b.req 268, s.ticks 4096, sample(our) 4468, sample(dr) 3763,
s.buf 32, s.queued 0, queued (real) 705, s.delay 5120
[I][96531.679839] default | [ audio-src.c: 92 on_process()] process, b.req 385, s.ticks 6144, sample(our) 6232, sample(dr) 5644,
s.buf 32, s.queued 0, queued (real) 588, s.delay 5120
[I][96531.722153] default | [ audio-src.c: 92 on_process()] process, b.req 503, s.ticks 8192, sample(our) 7996, sample(dr) 7526,
s.buf 32, s.queued 0, queued (real) 470, s.delay 5120
[I][96531.763450] default | [ audio-src.c: 92 on_process()] process, b.req 621, s.ticks 10240, sample(our) 9760, sample(dr) 9408,
s.buf 32, s.queued 0, queued (real) 352, s.delay 5120
Here we see an async stream running at 44100 rate, with a buffer size of 1764 samples (40ms). Every time process
is called, it ignores the pw_buffer->requested
size and just queues another 1764 samples. The driver is running at 48000 rate with a buffer size of 1024 (21.3ms).
In order to make a timeline of samples, the application uses pw_time->ticks
and converts it to the stream's sample rate. So, when the driver reports pw_time->ticks (s.ticks) = 1024
, the next sample we are writing is sample(dr) = 940
(because 940/44100 = 1024/48000). Then at s.ticks = 2048
, sample(dr) = 1881
and so on. This is consistent with the time that the driver wakes up this stream to queue more data, which is 1 cycle before the stream underruns (since it's not a RT stream).
This is, however, not consistent with how many samples have been queued. This is reasonable and expected. At sample 940 we queue 1764 more samples, so the next sample to start from would be 940+1764 = 2704
. There is therefore a difference between the next sample number that we are supposed to write (sample(our) = 2704
) and the sample that the driver is currently at (sample(dr) = 1881
). This difference is conceivably how many samples are still queued in the audioconverter but have not been pulled by the driver yet.
I would therefore expect, as per the documentation, to be able to find this number by adding up pw_time->queued
and pw_time->buffered
, but this does not work. At s.ticks = 2048
, we can see that pw_time->queued (s.queued)
is 0 and pw_time->buffered (s.buf)
is 32. In fact, this is ALWAYS the case. I understand that pw_time->queued
is expected to be 0 at this point, because the pw_stream buffer that was originally pushed (containing 1764 samples) has been consumed internally by the audioconverter, so there is nothing queued. But why is pw_time->buffered
always 32 ? This is documented to report exactly the latency of the audioconverter, so I would expect to be able to find this difference here.
I ended up calculating this number manually (see "queued (real)") by counting how many samples I push and taking the difference from the driver's current sample.
Then another interesting thing is pw_buffer->requested
... This is documented as "the suggested amount of data to write" and "the amount of samples required by the resampler". The numbers that I see in the log (see b.req
) don't make any sense to me, but notice how b.req + queued(real) = 973
all the time. It must be that the stream has some kind of internal quantum at 973 samples (not sure where this number comes from), and it accurately knows how many samples are missing to fill that, but it doesn't report the fill level in pw_time->buffered
.
PS: Another, totally unrelated issue that you can see in this log is that the stream begins with an XRun. This seems to be always the case for async streams.