I'm using Tracy 0.13.1 from vcpkg; on https://github.com/CorsixTH/CorsixTH
I found that if I enable the on-demand feature then even though I registered the LuaHook the lua functions do not show up in the Tracy gui even though the LuaHook function is being called.
if ( zoneCnt != 0 && !GetLuaZoneState().active ) return; returns non-zero and exits based on my debugging.
I suspect what is happening is that CorsixTH runs almost entirely within a co-routine, and even when running the Tracy gui before the program starts, the initial coroutine zone starts before the debugger is ready which causes it to discard every further zone.
Maybe it would be better to keep the current stack zone stack until the profiler is connected?
Activity
7For our case I wrote this slightly modified version of tracy:LuaHook. Let me know if such a PR would be accepted.
The main change is tracking the depth (as is done with GetLuaZoneState if ON_DEMAND was enabled); and verifying that the stack is at least that deep or adding more ZoneEnds until it does.
void l_tracy_hook(lua_State* L, lua_Debug* ar) {
using namespace tracy;
static int depth = 0;
if (ar->event == LUA_HOOKCALL) {
lua_getinfo(L, "Snl", ar);
depth++;
char src[256];
detail::LuaShortenSrc(src, ar->short_src);
const auto srcloc = Profiler::AllocSourceLocation(
ar->currentline, src, ar->name ? ar->name : ar->short_src);
TracyQueuePrepare(QueueType::ZoneBeginAllocSrcLoc);
MemWrite(&item->zoneBegin.time, Profiler::GetTime());
MemWrite(&item->zoneBegin.srcloc, srcloc);
TracyQueueCommit(zoneBeginThread);
} else if (ar->event == LUA_HOOKRET) {
do {
depth--;
TracyQueuePrepare(QueueType::ZoneEnd);
MemWrite(&item->zoneEnd.time, Profiler::GetTime());
TracyQueueCommit(zoneEndThread);
} while (lua_getstack(L, depth, ar) == 0);
}
}The hook was implemented by @anthofoxo
this isnt just an issue with on demand profiling. We simply dont properly handle lua errors.
4:7< pcall ([C]:-1) is very interesting to see. Lua uses longjmp to perform stack unwinding which the hook doesn't and can't see, which very well can cause this to get out of sync, so making sure to end the right function becomes tricky to do here.
It's not as easy as comparing the actual vs stored depth and submitting more end events since we will have mismatched source locations.
So when you invoke pcall, usually we don't install a message handler. So when an error occurs, stack unwinding happens, but the hook is never notified of this. Installing a message handler for pcall and pcallk will let you run your own code when errors occur. This is called before stack unwinding so more information can be gathered here.
With a message handler it's easy to say to end the current zone, but since we don't know how far the stack will be unwound. So im unsure of a good way to handle this. I'm thinking we can go about storing stack information in a lua global or in the lua_getextraspace.
To accurately handle this the hook function can begin and end function scopes for you. And we need a message handler to notify us that an error is about to get unwound. When this happens we can store a flag that an error occurred and at what time. This can allow us to correct our stack when the next function is called.
Example message handler:
function msgh()
endExample error check:
if error_occured then
compare current depth and actual depth
if nonzero difference then
lookup the zone information for the scopes that ended, will have been stored by our message handler
end
clear error flags and data
endAs for where we store this information, its hard to say, its a lot to ask of the user to let us take over some of their user pointer struct, our best is to store a global in the lua state, and expose the hook function in the lua registry to allow lua code to also use the message handler.
Opinions and feedback are welcome here
Since our hook can see if pcall(k) is invoked, we do indeed have some sort of idea where the stack will be unwound to if an error occurs. So every time pcall is entered, we can store the current function depth in a queue of sorts. and when an error occurs, use the message handler to look at the most recent pcall entry depth. And then we can end those scopes and proceed as normal.
The main issue is that there is overhead here. For this data to be accessible it needs stored in a lua global. _tracy_profiler_data i think will be just fine for a global name.
Additionally i have no checked for lua tail calls. I should take a look at that as well while we're here.
I believe a lot of the lua stuff needs reworked to begin with and I can begin on some of this asap.
Lua tail calls with the current approach get counted towards the calling methods time and don't show up in the profile. It wasn't obvious to me what the expected behavior would be e.g should the tail call count towards the caller, so I didn't touch it.
Can you elaborate on:
It's not as easy as comparing the actual vs stored depth and submitting more end events since we will have mismatched source locations.
I didn't think the source location mattered for ending zones.
This is hardly the bulk of the issue but tracy doesn't automatically know what scope is being ended. You have to inform it somehow and thats what the source location is for. Even if you didn't need to match source locations. Its still a complex issue to solve.
The issue is that errors dont close the scopes when stack unwinding occurs.
The coroutine isn't a necessary condition, what seems to matter is that the LuaHook view of the lua stack gets out of sync with reality. This happens whenever an error returns to a previous pcall.
I wrote my own lua hook to see what was happening:
Where the first number is the real stack depth as determined by looping through lua_getstack, and the second number is the depth you get if like tracy::LuaHook you only consider LUA_HOOKCALL and LUA_HOOKRET.
There's potentially two issues here; one being the TRACY_ON_DEMAND never sends the zone info in this scenario, and second the zone info stacking is wrong making it look like functions lived for the entire life of the program when in fact they errored.