doubt about log of LuaJIT's jit.v module

tweyseo · 2019-03-27T14:45:39+00:00

I am using OpenResty as a TCP (stream) proxy. I have been capable to read TCP packets using reqsock:peek and preread_by_lua_block directi...

doubt about log of LuaJIT's jit.v module

tweyseo

i notice the comment about side traces in jit/v.lua:

i don't quite understand "", what does the "" actually mean?

like code below:

local v = require("jit.v")
v.on("t1.log")
local a = { 1, 2, 3, 4 }
for i = 1, 100 do
    for i = 1, 100 do
        a[1] = i
    end

    a[2] = "1end2begin"
    for i = 1, 100 do
        a[2] = i
    end

    a[3] = "2end3begin"
    for i = 1, 100 do
        a[3] = i
    end
    
    a[4] = "3end4begin"
    for i = 1, 100 do
        a[4] = i
    end

    a[1] = "4end1begin"
end

and it's trace log:

[TRACE   1 t1.lua:5 loop]
[TRACE   2 t1.lua:10 loop]
[TRACE   3 t1.lua:15 loop]
[TRACE   4 t1.lua:20 loop]
[TRACE   5 (1/3) t1.lua:9 -> 2]
[TRACE   6 (2/3) t1.lua:14 -> 3]
[TRACE   7 (3/3) t1.lua:19 -> 4]
[TRACE   8 (4/3) t1.lua:24 -> 1]

what does the "" actually mean?

And when i use this tool to analyze my lua code, i met:

[TRACE --- re.lua:209 -- leaving loop in root trace at re.lua:247]
[TRACE --- hash.lua:74 -- inner loop in root trace at re.lua:210]
[TRACE --- index.lua:22 -- inner loop in root trace at re.lua:210]

this log means trace abort too? and how could i resolve them? Like in line 2, should i check hash.lua:74 or re.lua:210 ?

thibaultcha

Hi,

What the documentation refers to as the "exit number" is the snapshot
number LuaJIT uses when restoring the C stack from the JIT registers.

Let's dump the bytecode with the following:

    require("jit.dump").on("is")

Where the 'i' argument prints the IR, and 's' the snapshot maps[1].
We'll see 8 traces and their respective IR in the stdout output. Let's
take a look at two of them (apologies in advance for my mail client may
truncate lines):

---- TRACE 1 IR
....        SNAP   #0   [ ---- ]
0001    int SLOAD  #6    CI
0002 >  tab SLOAD  #1    T
0003    int FLOAD  0002  tab.asize
0004 >  int ABC    0003  +1
0005    p32 FLOAD  0002  tab.array
0006    p32 AREF   0005  +1
0007    tab FLOAD  0002  tab.meta
0008 >  tab EQ     0007  NULL
0009    num CONV   0001  num.int
0010    num ASTORE 0006  0009
0011  + int ADD    0001  +1
....        SNAP   #1   [ ---- ---- ---- ---- ---- ---- ]
0012 >  int LE     0011  +100
....        SNAP   #2   [ ---- ---- ---- ---- ---- ---- 0011 ---- ----
0011 ]
0013 ------ LOOP ------------
0014    num CONV   0011  num.int
0015    num ASTORE 0006  0014
0016  + int ADD    0011  +1
....        SNAP   #3   [ ---- ---- ---- ---- ---- ---- ]
0017 >  int LE     0016  +100
0018    int PHI    0011  0016
---- TRACE 1 stop -> loop


[... other traces ...]


---- TRACE 5 start 1/3 jit.lua:11
---- TRACE 5 IR
....        SNAP   #0   [ ---- ---- ---- ---- ---- ---- ]
0001 >  tab SLOAD  #1    T
0002    int FLOAD  0001  tab.asize
0003 >  int ABC    0002  +2
0004    p32 FLOAD  0001  tab.array
0005    p32 AREF   0004  +2
0006    tab FLOAD  0001  tab.meta
0007 >  tab EQ     0006  NULL
0008    str ASTORE 0005  "1end2begin"
0009    nil TBAR   0001
....        SNAP   #1   [ ---- ---- ---- ---- ---- ---- +1   +100 +1
+1   ]
---- TRACE 5 stop -> 2


The part that interests you here is "TRACE 5 start 1/3". The first
number (1) indicates the parent trace number as you pointed out, and the
second one (3) is the "exit number". What this means is that this
sidetrace was created from snapshot #3 of TRACE 1. See this line in TRACE 1:

....        SNAP   #3   [ ---- ---- ---- ---- ---- ---- ]

The JIT compiler saved a snapshot indicating that no registers should be
changed when exiting back to the interpreter. The following instruction:

0017 >  int LE     0016  +100

is a guard instruction, and in case of failure, the JIT will be
instructed to restore the previous snapshot (#3 in this case). This
instruction is your loop's exit-condition. When 'i' reaches 100, this
write guard will indeed fail, and the JIT must restore the previous
snapshot before moving on.

Regarding the second part of your question, you may have already had a
look at this part of the documentation[2]. It may be so that the loop in
question isn't worth it for the JIT to kick-in (e.g. it is falling back
to interpreter mode too quickly), so my guess is that it may eventually
be blacklisted, since the interpreter would still be faster than
constantly interpreting and attempting tracing. Since this is in re.lua
I suppose that it may be because your regex (or subject) is simple
enough that it does not warrant a lot of iterations in whatever loop is
being executed? We'd have to see the code to be able to tell.

Best,
Thibault

[1]: https://github.com/LuaJIT/LuaJIT/blob/master/src/jit/dump.lua
[2]: https://github.com/LuaJIT/LuaJIT/blob/master/src/jit/v.lua#L47-L49

tweyseo

thanks very much for your answer.

For my first question:

in my opinion, the sidetrace was a branch code path of the corresponding trace. and with your

explanation, i see the snapshot:

1.sidetrace was created from snapshot;

(the snapshot here means it was taken before the code path of a trace was branched, right?)

2.the registers should be changed according to the snapshot when the LuaJIT fell back to

interpreter from compiler;

(but a trace can contain many snapshots, so the registers will be changed according to all the

snapshots in a trace, right?)

3.there was a guard instruction next to each snapshot, and in case of failure, the LuaJIT will be

instructed to restore the previous snapshot.

(the failure here meas the LuaJIT fell back to interpreter from compiler? ulteriorly, a trace jump

to another trace(sidetrace) must fall back to interpreter from compiler? if so, does it contradicts

point 2 which pointed out the registers will be changed according to all the snapshots in a trace

when fallback?)

For the second question:

here is the minimal code:

  1 local random = math.random
  2 local split = require("ngx.re").split
  3 local v = require("jit.v")
  4 v.on("testTrace.log")
  5 
  6 local function f(path)
  7     local m, err = split(path, "/", "jo")
  8     if err then
  9         error(err)
 10     end
 11 
 12     return #m
 13 end
 14 
 15 local pathList = {
 16     "/test1/test2/test3/test4/test5",
 17     "/test1/test2/test3/test4",
 18     "/test1/test2/test3",
 19     "/test1/test2",
 20     "/test1"
 21 }
 22 
 23 local max, len = 10e1, #pathList
 24 for _ = 1, max do
 25     f(pathList[random(1, len)])
 26 end

and it's trace log:

[TRACE   1 lrucache.lua:76 loop]
[TRACE   2 re.lua:209 loop]
[TRACE   3 (2/13) re.lua:229 -> 2]
[TRACE --- t.lua:24 -- inner loop in root trace at re.lua:210]
[TRACE   4 (2/1) re.lua:59 -> 2]
[TRACE   5 (2/28) re.lua:229 -> 2]
[TRACE   6 (3/0) re.lua:229 -> 2]
[TRACE   7 (2/18) re.lua:59 -> 2]
[TRACE   8 (4/4) re.lua:264 -> 2]

how do i analyze [TRACE --- t.lua:24 -- inner loop in root trace at re.lua:210]?

and thank you again!

Tweyseo