Phergus wrote: ↑Tue May 14, 2019 5:13 pm
At the very least, we need a map with tokens and a bare bones macro that demonstrates the issue. Preferably exported from 1.4.0.5 that can then be tested against that, 1.4.1.8, NERPS 1.4.5.4 and 1.5.0.
Yeah, there is something weird going on... I've stripped out a bunch of stuff and the performance increases... but it doesn't make a lot of sense that it should because, as I mentioned above, I put a pause() before that single getTokens function and one after... and in doing so I can clearly tell that's were the delay is. Same campaign file directly from 1.4.0.5 to 1.5.2. In 1.4 it goes from pause to pause much more quickly than in 1.5.2. But if I strip the code out to a bare bones macro on a new map it doesn't do it.
Here is some logging showing the pauses around the getTokens call:
Code: Select all
06:39:51.106 INFO net.rptools.maptool.client.MapToolLineParser - up::Lib:MovePad::
06:39:51.108 INFO net.rptools.maptool.client.MapToolLineParser - stepDirection::Lib:MovePad::
06:39:51.113 INFO net.rptools.maptool.client.MapToolLineParser - changeFacing::Lib:MovePad::
06:39:51.158 INFO net.rptools.maptool.client.MapToolLineParser - pause::Lib:Setup::
06:39:52.976 INFO net.rptools.maptool.client.MapToolLineParser - pause::Lib:Setup::
06:39:53.134 INFO net.rptools.maptool.client.MapToolLineParser - setSingleAttack::Lib:Combat::
I clicked through the pauses as fast as I could and you can see that the majority of the time is in the getTokens call (nearly 2 seconds.) The rest of the macro is pretty fast.
Here is the logging without the pauses:
Code: Select all
06:37:05.768 INFO net.rptools.maptool.client.MapToolLineParser - up::Lib:MovePad::
06:37:05.770 INFO net.rptools.maptool.client.MapToolLineParser - stepDirection::Lib:MovePad::
06:37:05.776 INFO net.rptools.maptool.client.MapToolLineParser - changeFacing::Lib:MovePad::
06:37:07.318 INFO net.rptools.maptool.client.MapToolLineParser - setSingleAttack::Lib:Combat::
Showing 1.5 seconds for that particular step.
Not sure how to get the same clean macro logging from 1.4.0.5 (way easier to look at the log console in 1.5)... but here is the same bit of code to see the time between the two pauses:
Code: Select all
2019-05-15 07:40:40,143 [client.MapToolLineParser:1265] DEBUG - pause()
2019-05-15 07:40:40,144 [client.MapToolLineParser:1265] DEBUG - toolkit.DebugVariableCount = argCount()
2019-05-15 07:40:40,145 [client.MapToolLineParser:1265] DEBUG - toolkit.DebugInputParameter = ".|<html>" +
"<table cellspacing='2' cellpadding='0' style='background-color:#595751'>" +
"<tr><td>" +
"<table width='300px' cellspacing='0' cellpadding='2' style='background-color:#FAF9F5;'>" +
"%{toolkit.DebugVariableRows}</table></td></tr></html>" +
"|Debugger|LABEL|SPAN=TRUE"
2019-05-15 07:40:40,145 [client.MapToolLineParser:1265] DEBUG - toolkit.DebugVariableRow = "<tr %{toolkit.DebugVariableRowStyle}><td>" +
"<b>%{toolkit.DebugVariableName}</b></td><td>%{toolkit.DebugVariableContent}" +
"</td></tr>"
2019-05-15 07:40:40,146 [client.MapToolLineParser:1265] DEBUG - toolkit.DebugVariableRows = "<tr style='background-color:#E0DDD5; font-size:1.1em;'><td><b>Please Verify</b></td><td><b>Value</b></td></tr>"
2019-05-15 07:40:40,147 [client.MapToolLineParser:1265] DEBUG - toolkit.DebugVariableCount
2019-05-15 07:40:40,147 [client.MapToolLineParser:1265] DEBUG - if(toolkit.DebugVariableCount == 0, 1, 0)
2019-05-15 07:40:40,148 [client.MapToolLineParser:1265] DEBUG - toolkit.DebugVariableRows = "<tr><td style='font-size: 1.4em' align='center'><b>Pause</b></td></tr>"
2019-05-15 07:40:40,149 [client.MapToolLineParser:1265] DEBUG - toolkit.DebugBreak = input( strformat( toolkit.DebugInputParameter ) )
2019-05-15 07:40:40,364 [client.MapToolLineParser:1265] DEBUG - abort( toolkit.DebugBreak )
2019-05-15 07:40:40,366 [client.MapToolLineParser:1265] DEBUG - inPathNPC = getTokens("json", npcCond)
2019-05-15 07:40:40,389 [client.MapToolLineParser:1265] DEBUG - pause()
Harder to read, but you can see it moves through that getTokens function really quickly in 1.4. And, in fact, the entire step takes < half a second (a multiple of at least 3 times.) That's a big difference when you're moving a token 6-12 steps a round.
And perhaps unrelated...
I also noticed that I was getting a lot of red question marks when my character sheets were loading (pulling graphics from tables) and loading into maps that should have been fully cached. It was doing it all session... I was constantly seeing flashes of the red question marks.
I do two things different than the base install of MT expects:
1) I change the default install to a folder called "MapTool" on my desktop.
2) I create a custom data directory in my root directory and I use a different one for each version of MT.
But when I went in to look at the MapTool.cfg file (Maptool\app\MapTool.cfg) in my base install the JVMUserOptions did not match what the C:\User\Username\AppData\Roaming\net.maptools.maptool.client\packager\jvmuserargs.cfg JVMUserOverrideOptions were set at.
My Thread Stack size was not the same and the data directory did not match. Once I set those to be the same, the re-caching returned to more of what I was used to seeing in 1.4.