Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ALSA lib pcm.c:7339:(snd_pcm_recover) underrun occurred #852

Closed
gotsiboon opened this issue Dec 13, 2012 · 31 comments
Closed

ALSA lib pcm.c:7339:(snd_pcm_recover) underrun occurred #852

gotsiboon opened this issue Dec 13, 2012 · 31 comments
Assignees

Comments

@gotsiboon
Copy link

Hi guys,

I've got "ALSA lib pcm.c:7339:(snd_pcm_recover) underrun occurred" in todays master (FreeRDP version 1.1.0-dev (git 1.0.1-1519-g1ce9e)).
I'm using these parameters:
xfreerdp /u:user /vc:rdpsnd,sys:alsa,dev:default /mic +clipboard /workarea /v:192.168.x.x:3389

BR, gotsiboon.

@jiaxi2000
Copy link

I also get this log.
By the way,can you use audio input?

@Ghost99
Copy link

Ghost99 commented Jan 30, 2013

I also have that problem with build from commit SHA: 9f8d79c on x64 Gentoo.
I'm using xfreerdp from console with "/vc:rdpsnd,sys:alsa" key, connecting to WinXP machine. I'm currently using pulseaudio as a main sound system, but with "/vc:rdpsnd,sys:pulse" is always returns:

LoadLibraryA: /usr/lib64/freerdp/rdpsnd-client-pulse.so: cannot open shared object file: No such file or directory
LoadLibraryA: /usr/lib64/freerdp/rdpsnd-client-pulse.so: cannot open shared object file: No such file or directory
ALSA lib pcm.c:7339:(snd_pcm_recover) underrun occurred

Looks like it switching back to alsa. Sound quality is bad, and sound is laggy.
But I'm happy that I can at least hear sound.

@bmiklautz
Copy link
Member

@Ghost99 the "cannot open" is "okay". FreeRDP has currently a fixed module load order for sound and it tries pulse even if it wasn't compiled.
The underrun happens if the data isn't arriving fast enough. I think the upcoming changes will fix this.

@Shumen
Copy link

Shumen commented Feb 1, 2013

@bmiklautz is it the fault of rdpsnd channel thread's priority bug? since the sound data arrive, but the rdpsnd thread doesn't process immediately and put it into the alsa's buffer, see@ http://alsa.opensrc.org/Xruns

@bmiklautz
Copy link
Member

@gotsiboon @ShuminHuang @Ghost99 can you try the latest git master and test if the problem is fixed for you?

@Ghost99
Copy link

Ghost99 commented Feb 11, 2013

SHA: c581d89
Sound lags and ALSA overruns still present.

@awakecoding
Copy link
Member

@Ghost99 can you try with +async-update +async-input ?

@Ghost99
Copy link

Ghost99 commented Feb 11, 2013

Only difference is that two of my CPU cores is now fully consumed by xfreerdp process while it is running.
Sound lags and ALSA overruns still present with +async-update +async-input.

I'm also having a SIGSEGV with +async-update +async-input
Full command: "xfreerdp /w:1280 /h:960 /vc:rdpsnd,sys:alsa /u:login '/p:password' /v:192.168.4.66 +async-update +async-input"
SIGSEGV in thread 5.

Thread 7 (Thread 0x7fffdd232700 (LWP 27835)):
#0  0x00007ffff2935633 in poll () from /lib64/libc.so.6
No symbol table info available.
#1  0x00007fffec0faed3 in ?? () from /usr/lib64/libpulse.so.0
No symbol table info available.
#2  0x00007fffec0ec2bc in pa_mainloop_poll () from /usr/lib64/libpulse.so.0
No symbol table info available.
#3  0x00007fffec0ec949 in pa_mainloop_iterate () from /usr/lib64/libpulse.so.0
No symbol table info available.
#4  0x00007fffec0eca10 in pa_mainloop_run () from /usr/lib64/libpulse.so.0
No symbol table info available.
#5  0x00007fffec0fae73 in ?? () from /usr/lib64/libpulse.so.0
No symbol table info available.
#6  0x00007fffdfbd64f7 in ?? () from /usr/lib64/pulseaudio/libpulsecommon-2.1.so
No symbol table info available.
#7  0x00007ffff2c08f06 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#8  0x00007ffff293e62d in clone () from /lib64/libc.so.6
No symbol table info available.

Thread 6 (Thread 0x7fffddc39700 (LWP 27834)):
#0  0x00007ffff2935633 in poll () from /lib64/libc.so.6
No symbol table info available.
#1  0x00007fffec0faed3 in ?? () from /usr/lib64/libpulse.so.0
No symbol table info available.
#2  0x00007fffec0ec2bc in pa_mainloop_poll () from /usr/lib64/libpulse.so.0
No symbol table info available.
#3  0x00007fffec0ec949 in pa_mainloop_iterate () from /usr/lib64/libpulse.so.0
No symbol table info available.
#4  0x00007fffec0eca10 in pa_mainloop_run () from /usr/lib64/libpulse.so.0
No symbol table info available.
#5  0x00007fffec0fae73 in ?? () from /usr/lib64/libpulse.so.0
No symbol table info available.
#6  0x00007fffdfbd64f7 in ?? () from /usr/lib64/pulseaudio/libpulsecommon-2.1.so
No symbol table info available.
#7  0x00007ffff2c08f06 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#8  0x00007ffff293e62d in clone () from /lib64/libc.so.6
No symbol table info available.

Thread 5 (Thread 0x7fffecd16700 (LWP 27833)):
#0  0x00007ffff6bf9605 in update_message_SuppressOutput (context=0x7108c0, allow=0 '\000', area=0x0) at /home/ghost99/Programming/sources/FreeRDP/libfreerdp/core/message.c:133
        lParam = 0x7fffe4000960
#1  0x000000000040f48c in xf_event_UnmapNotify (xfi=0x7fffe80008c0, event=0x7fffecd15e00, app=0) at /home/ghost99/Programming/sources/FreeRDP/client/X11/xf_event.c:623
        window = 0x3
        update = 0x6b7e60
        rail = 0x7fffe8044630
#2  0x000000000040fca9 in xf_event_process (instance=0x6a0470, event=0x7fffecd15e00) at /home/ghost99/Programming/sources/FreeRDP/client/X11/xf_event.c:940
        status = 1
        xfi = 0x7fffe80008c0
        rail = 0x7fffe8044630
        window = 0x7fffecd15e00
#3  0x0000000000419a8e in xf_input_thread (arg=0x6a0470) at /home/ghost99/Programming/sources/FreeRDP/client/X11/xfreerdp.c:1098
        status = 1
        xfi = 0x7fffe80008c0
        event = 0x7fffe40008c0
        xevent = {type = 18, xany = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625}, xkey = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, root = 77594625, subwindow = 0, time = 0, x = 0, y = 580, x_root = 54, y_root = 630, state = 0, keycode = 0, same_screen = 1}, xbutton = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, root = 77594625, subwindow = 0, time = 0, x = 0, y = 580, x_root = 54, y_root = 630, state = 0, button = 0, same_screen = 1}, xmotion = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, root = 77594625, subwindow = 0, time = 0, x = 0, y = 580, x_root = 54, y_root = 630, state = 0, is_hint = 0 '\000', same_screen = 1}, xcrossing = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, root = 77594625, subwindow = 0, time = 0, x = 0, y = 580, x_root = 54, y_root = 630, mode = 0, detail = 0, same_screen = 1, focus = 1, state = 16}, xfocus = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, mode = 77594625, detail = 0}, xexpose = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, x = 77594625, y = 0, width = 0, height = 0, count = 0}, xgraphicsexpose = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, drawable = 77594625, x = 77594625, y = 0, width = 0, height = 0, count = 0, major_code = 0, minor_code = 0}, xnoexpose = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, drawable = 77594625, major_code = 77594625, minor_code = 0}, xvisibility = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, state = 77594625}, xcreatewindow = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, parent = 77594625, window = 77594625, x = 0, y = 0, width = 0, height = 0, border_width = 0, override_redirect = 580}, xdestroywindow = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, event = 77594625, window = 77594625}, xunmap = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, event = 77594625, window = 77594625, from_configure = 0}, xmap = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, event = 77594625, window = 77594625, override_redirect = 0}, xmaprequest = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, parent = 77594625, window = 77594625}, xreparent = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, event = 77594625, window = 77594625, parent = 0, x = 0, y = 0, override_redirect = 0}, xconfigure = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, event = 77594625, window = 77594625, x = 0, y = 0, width = 0, height = 0, border_width = 0, above = 2705829396534, override_redirect = 0}, xgravity = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, event = 77594625, window = 77594625, x = 0, y = 0}, xresizerequest = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, width = 77594625, height = 0}, xconfigurerequest = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, parent = 77594625, window = 77594625, x = 0, y = 0, width = 0, height = 0, border_width = 0, above = 2705829396534, detail = 0, value_mask = 4294967297}, xcirculate = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, event = 77594625, window = 77594625, place = 0}, xcirculaterequest = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, parent = 77594625, window = 77594625, place = 0}, xproperty = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, atom = 77594625, time = 0, state = 0}, xselectionclear = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, selection = 77594625, time = 0}, xselectionrequest = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, owner = 77594625, requestor = 77594625, selection = 0, target = 0, property = 2491081031680, time = 2705829396534}, xselection = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, requestor = 77594625, selection = 77594625, target = 0, property = 0, time = 2491081031680}, xcolormap = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, colormap = 77594625, new = 0, state = 0}, xclient = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, message_type = 77594625, format = 0, data = {b = '\000' <repeats 12 times>, "D\002\000\000\066\000\000", s = {0, 0, 0, 0, 0, 0, 580, 0, 54, 0}, l = {0, 2491081031680, 2705829396534, 0, 4294967297}}}, xmapping = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, request = 77594625, first_keycode = 0, count = 0}, xerror = {type = 18, display = 0x2202, resourceid = 34359738368, serial = 140737085706720, error_code = 1 '\001', request_code = 0 '\000', minor_code = 160 '\240'}, xkeymap = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, window = 77594625, key_vector = "\001\000\240\004", '\000' <repeats 24 times>, "D\002\000"}, xgeneric = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, extension = 77594625, evtype = 0}, xcookie = {type = 18, serial = 8706, send_event = 0, display = 0x7fffe80011e0, extension = 77594625, evtype = 0, cookie = 77594625, data = 0x0}, pad = {18, 8706, 34359738368, 140737085706720, 77594625, 77594625, 0, 0, 2491081031680, 2705829396534, 0, 4294967297, 16, 103079215104, 4, 16711680, 65280, 255, 34359738624, 140737085764568, 55, 103079215104, 140733193388036, 16711680}}
        instance = 0x6a0470
#4  0x00007ffff2c08f06 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#5  0x00007ffff293e62d in clone () from /lib64/libc.so.6
No symbol table info available.

Thread 4 (Thread 0x7fffed517700 (LWP 27832)):
#0  0x00007ffff2937d63 in select () from /lib64/libc.so.6
No symbol table info available.
#1  0x00007ffff3226c95 in WaitForSingleObject (hHandle=0x7fffe8045b50, dwMilliseconds=4294967295) at /home/ghost99/Programming/sources/FreeRDP/winpr/libwinpr/synch/wait.c:93
        status = 32767
        rfds = {__fds_bits = {262144, 0 <repeats 15 times>}}
        event = 0x7fffe8045b50
        timeout = {tv_sec = 0, tv_usec = 0}
        Type = 2
        Object = 0x7fffe8045b50
#2  0x00007ffff429abfe in MessageQueue_Wait (queue=0x7fffe8046410) at /home/ghost99/Programming/sources/FreeRDP/winpr/libwinpr/utils/collections/MessageQueue.c:54
        status = 0
#3  0x000000000041997e in xf_update_thread (arg=0x6a0470) at /home/ghost99/Programming/sources/FreeRDP/client/X11/xfreerdp.c:1059
        message = {id = 65538, context = 0x7108c0, wParam = 0x0, lParam = 0x0}
        queue = 0x7fffe8046410
        instance = 0x6a0470
#4  0x00007ffff2c08f06 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#5  0x00007ffff293e62d in clone () from /lib64/libc.so.6
No symbol table info available.

Thread 3 (Thread 0x7fffedd18700 (LWP 27831)):
#0  0x00007ffff2937d63 in select () from /lib64/libc.so.6
No symbol table info available.
#1  0x00007ffff3227046 in WaitForMultipleObjects (nCount=2, lpHandles=0x7fffe80455f8, bWaitAll=0, dwMilliseconds=10) at /home/ghost99/Programming/sources/FreeRDP/winpr/libwinpr/synch/wait.c:211
        fd = 17
        maxfd = 17
        index = 2
        status = -402649056
        fds = {__fds_bits = {196608, 0 <repeats 15 times>}}
        Type = 2
        Object = 0x7fffe8045680
        timeout = {tv_sec = 0, tv_usec = 9414}
#2  0x00007ffff61472aa in svc_plugin_thread_func (arg=0x7fffe8001020) at /home/ghost99/Programming/sources/FreeRDP/libfreerdp/utils/svc_plugin.c:297
        plugin = 0x7fffe8001020
#3  0x00007ffff2c08f06 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#4  0x00007ffff293e62d in clone () from /lib64/libc.so.6
No symbol table info available.

Thread 2 (Thread 0x7fffee519700 (LWP 27830)):
#0  0x00007ffff2937d63 in select () from /lib64/libc.so.6
No symbol table info available.
#1  0x00007ffff3226c95 in WaitForSingleObject (hHandle=0x6af980, dwMilliseconds=0) at /home/ghost99/Programming/sources/FreeRDP/winpr/libwinpr/synch/wait.c:93
        status = 32767
        rfds = {__fds_bits = {0 <repeats 16 times>}}
        event = 0x6af980
        timeout = {tv_sec = 0, tv_usec = 0}
        Type = 2
        Object = 0x6af980
#2  0x00007ffff3226476 in ResetEvent (hEvent=0x6af980) at /home/ghost99/Programming/sources/FreeRDP/winpr/libwinpr/synch/event.c:175
        Type = 2
        Object = 0x6af980
        length = 32767
        status = 0
        event = 0x6af980
#3  0x00007ffff6bf4eb4 in transport_check_fds (ptransport=0x6a0660) at /home/ghost99/Programming/sources/FreeRDP/libfreerdp/core/transport.c:603
        pos = 0
        status = 12
        length = 0
        recv_status = 32767
        received = 0x7fffee518d00
        transport = 0x6ab530
#4  0x00007ffff6bf094f in rdp_check_fds (rdp=0x6a0610) at /home/ghost99/Programming/sources/FreeRDP/libfreerdp/core/rdp.c:960
No locals.
#5  0x00007ffff6be22cc in freerdp_check_fds (instance=0x6a0470) at /home/ghost99/Programming/sources/FreeRDP/libfreerdp/core/freerdp.c:180
        status = 0
        rdp = 0x6a0610
#6  0x000000000041a095 in xfreerdp_run (instance=0x6a0470) at /home/ghost99/Programming/sources/FreeRDP/client/X11/xfreerdp.c:1291
        i = 4
        fds = 15
        xfi = 0x7fffe80008c0
        max_fds = 15
        rcount = 4
        wcount = 0
        ret = 0
        status = 1
        rfds = {0xe, 0x9, 0xc, 0xf, 0x0 <repeats 28 times>}
        wfds = {0x0 <repeats 32 times>}
        rfds_set = {__fds_bits = {32768, 0 <repeats 15 times>}}
        wfds_set = {__fds_bits = {0 <repeats 16 times>}}
        fd_input_event = 15
        input_event = 0x7fffe801eca0
        select_status = 1
        async_update = 1
        async_input = 1
        async_channels = 0
        update_thread = 0x7fffe8046490
        input_thread = 0x7fffe804acc0
        channels_thread = 0x3
        channels = 0x710d00
        settings = 0x6a0770
        timeout = {tv_sec = 0, tv_usec = 999998}
        fin = 0x0
#7  0x000000000041a33a in thread_func (param=0x711560) at /home/ghost99/Programming/sources/FreeRDP/client/X11/xfreerdp.c:1384
        data = 0x711560
#8  0x00007ffff2c08f06 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#9  0x00007ffff293e62d in clone () from /lib64/libc.so.6
No symbol table info available.

Thread 1 (Thread 0x7ffff7faa700 (LWP 27827)):
#0  0x00007ffff2937d63 in select () from /lib64/libc.so.6
No symbol table info available.
#1  0x00007ffff3226dd7 in WaitForSingleObject (hHandle=0x6a0450, dwMilliseconds=4294967295) at /home/ghost99/Programming/sources/FreeRDP/winpr/libwinpr/synch/wait.c:125
        status = 32767
        length = 0
        rfds = {__fds_bits = {32, 0 <repeats 15 times>}}
        timeout = {tv_sec = 0, tv_usec = 0}
        semaphore = 0x6a0450
        Type = 4
        Object = 0x6a0450
#2  0x000000000041a55f in main (argc=9, argv=0x7fffffffe058) at /home/ghost99/Programming/sources/FreeRDP/client/X11/xfreerdp.c:1457
        thread = 140737191712512
        instance = 0x6a0470
        data = 0x711560

@tonyhook
Copy link

Any progress? Still exists in HEAD.

@awakecoding
Copy link
Member

@tonyhook the recent improvements to /async-input /async-update make it more bearable, but the buffer underrun still occurs, especially when initially buffering. I'm open to suggestions as to why the buffer underrun happens so easily, probably due to poor thread synchronization for the channels?

@tonyhook
Copy link

@awakecoding
I compared FreeRDP and aplay, found when calling snd_pcm_writei, the parameters has something wrong.
snd_pcm_writei accepts multiples of chunk_size to be written, while chunk_size should be read by snd_pcm_hw_params_get_period_size.

I try to fix the problem, please have a check.
https://github.com/tonyhook/FreeRDP/commit/dc468cb1a123e3cf74c402849a4be0697772ec27

Thank you.

@tonyhook
Copy link

Sorry, line 422 should be:
if ((pindex <= end) && (pindex != alsa->audio_data))

@awakecoding
Copy link
Member

@tonyhook I applied your patch, but didn't see that much of a difference. There seems to be a lot of ways to setup alsa though, we might be other things wrong.

@awakecoding
Copy link
Member

Investigating further: when playing a video in GDI mode and the video not being shown (to get only sound, not video), 60% of the execution time is spent just in snd_pcm_writei called from rdpsnd_alsa_play

@tonyhook
Copy link

I connect to a Windows Server 2008 R2 RDSH server, play mp3 file in Windows Media Player. Before apply the patch, underrun occurs much in the beginning, and less after a while. After apply the patch, no underrun occurs.

CPU ultilization keeps at a low level under 2.4%.

Both Fedora 16 (running xfreerdp) and Windows are VMware Workstation virtual machine, and patched up-to-date.

Maybe different environment? I will test Windows XP and of course video playing later. Did you start the video playing and minimize the player window to get only sound? Thanks.

@jiaxi2000
Copy link

@tonyhook :Thanks for your hardwork.
My environment:
Server: Win 7 VM setuped by Windows 2008 R2 using Hyper-v.
Terminal:Thin Client [freerdp 1.0.2]
cmd:xfreerdp -d DOM -u admin -p H123 --no-nla --plugin rdpsnd --date alsa -- --rfx --rfx-mode i -f 192.168.1.113:3389&

I also can get underrun log when using VLC to play mp3 after apply your patch.

I also get underrun log when setting the audio quality to DYNAMIC_QUALITY.
The format of audio can change when setting audio quality to DYNAMIC_QUALITY.
alsa->actual_rate is 8000,alsa->actual_channels is 1,format->wFormatTag is 17, format is IMA ADPCM
alsa->actual_rate is 11025,alsa->actual_channels is 1,format->wFormatTag is 17, format is IMA ADPCM
alsa->actual_rate is 22050,alsa->actual_channels is 1,format->wFormatTag is 17, format is IMA ADPCM

And there are some flaw in your patch.
First, snd_pcm_hw_params_get_period_size should be called after set hw params finish.
Second,memory leak can cause when the format is IMA ADPCM. xree(decoded_data) should be called.

@awakecoding
Copy link
Member

@tonyhook I spent the last two days playing gangnam style in loop while testing sound redirection. This problem is not easily solved and it really has to do with threading & synchronization. I made major changes on my branch to refactor the way the channel is queueing and dequeuing events, making the synchronization more predictable but still similar to the original. I noticed that what makes a major difference is really the timing and values at which the Wave Confirm PDUs are sent back. What the code currently does is queue a Wave Confirm PDU for sending with a timestamp 250ms in the future. The dequeuing thread waits until that time is reached before sending it. Sending the Wave Confirm PDU ASAP simply makes it horribly skip. If you screw up the time values, the server thinks you can't handle the sound properly and starts degrading quality.

Reading the spec, we're doing this wrong, and the fact that it sometimes works fine is just luck. I have no idea why a delay of 250ms seems to work best, but I tried changing it to other values and it would be worse. I didn't write the original code so I guess the logic was to emulate more or so the proper timing.

Here's the part which explains the Wave Confirm PDU:
http://msdn.microsoft.com/en-ca/library/cc240969.aspx

There are two conditions which need to be met before sending the Wave Confirm PDU:

  • An audio data sample is received from the server, whether using a WaveInfo PDU and Wave PDU, a Wave2 PDU, a Wave Encrypt PDU, or several UDP Wave PDUs followed by a UDP Wave Last PDU.
  • The audio data sample is emitted to completion by the client.

In other words, we need to receive the full sample, which is sent with a sequence of Wave Info PDU and Wave PDUs. We are currently queuing the Wave Confirm PDU on receipt, which does not comply with the second condition: we should be producing the Wave Confirm PDU after consuming it the audio sample! My guess is that the added 250ms delay on the timestamp somehow emulates processing the audio sample and sending the Wave Confirm PDU at the proper time. However, this is far from perfect and it just doesn't work all the time.

Here's my suggestion: we need a proper asynchronous queue for audio samples, which dequeues and processes the samples when ALSA is ready to process them, and then sends the Wave Confirm PDUs. I am pretty sure this would truly solve the issue once and for good.

@awakecoding
Copy link
Member

@tonyhook oh, by the way, I'm testing with the Gangnam Style videoclip. I've made a copy of the video at different resolutions using keepvid.com. You can also get just the mp3 if you want to avoid putting additional stress with RemoteFX.

@awakecoding
Copy link
Member

@tonyhook I am now wondering if this isn't a hardware limitation up to a certain degree... I noticed we couldn't set the buffer and period size to the values we wished. Doing proper checks and setting the values to the maximum allowed by the hardware, I end up with a buffer size of 7526 and a period size of 940. The latency values we were using were pretty much ignored. As for the start threshold, it is useless: a single wave pdu contains more audio data than the buffer can hold! this means that no matter what threshold you set, playback will start as soon as you get data (unless you put a threshold higher than the buffer size, which would cause issues for obvious reasons). Result: playback starts immediately with almost no latency, and there is a very tiny window in which we can play.

Could other people run the code off my branch and report what values are printed out for their card? If we have to deal with such tiny values, then the only solution I could think of would be the handle the buffering ourselves with the timestamps given by the server and introduce the delay manually before giving the audio data to ALSA.

@awakecoding
Copy link
Member

Further comments: I found out that the wave confirm pdu needs to be sent after the corresponding audio data has been played:

http://qa.social.msdn.microsoft.com/Forums/en-US/os_windowsprotocols/thread/a05987a8-232b-4aec-a361-5060b96ed851

This means we're doing it wrong for all rdpsnd ports. We need way to properly queue data as we're getting it, and send the wave confirm pdu only after it's been played. Right now we're emulating this behavior by scheduling to send a wave confirm pdu somewhere in the future, like +250ms.

As for ALSA, I've tried other systems, and I don't have the tiny buffer issue I have on my main system. Could other people try my branch and tell me what the reported buffer size is? It works better when the buffer size is large, but different issues occur. I'm trying to avoid mixing problems here:

Format: wBitsPerSample: 4 nChannels: 1 nSamplesPerSec: 44100
Parameters: BufferSize: 2097152 PeriodSize: 2048

@Shumen
Copy link

Shumen commented Feb 26, 2013

@awakecoding hi Marc, I've check outed to your branch, and tested the buffer size both on my laptop and notebook ubuntu 12.04, and got these output:
loading channel rdpsnd connected to 192.168.1.231:3389 Format: wBitsPerSample: 4 nChannels: 1 nSamplesPerSec: 44100 Parameters: BufferSize: 2097152 PeriodSize: 2048 Buffer Underrun Gap: 97565229 ms ALSA lib pcm.c:7339:(snd_pcm_recover) underrun occurred Buffer Underrun Gap: 97565229 ms ALSA lib pcm.c:7339:(snd_pcm_recover) underrun occurred Buffer Underrun Gap: 97565229 ms ALSA lib pcm.c:7339:(snd_pcm_recover) underrun occurred Buffer Underrun Gap: 97565229 ms ALSA lib pcm.c:7339:(snd_pcm_recover) underrun occurred Format: wBitsPerSample: 4 nChannels: 1 nSamplesPerSec: 8000 Buffer Underrun Gap: 30540 ms Buffer Underrun Gap: 261126 ms Buffer Underrun Gap: 260108 ms Buffer Underrun Gap: 259090 ms Buffer Underrun Gap: 258072 ms Warning rdpsnd_alsa_schedule_thread (532): snd_pcm_writei status -5 Parameters: BufferSize: 2097152 PeriodSize: 2048 Parameters: BufferSize: 2097152 PeriodSize: 2048 Format: wBitsPerSample: 4 nChannels: 1 nSamplesPerSec: 8000 Buffer Underrun Gap: 536608764 ms ALSA lib pcm.c:7339:(snd_pcm_recover) underrun occurred Parameters: BufferSize: 2097152 PeriodSize: 2048 Format: wBitsPerSample: 4 nChannels: 1 nSamplesPerSec: 11025

@Shumen
Copy link

Shumen commented Feb 26, 2013

@awakecoding so it seems the same with most of the latest linux systems.

@tonyhook
Copy link

Sorry for response late. I just fix issue #977, opened by myself :p. Anyone can merge the fix.

You are right, awakecoding, FreeRDP seems to has a wrong implementation of alsa rdpsnd channel. In the version of 0.8.2, I tried to write a Windows support using winmm libraries, the same problem. But here I'd better focus on alsa.
I think, according to M$ document, data should be queued waiting for alsa module issues a buffer-can-be-written callback, and write some data to alsa. After a complete buffer sent from server is written, a response should return to server immediately.
Attention, the FOLLOWING is my guess, not the truth. If the above is right, server knows the data is issued to device and send more data to client. As a single buffer, new data must arrive at client before the tiny alsa buffer is played, or, consumed. That's a bad idea and would lead to a bad experience. So Windows will use a mechanism like ethernet slip-window to issue more than one buffer to client (I observed such circumstance, no more than 4 buffer are sent to client, Windows 2008 R2). If the default amount of data per window is just 250ms (total one second buffer, beautiful?), the current implementation of FreeRDP can achieve the best performance while any change to the latency would be worse, no matter bigger or less. When Windows find response is returned with a long latency, it of course knows the client sound stream is corrupted.So Windows will lower the quality of sound, hopes that would getover the bad network latency.

@Shumen
Copy link

Shumen commented Feb 26, 2013

@tonyhook I merged your fix a few days, just you pushed in your repository, and I found it won't work with your patch, there's no sound at all with alsa sound option after merging your patch.

@tonyhook
Copy link

Don't apply that patch any longer, pls. I realized that it can do little for this bug.

@awakecoding
Copy link
Member

http://www.youtube.com/watch?v=JUF8xPKBQJM

I got it improved on my branch, better server performance also helps

@awakecoding
Copy link
Member

I have merged my changes on master, it fixes the issue for me. Please give it a try and report back.

@Shumen
Copy link

Shumen commented Feb 28, 2013

@tonyhook yes, with that patch applied, only pulse of rdpsnd works.

@ghost ghost assigned awakecoding Jun 17, 2013
@bmiklautz
Copy link
Member

@tonyhook @gotsiboon do @awakecoding fixes (current git master) fix this problem?

@rozhuk-im
Copy link
Contributor

Fix: rozhuk-im@8d5825e
or use: /sound:sys:alsa,format:1,quality:high

@bmiklautz bmiklautz removed this from the 1.1 milestone May 25, 2016
@lhzw
Copy link

lhzw commented Nov 15, 2019

/sound:sys:alsa,format:1,quality:high
works for me, thanks a lot!!

With this package:
https://ci.freerdp.com/job/freerdp-nightly-binaries/architecture=amd64,distribution=buster,label=pkg-deb/
freerdp-nightly_2.0.0+020191115024827.7261.gbp6bf949_amd64.deb

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

10 participants