dheijl / swyh-rs

Stream What You Hear written in rust, inspired by SWYH.
MIT License
371 stars 15 forks source link

Comparison against foo_out_upnp #125

Open stewartsiu opened 8 months ago

stewartsiu commented 8 months ago

I'm starting a new thread to document my observations started in #108, where I described stuttering issues I found in swyh-rs but not in foobar2000's foo_out_upnp. It looks like a recent thread (#124) also mentioned comparison against foo_out_upnp. I managed to reproduce a side by side comparison of Wireshark captures of the two streaming the same content, where swyh-rs has stuttering but foo_out_upnp doesn't. two_pcap_files.zip testfoo2448.pcap is captured with directly playing the 24/48 content in foobar to the streamer. testfoo2448_swyh.pcap is captured with starting swyh-rs, and as soon as the streaming to renderer started, hitting play in foobar to primary sound output, which is then captured by swyh-rs. The version of swyh-rs cli I ran is one I compiled myself, with minor changes to headers and posts to make the output more similar to foo_out_upnp. The response header at packet 110 in test2448_swyh looks just like packet 71 in test2448, with no chunked transfer (previously thought to be an issue in #108)

dheijl commented 8 months ago

What you are seeing is the fact that that foobar2000 can read the music file/stream ahead as fast and as much as it wants so that it can send the audio faster than your streamer can play it.

swyh-rs on the other hand can only send the music as fast as it receives it from the Windows sound system, and that is at exactly the same rate as your receiver plays it. It also does not use any extra buffering in an attempt to minimize delay.

So the only way to prevent stutter with swyh-rs is:

If any of the above does not prevent stutter you can also

If all this too is not option you can always decide to not use swyh-rs at all of course.

stewartsiu commented 8 months ago

Thanks for your analysis. For my education, could you explain briefly what pattern you see in the packets that led you to this conclusion?

My PC is connected via a 12 inch LAN cable to an unmanaged switch, and then via a 12 inch cable to the streamer. My general observation is that more than half of the time (unforunately not all) swyh-rs only has about 50ms delay.

The reason I thoguht stuttering might have to do with other issues is because I don't have stuttering problems (at least not for tens of minutes) when I first start my streamer and swyh-rs. This stuttering only happens if I Ctrl-C the swyh-rs program and run it again without restarting the streamer, and this happens 100% of the time, with swyh-rs showing "Streaming to... has ended.". Foobar on the hand doesn't care whether I restart my streamer, so that's how I conducted the side-by-side comparison.

One thing I want to know from the packet analysis is whether it's worth trying a library other than tiny-http for handling the http response.

dheijl commented 8 months ago

...50 msec delay..

This means that your streamer does minimal buffering, so stuttering is probably unavoidable at times. Feel free to try any web server alternative.

stewartsiu commented 8 months ago

To make sure I understand "...foobar2000 can read the music file/stream ahead as fast and as much as it wants so that it can send the audio faster", I tried artifically injecting silence before anything is sent, but it doesn't seem to help. Can you tell me why?

In the write function of rwstream.rs, I added: unsafe{ if GLOBAL_COUNTER == 0 { let mut silence = Vec::with_capacity(9600); silence.resize(9600, 0f32); //~100ms at 48khz stereo self.s.send(silence).unwrap(); GLOBAL_COUNTER = 1; } ... }

dheijl commented 8 months ago

Can you attach your config.toml?

This stuttering only happens if I Ctrl-C the swyh-rs program ...

So you are using swyh-rs-cli and not the swyh-rs GUI ?

Have you tried FLAC ?

stewartsiu commented 8 months ago

Yes I use CLI. The config doesn't matter much as I've explored a range of settings, here you are: config_cli.zip FLAC works of course but the latency is way too much, >10s for 24/48.

dheijl commented 8 months ago

inject_silence=true Turn this off and the latency will disappear. Or start the music before you start swyh-rs and the latency will disappear.

stewartsiu commented 8 months ago

Thank you dheijl - this is very interesting. So if I set inject_silence=false and use flac, indeed the latency goes down to the level of wav. But, if I do Ctrl-C and restart, I get the same stuttering issue as using wav! Here is a capture of a flac stream after restart, same music as in the first post: testfoo2448_swyhflac.zip

dheijl commented 8 months ago

If I were you I would run swyh-rs-cli in serve-only mode (-x), add it as a radio station to the streamer, and start/stop streaming with the remote of the streamer. Using flac. Why stopping swyh-rs-cli with ctrl-c and restarting it causes stuttering beats me.

dheijl commented 8 months ago

Why stopping swyh-rs-cli with ctrl-c and restarting it causes stuttering beats me.

Actually I think I do know and I think I can fix it too.

dheijl commented 8 months ago

I think (hope) that the new release 1.10.1 will fix the stuttering on a second run after CTRL-C.

I think the issue is caused by swyh-rs-cli just aborting the connection on CTRL-C, and your streamer fails to cleanup "something" internally causing it to start stuttering until restarted. swyh-rs-cli will now first tell the streamer to stop streaming before it aborts, so that the connection is properly cleaned up in the streamer.

stewartsiu commented 8 months ago

A few observations:

  1. [Edit: This is due to incorrect build params] The new code 1.10.1 actually prevents me from breaking with Ctrl-C altogether. I'm using Windows git-bash and I had trouble killing the process with "kill" after Ctrl-C failed.
  2. [Edit: This is due to incorrect build params] This may or may not be relevant to 1), but starting from v 1.9.5, the cli would start streaming and immediately go back to "Found source ..." and repeat the process non-stop. It doesn't actually affect the sound output but I would have to pipe stderr to /dev/null.
  3. I noticed that the new code sends a Stop message to the server at shut down, but we're already doing that every time the code starts, no? I've added a longer wait time between Stop and Play but it doesn't seem to have made a difference.
  4. The reason I have to use Ctrl-C is not because I need to pause the music, which I can do from the streamer, but that streaming would fail at some time (e.g. due to inject_silence = False). If the new approach doesn't work, my next option to replace tiny-http. But even if I hand craft the server response without using any library (e.g. https://doc.rust-lang.org/book/ch20-01-single-threaded.html), it's not clear what I need to write in the response besides what tiny-http does. I notice that right after the GET request from renderer, swyh-rs would respond immediately with header and wav data, but if I look at foobar's output (testfoo2448.pcap), I see at packet 69 that it sends a small packet to the renderer, some kind of TCP acknowledgement, before sending the response header at packet 71. I don't know how to do that.
dheijl commented 8 months ago

CTRL-C works here on Windows 10 with GIT bash.

This conversation is going nowhere as it looks to me like you're not using the "official" version as published on Github.

It would also have helped if you would have provided relevant information from the start like

So I'm closing this and I think you'd better start your own fork of swyh-rs, it's open source, MIT licensed, and you can do with it what you like.

stewartsiu commented 8 months ago

I appreciate your help but you misunderstood. I've always been using the official version, and I only tweaked the code and used CLI in desperation to debug (to save my marriage, you could say, as my wife was not happy about the media console not having sound when she wants it :))

Let me try to download the exe file directly to see if it's different from what I got from git clone + cargo build. [Edit: yes it turned out that I built with incorrect parameters after 1.9.4]

dheijl commented 8 months ago

the stuttering I mentioned apply if I pause on GUI and restart

The GUI does not have a "PAUSE" functionality, you can only STOP and START streaming using the streamer button.

but starting from v 1.9.5, the cli would start streaming and immediately go back to "Found source ..." and repeat the process non-stop

Between 1.9.4 and 1.9.5 all changes were related to the new volume sliders functionality, so I find this unlikely unless you can prove it with a debug log of course.

I see at packet 69 that it sends a small packet to the renderer, some kind of TCP acknowledgement, before sending the response header at packet 71. I don't know how to do that

I think that is totally irrelevant to your problems.

What I see as your real problem is that the streamer does not handle a TCP disconnect gracefully, and that it also disconnects automatically if the music stops without an AV-Transport STOP command, which you try to work-around by enabling the "inject silence" feature. I personally consider that feature a "kludge" that may work or may not work depending on your streamer. It certainly is not a part of the AVTransport or Openhome UPNP/DLNA specs.

The fact that the stuttering only happens after you restart swyh-rs and that it then only disappears after a streamer restart places the problem firmly in the streamer, not in swyh-rs.

Anyway that is what I think based on the information you gave me so far.

stewartsiu commented 7 months ago

Was busy for a couple weeks, here are some updates.

Problems with Ctrl-C not stopping the code etc - Turned out that I didn't build correctly after 1.9.4, as some build parameters changed, so please ignore that issue. I edited the comment above to not confuse other readers.

Stuttering after reconnect - The new code at 1.10.1 handling Ctrl-C more gracefully didn't help. If I stop and restart, the stuttering (it's actually more like clicking noise, not pauses) would start in a few mins at most.

What I'm trying to do despite knowing it's a problem with my streamer - @dheijl I want to make it clear that it's not a problem with swyh-rs I'm trying to fix. This project is awesome as is. Instead I'm trying to work around my streamer's idiosyncracies, knowing that foo_out_upnp never plays with stuttering / clicking with my streamer, so I want to copy its behavior as much as possible. The TCP acknowledgement is probably irrelevant as you said, so the only thing left I can think of is to get closer to how "foobar2000 can read the music file/stream ahead as fast and as much as it wants". Also, as mentioned in #108, Rust has a default buffer size of 8kb, while foobar2000's pcap file shows it has a max buffer of 16kb. So I did two things: a) I added some zero samples to self.fifo when the wave headers are being written in rwstream.rs, to make sure that it always has something to send. I added 24000 samples last time I tried. b) I managed to change the buffer size to 16k, by patching tiny-http and replacing the standard copy(reader, writer) in response.rs with a custom copy function that moves up to 16k. I confirmed that it's working with Wirehsark. Unfortunately, a) and b) together still didn't solve the problem.

dheijl commented 7 months ago

I don't think that you're going to solve your problem with trial and error. You have to try and find where and why the problem occurs.

To make things absolutely clear, could you answer the following questions:

1 - the clicking never occurs when you have restarted the streamer and you then run swyh-rs-cli for the first time, it's only when you have aborted swyh-rs-cli with ^C and restarted swyh-rs-cli that the clicking occurs, right ?

2 - does the clicking occur when you have restarted your streamer, and you start streaming from swyh-rs GUI, then you stop streaming with the button (NOT closing swyh-rs GUI), wait a second or two, and you restart streaming with the button, does the clicking also occur now?

If the clicking does not occur when using the GUI this way, then 1.10.3 will probably fix the problem.

If it does occur, we have to find the difference between the first streaming session and the following streaming sessions, probably on the TCP level, not the HTTP level.

The fix I made in 1.10.3 tries to make sure that the HTTP streaming connection also gets closed properly from both sides when streaming ends, because I suspect that something is not cleaned up in the streamer when streaming is ended with ^C. If you decide to test 1.10.3 you should use the unmodified Github code or the released 1.10.3 binary.

stewartsiu commented 7 months ago

1 - the clicking never occurs when you have restarted the streamer and you then run swyh-rs-cli for the first time, it's only when you have aborted swyh-rs-cli with ^C and restarted swyh-rs-cli that the clicking occurs, right ?

That's right.

2 - does the clicking occur when you have restarted your streamer, and you start streaming from swyh-rs GUI, then you stop streaming with the button (NOT closing swyh-rs GUI), wait a second or two, and you restart streaming with the button, does the clicking also occur now?

Yes, it would still occur, so 1.10.3 didn't fix the problem.

Regardless the underlying cause, I took a different approach and tried to mitigate what is obviously a buffer underrun problem. Earlier I reported that injecting zeros didn't help. But eventually I found that it did if I inject at the right time and with the right amount. There are many combinations that work, but here is one example: a) Set the buffer size in tiny-http to be 64KB (the Rust default was 8KB) before, b) Inject 64K of zero samples in read() in rwstream.rs, NOT along with the wav header but right afterwards. By that I mean I would return the read() function right after adding the wav header, and add the zeros to self.fifo so that they can be used next time read() is called. My sample rate is 48khz stereo, so 64K of samples should add about 2/3 of a second, which is a lot of delay. But when I check audio/video sync (https://www.youtube.com/watch?v=ucZl6vQ_8Uo) I only see about 1/3 second delay, so there's something else going on. Anyway, to avoid this much delay, I later switched to a strategy of periodically injecting these zeros every 10 mins or so.

This may seem ugly, but allowing restart without clicks really changed my user experience. Every time there's an issue I can just click twice in the GUI to restart the connection, which is a big win compared to having to restart the streamer.

There is one idiosyncracy with my streamer that maybe I should mention to complete the story: After some time the playing would stop and I would have to hit play again. This is the same with foo_out_upnp as well. I investigated by adding more logging with swyh-rs, and found that after ~700 million of 24bit samples, the read() function would stop being called. This adds up to only about 2GB, so well under the 4GB wav file limit and doesn't change if I use RF64 or increase my streamsize (I use U32 not chunked by default). At 48/24 this is about 2 hours, long enough to not bother me, but let's say I want to do 384/24 it would only be 15 mins. Also, if I leave the swyh-rs on, this is like a memory leak, because the buffer would build up eventually consuming all RAM in my PC. When the playing stop usually I don't see any debug messages in debug mode, with the exception of one time when I saw some SOAP POST error saying the streamer was unresponsive, and after the error the music actually just kept on playing many hours beyond the normal stop time without latency or clicks.

dheijl commented 7 months ago

Thanks for keeping me informed of your progress. Now that you have established that buffer underrun is definitely the cause, I think there is a simple fix that I can integrate. I'll introduce an optional configurable "up-front" buffering delay in streaming_server.rs around line 170:

                        let nclients = {
                            let mut clients = CLIENTS.write();
                            clients.insert(remote_addr.clone(), channel_stream.clone());
                            clients.len()
                        };
                        debug!("Now have {} streaming clients", nclients);

==> I'll add a configurable sleep of x msecs here so that the crossbeam send channel 
==> can start buffering x msecs of real audio before the audio streaming starts

                        feedback_tx_c
                            .send(StreamerFeedBack {
                                remote_ip: remote_ip.clone(),
                                streaming_state: StreamingState::Started,
                            })
                            .unwrap();

That should have the same effect as your adding initial silence in rwstream.rs.

I'll hopefully publish in the next few days.

dheijl commented 7 months ago

If you compile the current master and run swyh-rs once, you'll get a new config entry: buffering_delay_msec = 0.

I would be interested to know if playing with this value does help to prevent your problem.

dheijl commented 6 months ago

Or you can just try 1.10.5 to see if it helps you.