Recent performance problems
Closed this issue · 8 comments
Describe the bug
The tracker has been hanging to the point where I have to force quit it.
Most of the time, when I start a match I need to force quit the tracker because it's not doing anything. Often after restarting it will then take a few minutes before it actually starts tracking the cards.
I've been running the tracker forever, so I thought it might be a data accumulation problem. I tried deleting all my old decks so I only have a few left in the tracker but that didn't seem to do much.
Happy to look at a log if you point me to the location to see if there is any info in there. Also happy to try clearing any cache directories that might have accumulated cruft over the years that might be causing the problem.
Version (please complete the following information):
1.7.5
@jpalermo There is a log found in ~/Library/Logs/HSTracker/hstracker.log. It will be big because there is no rotation, so I suggest you delete it first. If the problem persists, then you can attach the new smaller log to the issue so that we can take a look. What OS X version are you using?
I'm on Catalina 10.15.7.
I cleared the log and tailed it while running the game. Looks like at the start of battle I get this:
17:41:21.855 INFO Game.gameStart():1110 - ----- Game Started -----
17:41:21.862 VERBOSE MirrorHelper.mirror():27 - Initializing HearthMirror with pid 75378
17:41:21.893 ERROR MirrorHelper.initMirror():57 - Mirror is not working, trying again...
That last line repeats every half second for a couple minutes and then:
17:43:51.671 ERROR MirrorHelper.initMirror():57 - Mirror is not working, trying again...
17:43:52.500 VERBOSE MirrorHelper.initMirror():52 - Getting BattleTag from HearthMirror : Atlas#1119
17:43:52.558 DEBUG BattlegroundsOverlayView.updateTrackingAreas():40 - update Tracking Area
I don't have a goo idea yet on what could be causing that. Do you see an attempt to upload your collection if you start the game and go to your collection? Don't move out until you get either a confirmation or error message about the collection upload. Just want to see if this persists or not.
@martinbonnin have you seen this before?
I didn't have collection uploading enabled for HSReplay, and I actually turned off replay uploading to see if that was the part initializing the MirrorHelper. It's not though, MirrorHelper is initialized regardless of the HSReplay integrations.
I just turned on collection uploading and tested it.
18:45:28.209 DEBUG CollectionWatcher.run():124 - getting mirrorCollection
18:45:28.216 VERBOSE MirrorHelper.mirror():27 - Initializing HearthMirror with pid 72962
18:45:28.241 ERROR MirrorHelper.initMirror():57 - Mirror is not working, trying again...
That is the correct pid of the Hearthstone process it was initialized with. It failed regularly for 3 minutes and then looks like it was able to fetch my BattleTag and continue:
18:48:40.929 ERROR MirrorHelper.initMirror():57 - Mirror is not working, trying again...
18:48:51.429 ERROR MirrorHelper.initMirror():57 - Mirror is not working, trying again...
18:48:56.211 VERBOSE MirrorHelper.initMirror():52 - Getting BattleTag from HearthMirror : Atlas#1119
18:48:59.249 DEBUG CollectionWatcher.run():126 - got mirrorCollection
18:48:59.250 DEBUG CollectionWatcher.run():134 - Converting collection for upload
18:48:59.265 DEBUG CollectionWatcher.run():136 - Done converting
I played a full game of Battlegrounds and it didn't initialize until the very end I believe. It might have been after the game was over. If I understand correctly, the MirrorHelper is reading the memory of the Hearthstone process; maybe there are some assumptions in there about where stuff should be in memory that isn't always true any more. Tried to take a look, but it seems like that part of the code base is closed source.
Something odd though, it seems like there are some gaps in the log. Normally there is a half second between log lines, which makes sense based on the Sleep:
https://github.com/HearthSim/HSTracker/blob/master/HSTracker/HearthMirror/MirrorHelper.swift#L60
But sometimes there will be a full 5 or 10 second gap as I'm watching it. No hard evidence, but it seems like it happens when I don't have Hearthstone or HSTracker focused. It doesn't seem like the OS would be making either process sleep, and that's probably not related to the failures initializing the MirrorHelper, but I did find it interesting.
@jpalermo Thanks for your detailed log. I will have to take a look more closely on that part of the code to see if there is anything that could be causing it. I am on Catalina 10.15.7 and I haven't seen this problem, so it is hard to find exactly what's going on but I appreciate anything you can find. You could try running the Console.app and filter by HSTracker and see if anything jumps out there. No promises but maybe the mirror code could be logging something there as it won't go to the HST log.
Bah! Looks like it was my fault, sorry about that. Work installed CarbonBlack on my computer and it looks like it's preventing HSTracker from reading the memory. Found this in the Console.app:
default 21:06:16.877986-0800 repmgr The application "/Applications/HSTracker.app/Contents/MacOS/HSTracker" attempted to read the memory of "Hearthstone" (potentially scraping memory) by calling the function "task_for_pid". The operation was blocked by CbDefense
Confirmed that if I shut down the CarbonBlack processes HSTracker no longer stalls while trying to start HearthMirror
Thanks for the help pointing me where to look, I'll go ahead and close this out. It's good to know why it's happening, but I'm guessing it's not a priority to fix given the number of people impacted by this (possibly 1), and how difficult it would be to fix (possibly impossible).
@jpalermo Thanks for the update. It is interesting the CarbonBlack is blocking it even though it is signed application and has the debugging entitlement listed. I wonder if you can add HSTracker to the Developer Tools under Security&Privacy settings to give it an exception.
That seems like something CarbonBlack should respect, but it doesn't look like it does. Added HSTracker to the Developer Tools, restarted and enabled CarbonBlack, same behavior as before.
I'm guessing it's configured to just block all cross app memory scraping. Maybe that's one of the more heavy handed options in CarbonBlack that my employer has enabled, or maybe it just always does that. I don't have access to see the configuration for it so it's hard to tell.