Inflated Memory Usage: consolidated thread (since v0.19.3)

[TickMan]

I figured a new "issue" would be less confusing for visitors... 😜

This is meant to be a consolidated thread for any issues relating to unexpected increases in the memory consumption of HSTracker.

(The most-recent thread can be found here, and some older threads can be found here...)

The two issues (that I know of) still present in v0.19.3 are:

1. The slow memory "growth" of 30-60MB per game, resulting in the process inflating to 200-900MB
   • (...may be a normal side-effect of HSTracker's current design?)
2. The rapid memory "spike" of 300-400MB per second, resulting in the process inflating to 2-60GB
   • (...has only occurred following an Arena a game?)

I'll try to come back and edit this post if any notable insights occur (or the developers are also welcome to do so), and will make a separate post below for my own "data".

-TM

[TickMan]

So... another afternoon playing Arena, and another memory-spike.

This time, I noticed it quickly and shut down HSTracker before my system even realized that anything was wrong... and there was also blissfully little happening in the background. How do I know all of that? Because I immediately went and scoured every System Message, Log, Diagnostic and Report for the timeframe involved and found virtually nothing but the HSTracker notifications.

I also found Hearthstone's own logs (in /Applications/Hearthstone/Logs, go figure 😜) and checked the same timeframe for anything "unusual" (not that I really know what to look for).

The result? I got nothing... well, not quite nothing: I've got all my (combined/sorted) logs for the timeframe involved! Maybe someone can see something I don't.

---

The Prequel (...everything in the 20 seconds pre-spike):

|I|15:11:10.207| You lose : (

D 15:11:12.2094490 PowerProcessor.EndCurrentTaskList() - m_currentTaskList=479
D 15:11:12.2095190 PowerTaskList.DebugDump() - ID=480 ParentID=0 PreviousID=0 TaskCount=1
D 15:11:12.2095610 PowerTaskList.DebugPrintPower() - BLOCK_START BlockType=TRIGGER Entity=GameEntity EffectCardId= EffectIndex=-1 Target=0
D 15:11:12.2096040 PowerTaskList.DebugPrintPower() -     TAG_CHANGE Entity=GameEntity tag=NEXT_STEP value=FINAL_GAMEOVER
D 15:11:12.2096270 PowerTaskList.DebugPrintPower() - BLOCK_END
D 15:11:12.2096480 PowerProcessor.PrepareHistoryForCurrentTaskList() - m_currentTaskList=480
D 15:11:12.2106530 PowerProcessor.EndCurrentTaskList() - m_currentTaskList=480
D 15:11:12.2106920 PowerTaskList.DebugDump() - ID=481 ParentID=0 PreviousID=0 TaskCount=2
D 15:11:12.2107140 PowerTaskList.DebugDump() - Block Start=(null)
D 15:11:12.2107500 PowerTaskList.DebugPrintPower() -     TAG_CHANGE Entity=GameEntity tag=STEP value=FINAL_GAMEOVER
D 15:11:12.2107870 PowerTaskList.DebugPrintPower() -     TAG_CHANGE Entity=GameEntity tag=STATE value=COMPLETE
D 15:11:12.2108080 PowerTaskList.DebugDump() - Block End=(null)
D 15:11:12.2108300 PowerProcessor.PrepareHistoryForCurrentTaskList() - m_currentTaskList=481
D 15:11:12.2108580 PowerProcessor.EndCurrentTaskList() - m_currentTaskList=481
D 15:11:12.2108860 PowerTaskList.DebugDump() - ID=482 ParentID=0 PreviousID=0 TaskCount=2
D 15:11:12.2109080 PowerTaskList.DebugDump() - Block Start=(null)
D 15:11:12.2109450 PowerTaskList.DebugPrintPower() -     TAG_CHANGE Entity=Steinfield tag=GOLD_REWARD_STATE value=2
D 15:11:12.2109790 PowerTaskList.DebugPrintPower() -     TAG_CHANGE Entity=TickMan tag=GOLD_REWARD_STATE value=2
D 15:11:12.2110040 PowerTaskList.DebugDump() - Block End=(null)
D 15:11:12.2110270 PowerProcessor.PrepareHistoryForCurrentTaskList() - m_currentTaskList=482
D 15:11:12.2110850 PowerProcessor.EndCurrentTaskList() - m_currentTaskList=482

|I|15:11:12.278| ----- Game End -----
|V|15:11:12.278| currentGameStats: Optional(statId: E5F6A0BA-BACF-4A8E-B189-9DD683D53A94-1489529000.84137, hearthstoneBuild: nil, playerCardbackId: -1, opponentCardbackId: -1, friendlyPlayerId: -1, scenarioId: -1, serverInfo: nil, season: 0, gameType: gt_unknown, hsDeckId: nil, brawlSeasonId: -1, rankedSeasonId: -1, arenaWins: 0, arenaLosses: 0, brawlWins: 0, brawlLosses: 0, format: nil, hsReplayId: nil, opponentCards: [], revealedCards: []), handledGameEnd: false
|V|15:11:12.496| End game: statId: E5F6A0BA-BACF-4A8E-B189-9DD683D53A94-1489529000.84137, hearthstoneBuild: Optional(17994), playerCardbackId: 4, opponentCardbackId: 61, friendlyPlayerId: 2, scenarioId: 2, serverInfo: Optional(ServerInfo {
    address = 24.105.24.86;
    auroraPassword = BHEkkd;
    clientHandle = 2807434;
    gameHandle = 4980769;
    mission = 2;
    port = 3724;
    resumable = 1;
    spectatorMode = 0;
    spectatorPassword = ckHdfa;
    version = 350184;
}), season: 36, gameType: gt_arena, hsDeckId: Optional(742814848), brawlSeasonId: 0, rankedSeasonId: 41, arenaWins: 0, arenaLosses: 1, brawlWins: 0, brawlLosses: 0, format: nil, hsReplayId: nil, opponentCards: [], revealedCards: []
|I|15:11:12.537| Cleared secrets
|I|15:11:12.553| GOLD_REWARD_STATE not found

D 15:11:17.5078570 BeginEffect blur 1 => 1

D 15:11:21.8053140 LoadingScreen.SetTransitionAudioListener() - AudioListener (UnityEngine.AudioListener)
D 15:11:21.8053920 LoadingScreen.OnScenePreUnload() - prevMode=GAMEPLAY nextMode=DRAFT m_phase=INVALID
D 15:11:21.9728300 Gameplay.Unload()
D 15:11:21.9737740 LoadingScreen.OnSceneUnloaded() - prevMode=GAMEPLAY nextMode=DRAFT m_phase=WAITING_FOR_SCENE_UNLOAD
D 15:11:21.9738090 LoadingScreen.OnSceneUnloaded() - m_assetLoadEndTimestamp=5247937281245441984
D 15:11:22.0002120 Gameplay.OnDestroy()

D 15:11:24.9890380 Box.Awake()
D 15:11:24.9892580 LoadingScreen.DisableTransitionUnfriendlyStuff() - TheBox(Clone) (UnityEngine.GameObject)

The Trigger (...it starts at some point during this 4-second timeframe):

D 15:11:30.8066030 DraftManager.OnChoicesAndContents - Draft Deck ID: 742814848, Hero Card = HERO_01
D 15:11:30.8066860 DraftManager.OnChoicesAndContents - Draft deck contains card CFM_756
D 15:11:30.8067540 DraftManager.OnChoicesAndContents - Draft deck contains card CFM_321
D 15:11:30.8067860 DraftManager.OnChoicesAndContents - Draft deck contains card EX1_028
D 15:11:30.8068270 DraftManager.OnChoicesAndContents - Draft deck contains card EX1_586
D 15:11:30.8068760 DraftManager.OnChoicesAndContents - Draft deck contains card OG_315
D 15:11:30.8069340 DraftManager.OnChoicesAndContents - Draft deck contains card EX1_020
D 15:11:30.8069770 DraftManager.OnChoicesAndContents - Draft deck contains card CFM_656
D 15:11:30.8070480 DraftManager.OnChoicesAndContents - Draft deck contains card OG_156
D 15:11:30.8070840 DraftManager.OnChoicesAndContents - Draft deck contains card CFM_755
D 15:11:30.8071270 DraftManager.OnChoicesAndContents - Draft deck contains card OG_138
D 15:11:30.8071600 DraftManager.OnChoicesAndContents - Draft deck contains card CFM_120
D 15:11:30.8071970 DraftManager.OnChoicesAndContents - Draft deck contains card EX1_603
D 15:11:30.8072360 DraftManager.OnChoicesAndContents - Draft deck contains card EX1_407
D 15:11:30.8072770 DraftManager.OnChoicesAndContents - Draft deck contains card EX1_604
D 15:11:30.8073160 DraftManager.OnChoicesAndContents - Draft deck contains card CFM_647
D 15:11:30.8073690 DraftManager.OnChoicesAndContents - Draft deck contains card AT_114
D 15:11:30.8074050 DraftManager.OnChoicesAndContents - Draft deck contains card OG_271
D 15:11:30.8074480 DraftManager.OnChoicesAndContents - Draft deck contains card OG_150
D 15:11:30.8074870 DraftManager.OnChoicesAndContents - Draft deck contains card LOE_089
D 15:11:30.8075350 DraftManager.OnChoicesAndContents - Draft deck contains card EX1_283
D 15:11:30.8075820 DraftManager.OnChoicesAndContents - Draft deck contains card AT_087
D 15:11:30.8076240 DraftManager.OnChoicesAndContents - Draft deck contains card EX1_409
D 15:11:30.8076610 DraftManager.OnChoicesAndContents - Draft deck contains card NEW1_018
D 15:11:30.8077150 DraftManager.OnChoicesAndContents - Draft deck contains card OG_327
D 15:11:30.8077670 DraftManager.OnChoicesAndContents - Draft deck contains card CFM_688
D 15:11:30.8078160 DraftManager.OnChoicesAndContents - Draft deck contains card CFM_063
D 15:11:30.8078630 DraftManager.OnChoicesAndContents - Draft deck contains card AT_103
D 15:11:30.8079050 DraftManager.OnChoicesAndContents - Draft deck contains card BRM_025
D 15:11:30.8079600 DraftManager.OnChoicesAndContents - Draft deck contains card AT_069
D 15:11:30.8081110 SetDraftMode - ACTIVE_DRAFT_DECK

|I|15:11:30.887| Found arena hero : warrior

D 15:11:32.5895180 LoadingScreen.OnSceneLoaded() - prevMode=GAMEPLAY currMode=DRAFT
D 15:11:32.5895840 LoadingScreen.HackWaitThenStartTransitionEffects() - START
D 15:11:32.5964810 LoadingScreen.FadeOut()
D 15:11:33.6062350 LoadingScreen.OnFadeOutComplete()
D 15:11:33.6062810 LoadingScreen.FinishPreviousScene()
D 15:11:33.6067580 LoadingScreen.ClearPreviousSceneAssets() - START m_assetLoadStartTimestamp=5247937276259001064 m_assetLoadEndTimestamp=5247937281245441984
D 15:11:33.6067880 LoadingScreen.ClearAssets() - START startTimestamp=5247937276259001064 endTimestamp=5247937281245441984 diff=4986440920
D 15:11:33.6069270 LoadingScreen.ClearPreviousSceneAssets() - END m_assetLoadStartTimestamp=5247937281245441984 m_assetLoadEndTimestamp=0
D 15:11:33.6069590 LoadingScreen.FadeIn()

|I|15:11:32.643| Game mode from Optional(HSTracker.Mode.gameplay) to Optional(HSTracker.Mode.draft)
|V|15:11:32.643| Game is now in menu
|I|15:11:32.643| Starting ArenaDeckWatcher

D 15:11:34.6720720 LoadingScreen.OnFadeInComplete()

The Finale (...the remainder of the spike and my quitting HSTracker)

Mar 14 15:11:38 TickMan-MacBook Dock[299] <Notice>: 

|I|15:11:39.703| Stop Tracking
|I|15:11:39.703| Stopping all trackers
|I|15:11:39.703| Stopping tracker power
|I|15:11:39.717| Stopping tracker rachelle
|I|15:11:39.717| Stopping tracker arena
|I|15:11:39.718| Stopping tracker loadingScreen
|I|15:11:39.718| Stopping tracker fullScreenFX
|I|15:11:39.719| Stopping tracker power
|I|15:11:39.719| Stopping DeckWatcher
|I|15:11:39.720| Stopping ArenaDeckWatcher

---

Of note: the only system process in all the combined logs/messages for the timeframe was a single notice from the Dock after the spike started ramping-up (as I mentioned, a "blissfully quiet" background)... so if there's any clues to be found, I suspect that they're in the Hearthstone logs being "watched" by HSTracker.

Unfortunately, I can't see any appreciable differences between the logs of the "spiked" game and my previous ones... so I can only hope that this data will be more useful to someone else! ¯\_(ツ)_/¯

Good luck,

-TM

[ghost]

I had a memory leak / spike as well during my arena run, so just confirming.

[aemrich]

I've had the rapid memory spike outside of arena games. Just wanted to add on here.

[TickMan]

I've had the rapid memory spike outside of arena games. Just wanted to add on here.

Hmm, good to know... is it possible you had played Arena earlier, or was it a completely "Arena-less" gaming-session?

-TM

[ghost]

It was just one time and I haven't had any issues since; if it happens again, I'll do a better job of processing what happened.

Best,

On Thu, Mar 23, 2017 at 6:36 PM, TickMan notifications@github.com wrote:

I've had the rapid memory spike outside of arena games. Just wanted to add on here.

Hmm, good to know... is it possible you had played Arena earlier, or was it a completely "Arena-less" gaming-session?

-TM

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/HearthSim/HSTracker/issues/774#issuecomment-288892254, or mute the thread https://github.com/notifications/unsubscribe-auth/AZBnc_7FQ-6GXMBUCfCSriTHjof5_oRbks5rowHpgaJpZM4MdYZT .

[ausgop]

I have had numerous memory spiked, can figure out a pattern for it though. I have resorted to keeping Activity Monitor running and just restarting HSTracker when things grow above 1GB. Almost all instances are with no Arena

[TickMan]

I have had numerous memory spiked, can figure out a pattern for it though.

How "numerous" are we talking about? 80% of games? 50%? 20%? Lately I've only been experiencing it after about 10% of my arena games... maybe less. If you get it considerably more often, perhaps we could speculate about how your circumstances might differ from other users?

I have resorted to keeping Activity Monitor running and just restarting HSTracker when things grow above 1GB.

I do the same... but more in an attempt to pinpoint the exact moment that the "spike" starts.

Almost all instances are with no Arena

Really? Damn... I had hoped that it was one thing that we all had in common, but apparently even that isn't consistent. I'll edit the first post to reflect it. ¯\_(ツ)_/¯

I can't get over how such an explosive memory-leak is simultaneously infrequent/widespread. Trying to identify the triggering condition is bordering on "superstition" at this point... could it be the random map I'm playing on? A letter in my opponent's name? The color of my socks? It's maddening! 😜

-TM

[aemrich]

I'm not sure of the pattern either. I never play Arena, and I only notice the spikes when my computer slows down and activity tracker shows me that HSTracker is taking up an absurd amount of ram (40+GB).

[bewebste]

I've seen this happen a number of times on my own system. I always play Arena, so I don't know whether Arena vs. constructed makes a difference. The last time it happened, it was just after completing an Arena run (11-3 Rogue lost vs. constructed Jade Shaman FeelsBadMan). I managed to get a sample using Activity Monitor before I had to kill it, and have attached that here. Hope that helps! Sample of HSTracker.txt

[TickMan]

The last time it happened, it was just after completing an Arena run (11-3 Rogue lost vs. constructed Jade Shaman FeelsBadMan).

I can empathize... sometimes I swear that my occasional Arena triumphs have nothing to do with my ability, and are simply indicators that I avoided enough ridiculous opponents on those runs. ¯\_(ツ)_/¯

I managed to get a sample using Activity Monitor before I had to kill it, and have attached that here.

Holy crap, that totally slipped my mind... good call! I'll do the same next time I play. (Also... if you are who I think you are, your PList Editor got me out of a bind a couple of years ago, making you officially awesome!) 👍

-TM

[lmeuser]

This is not an Arena thing, I pretty much exclusively play Constructed and I also get the spikes.

[ifeherva]

Thanks @bewebste, your log helped me to find the root of the problem. It is mirror where I committed the fix so it will be there in the next release.

@lmeuser Yes, this is not an arena issue, but was superhard to recreate.

[bewebste]

Cool, glad the sample helped! And yes @TickMan, I am the PlistEdit Pro guy - glad to hear it came in useful. 🙂

[bmichotte]

out of scope: Awesome @bewebste, I used to use it also :) Glad you're part of the HSTracker community :)

[bmichotte]

Guys, I just published a beta with the fix from @ifeherva, could you please test it and report any progress/regression ?

[ausgop]

Playing with the new beta for about an hour...all constructed, no arena and memory spiked up to 4+ GB in the middle of a game. Attached a sample at the time. Also, your opponent's name does not show up in the beta.

Sample of HSTracker.txt

[ausgop]

Looks like the opponent name does appear but doesn't update.

[bewebste]

Did several sessions today with the beta and worked OK (except for the thing with the opponent name not updating), but finally run into a runaway memory during an Arena run.

To give you an idea of my usage pattern, I tend to only play a game or two at a time throughout the day, and typically just leave HSTrack running in the background all the time, only launching Hearthstone when I'm actually playing.

I'd done this a few times today, and then on my last session after starting my second game, I noticed the tracker wasn't updating with my drawn cards. Checked and saw the memory bug doing its thing, so grabbed another sample attached here. Sample of HSTracker.txt

Also attached today's HSTracker log in case that's helpful. I relaunched the app after force quitting it so I could look at my deck list during the second game. 2017-03-30.log.txt

[akodate]

I'm also experiencing frequent acute memory leaks in 0.20 and ever since the Un'Goro update.

[buddhapest]

0.20.1 here - played maybe 4 games - memory usage of HSTracker is... 41GB (yes, GIGAbytes) - os x not happy

edit: non-arena games - just standard ladder

[AlexanderSchmedes]

Hey, Version 0.20.1 (1529) here, have to restart it every few games since it starts using 4gb+ and doesn't work/upload replays anymore.

Standard ladder too.

[jus10g]

Same here. 0.20.1 here. Memory leak becomes intolerable after about 3 games in Standard or Wild.

[mrduit]

same issue here. Memory leak becomes so unbearable. Please fix this bug ASAP.

[mlippold]

Same issue as well. I even use an app called Memory Clean 2 and it can't keep up with the leak.

[Tzachizach]

I am on 0.20.1 and i believe i am experiencing similar symptoms to those mentioned in this thread. I will follow it closely.

[Mars19845]

I am also on 0.20.1 and i am experiencing the same issue. The pictures i took were from a casual game. This memory ramping stayed around 30 gb but i have experienced 60+ gb.

[all-your-database]

Having the same issue. I'm not a great programmer but if you need any info or tracing let me know and I'll provide it. The memory leak is making the tracker basically unusable for a few weeks now.

[ruchernchong]

@ifeherva Looking through the commits of the memory_leak_fix branch, how is the progress going? Not too familiar with Swift so could not really understand much.

[mlippold]

I complied the current memory fix branch the other day (with all of the current commits) and it is still doing it. Hopefully they have a handle on what is doing it and just working offline on it. As far as I can tell it is completely random. I've had it happen during games.. after games etc.. The longest stretch that it has worked with no issues was yesterday and went like 6 games without spinning out of control.

[ifeherva]

A new beta has just been released that should solve a lot of problems, including the memory leak. Please test and give feedback: https://github.com/HearthSim/HSTracker-Beta/releases/tag/0.21-beta1

[mlippold]

Giving it a try. Thanks!

[mrduit]

@ifeherva May i ask why the release time is one year ago?

[ruchernchong]

@sisuclimber Probably some glitch at Github side. Look at all the releases here. All releases are at 15 Aug 2016.

[mrduit]

@ruchern Thanks for the information.I will give it a try.

[mrduit]

The memory usage begins about 120MB, it increases with each game by 60~80MB. It's better than before, but the issue still is not fixed?

Sorry for my poor English, just want to provide the feedback.

[ifeherva]

That is a known issue, certain swift factory-functions leak, we are hoping apple will address them at some point.

[mrduit]

so, the way we use HSTracker for now is to stop and restart it after several games,right? Hope apple can fix the issue soon.

[ifeherva]

I have a partial solution that resets certain modules to clean up unused memory but it takes cpu usage in return... so not ideal for people on macbooks.

[mrduit]

Heartfelt thanks.

[mlippold]

I just use Memory Cleaner from the app store (free) and set it to run at startup and check the automatic optimization checkbox at the highest memory threshold it lets you set it to (mine is at 2,048). This may be the type of thing that ifeherva was talking about that frees up memory at a cost of CPU though.

Even with a small leak like this it is completely usable (unlike the memory situation that was happening pre-beta).

[ifeherva]

@mlippold not at all. Memory reserved by an app cannot be freed with an other app, only the operating system has access to it. HSTracker is parsing several thousand lines per game, each parsing is calling swift string functions that leak. I can allocate a special mempool, but it has to be then drained after each line is processed: this is extremely cpu intensive. I am testing several solutions for this problem, but xcode profiling takes ages and I cannot just "leave it alone", because the game will log out due to inactivity. That is why you guys have to wait so long for such performance fixes.

[mlippold]

Got ya.

[mlippold]

ifeherva, I compiled the latest version of master with the "autoreleasepools" update and the memory is holding steady at 211mb after 5 games. 👍

[mrduit]

@bmichotte May I ask when will the new version be released? I'm looking forward to it.

[Havok56]

Hello, display the name of the opponent seems to no longer work.

[buddhapest]

Hello, display the name of the opponent seems to no longer work.

~read title of this issue: create a new issue~ actually it's already been reported: https://github.com/HearthSim/HSTracker/issues/783

[Havok56]

Ok, sorry.

[bewebste]

I've been running this beta for the last few days, and the memory usage appears to be under control in my usage at least. 👍

[bmichotte]

Awesome. We have a last issue with HSReplay uploading. As soon as this issue is resolved, HSTracker will turn 1.0 !

[ruchernchong]

@bmichotte v1.0 that's a huge leap. But at least we are now a major version in!