HermesApp / Hermes

Compact macOS Pandora client that doesn’t use Flash
http://hermesapp.org/
MIT License
381 stars 99 forks source link

Hermes 1.3.0 stutters consistently #285

Open zekedroid opened 7 years ago

zekedroid commented 7 years ago

I just upgraded to v1.3.0 and notice that the sound continuously stutters to the point that it's impossible to listen to music on the client. It goes quiet for about 500-1000ms and then plays for 2 to 3 seconds, sometimes the intervals are faster.

Hermes v1.3.0 Mac OS Sierra

From the elapsed time and the lyrics, it looks like the song continues, so I thought maybe it was a sound driver issue but I've checked with other music players like Spotify, iTunes, and even video players, all work fine.

nriley commented 7 years ago

Has anyone been able to reproduce this? I still don't have Sierra running on real hardware (pending installation of a new SSD as I'm out of disk space...) and haven't seen this in a VM, which makes it difficult to look at (also I've been incredibly busy up until this week and am only slightly less busy until the end of the month, so I doubt I'll have time to look at this until January.)

paullj1 commented 7 years ago

I'm running Sierra and haven't experienced. I've tried over AirPlay, and with third party sound card. On Sat, Dec 17, 2016 at 12:54 Nicholas Riley notifications@github.com wrote:

Has anyone been able to reproduce this? I still don't have Sierra running on real hardware and haven't seen this in a VM, which makes it difficult to look at (also I've been incredibly busy up until this week and am only slightly less busy until the end of the month, so I doubt I'll have time to look at this until January.)

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/HermesApp/Hermes/issues/285#issuecomment-267776716, or mute the thread https://github.com/notifications/unsubscribe-auth/AIb5BxG650qImFlqRW2kkwMq1lvFI7_Kks5rJCHTgaJpZM4LIB2c .

borgendorf commented 7 years ago

I'm using Sierra and only very rarely hear a stutter when a new song starts. Maybe try clearing the preference file at ~/Library/Preferences/com.alexcrichton.Hermes.plist?

nriley commented 7 years ago

What Macs are people using? Does this persist after a reboot? What about with a new user account? Trying to figure out if there's some commonality here. (On the good side, just ordered a new iMac for a family member that will come with Sierra, so I'll have somewhere to test over the new year!)

borgendorf commented 7 years ago

I'm on a MacBook Pro (Retina, 15-inch, Mid 2015) 2.5Ghz i7 16GB Ram.

zekedroid commented 7 years ago

Sorry, was out. I'm on the same as @borgendorf, running El Capitan. Cleared the preference list and no change seen. I should note that I'm behind a company firewall. The stuttering comes and goes sometimes, and I don't use hermes outside my work computer but I'll give it a try and see if I see stuttering there.

nriley commented 7 years ago

OK, that's the first I've heard about El Capitan. I just tested on a brand new Sierra install and couldn't reproduce…going to be pretty hard to fix if I can't get to to happen, unfortunately.

zekedroid commented 7 years ago

Of course. I'm going to debug further and try to provide a better diagnostic

On Jan 3, 2017 12:20 PM, "Nicholas Riley" notifications@github.com wrote:

OK, that's the first I've heard about El Capitan. I just tested on a brand new Sierra install and couldn't reproduce…going to be pretty hard to fix if I can't get to to happen, unfortunately.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/HermesApp/Hermes/issues/285#issuecomment-270168997, or mute the thread https://github.com/notifications/unsubscribe-auth/ADyI_m8CEMb-Y0btnVmpx9j4HAe49biuks5rOoNSgaJpZM4LIB2c .

bmehling commented 7 years ago

I am not sure if this is the same issue or not -- just another data point:

I've just switched over to a new work machine (2016 MBP 13") and reinstalled my beloved Hermes (1.3.0). I think, but can't be sure, that it worked fine for a couple days.

Starting yesterday after a few seconds of playing the stream started stuttering. It stutters more and more, eventually error-ing (usually w/in the first song -- so less than a minute in), claiming a network problem:

screen shot 2017-01-05 at 4 17 26 pm

I thought perhaps it was network related. I changed the stream quality down -- no change. I did a speedtest and we have no issues (sustained 45Mbps). Further I tested on a different network (home vs. work, two different ISPs) and had the exact same issue.

zekedroid commented 7 years ago

Just confirmed that the issue appears to only happen on my company network. No heavy network use seen and nothing out of the ordinary in terms of processes running. It worked fine for about 2 hours on this network, then started stuttering, switched to my phone's hotspot, stutter disappeared. Go back on the network, stutter comes back.

Is there some diagnostics I could run, either Pandora service calls or Hermes overall?

nriley commented 7 years ago

Thanks, this is very helpful. We might be able to use Apple's Network Link Conditioner to simulate bad network conditions and trigger the stuttering. Not sure I'll have a chance any time soon but it's a start!

On Fri, Jan 06, 2017 at 11:15:50AM -0800, Zeke Schmois wrote:

Just confirmed that the issue appears to only happen on my company network. No heavy network use seen and nothing out of the ordinary in terms of processes running. It worked fine for about 2 hours on this network, then started stuttering, switched to my phone's hotspot, stutter disappeared. Go back on the network, stutter comes back.

Is there some diagnostics I could run, either Pandora service calls or Hermes overall?

bmehling commented 7 years ago

I'll try on my older Mac this weekend (10.11) vs. the one w/ the issue (10.12). Here's the console output of Hermes when the stream dies (and client displays "audio stream failed":

default 13:40:46.136439 -0800   Hermes  [0x7f92fb202c00] Releasing session
default 13:40:46.632359 -0800   NowPlayingTouchUI   [NowPlayingTouchUI] Reloading available apps due to workspace activating an application: NSConcreteNotification 0x608000259a70 {name = NSWorkspaceDidActivateApplicationNotification; object = <NSWorkspace: 0x6000000025e0>; userInfo = {
    NSWorkspaceApplicationKey = "<NSRunningApplication: 0x608000111dc0 (com.alexcrichton.Hermes - 71830)>";
}}
default 13:40:46.805795 -0800   Hermes  [0x7f92fa1c0600] Created session
default 13:40:46.806140 -0800   Hermes  [0x7f92fa1c0600] Decoding: C0 0x01F401F4 0x0000304A 0x22111100 0x00000000 45954
default 13:40:46.806173 -0800   Hermes  [0x7f92fa1c0600] Options: 8x-1 [00000000,01F001F0] 0001D060
default 13:40:46.807232 -0800   Hermes  [0x7f92fa1c0600] Decoding completed without errors
default 13:40:46.807699 -0800   Hermes  TCP Conn 0x600000386250 started
default 13:40:46.808736 -0800   Hermes  [0x7f92fa1c0600] Releasing session
default 13:40:46.818767 -0800   Hermes  TCP Conn 0x600000386250 event 1. err: 0
default 13:40:46.818871 -0800   Hermes  TCP Conn 0x600000386250 complete. fd: 7, err: 0
default 13:40:46.881140 -0800   Hermes  [0x7f92fa1c3200] Created session
default 13:40:46.881437 -0800   Hermes  [0x7f92fa1c3200] Decoding: C0 0x01F401F4 0x0000304A 0x22111100 0x00000000 45954
default 13:40:46.881464 -0800   Hermes  [0x7f92fa1c3200] Options: 8x-1 [00000000,01F001F0] 0001D060
default 13:40:46.882217 -0800   Hermes  [0x7f92fa1c3200] Decoding completed without errors
default 13:40:46.883344 -0800   Hermes  TCP Conn 0x600000386250 canceled
default 13:40:46.883650 -0800   Hermes  [0x7f92fb202c00] Created session
default 13:40:46.883915 -0800   Hermes  [0x7f92fb202c00] Decoding: C0 0x01F401F4 0x0000304A 0x22111100 0x00000000 45954
default 13:40:46.883937 -0800   Hermes  [0x7f92fb202c00] Options: 8x-1 [00000000,01F001F0] 0001D060
default 13:40:46.884723 -0800   Hermes  [0x7f92fb202c00] Decoding completed without errors
default 13:40:46.885124 -0800   Hermes  TCP Conn 0x608000190f60 started
default 13:40:46.885578 -0800   Hermes  TCP Conn 0x6080001911d0 started
default 13:40:46.885739 -0800   Hermes  [0x7f92fb202c00] Releasing session
default 13:40:46.892384 -0800   Hermes  TCP Conn 0x608000190f60 event 1. err: 0
default 13:40:46.892423 -0800   Hermes  TCP Conn 0x608000190f60 complete. fd: 10, err: 0
default 13:40:46.892841 -0800   Hermes  TCP Conn 0x6080001911d0 event 1. err: 0
default 13:40:46.893005 -0800   Hermes  TCP Conn 0x6080001911d0 complete. fd: 11, err: 0
default 13:40:46.899096 -0800   Hermes  TCP Conn 0x6080001911d0 starting SSL negotiation
default 13:40:46.925941 -0800   Hermes  TCP Conn 0x6080001911d0 SSL Handshake DONE
default 13:40:47.318410 -0800   Hermes  TCP Conn 0x6080001911d0 canceled
default 13:40:47.950748 -0800   Hermes  [0x7f92fa1c3200] Releasing session
default 13:40:49.098749 -0800   Hermes  [0x7f92fb1dc000] Created session
default 13:40:49.099016 -0800   Hermes  [0x7f92fb1dc000] Decoding: C0 0x01F401F4 0x0000304A 0x22111100 0x00000000 45954
default 13:40:49.099040 -0800   Hermes  [0x7f92fb1dc000] Options: 8x-1 [00000000,01F001F0] 0001D060
default 13:40:49.099782 -0800   Hermes  [0x7f92fb1dc000] Decoding completed without errors
default 13:40:49.100269 -0800   Hermes  TCP Conn 0x608000190f60 canceled
default 13:40:49.102642 -0800   Hermes  [0x7f92f98c1200] Created session
default 13:40:49.103008 -0800   Hermes  [0x7f92f98c1200] Decoding: C0 0x01F401F4 0x0000304A 0x22111100 0x00000000 45954
default 13:40:49.103044 -0800   Hermes  [0x7f92f98c1200] Options: 8x-1 [00000000,01F001F0] 0001D060
default 13:40:49.104237 -0800   Hermes  [0x7f92f98c1200] Decoding completed without errors
default 13:40:49.104746 -0800   Hermes  TCP Conn 0x6000003863f0 started
default 13:40:49.105181 -0800   Hermes  [0x7f92f98c1200] Releasing session
default 13:40:49.105333 -0800   Hermes  [0x7f92fb1dc000] Releasing session
default 13:40:49.111867 -0800   Hermes  TCP Conn 0x6000003863f0 event 1. err: 0
default 13:40:49.112038 -0800   Hermes  TCP Conn 0x6000003863f0 complete. fd: 7, err: 0
default 13:40:59.965425 -0800   Hermes  ACMP4AACBaseDecoder.cpp:352:Initialize: (0x7f92f989a840) Input format:  2 ch,  22050 Hz, 'aac ' (0x00000000) 0 bits/channel, 0 bytes/packet, 1024 frames/packet, 0 bytes/frame
default 13:40:59.965455 -0800   Hermes  ACMP4AACBaseDecoder.cpp:355:Initialize: (0x7f92f989a840) Output format:  2 ch,  22050 Hz, Float32, non-inter
default 13:40:59.968196 -0800   Hermes  ACMP4AACBaseDecoder.cpp:352:Initialize: (0x7f92fb0dc640) Input format:  2 ch,  22050 Hz, 'aac ' (0x00000000) 0 bits/channel, 0 bytes/packet, 1024 frames/packet, 0 bytes/frame
default 13:40:59.968227 -0800   Hermes  ACMP4AACBaseDecoder.cpp:355:Initialize: (0x7f92fb0dc640) Output format:  2 ch,  22050 Hz, Float32, non-inter
default 13:40:59.974733 -0800   Hermes  3243: aq@0x7f92f9863000 volume 1.000 1.000 1.000 1.000 1.000
default 13:40:59.975062 -0800   Hermes  194: AQME device AQDefaultOutput: client starting: <AudioQueueObject@0x7f92f9863000; [0]; play>; running count now 1
default 13:40:59.975299 -0800   Hermes  879: aqmeio@0x7f92f941e3d0, device 0x2e (AQDefaultOutput), AudioDeviceStart (err 0)
default 13:40:59.988200 -0800   Hermes  [0x7f92f98db000] Created session
default 13:40:59.988495 -0800   Hermes  [0x7f92f98db000] Decoding: C0 0x01F401F4 0x0000304A 0x22111100 0x00000000 45954
default 13:40:59.988523 -0800   Hermes  [0x7f92f98db000] Options: 8x-1 [00000000,01F001F0] 0001D060
default 13:40:59.989126 -0800   Hermes  [0x7f92f98db000] Decoding completed without errors
default 13:40:59.990450 -0800   Hermes  TCP Conn 0x600000386800 started
default 13:41:00.001291 -0800   Hermes  TCP Conn 0x600000386800 event 1. err: 0
default 13:41:00.001311 -0800   Hermes  TCP Conn 0x600000386800 complete. fd: 11, err: 0
default 13:41:00.072288 -0800   Hermes  [0x7f92fa1b1200] Created session
default 13:41:00.072614 -0800   Hermes  [0x7f92fa211c00] Created session
default 13:41:00.072855 -0800   Hermes  [0x7f92fa211c00] Decoding: C0 0x01F401F4 0x0000304A 0x22111100 0x00000000 77662
default 13:41:00.072877 -0800   Hermes  [0x7f92fa211c00] Options: 8x-1 [00000000,01F001F0] 0001D060
default 13:41:00.074008 -0800   Hermes  [0x7f92fa211c00] Decoding completed without errors
default 13:41:00.078719 -0800   Hermes  [0x7f92f98c3000] Created session
default 13:41:00.078932 -0800   Hermes  TCP Conn 0x600000386800 canceled
default 13:41:00.080532 -0800   Hermes  [0x7f92fa1b1200] Decoding: C0 0x01F401F4 0x0000304A 0x22111100 0x00000000 77662
default 13:41:00.080565 -0800   Hermes  [0x7f92fa1b1200] Options: 500x500 [FFFFFFFF,FFFFFFFF] 0001D060
default 13:41:00.083229 -0800   Hermes  [0x7f92fa1b1200] Decoding completed without errors
default 13:41:02.365597 -0800   Hermes  [0x7f92fa211c00] Releasing session
default 13:41:02.365786 -0800   Hermes  [0x7f92fb200000] Releasing session
default 13:41:02.366046 -0800   Hermes  [0x7f92f98db000] Releasing session
default 13:42:04.109044 -0800   Hermes  [0x7f92fa1c0000] Created session
default 13:42:04.109532 -0800   Hermes  [0x7f92fa1c0000] Decoding: C0 0x01F401F4 0x0000304A 0x22111100 0x00000000 77662
default 13:42:04.109598 -0800   Hermes  [0x7f92fa1c0000] Options: 8x-1 [00000000,01F001F0] 0001D060
default 13:42:04.111461 -0800   Hermes  [0x7f92fa1c0000] Decoding completed without errors
default 13:42:04.113032 -0800   Hermes  TCP Conn 0x6000003863f0 canceled
default 13:42:04.123980 -0800   Hermes  370: AQME device AQDefaultOutput: client stopping: <AudioQueueObject@0x7f92f9863000; [0]; play>; running count now 0
default 13:42:04.124449 -0800   Hermes  [0x7f92fa1c3c00] Created session
default 13:42:04.124849 -0800   Hermes  [0x7f92fa1c3c00] Decoding: C0 0x01F401F4 0x0000304A 0x22111100 0x00000000 77662
default 13:42:04.124908 -0800   Hermes  [0x7f92fa1c3c00] Options: 8x-1 [00000000,01F001F0] 0001D060
default 13:42:04.126594 -0800   Hermes  [0x7f92fa1c3c00] Decoding completed without errors
default 13:42:04.170413 -0800   Hermes  [0x7f92fa1c3c00] Releasing session
default 13:42:04.170577 -0800   Hermes  [0x7f92fa1c0000] Releasing session
default 13:42:47.780284 -0800   NowPlayingTouchUI   [NowPlayingTouchUI] Reloading available apps due to workspace activating an application: NSConcreteNotification 0x600000443780 {name = NSWorkspaceDidActivateApplicationNotification; object = <NSWorkspace: 0x6000000025e0>; userInfo = {
    NSWorkspaceApplicationKey = "<NSRunningApplication: 0x60000010e2b0 (com.alexcrichton.Hermes - 71830)>";
}}
bmehling commented 7 years ago

I hope I haven't muddied the waters here. For the heck of it, I tried Hermes (1.3.0 2056) again this morning. It's been working w/out any issues for over an hour.

zekedroid commented 7 years ago

Interestingly enough, I tried downloading that other Pandora app (https://itunes.apple.com/us/app/music-streaming-for-pandora/id1123406334?mt=12) and it stutters too. I'm starting to think it has something to do with the Pandora API...

nriley commented 7 years ago

That app is clearly based on Hermes’ source code (check out the about box), so it's probably using the identical streaming code — I wouldn't make any assumptions, it's still probably our bug. It's also lacking our copyright notice, so it's in violation of our software license and is being sold for money (which is not a violation of the license). I will report this…

On Wed, Jan 11, 2017 at 10:50:48AM -0800, Zeke Schmois wrote:

Interestingly enough, I tried downloading that other Pandora app (https://itunes.apple.com/us/app/music-streaming-for-pandora/id1123406334?mt=12) and it stutters too. I'm starting to think it has something to do with the Pandora API...

nriley commented 7 years ago

I've started to be able to reproduce this issue in my 10.12 VM. I will spend some time on it this weekend, but I have no idea whether I'll be able to make any headway. Will keep you up to date…

(And of course, after I go to the trouble of installing 10.12 on a spare SSD, it works perfectly again. Sigh.)

paullj1 commented 7 years ago

Recently, I've noticed the same issue occasionally using Pandora in Google Chrome from work. Maybe it's a latency/throughput issue caused by packet inspection at your company's firewall? Unfortunately, I cannot do any diagnostics where I work. Just a thought.

On Fri, Jan 13, 2017 at 4:28 PM Nicholas Riley notifications@github.com wrote:

I've started to be able to reproduce this issue in my 10.12 VM. I will spend some time on it this weekend, but I have no idea whether I'll be able to make any headway. Will keep you up to date…

— You are receiving this because you commented.

Reply to this email directly, view it on GitHub https://github.com/HermesApp/Hermes/issues/285#issuecomment-272565463, or mute the thread https://github.com/notifications/unsubscribe-auth/AIb5Bz6yLhmPzcA_d-QJ8qE7u_KDvy_Qks5rR_qLgaJpZM4LIB2c .

zekedroid commented 7 years ago

@paullj1 I too noticed it on the web client, however it's not quite the same issue (or rather, might be the same issue but the UIs display it differently). See if you pay close attention at the stutter on the web client, at least for me it happens when the page is not in focus for a while (so keep it on a different monitor or smaller window so you can see it when not focused). As soon as the stutter begins, it very quickly alternates from pause/play.

I didn't make much of this because I wasn't seeing the same behavior in Hermes. But then I tried something really dumb. I waited until Hermes started stuttering and hit play/pause a bunch of times. Interestingly enough, it stops the stuttering.

I then tried pausing for a while since maybe it buffers and all I was doing was giving it time to load? That doesn't do it.

Is it possible the stuttering is Hermes auto pausing/playing because of network latency? Maybe there's a feature to "pause when foo, play when bar" and the condition is tripped in this type of network?

nriley commented 7 years ago

I'm guessing something weird is going on with buffering but maybe my network connections are too good to reproduce it? I had thought that upgrading my MBP to 10.12 would help, but I'm not seeing a lot of reports of this. Apple does have Network Link Conditioner which may help to simulate poor network conditions, if someone else is interested in fixing this issue.

tresni commented 7 years ago

@zekedroid Chrome introduced some new background tab logic that is suppose to reduce the CPU consumption on background tabs. I thought this was disabled for music/videos but I'm not sure. Alternating from pause/play in the WebUI generally indicates buffering (or at least did for me in the past.)

It definitely sounds like a bad network where Hermes is simply playing what it can when it gets it, but (for whatever reason, QOS maybe) is getting choked on streaming audio.

flyingchipmunk commented 5 years ago

I am getting a lot of stutters also. Makes it pretty unusable :/

If I play on pandora.com web player it plays high quality perfectly fine.