[pjsip] pjsua: audio bursting

Nanang Izzuddin nanang at pjsip.org
Fri Dec 4 15:56:08 CST 2009 

Hi Peter,

Please check troubleshooting sound problems on wiki [1].

Such problem could be triggered by high-burst or clock-drift in audio
device, which is usually caused by CPU load/spikes. This pjsystest
tool may be able to help examining audio device behaviour [2].

---
[1] http://trac.pjsip.org/repos/wiki/sound-problems
[2] http://trac.pjsip.org/repos/wiki/Testing_Audio_Device_with_pjsystest
---

BR,
nanang


On Fri, Nov 27, 2009 at 5:35 PM, Peter Lukac <p.lukac at emtest.sk> wrote:
> hello again :)
> Can me somebody explain what does mean these logs?
>
> 233 samples reduced, buf_cnt=877
> JB shrinking 1 frame(s), cur size=32
> jb updated(1), prefetch=12, size=33
> Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>
> -------------------------------------------------------------
> 233 samples reduced, buf_cnt=877
> -------------------------------------------------------------
> this log is generate with function
>
> /* This function will erase samples from delay buffer.
>  * The number of erased samples is guaranteed to be >= erase_cnt.
>  */
> static void shrink_buffer(pjmedia_delay_buf *b, unsigned erase_cnt)
>
> why is sample erase from buffer..buffer is too smal? or write stream is bigger
> than read stream?
>
> -------------------------------------------------------------
> Master/sound  Underflow, buf_cnt=0, will generate 1 frame
> -------------------------------------------------------------
> And what is this.. No data in "sound buffer"? If yes...why?
>
> I have problem with audio... i using sample application pjsua.. but when i
> calling i hear bursting...
>
> when i compile with empty config_site.h config and run pjsua as:
>
> ./pjsua-arm-unknown-linux-gnu --id sip:pc3 at 192.168.32.123 --registrar
> sip:192.168.32.123 --realm asterisk --username pc3 --password heslo  --auto-
> answer 200 --app-log-level=5 --playback-dev=1 --clock-rate=8000 --snd-clock-
> rate=8000  --play-file ./samples/test8000.wav --no-vad
>
> i get lot of these logs:
>
> 10:15:30.879   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:30.901     ec0x2581d0  50 samples reduced, buf_cnt=930
>  10:15:30.905   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:30.909   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:30.921     ec0x2581d0  166 samples reduced, buf_cnt=924
>  10:15:30.933     ec0x2581d0  143 samples reduced, buf_cnt=941
>  10:15:30.963   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:30.969   strm0x27baec  jb updated(1), prefetch=23, size=39
>  10:15:30.976     ec0x2581d0  266 samples reduced, buf_cnt=835
>  10:15:30.993   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:31.004     ec0x2581d0  46 samples reduced, buf_cnt=949
>  10:15:31.007   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:31.016   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:31.027     ec0x2581d0  245 samples reduced, buf_cnt=864
>  10:15:31.030   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:31.047     ec0x2581d0  77 samples reduced, buf_cnt=947
>  10:15:31.055     ec0x2581d0  162 samples reduced, buf_cnt=945
>  10:15:31.083   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:31.104     ec0x2581d0  293 samples reduced, buf_cnt=812
>  10:15:31.107   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:31.115     ec0x2581d0  49 samples reduced, buf_cnt=923
>  10:15:31.120   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:31.141     ec0x2581d0  145 samples reduced, buf_cnt=938
>  10:15:31.153   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:31.166     ec0x2581d0  231 samples reduced, buf_cnt=867
>  10:15:31.183   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:31.194     ec0x2581d0  97 samples reduced, buf_cnt=930
>  10:15:31.200   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:31.218     ec0x2581d0  188 samples reduced, buf_cnt=902
>  10:15:31.228   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>  10:15:31.260     ec0x2581d0  108 samples reduced, buf_cnt=954
>  10:15:31.263   Master/sound  Underflow, buf_cnt=0, will generate 1 frame
>
>
> but when i run with paramter
>
> --ec-tail=0
>
> i get these logs:
>
> 10:19:01.011   strm0x26774c  JB shrinking 1 frame(s), cur size=41
>  10:19:01.211   strm0x26774c  JB shrinking 1 frame(s), cur size=38
>  10:19:01.411   strm0x26774c  JB shrinking 1 frame(s), cur size=37
>  10:19:01.611   strm0x26774c  JB shrinking 1 frame(s), cur size=38
>  10:19:01.811   strm0x26774c  JB shrinking 1 frame(s), cur size=37
>  10:19:02.011   strm0x26774c  JB shrinking 1 frame(s), cur size=34
>  10:19:02.214   strm0x26774c  JB shrinking 1 frame(s), cur size=34
>  10:19:02.438   strm0x26774c  JB shrinking 1 frame(s), cur size=34
>  10:19:02.663   strm0x26774c  JB shrinking 1 frame(s), cur size=34
>  10:19:03.333   strm0x26774c  JB shrinking 1 frame(s), cur size=34
>  10:19:03.353   Master/sound  Underflow, buf_cnt=44, will generate 1 frame
>  10:19:03.661   strm0x26774c  JB shrinking 1 frame(s), cur size=34
>  10:19:03.668   Master/sound  172 samples reduced, buf_cnt=672
>  10:19:04.196   strm0x26774c  JB shrinking 1 frame(s), cur size=34
>  10:19:04.311   strm0x26774c  jb updated(2), prefetch=22, size=48
>  10:19:04.684   strm0x26774c  JB shrinking 1 frame(s), cur size=44
>  10:19:04.691   Master/sound  92 samples reduced, buf_cnt=740
>  10:19:04.729   Master/sound  164 samples reduced, buf_cnt=736
>  10:19:04.767   Master/sound  235 samples reduced, buf_cnt=661
>  10:19:04.797   Master/sound  37 samples reduced, buf_cnt=784
>  10:19:04.818   Master/sound  161 samples reduced, buf_cnt=783
>  10:19:04.831   Master/sound  160 samples reduced, buf_cnt=783
>  10:19:04.839   Master/sound  273 samples reduced, buf_cnt=670
>  10:19:04.847   Master/sound  128 samples reduced, buf_cnt=702
>  10:19:04.935   Master/sound  189 samples reduced, buf_cnt=673
>  10:19:04.943   strm0x26774c  jb updated(2), prefetch=32, size=43
>  10:19:08.171   strm0x26774c  jb updated(1), prefetch=31, size=45
>  10:19:11.411   strm0x26774c  jb updated(1), prefetch=22, size=45
>  10:19:11.413   strm0x26774c  JB shrinking 1 frame(s), cur size=44
>  10:19:11.622   strm0x26774c  JB shrinking 1 frame(s), cur size=44
>  10:19:12.653   strm0x26774c  JB shrinking 1 frame(s), cur size=44
>  10:19:12.795   Master/sound  170 samples reduced, buf_cnt=663
>  10:19:12.814   Master/sound  131 samples reduced, buf_cnt=692
>  10:19:12.827   Master/sound  103 samples reduced, buf_cnt=749
>  10:19:12.857   Master/sound  200 samples reduced, buf_cnt=709
>  10:19:12.898   Master/sound  174 samples reduced, buf_cnt=695
>  10:19:12.928   Master/sound  187 samples reduced, buf_cnt=668
>  10:19:12.902   strm0x26774c  JB shrinking 1 frame(s), cur size=44
>  10:19:12.983   strm0x26774c  jb updated(2), prefetch=26, size=39
>  10:19:13.602    pjsua_acc.c  Sending 2 bytes keep-alive packet for acc 2 to
> 192.168.32.123:5060
>  10:19:13.608   tdta0x25f0f0  Destroying txdata raw
>  10:19:13.636   Master/sound  76 samples reduced, buf_cnt=752
>
>
> when i compile project with config_site.h
>
> #define PJMEDIA_CONF_USE_SWITCH_BOARD     1.
> #define PJMEDIA_WSOLA_IMP   PJMEDIA_WSOLA_IMP_WSOLA_LITE
>
> Is it better. (sound bursting sometimes ..i think when  JB shrinking log is
> occured )
>
> and i get lot of logs like this:
>
>
> without --ec-tail=0
>
>  11:21:43.271   strm0x27bfc4  JB shrinking 1 frame(s), cur size=29
>  11:21:43.274     ec0x250268  239 samples reduced, buf_cnt=826
>  11:21:43.293     ec0x250268  104 samples reduced, buf_cnt=882
>  11:21:43.313     ec0x250268  162 samples reduced, buf_cnt=880
>  11:21:43.332     ec0x250268  156 samples reduced, buf_cnt=884
>  11:21:43.353     ec0x250268  188 samples reduced, buf_cnt=856
>  11:21:43.384     ec0x250268  83 samples reduced, buf_cnt=933
>  11:21:43.394     ec0x250268  164 samples reduced, buf_cnt=929
>  11:21:43.422     ec0x250268  202 samples reduced, buf_cnt=887
>  11:21:43.444     ec0x250268  99 samples reduced, buf_cnt=948
>  11:21:43.464     ec0x250268  265 samples reduced, buf_cnt=843
>  11:21:43.479   strm0x27bfc4  JB shrinking 1 frame(s), cur size=30
>  11:21:43.482     ec0x250268  122 samples reduced, buf_cnt=881
>  11:21:43.534     ec0x250268  99 samples reduced, buf_cnt=942
>  11:21:43.544     ec0x250268  244 samples reduced, buf_cnt=858
>  11:21:43.554     ec0x250268  115 samples reduced, buf_cnt=903
>  11:21:43.569     ec0x250268  248 samples reduced, buf_cnt=815
>  11:21:43.633     ec0x250268  106 samples reduced, buf_cnt=869
>  11:21:43.636     ec0x250268  176 samples reduced, buf_cnt=853
>  11:21:43.640     ec0x250268  151 samples reduced, buf_cnt=862
>  11:21:43.671   strm0x27bfc4  JB shrinking 1 frame(s), cur size=29
>
>
> with --ec-tail=0
>
> 09:42:49.105     ec0x256b70  215 samples reduced, buf_cnt=801
>  09:42:49.120   strm0x27bdc4  JB shrinking 1 frame(s), cur size=33
>  09:42:49.126     ec0x256b70  11 samples reduced, buf_cnt=950
>  09:42:49.164     ec0x256b70  233 samples reduced, buf_cnt=877
>  09:42:49.184     ec0x256b70  212 samples reduced, buf_cnt=825
>  09:42:49.224     ec0x256b70  148 samples reduced, buf_cnt=837
>  09:42:49.244     ec0x256b70  128 samples reduced, buf_cnt=869
>  09:42:49.284     ec0x256b70  212 samples reduced, buf_cnt=817
>  09:42:49.305     ec0x256b70  60 samples reduced, buf_cnt=917
>  09:42:49.320   strm0x27bdc4  JB shrinking 1 frame(s), cur size=32
>  09:42:49.344     ec0x256b70  214 samples reduced, buf_cnt=863
>
>
>>>> cl
> Conference ports:
> Port #00[ 8KHz/20ms/1]   UCB1400:  (hw:0,0)  transmitting to:
> Port #01[ 8KHz/20ms/1] ./samples/test8000.wav  transmitting to: #0
> Port #02[ 8KHz/20ms/1]             ringback  transmitting to:
> Port #03[ 8KHz/20ms/1]                 ring  transmitting to:
>
> when i run sound localy as
> cc 1 0
>
> without --ec-tail=0
>
> sound bursting sometimes
>
> i get these logs:
>
> 11:04:54.954     ec0x24d890  240 samples reduced, buf_cnt=842
>  11:04:54.974     ec0x24d890  144 samples reduced, buf_cnt=858
>  11:04:54.994     ec0x24d890  145 samples reduced, buf_cnt=873
>  11:04:55.034     ec0x24d890  144 samples reduced, buf_cnt=889
>  11:04:55.074     ec0x24d890  145 samples reduced, buf_cnt=904
>  11:04:55.114     ec0x24d890  145 samples reduced, buf_cnt=919
>  11:04:55.134     ec0x24d890  144 samples reduced, buf_cnt=935
>  11:04:55.154     ec0x24d890  289 samples reduced, buf_cnt=806
> c 11:04:55.245     ec0x24d890  142 samples reduced, buf_cnt=824
>  11:04:55.252     ec0x24d890  144 samples reduced, buf_cnt=840
> d 11:04:55.347     ec0x24d890  97 samples reduced, buf_cnt=903
>  11:04:55.368     ec0x24d890  145 samples reduced, buf_cnt=918
>  11:04:55.387     ec0x24d890  145 samples reduced, buf_cnt=933
>  11:04:55.407     ec0x24d890  289 samples reduced, buf_cnt=804
>  11:04:55.447     ec0x24d890  145 samples reduced, buf_cnt=819
>  11:04:55.529     ec0x24d890  144 samples reduced, buf_cnt=835
>  11:04:55.556     ec0x24d890  145 samples reduced, buf_cnt=850
>
>  11:04:57.875       pa_dev.c  Done, status=0
>  11:04:57.877       pa_dev.c  Closing UCB1400:  (hw:0,0): 87 underflow, 639
> overflow
>
>
> with --ec-tail=0
> all work fine.. but:
> Closing UCB1400:  (hw:0,0): 1 underflow, 6 overflow :)
>
>
> Can me somebody help where the potential problem is?
>
> Is it ARM processor and CPU load is cca 80%
>
>
>
> thanks
>
>
>
>
> _______________________________________________
> Visit our blog: http://blog.pjsip.org
>
> pjsip mailing list
> pjsip at lists.pjsip.org
> http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org
>

More information about the pjsip mailing list