Intermittent errors

[ignacio]

The following code makes the luatrace.profile script to fail sometimes.

require "luarocks.require"
require "json"

local luatrace = require "luatrace"

luatrace.tron()
local t = json.decode[[
{
    "friends": [],
    "blah": {},
}
]]
luatrace.troff()

It gives the following error:

ERROR (   1, line     147): counted execution of 0.5 microseconds at line 1 of a function defined at C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:633-650
lua: ...Rocks/rocks//luatrace/scm-2/lua/luatrace\profile.lua:266: attempt to index local 'top' (a nil value)
stack traceback:
        ...Rocks/rocks//luatrace/scm-2/lua/luatrace\profile.lua:266: in function 'record'
        ...ks/rocks//luatrace/scm-2/lua/luatrace\trace_file.lua:142: in function 'read'
        ...Rocks/rocks//luatrace/scm-2/lua/luatrace\profile.lua:459: in function 'go'
        (command line):1: in main chunk
        [C]: ?

The strange thing is that sometimes it works fine.

C:\>lua -lluarocks.require -e "require('luatrace.profile').go()"
Total time 103.50 microseconds
Times in microseconds
Top 20 lines by total time
File:line                                                   Hits   Total    Self   Child | Line
test_json.lua:7                                                1  102.50    1.00  101.50 | local t = json.decode[[
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:650             1   93.50    1.00   92.50 |           end
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:628             3   92.50    2.50   90.00 |              local t = next_token(tt_object_value)
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:575             2   90.00    1.50   88.50 |              if t == tt_object_key         then return read_object_key({}) end
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:640             2   69.50    1.00   68.50 |                      if t == tt_object_key then return read_object_key(o) end
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:635             5   32.50    2.50   30.00 |                      local t = next_token(tt_object_key)
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:486            25   19.00   19.00    0.00 |                      local b = js_string:byte(pos)
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:504             1   18.00    0.50   17.50 |                      local t = next_token(tok)
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:524             2   16.50   16.50    0.00 |              return (loadstring("return " .. stringValue ) ())
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:485            14   12.50   12.50    0.00 |              while pos <= #js_string do
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:487            19    9.50    9.50    0.00 |                      local t = tok[b]
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:643             1    9.00    0.50    8.50 |                      if next_token(tt_object_colon) == tt_comment_start then
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:501             2    8.50    1.50    7.00 |              local start = pos
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:641             2    8.00    1.00    7.00 |                      local k = read_string(t)
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:493            12    6.00    6.00    0.00 |                      pos = pos + 1
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:636             3    6.00    1.50    4.50 |                      if t == tt_comment_start then
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:494             9    4.50    4.50    0.00 |                      if t~=tt_ignore then return t end
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:488             6    3.00    3.00    0.00 |                      if not t then
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:513             2    2.50    2.50    0.00 |              stringValue = string.gsub(stringValue, "([\\]+)u(%x%x)(%x%x)", function(escape, hex_value_high, hex_value_low)
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:512             2    2.00    2.00    0.00 |              local stringValue = js_string:sub(start-1, pos-1)

Top 20 functions by self time
File:lines                                                  Hits   Total    Self   Child | Line
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:484-497        14   54.50   54.50    0.00 |           local function next_token (tok)
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:500-536         2   48.50   24.00   24.50 |           local function read_string (tok)
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:633-650         4   89.50    9.50   80.00 |           function read_object_key (o)
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:458-660         1  101.50    9.00   92.50 |      function decode (js_string)
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:627-630         3   92.50    2.50   90.00 |           function read_object_value (o)
test_json.lua:0-0                                              1    2.00    2.00    0.00 | -
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:574-584         3   90.00    1.50   88.50 |           function read_value (t,fromt)
C:\LuaRocks/rocks//json4lua/git-1/lua/json.lua:603-624         1    4.00    0.50    3.50 |           function read_array (o,i)
C:\LuaRocks/rocks//luatrace/scm-2/lua/luatrace.lua:350-358     1    0.00    0.00    0.00 | -

To reproduce, install json4lua with luarocks and run the provided script. The script, a trace that succeeds and a trace that fail are available here.

[ignacio]

Any update on this?

[geoffleyland]

Sorry, last time I looked at this I was pushed for time and couldn't work anything out because the stack traces in the two are exactly the same. Turns out that the problem is that both traces trace off the top of the trace stack (I'm not quite sure how this happens because when the trace starts there's an attempt to build the full current stack), but a the failing trace records a line with non-zero time when were "above" the top of the stack. The quick and dirty solution is to just ignore time that occurs in a stack frame we don't know about.
I'll have a look at the initial stack build and see if there's anything obvious, but I'm not hopeful.

[geoffleyland]

Nope, that wasn't it at all.
trace-out-failing.txt includes a line that records time on a line that isn't in the current function's set of lines. I don't know why that might be.
When this happens, profile guesses that it's LuaJIT forgetting to tell us about a return (this used to happen, I don't know if it still does) and adds an extra return before continuing.
In this case, it's the wrong thing to do. The extra return means that we jump off the top of the stack when we should be returning to test_json.lua.
So now, when we find time attributed to a line that's not in the current function, we look and see if the line is in the caller of the current function. If it is, then we guess the missing return as before. If it's not, we give up, complain, but don't add the extra return.
Which, in this case, prevents the stack getting out-of-whack by one frame.

[ignacio]

Well, with your latest changes I can't reproduce the issue, so it seems to be fixed :)

Thanks a lot!