luatrace.profile crashes trying to index a local 'thread'

[tbogdala]

On Mac OS X with lua (and luajit) installed via Homebrew, I have luajit embedded in my 3d graphics engine. I'm then writing the vast majority of the game in lua, which is why I'm interested in the profiler.

Near the top of my main lua file I use: Luatrace = require("luatrace")

Then when I want to profile a section, I use: Luatrace.tron({trace_file_name="cms_trace.txt"})

Then I finish it with: Luatrace.troff()

That does create a cms_trace.txt file that's 56k in size. So I try to run luatrace.profile and it crashes with an access to a nil local value:

tbogdala$ luatrace.profile cms_trace.txt lua: /usr/local/share/lua/5.1/luatrace/profile.lua:125: attempt to index local 'thread' (a nil value) stack traceback: /usr/local/share/lua/5.1/luatrace/profile.lua:125: in function 'call_on_thread' /usr/local/share/lua/5.1/luatrace/profile.lua:213: in function 'record' /usr/local/share/lua/5.1/luatrace/trace_file.lua:133: in function 'read' /usr/local/share/lua/5.1/luatrace/profile.lua:463: in function 'go' (command line):1: in main chunk

[tbogdala]

I put the cms_trace.txt file onto pastebucket: http://goo.gl/uGl99o

Edit: Also, I'll try to debug it a bit if that would help, though few tips as to why thread_stack would be empty or nil would help.

[geoffleyland]

On 14/02/2014, at 4:47 am, Timothy Bogdala notifications@github.com wrote:

I put the cms_trace.txt file onto pastebucket: http://goo.gl/uGl99o

Have you renamed resume, or are you calling resume from C?

[tbogdala]

Nope, I just double checked. Checked all the lua scripts in the game and checked the C code for the wrappers. A grep for resume doesn't have any results.

[geoffleyland]

Odd. Never mind. Try now. It just uses -1 as a thread ID if you're you've yielded off the top of the thread stack. Hopefully it won't muck the call stack up, but I'm a bit pressed to think about it too hard.

[geoffleyland]

Did the latest commit work for you? If so, could you close this issue? Thanks.

[tbogdala]

Sorry, I haven't tried it yet and will do so this weekend.

[tbogdala]

lua: /usr/local/share/lua/5.1/luatrace/profile.lua:168: attempt to index local 'caller' (a nil value) stack traceback: /usr/local/share/lua/5.1/luatrace/profile.lua:168: in function 'play_return' /usr/local/share/lua/5.1/luatrace/profile.lua:243: in function 'record' /usr/local/share/lua/5.1/luatrace/trace_file.lua:138: in function 'read' /usr/local/share/lua/5.1/luatrace/profile.lua:466: in function 'go' (command line):1: in main chunk

For what it's worth:

1) my game is written in C 2) the game loads an initial main.lua files that sets callbacks for update/draw/input events 3) these callbacks are invoked with lua_pcall()

I uploaded the newest cms_trace.txt file here: http://animal-machine.com/static/temp/cms_trace.txt

[tbogdala]

I did a little debugging with zbstudio and did some investigation when play_return() gets called with a null caller parameter.

Callee looks like:

{current_line = {child_time = 92009.501, file = {filename = "scripts/client_main.lua", functions = {[99] = {{child_time = 0, hits = 1, last_line_defined = 149, line_defined = 99, name = "scripts/client_main.lua:99-149", self_time = 1.515, source_file = nil}}, [153] = {{child_time = 91979.417, hits = 1, last_line_defined = 155, line_defined = 153, name = "scripts/client_main.lua:153-155", self_time = 0.685, source_file = nil}}, [158] = {{child_time = 0, hits = 1, last_line_defined = 168, line_defined = 158, name = "scripts/client_main.lua:158-168", self_time = 4.617, source_file = nil}}}, lines = {[147] = {child_time = 0, file = nil, hits = 1, line_number = 147, self_time = 0.186}, [148] = {child_time = 0.681, file = nil, hits = 1, line_number = 148, self_time = 1.285}, [149] = {child_time = 0, file = nil, hits = 1, line_number = 149, self_time = 0.044}, [153] = {child_time = 0, file = nil, hits = 1, line_number = 153, self_time = 0.108}, [154] = {child_time = 91979.417, file = nil, hits = 1, line_number = 154, self_time = 0.548}, [155] = {child_time = 0, file = nil, hits = 1, line_number = 155, self_time = 0.029}, [158] = {child_time = 0, file = nil, hits = 1, line_number = 158, self_time = 2.104}, [159] = {child_time = 0, file = nil, hits = 1, line_number = 159, self_time = 0.244}, [160] = {child_time = 0, file = nil, hits = 1, line_number = 160, self_time = 0.29}, [163] = {child_time = 0, file = nil, hits = 1, line_number = 163, self_time = 0.196}, [164] = {child_time = 8.395, file = nil, hits = 1, line_number = 164, self_time = 0.847}, [165] = {child_time = 1.607, file = nil, hits = 1, line_number = 165, self_time = 0.582}, [167] = nil}}, hits = 1, line_number = 167, self_time = 0.354}, func = nil, func_child_time_at_start = 0, func_self_time_at_start = 0, func_start_time = 17.406, line_child_time_at_start = 0, line_self_time_at_start = 0.354, line_start_time = 32.025, protected = false} --[[table: 0x7fac737225d0]] --[[incomplete output with shared/self-references skipped]]

If I move up the stack to profile.record, it's in the Yield portion (elseif a=='Y') of the if statement and in the else branch of the thread_stack.top <= 0 check.

Some locals:

i = 1 stack.top = 0 thread[1] = {current_line = {child_time = 92009.501, file = {filename = "scripts/client_main.lua", functions = {[99] = {{child_time = 0, hits = 1, last_line_defined = 149, line_defined = 99, name = "scripts/client_main.lua:99-149", self_time = 1.515, source_file = nil}}, [153] = {{child_time = 91979.417, hits = 1, last_line_defined = 155, line_defined = 153, name = "scripts/client_main.lua:153-155", self_time = 0.685, source_file = nil}}, [158] = {{child_time = 0, hits = 1, last_line_defined = 168, line_defined = 158, name = "scripts/client_main.lua:158-168", self_time = 4.617, source_file = nil}}}, lines = {[147] = {child_time = 0, file = nil, hits = 1, line_number = 147, self_time = 0.186}, [148] = {child_time = 0.681, file = nil, hits = 1, line_number = 148, self_time = 1.285}, [149] = {child_time = 0, file = nil, hits = 1, line_number = 149, self_time = 0.044}, [153] = {child_time = 0, file = nil, hits = 1, line_number = 153, self_time = 0.108}, [154] = {child_time = 91979.417, file = nil, hits = 1, line_number = 154, self_time = 0.548}, [155] = {child_time = 0, file = nil, hits = 1, line_number = 155, self_time = 0.029}, [158] = {child_time = 0, file = nil, hits = 1, line_number = 158, self_time = 2.104}, [159] = {child_time = 0, file = nil, hits = 1, line_number = 159, self_time = 0.244}, [160] = {child_time = 0, file = nil, hits = 1, line_number = 160, self_time = 0.29}, [163] = {child_time = 0, file = nil, hits = 1, line_number = 163, self_time = 0.196}, [164] = {child_time = 8.395, file = nil, hits = 1, line_number = 164, self_time = 0.847}, [165] = {child_time = 1.607, file = nil, hits = 1, line_number = 165, self_time = 0.582}, [167] = nil}}, hits = 1, line_number = 167, self_time = 0.354}, func = nil, func_child_time_at_start = 0, func_self_time_at_start = 0, func_start_time = 17.406, line_child_time_at_start = 0, line_self_time_at_start = 0.354, line_start_time = 32.025, protected = false} --[[table: 0x7fac737225d0]] --[[incomplete output with shared/self-references skipped]]

Does that help at all?