Rethink debug strings.

[ltratt]

This commit changes how yklua creates debug strings to help a yklua/yk developer understand what's going on in traces. The major parts of this commit are.

1. Move from printing source lines to printing opcodes.
2. Output yk "debug strings" in traces.

As will shortly become obvious, this commit extends debugging output beyond HotLocations, so the macro has become YKLUA_DEBUG_STRS. Since in tests -- which will probably be the main use of this macro I suspect -- full pathnames are a problem, defining this with a value of 2 only outputs leaf names.

Move from printing source lines to printing opcodes.

Previously debug strings contained Lua source code e.g.:

x.lua:41: if x < y

This caused two problems:

1. One source line can generate lots of IR so this gave poor visibility into what was going on: often one source line would be responsible for nearly all debug strings seen at runtime.
2. There is a bug where the fgets used to read source code sometimes led (much later) to a segfault. Exactly why this happens is a bit of a mystery to me. It doesn't seem to be errno related. Perhaps it's shadowstack related? I spent a while on this, but eventually gave up, because I realised that solving problem (1) means that it's no longer really worth printing out source lines anyway.

The solution this commit alights upon is to print out opcodes. So the example above might become something like:

x.lua:41: OP_LOADI
x.lua:41: OP_EQ

and so on. In other words, one source line is now decomposed into its constituent opcodes. This makes much more fine-grained tests possible, and has already given me a much greater insight into what tracing is doing.

Output yk "debug strings" in traces.

I have not found debug strings in HotLocations to give me as much insight as I expected. Instead, it's much more useful to know what opcodes have been traced. So this commit leads to traces like this:

--- Begin jit-pre-opt ---
  ...
  ; debug_str: nested_loops.lua:33: ADDK
  %63: i32 = and %45, 127i32
  ...
  %139: ptr = load %138
  ; debug_str: nested_loops.lua:32: FORLOOP
  %141: i32 = and %108, 127i32
  ...
--- End jit-pre-opt ---

This has already given me much greater insight into what's being traced and thrown light onto factors I had either misunderstood or been unaware of.

[ltratt]

I'm probably going to tweak this slightly as I noticed that (before this PR too, but still in here) we sometimes seem to give quirky debug strings to HoLocations. Probably worth holding off review until I work out why.

[ltratt]

OK that wasn't too difficult. In essence, I just had to recognise that because we attach HotLocations at a PC that is different to the currently processing PC, I needed to generate two debug strings. In conjunction with an upcoming yk PR this means that for a program like:

local x = 0
while x <= 6 do
  io.stderr:write(tostring(x), "\n")
  x = x + 1
end
io.stderr:write("exit\n")

I can now get output such as:

0
1
2
yk-jit-event: start-tracing: while_loop.lua:35: LEI
3
yk-jit-event: stop-tracing: ...
--- Begin debugstrs: header: while_loop.lua:35: LEI ---
  while_loop.lua:36: GETTABUP
  while_loop.lua:36: GETFIELD
  while_loop.lua:36: SELF
  while_loop.lua:36: GETTABUP
  while_loop.lua:36: MOVE
  while_loop.lua:36: CALL
  while_loop.lua:36: LOADK
  while_loop.lua:36: CALL
  while_loop.lua:37: ADDI
  while_loop.lua:37: JMP
  while_loop.lua:35: LEI
--- End debugstrs ---
4
yk-jit-event: enter-jit-code: while_loop.lua:35: LEI
5
6
yk-jit-event: deoptimise
exit

which really helps me work out what's been traced (and executed) and why.

[vext01]

I see two new mallocs, but no new frees. Is that intentional?

[ltratt]

That's me being an idiot. Fixed in a4a142f.

[vext01]

Sorry, I meant the direct calls to malloc(3).

(side note: In the old design I was careful to only do stack allocation in C and to let Rust take its own copies of CStrs -- that way we can't forget to free(3))

[ltratt]

Fixed in 2c9d68f.

FWIW, I moved away from stack allocation because of an (eventually probably unrelated) bug I hit where stack space was a possible issue. Maybe we can move back at some point.

[vext01]

potential double free here :) s/dstr/loc_dstr/

[ltratt]

Already fixed, but I've realised I can simplify this and solve a bigger issue too. Fix coming soon.

[ltratt]

Done in 309f58e.

[vext01]

Ah, the shadow stack stuff. Now it makes sense.

[vext01]

Please squash.

[ltratt]

Squashed.

[For some reason, tryci doesn't work for me on this repo. I should investigate why. But it does mean that I have lower-than-normal confidence about a merge!]

[ltratt]

There is a genuine bug here, but whether it's caused by, or tickled by, this PR is not yet clear.

[ltratt]

Possibly related: in d8f1373 we removed the assignment to sizeyklocs, which has subsequently always been set to 0.

[ltratt]

@vext01 I think 53c6915 fixes the problems. We had an entertaining combination of not setting a vector size properly and uninitialised memory. With those two things fix, my (previously deterministically) failing case succeeds.

[vext01]

Please squash.

[ltratt]

Force pushed but ykjit/yk#1707 will need to go in before this one will merge.