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

Open
tbogdala opened this Issue Feb 13, 2014 · 8 comments

Comments

Projects
None yet
2 participants
@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

This comment has been minimized.

Show comment Hide comment
@tbogdala

tbogdala Feb 13, 2014

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.

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

This comment has been minimized.

Show comment Hide comment
@geoffleyland

geoffleyland Feb 15, 2014

Owner

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?

Owner

geoffleyland commented Feb 15, 2014

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

This comment has been minimized.

Show comment Hide comment
@tbogdala

tbogdala Feb 17, 2014

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.

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

This comment has been minimized.

Show comment Hide comment
@geoffleyland

geoffleyland Feb 17, 2014

Owner

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.

Owner

geoffleyland commented Feb 17, 2014

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

This comment has been minimized.

Show comment Hide comment
@geoffleyland

geoffleyland Feb 19, 2014

Owner

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

Owner

geoffleyland commented Feb 19, 2014

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

@tbogdala

This comment has been minimized.

Show comment Hide comment
@tbogdala

tbogdala Feb 22, 2014

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

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

@tbogdala

This comment has been minimized.

Show comment Hide comment
@tbogdala

tbogdala Feb 22, 2014

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
[C]: ?

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

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
[C]: ?

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

This comment has been minimized.

Show comment Hide comment
@tbogdala

tbogdala Feb 23, 2014

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?

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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment