profiling problem

[Thijs Schreijer <thijs@...>]

Hi all,

Triggered by a message on this list I picked up an old todo item still lingering around. I tried to test the impact of corowatch [1] (that is using a debug hook that is set to run every 10000 vm instructions) over a coroutine without it.

When I run the tests, the outcome differs per run, too much imo, so I probably am doing something wrong. Quite regularly the debug version runs faster...
So I updated the functions with everything I could think of that might have caused it, but to no avail;
- wrote two identical test functions, 1 with, 1 without and measured them
- then added a 'warm up' section
- then disabled GC
- then removed a table to store the results to further minimize GC impact
- then added a 10 run average
- then... posted this message because I ran out of ideas

So any ideas as to what (silliness) I'm missing?

Thijs

[1] https://github.com/Tieske/corowatch 



The code:

package.path = "C:\\Users\\Thijs\\Dropbox\\Lua projects\\corowatch\\src\\?.lua;"..package.path
require("corowatch")

local res = 1

local testfunc = function()
  for n = 1,2000000 do
    res=math.sin(n/1000)
  end
end

local function test1()
  collectgarbage()
  collectgarbage()
  collectgarbage("stop")
  local t1 = coroutine.gettime()
  testfunc()
  t1 = coroutine.gettime() - t1
  collectgarbage("restart")
  collectgarbage()
  collectgarbage()
  return t1
end

local function test2()
  collectgarbage()
  collectgarbage()
  collectgarbage("stop")
  local t2 = coroutine.gettime()
  coroutine.wrapf(testfunc, 10001, 10000, function() end)()
  t2 = coroutine.gettime() - t2
  collectgarbage("restart")
  collectgarbage()
  collectgarbage()
  return t2
end

-- warm up
for n = 1,3 do
  test1()
  test2()
end

-- run test
local t1, t2, iter = 0,0,10
for n = 1,iter do
  t1=test1() + t1
  t2=test2() + t2
end
t1=t1/iter
t2=t2/iter

print(t1)
print(t2)
print("corowatch is " .. math.floor((t2-t1)/t1 *100) .. "% slower")


My results (in this set the debug version consistently runs faster);

C:\Users\Thijs\Dropbox\Lua projects\corowatch\examples>performance.lua
0.23556060791016
0.22308025360107
corowatch is -6% slower

C:\Users\Thijs\Dropbox\Lua projects\corowatch\examples>performance.lua
0.24024028778076
0.2324405670166
corowatch is -4% slower

C:\Users\Thijs\Dropbox\Lua projects\corowatch\examples>performance.lua
0.24336032867432
0.23556041717529
corowatch is -4% slower

C:\Users\Thijs\Dropbox\Lua projects\corowatch\examples>performance.lua
0.24336013793945
0.23400058746338
corowatch is -4% slower

C:\Users\Thijs\Dropbox\Lua projects\corowatch\examples>performance.lua
0.24960060119629
0.23244037628174
corowatch is -7% slower

C:\Users\Thijs\Dropbox\Lua projects\corowatch\examples>performance.lua
0.25272045135498
0.23400039672852
corowatch is -8% slower

C:\Users\Thijs\Dropbox\Lua projects\corowatch\examples>performance.lua
0.24180030822754
0.22308044433594
corowatch is -8% slower

C:\Users\Thijs\Dropbox\Lua projects\corowatch\examples>
C:\Users\Thijs\Dropbox\Lua projects\corowatch\examples>performance.lua
0.25116081237793
0.23087997436523
corowatch is -9% slower

C:\Users\Thijs\Dropbox\Lua projects\corowatch\examples>performance.lua
0.24804058074951
0.22620010375977
corowatch is -9% slower

C:\Users\Thijs\Dropbox\Lua projects\corowatch\examples>performance.lua
0.25272026062012
0.22776069641113
corowatch is -10% slower

C:\Users\Thijs\Dropbox\Lua projects\corowatch\examples>