Bug - Not A Bug KoLmafia using up lots of CPU

Z

Zyro

Member
I didn't notice exactly when it started happening, but recently KoLmafia has been using up large amounts of CPU after running (including 30+% CPU when idle). Clicking the "Collect Garbage" button seems to reset the CPU back to ~0%, but if I use it to automate anything again, it goes back up to 30% and stays there. This results in not only slowing down KoLmafia drastically but also causes my fan to run really loudly.

I download the latest build from http://ci.kolmafia.us/job/Kolmafia/ on a regular basis, so maybe it was an update that changed something?

I would like to know if anyone else has had this issue and whether there is a known fix.

Thanks,
Zyro
 
People have reported something that might be similar but no one has gotten to the bottom of it. And not everyone sees similar behavior.

I'm not sure how I would debug/diagnose this even if I were setting at your computer. The first thing that comes to mind is that the total amount of resources needed to run KoLmafia and everything else you run at the same time approaches the capacity of your hardware.

What OS are you running? How many cores does your machine have? How much memory?

If you run TaskManager or the equivalent is KoLmafia the only process that is consuming significant CPU (more than 5%) or is it one of many. For example, Firefox often is a resource hog on my system and in a relay browser situation it makes a difference whether it is KoLmafia (Java) or the browser that is consuming the resources.

Are there processes that are using a significant amount of memory, possibly including KoLmafia? Does KoLmafia's memory use increase?

It has been a long time since I had to micromanage Java's memory use. My recollection is the operating system allocates memory and Java manages it. If Java needs more it either asks and receives or aborts with an out of memory error. What you describe sounds like Java memory management but it is not clear whether Java is (on its own) Garbage Collecting a lot or what.

Grasping at straws, there are two numbers in the "GC counter". Does the second one ever change? Does the first one go up and down as you automate but don't touch the GC button?

I'm thinking this is an issue with your environment and adding a lot of new items (Pokefams, for example) to KoL pushed your system to the limit, but I don't know so this is nothing more than speculation.
 
Hi fronobulax,

Thank you for the response. Let me try to answer your questions in order.

I am running Windows 10 on a Microsoft Surface Book with Performance Base. It has 2 cores and 16 GB of ram. I would be surprised if my hardware were the issue, since in the past I have had no problems running KoLmafia on the same machine (and even earlier ones).

I often have a lot of programs up and running, but again, it's always been this way and I haven't encountered this issue previously. Here is a screenshot of my Task Manager right now that shows the situation: https://i.imgur.com/FoYTefW.png

All I did to trigger the CPU increase in KoLmafia was type the line "/count freddy k" in the gCLI. I guess I don't have to be automating something for this to happen - doing almost anything in KoLmafia appears to trigger it.

As far as I can tell, the second number in the GC counter does not change.

I do not know what my environment means, but if it's relevant at all, I have not done the Pokefam path yet.


EDIT: Based on my (admittedly limited) testing, doing things in the relay browser does not cause the CPU to increase, while doing things in the KoLmafia program usually triggers the increase after only a couple actions.
 
Last edited:
So I actually paid attention to Task Manager while running. Windows 10, 8 core, 16 GB. CPU was generally under 10% and no signs of memory issues, with one exception. The character running Veracity's Meat Farming script with BestBetweenBattles enabled was seeing CPU close to 20% and after a while the fan came on. So there may be something there.

Your screen grab does not suggest any memory issues although it would be interesting to see what changes if Chrome and Firefox were not sucking up so much memory. It would also be interesting to see what happened if Java were given more memory when it started. That's probably a Windows 10 setting although I have not researched where it can be changed.

I will ponder.
 
Based on (again) limited testing, it seems that using the .exe program found here: https://sourceforge.net/projects/kolmafia/ does not cause the high CPU issue, but using the .jar file found here: http://ci.kolmafia.us/job/Kolmafia/ does.

I have to use the .jar file because I have a weird scaling issue that makes KoLmafia super tiny on Windows 10 (it's described here: https://www.reddit.com/r/kol/comments/4buhtq/finally_managed_to_get_kolmafia_to_work_in/). There is a fix mentioned in a link on that thread, which I've applied, and it only fixes the display problem for the .jar file and not the .exe.

I recently installed a Java update, so I don't know if that could possibly be the cause of the CPU issue.


EDIT: I did a little bit of digging online and saw garbage collection mentioned several times regarding high CPU usage for a Java program. Since clicking the GC button in KoLmafia appears to be a temporary fix, I feel that this is definitely somehow related (though I have zero technical expertise on this subject).

Also, typing "/count anything" in the gCLI will trigger the high CPU usage without fail for me.
 
Last edited:
The .exe from SourceForge was updated in December whereas the jar file from KoLmafia.us is built from the most recent code available. It is possible that changes to KoL that are reflected in KoLmafia (new items, etc.) could account for the difference. But it is also possible, if this is a memory issue, that Windows allocates more memory for the .exe than the .jar.

I have solved the scaling issue and commented on it KoLmafia.us. Try searching on HDPI or DPI but it is basically the reddit solution. It can be applied to the .exe with a little digging but, to be honest, I'll never run the .exe and it is not worth the effort.

Generally Java only does garbage collection when it needs memory or there is a lot of garbage. So one quick test would be to try and tell the operating system to start Java with more memory. I cannot trivially find the default settings for Windows or how to change them at the OS level, but if you open Windows cmd, change to the directory that contains the jar file, (and presumably all your mafia files) and type

Code: 
java -Xms256m -Xmx2048m -jar KoLmafia-18577.jar

that will run mafia with a known amount of memory. You should use change the jar file name parameter to match the version you have. Depending on how you implemented the HDPI fix you may find this launches tiny screen mafia (in which case find java.exe and add a manifest file there, assuming you understand the fix). You should not have to change the 2048 unless you get an out of memory abort or the operating system complains it can't allocate that much. The key is the 256. If you really have a garbage collection problem then increasing "the 256" should result in less GC and possibly address your problem. I suspect the 256 might be higher than your system's default is so try that first.

It is good to know that /count is a culprit. What is it supposed to do? I have a vague recollection that slash anything in the gCLI invokes a chat command that is "native" to KoL but since I take a perverse pleasure in ignoring all things chat as much as possible I will plead ignorance :-)
 
I do not know how to use the command prompt to change to the directory with mafia, but I did follow the instructions here to allocate more memory to Java: http://www.messiahpsychoanalyst.org/wikihow/index.php/How_to_Increase_Java_Memory_in_Windows Unfortunately, it did not solve the issue, as another "/count " made the CPU jump up to 20-30% as usual.

/count is a chat command that counts the number of an item in your inventory. I was only using it as an example of a basic command that causes the problem - other gCLI commands do the same thing (e.g., https://i.imgur.com/J0WZewN.png). Perhaps interestingly, after I reset the CPU and ran a script from the scripts menu, the CPU stayed normal (so not everything causes the CPU to increase).

Doing anything in the gCLI does appear to always trigger it, and based on what I've noticed, automating turns will also trigger it.
 
Also, fwiw, typing "gc" in the gCLI causes the first number in the GC counter to oscillate up and down and triggers the CPU increase.
 
Zyro said:
other gCLI commands do the same thing
Click to expand...

That also shows a chat command. Does it only happen after using chat commands (AFAIK anything that starts with / is essentially passed to kol's chat system somehow?), or normall mafia commands (for something that will probably hit the server, try ... hmm ... putting something in your DC? or searchmall? or refresh all?)
(to be clear: I am now asking if this happens even if you *never* use a chat command in the gCLI)


Zyro said:
Also, fwiw, typing "gc" in the gCLI causes the first number in the GC counter to oscillate up and down and triggers the CPU increase.
Click to expand...

That's probably normal. GC is always CPU work. Unless it takes longer than half a second or so.

To me, this sounds a little like what I sometimes see on out work windows machines - there still seems to be RAM free, but the system starts swapping like hell for some reason. With a SSD you wouldn't even hear it (and with a modern thin thingy there wouldn't even be an activity light).
 
I will note that this might be Much Ado About Nothing since I am used to bursts of 20% CPU with associated fan operations on a slightly more powerful machine and consider it normal. That said since there is an assertion that it only started happening recently there may be some code that could be looked at. I will also note that writing Java to implicitly manage GC is not for the faint of heart and migth even be a Fool's Errand.

Profiling options have changed significantly since the last time I had to do it for real -)
 
Zyro said:
I do not know how to use the command prompt to change to the directory with mafia, but I did follow the instructions here to allocate more memory to Java: http://www.messiahpsychoanalyst.org/wikihow/index.php/How_to_Increase_Java_Memory_in_Windows Unfortunately, it did not solve the issue, as another "/count " made the CPU jump up to 20-30% as usual.
Click to expand...

That link has -Xmx2048m being changed. If this is a GC problem you should do the same thing but enter -Xms256m (or similar). If my memory is not completely shot -Xmx sets the maximum amount of memory Java is allowed to use. -Xms sets the initial heap size. When Java runs out of memory it will GC and if it still needs some ask for more up to the -Xmx value. So in a primitive way if -Xms is increased the amount of time between calls to GC should increase because there is more memory initially available.
 
xKiv said:
That also shows a chat command. Does it only happen after using chat commands (AFAIK anything that starts with / is essentially passed to kol's chat system somehow?), or normall mafia commands (for something that will probably hit the server, try ... hmm ... putting something in your DC? or searchmall? or refresh all?)
(to be clear: I am now asking if this happens even if you *never* use a chat command in the gCLI)
Click to expand...

As far as I can tell, typing anything in the gCLI and pressing enter causes the CPU to rise to around 30% and it doesn't go down until I press the Garbage Collect button or restart mafia. I just tested by typing "cast ode" (no / in front of cast) and the same thing occurred.

xKiv said:
That's probably normal. GC is always CPU work. Unless it takes longer than half a second or so.
Click to expand...

It takes far longer than half a second - I've seen the CPU stay at around 30% for many minutes before I press the GC button to make it go back down. In fact, it's never gone down again by itself in any of these situations.
 
fronobulax said:
I will note that this might be Much Ado About Nothing since I am used to bursts of 20% CPU with associated fan operations on a slightly more powerful machine and consider it normal.
Click to expand...

It is not bursts of high CPU usage - every time this occurs, even with very minimal mafia usage (e.g., typing a single line in the gCLI and hitting enter), it will go up to around 30% and stay there permanently until I manually do something about it.

EDIT: To add to this, under regular conditions, mafia's CPU usage is usually no higher than 10% for me. I'm running an ascension script right now, and after a short while, the CPU rocketed up to 30+%. I clicked the GC button while the script was still running, and the CPU went back down to below 5%. Several minutes have passed since then, and now it is back up to 30+%. (Cycle repeats...)

fronobulax said:
That link has -Xmx2048m being changed. If this is a GC problem you should do the same thing but enter -Xms256m (or similar). If my memory is not completely shot -Xmx sets the maximum amount of memory Java is allowed to use. -Xms sets the initial heap size. When Java runs out of memory it will GC and if it still needs some ask for more up to the -Xmx value. So in a primitive way if -Xms is increased the amount of time between calls to GC should increase because there is more memory initially available.
Click to expand...

I just tried that as well, but to no avail. Fwiw, after doing that and restarting mafia, the second number in the GC counter hasn't changed.
 
Last edited:
After further testing, it definitely seems like the issue is connected to the gCLI. I can reproduce causing the CPU to spike and then go back down as follows:

1. Type anything in the gCLI and press enter (e.g., "cast ode")
2. Perform another action in mafia not using the gCLI (e.g., run a script, automate some turns, or press the GC button)

Performing step 1 causes the CPU to rise to 20-30% almost instantaneously, and performing step 2 causes it to drop back down to <5% just as fast.

At this point, I am out of ideas for testing.
 
On my system the second GC number is 3704832KB so it is pretty obvious I am running KoLmafia with more resources than you. I cannot recall seeing the first number ever exceed a tenth of the second. I have some instrumentation in place. I'm not making sense yet. I'm running scripts and all of the hot spots seem to be associated with parsing and executing scripts. There doesn't seem to be a lot of garbage collection going on but that may be me not understanding how much time I am looking at.

Since your test is pretty specific I will try it at some point and see if I can learn anything.
 
Mine is at 1853440 KB, and when idling first number is around 1/10 of that. I can well believe that having only 256 MB allocated is a level easily exceeded and may trigger garbage collection if close.

Edit - Saw it hit 310 MB when maximizing and equipping that equipment. Was a lot lower when actually running automation.
 
Last edited:
You must log in or register to reply here.
Back
Top