Profiling in LoG1

[Diarmuid]

Hi guys,

I'm working on streamlining the ORRR2, and am wondering if there's any way to run some benchmark-type measurments. I tried getStatistic("play_time") like this:

Code: Select all

	print(getStatistic("play_time"))
	for i = 1, 500000 do
		local x = findEntity("temple_secret_door_90")
	end	
	print(getStatistic("play_time"))

but it returned the same value despited waiting a good 3-4 seconds between the two calls. This means play_time is updated between frames. Any other way to get a precise time measurments?

[JohnWordsworth]

I guess it makes sense that play_time is update between frames as it needs to be scaled if you are resting! as well as it being more convenient for any dt evaluations in scripts to all be seeing the same dt (derived from play_time).

As os.time() isn't available, my only suggestion is very faffy, but if you did want to estimate the impact of a given (repeatable) function, I would...

Frame 1: Store play_time
Frame 2: Calculate dt1 and store new play_time - now you have dt without running your method. Then run your method in a for loop 1,000 times.
Frame 3: Calculate dt2. This dt will theoretically be dt1+time to run your method 1,000 times.

So, 1000x = dt2-dt1 (where x is the time for your function to run)
Or x=(dt2-dt1)/1000

Now, obviously dt is not always the same each frame, even when not running your function. The logic though is that 1000x is hopefully high enough to cause a 1-10 second delay say, which means even natural variations in the standard dt of the dungeon will not have too much of an impact. If it does, make it 10,000 runs :p.

[Diarmuid]

Hi! With JohnW's suggestion, I managed to code a profiler which works reasonably well. You pass it a function, and it gives you approximately how many ms it takes to run.

Put the code in a script entity named "logProfiler". Then call the profiler using something like that (example called from onDrawGui using profileOnce, you can manually call profile as well).:

Code: Select all

	logProfiler.profileOnce("JohnW's QuickBar",
		function()
			qb_script.onDrawGui(g); -- JW's QuickBar hook
		end)

Which gave me the following results:

SpoilerShow

If you have too much "discarded passes", lower the iterations number, but it might lower the accuracy a bit.
More passes = more accurate measurement, but it takes longer to calculate.

Code: Select all

-- LoG Profiler by Diarmuid
-- To setup, link a call to logProfiler.onDrawGui() from the onDrawGui party hook.
-- To run, call logProfiler.profile(profileName, function)
-- You can also call logProfiler.profileOnce(profileName, function), it will only run the profiler once (if it's from a timer, or onDrawGui for example).
-- Profile name is just an identifier.

iterations = 100;
passes = 500;
frame = 1;
functName = "";
funct = nil;
playTime = {};
frame25 = math.floor(passes * 2 * 0.25);
frame50 = math.floor(passes * 2 * 0.5);
frame75 = math.floor(passes * 2 * 0.75);

function profileOnce(fName, f)
	if functName == fName then return; end
	frame = -5;
	runProfile(fName, f);
end

function profile(fName, f)
	frame = 0;
	runProfile(fName, f);
end

function runProfile(fName, f)
	if funct then return; end
	if type(fName) ~= "string" or type(f) ~= "function" then
		print("Warning: LoG Profiler, attempting to run with incorrect arguments.");
		return;
	end
	playTime = {};
	functName = fName;
	funct = f;
	print("==== Starting LoG Profiler for "..functName.." ("..iterations.." iterations, "..passes.." passes) ====");
	
end

function onDrawGui()
	if not(funct) then return; end
	frame = frame + 1;
	if frame < 1 then return; end
	if frame <= passes * 2 then
		if frame % 2 == 1 then
			registerTime();
		end
		if frame % 2 == 0 then
			registerTime(); 
			executeFunction();
		end
	else
		registerTime();
		funct = nil;
		printReport();
		return;
	end
	if frame == frame25 then
		print("..25%");
	elseif frame == frame50 then
		print("..50%");
	elseif frame == frame75 then
		print("..75%");
	end
end

function registerTime()
	playTime[frame] = getStatistic("play_time");
end

function executeFunction()
	for i = 1, iterations do
		funct();
	end
end

function printReport()
	local dt = {};
	local maxDt = 0;
	local oDt = {}
	for i = 1, passes * 2 do
		dt[i] = playTime[i + 1] - playTime[i];
		if dt[i] >= 0.1 then
			--print("Warning: dt["..i.."] capped at 0.1s");
			table.insert(oDt, i);
		end
		if dt[i] > maxDt then
			maxDt = dt[i];
		end
	end
	local pTime = {};
	local totalTime = 0;
	local oPasses = 0`;
	for i = 1, passes do
		pTime[i] = dt[i * 2] - dt[(i * 2) - 1];
		for j in ipairs(oDt) do
			if oDt[j] == i * 2 or oDt[j] == (i * 2) - 1 then
				--print("Overloaded pass time ["..i.."] :"..pTime[i]);
				oPasses = oPasses + 1;
				totalTime = totalTime - pTime[i];
			end
		end
		totalTime = totalTime + pTime[i];
	end	
	print("==== Profiling results for "..functName.." ====");
	print("Total time: "..round(totalTime, 2).."s for "..(iterations * (passes - oPasses)).." calls ("..oPasses.." passes discarded).");
	print("Average pass time: "..round(totalTime / (passes - oPasses), 3).."s.");
	print("Average call: "..round(totalTime / (passes - oPasses) / iterations * 1000, 2).."ms.");
end

function round(num, idp)
    local mult = 10^(idp or 0)
    if num >= 0 then return math.floor(num * mult + 0.5) / mult
    else return math.ceil(num * mult - 0.5) / mult end
end

[Eleven Warrior]

Hi Diarmuid how r u?

I don't know what your coding does exactly?? What is it supposed to do, Sorry imam not very good with coding.. I have some idea, but would like to know what this coding would be good for??

Sorry for my ignorance but I don't understand what it does.. I wish I did though..

[Diarmuid]

Hi Diarmuid how r u?

I don't know what your coding does exactly?? What is it supposed to do, Sorry imam not very good with coding.. I have some idea, but would like to know what this coding would be good for??

Sorry for my ignorance but I don't understand what it does.. I wish I did though..

It's a performance optimization tool, which can show you how much time a particular function takes to execute, in milliseconds (ms). That way, you can identify which scripts are taking too long to execute, and where the framerate issues come from : then make changes to the code so that it's more efficient.

Obviously that's just for script-related framerate problems, graphics are a separate thing.

So to use, basically you run through it all functions you suspect may cause slow-downs, starting with things that run constantly on timers, or everything in party hooks (like onMove, all onDraw hooks, onTurn, onAttack).

[Eleven Warrior]

Yeah that would be a bonus. Now I can see the light of this Script, it will be extremely handy to have..
That way I can adjust my Timers to perfect timming right?? Yeah I love this Script already.. Man wish I had your talents.. Ohhh well I keep trying LOL..

So I just connect your script to my timer?? or my timer to your script?? or add it to your script?? Imma not good with coding as you already know LOL...

EDIT: Where did you learn to Program the way you do, I would like to learn more and more.. THXS

[Diarmuid]

Yeah that would be a bonus. Now I can see the light of this Script, it will be extremely handy to have..
That way I can adjust my Timers to perfect timming right?? Yeah I love this Script already.. Man wish I had your talents.. Ohhh well I keep trying LOL..

So I just connect your script to my timer?? or my timer to your script?? or add it to your script?? Imma not good with coding as you already know LOL...

EDIT: Where did you learn to Program the way you do, I would like to learn more and more.. THXS

To test it, in your script entity, make a second function for profiling, and link the timer to that one too. If for example your timer is triggering a function named destroyTheWorld in script_entity_1:

1. In script_entity_1, add the following code:

Code: Select all

function profile()
	logProfiler.profileOnce("Destroy The World", function()
		destroyTheWorld()
		end)
end

2. Then add another connector to the timer to activate that new "profile" function.
3. Start the timer and wait.

As of learning to program, well, I did some programming way back in my teens (the 90s), and had dropped it. Picked it up again a year ago with LoG, then perfected my skills while working on DarkDale. All self-taught through internet resources, and a lot of help from the community here.

[Eleven Warrior]

Hi Diarmuid..

Thxs for the reply, appreciated..

How long till DarkDale comes out?? I have been watching your Website for the updates (except for the last week) working long hours at work..

Oh and by the way it looks awesome and I will definitely buy it for sure... Yes you are right I should look for programming websites to learn more..
Sometimes it's so hard to understand the coding though.. LOL..

[JohnWordsworth]

@Diarmuid: This is really cool. What's nice is that when a mod-developer gets feedback stating "I get low frame-rate in your mod", even if the mod-developer doesn't see it (likely that have a dedicated GPU where as the gamer with low frame rate just has an Intel HDX000), they can still check over bits of code to see which are taking the longest to run. Then they can iterate and fix. Also, from a really geeky perspective - it's cool .

@Eleven Warrior: One really good way to learn programming is to set yourself goals and challenges and just keep trying until you can do them. It's hard to explain, but a lot of things with programming need to 'click' into place - which can only happen by overcoming the problems you set yourself. Grimrock is actually quite a nice way to learn programming (granted, you won't find Lua in that many places, but just learning the concepts of programming is more important than learning a single language). What's nice about Grimrock, is you get to write little 10 line scripts that actually solve a problem - great practice for learning!

[Eleven Warrior]

Man I have said it a thousand times but this community ROCKS.....

Thxs John I will try to learn lua, man I hope I can. I see how other Scripts work and Copy them and change the names EG: altar_1 to what I want, and then the function of that script.. The problem is I don't know how it works. it just does...

So I need to figure out why the Script works EG: if , then , else, etc....... So it goes..

At my age the best I can do is copy what you guys have put in the Forums.. Imma sorry for taking your work all.. But its all I can do ATM.. THXS again..

EDIT: If I had 3 wishes:

1 I could code anything in any programming Language that I wanted.
2 Could use any 3D model program and create any thing I wanted
3 not sure about this one....