Created attachment 74297 [details]
debug log

Created attachment 75034 [details]
image showing graphical performance data for GStreamer running on Solaris


I ran the Sun Studio collect program to collect performance information so I 
could see where GStreamer seems to be spending its time.  I've attached a
screenshot of the analyzer GUI program running, which shows a timeline of 
where the CPU is spending its time.  You can see that there are 5 threads and
this might highlight what is going on.  I'll give some details of each of the
5 threads, to explain what the screenshot is showing:

Thread 1: This thread is the main thread.  You can see at the beginning it is
          doing all the work and then seems to go into poll state.

Thread 2: This thread seems to be used just in one place, near the end of the
          run.  Seems to be a call to gst_system_clock_async_thread. 

Thread 3: This thread seems to be called a lot.  Seems to be where
          g_thread_pool_thread_proxy is calling gst_task_func, then 
          gst_pad_push, gst_pad_chain_unchecked.  This seems to eventually
          call g_atomic_int_get, which then calls pthread_mutex_lock.

Thread 4: Calls to write

Thread 5: Just used once near the beginning.  _lwp_start calls _thr_setup, 
          calls g_thread_create_proxy, etc.

Not sure if this adds any information.  Though I wonder if something weird is
going on since thread #3 seems to be eating up all the time and the "stuttering"
effect of thread 4 could correspond to the fact that this thread is only
invoked every 4 seconds which corresponds with the stuttering behavior.
Perhaps thread #3 is getting stuck in mutex_locks and preventing thread #4 
from being able to be called as often as it needs?

The fact that thread #3 is spending time in the pad logic makes me curious.
I would think GStreamer would figure out the plugin pads once at the beginning
and not need to spend so many CPU cycles dealing with the pads, though perhaps
I don't understand what is going on here.

Perhaps this "stuttering" behavior is caused by a slight difference in the
way threads and thread locking is managed on Solaris, causing the write ()
thread to be starved so it can only occasionally be called, every 4 seconds or
so?

This would explain why increasing the SunAudio write buffer to 512K fixes the
problem, so that GStreamer can fill the buffer enough so it can continue 
playing while GStreamer waits 4 seconds for the next write call?

I should mention that if you build and install gst-plugins-good, you will not see this problem of "stuttering".  This is because the gstsunaudiosink.c code contains these lines:

  /*
   * SunAudio doesn't really give access to buffer size, these values work.  
   * Setting the buffer so large (512K) is a bit annoying because this causes 
   * the volume control in audio players to be slow in responding since the 
   * audio volume won't change until the buffer empties.  SunAudio doesn't seem 
   * to allow changing the audio output buffer size to anything smaller, though.  
   * I notice setting the values smaller causes the audio to stutter, which is 
   * worse.
   */
  spec->segsize = 4096;
  spec->segtotal = 128;

You need to remove the setting of segsize and segtotal to see this problem.  Although setting segsize and segtotal does work around the problem, it makes
GStreamer unresponsive, so that when you change the volume in an application, hit the Stop, Rewind, Fast-forward, etc. buttons, there is a several second lag before you notice the change taking effect.  This is better than stuttering, 
but still undesirable.

It would be better if we could fix the underlying bug so that setting segsize and segtotal is not necessary.  I would suspect this will fix the "lagging" issue.  So if you want to see this issue, please recompile gst-plugins-good and 
modify the code to not set segsize and segtotal.

Does anybody have any ideas of where I should look, explore, test, etc. in
order to help figure out this problem?

The problems of lag show up in any program, like totem or gstreamer that uses the GStreamer framework.  You will notice the lag, as I mention above, when you change volume, press fast-forward, revierse, etc.  

Once you remove the segsize/segtotal lines mentioned above, you will notice any program using GStreamer starts to stutter, such as totem or rhythmbox.  However, I find testing with the gst-launch command easier.  A command like this is good for testing:

  gst-launch audiotestsrc ! sunaudiosink

Other example commands for using gst-launch to play files encoded in various formats (wav, ogg, mp3, etc.) are described in the gst-launch.1 manpage.  Make sure you look at the 2.16 Sun manpages since the 2.14 and earlier manpages have commands that don't actually work on Solaris (refer to alsasink instead of sunaudiosink for example).

For reference, the command to see the same debug output as shown in the log above, run:

   gst-launch --gst-debug=ringbuffer:5,audiosink:5 audiotestsrc !
   sunaudiosink

Or you can run the following to get even more debug output.

   gst-launch --gst-debug-5 audiotestsrc ! sunaudiosink

Note the code in gst-plugins-base/gst-libs/gst/audio.  In this
directory you will find gstbaseaudiosink.[ch] and
gstringbuffer.[ch].  This is the actual code that is managing
the audiosink and the ringbuffer and the source of the debug
messages in the log.  In gst-plugins-good/sys/sunaudio
is the sunaudiosink plugin which is a child class of the
baseaudiosink.  So these files are the ones that are probably
involved with the problem. 

Created attachment 75678 [details]
gst.out1


Padriag O'Briain is looking into this bug, and here are some of his findings.  

I  experimented with two sets of values (882x20) and (882x600). The first set of values causes stutter and the second set does not.

I discovered that, in both cases, the time between successive calls to gst_audo_write is normally 0.00003 seconds but occasionally, about every 300 times, the time is about 2.6 seconds.

It looks to me that this time is being spent in the write call in gst_audio_write.

My evidence for this is in the attachments.

gst.out1 is for (882,20) and gst.out2 is for (882,600) and the output suggests that every so often a write call takes a long time to return.

I had a look at prstat output while gst-launch was running and the only thread that appears there is thread 4 which consumes about 1% of CPU.

Is the audio device fd is blovking or non-blocking mode?

Created attachment 75679 [details]
gst.out2

In response to Padraig's question, the sunaudiosink tries to open the device non-blocking first, then if this fails, tries blocking.  I will need to test to see which it is actually using.  I recommended to Padraig that he modify the sunaudiosink code so it will only open in non-blocking so we can verify that this is not the problem.  I suspect that perhaps this might be an issue with the SunAudio device not accepting data on too frequent of a basis or something.  Perhaps we need to set an ioctl on the device to be able to write data as frequently as we want?

Some more analysis from Padraig.

I tried opening in non-blocking mode and this had the effect that the sound stopped bei ng emitted, (just?) before the first write call which took about 2.6 seconds.

When we are running the sunaudiosink program does the process have /dev/audio open the whole time so there is no possibility of some other process attempting to use the device?

My view, now, is that the writing is happening too quickly rather than too slowly; the STREAMS buffers being maintained for the audio data fill up and the write system call blocks until that data is drained.

I need to figure out whether this theory fits the facts we have when the sound stutters and if so, what we can do about it. 

More comments from Padraig, based on his analysis.  Is it possible someone from the Fluendo team could respond to Padraig's findings and let us know if what we have found points the way to the problem we are seeing?

I have finally spotted something which may explain what is going on.

I put printf calls in gstringbuffer.c and gstbaseaudiosink.c in gst-plugins-base-0.10.10/gst-libs/gst/audio and in gstsunaudiosink.c in gst-plugins-good-0.10.4/sys/sunaudio.

I looked at the output which is attached. It seems to me that data is being written from the ring buffer to the audio device before the data is written to the ring buffer; see line 364 and following. New data has not been written to the buffer since it was last written to the audio device.

This seems to coincide with the stuttering.

What causes thread 4 to be activated?

Is there a way to indicate that the position in the ring buffer is not ready to be written? 

Padraig has the following analysis:

It looks to me that the stuttering is happening because the write thread is writing silent samples to the audio device. This is happening because there does not seem to be a way to tell the write thread that there is not data in the ring buffer available for writing.

If the ring buffer is big enough,  the buffer in the audio device is filled up before the silent samples are reached and the write call blocks until all the data has been written to the audio device. In this case stuttering does not occur.

More comments from Padraig:

I had a look at the use of buf->waiting and this is what I see:

The function gst_ring_buffer_commit writes samples to the ring buffer until the ring buffer is filled up. When this occurs the function wait_segment is called and sets buf->waiting to 1.

This causes the write thread which was waiting in audioringbuffer_thread_func to be woken up. The reason that audioringbuffer_thread_func had been waiting is that gst_ring_buffer_prepare_read had returned FALSE.

When a buffer is written to the audio device the function gst_ring_buffer_advance is called. This sets buf->waiting to 0 which allows data to be written to the ring buffer. The thread which writes data to the ring buffer wakes up and fil sup the ring buffer again and sets buf->waiting to 1.

The variable buf->waiting is set when the ring buffer fills up and so prevents the thread which writes to the ring buffer from overwriting samples which have not been written to the audio device.

There does not seem  to be a similar mechanism to prevent the thread which writes samples to the audio device from reading segments in the ring buffer which have not been written.

If there were I would expect gst_ring_buffer_prepare_read to return FALSE other than at the beginning. This function should return FALSE if there is no data in the ring buffer but there
does not seem to be a way to determine that.

It looks like there is an assumption that the thread which writes data to the audio device will yield the CPU to allow the thread which writes to the ring buffer to run but there is nothing to make that happen.

As an experiment try adding a call to thr_yield to the function audioringbuffer_thread_func in gstaudiosink.c after the loop which writes data to the audio device.

I tested the thr_yield function immediately after the while loop, but this doesn't seem to help at all.

Wim, would you be able to respond to this bug report?  I've heard that you are the right person to answer hard questions about how the ringbuffer works, or is supposed to work.

Actually digging into this a bit more, I notice that if I add the thr_yield function as follows in the audioringbuffer_thread_func ()

      do {
        written = writefunc (sink, readptr + written, left);
        GST_LOG ("transfered %d bytes of %d from segment %d", written, left,
            readseg);
        if (written < 0 || written > left) {
          GST_WARNING ("error writing data (reason: %s), skipping segment\n",
              strerror (errno));
          break;
        }
        left -= written;
      } while (left > 0);

      thr_yield ();

and also force the sunaudiosink to always open non-blocking by commenting out the if test in the open function like this:


  fd = open (sunaudiosink->device, O_WRONLY | O_NONBLOCK);

  /*
  if (fd >= 0) {
    close (fd);
    fd = open (sunaudiosink->device, O_WRONLY);
  }
  */

That this does make the stuttering less bad.  With these changes it seems that the audio starts to play consistently, and then after a few seconds it starts to stutter.  As if this fixes the problem for a few seconds and then it gets out of sync somehow.

So this thread yielding does seem to be related to the stuttering behavior, but isn't a complete fix.  But hopefully it points the way to the solution?  Wim?

More info from Padraig:

I am using a segment size of 4410 and a segtotal of 20. have the lines
spec->segsize *=5;
spec->segtotal = 20;
in gst_sunaudiosink_prepare.

I have threied calling thr_yield without corcing the audio device to open non-blocking.

The results seem to be better than you see but are not perfect.

I have worked my way through mu debug log and I see that after writing segments 0 and 1 to the audio device, new data is written to segment 0. Then after segment 2 is written to the
audio device new data is written to segment 1. This happy situation of writing segment n to the audio device and then writing  data to segment n-1 before writing segment n+1 to the audio device continues for some time.

Then suddenly data stops being written to the segments in the ring buffer and data continues to be written to the audio device which causes stuttering as silent samples are eventually written.

I have not been able to determine why this is so. It looks like the call to thr_yield sometimes does not cause the thread which writes data to the ring buffer to be activated.

Be that it may, I would to like to see if we can implement a proper fix. I believe that we need the function gst_ring_buffer_prepare_read to return FALSE if the next segment has been filled with silence samples and has not had data written to it since.

I have coded what I think is required but do not have it working yet; hopefully on Monday. 

Above analysis is pretty accurate. 

 Thread 3: This is the streaming thread doing all the decoding and eventually 
           writing samples in the ringbuffer. This function can block on a GCond
           when the ringbuffer is full.

 Thread 4: This is a thread that reads from the ringbuffer and writes to the
           audio device. It works lockfree so that the only blocking operation
           is the write() call. After writing each segment (segsize bytes) it
           will signal Thread 3 that more space is available in the ringbuffer
           (when needed, atomically checking the waiting flag).

Several assumptions are made:

 a Thread 4 only waits in write(), the other operations are lockfree and fast. 
   Its timeslice is practically never consumed. It should be considered an
   interactive task.
 b Thread 3 is mostly scheduled, hopefully enough to write enough samples in the
   ringbuffer. It is the only task that requires a lot of CPU and should always
   be scheduled whith lower priority than the other tasks.
 c When thread 4 blocks in the write() it is never much longer than the time of
   the segment (segsize bytes * SECOND) / (bytes_per_sample * samplerate), which
   is typically a few milliseconds. 
 d Thread 4 is able to write N segments without blocking, it blocks writing
   segment N+1. The segtotal should be set to N. When the write unblocks, at
   least one segment is physically played by the device and a new one queued.

The reason for not blocking in Thread 4 when the ringbuffer is empty is because
it simulates a DMA hardware buffer. This also keeps the audio buffer in the
device maximally filled to further limit the number of dropouts due to
thread scheduling jitter.

If the write() call takes a long time (as in comment #6) (c) is violated and
the total buffer time needs to be increased. If (d) is violated because not
enough segments where allocated, Thread 4 will race ahead and will write
silence. If Thread 3 is not scheduled enough, the ringbuffer will underflow and
silence will be written (dropouts). 

Did you check how pulseaudio compares?

From assumption d above, if I understand correctly, if thread 4 is able to write a large number of segments without blocking we should use that ]large value for segtotal.

This is what we had been doing but this has the effect that pausing appears to be unresponsive as it seems to play all the sound in the ring buffer before the pause takes effect.

Is this what you expect or does it indicate that we have a different problem?

Created attachment 77040 [details] [review]
preliminary patch to fix performance issues


Padraig provided the attached patch to improve performance on Solaris.  I
haven't yet tested this to verify it works well, so I'd hold off on 
committing the patch until we test it some more.  I just wanted to attach
the patch for reference, comments, etc.  I'll follow up with a comment 
telling you how I find things work after testing.

 Before he wrote the patch he had the following comments:

I am using a segment size of 4410 and a segtotal of 20. have the lines
spec->segsize *=5;
spec->segtotal = 20;
in gst_sunaudiosink_prepare.

I have threied calling thr_yield without corcing the audio device to open non-blocking.

The results seem to be better than you see but are not perfect.

I have worked my way through mu debug log and I see that after writing segments 0 and 1 to the audio device, new data is written to segment 0. Then after segment 2 is written to the
audio device new data is written to segment 1. This happy situation of writing segment n to the audio device and then writing  data to segment n-1 before writing segment n+1 to the audio device containues for some time.

Then suddenly data stops being written to the segments in the ring buffer and data continues to be written to the audio device which causes stuttering as silent samples are eventually written.

I have not been ablt to determine why this is so. It looks like the call to thr_yield sometimes does not cause the thread which writes data to the ring buffer to be activated.

Be that it may, I would to like to see if we can implement a proper fix. I believe that we need the function gst_ring_buffer_prepare_read to return FALSE if the next segment has been filled with silence samples and has not had data written to it since.

I wrote my comments and the preliminary patch before seeing the explanation of how GStreamer works in #17.

The question I have been asking myself and have not found an answer is whether GStreamer must be unresponsive when Stop, Rewind, etc. buttons are pressed with a large buffersize.

Re: Comment #20, I'm not sure what you mean by 'whether
GStreamer must be unresponsive when Stop, Rewind, etc. buttons are pressed'

In general, the audio sink should not care - it receives samples and plays them, and flushes the output buffer (if it can) when handling a FLUSH_STOP event from the pipeline.

Does that answer your question?

If you stop the audiosink, it will call _reset() which should cancel the current write(), which is most of the times blocked because the hardware buffer is filled. If it cannot cancel the write(), which is most common case for sound APIs, it will wait for the write() to complete. If the write() is doing a lot of bytes, this might take a long time. The amount of bytes it writes in one go is defined by the latency parameter. So, the smaller the latency, the faster the pause/stop operations respond if there is no way to cancel a write. 

Created attachment 77253 [details] [review]
patch to add reset logic to sunaudio sink and source plugins


Padraig had the following comments today:

have spent some time trying to understand what happens when the Stop button is pressed in an application which is playing audio.

The test case I am using is gnome-sound-recorder. I record some sound and then play it back. Is there a better test case I could use?

I am seeing that the callback for the Stop button takes about 1 second to run and most of this time is spent in the close system call in gst_sunaudiosink_close in
gst_plugins-good-0.10.4/sys/sunaudio/gstsunaudiosink.c

Strangely, I am finding that the segsize and segtotal setting for the ringbuffer does not seem to affcet the time taken in the close system call. 

I wrote the attached patch which adds a reset function to the source and sink plugin.  This seems to greatly speed up the performance of hitting the stop/pause buttons.  

I think we want this patch and also to continue working on the patch so that we no longer need to set segsize/segtotal to a large buffer on Solaris. 

This patch fixes the problem of stop/pause being slow, but changing volume is still very unresponsive.

We need the patch so we no longer need to set segsize/segtotal to improve the performance of changing volume.

Okay.  I think the patch in comment #23 should be commited to gst-plugins-good.  Padraig has also tested the patch and we agree this fixes a good bit of the performance problem.

Padraig is a bit concerned about his 1st patch (in comment #19).  He says: Comment #17 by Wim Taymans suggested to me that the proposed patch was fighting against the original design so I would like to see if we can solve our problems without that patch. 

I have stumbled across the library libgstvolume.so. Its source code is in gst-plugins-0.10.10.gst/volume/gstvolume.c.

The function volume_update_volume is called when I move the volume slider. This looks like the volume for the current program you refer to.

I have noticed that the function volume_transform_ip is called when processing the sound.

This function has an intriguing FIXME: subdivide GST_BUFFER_SIZE into small chunks for smooth fades. Does this mean anything to you? 

Based on this, I think that the performance problems on Solaris had two causes:

1) Not implementing reset() in the sink/source plugins, causing the
   stop/previous/next buttons in rhythmbox to be slow.  I think my
   patch fixes this.
2) The fact that the volume slider doesn't do smooth fades, and when
   combined with a large buffer causes slow fades also. 

So, perhaps the right fix is to leave the buffer size large (512K) on Solaris and fix volume changing so that smooth fades work better, especially since it works badly when the buffer size is big.  Is there another GStreamer bug about this issue?

Or, Wim, do you think that Padraig's first patch (in comment #19) has some 
merit and perhaps the ringbuffer should have some code like this so that it works better when some of the assumptions break (as they seem to on Solaris since it doesn't work when the buffer is set to a smaller size than 512K).
Padraig's patch in comment #19 *does* allow GStreamer to work on Solaris with
small buffer sizes, although it does introduce a bug that causes GStreamer
apps to hang when you try to play a second track (e.g. hit Prev/Next in rhythmbox).  Probably because the locks aren't being freed properly on 
reset or something?  Wim?

Can patch in comment #23 be committed to gst-plugins-good since it partially corrects the performance problems we are seeing?

Filed separate bug for smooth volume issue (refer to bug #382423), so after committing patch in comment #23, I think we can close this bug and leave the other bug open.

Note in the discussion of bug #382423 that GStreamer engineers believe that smooth volume transitions is not a valid solution to the performance problems when changing application volume when a large buffer is used in the sink.

This implies that perhaps a solution such as Padraig suggests in comment #19 might be appropriate for GStreamer?  I'd appreciate comment from the GStreamer engineers who best understand this code.  Is Padriag's approach appropriate or does it break fundamental assumptions about how things are supposed to work in GStreamer?  It would be useful if, based on the analysis so far, we could decide what the right way to fix this problem would be.

I hope the solution isn't just that we have to live with poor performance on Solaris and other systems that might have similar issues.

IMO, you need to figure out a way to get low(er) latency output on existing Solaris, or fix Solaris until it supports it.

Applying the reset patch:

        * sys/sunaudio/gstsunaudiosink.c: (gst_sunaudiosink_reset):
        * sys/sunaudio/gstsunaudiosrc.c: (gst_sunaudiosrc_open),
        (gst_sunaudiosrc_reset):

        Implement reset functions to unblock the src/sink more quickly on 
        state change requests.
        Patch by: Padraig O'Briain <padraig dot obriain at sun dot com>

Padraig, not sure if your surname should have an apostrophe - let me know if I need to fix the changelog.

Jan,

That patch was from Brian Cameron.

Jan, yes, this patch to add the reset() function was written by me.  The other patch under discussion (Comment #19) was by Padraig.  His name, by the way does have the apostrophe.

Created attachment 77995 [details] [review]
Fix for delaying the write call from racing ahead of the ring buffer.

The problem with silence is (as described elsewhere in the bug report) that sunaudio will accept 5.5 seconds of audio data (at 44.1khz) before blocking, while the default GStreamer ringbuffer is 200ms. This causes the audio output thread to race ahead writing loads of silence to the device. 

This patch fixes that by causing the writing thread to artificially block (using short nanosleeps) whenever the audio device has 'segtotal - 1' unplayed segments already queued.

The patch also:
 * Uses the sunaudio debug category for all debug output
 * Implements the _delay() callback to synchronise video playback better
 * Resets the segtotal and segsize values to the parent class defaults (taken from buffer_time and latency_times of 200ms and 10ms respectively)

The diff is against current CVS head.

Oh, I forgot to mention:
  * The blocking could be done before the write call instead, which might better mimic a hardware dma buffer of buffer_time size, in that samples can't be written until there is a slot available
  * The waiting is done using nanosleep because the only way I could see to be notified when audio_info.play.eof is incremented otherwise is to use SIGPOLL, which GStreamer cannot do as a support library, because it involves installing a global signal handler that the app might want. 

Created attachment 77998 [details] [review]
Patch update

Oops, updated patch that fixes a typo in the _delay() calculation, and removes a g_print debug line that shouldn't have stayed in.

After sleeping on it, I'm thinking that I'd like to try a solution that uses a control socket (a la fdsrc/fdsink in GStreamer core) with poll+timeout instead of nanosleep. 

That would allow the reset function to abort the write thread sooner than whenever the next nanosleep wakes up (which is up to 5 ms with the default latency_time)

I'll cook a patch for that later and see whether it works better. In the meantime, the above patch works fine for me

Created attachment 78032 [details] [review]
Patch update for stuttering problems

This update uses a mutex/cond pair to wake up the write thread when it is sleeping.

        * sys/sunaudio/gstsunaudiomixerctrl.c:
        * sys/sunaudio/gstsunaudiosrc.c:

        Use the sunaudio debug category.

        * sys/sunaudio/gstsunaudiosink.c: (gst_sunaudiosink_finalize),
        (gst_sunaudiosink_class_init), (gst_sunaudiosink_init),
        (gst_sunaudiosink_set_property), (gst_sunaudiosink_get_property),
        (gst_sunaudiosink_open), (gst_sunaudiosink_close),
        (gst_sunaudiosink_prepare), (gst_sunaudio_sink_do_delay),
        (gst_sunaudiosink_write), (gst_sunaudiosink_delay),
        (gst_sunaudiosink_reset):
        * sys/sunaudio/gstsunaudiosink.h:

        Uses the sunaudio debug category for all debug output
        Implements the _delay() callback to synchronise video playback better
        Change the segtotal and segsize values back to the parent class 
          defaults (taken from buffer_time and latency_times of 200ms and 10ms
          respectively)
        Measure the samples written to the device vs. played.
        Keep track of segments in the device by writing empty eof frames, and
        sleep using a GCond when we get too far ahead and risk overrunning the
        sink's ringbuffer.

        Fixes: #360673