Underrun on Jade controller...

Underrun on Jade controller...

[Sandulescu Bogdan]

Hello ALSA community.

I'm an User-Space application developer, using the ALSA library to play mixed sounds. My application (and for that matter also aplay) are having one underrun problem, and I need help on how to interpret the following debug information and receive some possible workarounds/solutions.

The underrun occurs only: once after writei() was performed with get_buffer_size bytes  written, and try to do another writei().

Target: Fujitsu Jade microcontroller

ALSA: 1.0.25

ALSA PCM interface for Jade-xxsvideo: /kernel/linux-2.6.31.4/sound/soc/xxsvideo/jade-pcm.c

DMA driver: /kernel/linux-2.6.31.4/arch/arm/mach-xxsvideo/dma.c


Here are the traces I managed to do, if there is any other information needed, please ask me for it.

Application trace:
[line: 1297 ]: Trying to open the ALSA plugin = plug:'dmix:RATE=8000'
 [463379 ms] : Play ThreadID [1126167328]: before open ALSA
[line: 1313 ]: Play Sound No: 0, Sound name: Snd_000.wav - from Thread-ID: 1126167328
 [463417 ms] : Play ThreadID [1126167328]: before setting parameters
[line: 1377 ]: 16 Bit format
[line: 1386 ]: Channel count: 1
[line: 1394 ]: Sample rate: 8000
[line: 1473 ]: Period size = 1024 ; Buffer size = 4096
[line: 1514 ]: Start threshold = 4096
 [463441 ms] : Play ThreadID [1126167328]: after parmas ended
 [463442 ms] : Play ThreadID [1126167328]: before malloc
 [463442 ms] : Play ThreadID [1126167328]: before reading/writing
[line: 1691 ]: Writei() ended, bytes written = 2048, available bytes to be written = 2048
[line: 1691 ]: Writei() ended, bytes written = 2048, available bytes to be written = 48
underrun!!! (at least 0.019 ms long)
[line: 1660 ]: Underrun encountered: status = -32
ALSA lib pcm.c:7339:(snd_pcm_recover) underrun occurred
[line: 1691 ]: Writei() ended, bytes written = 0, available bytes to be written = 4096
[line: 1691 ]: Writei() ended, bytes written = 2048, available bytes to be written = 2048
[line: 1615 ]: Add silence in last buffer, with size = 1948
[line: 1691 ]: Writei() ended, bytes written = 2048, available bytes to be written = 64
 [463526 ms] : Play ThreadID [1126167328]: after reading/writing fully ended
 [464152 ms] : Play ThreadID [1126167328]: after ALSA drain


X_RUN DEBUG TRACE:
echo 1 > /proc/asound/card0/pcm0p/xrun_debug

ALSA /home/kernel/linux-2.6.31.4/sound/core/pcm_lib.c:330: PCM: Lost interrupts? (stream=0, delta=15360, intr_ptr=1024)
ALSA /home/kernel/linux-2.6.31.4/sound/core/pcm_lib.c:266: PCM: Unexpected hw_pointer value (stream=0, pos=0, intr_ptr=17408)
ALSA /home/kernel/linux-2.6.31.4/sound/core/pcm_lib.c:266: PCM: Unexpected hw_pointer value (stream=0, pos=1024, intr_ptr=18432)
ALSA /home/kernel/linux-2.6.31.4/sound/core/pcm_lib.c:266: PCM: Unexpected hw_pointer value (stream=0, pos=2048, intr_ptr=19456)
ALSA /home/kernel/linux-2.6.31.4/sound/core/pcm_lib.c:266: PCM: Unexpected hw_pointer value (stream=0, pos=3072, intr_ptr=20480)
ALSA /home/kernel/linux-2.6.31.4/sound/core/pcm_lib.c:266: PCM: Unexpected hw_pointer value (stream=0, pos=4096, intr_ptr=21504)
ALSA /home/kernel/linux-2.6.31.4/sound/core/pcm_lib.c:266: PCM: Unexpected hw_pointer value (stream=0, pos=5120, intr_ptr=22528)
ALSA /home/kernel/linux-2.6.31.4/sound/core/pcm_lib.c:266: PCM: Unexpected hw_pointer value (stream=0, pos=6144, intr_ptr=23552)
ALSA /home/kernel/linux-2.6.31.4/sound/core/pcm_lib.c:266: PCM: Unexpected hw_pointer value (stream=0, pos=7168, intr_ptr=24576)
ALSA /home/kernel/linux-2.6.31.4/sound/core/pcm_lib.c:266: PCM: Unexpected hw_pointer value (stream=0, pos=8192, intr_ptr=25600)


Additional note:
using the :
#echo 2 > /proc/asound/card0/pcm0p/xrun_debug
there are no more underruns occurrences!! And this seems to be normal, according to Procfile.txt description from Takashi Iwai (...can be lead to too much corrections for a (mostly buggy) hardware that doesn't give smooth pointer updates)

Thank you for any information and help given.

Re: Underrun on Jade controller...

[Daniel Mack]

On 23.11.2012 11:05, Sandulescu Bogdan wrote:
> I'm an User-Space application developer, using the ALSA library to
> play mixed sounds. My application (and for that matter also aplay)
> are having one underrun problem, and I need help on how to interpret
> the following debug information and receive some possible
> workarounds/solutions.
> 
> The underrun occurs only: once after writei() was performed with
> get_buffer_size bytes  written, and try to do another writei().
> 
> Target: Fujitsu Jade microcontroller
> 
> ALSA: 1.0.25
> 
> ALSA PCM interface for Jade-xxsvideo:
> /kernel/linux-2.6.31.4/sound/soc/xxsvideo/jade-pcm.c
> 
> DMA driver: /kernel/linux-2.6.31.4/arch/arm/mach-xxsvideo/dma.c

Neither the ARM platform code nor the ASoC parts are present in mainline.

> Here are the traces I managed to do, if there is any other
> information needed, please ask me for it.

Without providing any code, I guess nobody on this list will be able to
help you.


Daniel

Re: Underrun on Jade controller...

[Sandulescu Bogdan]

Daniel Mack <zonque <at> gmail.com> writes:
> 
> Without providing any code, I guess nobody on this list will be able to
> help you.
> 
> Daniel
> 


OK. Here is the essential part of my code - settings and write to ALSA:

PlayThread()
{
...

    /********************************* SET PARAMS ******************/    
    /* Set HW Parameters, based on .wav header settings */
        ...
           /* APLAY settings */
         if (buffer_time == 0 && buffer_frames == 0)
            {
            iCheckErrorState =
snd_pcm_hw_params_get_buffer_time_max(pcmHwParameterCfg, &buffer_time, 0);
            if (iCheckErrorState < 0)
               {
               iStatus = -1; /* set erroneous state */
               }
            if (buffer_time > 500000)
               {
               buffer_time = 500000;
               }
            }
         if (period_time == 0 && period_frames == 0)
            {
            if (buffer_time > 0)
               {
               period_time = buffer_time / 4;
               }
            else
               {
               period_frames = buffer_frames / 4;
               }
            }
         if (period_time > 0)
            {
               period_time = 500000;    /* restrict /smaller period time */
            iCheckErrorState =
snd_pcm_hw_params_set_period_time_near(pPcmPlayHandle, pcmHwParameterCfg,
                                                         &period_time, 0);
            }
         else
            {
            iCheckErrorState =
snd_pcm_hw_params_set_period_size_near(pPcmPlayHandle, pcmHwParameterCfg,
                                                         &period_frames, 0);
            }
         if (iCheckErrorState < 0)
            {
            iStatus = -1; /* set erroneous state */
            }
         if (buffer_time > 0)
            {
            iCheckErrorState =
snd_pcm_hw_params_set_buffer_time_near(pPcmPlayHandle, pcmHwParameterCfg,
                                                         &buffer_time, 0);
            }
         else
            {
            iCheckErrorState =
snd_pcm_hw_params_set_buffer_size_near(pPcmPlayHandle, pcmHwParameterCfg,
                                                         &buffer_frames);
            }
         if (iCheckErrorState < 0)
            {
            iStatus = -1; /* set erroneous state */
            }

         iCheckErrorState = snd_pcm_hw_params(pPcmPlayHandle, pcmHwParameterCfg);
         if (iCheckErrorState != 0)
            {
            iStatus = -1;
            }
         snd_pcm_hw_params_get_period_size(pcmHwParameterCfg, &pcmPeriodSize, 0);
         snd_pcm_hw_params_get_buffer_size(pcmHwParameterCfg, &pcmBufferSize);

         fprintf(stderr,"Period size = %lu ; Buffer size = %lu \n",
pcmPeriodSize, pcmBufferSize);

         if (pcmPeriodSize == pcmBufferSize)
            {
            fprintf(stderr,"Can't use period equal to buffer size (%lu == %lu)",
pcmPeriodSize, pcmBufferSize);
            }

         snd_pcm_sw_params_current(pPcmPlayHandle, pcmSWParameterCfg);
         if (avail_min < 0)
            {
            n = pcmPeriodSize;
            }
         else
            {
            n = (double) rate * avail_min / 1000000;
            }
         iCheckErrorState = snd_pcm_sw_params_set_avail_min(pPcmPlayHandle,
pcmSWParameterCfg, n);
         
         /* round up to closest transfer boundary */
         n = pcmBufferSize;
         if (start_delay <= 0)
            {
            start_threshold = n + (double) rate * start_delay / 1000000;
            }
         else
            {
            start_threshold = (double) rate * start_delay / 1000000;
            }
         if (start_threshold < 1)
            {
            start_threshold = 1;
            }
         if (start_threshold > n)
            {
            start_threshold = n;
            }

         iCheckErrorState =
snd_pcm_sw_params_set_start_threshold(pPcmPlayHandle, pcmSWParameterCfg,
start_threshold);
         if (iCheckErrorState < 0)
            {
            iStatus = -1; /* set erroneous state */
            }

         fprintf(stderr,"Start threshold = %lu \n",start_threshold);

         if (stop_delay <= 0)
            {
            stop_threshold = pcmBufferSize + (double) rate * stop_delay / 1000000;
            }
         else
            {
            stop_threshold = (double) rate * stop_delay / 1000000;
            }

         iCheckErrorState = snd_pcm_sw_params_set_stop_threshold(pPcmPlayHandle,
pcmSWParameterCfg, stop_threshold);
         if (iCheckErrorState < 0)
            {
            iStatus = -1; /* set erroneous state */
            }

         if (snd_pcm_sw_params(pPcmPlayHandle, pcmSWParameterCfg) < 0)
            {
            fprintf(stderr,"Unable to install sw parameters, exit thread \n");
            iStatus = -1; /* set erroneous state */
            }

         fprintf(stderr,"Play ThreadID [%lu]: after parmas ended\n",
pthread_self());
     /* END APLAY settings */
         /*********************************END SET PARAMS ******************/
         /* Check if the Settings were correctly done or not */
         if (iStatus < 0)
            {
            fprintf(stderr,"Could not SET correctly the wav settings! \n");
        /* ... do something */
            }
         else
            {
            /* Finished operation with Settings, continue processing */
                 /*Now we've set up our device, but we still can't write to it.
There's one last step we have to take: prepare the device */
                 snd_pcm_prepare (pPcmPlayHandle);
            
            
                 /* NOTE: cannot use to malloc the entire wav file size, as this
leads to: frequent overrun (more data in output buffer),
                  * and the User-Space app runtime memory is increased with wav
file size; Hence, is better to use the ALSA pcm buffer sizes. */

            iBufferSize = pcmBufferSize;

            TimeStamp("Play ThreadID [%lu]: before malloc\n", pthread_self());
            fprintf(stderr,"About to allocate %u buffer...\n", iBufferSize);

            pu8WavDataBuf = (uint8*) malloc( (size_t) iBufferSize);
            if (pu8WavDataBuf != NULL)
               {
                  /* Data allocation successful continue with play... */
               fprintf(stderr,"Done allocating the buffer, start execute ALSA
play sequence...\n");

               size_t offset = 0;
               int remaining = WavSoundSize;

               Wavfp = fopen(WavPathAndName, "r");
               if (Wavfp != NULL)
                  {
                  /* Wav FILE opened OK, continue reading the data and send it
to ALSA driver */
                  TimeStamp("Play ThreadID [%lu]: before reading/writing\n",
pthread_self());
                  while (remaining > 0)
                     {
                        /* READ DATA into local buffer */
                     /* Firstly, read a block of data into buffer */
                     /********* READ DATA ********/
                     /* Normal read from wav file, with a complete a buffer size */
                        iStatus = fread(pu8WavDataBuf, sizeof(uint8),
iBufferSize , Wavfp);
                     /********** END READ DATA ****************/

                     /* Secondly, output that buffer to ALSA driver */
                     iStatus = snd_pcm_writei(pPcmPlayHandle, pu8WavDataBuf,
iBufferSize / (stHWSettings.format * stHWSettings.channels) );
                     if (iStatus == -EAGAIN || (iStatus >= 0 && (
(size_t)iStatus < iBufferSize / (stHWSettings.format * stHWSettings.channels)  ) ))
                        {
                        /* The ALSA ring buffer is full, wait some small time to
flush parts of data, so we can fill it with rest of .wav data */
                        fprintf(stderr,"The ALSA ring buffer is full, wait some
small time to flush parts of data \n");
                        snd_pcm_wait(pPcmPlayHandle, 10);
                        }
                     else
                        {
                        if (iStatus == -EPIPE)
                           {
                           /* In some cases, it might happen that this thread
does not feed new samples in time to alsa-lib (due to high CPU usage - thread
interrupted often -
                            * or large delay between consecutive writei()
calls). Therefore, we must prepare/recover the PCM handle for next usage.
                            */

                            /* Print delay time */
                            snd_pcm_status_t *status;
                            snd_pcm_status_alloca(&status);
                            if ((snd_pcm_status(pPcmPlayHandle, status))<0) {
                                fprintf(stderr, "some error \n");
                            }
                            struct timespec now, diff, tstamp;
                            clock_gettime(CLOCK_MONOTONIC, &now);
                            snd_pcm_status_get_trigger_htstamp(status, &tstamp);
                            timermsub(&now, &tstamp, &diff);
                            fprintf(stderr,"underrun!!! (at least %.3f ms long)\n",
diff.tv_sec * 1000 + diff.tv_nsec / 10000000.0);

                            fprintf(stderr,"Underrun encountered: application
didn't sent enough data to the ALSA buffer, status = %d \n", iStatus);
                           iStatus = snd_pcm_recover(pPcmPlayHandle,iStatus,0 );
                           }
                        else
                           {
                           if (iStatus == -ESTRPIPE)
                              {
                /* ignore it */
                              }
                           else
                              {
                              if (iStatus < 0)
                                 {
                       /* ignore it */
                                 }
                              else
                                 {
                                 /* Write performed OK */
                                 }
                              }
                           }
                        }
                     /* Use the pcm_avail_update() only for checking buffer
playback fill level - not for SYNCHRONISATION */
                     snd_pcm_sframes_t pcmAvailBytes;
                     pcmAvailBytes = snd_pcm_avail_update(pPcmPlayHandle);
                     
                     offset = offset +  ( iStatus * (stHWSettings.format *
stHWSettings.channels));
                     remaining = remaining -  ( iStatus * (stHWSettings.format *
stHWSettings.channels));
                     
                      fprintf(stderr,"Writei() ended, bytes written = %d,
available bytes to be written = %lu\n", iStatus, pcmAvailBytes);
                     }

                  TimeStamp("Play ThreadID [%lu]: after reading/writing fully
ended\n", pthread_self());
                  /* Finished reading the wav file, now it's time to close it */
                  fclose(Wavfp);
                     /* Done the complete output, now drain/reset the ALSA device */
                     snd_pcm_nonblock(pPcmPlayHandle, 0);
                     snd_pcm_drain(pPcmPlayHandle);
                     snd_pcm_nonblock(pPcmPlayHandle, 0);
...
}

Re: Underrun on Jade controller...

[Daniel Mack]

On 23.11.2012 11:35, Sandulescu Bogdan wrote:
> 
> Daniel Mack <zonque <at> gmail.com> writes:
>>
>> Without providing any code, I guess nobody on this list will be able to
>> help you.
>>
>> Daniel
>>
> 
> 
> OK. Here is the essential part of my code - settings and write to ALSA:

It's not about the userspace code in the first place but the kernel part.

I guess you are based on a BSP kernel that the vendor of the
chip/module/board you are using provides. For whatever reason, this
vendor has decided to not push its code to the mainline kernel but keep
changes in a private repository.

While this is a common approach, your vendor is the only instance in the
game that is in charge of supporting you here. The community can't, as
the code has not been shared for discussion and integration in mainline.


Daniel

Re: Underrun on Jade controller...

[Sandulescu Bogdan]

> On 23.11.2012 11:35, Sandulescu Bogdan wrote:
> > 
> > Daniel Mack <zonque <at> gmail.com> writes:
> >>
> >> Without providing any code, I guess nobody on this list will be able to
> >> help you.
> >>
> >> Daniel
> >>
> > 
> > 
> > OK. Here is the essential part of my code - settings and write to ALSA:
> 
> It's not about the userspace code in the first place but the kernel part.
> 
> I guess you are based on a BSP kernel that the vendor of the
> chip/module/board you are using provides. For whatever reason, this
> vendor has decided to not push its code to the mainline kernel but keep
> changes in a private repository.
> 
> While this is a common approach, your vendor is the only instance in the
> game that is in charge of supporting you here. The community can't, as
> the code has not been shared for discussion and integration in mainline.
> 
> Daniel
> 
> 


Hello Daniel,

Thank you for your answer. Initially I thought I should share my app, as every information I got regarding underruns was that the application is not feeding data fast enough - hence I thought it was my application's fault.

Considering your precise answer, I will try to get support directly from the module vendor.

Yours,
    Bogdan

Re: Underrun on Jade controller...

[Daniel Mack]

On 23.11.2012 13:54, Sandulescu Bogdan wrote:
>> On 23.11.2012 11:35, Sandulescu Bogdan wrote:
>> >
>> > Daniel Mack <zonque <at> gmail.com> writes:
>> >>
>> >> Without providing any code, I guess nobody on this list will be able to
>> >> help you.
>> >>
>> >> Daniel
>> >>
>> >
>> >
>> > OK. Here is the essential part of my code - settings and write to ALSA:
>>
>> It's not about the userspace code in the first place but the kernel part.
>>
>> I guess you are based on a BSP kernel that the vendor of the
>> chip/module/board you are using provides. For whatever reason, this
>> vendor has decided to not push its code to the mainline kernel but keep
>> changes in a private repository.
>>
>> While this is a common approach, your vendor is the only instance in the
>> game that is in charge of supporting you here. The community can't, as
>> the code has not been shared for discussion and integration in mainline.
>>
>> Daniel
>>
>>
> 
> Hello Daniel,
> 
> Thank you for your answer. Initially I thought I should share my app, as
> every information I got regarding underruns was that the application is
> not feeding data fast enough - hence I thought it was my application's
> fault.
> 
> Considering your precise answer, I will try to get support directly from
> the module vendor.

... and make them push their changes to mainline already, as this is
your only option to keep up-to-date with all the continously added new
features in mainline. Rebasing vendor patches has always caused major
headache an much more work on the long run.


Daniel