[pulseaudio-discuss] [PATCH v2] pacat: Write to stream in frame-sized chunks

[Ahmed S. Darwish]

On Tue, Dec 20, 2016 at 10:03:22AM +0000, Ahmed S. Darwish wrote:
> On Tue, Dec 20, 2016 at 03:20:00PM +0530, Arun Raghavan wrote:
> > 
> > On Tue, 20 Dec 2016, at 03:14 PM, Ahmed S. Darwish wrote:
> > > Hi Tanu,
> > > 
> > > On Sun, Dec 18, 2016 at 08:59:58PM +0200, Tanu Kaskinen wrote:
> > > >
> > > > On Sat, 2016-12-17 at 01:43 +0200, Ahmed S. Darwish wrote:
> > > > > # Note: Documentation of `pa_stream_begin_write(stream, &buf, &nbytes)'
> > > > > # suggests to pass nbytes = -1. Doing so though lends to a huge returned
> > > > > # nbytes values. Calling a pa_stream_write() with such values chokes the
> > > > > # stream: making it go silent and not produce any further write-callback
> > > > > # events.
> > > > > #
> > > > > # Is this a problem in usage pattern, or a bug?
> > > > 
> > > > Sounds like a bug. Trying to write more than buffer_attr.maxlength
> > > > bytes at once would be expected to cause some kind of problems, but I
> > > > don't think that's the case here. The returned nbytes value is 64k,
> > > > isn't it? pacat uses the default maxlength, and the default maxlength
> > > > is 4M, so nbytes is nowhere near that limit. As long as maxlength isn't
> > > > exceeded, any "extra" audio should just get buffered in the stream
> > > > buffer at the server side.
> > > >
> > > 
> > > Yeah; sounds like a bug in the write stream indeed.
> > > 
> > > In the command below, (second pacat):
> > > 
> > >   ./src/pacat -r --latency-msec=4 | ./src/pacat --latency-msec=4
> > > 
> > > When using "writable" values from pa_stream_writable_size(), we
> > > get the following, valid, sequence:
> > > 
> > >   ++ STDIN callback: mute! stream writable = 0
> > >   @@ WRITE callback: Re-enable STDIN events
> > >   <-- Small writable val; appropriate for requested small latency -->  
> > >   @@ STDIN callback: stream writable size = 192
> > >   ** Writing 192 bytes; frame len = 4
> > > 
> > >   ++ STDIN callback: mute! writable = 0
> > >   @@ WRITE callback: Re-enable STDIN events
> > >   <-- Small writable val; appropriate for requested small latency -->  
> > >   @@ STDIN callback: stream writable size = 192
> > >   ** Writing 192 bytes; frame len = 4
> > > 
> > >   ... Sequence endlessly repeated ...
> > > 
> > > BUT when using "writable" values from pa_stream_begin_read(), with
> > > "writable = (size_t)-1" as the documentation recommends, we get
> > > that sequence instead:
> > > 
> > >   @@ WRITE callback: Re-enable STDIN events
> > >   @@ STDIN callback: stream writable size = 65472   <== 64K indeed
> > >   ** Writing 2112 bytes; frame len = 4
> > >   ++ STDIN callback: mute! writable = 0
> > > 
> > >   <-- COMPLETE silence! - no more stream write callback events -->
> > > 
> > > Hopefully not a new blocker, but if you agree with the assessment
> > > above, I'll submit a bug to be tracked for v11.
> > 
> > Is that a regression?
> >
> 
> Didn't try this on earlier versions of pulse to know for sure;
> will invesitgate further..
> 

OK, it is a regression introduced after v9.0. I've dome some
bisections; here is the offending commit:

commit 74251f07864c63439ea847d7287024ac54578d64
Author: Pierre Ossman <ossman at cendio.se>
Date:   Thu May 19 15:54:08 2016 +0200

    memblockq: remove internal "missing" state variable

    It was a very confusing state variable that required a lot of
    fiddling. It was also redundant in that it can be computed from
    the other variables, removing any risk of it getting out of sync.
    In the same spirit, make sure "requested" also always contains a
    sane value, even though it may not be used by every caller.

The issue (not receiving any more stream write callback events) can
be triggered by:

    ./src/pacat -r --latency-msec=4 | ./src/pacat --latency-msec=4

After applying below patch on top of master (note the writable = -1
line, increasing our writes size):

---
diff --git a/src/utils/pacat.c b/src/utils/pacat.c
index 4e1bbfc6b..fd3cc35d7 100644
--- a/src/utils/pacat.c
+++ b/src/utils/pacat.c
@@ -178,6 +178,7 @@ static void stream_write_callback(pa_stream *s, size_t length, void *userdata) {
     if (raw) {
         pa_assert(!sndfile);
 
+        pa_log("++WRITE callback: Re-enable stdin events");
         if (stdio_event)
             mainloop_api->io_enable(stdio_event, PA_IO_EVENT_INPUT);
 
@@ -535,16 +536,20 @@ static void stdin_callback(pa_mainloop_api*a, pa_io_event *e, int fd, pa_io_even
     if (!stream || pa_stream_get_state(stream) != PA_STREAM_READY ||
         !(writable = pa_stream_writable_size(stream))) {
 
+        pa_log("@@STDIN callback: Mute ourself!");
         mainloop_api->io_enable(stdio_event, PA_IO_EVENT_NULL);
         return;
     }
 
+    writable = (size_t) -1;
     if (pa_stream_begin_write(stream, (void **)&buf, &writable) < 0) {
         pa_log(_("pa_stream_begin_write() failed: %s"), pa_strerror(pa_context_errno(context)));
         quit(1);
         return;
     }
 
+    pa_log("@@STDIN callback: writable = %zu", writable);
+
     /* Partial frame cached from a previous write iteration? */
     if (partialframe_len) {
         pa_assert(partialframe_len < pa_frame_size(&sample_spec));
@@ -577,13 +582,16 @@ static void stdin_callback(pa_mainloop_api*a, pa_io_event *e, int fd, pa_io_even
         memcpy(partialframe_buf, buf + towrite, partialframe_len);
 
     if (towrite) {
+        pa_log("@@STDIN callback: Writing %zu bytes to stream", towrite);
         if (pa_stream_write(stream, buf, towrite, NULL, 0, PA_SEEK_RELATIVE) < 0) {
             pa_log(_("pa_stream_write() failed: %s"), pa_strerror(pa_context_errno(context)));
             quit(1);
             return;
         }
-    } else
+    } else {
+        pa_log("@@STDIN callback: Canceling stream write!");
         pa_stream_cancel_write(stream);
+    }
 }
 
 /* Some data may be written to STDOUT */

Here was also some earlier discussions on the topic
[gmane, where have you gone .. :-(]

    https://www.mail-archive.com/pulseaudio-discuss@lists.freedesktop.org/msg15927.html
    https://patchwork.freedesktop.org/patch/88098/

Any ideas? I guess we'll need to add some more test cases; this
seems to be rather very delicate.

Regards,

-- 
Darwish
http://darwish.chasingpointers.com