I am currently trying to pin down some client performance issues with the stat() panel on an ss13 server. To this end I've been trying to make test cases that might illustrate the issues & provide something that can be debugged.
However, one hurdle I've come across is that quantifying the lag produced by the panel itself is difficult. The CPU & time spent on a client/stat() call appears to be disproportionate to the effect it has on client performance; it's punching well above its weight on the profiler. This makes it difficult to test different things, as I have to rely on largely qualitative performance changes (ie: does this feel more or less choppy than before?).
Numbered Steps to Reproduce Problem:
1. Run the test project from the code snippet.
2. Profile 100 calls on status panel static.
3. Profile 100 calls on status panel large.
4. Compare results.
Code Snippet (if applicable) to Reproduce Problem:
var/global/number = 0
var/global/name = "Points"
var/global/looping = 1
var/global/lastoutput = 0
var/global/timedifference = 0
world
tick_lag = 0.1
New()
simulate_game()
proc/simulate_game()
var/counter = 0
while(looping)
for (var/i = 1 to 100)
for (var/j = 1 to 100)
for (var/k = 1 to 100)
counter = counter + 1
sleep(5)
increment_number()
timedifference = (world.timeofday-lastoutput) / 10
world << "The game loop finished in [timedifference] real seconds"
lastoutput = world.timeofday
proc/increment_number()
number = number + 1
client
Stat()
if(statpanel("Static"))
stat("Value","Number")
sleep(1)
if(statpanel("Small"))
stat("Value","Number")
stat("[name]","[number]")
stat("[name]","[number]")
stat("[name]","[number]")
sleep(1)
if(statpanel("Large"))
stat(name, number)
var/counter2
for (var/l = 1 to 100)
counter2 = counter2 + 1
stat(name, counter2)
stat(null,"")
stat("The quick brown fox", "jumped over the lazy dog [number] times")
stat(null,"")
stat("The quick brown fox", "jumped over the sleepy dog [number + 2] times")
stat(null,"")
stat("The quick brown fox", "flew over the sleepy dog [number / 2] times")
stat(null,"")
stat("The quick brown ghost", "flew over the sleepy dog [number ^ 2] times")
stat(null,"")
stat("The quick brown ghost", "flew through the sleepy dog [number + number] times")
stat(null,"")
stat("The quick friendly ghost", "flew through the sleepy dog [1 - number] times")
stat(null,"")
stat("The mischevious friendly ghost", "flew through the sleepy dog [(1 - number)^2] times")
stat(null,"")
stat("The mischevious friendly ghost", "flew through the sleepy town [(1 + number)^0.5] times")
stat(null,"")
stat("A mischevious friendly ghost", "flew through the sleepy town [number - 6] times")
stat(null,"")
stat("A mischevious friendly ghost", "flew through my sleepy town [number/8 + 100] times")
stat(null,"")
stat("A mischevious friendly ghost", "flew through the sleepy town [number - 6] times")
stat(null,"")
stat("The mischevious friendly ghost", "flew through the sleepy town [(1 + number)^0.5] times")
stat(null,"")
stat("The mischevious friendly ghost", "flew through the sleepy dog [(1 - number)^2] times")
stat(null,"")
stat("The quick friendly ghost", "flew through the sleepy dog [1 - number] times")
stat(null,"")
stat("The quick brown ghost", "flew through the sleepy dog [number + number] times")
stat(null,"")
stat("The quick brown ghost", "flew over the sleepy dog [number ^ 2] times")
stat(null,"")
stat("The quick brown fox", "flew over the sleepy dog [number / 2] times")
stat(null,"")
stat("The quick brown fox", "jumped over the sleepy dog [number + 2] times")
stat(null,"")
stat("The quick brown fox", "jumped over the lazy dog [number] times")
sleep(1)
Expected Results:
I would expect that any lag caused by the stat() command is proportionate to the delay that is displayed on the profiler.
Actual Results:
With the static panel open (which should be relatively performant), I got the following results profiled:
client/stat():
- Self CPU: 0.000
- Total CPU: 0.000
- Real time: 11.812
- Real time (avg): 0.117
- Calls: 101
/increment_number()
- Calls: 33
- Game loop range: 0.5 - 0.6 seconds
With the large panel open (which should be bad for performance), I got the following results profiled:
client/stat():
- Self CPU: 0.000
- Total CPU: 0.000
- Real time: 12.222
- Real time (avg): 0.119
- Calls: 103
/increment_number()
- Calls: 33
- Game loop range: 0.7 - 0.8 seconds
Given that:
- Increment number calls 33 times in both.
- Each increment number call is taking 0.1 seconds longer (conservative)
- The total real time delay should be 3.3 seconds
However:
- The total real time delay accounted by the profiler is 0.4 seconds.
or
- Measured real time on the proc has increased 3%, but in-game lag has increased 16%
Hope someone can help!
Does the problem occur:
Every time? Or how often? Every time
In other games? At least one other
In other user accounts? Presumably
On other computers? Not sure
When does the problem NOT occur?
Not sure
Did the problem NOT occur in any earlier versions? If so, what was the last version that worked? (Visit http://www.byond.com/download/build to download old versions for testing.)
Not sure
Workarounds:
Don't know - is there some neat trick I can use to assign a performance metric to a stat panel & shine a light on how long some of the background processes are taking?
(though advice on assigning a cost to stat() elements still welcome!)