Re: [PATCH v1 00/15] Introduce threaded trace streaming for basic perf record operation

[Arnaldo Carvalho de Melo]

Em Mon, Oct 12, 2020 at 11:50:29AM +0300, Alexey Budankov escreveu:
> 
> Patch set provides threaded trace streaming for base perf record
> operation. Provided streaming mode (--threads) mitigates profiling
> data losses and resolves scalability issues of serial and asynchronous
> (--aio) trace streaming modes on multicore server systems. The patch
> set is based on the prototype [1], [2] and the most closely relates
> to mode 3) "mode that creates thread for every monitored memory map".
> 
> The threaded mode executes one-to-one mapping of trace streaming threads
> to mapped data buffers and streaming into per-CPU trace files located
> at data directory. The data buffers and threads are affined to NUMA
> nodes and monitored CPUs according to system topology. --cpu option
> can be used to specify exact CPUs to be monitored.
> 
> Basic analysis of data directories is provided for perf report mode.
> Raw dump (-D) and aggregated reports are available for data directories,
> still with no memory consumption optimizations. However data directories
> collected with --compression-level option enabled can be analyzed with
> little less memory because trace files are unmaped from tool process
> memory after loading collected data.
> 
> Provided streaming mode is available with Zstd compression/decompression
> (--compression-level) and handling of external commands (--control).
> AUX area tracing, related and derived modes like --snapshot or
> --aux-sample are not enabled. --switch-output, --switch-output-event, 
> --switch-max-files and --timestamp-filename options are not enabled.

Would be interesting to spell out what are the difficulties to have
those options working with this threaded mode, as I expect that once
this is all reviewed and tested we should switch to it by default, no?

- Arnaldo

> Threaded trace streaming is not enabled for pipe mode. Asynchronous
> (--aio) trace streaming and affinity (--affinity) modes are mutually
> exclusive to threaded streaming mode.
> 
> See testing results and validation examples below.
> 
> [1] git clone https://git.kernel.org/pub/scm/linux/kernel/git/jolsa/perf.git -b perf/record_threads
> [2] https://lore.kernel.org/lkml/20180913125450.21342-1-jolsa@xxxxxxxxxx/
> 
> ---
> Alexey Budankov (15):
>   perf session: introduce trace file path to be shown in raw trace dump
>   perf report: output trace file name in raw trace dump
>   perf data: open data directory in read access mode
>   perf session: move reader object definition to header file
>   perf session: introduce decompressor into trace reader object
>   perf session: load data directory into tool process memory
>   perf record: introduce trace file, compressor and stats in mmap object
>   perf record: write trace data into mmap trace files
>   perf record: introduce thread specific objects for trace streaming
>   perf record: manage thread specific data array
>   perf evlist: introduce evlist__ctlfd_update() to update ctl fd status
>   perf record: introduce thread local variable for trace streaming
>   perf record: stop threads in the end of trace streaming
>   perf record: start threads in the beginning of trace streaming
>   perf record: introduce --threads command line option
> 
>  tools/perf/Documentation/perf-record.txt |   7 +
>  tools/perf/builtin-record.c              | 514 +++++++++++++++++++++--
>  tools/perf/util/data.c                   |   4 +
>  tools/perf/util/evlist.c                 |  16 +
>  tools/perf/util/evlist.h                 |   1 +
>  tools/perf/util/mmap.c                   |   6 +
>  tools/perf/util/mmap.h                   |   5 +
>  tools/perf/util/ordered-events.h         |   1 +
>  tools/perf/util/record.h                 |   1 +
>  tools/perf/util/session.c                | 150 ++++---
>  tools/perf/util/session.h                |  28 ++
>  tools/perf/util/tool.h                   |   3 +-
>  12 files changed, 635 insertions(+), 101 deletions(-)
> 
> ---
> Testing results:
> 
>  $ perf test
>  1: vmlinux symtab matches kallsyms                                 : Skip
>  2: Detect openat syscall event                                     : Ok
>  3: Detect openat syscall event on all cpus                         : Ok
>  4: Read samples using the mmap interface                           : Ok
>  5: Test data source output                                         : Ok
>  6: Parse event definition strings                                  : Ok
>  7: Simple expression parser                                        : Ok
>  8: PERF_RECORD_* events & perf_sample fields                       : Ok
>  9: Parse perf pmu format                                           : Ok
> 10: PMU events                                                      :
> 10.1: PMU event table sanity                                        : Ok
> 10.2: PMU event map aliases                                         : Ok
> 10.3: Parsing of PMU event table metrics                            : Skip (some metrics failed)
> 10.4: Parsing of PMU event table metrics with fake PMUs             : Ok
> 11: DSO data read                                                   : Ok
> 12: DSO data cache                                                  : Ok
> 13: DSO data reopen                                                 : FAILED!
> 14: Roundtrip evsel->name                                           : Ok
> 15: Parse sched tracepoints fields                                  : Ok
> 16: syscalls:sys_enter_openat event fields                          : Ok
> 17: Setup struct perf_event_attr                                    : Ok
> 18: Match and link multiple hists                                   : Ok
> 19: 'import perf' in python                                         : FAILED!
> 20: Breakpoint overflow signal handler                              : Ok
> 21: Breakpoint overflow sampling                                    : Ok
> 22: Breakpoint accounting                                           : Ok
> 23: Watchpoint                                                      :
> 23.1: Read Only Watchpoint                                          : Skip
> 23.2: Write Only Watchpoint                                         : Ok
> 23.3: Read / Write Watchpoint                                       : Ok
> 23.4: Modify Watchpoint                                             : Ok
> 24: Number of exit events of a simple workload                      : Ok
> 25: Software clock events period values                             : Ok
> 26: Object code reading                                             : Ok
> 27: Sample parsing                                                  : Ok
> 28: Use a dummy software event to keep tracking                     : Ok
> 29: Parse with no sample_id_all bit set                             : Ok
> 30: Filter hist entries                                             : Ok
> 31: Lookup mmap thread                                              : Ok
> 32: Share thread maps                                               : Ok
> 33: Sort output of hist entries                                     : Ok
> 34: Cumulate child hist entries                                     : Ok
> 35: Track with sched_switch                                         : Ok
> 36: Filter fds with revents mask in a fdarray                       : Ok
> 37: Add fd to a fdarray, making it autogrow                         : Ok
> 38: kmod_path__parse                                                : Ok
> 39: Thread map                                                      : Ok
> 40: LLVM search and compile                                         :
> 40.1: Basic BPF llvm compile                                        : Skip
> 40.2: kbuild searching                                              : Skip
> 40.3: Compile source for BPF prologue generation                    : Skip
> 40.4: Compile source for BPF relocation                             : Skip
> 41: Session topology                                                : Ok
> 42: BPF filter                                                      :
> 42.1: Basic BPF filtering                                           : Skip
> 42.2: BPF pinning                                                   : Skip
> 42.3: BPF prologue generation                                       : Skip
> 42.4: BPF relocation checker                                        : Skip
> 43: Synthesize thread map                                           : Ok
> 44: Remove thread map                                               : Ok
> 45: Synthesize cpu map                                              : Ok
> 46: Synthesize stat config                                          : Ok
> 47: Synthesize stat                                                 : Ok
> 48: Synthesize stat round                                           : Ok
> 49: Synthesize attr update                                          : Ok
> 50: Event times                                                     : Ok
> 51: Read backward ring buffer                                       : Ok
> 52: Print cpu map                                                   : Ok
> 53: Merge cpu map                                                   : Ok
> 54: Probe SDT events                                                : Ok
> 55: is_printable_array                                              : Ok
> 56: Print bitmap                                                    : Ok
> 57: perf hooks                                                      : Ok
> 58: builtin clang support                                           : Skip (not compiled in)
> 59: unit_number__scnprintf                                          : Ok
> 60: mem2node                                                        : Ok
> 61: time utils                                                      : Ok
> 62: Test jit_write_elf                                              : Ok
> 63: Test libpfm4 support                                            : Skip (not compiled in)
> 64: Test api io                                                     : Ok
> 65: maps__merge_in                                                  : Ok
> 66: Demangle Java                                                   : Ok
> 67: Parse and process metrics                                       : Ok
> 68: PE file support                                                 : Ok
> 69: Event expansion for cgroups                                     : Ok
> 70: x86 rdpmc                                                       : Ok
> 71: Convert perf time to TSC                                        : Ok
> 72: DWARF unwind                                                    : Ok
> 73: x86 instruction decoder - new instructions                      : Ok
> 74: Intel PT packet decoder                                         : Ok
> 75: x86 bp modify                                                   : Ok
> 76: Check open filename arg using perf trace + vfs_getname          : FAILED!
> 77: Add vfs_getname probe to get syscall args filenames             : FAILED!
> 78: probe libc's inet_pton & backtrace it with ping                 : Ok
> 79: Use vfs_getname probe to get syscall args filenames             : FAILED!
> 80: Zstd perf.data compression/decompression                        : Ok
> 81: Check Arm CoreSight trace data recording and synthesized samples: Skip
> 
> Validation:
> 
>   $ tools/perf/perf record --threads --compression-level=3 -e cycles,instructions -- ../../bench/matrix/linux/matrix.gcc.g.O3
>   Addr of buf1 = 0x7f8af24ae010
>   Offs of buf1 = 0x7f8af24ae180
>   Addr of buf2 = 0x7f8af04ad010
>   Offs of buf2 = 0x7f8af04ad1c0
>   Addr of buf3 = 0x7f8aee4ac010
>   Offs of buf3 = 0x7f8aee4ac100
>   Addr of buf4 = 0x7f8aec4ab010
>   Offs of buf4 = 0x7f8aec4ab140
>   Threads #: 8 Pthreads
>   Matrix size: 2048
>   Using multiply kernel: multiply1
>   Execution time = 24.579 seconds
>   [ perf record: Woken up 972 times to write data ]
>   [ perf record: Captured and wrote 11.280 MB perf.data (403 samples), compressed (original 66.670 MB, ratio is 5.926) ]
> 
>   $ perf report --header --stats
>   # ========
>   # captured on    : Wed Oct  7 19:07:50 2020
>   # header version : 1
>   # data offset    : 504
>   # data size      : 30056
>   # feat offset    : 30560
>   # hostname : nntvtune39
>   # os release : 5.8.8-100.fc31.x86_64
>   # perf version : 4.13.rc5.gdf19b1347b82
>   # arch : x86_64
>   # nrcpus online : 8
>   # nrcpus avail : 8
>   # cpudesc : Intel(R) Core(TM) i7-6700K CPU @ 4.00GHz
>   # cpuid : GenuineIntel,6,94,3
>   # total memory : 16119484 kB
>   # cmdline : /root/abudanko/kernel/acme/tools/perf/perf record --threads --compression-level=3 -e cycles,instructions -- ../../bench  /matrix/linux/matrix.gcc.g.O3 
>   # event : name = cycles, , id = { 54562, 54563, 54564, 54565, 54566, 54567, 54568, 54569 }, size = 120, { sample_period, sample_freq } = 4000, sample_type = IP|TID|TIME|ID|>
>   # event : name = instructions, , id = { 54570, 54571, 54572, 54573, 54574, 54575, 54576, 54577 }, size = 120, config = 0x1, { sample_period, sample_freq } = 4000, sample_ty>
>   # sibling sockets : 0-7
>   # sibling dies    : 0-7
>   # sibling threads : 0,4
>   # sibling threads : 1,5
>   # sibling threads : 2,6
>   # sibling threads : 3,7
>   # CPU 0: Core ID 0, Die ID 0, Socket ID 0
>   # CPU 1: Core ID 1, Die ID 0, Socket ID 0
>   # CPU 2: Core ID 2, Die ID 0, Socket ID 0
>   # CPU 3: Core ID 3, Die ID 0, Socket ID 0
>   # CPU 4: Core ID 0, Die ID 0, Socket ID 0
>   # CPU 5: Core ID 1, Die ID 0, Socket ID 0
>   # CPU 6: Core ID 2, Die ID 0, Socket ID 0
>   # CPU 7: Core ID 3, Die ID 0, Socket ID 0
>   # node0 meminfo  : total = 16119484 kB, free = 933088 kB
>   # node0 cpu list : 0-7
>   # pmu mappings: intel_pt = 8, software = 1, power = 19, uprobe = 7, uncore_imc = 11, cpu = 4, cstate_core = 17, uncore_cbox_2 = 14, breakpoint = 5, uncore_cbox_0 = 12, trac>
>   # CPU cache info:
>   #  L1 Data                 32K [0,4]
>   #  L1 Instruction          32K [0,4]
>   #  L1 Data                 32K [1,5]
>   #  L1 Instruction          32K [1,5]
>   #  L1 Data                 32K [1,5]
>   #  L1 Instruction          32K [1,5]
>   #  L1 Data                 32K [2,6]
>   #  L1 Instruction          32K [2,6]
>   #  L1 Data                 32K [3,7]
>   #  L1 Instruction          32K [3,7]
>   #  L2 Unified             256K [0,4]
>   #  L2 Unified             256K [1,5]
>   #  L2 Unified             256K [2,6]
>   #  L2 Unified             256K [3,7]
>   #  L3 Unified            8192K [0-7]
>   # time of first sample : 0.000000
>   # time of last sample : 0.000000
>   # sample duration :      0.000 ms
>   # memory nodes (nr 1, block size 0x8000000):
>   #    0 [16G]: 0-23,32-135
>   # directory data version : 1
>   # bpf_prog_info 835: bpf_prog_6deef7357e7b4530 addr 0xffffffffc07c5138 size 66
>   # bpf_prog_info 836: bpf_prog_6deef7357e7b4530 addr 0xffffffffc0804558 size 66
>   # bpf_prog_info 837: bpf_prog_84efc2eecc454ca6 addr 0xffffffffc080804c size 373
>   # bpf_prog_info 838: bpf_prog_6deef7357e7b4530 addr 0xffffffffc0817f50 size 66
>   # bpf_prog_info 839: bpf_prog_6deef7357e7b4530 addr 0xffffffffc082aee8 size 66
>   # bpf_prog_info 840: bpf_prog_5a2b06eab81b8f51 addr 0xffffffffc082c0fc size 1132
>   # bpf_prog_info 841: bpf_prog_8a642ed2819e9acc addr 0xffffffffc0aac380 size 62
>   # bpf_prog_info 842: bpf_prog_8a642ed2819e9acc addr 0xffffffffc0d4c970 size 62
>   # bpf_prog_info 843: bpf_prog_6deef7357e7b4530 addr 0xffffffffc0d4e8bc size 66
>   # bpf_prog_info 844: bpf_prog_6deef7357e7b4530 addr 0xffffffffc0d5050c size 66
>   # bpf_prog_info 845: bpf_prog_3ff695c0afc2579c addr 0xffffffffc0d56098 size 1552
>   # bpf_prog_info 846: bpf_prog_6deef7357e7b4530 addr 0xffffffffc0d58364 size 66
>   # bpf_prog_info 847: bpf_prog_6deef7357e7b4530 addr 0xffffffffc0d6ec00 size 66
>   # compressed : Zstd, level = 3, ratio = 6
>   # cpu pmu capabilities: branches=32, max_precise=3, pmu_name=skylake
>   # missing features: TRACING_DATA BUILD_ID BRANCH_STACK GROUP_DESC AUXTRACE STAT CLOCKID CLOCK_DATA 
>   # ========
>   #
>   Aggregated stats:
>            TOTAL events:    1457107
>             MMAP events:         98
>             LOST events:          0
>             COMM events:          2
>             EXIT events:          6
>         THROTTLE events:          0
>       UNTHROTTLE events:          0
>             FORK events:          8
>             READ events:          0
>           SAMPLE events:    1456388
>            MMAP2 events:          7
>              AUX events:          0
>     ITRACE_START events:          0
>     LOST_SAMPLES events:          0
>           SWITCH events:          0
>  SWITCH_CPU_WIDE events:          0
>       NAMESPACES events:          0
>          KSYMBOL events:         13
>        BPF_EVENT events:         13
>           CGROUP events:        166
>        TEXT_POKE events:          0
>             ATTR events:          0
>       EVENT_TYPE events:          0
>     TRACING_DATA events:          0
>         BUILD_ID events:          0
>   FINISHED_ROUND events:          0
>         ID_INDEX events:          0
>    AUXTRACE_INFO events:          0
>         AUXTRACE events:          0
>   AUXTRACE_ERROR events:          0
>       THREAD_MAP events:          1
>          CPU_MAP events:          1
>      STAT_CONFIG events:          0
>             STAT events:          0
>       STAT_ROUND events:          0
>     EVENT_UPDATE events:          0
>        TIME_CONV events:          1
>          FEATURE events:          0
>       COMPRESSED events:        403
> 
>   $ tools/perf/perf record --threads --compression-level=3 -g --call-graph dwarf,1024 -e cycles,instructions -- ../../bench/matrix/linux/matrix.gcc.g.O3
>   Addr of buf1 = 0x7f15e8b89010
>   Offs of buf1 = 0x7f15e8b89180
>   Addr of buf2 = 0x7f15e6b88010
>   Offs of buf2 = 0x7f15e6b881c0
>   Addr of buf3 = 0x7f15e4b87010
>   Offs of buf3 = 0x7f15e4b87100
>   Addr of buf4 = 0x7f15e2b86010
>   Offs of buf4 = 0x7f15e2b86140
>   Threads #: 8 Pthreads
>   Matrix size: 2048
>   Using multiply kernel: multiply1
>   Execution time = 24.281 seconds
>   [ perf record: Woken up 6923 times to write data ]
>   [ perf record: Captured and wrote 34.933 MB perf.data (10414 samples), compressed (original 1728.795 MB, ratio is 49.530) ]
> 
>   $ perf report --stdio
>   # To display the perf.data header info, please use --header/--header-only options.
>   #
>   #
>   # Total Lost Samples: 0
>   #
>   # Samples: 708K of event 'cycles'
>   # Event count (approx.): 277718834163
>   #
>   # Children      Self  Command          Shared Object             Symbol                                                  
>   # ........  ........  ...............  ........................  ........................................................
>   #
>     99.97%     0.00%  matrix.gcc.g.O3  libc-2.30.so              [.] __GI___clone (inlined)
>             |
>             ---__GI___clone (inlined)
>                |          
>                 --99.97%--start_thread
>                           |          
>                            --99.97%--ThreadFunction
>                                      multiply1
>                                      |          
>                                       --0.96%--asm_sysvec_apic_timer_interrupt
>                                                 |          
>                                                  --0.70%--subflow_syn_recv_sock
>                                                            |          
>                                                             --0.60%--__sysvec_apic_timer_interrupt
>                                                                       |          
>                                                                        --0.57%--hrtimer_interrupt
> 
>     99.97%     0.00%  matrix.gcc.g.O3  libpthread-2.30.so        [.] start_thread
>             |
>             ---start_thread
>                |          
>                 --99.97%--ThreadFunction
>                           |          
>                            --99.97%--multiply1
>                                      |          
>                                       --0.96%--asm_sysvec_apic_timer_interrupt
>                                                 |          
>                                                  --0.70%--subflow_syn_recv_sock
>                                                            |          
>                                                             --0.60%--__sysvec_apic_timer_interrupt
>                                                                       |          
>                                                                        --0.57%--hrtimer_interrupt
> 
>     99.97%     0.00%  matrix.gcc.g.O3  matrix.gcc.g.O3           [.] ThreadFunction
>             |
>             ---ThreadFunction
>                |          
>                 --99.97%--multiply1
>                           |          
>                            --0.96%--asm_sysvec_apic_timer_interrupt
>                                      |          
>                                       --0.70%--subflow_syn_recv_sock
>                                                 |          
>                                                  --0.60%--__sysvec_apic_timer_interrupt
>                                                            |          
>                                                             --0.57%--hrtimer_interrupt
> 
>     99.97%    98.68%  matrix.gcc.g.O3  matrix.gcc.g.O3           [.] multiply1
>             |          
>             |--98.68%--__GI___clone (inlined)
>             |          start_thread
>             |          ThreadFunction
>             |          multiply1
>             |          
>              --1.28%--multiply1
>                        |          
>                         --0.96%--asm_sysvec_apic_timer_interrupt
>                                   |          
>                                    --0.70%--subflow_syn_recv_sock
>                                              |          
>                                               --0.60%--__sysvec_apic_timer_interrupt
>                                                         |          
>                                                          --0.57%--hrtimer_interrupt
> 
>      0.97%     0.05%  matrix.gcc.g.O3  [kernel.kallsyms]         [k] asm_sysvec_apic_timer_interrupt
>             |          
>              --0.91%--asm_sysvec_apic_timer_interrupt
>                        |          
>                         --0.70%--subflow_syn_recv_sock
> 
> 
> -- 
> 2.24.1
> 

-- 

- Arnaldo