{"action":"opened","issue":{"url":"https://api.github.com/repos/LuaJIT/LuaJIT/issues/293","repository_url":"https://api.github.com/repos/LuaJIT/LuaJIT","labels_url":"https://api.github.com/repos/LuaJIT/LuaJIT/issues/293/labels{/name}","comments_url":"https://api.github.com/repos/LuaJIT/LuaJIT/issues/293/comments","events_url":"https://api.github.com/repos/LuaJIT/LuaJIT/issues/293/events","html_url":"https://github.com/LuaJIT/LuaJIT/issues/293","id":211374892,"number":293,"title":"Understanding how functions are traced: example","user":{"login":"lukego","id":13791,"avatar_url":"https://avatars3.githubusercontent.com/u/13791?v=3","gravatar_id":"","url":"https://api.github.com/users/lukego","html_url":"https://github.com/lukego","followers_url":"https://api.github.com/users/lukego/followers","following_url":"https://api.github.com/users/lukego/following{/other_user}","gists_url":"https://api.github.com/users/lukego/gists{/gist_id}","starred_url":"https://api.github.com/users/lukego/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/lukego/subscriptions","organizations_url":"https://api.github.com/users/lukego/orgs","repos_url":"https://api.github.com/users/lukego/repos","events_url":"https://api.github.com/users/lukego/events{/privacy}","received_events_url":"https://api.github.com/users/lukego/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":0,"created_at":"2017-03-02T12:18:22Z","updated_at":"2017-03-02T12:18:22Z","closed_at":null,"body":"Please indulge my using this issue to think aloud about how LuaJIT traces code. I would like to understand this well enough to explain it to other people, and I think it will help to chat about it here with everybody else who is interested.\r\n\r\nThe example I am interested in today has these main features:\r\n- One outer loop.\r\n- Three inner loops.\r\n- One `uint64_t` value loaded via FFI and kept live across the inner loops.\r\n\r\nI am interested in understanding:\r\n- The order in which the code is traced.\r\n- The way the traces are connected together.\r\n- How the `uint64_t` value is handled (is it boxed? where? why?)\r\n\r\nHere is the code:\r\n\r\n```\r\nlocal ffi = require(\"ffi\")\r\nlocal a = ffi.new('uint64_t[1]')\r\nfor i = 1, 1000 do\r\n   x = a[0]               -- x is a 64-bit value loaded from FFI\r\n   for i = 1, 1000 do end -- loop 1\r\n   for i = 1, 1000 do end -- loop 2\r\n   for i = 1, 1000 do end -- loop 3\r\n   z = x                  -- x is still alive here\r\nend\r\n```\r\n\r\n### jit.v view\r\n\r\nHere is the `jit.v` output:\r\n\r\n```\r\n$ ./luajit -jv test2.lua\r\n[TRACE   1 test2.lua:5 loop]\r\n[TRACE   2 test2.lua:6 loop]\r\n[TRACE   3 test2.lua:7 loop]\r\n[TRACE   4 (1/3) test2.lua:6 -> 2]\r\n[TRACE   5 (2/3) test2.lua:7 -> 3]\r\n[TRACE   6 (3/3) test2.lua:8 -> 1]\r\n```\r\n\r\nThe first three lines tell us that the first inner loop is traced first, then the second inner loop, then the third inner loop. At this point the loops have been compiled to machine code, but at the end of each one the JIT will return to the interpreter before starting the next one.\r\n\r\nThe other three lines tell us that the JIT then creates traces for three transitions: the first loop (trace 1) to the second loop (trace 2), the second loop to the third loop, and for the third loop back to the first loop. These traces were created because the \"exits\" at the end of the looping traces were executed often enough to become \"hot\" and cause a new trace to start where the loop finishes.\r\n\r\nThe last trace, trace 6, is the most interesting one. This one starts at the end of the third inner loop and then continues back to the first inner loop. This means that it includes all the code in between: both the assignment `z = x` and also the re-entry back into the outer loop. So from the compiler's point of view the start of the other loop is basically the _last_ thing that happens and the first thing is inner loop number one. The opposite of what I would have imagined :). Funky stuff!\r\n\r\n### IR view\r\n\r\nHere is how the basic intermediate representation dump looks. I'll break it into three similar pieces. First the inner loops that are all identical:\r\n\r\n```\r\n---- TRACE 1 start test2.lua:5\r\n---- TRACE 1 IR\r\n0001    int SLOAD  #7    CI\r\n0002  + int ADD    0001  +1  \r\n0003 >  int LE     0002  +1000\r\n0004 ------ LOOP ------------\r\n0005  + int ADD    0002  +1  \r\n0006 >  int LE     0005  +1000\r\n0007    int PHI    0002  0005\r\n---- TRACE 1 stop -> loop\r\n\r\n---- TRACE 2 start test2.lua:6\r\n---- TRACE 2 IR\r\n0001    int SLOAD  #7    CI\r\n0002  + int ADD    0001  +1  \r\n0003 >  int LE     0002  +1000\r\n0004 ------ LOOP ------------\r\n0005  + int ADD    0002  +1  \r\n0006 >  int LE     0005  +1000\r\n0007    int PHI    0002  0005\r\n---- TRACE 2 stop -> loop\r\n\r\n---- TRACE 3 start test2.lua:7\r\n---- TRACE 3 IR\r\n0001    int SLOAD  #7    CI\r\n0002  + int ADD    0001  +1  \r\n0003 >  int LE     0002  +1000\r\n0004 ------ LOOP ------------\r\n0005  + int ADD    0002  +1  \r\n0006 >  int LE     0005  +1000\r\n0007    int PHI    0002  0005\r\n---- TRACE 3 stop -> loop\r\n```\r\n\r\nThen the transitions from the first loop to the second, and second to third. These traces don't actually do any work and only serve to connect the looping traces together. The IR trace shows that they don't include any instructions:\r\n\r\n```\r\n---- TRACE 4 start 1/3 test2.lua:6\r\n---- TRACE 4 IR\r\n---- TRACE 4 stop -> 2\r\n\r\n---- TRACE 5 start 2/3 test2.lua:7\r\n---- TRACE 5 IR\r\n---- TRACE 5 stop -> 3\r\n```\r\n\r\nFinally the last trace does some real work. Correct me if I am wrong:\r\n- Load the value of `x` because none of the earlier traces did so (it wasn't referenced in the loops.)\r\n- Stores this value in z.\r\n- Updates the outer loop counter and checks for termination.\r\n- Loads the new value of `x` for the start of the next outer loop iteration.\r\n\r\n```\r\n---- TRACE 6 start 3/3 test2.lua:8\r\n---- TRACE 6 IR\r\n0001    fun SLOAD  #0    R\r\n0002    tab FLOAD  0001  func.env\r\n0003    int FLOAD  0002  tab.hmask\r\n0004 >  int EQ     0003  +63 \r\n0005    p32 FLOAD  0002  tab.node\r\n0006 >  p32 HREFK  0005  \"x\"  @33\r\n0007 >  cdt HLOAD  0006\r\n0008 >  p32 HREFK  0005  \"z\"  @46\r\n0009    tab FLOAD  0002  tab.meta\r\n0010 >  tab EQ     0009  NULL\r\n0011    cdt HSTORE 0008  0007\r\n0012    nil TBAR   0002\r\n0013    num SLOAD  #3    I\r\n0014    num ADD    0013  +1  \r\n0015 >  num LE     0014  +1000\r\n0016 >  cdt SLOAD  #2    T\r\n0017    u16 FLOAD  0016  cdata.ctypeid\r\n0018 >  int EQ     0017  +96 \r\n0019    p64 ADD    0016  +8  \r\n0020    u64 XLOAD  0019  \r\n0021 >  cdt CNEWI  +12   0020\r\n0022    cdt HSTORE 0006  0021\r\n---- TRACE 6 stop -> 1\r\n```\r\n\r\nInteresting stuff eh?\r\n\r\n### mcode view\r\n\r\nSo now we have seen which traces are created and how they are connected together. Last question: How is the `uint64_t` value loaded from FFI handled? Is this kept locally in registers, with no heap allocation, or does it get stored on the stack, requiring allocation of a GC-able box?\r\n\r\nLooking at IR TRACE 6 above I am specifically wondering about the `CNEWI` instruction at the end that logically allocates a `uint64_t`. Is this \"sunk\" to avoid a real allocation?\r\n\r\nLet's look at the end of the IR trace with `jdump=+rs` enabled to see snapshots, register assignments, and sunk allocations. Here is the relevant bit:\r\n\r\n```\r\n---- TRACE 6 IR\r\n...\r\n0021 rax   >  cdt CNEWI  +12   0020\r\n0022          cdt HSTORE 0006  0021\r\n....              SNAP   #3   [ ---- ---- ---- 0014 ---- ---- 0014 +1   +1000 +1   +1   ]\r\n```\r\n\r\nHere we can see that the allocation is not sunk. The reason is not that the value is still alive at the end of the trace: if that were so we would see the IR instruction number `0021` referenced in the last line snapshot. (The snapshot is a picture of the Lua stack showing where we need to copy updated values of variables out of registers and back onto the stack.) So what is the reason? I am not sure. Could it be a requirement of the `HSTORE` instruction that the value being stored cannot be sunk? Great if somebody knows and can tell me, I feel like I have misunderstood this part.\r\n\r\nAnyway: The machine code shows quite explicitly that this trace does require allowing the GC to run and allocating a new GC-able object:\r\n\r\n```\r\n---- TRACE 6 mcode 386\r\n...\r\nf125fd93  call 0x100006bf0\t->lj_gc_step_jit\r\n...\r\nf125fe81  call 0x100006f20\t->lj_mem_newgco\r\n...\r\n---- TRACE 6 stop -> 1\r\n```\r\n\r\n### The end\r\n\r\nDoes that explanation make any sense? (I wonder if some pictures would help to illustrate the structure of the traces better? Do LOOM and luajit-web-analyzer make this transparent to people already?)"}}
{"actor":{"display_login":"lukego"}}