search

HermesApp / Hermes

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

Audio Stutters After Hermes is in the Background for a Few Minutes #271

Closed caffeinewriter closed 7 years ago

caffeinewriter commented 8 years ago

This is a strange one. The audio starts to stutter after a few minutes of the app being in the background. (i.e. Not Visible/Active) I'm running OS X El Capitan 10.11.2. Only about a quarter of the memory is being used, CPU usage isn't spiking, and the problem only occurs if the app is positioned behind another application. If the app is visible at all, the problem does not occur. Even more strange, is it only seems to occur if positioned on a specific desktop, specifically one with multiple applications open (Atom, Slack & Finder), however moving it to another desktop seems to stop it from stuttering. It's probably a super-specific situation, so to cover all possible bases, Desktop 1 has Atom, Slack, Hermes, and Finder. Desktop 2 has iTerm, and Desktop 3 has 2 Chrome windows. My first guess is it relates to how OS X handles prioritization. Another possible culprit is Hermes in combination with Background Music, but it's definitely one of the stranger behaviors I've seen.

Steps to Reproduce:

  1. Start playing music.
  2. Start using another application in the foreground, where Hermes is hidden behind another window.
  3. Wait several minutes, and the audio may start stuttering.

Log:

HermesAppDelegate.m:158 -[HermesAppDelegate applicationDidFinishLaunching:] Starting in debug mode. Log file: /Users/username/Library/Logs/Hermes/HermesLog_2016-07-27_14:27:14_-0700.log
Pandora.m:290 -[Pandora doPartnerLogin:] Getting partner ID...
Pandora.m:842 -[Pandora sendRequest:] https://tuner.pandora.com/services/json/?method=auth.partnerLogin&partner_id=&auth_token=&user_id=
Pandora.m:842 -[Pandora sendRequest:] https://tuner.pandora.com/services/json/?method=auth.userLogin&partner_id=42&auth_token=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx&user_id=
Pandora.m:842 -[Pandora sendRequest:] https://tuner.pandora.com/services/json/?method=user.canSubscribe&partner_id=42&auth_token=VImsuoT5yxr8hod7Hnhqa8XEYNPvDO4GQ2JXHMp4Pmv6HFHsylOhfOXA%3D%3D&user_id=197963608
Pandora.m:327 __33-[Pandora checkSubscriberStatus:]_block_invoke Subscriber status: 0
Pandora.m:842 -[Pandora sendRequest:] https://tuner.pandora.com/services/json/?method=auth.userLogin&partner_id=42&auth_token=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx&user_id=
Pandora.m:281 __41-[Pandora doUserLogin:password:callback:]_block_invoke.257 Logged in as <email>.
Pandora.m:425 -[Pandora fetchStations] Fetching stations...
Pandora.m:842 -[Pandora sendRequest:] http://tuner.pandora.com/services/json/?method=user.getStationList&partner_id=42&auth_token=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx%3D%3D&user_id=197963608
FileReader.m:40 -[FileReader stream:handleEvent:] notifying
FMEngine.m:37 -[FMEngine performMethod:withCallback:withParameters:useSignature:httpMethod:] {
    album = Torches;
    "api_key" = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    "api_sig" = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    artist = "Foster The People";
    chosenByUser = 0;
    method = "track.updateNowPlaying";
    sk = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    timestamp = 1469654835;
    track = "Don't Stop (Color On The Walls)";
}
HistoryController.m:26 -[HistoryController loadSavedSongs] loading saved songs
ASPlaylist.m:78 -[ASPlaylist bitrateReady:] <AudioStreamer: 0x7fce8c90f400> 44.1 KHz '.mp3' ~128 Kbps
PlaybackController.m:228 -[PlaybackController playbackStateChanged:] Stream playing: <Song 0x7fce8aeb69e0 Foster The People - Don't Stop (Color On The Walls)>
FileReader.m:40 -[FileReader stream:handleEvent:] notifying
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://cont-2.p-cdn.com/images/public/rovi/albumart/9/2/7/5/886977445729_500W_500H.jpg
ImageLoader.m:44 __24-[ImageLoader fetch:cb:]_block_invoke cached:   http://cont-2.p-cdn.com/images/public/rovi/albumart/9/2/7/5/886977445729_500W_500H.jpg
PlaybackController.m:228 -[PlaybackController playbackStateChanged:] Stream playing: <Song 0x7fce8aeb69e0 Foster The People - Don't Stop (Color On The Walls)>
FMEngine.m:37 -[FMEngine performMethod:withCallback:withParameters:useSignature:httpMethod:] {
    album = Torches;
    "api_key" = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    "api_sig" = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    artist = "Foster The People";
    chosenByUser = 0;
    method = "track.scrobble";
    sk = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    timestamp = 1469654836;
    track = "Don't Stop (Color On The Walls)";
}
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-dc6-2-v4v6.pandora.com/images/public/rovi/albumart/6/0/4/9/602517979406_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-sv5-1-v4v6.pandora.com/images/public/rovi/albumart/4/3/1/6/602517306134_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://cont-1.p-cdn.com/images/public/amz/1/2/2/8/801061018221_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://cont-1.p-cdn.com/images/public/gracenote/albumart/5/7/1/7/4020796447175_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-sv3-2-v4v6.pandora.com/images/public/amz/2/6/8/8/800078862_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-sv5-1-v4v6.pandora.com/images/public/rovi/albumart/8/2/3/5/724384885328_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-dc6-1-v4v6.pandora.com/images/public/amz/3/4/0/1/800051043_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-dc6-1-v4v6.pandora.com/images/public/gracenote/albumart/8/4/0/8/836766008048_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-sv5-3-v4v6.pandora.com/images/public/amz/4/7/2/9/800059274_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-sv5-1-v4v6.pandora.com/images/public/rovi/albumart/8/0/6/7/602547527608_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-sv3-2-v4v6.pandora.com/images/public/rovi/albumart/4/2/5/8/878037008524_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-ch1-2-v4v6.pandora.com/images/public/rovi/albumart/8/2/8/0/803020160828_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-sv5-3-v4v6.pandora.com/images/public/rovi/albumart/9/2/7/5/886977445729_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://cont-2.p-cdn.com/images/public/amz/5/0/5/1/900001505_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://cont-2.p-cdn.com/images/public/gracenote/albumart/6/7/1/2/892038002176_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-sv3-1-v4v6.pandora.com/images/public/gracenote/albumart/2/2/5/2/696998712522_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-ch1-2-v4v6.pandora.com/images/public/gracenote/albumart/9/6/6/3/800023669_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://cont-1.p-cdn.com/images/public/amz/6/6/4/4/044003184466_500W_500H.jpg
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://cont-1.p-cdn.com/images/public/rovi/albumart/3/7/7/2/602498622773_500W_500H.jpg
PlaybackController.m:228 -[PlaybackController playbackStateChanged:] Stream playing: <Song 0x7fce8aeb63f0 The Lumineers - Ophelia>
FMEngine.m:37 -[FMEngine performMethod:withCallback:withParameters:useSignature:httpMethod:] {
    album = "Cleopatra (Deluxe)";
    "api_key" = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    "api_sig" = c2cddfe61cd111aa36a0296f383b9f0b;
    artist = "The Lumineers";
    chosenByUser = 0;
    method = "track.updateNowPlaying";
    sk = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    timestamp = 1469654861;
    track = Ophelia;
}
ASPlaylist.m:78 -[ASPlaylist bitrateReady:] <AudioStreamer: 0x7fce8b321800> 44.1 KHz '.mp3' ~128 Kbps
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://cont-2.p-cdn.com/images/public/gracenote/albumart/9/6/8/9/800079869_500W_500H.jpg
ImageLoader.m:44 __24-[ImageLoader fetch:cb:]_block_invoke cached:   http://cont-2.p-cdn.com/images/public/gracenote/albumart/9/6/8/9/800079869_500W_500H.jpg
PlaybackController.m:233 -[PlaybackController playbackStateChanged:] Stream paused.
PlaybackController.m:228 -[PlaybackController playbackStateChanged:] Stream playing: <Song 0x7fce8aeb63f0 The Lumineers - Ophelia>
FMEngine.m:37 -[FMEngine performMethod:withCallback:withParameters:useSignature:httpMethod:] {
    album = "Cleopatra (Deluxe)";
    "api_key" = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    "api_sig" = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    artist = "The Lumineers";
    chosenByUser = 0;
    method = "track.scrobble";
    sk = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    timestamp = 1469654998;
    track = Ophelia;
}
PlaybackController.m:228 -[PlaybackController playbackStateChanged:] Stream playing: <Song 0x7fce8aeb6710 Vampire Weekend - Horchata>
FMEngine.m:37 -[FMEngine performMethod:withCallback:withParameters:useSignature:httpMethod:] {
    album = Contra;
    "api_key" = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    "api_sig" = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    artist = "Vampire Weekend";
    chosenByUser = 0;
    method = "track.updateNowPlaying";
    sk = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    timestamp = 1469655078;
    track = Horchata;
}
ASPlaylist.m:78 -[ASPlaylist bitrateReady:] <AudioStreamer: 0x7fce8b321800> 44.1 KHz '.mp3' ~128 Kbps
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-ch1-1-v4v6.pandora.com/images/public/rovi/albumart/9/2/9/2/634904042929_500W_500H.jpg
ImageLoader.m:44 __24-[ImageLoader fetch:cb:]_block_invoke cached:   http://mediaserver-cont-ch1-1-v4v6.pandora.com/images/public/rovi/albumart/9/2/9/2/634904042929_500W_500H.jpg
FMEngine.m:37 -[FMEngine performMethod:withCallback:withParameters:useSignature:httpMethod:] {
    album = Contra;
    "api_key" = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    "api_sig" = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    artist = "Vampire Weekend";
    chosenByUser = 0;
    method = "track.scrobble";
    sk = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    timestamp = 1469655182;
    track = Horchata;
}
Pandora.m:469 -[Pandora fetchPlaylistForStation:] Getting fragment for Indie Pop Radio...
Pandora.m:842 -[Pandora sendRequest:] https://tuner.pandora.com/services/json/?method=station.getPlaylist&partner_id=42&auth_token=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx%3D%3D&user_id=197963608
FMEngine.m:37 -[FMEngine performMethod:withCallback:withParameters:useSignature:httpMethod:] {
    album = Nighttiming;
    "api_key" = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    "api_sig" = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    artist = "Coconut Records";
    chosenByUser = 0;
    method = "track.updateNowPlaying";
    sk = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx;
    timestamp = 1469655289;
    track = "West Coast";
}
ASPlaylist.m:78 -[ASPlaylist bitrateReady:] <AudioStreamer: 0x7fce8ca28000> 44.1 KHz '.mp3' ~128 Kbps
PlaybackController.m:228 -[PlaybackController playbackStateChanged:] Stream playing: <Song 0x7fce8aeb9660 Coconut Records - West Coast>
Pandora.m:519 __35-[Pandora fetchPlaylistForStation:]_block_invoke High quality audio from audioUrlMap is 64 Kbps aacplus
Pandora.m:525 __35-[Pandora fetchPlaylistForStation:]_block_invoke Medium quality audio from audioUrlMap is 64 Kbps aacplus
Pandora.m:531 __35-[Pandora fetchPlaylistForStation:]_block_invoke Low quality audio from audioUrlMap is 32 Kbps aacplus
Pandora.m:519 __35-[Pandora fetchPlaylistForStation:]_block_invoke High quality audio from audioUrlMap is 64 Kbps aacplus
Pandora.m:525 __35-[Pandora fetchPlaylistForStation:]_block_invoke Medium quality audio from audioUrlMap is 64 Kbps aacplus
Pandora.m:531 __35-[Pandora fetchPlaylistForStation:]_block_invoke Low quality audio from audioUrlMap is 32 Kbps aacplus
Pandora.m:519 __35-[Pandora fetchPlaylistForStation:]_block_invoke High quality audio from audioUrlMap is 64 Kbps aacplus
Pandora.m:525 __35-[Pandora fetchPlaylistForStation:]_block_invoke Medium quality audio from audioUrlMap is 64 Kbps aacplus
Pandora.m:531 __35-[Pandora fetchPlaylistForStation:]_block_invoke Low quality audio from audioUrlMap is 32 Kbps aacplus
Pandora.m:519 __35-[Pandora fetchPlaylistForStation:]_block_invoke High quality audio from audioUrlMap is 64 Kbps aacplus
Pandora.m:525 __35-[Pandora fetchPlaylistForStation:]_block_invoke Medium quality audio from audioUrlMap is 64 Kbps aacplus
Pandora.m:531 __35-[Pandora fetchPlaylistForStation:]_block_invoke Low quality audio from audioUrlMap is 32 Kbps aacplus
Station.m:157 -[Station songsLoaded:] Received hermes.fragment-fetched.2739086226099056472 from (null) with qualities: high high high high
Station.m:157 -[Station songsLoaded:] Received hermes.fragment-fetched.2739086226099056472 from (null) with qualities: high high high high
ImageLoader.m:36 __24-[ImageLoader fetch:cb:]_block_invoke fetching: http://mediaserver-cont-ch1-1-v4v6.pandora.com/images/public/gracenote/albumart/3/7/2/1/018736111273_500W_500H.jpg
ImageLoader.m:44 __24-[ImageLoader fetch:cb:]_block_invoke cached:   http://mediaserver-cont-ch1-1-v4v6.pandora.com/images/public/gracenote/albumart/3/7/2/1/018736111273_500W_500H.jpg

What it sounds like:

audio_stutter_hermes.zip

At 15 seconds in, I return Hermes to the foreground, stoping the stuttering.

deltamikeecho commented 8 years ago

What version of Hermes are you using and can you update your OS to the latest? I'm using 10.11.5 with Hermes v1.2.8 and don't have any issues with running it in the background.

nriley commented 8 years ago

I don’t see anything in that log that looks out of the ordinary, and have never heard anything like that on my own Macs (on which I use Hermes for hours a day).

It seems like you are using several things on your Mac which can interfere with audio playback (particularly if you’ve got software like Background Music which creates a custom audio device). I use Hermes for hours at a time on 10.10 and 10.11, and have never noticed any kind of stuttering. I would suggest you start by standardizing your setup one step at a time (e.g., upgrade to the latest OS X, test, remove Background Music, test, and so forth). You can also try creating a new user account on your Mac and testing from there to see if it happens. I barely have time to debug Hermes for regular supported setups!

Thanks.

caffeinewriter commented 8 years ago

I'll give this a shot! I'll try and isolate exactly what's causing it, or at least a minimal example scenario. It's such a weird bug, since it only happens on one monitor. I'll definitely try and get everything standardized.