Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[LuaJIT] jit.p: Enhance 'v' profiler mode #621

Merged
merged 2 commits into from
Sep 14, 2015

Conversation

lukego
Copy link
Member

@lukego lukego commented Sep 14, 2015

This change prints more information when profiling at trace granularity. The idea is to make it easier to audit the runtime behavior of your apps: how many traces do they compile into, how are those traces connected together, and which execution path does each trace represent.

This PR builds on #619 and contains the code previously described in issue #611.

More detail with examples:

Previously the 'v' mode would print a terse summary. For example when profiling the rate_limiter app selftest:

    $ sudo ./snabb snsh -jdump=+rs,x -jp=v -t apps.rate_limiter.rate_limiter
    47%  TRACE 16
    22%  TRACE 15
    11%  TRACE 14
    10%  TRACE 12
     4%  TRACE 18
     4%  TRACE 24

More information is shown with this change:

    $ sudo ./snabb snsh -jdump=+rs,x -jp=v -t apps.rate_limiter.rate_limiter
    47%  TRACE  16 (14/4)   ->14       rate_limiter.lua:82
    22%  TRACE  15          ->loop     basic_apps.lua:82
    11%  TRACE  14          ->loop     rate_limiter.lua:73
    10%  TRACE  12          ->loop     basic_apps.lua:26
     4%  TRACE  18 (12/13)  ->14       basic_apps.lua:25
     4%  TRACE  24 (19/10)  ->12       app.lua:293

This tells us:

  • Is this a side-trace? If so then (PARENT/EXIT) is shown.
  • What does the end of the trace link to? (loop, other trace, ..?)
  • What source line does the trace begin on? (Requires -jdump to be in use)

Note that it is also possible to combine this profile mode with line based profiling to have more visibility into what is happening inside traces:

    45%  TRACE  13 (10/9)   ->10       rate_limiter.lua:82
      -- 33%  counter.lua:add
      -- 32%  packet.lua:free
      -- 20%  freelist.lua:freelist_add
      -- 10%  rate_limiter.lua:method
      --  3%  link.lua:full
    21%  TRACE   8          ->loop     basic_apps.lua:26
      -- 44%  packet.lua:clone
      -- 18%  counter.lua:add
      -- 11%  packet.lua:allocate
      --  9%  freelist.lua:allocate
      --  9%  basic_apps.lua:method
      --  7%  link.lua:full
      --  4%  link.lua:transmit
    19%  TRACE  10          ->loop     rate_limiter.lua:73
      -- 58%  rate_limiter.lua:method
      -- 21%  link.lua:receive
      -- 17%  counter.lua:add
     7%  TRACE  11          ->loop     basic_apps.lua:82
      -- 74%  counter.lua:add
      -- 21%  link.lua:receive
      --  5%  packet.lua:free_internal

This is a patch written by Mike Pall that makes the profiler "v"
option report the time used by each trace separately. This can be used
to decide which traces to analyze when profiling large programs.

Example:

    $ ./luajit -jp=v ../test.lua
    47%  TRACE 1
    43%  TRACE 2
     6%  Interpreted
     3%  Garbage Collector

Originally posted by Mike on the LuaJIT mailing list:
https://www.freelists.org/post/luajit/Profile-at-trace-granularity,1
This change prints more information when profiling at trace
granularity. The idea is to make it easier to audit the runtime
behavior of your apps: how many traces do they compile into, how are
those traces connected together, and which execution path does each
trace represent.

More detail with examples:

Previously the 'v' mode would print a terse summary. For example when
profiling the rate_limiter app selftest:

    $ sudo ./snabb snsh -jdump=+rs,x -jp=v -t apps.rate_limiter.rate_limiter
    47%  TRACE 16
    22%  TRACE 15
    11%  TRACE 14
    10%  TRACE 12
     4%  TRACE 18
     4%  TRACE 24

More information is shown with this change:

    $ sudo ./snabb snsh -jdump=+rs,x -jp=v -t apps.rate_limiter.rate_limiter
    47%  TRACE  16 (14/4)   ->14       rate_limiter.lua:82
    22%  TRACE  15          ->loop     basic_apps.lua:82
    11%  TRACE  14          ->loop     rate_limiter.lua:73
    10%  TRACE  12          ->loop     basic_apps.lua:26
     4%  TRACE  18 (12/13)  ->14       basic_apps.lua:25
     4%  TRACE  24 (19/10)  ->12       app.lua:293

This tells us:

- Is this a side-trace? If so then (PARENT/EXIT) is shown.
- What does the end of the trace link to? (loop, other trace, ..?)
- What source line does the trace begin on? (Requires -jdump to be in use)

Note that it is also possible to combine this profile mode with line
based profiling to have more visibility into what is happening inside
traces:

    45%  TRACE  13 (10/9)   ->10       rate_limiter.lua:82
      -- 33%  counter.lua:add
      -- 32%  packet.lua:free
      -- 20%  freelist.lua:freelist_add
      -- 10%  rate_limiter.lua:method
      --  3%  link.lua:full
    21%  TRACE   8          ->loop     basic_apps.lua:26
      -- 44%  packet.lua:clone
      -- 18%  counter.lua:add
      -- 11%  packet.lua:allocate
      --  9%  freelist.lua:allocate
      --  9%  basic_apps.lua:method
      --  7%  link.lua:full
      --  4%  link.lua:transmit
    19%  TRACE  10          ->loop     rate_limiter.lua:73
      -- 58%  rate_limiter.lua:method
      -- 21%  link.lua:receive
      -- 17%  counter.lua:add
     7%  TRACE  11          ->loop     basic_apps.lua:82
      -- 74%  counter.lua:add
      -- 21%  link.lua:receive
      --  5%  packet.lua:free_internal
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

1 participant