question on debug hooks

classic Classic list List threaded Threaded
9 messages Options
Reply | Threaded
Open this post in threaded view
|

question on debug hooks

Thijs Schreijer
List,

I have some behavior I can't explain using a debug hook.
I created a small test. Both the function running and the debug hook only contain a counter.
Now when running with the different debug mask and count values I expected to see large differences in both counters. But there aren't.

These are the mask and count values and the counts returned:
With    c       nil
    loop count :        2888804
    check count:        2888813
With    c       100
    loop count :        2219481
    check count:        2404448
With    c       1000
    loop count :        2480837
    check count:        2493768
With    c       50000
    loop count :        2410984
    check count:        2411308
With    r       nil
    loop count :        2229461
    check count:        2229473
With    r       100
    loop count :        2019846
    check count:        2188178
With    r       1000
    loop count :        2162406
    check count:        2173679
With    r       50000
    loop count :        2325529
    check count:        2325842
With    l       nil
    loop count :        2111964
    check count:        2111971
With    l       100
    loop count :        2001379
    check count:        2168168
With    l       1000
    loop count :        2106344
    check count:        2117323
With    l       50000
    loop count :        2089613
    check count:        2089893

Especially with values "l" and 50000, I would have expected the debug counter to be far lower than the loop counter.
What am I missing? Any help is appreciated.

Thijs

Test script below


local gettime = require("socket").gettime
local t, loopcount, checkcount

local loop = function()
  while t+1>gettime() do loopcount = loopcount + 1 end
end

local hook = function() checkcount = checkcount + 1 end

local test = function(mask, count)
  loopcount = 0
  checkcount = 0
  t = gettime()
  debug.sethook(hook, mask, count)
  loop()
  print("With",mask,count)
  print("    loop count :",loopcount)
  print("    check count:", checkcount)
end

test("c", nil)
test("c", 100)
test("c", 1000)
test("c", 50000)
test("r", nil)
test("r", 100)
test("r", 1000)
test("r", 50000)
test("l", nil)
test("l", 100)
test("l", 1000)
test("l", 50000)





Reply | Threaded
Open this post in threaded view
|

Re: question on debug hooks

Paul K
Hi Thijs,

> Now when running with the different debug mask and count values I expected to see large differences in both counters. But there aren't.
...
>   debug.sethook(hook, mask, count)

I think mask and count are mutually exclusive; in other words, if you
have "c", 100, it doesn't mean that it will be called every 100th
"call" event. I may be mistaken, but last time I checked, count
behaves like a line event with a threshold.

So, sethook(hook, "r", 100) is the same as sethook(hook, "r"). If you
want to get every Nth statement, then try sethook(hook, "", N):

test("", nil)
test("", 100)
test("", 1000)
test("", 50000)

With nil
    loop count : 4036736
    check count: 0
With 100
    loop count : 3575464
    check count: 335199
With 1000
    loop count : 3100648
    check count: 28017
With 50000
    loop count : 4043297
    check count: 727

Paul.

On Fri, Apr 5, 2013 at 9:33 AM, Thijs Schreijer <[hidden email]> wrote:

> List,
>
> I have some behavior I can't explain using a debug hook.
> I created a small test. Both the function running and the debug hook only contain a counter.
> Now when running with the different debug mask and count values I expected to see large differences in both counters. But there aren't.
>
> These are the mask and count values and the counts returned:
> With    c       nil
>     loop count :        2888804
>     check count:        2888813
> With    c       100
>     loop count :        2219481
>     check count:        2404448
> With    c       1000
>     loop count :        2480837
>     check count:        2493768
> With    c       50000
>     loop count :        2410984
>     check count:        2411308
> With    r       nil
>     loop count :        2229461
>     check count:        2229473
> With    r       100
>     loop count :        2019846
>     check count:        2188178
> With    r       1000
>     loop count :        2162406
>     check count:        2173679
> With    r       50000
>     loop count :        2325529
>     check count:        2325842
> With    l       nil
>     loop count :        2111964
>     check count:        2111971
> With    l       100
>     loop count :        2001379
>     check count:        2168168
> With    l       1000
>     loop count :        2106344
>     check count:        2117323
> With    l       50000
>     loop count :        2089613
>     check count:        2089893
>
> Especially with values "l" and 50000, I would have expected the debug counter to be far lower than the loop counter.
> What am I missing? Any help is appreciated.
>
> Thijs
>
> Test script below
>
>
> local gettime = require("socket").gettime
> local t, loopcount, checkcount
>
> local loop = function()
>   while t+1>gettime() do loopcount = loopcount + 1 end
> end
>
> local hook = function() checkcount = checkcount + 1 end
>
> local test = function(mask, count)
>   loopcount = 0
>   checkcount = 0
>   t = gettime()
>   debug.sethook(hook, mask, count)
>   loop()
>   print("With",mask,count)
>   print("    loop count :",loopcount)
>   print("    check count:", checkcount)
> end
>
> test("c", nil)
> test("c", 100)
> test("c", 1000)
> test("c", 50000)
> test("r", nil)
> test("r", 100)
> test("r", 1000)
> test("r", 50000)
> test("l", nil)
> test("l", 100)
> test("l", 1000)
> test("l", 50000)
>
>
>
>
>

Reply | Threaded
Open this post in threaded view
|

Re: question on debug hooks

Roberto Ierusalimschy
In reply to this post by Thijs Schreijer
> Especially with values "l" and 50000, I would have expected the debug counter to be far lower than the loop counter.
> What am I missing? Any help is appreciated.

* http://www.lua.org/manual/5.2/manual.html#pdf-debug.sethook

   With a count different from zero, the hook is called after every
   count instructions.

"instructions" here means opcode instructions of the virtual machine.

So, with values "l" and 50000, the hook is called for every line and for
every 50000 instructions executed. Each line in your loop has less than a
dozen instructions, so the line calls completely dominates the counting.

-- Roberto

Reply | Threaded
Open this post in threaded view
|

Re: question on debug hooks

Paul K
In reply to this post by Paul K
> I think mask and count are mutually exclusive; in other words, if you
> have "c", 100, it doesn't mean that it will be called every 100th
> "call" event. I may be mistaken, but last time I checked, count
> behaves like a line event with a threshold.

This is not the case per Roberto's comment as mask and count are not
exclusive; "count" hook is executed every Nth instruction. I stand
corrected.

Paul.

Reply | Threaded
Open this post in threaded view
|

RE: question on debug hooks

Thijs Schreijer
In reply to this post by Paul K
> -----Original Message-----
> From: [hidden email] [mailto:[hidden email]] On
> Behalf Of Paul K
> Sent: zaterdag 6 april 2013 3:01
> To: Lua mailing list
> Subject: Re: question on debug hooks
>
> Hi Thijs,
>
> > Now when running with the different debug mask and count values I
> expected to see large differences in both counters. But there aren't.
> ...
> >   debug.sethook(hook, mask, count)
>
> I think mask and count are mutually exclusive; in other words, if you
> have "c", 100, it doesn't mean that it will be called every 100th
> "call" event. I may be mistaken, but last time I checked, count
> behaves like a line event with a threshold.
>
> So, sethook(hook, "r", 100) is the same as sethook(hook, "r"). If you
> want to get every Nth statement, then try sethook(hook, "", N):
>
> test("", nil)
> test("", 100)
> test("", 1000)
> test("", 50000)
>
> With nil
>     loop count : 4036736
>     check count: 0
> With 100
>     loop count : 3575464
>     check count: 335199
> With 1000
>     loop count : 3100648
>     check count: 28017
> With 50000
>     loop count : 4043297
>     check count: 727
>
> Paul.

Thx. Got it!

Reply | Threaded
Open this post in threaded view
|

RE: question on debug hooks

Thijs Schreijer
In reply to this post by Roberto Ierusalimschy
> -----Original Message-----
> From: [hidden email] [mailto:[hidden email]] On
> Behalf Of Roberto Ierusalimschy
> Sent: zaterdag 6 april 2013 15:12
> To: Lua mailing list
> Subject: Re: question on debug hooks
>
> > Especially with values "l" and 50000, I would have expected the debug
> counter to be far lower than the loop counter.
> > What am I missing? Any help is appreciated.
>
> * http://www.lua.org/manual/5.2/manual.html#pdf-debug.sethook
>
>    With a count different from zero, the hook is called after every
>    count instructions.
>
> "instructions" here means opcode instructions of the virtual machine.

I read that and already figured it would be opcode instructions. But in the case when a number is provided, the mask is ignored, but still checked. From what I read I tried a nil value for mask, but that failed with a "string expected" error.

If I understand it correctly, couldn't the api be simpler with behavior like this;

local sethook = debug.sethook
debug.sethook = function(coro, mask)
  if tonumber(mask) then
    return debug.sethook(coro, "", mask)
  else
    return debug.sethook(coro, mask)
  end
end

Under all circumstances only parameter (either mask or count) is used, so why have 2?

And imo the following would be clearer for the manual;
    With a count different from zero, the hook is called after every
    count instructions (compiled opcode instructions). Mask must still
    be a string, but will be ignored.

>
> So, with values "l" and 50000, the hook is called for every line and for
> every 50000 instructions executed. Each line in your loop has less than a
> dozen instructions, so the line calls completely dominates the counting.

That makes sense.

Thx.
Thijs

Reply | Threaded
Open this post in threaded view
|

Re: question on debug hooks

Roberto Ierusalimschy
> I read that and already figured it would be opcode instructions. But
> in the case when a number is provided, the mask is ignored, but still
> checked. From what I read I tried a nil value for mask, but that
> failed with a "string expected" error.

The mask is not ignored when a number if provided, as your own example
showed (hooks are called for every line *and* for every n-th instruction).

-- Roberto

Reply | Threaded
Open this post in threaded view
|

RE: question on debug hooks

Thijs Schreijer
> -----Original Message-----
> From: [hidden email] [mailto:[hidden email]] On
> Behalf Of Roberto Ierusalimschy
> Sent: zaterdag 6 april 2013 21:26
> To: Lua mailing list
> Subject: Re: question on debug hooks
>
> > I read that and already figured it would be opcode instructions. But
> > in the case when a number is provided, the mask is ignored, but still
> > checked. From what I read I tried a nil value for mask, but that
> > failed with a "string expected" error.
>
> The mask is not ignored when a number if provided, as your own example
> showed (hooks are called for every line *and* for every n-th instruction).
>

Ok thx. Now I get it. Rereading the manual; it does exactly say that, but maybe;

*if mask contains a 'c':  the hook is called every time Lua calls a function;
*if mask contains a 'r':  the hook is called every time Lua returns from a function;
*if mask contains a 'l':  the hook is called every time Lua enters a new line of code.
 ^^^^^^^^^^^^^^^^^^ <- added

With a count different from zero, the hook is also called after every count instructions.
                                     added -> ^^^^

Would be clearer. Anyway thx for pointing me in the right direction.
Thijs

Reply | Threaded
Open this post in threaded view
|

Re: question on debug hooks

Miles Bader-2
Thijs Schreijer <[hidden email]> writes:

> it does exactly say that, but maybe;
>
> *if mask contains a 'c':  the hook is called every time Lua calls a function;
> *if mask contains a 'r':  the hook is called every time Lua returns from a function;
> *if mask contains a 'l':  the hook is called every time Lua enters a new line of code.
>  ^^^^^^^^^^^^^^^^^^ <- added
>
> With a count different from zero, the hook is also called after
>                                      added -> ^^^^
> every count instructions.
>
> Would be clearer.

I like this change... it does seem clearer to me.

[Even though the current manual is accurate, I didn't get the
interaction of mask/count when I read it...]

-miles

--
Politics, n. A strife of interests masquerading as a contest of
principles. The conduct of public affairs for private advantage.