-Z size filter is needed

[honggyukim]

If we have -Z size filter that can filter out some small functions based on their size, it might be another big improvement along with full dynamic tracing support.

It's important especially for tracing speed, it will make huge tracing speed up with applying NOP instruction to mcount calls in small functions.

It'd be also very useful for debugging some uftrace internal errors. We can narrow down the problem by adjusting the function size filtering out the tracing target functions.

[ParkHanbum]

I want enhanced the debugging message generated while dynamic tracing, also. because we have to enhance the filtering rules that the function could be instrumented. so, debugging message must include the detail of instrumentating informations, for example which function have been patched and the patched instruction.

[namhyung]

@ParkHanbum that kind of information is useful only for development. Please add it for your need and remove when you want to push to upstream, ok?

[namhyung]

Pushed review/size-filter-v1

Example: My test program has 3 functions - main, foo and bar - and their size are 94, 95 and 67 respectively. So the setting it with 70 will remove the last function (bar) in the trace.

$ uftrace -P. -Z 70 a.out
# DURATION     TID     FUNCTION
            [214344] | main() {
   0.145 us [214344] |   foo();
   1.222 us [214344] | } /* main */

And 60 will show it again:

$ uftrace -P. -Z 60 a.out
# DURATION     TID     FUNCTION
            [214382] | main() {
            [214382] |   foo() {
   0.125 us [214382] |     bar();
   1.004 us [214382] |   } /* foo */
   1.885 us [214382] | } /* main */

[honggyukim]

@namhyung Thanks a lot for doing this. I just tested it for node and found that it has huge speed up.

$ uftrace record --time -P. node -e '' 
elapsed time:     27.804769417 sec
 system time:      0.304020000 sec
   user time:     27.505890000 sec

$ uftrace record --time -P. -t 1ms node -e '' 
elapsed time:     22.689101694 sec
 system time:      0.192048000 sec
   user time:     22.501627000 sec

$ uftrace record --time -P. -t 1ms -Z 100 node -e '' 
elapsed time:     13.169035867 sec
 system time:      0.176015000 sec
   user time:     12.997147000 sec

$ uftrace record --time -P. -t 1ms -Z 1000 node -e '' 
elapsed time:      4.103896619 sec
 system time:      0.151687000 sec
   user time:      3.955845000 sec

$ uftrace record --time -P. -t 1ms -Z 1000 --no-libcall node -e ''
elapsed time:      3.277969505 sec
 system time:      0.128046000 sec
   user time:      3.153136000 sec

It's a lot faster than only using time-filter. I also found that some big functions have really a short running time especially when it has a big switch condition or makes an early return.

I think it'd be better to use both -Z size filter along with -t time-filter, then it makes a huge speedup.

[honggyukim]

In addition to this, it'd also make a better speedup if we can detect the size of each library function. Maybe we should first resolve where the function is.

[honggyukim]

Here is another test for chrome. It works fine as follows but I'm not clear if it's faster:

$ uftrace record --time -t 30ms ./chrome --no-sandbox --headless https://www.google.com
elapsed time:    140.795109732 sec
 system time:      2.196000000 sec
   user time:    136.676000000 sec

$ uftrace record --time -t 30ms -Z 3000 ./chrome --no-sandbox --headless https://www.google.com
elapsed time:    175.949800851 sec
 system time:      3.012000000 sec
   user time:    148.692000000 sec

$ uftrace record --time -t 30ms -Z 3000 --no-libcall ./chrome --no-sandbox --headless https://www.google.com
[0614/120031.213625:WARNING:spdy_session.cc(3180)] Received HEADERS for invalid stream 23
elapsed time:    140.910695784 sec
 system time:      2.124000000 sec
   user time:     94.580000000 sec

$ uftrace record --time -t 30ms -Z 10000 --no-libcall ./chrome --no-sandbox --headless https://www.google.com
elapsed time:    140.285842272 sec
 system time:      2.264000000 sec
   user time:     93.188000000 sec

It gets crashed sometimes as follows:

$ uftrace record --time -t 30ms -Z 50000 --no-libcall ./chrome --no-sandbox --headless https://www.google.com
[0614/125627.805850:FATAL:local_window_proxy.cc(147)] Check failed: !GetFrame()->IsProvisional().
#0 0x7f52a7923397 backtrace
#1 0x557adeefeb79 base::debug::StackTrace::StackTrace()
#2 0x557adee575d1 logging::LogMessage::~LogMessage()
#3 0x557ae2d1ca83 blink::LocalWindowProxy::Initialize()
#4 0x557ae1941239 blink::LocalFrame::WindowProxy()
#5 0x557ae2d3ed4f blink::ToScriptState()
#6 0x557ae1c0eeb1 blink::MainThreadDebugger::ensureDefaultContextInGroup()
#7 0x557ade4c771e v8_inspector::(anonymous namespace)::ensureContext()
    ...
#35 0x557ae2a44501 headless::RunChildProcessIfNeeded()
#36 0x557adea44e6f headless::HeadlessShellMain()
#37 0x557adc79ef51 ChromeMain
#38 0x7f52a1390830 __libc_start_main
#39 0x557adc79edba _start
  r8: 00007f52a1736770  r9: 00007f52a7c99b80 r10: 0000000000000008 r11: 0000000000000202
 r12: 00007ffdc9076158 r13: 0000000000000000 r14: 00007ffdc9075758 r15: 00007ffdc9076148
  di: 0000000000022123  si: 0000000000022123  bp: 00007ffdc9075710  bx: 00002ecb7dedc000
  dx: 0000000000000006  ax: 0000000000000000  cx: 00007f52a13a5428  sp: 00007ffdc90755d8
  ip: 00007f52a13a5428 efl: 0000000000000202 cgf: 0000000000000033 erf: 0000000000000000
 trp: 0000000000000000 msk: 0000000000000000 cr2: 0000000000000000
[end of stack trace]
Calling _exit(1). Core file will not be generated.

[namhyung]

Pushed review/size-filter-v2

Changelog:

• apply size filter for other kinds of dynamic tracing (nop-mcount or xray) too.
• add a test case

[namhyung]

Merged 4eec7f8