Attachment 316691 Details for Bug 462200 – Analysis of a similar problem

Analysis of a similar problem

pulseaudio.txt (text/plain), 7.99 KB, created by Alexander Gavrilov on 2008-09-14 15:24:10 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Alexander Gavrilov

Created: 2008-09-14 15:24:10 UTC

Size: 7.99 KB

patch

obsolete

>In thread_func, 'n' has insanely huge values:
>  
>  Breakpoint 7, thread_func (userdata=0x8788958) at modules/module-alsa-sink.c:210
>  210             if (frames >= (snd_pcm_uframes_t) n)
>  (gdb) x/1 0xb7c072f8
>  0xb7c072f8:     0x00001100
>  (gdb) n
>  112     PA_DECLARE_CLASS(pa_sink);
>  (gdb)
>  130             if ((n = snd_pcm_avail_update(u->pcm_handle)) < 0) {
>  (gdb)
>  149             if (n <= 0)
>  (gdb) n
>  154             if ((err = snd_pcm_mmap_begin(u->pcm_handle, &areas, &offset, &frames)) < 0) {
>  (gdb)
>  152             frames = n;
>  (gdb)
>  154             if ((err = snd_pcm_mmap_begin(u->pcm_handle, &areas, &offset, &frames)) < 0) {
>  (gdb) x/1 0xb7c072f8
>  0xb7c072f8:     0x3c4d7a40    
>      -- this is the value of the frames variable
>
>Because of this the loop never ends, and CPU time limit is exhausted.
>
>The value comes from
>
>  2396    snd_pcm_sframes_t snd_pcm_avail_update(snd_pcm_t *pcm)               
>  2397    {                                                                    
>  2398            return pcm->fast_ops->avail_update(pcm->fast_op_arg);        
>  2399    }
>
>which calls
>
>  978     static snd_pcm_sframes_t snd_pcm_hw_avail_update(snd_pcm_t *pcm)
>  979     {                                                               
>  980             snd_pcm_hw_t *hw = pcm->private_data;                   
>  981             snd_pcm_uframes_t avail;                                
>  982                                                                     
>  983             sync_ptr(hw, 0);                                        
>  984             avail = snd_pcm_mmap_avail(pcm);                        
>  (gdb)                                                                   
>  985             switch (FAST_PCM_STATE(hw)) {
>  986             case SNDRV_PCM_STATE_RUNNING:                           
>  987                     if (avail >= pcm->stop_threshold) {             
>  988                             /* SNDRV_PCM_IOCTL_XRUN ioctl has been implemented since PCM kernel API 2.0.1 */
>  989                             if (SNDRV_PROTOCOL_VERSION(2, 0, 1) <= hw->version) {                           
>  990                                     if (ioctl(hw->fd, SNDRV_PCM_IOCTL_XRUN) < 0)                            
>  991                                             return -errno;                                                  
>  992                             }                                                                               
>  993                             /* everything is ok, state == SND_PCM_STATE_XRUN at the moment */               
>  994                             return -EPIPE;                                                                  
>  (gdb)                                                                                                           
>  995                     }                                                                                       
>  996                     break;                                                                                  
>  997             case SNDRV_PCM_STATE_XRUN:                                                                      
>  998                     return -EPIPE;                                                                          
>  999             default:                                                                                        
>  1000                    break;                                                                                  
>  1001            }                                                                                               
>  1002            return avail;                                                                                   
>  1003    }
>
>which uses
>
>  414     static inline snd_pcm_uframes_t snd_pcm_mmap_playback_avail(snd_pcm_t *pcm)
>  415     {                                                                          
>  416             snd_pcm_sframes_t avail;                                           
>  417             avail = *pcm->hw.ptr + pcm->buffer_size - *pcm->appl.ptr;          
>  418             if (avail < 0)                                                     
>  419                     avail += pcm->boundary;                                    
>  420             else if ((snd_pcm_uframes_t) avail >= pcm->boundary)               
>  421                     avail -= pcm->boundary;                                    
>  422             return avail;
>
>where
>
>  (gdb) p *((snd_pcm_t*)0x087c4d18)->hw.ptr
>  $218 = 66023112
>      -- and grows
>  
>  (gdb) p *((snd_pcm_t*)0x087c4d18)->appl.ptr
>  $219 = 134455040
>
>  (gdb) p ((snd_pcm_t*)0x087c4d18)->buffer_size
>  $223 = 4352
>
>thus the value is negative, and
>
>  (gdb) p ((snd_pcm_t*)0x087c4d18)->boundary
>  $224 = 1140850688
>  
>gets added; EPIPE is not returned because
>
>  (gdb) p ((snd_pcm_t*)0x087c4d18)->stop_threshold
>  $225 = 4294967295
>  
>A breakpoint set on this line shows such figures:
>
>  Breakpoint 10, snd_pcm_hw_avail_update (pcm=0x962dd30) at pcm_local.h:430
>  430                     avail += pcm->boundary;
>  3: *pcm->hw.ptr + pcm->buffer_size = 32569296
>  2: *pcm->appl.ptr = 32569352
>  1: *pcm->hw.ptr = 32564944
>
>Further tracing with a hardware watchpoint
>
>  (gdb) info break 16
>  Num     Type           Disp Enb Address    What
>  16      hw watchpoint  keep y              *(int *) 3081981952
>	  stop only if *(int*)0xb7b36008 + 4352 - *(int*)0xb7b35000 < 0
>	  breakpoint already hit 10105 times
>	  silent
>	  printf "delta %d (%d, %d)\n", (*(int*)0xb7b36008 + 4352 - *(int*)0xb7b35000), (*(int*)0xb7b36008 + 4352), *(int*)0xb7b35000
>	  cont
>
>  delta 1352 (180947456, 180946104)                     
>  delta 0 (180947456, 180947456)                        
>  delta 1088 (180949632, 180948544)                     
>  delta 0 (180949632, 180949632)                        
>  delta 1360 (180953168, 180951808)                     
>  delta 0 (180953168, 180953168)                        
>  delta 272 (180955072, 180954800)                      
>  delta 0 (180955072, 180955072)                        
>  delta 0 (180955592, 180955592)                        
>  delta 0 (180956160, 180956160)                        
>  delta 0 (180960016, 180960016)                        
>
>Shows that *pcm->hw.ptr apparently gets decremented somewhere:
>
>  Breakpoint 10, snd_pcm_hw_avail_update (pcm=0x962dd30) at pcm_local.h:430
>  430                     avail += pcm->boundary;                          
>  5: ((struct _snd_pcm *) 157474096)->buffer_size = 4352                   
>  4: *((struct _snd_pcm *) 157474096)->hw.ptr + ((struct _snd_pcm *) 157474096)->buffer_size - *((struct _snd_pcm *) 157474096)->appl.ptr = 4294965768
>  3: *pcm->hw.ptr + pcm->buffer_size = 180958488                                                                                                      
>  2: *pcm->appl.ptr = 180960016                                                                                                                       
>  1: *pcm->hw.ptr = 180954136 
>
>as 180958488 is less than 180960016 shown by the watchpoint.
>
>Setting a watchpoint on *pcm->hw.ptr doesn't work, as it is
>a kernel variable.
>
>However, tracing the values from the proc filesystem does show
>some anomalies (this requires very frequent polling and a bit of luck):
>
>  nice -n -10 sh -c 'while true; do date +%M:%S.%N; grep _ptr < /proc/asound/card0/pcm0p/sub0/status; done > /tmp/hwlog'
>
>  41:22.953791921
>  hw_ptr      : 74627736
>  appl_ptr    : 74631360
>  41:22.967029353
>  hw_ptr      : 74628976
>  appl_ptr    : 74632448
>  41:23.053130038
>  hw_ptr      : 74632072
>  appl_ptr    : 74636168
>  41:23.164889662
>  hw_ptr      : 74636376
>  appl_ptr    : 74640728
>  41:23.222819090
>  hw_ptr      : 74635288  <<<<
>  appl_ptr    : 74640728
>  41:23.234607753
>  hw_ptr      : 74637216
>  appl_ptr    : 74640728
>  41:23.274271946
>  hw_ptr      : 74637512
>  appl_ptr    : 74640728
>
>  Breakpoint 10, snd_pcm_hw_avail_update (pcm=0x8268d40) at pcm_local.h:430
>  430                     avail += pcm->boundary;
>  8: *pcm->appl.ptr = 74640728
>  7: *pcm->hw.ptr + pcm->buffer_size = 74638976
>  6: *pcm->hw.ptr = 74634624

Actions: View

Attachments on bug 462200: 316675 | 316691 | 316695 | 320901 | 321372 | 321388 | 321400 | 321431 | 321485 | 321529 | 321551 | 322163 | 322164