Re: profiling problem

[Peng Zhicheng <pengzhicheng1986@...>]

于 2013-11-3 15:31, Thijs Schreijer 写道:
> 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>

It is really weird. I also got similar result running your code.
After some exploring, I think I have got some points, but not quit clear.

Well, although I don't know why, some experiments shows that the *main thread* runs
slower than *user created thread(coroutines)*.

Please someone would tell me the deep reason for that?

I modified your code as follow:
==================================================
--- perf.lua 2013-11-03 20:10:11.937500000 +0800
+++ perf2.lua 2013-11-03 20:42:44.937500000 +0800
@@ -1,3 +1,5 @@
+local old_wrap = coroutine.wrap
+
require("corowatch")

local res = 1
@@ -13,7 +15,7 @@
collectgarbage()
collectgarbage("stop")
local t1 = coroutine.gettime()
- testfunc()
+ old_wrap(testfunc)()
t1 = coroutine.gettime() - t1
collectgarbage("restart")
collectgarbage()
===================================================

then the result is:
===================================================
E:\playground>lua perf2.lua
0.465625
0.478125
corowatch is 2% slower

E:\playground>lua perf2.lua
0.471875
0.48125
corowatch is 1% slower

E:\playground>lua perf2.lua
0.46875
0.471875
corowatch is 0% slower

E:\playground>lua perf2.lua
0.4671875
0.4734375
corowatch is 1% slower

E:\playground>lua perf2.lua
0.4671875
0.475
corowatch is 1% slower

E:\playground>lua perf2.lua
0.46875
0.48125
corowatch is 2% slower

E:\playground>lua perf2.lua
0.465625
0.478125
corowatch is 2% slower

E:\playground>lua perf2.lua
0.465625
0.475
corowatch is 2% slower

E:\playground>lua perf2.lua
0.4703125
0.4734375
corowatch is 0% slower
===================================================

As seen from the experiments, the coroutine with a debughook set *IS* slower than
the one not set, but the difference is not significant.
This result is what I first expected, because the Lua VM would always check
for the debug hook at each VM instruction boundary, and as long as the hook is
not triggered, the difference between the two coroutines(with debug hook set and
not set) are quit small.

But still, could anyone give me some hints to figure out why the main thread is slower,
because this seems really not understandable to me.
Any suggestion is appreciated.