record: Add -C/--caller-filter option

[honggyukim]

-F/--filter option is useful when tracing the callee functions, but
sometime it's also useful to see its callers in a reverse way.

This patch adds -C/--caller-filter to show caller functions by tracing
the call path to the given function.

The same purpose could be acheived by time-filter with trace trigger
but it's a kind of weird combination to general users. So this adds a
new option to provide the same feature.

The below shows the example to trace the call path to 'free' and its
callers.

  Before:
    $ uftrace -t 1000s -T free@trace <program>

  After:
    $ uftrace -C free <program>

The example output is as follows:

  # DURATION    TID     FUNCTION
              [32587] | main() {
              [32587] |   v8::Shell::Main() {
              [32587] |     v8::V8::InitializeICUDefaultLocation() {
              [32587] |       v8::internal::InitializeICUDefaultLocation() {
     1.380 us [32587] |         free();
     2.493 ms [32587] |       } /* v8::internal::InitializeICUDefaultLocation */
     2.496 ms [32587] |     } /* v8::V8::InitializeICUDefaultLocation */
              [32587] |     v8::V8::InitializeExternalStartupData() {
              [32587] |       v8::internal::InitializeExternalStartupData() {
     0.099 us [32587] |         free();
     0.049 us [32587] |         free();
   653.622 us [32587] |       } /* v8::internal::InitializeExternalStartupData */
   653.826 us [32587] |     } /* v8::V8::InitializeExternalStartupData */
                                ...

Signed-off-by: Honggyu Kim [email protected]

[honggyukim]

I made a new option -C/--caller-filter to provide parent filter as we discussed in the previous meeting.
I prefer to use parent filter than caller filter but -P is already used so chose -C instead.

This is record side implementation but if you agree on adding this option, I will add this to replay side as well. Please take a look at it. Thanks!

[namhyung]

A problem with this approach is that it disables the time filter. User may want to use time filter along with the caller filter - ex) show all memory allocation paths which take longer than XXX.

You'd better adding a new flag for the caller filter and check both of time and caller filters if they are given. And let the 'trace' trigger overrules them.

[namhyung]

Could you please take a look at review/caller-filter-v1? It'd work together with the time filter (and others).

[honggyukim]

@namhyung It works great with clang as follows:

$ uftrace -C mmap --no-event clang s-abc.c
# DURATION     TID     FUNCTION
            [107356] | main() {
            [107356] |   cc1_main() {
            [107356] |     clang::ExecuteCompilerInvocation() {
            [107356] |       clang::CompilerInstance::ExecuteAction() {
            [107356] |         clang::FrontendAction::Execute() {
            [107356] |           clang::CodeGenAction::ExecuteAction() {
            [107356] |             clang::ASTFrontendAction::ExecuteAction() {
            [107356] |               clang::ParseAST() {
            [107356] |                 clang::Parser::Initialize() {
            [107356] |                   clang::Preprocessor::Lex() {
            [107356] |                     clang::Lexer::Lex() {
            [107356] |                       clang::Lexer::LexTokenInternal() {
            [107356] |                         clang::Preprocessor::HandleDirective() {
            [107356] |                           clang::Preprocessor::HandleIncludeDirective() {
            [107356] |                             clang::Preprocessor::EnterSourceFile() {
            [107356] |                               clang::SrcMgr::ContentCache::getBuffer() {
            [107356] |                                 clang::FileManager::getBufferForFile() {
            [107356] |                                   _GLOBAL__N_1::RealFile::getBuffer() {
            [107356] |                                     llvm::MemoryBuffer::getOpenFile() {
            [107356] |                                       getOpenFileImpl() {
            [107356] |                                         llvm::sys::fs::mapped_file_region::mapped_file_region() {
   4.397 us [107356] |                                           mmap();
   6.141 us [107356] |                                         } /* llvm::sys::fs::mapped_file_region::mapped_file_region */
   8.239 us [107356] |                                       } /* getOpenFileImpl */
   8.425 us [107356] |                                     } /* llvm::MemoryBuffer::getOpenFile */
   8.612 us [107356] |                                   } /* _GLOBAL__N_1::RealFile::getBuffer */
  11.933 us [107356] |                                 } /* clang::FileManager::getBufferForFile */
  15.022 us [107356] |                               } /* clang::SrcMgr::ContentCache::getBuffer */
  21.873 us [107356] |                             } /* clang::Preprocessor::EnterSourceFile */
  98.077 us [107356] |                           } /* clang::Preprocessor::HandleIncludeDirective */
 100.657 us [107356] |                         } /* clang::Preprocessor::HandleDirective */
 108.738 us [107356] |                       } /* clang::Lexer::LexTokenInternal */
 108.921 us [107356] |                     } /* clang::Lexer::Lex */
   7.656 ms [107356] |                   } /* clang::Preprocessor::Lex */
   7.761 ms [107356] |                 } /* clang::Parser::Initialize */
            [107356] |                 clang::Parser::ParseTopLevelDecl() {
            [107356] |                   clang::Parser::ParseExternalDeclaration() {
    ...

[honggyukim]

But it fails for node example.

$ uftrace record -C mmap node -e ''

$ uftrace replay
WARN: cannot open record data: uftrace.data: No data available

[honggyukim]

Ah.. It seems that uftrace doesn't catch mmap call in node execution.

$ uftrace -F mmap node -e ''
WARN: cannot open record data: /tmp/uftrace-live-ej71qK: No data available

[honggyukim]

It works great with time filter. Thanks a lot!

$ uftrace -C Builtin.* -t 10ms -a node -e ''
# DURATION     TID     FUNCTION
            [108048] | main(3, 0x7ffd47880ab8) {
            [108048] |   node::Start(3, 0x7ffd47880ab8) {
            [108048] |     v8::Isolate::New(0x7ffd478808f0) {
            [108048] |       v8::Isolate::Initialize(0xb390ae0, 0x7ffd478808f0) {
            [108048] |         v8::internal::Snapshot::Initialize(0xb390ae0) {
            [108048] |           v8::internal::Isolate::Init(0xb390ae0, 0x7ffd478805b0) {
            [108048] |             v8::internal::StartupDeserializer::DeserializeInto(0x7ffd478805b0, 0xb390ae0) {
  11.672 ms [108048] |               v8::internal::BuiltinDeserializer::DeserializeEagerBuiltinsAndHandlers(0x7ffd478800b0);
  45.590 ms [108048] |             } /* v8::internal::StartupDeserializer::DeserializeInto */
 113.775 ms [108048] |           } = 1; /* v8::internal::Isolate::Init */
 113.811 ms [108048] |         } = 1; /* v8::internal::Snapshot::Initialize */
 113.830 ms [108048] |       } /* v8::Isolate::Initialize */
 114.060 ms [108048] |     } = 0xb390ae0; /* v8::Isolate::New */
            [108048] |     node::Start(0xb390ae0, 0xb405f20, 1, 0x3b67cc0, 2, 0xaed9240) {
            [108048] |       node::LoadEnvironment(0x7ffd4787fef0) {
            [108048] |         v8::Function::Call(0xb4094c8, 0xb40ec90, 0xb390b58, 3, 0x7ffd4787fd50) {
            [108048] |           v8::internal::Execution::Call(0xb390ae0, 0xb4094c8, 0xb390b58, 3, 0x7ffd4787fd50) {
  24.090 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787f658, 0xb390ae0) = 0x181f8fe1b479;
  20.630 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787f5f8, 0xb390ae0) = 0x181f8fe20a79;
  48.450 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787f350, 0xb390ae0) = 0x181f8fe25569;
  57.655 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787f5d0, 0xb390ae0) = 0x181f8fe719a9;
  25.275 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787f2f8, 0xb390ae0) = 0x181f8fe7f499;
  12.888 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787f0b0, 0xb390ae0) = 0x29fdfec08d61;
  19.862 ms [108048] |             v8::internal::Builtin_HandleApiCall(6, 0x7ffd4787eff0, 0xb390ae0) = 0x29fdfec0c191;
  38.839 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787f2f8, 0xb390ae0) = 0x29fdfec31ed1;
  34.069 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787efd8, 0xb390ae0) = 0x29fdfec3ad41;
  23.038 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787f480, 0xb390ae0) = 0x29fdfec57db1;
  64.620 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787f270, 0xb390ae0) = 0x29fdfec61019;
  38.436 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787edc0, 0xb390ae0) = 0x29fdfec6f399;
  22.359 ms [108048] |             v8::internal::Builtin_HandleApiCall(6, 0x7ffd4787ef48, 0xb390ae0) = 0x1a33c309b41;
  10.830 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787edc0, 0xb390ae0) = 0x1efe3bd415b9;
  41.870 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787edc0, 0xb390ae0) = 0x1efe3bd45431;
  15.878 ms [108048] |             v8::internal::Builtin_HandleApiCall(6, 0x7ffd4787f640, 0xb390ae0) = 0x181f8fe02d39;
  16.610 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787f600, 0xb390ae0) = 0x181f8fe32d99;
  21.679 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787f5e0, 0xb390ae0) = 0x181f8fe44531;
  15.103 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787f5e0, 0xb390ae0) = 0x181f8fe54991;
  42.088 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787f288, 0xb390ae0) = 0x181f8fe5d5f9;
  24.585 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787ee48, 0xb390ae0) = 0x181f8fe6daf1;
  16.738 ms [108048] |             v8::internal::Builtin_HandleApiCall(12, 0x7ffd4787ee48, 0xb390ae0) = 0x181f8fe7bce1;
   1.119  s [108048] |           } = 0xb409800; /* v8::internal::Execution::Call */
   1.119  s [108048] |         } = 0xb4097f0; /* v8::Function::Call */
   1.188  s [108048] |       } /* node::LoadEnvironment */
   1.221  s [108048] |     } = 0; /* node::Start */
   1.342  s [108048] |   } = 0; /* node::Start */
   1.342  s [108048] | } = 0; /* main */

[namhyung]

Merged: dc6fd55