Upgrade to Pro — share decks privately, control downloads, hide ads and more …

ConFoo 2019: Profiling and tracing with ptrace,...

ConFoo 2019: Profiling and tracing with ptrace, perf and SystemTap

https://confoo.ca/en/yul2019/session/profiling-and-tracing-with-ptrace-perf-and-systemtap

Modern OS and CPUs come with a variety of APIs for monitoring. Ptrace based commands like strace are easy to use but slow. Perf allows lightweight profiling. SystemTap is a powerful toolkit plus DSL to instrument probe points inside the Kernel as well as static SystemTap/DTrace markers in libs and languages like Java, PHP, and Python. In my talk I'll show and compare various low and high level tools as well as visualization (e.g. flame graphs).

Christian Heimes

March 13, 2019
Tweet

More Decks by Christian Heimes

Other Decks in Programming

Transcript

  1. Profiling and tracing with ptrace, perf and SystemTap ConFoo 2019

    / Montreal 2019-03-13 Christian Heimes Principal Software Engineer [email protected] / [email protected] @ChristianHeimes
  2. Profiling and Tracing, ConFoo 19, @ChristianHeimes • introduction • ptrace

    (strace, ltrace) • kernel & hardware tracing tools • Summary • ~ 5 minutes Q&A Agenda
  3. Profiling and Tracing, ConFoo 19, @ChristianHeimes • Brendan Gregg (Netflix)

    • Victor Stinner (CPython, Red Hat) https://vstinner.readthedocs.io/benchmark.html • Dmitry Levin (strace) ”Modern Strace”, DevConf.CZ 2019 • Michal Sekletár (Red Hat) ”Tracing Tools for Systems Engineers”, DevConf.CZ 2019 Special thanks
  4. Profiling and Tracing, ConFoo 19, @ChristianHeimes Debugging – The process

    of identifying and removing bugs. • active, expensive, intrusive, slow-down • deploy new version • attach debugger Tracing – observing and monitoring behavior • passive, non-intrusive, and fast* Profiling – gathering and analyzing metrics • byproduct of tracing with counting and timing Terminology
  5. Profiling and Tracing, ConFoo 19, @ChristianHeimes Application level tracing •

    debug builds • performance logs (MySQL Slow Query Log, PHP xdebug) • trace hooks (Python: sys.settrace()) User space tracing • LD_PRELOAD, ptrace Kernel space tracing • ftrace, eBPF, systemtap, LTTng, ... Hardware tracing • hardware performance counter, PMU, ... Methodology
  6. Profiling and Tracing, ConFoo 19, @ChristianHeimes • installation of extra

    packages • permissions • root or special group • CAP_SYS_PTRACE, CAP_SYS_ADMIN, CAP_SYS_MODULE • recent Kernel (BCC, eBPF) • debug symbols dnf debuginfo-install package, apt install package-dbg • compiler/linker flags (-g, -fno-omit-framepointer, BIND_LAZY) • disable secure boot (stap) Kernel Live Patching or dynamic modules Prerequisites
  7. Profiling and Tracing, ConFoo 19, @ChristianHeimes • average, median, standard

    deviation, percentile • observational error • systematic error • random error • systemic bias, cognitive bias (human factor) • misleading presentation (Vatican City has 2.27 popes / km²) • sampling profiler: quantization error, Nyquist–Shannon theorem “Producing Wrong Data Without Doing Anything Obviously Wrong!” (Mytkowicz, Diwan, Hauswirth, Sweeney) benchmarks / statistics
  8. Profiling and Tracing, ConFoo 19, @ChristianHeimes • CPU power states

    (P-states, C-states, TurboBoost, thermal throttling) • caches (L1 CPU, file system, JIT warm-up, DNS/HTTP) • hardware IRQs, Address Space Layout Randomization (ASLR) https://vstinner.readthedocs.io/benchmark.html Computers are noisy
  9. Profiling and Tracing, ConFoo 19, @ChristianHeimes env vars, path length,

    hostname, username Benchmark without Python virtual environment % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 28.78 0.000438 0 1440 read 27.33 0.000416 1 440 25 stat 9.72 0.000148 1 144 mmap ... 0.79 0.000012 1 11 munmap Benchmark inside a virtual environment % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 57.12 0.099023 2 61471 munmap 41.87 0.072580 1 61618 mmap 0.23 0.000395 1 465 27 stat Benchmark without Python virtual environment % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 28.78 0.000438 0 1440 read 27.33 0.000416 1 440 25 stat 9.72 0.000148 1 144 mmap ... 0.79 0.000012 1 11 munmap Benchmark inside a virtual environment % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 57.12 0.099023 2 61471 munmap 41.87 0.072580 1 61618 mmap 0.23 0.000395 1 465 27 stat • https://mail.python.org/pipermail/python-dev/2019-February/156522.html • https://homes.cs.washington.edu/~bornholt/post/performance-evaluation.html
  10. Profiling and Tracing, ConFoo 19, @ChristianHeimes Let's profile import time

    start = time.time() with open('/etc/os-release') as f: lines = f.readlines() print(time.time() - start) import time start = time.time() with open('/etc/os-release') as f: lines = f.readlines() print(time.time() - start)
  11. Profiling and Tracing, ConFoo 19, @ChristianHeimes • shell • cat

    • Python • open + read file • HTTPS request with requests • PHP • HTTPS request with libcurl Examples
  12. Profiling and Tracing, ConFoo 19, @ChristianHeimes • process trace syscall

    • introduced in Unix Version 6 (~1985) • user-space tracing • used by debuggers and code analysis tools • gdb • strace • ltrace • code coverage • ... ptrace
  13. Profiling and Tracing, ConFoo 19, @ChristianHeimes ltrace – A library

    call tracer $ ltrace -e 'SSL_CTX*@*' \ python3 -c 'import requests; requests.get("https://www.confoo.ca/en")' _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_new(0x7fa4a1a77120, 0, 0, 0) = 0x55636123a100 _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_get_verify_callback(0x55636123a100, -2, 0x7fa4a1acd5e0, 0x7fa4a1acd5f8) = 0 _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_set_verify(0x55636123a100, 0, 0, 0x7fa4a1acd5f8) = 0 _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_set_options(0x55636123a100, 0x82420054, 0, 0x7fa4a1acd5f8) = 0x82520054 _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_ctrl(0x55636123a100, 33, 16, 0) = 20 _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_set_session_id_context(0x55636123a100, 0x7fa4af500494, 7, 0) = 1 ... _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_free(0x55636123a100, 0x7fa4af4b1e10, -3, 0x7fa4a12734c8) = 0 $ ltrace -e 'SSL_CTX*@*' \ python3 -c 'import requests; requests.get("https://www.confoo.ca/en")' _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_new(0x7fa4a1a77120, 0, 0, 0) = 0x55636123a100 _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_get_verify_callback(0x55636123a100, -2, 0x7fa4a1acd5e0, 0x7fa4a1acd5f8) = 0 _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_set_verify(0x55636123a100, 0, 0, 0x7fa4a1acd5f8) = 0 _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_set_options(0x55636123a100, 0x82420054, 0, 0x7fa4a1acd5f8) = 0x82520054 _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_ctrl(0x55636123a100, 33, 16, 0) = 20 _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_set_session_id_context(0x55636123a100, 0x7fa4af500494, 7, 0) = 1 ... _ssl.cpython-37m-x86_64-linux-gnu.so->SSL_CTX_free(0x55636123a100, 0x7fa4af4b1e10, -3, 0x7fa4a12734c8) = 0
  14. Profiling and Tracing, ConFoo 19, @ChristianHeimes ltrace – count memory

    allocations >>> import os, time, requests >>> os.getpid() 6504 # attach ltrace >>> start = time.time(); r = requests.get("https://www.confoo.ca/en"); print(time.time() - start) # without ltrace: 0.566 sec # with ltrace: 3.396 sec >>> import os, time, requests >>> os.getpid() 6504 # attach ltrace >>> start = time.time(); r = requests.get("https://www.confoo.ca/en"); print(time.time() - start) # without ltrace: 0.566 sec # with ltrace: 3.396 sec $ ltrace -e 'malloc+free+realloc@*' -c -p 6504 % time seconds usecs/call calls function ------ ----------- ----------- --------- -------------------- 53.49 1.104804 37 29796 free 45.78 0.945565 37 25523 malloc 0.73 0.015069 48 309 realloc ------ ----------- ----------- --------- -------------------- 100.00 2.065438 55628 total $ ltrace -e 'malloc+free+realloc@*' -c -p 6504 % time seconds usecs/call calls function ------ ----------- ----------- --------- -------------------- 53.49 1.104804 37 29796 free 45.78 0.945565 37 25523 malloc 0.73 0.015069 48 309 realloc ------ ----------- ----------- --------- -------------------- 100.00 2.065438 55628 total
  15. Profiling and Tracing, ConFoo 19, @ChristianHeimes Ring 3 Ring 2

    Ring 1 Ring 0 Kernel Device drivers Applications Device drivers Least privileged Most privileged Hertzsprung at English Wikipedia [CC BY-SA 3.0] • Paul Kranenburg in 1991 • Dmitry Levin (current maintainer) strace – trace system calls and signals syscall
  16. Profiling and Tracing, ConFoo 19, @ChristianHeimes strace “open” syscall $

    strace -e open cat /etc/os-release >/dev/null +++ exited with 0 +++ $ man 2 open ... The open() system call opens the file specified by pathname. $ strace -e open cat /etc/os-release >/dev/null +++ exited with 0 +++ $ man 2 open ... The open() system call opens the file specified by pathname. $ strace -c cat /etc/os-release >/dev/null % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 31,40 0,000591 590 1 execve 13,51 0,000254 28 9 mmap 8,67 0,000163 40 4 mprotect 7,20 0,000135 22 6 read 6,95 0,000131 32 4 openat 6,36 0,000120 19 6 close 6,21 0,000117 29 4 brk ... ------ ----------- ----------- --------- --------- ---------------- 100.00 0,001882 49 2 total $ strace -c cat /etc/os-release >/dev/null % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 31,40 0,000591 590 1 execve 13,51 0,000254 28 9 mmap 8,67 0,000163 40 4 mprotect 7,20 0,000135 22 6 read 6,95 0,000131 32 4 openat 6,36 0,000120 19 6 close 6,21 0,000117 29 4 brk ... ------ ----------- ----------- --------- --------- ---------------- 100.00 0,001882 49 2 total
  17. Profiling and Tracing, ConFoo 19, @ChristianHeimes • open • x86_64

    glibc <= 2.25: open • x86_64 glibc >= 2.26: openat • riscv: openat $ strace -e ’/^open(at)?$’ syscall ABI / API • stat • fstat, fstat64, fstatat64, lstat, lstat64, newfstatat, oldfstat, oldlstat, oldstat, stat, stat64, statx $ strace -e %%stat %%stat = %stat + %lstat + %fstat + statx
  18. Profiling and Tracing, ConFoo 19, @ChristianHeimes strace “openat” syscall $

    strace -e openat cat /etc/os-release >/dev/null openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/etc/os-release", O_RDONLY) = 3 +++ exited with 0 +++ $ strace -e openat cat /etc/os-release >/dev/null openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/etc/os-release", O_RDONLY) = 3 +++ exited with 0 +++ $ strace -P /etc/os-release cat /etc/os-release >/dev/null strace: Requested path '/etc/os-release' resolved into '/usr/lib/os.release.d/os-release-fedora' openat(AT_FDCWD, "/etc/os-release", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=693, ...}) = 0 fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0 read(3, "NAME=Fedora\nVERSION=\"29 (Twenty "..., 131072) = 693 read(3, "", 131072) = 0 close(3) = 0 +++ exited with 0 +++ $ strace -P /etc/os-release cat /etc/os-release >/dev/null strace: Requested path '/etc/os-release' resolved into '/usr/lib/os.release.d/os-release-fedora' openat(AT_FDCWD, "/etc/os-release", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=693, ...}) = 0 fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0 read(3, "NAME=Fedora\nVERSION=\"29 (Twenty "..., 131072) = 693 read(3, "", 131072) = 0 close(3) = 0 +++ exited with 0 +++
  19. Profiling and Tracing, ConFoo 19, @ChristianHeimes • filter class examples

    • %file: syscall that take a file name as argument • %desc: file descriptor related syscalls • %net: network related syscalls • arguments • -P: path filter • -y: print path associated with file descriptor • -yy: print protocol information (e.g. ip:port) • -t/-tt/-ttt: time stamp • -T: time spent • -k: caller stack trace strace options
  20. Profiling and Tracing, ConFoo 19, @ChristianHeimes strace: requests.get(...) $ strace

    -e %file -p 6504 ... stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=300, ...}) = 0 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/etc/crypto-policies/back-ends/openssl.config", O_RDONLY) = 4 openat(AT_FDCWD, "/etc/ssl/cacert.pem", O_RDONLY) = -1 ENOENT (No such file or directory) $ strace -e %file -p 6504 ... stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=300, ...}) = 0 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/etc/crypto-policies/back-ends/openssl.config", O_RDONLY) = 4 openat(AT_FDCWD, "/etc/ssl/cacert.pem", O_RDONLY) = -1 ENOENT (No such file or directory) $ strace -e %net -p 6504 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 4 connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.38.5.26")}, 16) = 0 sendmmsg(4, [{msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="B\213\1\0\0\1\0\0\0\0\0\0\3www\ 6confoo\2ca\0\0\1\0\1", iov_len=31}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, msg_len=31},...], 2, MSG_NOSIGNAL) = 2 recvfrom(4, "B\213\201\200\0\1\0\1\0\0\0\0\3www\6confoo\2ca\0\0\1\0\1\300"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.38.5.26")}, [28->16]) = 47 recvfrom(4, "9\224\201\200\0\1\0\0\0\1\0\0\3www\6confoo\2ca\0\0\34\0\1\300"..., 65536, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.38.5.26")}, [28->16]) = 98 socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC, IPPROTO_TCP) = 4 setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0 connect(4, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("107.170.8.46")}, 16) = 0 getsockopt(4, SOL_SOCKET, SO_TYPE, [1], [4]) = 0 getpeername(4, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("107.170.8.46")}, [16]) = 0 $ strace -e %net -p 6504 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 4 connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.38.5.26")}, 16) = 0 sendmmsg(4, [{msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="B\213\1\0\0\1\0\0\0\0\0\0\3www\ 6confoo\2ca\0\0\1\0\1", iov_len=31}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, msg_len=31},...], 2, MSG_NOSIGNAL) = 2 recvfrom(4, "B\213\201\200\0\1\0\1\0\0\0\0\3www\6confoo\2ca\0\0\1\0\1\300"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.38.5.26")}, [28->16]) = 47 recvfrom(4, "9\224\201\200\0\1\0\0\0\1\0\0\3www\6confoo\2ca\0\0\34\0\1\300"..., 65536, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.38.5.26")}, [28->16]) = 98 socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC, IPPROTO_TCP) = 4 setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0 connect(4, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("107.170.8.46")}, 16) = 0 getsockopt(4, SOL_SOCKET, SO_TYPE, [1], [4]) = 0 getpeername(4, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("107.170.8.46")}, [16]) = 0
  21. Profiling and Tracing, ConFoo 19, @ChristianHeimes syscall tampering $ strace

    -e inject=socket:error=EMFILE -p 6504 >>> requests.get("https://www.confoo.ca/en") Traceback (most recent call last): ... socket.gaierror: [Errno -2] Name or service not known $ strace -e inject=socket:error=EMFILE:when=2+ -p 6504 Traceback (most recent call last): ... File "/usr/lib64/python3.7/socket.py", line 151, in __init__ _socket.socket.__init__(self, family, type, proto, fileno) OSError: [Errno 24] Too many open files $ strace -e inject=socket:error=EMFILE -p 6504 >>> requests.get("https://www.confoo.ca/en") Traceback (most recent call last): ... socket.gaierror: [Errno -2] Name or service not known $ strace -e inject=socket:error=EMFILE:when=2+ -p 6504 Traceback (most recent call last): ... File "/usr/lib64/python3.7/socket.py", line 151, in __init__ _socket.socket.__init__(self, family, type, proto, fileno) OSError: [Errno 24] Too many open files $ dd if=/dev/zero of=/dev/null bs=1M count=10 10485760 bytes (10 MB, 10 MiB) copied, 0,00328225 s, 3,2 GB/s $ strace -e inject=write:delay_exit=100000 -o /dev/null \ dd if=/dev/zero of=/dev/null bs=1M count=10 10485760 bytes (10 MB, 10 MiB) copied, 1,10699 s, 9,5 MB/s $ dd if=/dev/zero of=/dev/null bs=1M count=10 10485760 bytes (10 MB, 10 MiB) copied, 0,00328225 s, 3,2 GB/s $ strace -e inject=write:delay_exit=100000 -o /dev/null \ dd if=/dev/zero of=/dev/null bs=1M count=10 10485760 bytes (10 MB, 10 MiB) copied, 1,10699 s, 9,5 MB/s
  22. Profiling and Tracing, ConFoo 19, @ChristianHeimes syscall tampering $ strace

    -P /tmp/foo -e inject=unlinkat:retval=0 \ rm /tmp/foo newfstatat(AT_FDCWD, "/tmp/foo", {st_mode=S_IFREG|0664, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0 newfstatat(AT_FDCWD, "/tmp/foo", {st_mode=S_IFREG|0664, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0 faccessat(AT_FDCWD, "/tmp/foo", W_OK) = 0 unlinkat(AT_FDCWD, "/tmp/foo", 0) = 0 (INJECTED) +++ exited with 0 +++ $ ls /tmp/foo /tmp/foo $ strace -P /tmp/foo -e inject=unlinkat:retval=0 \ rm /tmp/foo newfstatat(AT_FDCWD, "/tmp/foo", {st_mode=S_IFREG|0664, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0 newfstatat(AT_FDCWD, "/tmp/foo", {st_mode=S_IFREG|0664, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0 faccessat(AT_FDCWD, "/tmp/foo", W_OK) = 0 unlinkat(AT_FDCWD, "/tmp/foo", 0) = 0 (INJECTED) +++ exited with 0 +++ $ ls /tmp/foo /tmp/foo
  23. Profiling and Tracing, ConFoo 19, @ChristianHeimes ✔ easy to use

    ✔ powerful tool for quick hacks ✔ no extra privileges ✗ slow ✗ limit view (user-space only) ✗ ltrace incompatible with optimizations Verdict $ ltrace ls >/dev/null +++ exited (status 0) +++ $ scanelf -a /bin/ls TYPE PAX PERM ENDIAN STK/REL/PTL TEXTREL RPATH BIND FILE ET_DYN PeMRxS 0755 LE RW- R-- RW- - - NOW /bin/ls $ ltrace ls >/dev/null +++ exited (status 0) +++ $ scanelf -a /bin/ls TYPE PAX PERM ENDIAN STK/REL/PTL TEXTREL RPATH BIND FILE ET_DYN PeMRxS 0755 LE RW- R-- RW- - - NOW /bin/ls
  24. Profiling and Tracing, ConFoo 19, @ChristianHeimes • Trace inside the

    Kernel • file system • hardware drivers • Profile hardware • CPU cache • memory / MMU • efficient user-space tracing • single process • system-wide • learn how Kernel space and hardware works Low-level tracing
  25. Profiling and Tracing, ConFoo 19, @ChristianHeimes • kprobes • uprobes

    • events • perf_event (HPC, PMU, page faults, TLB, ...) • clock • Kernel TRACE_EVENT, DEFINE_EVENT • user defined • dtrace probe / USDT (Userland Statically Defined Tracing) • lttng-ust Data sources
  26. Profiling and Tracing, ConFoo 19, @ChristianHeimes Kernel probes • (almost)

    all internal Kernel functions • /proc/kallsyms User-space probes • (almost) all functions in binaries • applications • shared libraries kprobes / uprobes
  27. Profiling and Tracing, ConFoo 19, @ChristianHeimes perf_event & metrics $

    perf list branch-instructions OR branches [Hardware event] branch-misses [Hardware event] bus-cycles [Hardware event] ... alignment-faults [Software event] bpf-output [Software event] context-switches OR cs [Software event] cpu-clock [Software event] cpu-migrations OR migrations [Software event] ... L1-dcache-load-misses [Hardware cache event] L1-dcache-loads [Hardware cache event] L1-dcache-stores [Hardware cache event] L1-icache-load-misses [Hardware cache event] ... power/energy-cores/ [Kernel PMU event] power/energy-gpu/ [Kernel PMU event] power/energy-pkg/ [Kernel PMU event] power/energy-psys/ [Kernel PMU event] ... floating point: fp_arith_inst_retired.128b_packed_double [Number of SSE/AVX computational 128-bit packed double precision floating-point instructions ...] ... Summary: CLKS [Per-thread actual clocks when the logical processor is active. This is called 'Clockticks' in VTune] CPI [Cycles Per Instruction (threaded)] $ perf list branch-instructions OR branches [Hardware event] branch-misses [Hardware event] bus-cycles [Hardware event] ... alignment-faults [Software event] bpf-output [Software event] context-switches OR cs [Software event] cpu-clock [Software event] cpu-migrations OR migrations [Software event] ... L1-dcache-load-misses [Hardware cache event] L1-dcache-loads [Hardware cache event] L1-dcache-stores [Hardware cache event] L1-icache-load-misses [Hardware cache event] ... power/energy-cores/ [Kernel PMU event] power/energy-gpu/ [Kernel PMU event] power/energy-pkg/ [Kernel PMU event] power/energy-psys/ [Kernel PMU event] ... floating point: fp_arith_inst_retired.128b_packed_double [Number of SSE/AVX computational 128-bit packed double precision floating-point instructions ...] ... Summary: CLKS [Per-thread actual clocks when the logical processor is active. This is called 'Clockticks' in VTune] CPI [Cycles Per Instruction (threaded)]
  28. Profiling and Tracing, ConFoo 19, @ChristianHeimes Kernel trace events #

    find /sys/kernel/debug/tracing/events -name format | wc -l 1787 # find /sys/kernel/debug/tracing/events -name format | wc -l 1787 # trace-cmd record -e 'cfg80211:cfg80211_inform_bss_frame' -e 'cfg80211:cfg80211_get_bss' # trace-cmd report ... irq/140-iwlwifi-1834 [002] 91697.995389: cfg80211_inform_bss_frame: phy0, band: 1, freq: 5180(scan_width: 0) signal: -6600, tsb:132269768490547, detect_tsf:0, tsf_bssid: 00:00:00:00:00:00 kworker/u16:3-23176 [004] 91697.995468: cfg80211_inform_bss_frame: phy0, band: 1, freq: 5180(scan_width: 0) signal: -6600, tsb:132269768490547, detect_tsf:0, tsf_bssid: 00:00:00:00:00:00 irq/140-iwlwifi-1834 [002] 91698.002485: cfg80211_inform_bss_frame: phy0, band: 1, freq: 5180(scan_width: 0) signal: -6700, tsb:132269775585563, detect_tsf:0, tsf_bssid: 00:00:00:00:00:00 wpa_supplicant-2320 [000] 91698.198168: cfg80211_get_bss: phy0, band: 1, freq: 5180, 08:96:d7:XX:XX:XX, buf: 0x73, bss_type: 0, privacy: 2 wpa_supplicant-2320 [000] 91698.216052: cfg80211_get_bss: phy0, band: 1, freq: 5180, 08:96:d7:XX:XX:XX, buf: 0x73, bss_type: 0, privacy: 2 # trace-cmd record -e 'cfg80211:cfg80211_inform_bss_frame' -e 'cfg80211:cfg80211_get_bss' # trace-cmd report ... irq/140-iwlwifi-1834 [002] 91697.995389: cfg80211_inform_bss_frame: phy0, band: 1, freq: 5180(scan_width: 0) signal: -6600, tsb:132269768490547, detect_tsf:0, tsf_bssid: 00:00:00:00:00:00 kworker/u16:3-23176 [004] 91697.995468: cfg80211_inform_bss_frame: phy0, band: 1, freq: 5180(scan_width: 0) signal: -6600, tsb:132269768490547, detect_tsf:0, tsf_bssid: 00:00:00:00:00:00 irq/140-iwlwifi-1834 [002] 91698.002485: cfg80211_inform_bss_frame: phy0, band: 1, freq: 5180(scan_width: 0) signal: -6700, tsb:132269775585563, detect_tsf:0, tsf_bssid: 00:00:00:00:00:00 wpa_supplicant-2320 [000] 91698.198168: cfg80211_get_bss: phy0, band: 1, freq: 5180, 08:96:d7:XX:XX:XX, buf: 0x73, bss_type: 0, privacy: 2 wpa_supplicant-2320 [000] 91698.216052: cfg80211_get_bss: phy0, band: 1, freq: 5180, 08:96:d7:XX:XX:XX, buf: 0x73, bss_type: 0, privacy: 2
  29. Profiling and Tracing, ConFoo 19, @ChristianHeimes • ftrace (tracefs) •

    perf • BCC / eBPF tools • SystemTap • more tools • LTTng • dtrace • VTune • SysDig • ... Advanced tools
  30. Profiling and Tracing, ConFoo 19, @ChristianHeimes • Mathieu Desnoyers (2005)

    • École Polytechnique de Montréal • suite of tools • LTTng-tools • LTTng-modules (Kernel mod) • LTTng-UST LTTng is an open source software toolkit which you can use to simultaneously trace the Linux kernel, user applications, and user libraries. LTTng – Linux Trace Toolkit: next generation
  31. Profiling and Tracing, ConFoo 19, @ChristianHeimes • Sun Microsystems (2005)

    for Solaris • DTrace markers • operating systems • Linux (2017) • Windows (2018) • macOS • FreeBSD • NetBSD DTrace
  32. Profiling and Tracing, ConFoo 19, @ChristianHeimes • by Steven Rostedt

    (2008) • tracefs /sys/kernel/debug/tracing • ring buffer / pipes • GCC profiling, live patching, trampolines • foundation for Live Kernel Patching • frontends • busybox / shell (cat, echo) • trace-cmd • KernelShark • perf ftrace – Function Tracer
  33. Profiling and Tracing, ConFoo 19, @ChristianHeimes trace-cmd: NFS open (simplified)

    # trace-cmd record -p function_graph -l 'nfs_*' -c python3 python_open.py # trace-cmd report ... <...>-56879 [006] 8398345.057032: funcgraph_entry: | nfs_permission() { <...>-56879 [006] 8398345.057032: funcgraph_entry: 0.065 us | nfs_do_access(); <...>-56879 [006] 8398345.057033: funcgraph_entry: | nfs_do_access() { <...>-56879 [006] 8398345.057034: funcgraph_entry: 0.912 us | nfs_alloc_fattr(); <...>-56879 [006] 8398345.057947: funcgraph_entry: | nfs_refresh_inode() { <...>-56879 [006] 8398345.057950: funcgraph_entry: | nfs_refresh_inode.part.27() { <...>-56879 [006] 8398345.057951: funcgraph_entry: | nfs_refresh_inode_locked() { <...>-56879 [006] 8398345.057952: funcgraph_entry: | nfs_update_inode() { <...>-56879 [006] 8398345.057952: funcgraph_entry: 0.190 us | nfs_file_has_writers(); <...>-56879 [006] 8398345.057954: funcgraph_entry: 0.235 us | nfs_set_cache_invalid(); <...>-56879 [006] 8398345.057955: funcgraph_exit: 3.089 us | } <...>-56879 [006] 8398345.057955: funcgraph_exit: 4.106 us | } <...>-56879 [006] 8398345.057955: funcgraph_exit: 4.830 us | } <...>-56879 [006] 8398345.057964: funcgraph_exit: + 14.691 us | } <...>-56879 [006] 8398345.057964: funcgraph_entry: 0.053 us | nfs_access_set_mask(); <...>-56879 [006] 8398345.057966: funcgraph_entry: 2.621 us | nfs_access_add_cache(); <...>-56879 [006] 8398345.057970: funcgraph_exit: ! 936.572 us | } <...>-56879 [006] 8398345.057970: funcgraph_exit: ! 937.907 us | } # trace-cmd record -p function_graph -l 'nfs_*' -c python3 python_open.py # trace-cmd report ... <...>-56879 [006] 8398345.057032: funcgraph_entry: | nfs_permission() { <...>-56879 [006] 8398345.057032: funcgraph_entry: 0.065 us | nfs_do_access(); <...>-56879 [006] 8398345.057033: funcgraph_entry: | nfs_do_access() { <...>-56879 [006] 8398345.057034: funcgraph_entry: 0.912 us | nfs_alloc_fattr(); <...>-56879 [006] 8398345.057947: funcgraph_entry: | nfs_refresh_inode() { <...>-56879 [006] 8398345.057950: funcgraph_entry: | nfs_refresh_inode.part.27() { <...>-56879 [006] 8398345.057951: funcgraph_entry: | nfs_refresh_inode_locked() { <...>-56879 [006] 8398345.057952: funcgraph_entry: | nfs_update_inode() { <...>-56879 [006] 8398345.057952: funcgraph_entry: 0.190 us | nfs_file_has_writers(); <...>-56879 [006] 8398345.057954: funcgraph_entry: 0.235 us | nfs_set_cache_invalid(); <...>-56879 [006] 8398345.057955: funcgraph_exit: 3.089 us | } <...>-56879 [006] 8398345.057955: funcgraph_exit: 4.106 us | } <...>-56879 [006] 8398345.057955: funcgraph_exit: 4.830 us | } <...>-56879 [006] 8398345.057964: funcgraph_exit: + 14.691 us | } <...>-56879 [006] 8398345.057964: funcgraph_entry: 0.053 us | nfs_access_set_mask(); <...>-56879 [006] 8398345.057966: funcgraph_entry: 2.621 us | nfs_access_add_cache(); <...>-56879 [006] 8398345.057970: funcgraph_exit: ! 936.572 us | } <...>-56879 [006] 8398345.057970: funcgraph_exit: ! 937.907 us | }
  34. Profiling and Tracing, ConFoo 19, @ChristianHeimes trace-cmd: NFS open call

    stack # trace-cmd record -p function --func-stack -l nfs_permission -c python3 python_open.py # trace-cmd report <...>-56912 [006] 8398623.394239: function: nfs_permission <...>-56912 [006] 8398623.394605: kernel_stack: <stack trace> => nfs_permission (ffffffffc075d415) => inode_permission (ffffffffba2bb34e) => link_path_walk.part.49 (ffffffffba2bf172) => path_lookupat.isra.53 (ffffffffba2bfbc3) => filename_lookup.part.67 (ffffffffba2c18c0) => vfs_statx (ffffffffba2b5683) => __do_sys_newstat (ffffffffba2b5c29) => do_syscall_64 (ffffffffba00418b) => entry_SYSCALL_64_after_hwframe (ffffffffbaa00088) ... <...>-56912 [006] 8398623.396069: function: nfs_permission <...>-56912 [006] 8398623.396093: kernel_stack: <stack trace> => nfs_permission (ffffffffc075d415) => inode_permission (ffffffffba2bb34e) => link_path_walk.part.49 (ffffffffba2bf172) => path_openat (ffffffffba2bfdef) => do_filp_open (ffffffffba2c26e3) => do_sys_open (ffffffffba2ada36) => do_syscall_64 (ffffffffba00418b) => entry_SYSCALL_64_after_hwframe (ffffffffbaa00088) # trace-cmd record -p function --func-stack -l nfs_permission -c python3 python_open.py # trace-cmd report <...>-56912 [006] 8398623.394239: function: nfs_permission <...>-56912 [006] 8398623.394605: kernel_stack: <stack trace> => nfs_permission (ffffffffc075d415) => inode_permission (ffffffffba2bb34e) => link_path_walk.part.49 (ffffffffba2bf172) => path_lookupat.isra.53 (ffffffffba2bfbc3) => filename_lookup.part.67 (ffffffffba2c18c0) => vfs_statx (ffffffffba2b5683) => __do_sys_newstat (ffffffffba2b5c29) => do_syscall_64 (ffffffffba00418b) => entry_SYSCALL_64_after_hwframe (ffffffffbaa00088) ... <...>-56912 [006] 8398623.396069: function: nfs_permission <...>-56912 [006] 8398623.396093: kernel_stack: <stack trace> => nfs_permission (ffffffffc075d415) => inode_permission (ffffffffba2bb34e) => link_path_walk.part.49 (ffffffffba2bf172) => path_openat (ffffffffba2bfdef) => do_filp_open (ffffffffba2c26e3) => do_sys_open (ffffffffba2ada36) => do_syscall_64 (ffffffffba00418b) => entry_SYSCALL_64_after_hwframe (ffffffffbaa00088)
  35. Profiling and Tracing, ConFoo 19, @ChristianHeimes • Linux Kernel (2009)

    • perf_event_open() syscall • perf counters (HPC, SPC) • kprobes, uprobes, trace points • LBR (Last Branch Records) sampling on recent Intel CPUs • low-overhead sampling with callgraph • wide range analysis from CPU instructions to NodeJS • perf command • privileged and unprivileged • ncurse user interface perf – Performance analysis tools for Linux
  36. Profiling and Tracing, ConFoo 19, @ChristianHeimes perf stat # perf

    stat -d make -j 208.784,16 msec task-clock # 2,599 CPUs utilized 156.385 context-switches # 749,028 M/sec 7.964 cpu-migrations # 38,145 M/sec 3.774.260 page-faults # 18077,343 M/sec 611.151.444.573 cycles # 2927194,826 GHz (62,51%) 620.124.617.748 instructions # 1,01 insn per cycle (75,02%) 134.224.550.386 branches # 642887148,373 M/sec (75,02%) 4.022.428.040 branch-misses # 3,00% of all branches (75,00%) 170.553.275.660 L1-dcache-loads # 816888629,684 M/sec (75,00%) 10.332.035.249 L1-dcache-load-misses # 6,06% of all L1-dcache hits (74,99%) 2.288.155.928 LLC-loads # 10959440,992 M/sec (49,98%) 477.323.105 LLC-load-misses # 20,86% of all LL-cache hits (50,01%) 80,335503652 seconds time elapsed 185,163504000 seconds user 18,416851000 seconds sys # perf stat -d make -j 208.784,16 msec task-clock # 2,599 CPUs utilized 156.385 context-switches # 749,028 M/sec 7.964 cpu-migrations # 38,145 M/sec 3.774.260 page-faults # 18077,343 M/sec 611.151.444.573 cycles # 2927194,826 GHz (62,51%) 620.124.617.748 instructions # 1,01 insn per cycle (75,02%) 134.224.550.386 branches # 642887148,373 M/sec (75,02%) 4.022.428.040 branch-misses # 3,00% of all branches (75,00%) 170.553.275.660 L1-dcache-loads # 816888629,684 M/sec (75,00%) 10.332.035.249 L1-dcache-load-misses # 6,06% of all L1-dcache hits (74,99%) 2.288.155.928 LLC-loads # 10959440,992 M/sec (49,98%) 477.323.105 LLC-load-misses # 20,86% of all LL-cache hits (50,01%) 80,335503652 seconds time elapsed 185,163504000 seconds user 18,416851000 seconds sys # perf stat -M Turbo_Utilization make -j 599.287.742.470 cpu_clk_unhalted.thread # 1,7 Turbo_Utilization 354.672.677.325 cpu_clk_unhalted.ref_tsc Intel i5-8265U 1.60GHz / 3.90GHz # perf stat -M Turbo_Utilization make -j 599.287.742.470 cpu_clk_unhalted.thread # 1,7 Turbo_Utilization 354.672.677.325 cpu_clk_unhalted.ref_tsc Intel i5-8265U 1.60GHz / 3.90GHz
  37. Profiling and Tracing, ConFoo 19, @ChristianHeimes perf probe $ sudo

    perf probe -x /lib64/libc.so.6 --add malloc --add realloc --add free Added new events: probe_libc:malloc (on malloc in /usr/lib64/libc-2.28.so) probe_libc:malloc_1 (on malloc in /usr/lib64/libc-2.28.so) probe_libc:realloc (on realloc in /usr/lib64/libc-2.28.so) probe_libc:realloc_1 (on realloc in /usr/lib64/libc-2.28.so) probe_libc:free (on free in /usr/lib64/libc-2.28.so) probe_libc:free_1 (on free in /usr/lib64/libc-2.28.so) $ sudo perf probe -x /lib64/libc.so.6 --add malloc --add realloc --add free Added new events: probe_libc:malloc (on malloc in /usr/lib64/libc-2.28.so) probe_libc:malloc_1 (on malloc in /usr/lib64/libc-2.28.so) probe_libc:realloc (on realloc in /usr/lib64/libc-2.28.so) probe_libc:realloc_1 (on realloc in /usr/lib64/libc-2.28.so) probe_libc:free (on free in /usr/lib64/libc-2.28.so) probe_libc:free_1 (on free in /usr/lib64/libc-2.28.so) $ sudo perf stat -e 'probe_libc:malloc*' -e 'probe_libc:free*' -e 'probe_libc:realloc*' -p 18154 25.540 probe_libc:malloc_1 0 probe_libc:malloc 0 probe_libc:free 29.948 probe_libc:free_1 0 probe_libc:realloc 309 probe_libc:realloc_1 $ sudo perf stat -e 'probe_libc:malloc*' -e 'probe_libc:free*' -e 'probe_libc:realloc*' -p 18154 25.540 probe_libc:malloc_1 0 probe_libc:malloc 0 probe_libc:free 29.948 probe_libc:free_1 0 probe_libc:realloc 309 probe_libc:realloc_1 plain 0.566 sec ltrace 3.396 sec perf 0.705 sec
  38. Profiling and Tracing, ConFoo 19, @ChristianHeimes perf record / report

    $ perf record -Fmax --call-graph lbr php ../curl_example.php $ sudo perf record -Fmax -g -e 'syscalls:sys_enter_*' php ../curl_example.php $ perf record -Fmax --call-graph lbr php ../curl_example.php $ sudo perf record -Fmax -g -e 'syscalls:sys_enter_*' php ../curl_example.php $ perf script | stackcollapse-perf.pl > out.perf-folded $ flamegraph.pl out.perf-folded > perf-calls.svg $ perf script | stackcollapse-perf.pl > out.perf-folded $ flamegraph.pl out.perf-folded > perf-calls.svg $ perf report $ perf annotate $ perf report $ perf annotate
  39. Profiling and Tracing, ConFoo 19, @ChristianHeimes Flame Graph Reset Zoom

    Search [php] PEM_read_bio_ex _d.. SS.. AS.. ASN1_.. ph.. OPENS.. _.. dl.. _d.. SSL_C.. st.. [p.. zen.. dl_main [libc.. ga.. B.. dl.. [libc.. dl.. Curl_.. [libcrypto.so.1.1.1b] _.. [li.. curl_.. _.. _.. _.. [libcryp.. X5.. dl.. curl_mu.. ASN.. fe.. _d.. ze.. [lib.. dl.. _d.. AS.. ASN1_item_ex_d2i [libcrypto.so.1.1.1b] [l.. c.. ge.. [libcryp.. os.. [libcry.. _start c.. AS.. [l.. os.. zend_h.. dl.. ze.. ph.. [libcrypto.so.1.1.1b] [.. EVP_Dec.. [p.. PE.. curl_eas.. _d.. execute_ex [.. [libcrypto.so.1.1.1b] _d.. [.. ge.. [php] [lib.. __.. PEM_X509_INFO_read_bio zen.. os.. m.. ASN1_ite.. ossl_.. X5.. [php] _d.. _dl_reloc.. do_loo.. zend_exe.. [li.. _dl_look.. multi_.. X.. _dl_sysdep_s.. C.. php [php] [libcryp.. [l.. p.. [php] [lib.. [libcrypto.so.1.1.1b] _.. X509_.. [.. [libcrypto.so.1.1.1b] m.. _d.. ph.. _d.. php_modu.. [curl... Cu.. php_exec.. [php] AS.. [.. Cu.. _.. ASN1_item_d2i [libcrypto.so.1.1.1b] X509_load_cert_crl_file X509_.. curl_e.. [php] [libcry.. Curl_.. Cu.. [l.. [libcrypto.so.1.1... Curl_.. [libcrypto.so.1.1.1b] [l.. _d.. [libcry.. [libcrypto.so.1.1.1b] _.. A.. EC_G.. [libcr.. _d.. ph.. [.. cu.. [libcrypto.so.1.1.1b] ossl_connect_step1 X509_STORE_load_locations Curl_c.. dl.. _dl_start [li.. [libcryp.. zend_exe.. execut.. _.. [l.. BI.. c.. _d.. [curl.so] [.. zen.. ph.. [libc..
  40. Profiling and Tracing, ConFoo 19, @ChristianHeimes A toolkit for creating

    efficient kernel tracing and manipulation programs. • Run tracing code in Kernel space • extended BPF (Berkeley Packet Filters) • eBPF JIT 2014 • Usable Kernel 4.12 - 4.15, 2017 • C with Python and LUA frontends • rich set of existing tools BCC – BPF Compiler Collection
  41. Profiling and Tracing, ConFoo 19, @ChristianHeimes BCC: ext4slow, tcpconnect #

    ./ext4slower 1 Tracing ext4 operations slower than 1 ms TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME 18:44:18 bash 4573 R 128 0 6.45 balooctl 18:44:19 IndexedDB #198 4571 S 0 0 8.90 583651055lp.sqlite-wal 18:44:21 IndexedDB #198 4571 S 0 0 10.02 583651055lp.sqlite-wal 18:44:21 IndexedDB #198 4571 S 0 0 3.90 583651055lp.sqlite 18:44:43 mozStorage #5 4571 W 24 288 6.10 cookies.sqlite-wal # ./ext4slower 1 Tracing ext4 operations slower than 1 ms TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME 18:44:18 bash 4573 R 128 0 6.45 balooctl 18:44:19 IndexedDB #198 4571 S 0 0 8.90 583651055lp.sqlite-wal 18:44:21 IndexedDB #198 4571 S 0 0 10.02 583651055lp.sqlite-wal 18:44:21 IndexedDB #198 4571 S 0 0 3.90 583651055lp.sqlite 18:44:43 mozStorage #5 4571 W 24 288 6.10 cookies.sqlite-wal # ./tcpconnect -u 1000 PID COMM IP SADDR DADDR DPORT 4874 Chrome_IOThr 4 192.168.7.168 107.170.8.46 80 4874 Chrome_IOThr 4 192.168.7.168 107.170.8.46 443 4874 Chrome_IOThr 4 192.168.7.168 107.170.8.46 443 4874 Chrome_IOThr 4 192.168.7.168 107.170.8.46 443 4874 Chrome_IOThr 4 192.168.7.168 107.170.8.46 443 4874 Chrome_IOThr 4 192.168.7.168 107.170.8.46 443 # ./tcpconnect -u 1000 PID COMM IP SADDR DADDR DPORT 4874 Chrome_IOThr 4 192.168.7.168 107.170.8.46 80 4874 Chrome_IOThr 4 192.168.7.168 107.170.8.46 443 4874 Chrome_IOThr 4 192.168.7.168 107.170.8.46 443 4874 Chrome_IOThr 4 192.168.7.168 107.170.8.46 443 4874 Chrome_IOThr 4 192.168.7.168 107.170.8.46 443 4874 Chrome_IOThr 4 192.168.7.168 107.170.8.46 443 Slow ext4fs operations TCP connections for user id 1000
  42. Profiling and Tracing, ConFoo 19, @ChristianHeimes BCC: sslsniff >>> requests.get("https://www.confoo.ca/en",

    headers={'Accept-Encoding': 'identity'}) >>> requests.get("https://www.confoo.ca/en", headers={'Accept-Encoding': 'identity'}) # ./sslsniff -p7767 FUNC TIME(s) COMM PID LEN WRITE/SEND 0.000000000 python3 7767 141 ----- DATA ----- GET /en HTTP/1.1 Host: www.confoo.ca User-Agent: python-requests/2.20.0 Accept-Encoding: identity Accept: */* Connection: keep-alive ----- END DATA ----- READ/RECV 0.247776305 python3 7767 327 ----- DATA ----- HTTP/1.1 200 OK Date: Wed, 06 Mar 2019 20:19:33 GMT Server: Apache/2.4.7 (Ubuntu) X-Powered-By: PHP/5.5.9-1ubuntu4.25 Set-Cookie: symfony=3cvshku4imcfb92isalpa5p243; path=/ Vary: Accept-Encoding Keep-Alive: timeout=5, max=100 Connection: Keep-Alive Transfer-Encoding: chunked Content-Type: text/html; charset=utf-8 ----- END DATA ----- READ/RECV 0.250146592 python3 7767 6 # ./sslsniff -p7767 FUNC TIME(s) COMM PID LEN WRITE/SEND 0.000000000 python3 7767 141 ----- DATA ----- GET /en HTTP/1.1 Host: www.confoo.ca User-Agent: python-requests/2.20.0 Accept-Encoding: identity Accept: */* Connection: keep-alive ----- END DATA ----- READ/RECV 0.247776305 python3 7767 327 ----- DATA ----- HTTP/1.1 200 OK Date: Wed, 06 Mar 2019 20:19:33 GMT Server: Apache/2.4.7 (Ubuntu) X-Powered-By: PHP/5.5.9-1ubuntu4.25 Set-Cookie: symfony=3cvshku4imcfb92isalpa5p243; path=/ Vary: Accept-Encoding Keep-Alive: timeout=5, max=100 Connection: Keep-Alive Transfer-Encoding: chunked Content-Type: text/html; charset=utf-8 ----- END DATA ----- READ/RECV 0.250146592 python3 7767 6
  43. Profiling and Tracing, ConFoo 19, @ChristianHeimes BPFtrace https://github.com/iovisor/bpftrace $ sudo

    bpftrace -e \ 'tracepoint:syscalls:sys_enter_openat { printf("%s(%d) %s\n", comm, pid, str(args->filename)); }' irqbalance(1329) /proc/interrupts $ sudo bpftrace -e \ 'tracepoint:syscalls:sys_enter_openat { printf("%s(%d) %s\n", comm, pid, str(args->filename)); }' irqbalance(1329) /proc/interrupts $ sudo bpftrace -e 'uprobe:/lib64/libc.so.6:malloc / comm == "php" / { @bytes = hist(arg0); }' @bytes: [0, 1] 146 | | [2, 4) 668 |@ | [4, 8) 438 | | [8, 16) 2064 |@@@@ | [16, 32) 13092 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ | [32, 64) 22880 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| [64, 128) 5300 |@@@@@@@@@@@@ | [128, 256) 768 |@ | [256, 512) 1429 |@@@ | [512, 1K) 741 |@ | [1K, 2K) 381 | | [2K, 4K) 82 | | [4K, 8K) 26 | | [8K, 16K) 9 | | [16K, 32K) 22 | | [32K, 64K) 4 | | [64K, 128K) 7 | | [128K, 256K) 1 | | [256K, 512K) 2 | | $ sudo bpftrace -e 'uprobe:/lib64/libc.so.6:malloc / comm == "php" / { @bytes = hist(arg0); }' @bytes: [0, 1] 146 | | [2, 4) 668 |@ | [4, 8) 438 | | [8, 16) 2064 |@@@@ | [16, 32) 13092 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ | [32, 64) 22880 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| [64, 128) 5300 |@@@@@@@@@@@@ | [128, 256) 768 |@ | [256, 512) 1429 |@@@ | [512, 1K) 741 |@ | [1K, 2K) 381 | | [2K, 4K) 82 | | [4K, 8K) 26 | | [8K, 16K) 9 | | [16K, 32K) 22 | | [32K, 64K) 4 | | [64K, 128K) 7 | | [128K, 256K) 1 | | [256K, 512K) 2 | |
  44. Profiling and Tracing, ConFoo 19, @ChristianHeimes • Initial release 2005

    • stap • Scripting Language for dynamic instrumentation • Kernel module • DynInst • eBPF (extended Berkeley Packet Filter) programs • additional features: • USDT / DTrace probes (Userland Statically Defined Tracing) • Cross-VM instrumentation • Prometheus SystemTap
  45. Profiling and Tracing, ConFoo 19, @ChristianHeimes USDT (dtrace / systemtap)

    $ stap -l 'process.provider("php").mark("*")' -c /usr/bin/php process("/usr/bin/php").provider("php").mark("compile__file__entry") process("/usr/bin/php").provider("php").mark("compile__file__return") process("/usr/bin/php").provider("php").mark("error") process("/usr/bin/php").provider("php").mark("exception__caught") process("/usr/bin/php").provider("php").mark("exception__thrown") process("/usr/bin/php").provider("php").mark("execute__entry") process("/usr/bin/php").provider("php").mark("execute__return") process("/usr/bin/php").provider("php").mark("function__entry") process("/usr/bin/php").provider("php").mark("function__return") process("/usr/bin/php").provider("php").mark("request__shutdown") process("/usr/bin/php").provider("php").mark("request__startup") $ stap -l 'process.provider("php").mark("*")' -c /usr/bin/php process("/usr/bin/php").provider("php").mark("compile__file__entry") process("/usr/bin/php").provider("php").mark("compile__file__return") process("/usr/bin/php").provider("php").mark("error") process("/usr/bin/php").provider("php").mark("exception__caught") process("/usr/bin/php").provider("php").mark("exception__thrown") process("/usr/bin/php").provider("php").mark("execute__entry") process("/usr/bin/php").provider("php").mark("execute__return") process("/usr/bin/php").provider("php").mark("function__entry") process("/usr/bin/php").provider("php").mark("function__return") process("/usr/bin/php").provider("php").mark("request__shutdown") process("/usr/bin/php").provider("php").mark("request__startup") $ stap -l 'process("/usr/lib64/libpython3.7m*").mark("*")' process("/usr/lib64/libpython3.7m.so.1.0").mark("function__entry") process("/usr/lib64/libpython3.7m.so.1.0").mark("function__return") process("/usr/lib64/libpython3.7m.so.1.0").mark("gc__done") process("/usr/lib64/libpython3.7m.so.1.0").mark("gc__start") process("/usr/lib64/libpython3.7m.so.1.0").mark("import__find__load__done") process("/usr/lib64/libpython3.7m.so.1.0").mark("import__find__load__start") process("/usr/lib64/libpython3.7m.so.1.0").mark("line") $ stap -l 'process("/usr/lib64/libpython3.7m*").mark("*")' process("/usr/lib64/libpython3.7m.so.1.0").mark("function__entry") process("/usr/lib64/libpython3.7m.so.1.0").mark("function__return") process("/usr/lib64/libpython3.7m.so.1.0").mark("gc__done") process("/usr/lib64/libpython3.7m.so.1.0").mark("gc__start") process("/usr/lib64/libpython3.7m.so.1.0").mark("import__find__load__done") process("/usr/lib64/libpython3.7m.so.1.0").mark("import__find__load__start") process("/usr/lib64/libpython3.7m.so.1.0").mark("line") $ stap -l 'process("/usr/lib/jvm/java*/jre/lib/amd64/server/libjvm.so").mark("*")' | wc -l 521 $ stap -l 'process("/usr/lib/jvm/java*/jre/lib/amd64/server/libjvm.so").mark("*")' | wc -l 521
  46. Profiling and Tracing, ConFoo 19, @ChristianHeimes Trace PHP probe process("php").mark("exception__thrown")

    { printf("Probe exception__thrown\n"); printf(" classname %s\n", user_string($arg1)); } probe process("php").mark("exception__thrown") { printf("Probe exception__thrown\n"); printf(" classname %s\n", user_string($arg1)); } $ sudo stap /usr/share/systemtap/examples/apps/php-trace.stp Pass 1: parsed user script and 496 library scripts ... Pass 2: analyzed script: 2 probes, 4 functions, 4 embeds, 2 globals ... Pass 3: translated to C into "/tmp/stapz4MP9b/stap_d6d27027af93310fa02967b0e5910963_5289_src.c" ... Pass 4: compiled C into "stap_d6d27027af93310fa02967b0e5910963_5289.ko" ... Pass 5: starting run. ERROR: Couldn't insert module '/tmp/stapz4MP9b/stap_d6d27027af93310fa02967b0e5910963_5289.ko': Operation not permitted $ dmesg [335808.816759] Lockdown: staprun: Loading of unsigned module is restricted; see man kernel_lockdown.7 $ sudo stap /usr/share/systemtap/examples/apps/php-trace.stp Pass 1: parsed user script and 496 library scripts ... Pass 2: analyzed script: 2 probes, 4 functions, 4 embeds, 2 globals ... Pass 3: translated to C into "/tmp/stapz4MP9b/stap_d6d27027af93310fa02967b0e5910963_5289_src.c" ... Pass 4: compiled C into "stap_d6d27027af93310fa02967b0e5910963_5289.ko" ... Pass 5: starting run. ERROR: Couldn't insert module '/tmp/stapz4MP9b/stap_d6d27027af93310fa02967b0e5910963_5289.ko': Operation not permitted $ dmesg [335808.816759] Lockdown: staprun: Loading of unsigned module is restricted; see man kernel_lockdown.7 $ php -S localhost:8080 $ php -S localhost:8080 $ sudo systemctl reboot --firmware-setup $ sudo systemctl reboot --firmware-setup
  47. Profiling and Tracing, ConFoo 19, @ChristianHeimes Trace PHP (2) Probe

    request__startup file .../confoo19/profiling/bolt-v3.6.5/public/index.php request_uri /_profiler/5deb7d?panel=bolt request_method GET Probe exception__thrown classname Bolt\Filesystem\Exception\FileNotFoundException ... Probe exception__thrown classname Symfony\Component\Intl\Exception\MethodNotImplementedException Probe error errormsg Using an instance of "Twig_SimpleFilter" for function "6" is deprecated since version 1.21. Use Twig_SimpleFunction instead. request_file .../confoo19/profiling/bolt-v3.6.5/vendor/twig/twig/lib/Twig/Environment.php lineno 1541 ... Probe exception__thrown classname Symfony\Component\Intl\Exception\MethodNotImplementedException Probe exception__caught classname Probe request__shutdown file .../confoo19/profiling/bolt-v3.6.5/public/index.php request_uri /_profiler/5deb7d?panel=bolt request_method GET Probe request__startup file .../confoo19/profiling/bolt-v3.6.5/public/index.php request_uri /_profiler/5deb7d?panel=bolt request_method GET Probe exception__thrown classname Bolt\Filesystem\Exception\FileNotFoundException ... Probe exception__thrown classname Symfony\Component\Intl\Exception\MethodNotImplementedException Probe error errormsg Using an instance of "Twig_SimpleFilter" for function "6" is deprecated since version 1.21. Use Twig_SimpleFunction instead. request_file .../confoo19/profiling/bolt-v3.6.5/vendor/twig/twig/lib/Twig/Environment.php lineno 1541 ... Probe exception__thrown classname Symfony\Component\Intl\Exception\MethodNotImplementedException Probe exception__caught classname Probe request__shutdown file .../confoo19/profiling/bolt-v3.6.5/public/index.php request_uri /_profiler/5deb7d?panel=bolt request_method GET
  48. Profiling and Tracing, ConFoo 19, @ChristianHeimes Trace Python imports global

    depths = 0; global timing probe process("python3").library("libpython3.7m.so.1.0").mark("import__find__load__start") { modname = user_string($arg1); now = local_clock_ns() timing[tid(), depths] = now printf("%*s* Importing '%s' ...\n", 2*depths, "", modname); depths++; } probe process("python3").library("libpython3.7m.so.1.0").mark("import__find__load__done") { modname = user_string($arg1); found = $arg2; depths--; now = local_clock_ns() dur = now - timing[tid(), depths] if (found) printf("%*s+ Imported '%s' in %ldus\n", 2*depths, "", modname, dur/1000); else printf("%*s- Failed '%s' in %ldus\n", 2*depths, "", modname, dur/1000); } global depths = 0; global timing probe process("python3").library("libpython3.7m.so.1.0").mark("import__find__load__start") { modname = user_string($arg1); now = local_clock_ns() timing[tid(), depths] = now printf("%*s* Importing '%s' ...\n", 2*depths, "", modname); depths++; } probe process("python3").library("libpython3.7m.so.1.0").mark("import__find__load__done") { modname = user_string($arg1); found = $arg2; depths--; now = local_clock_ns() dur = now - timing[tid(), depths] if (found) printf("%*s+ Imported '%s' in %ldus\n", 2*depths, "", modname, dur/1000); else printf("%*s- Failed '%s' in %ldus\n", 2*depths, "", modname, dur/1000); }
  49. Profiling and Tracing, ConFoo 19, @ChristianHeimes Trace Python imports $

    sudo stap import.stp -c "python3 -c pass" * Importing 'zipimport' ... + Imported 'zipimport' in 125us ... * Importing 'encodings' ... * Importing 'codecs' ... * Importing '_codecs' ... + Imported '_codecs' in 187us + Imported 'codecs' in 1273us * Importing 'encodings.aliases' ... + Imported 'encodings.aliases' in 836us + Imported 'encodings' in 3263us ... * Importing 'site' ... ... * Importing 'sitecustomize' ... - Failed 'sitecustomize' in 149us * Importing 'usercustomize' ... - Failed 'usercustomize' in 144us + Imported 'site' in 28946us $ sudo stap import.stp -c "python3 -c pass" * Importing 'zipimport' ... + Imported 'zipimport' in 125us ... * Importing 'encodings' ... * Importing 'codecs' ... * Importing '_codecs' ... + Imported '_codecs' in 187us + Imported 'codecs' in 1273us * Importing 'encodings.aliases' ... + Imported 'encodings.aliases' in 836us + Imported 'encodings' in 3263us ... * Importing 'site' ... ... * Importing 'sitecustomize' ... - Failed 'sitecustomize' in 149us * Importing 'usercustomize' ... - Failed 'usercustomize' in 144us + Imported 'site' in 28946us
  50. Profiling and Tracing, ConFoo 19, @ChristianHeimes ✔ extremely detailed information

    ✔ fast, efficient ✔ apps, system-wide, hardware events ✔ wide range from pre-build tools to custom code ✗ extremely detailed information ✗ learning curve ✗ turn your 64 core server into a Commodore C64 Verdict
  51. Profiling and Tracing, ConFoo 19, @ChristianHeimes • strace, bpftrace: Swiss

    Army Knife for simple tasks • bcc: pre-build tools • perf: benchmarking and hot-spot profiling • SystemTap: dynamic languages (Python) • ftrace: tracing on old Kernels • want to learn: LTTng, SystemTap In my humble opinion
  52. Profiling and Tracing, ConFoo 19, @ChristianHeimes • Brendan Gregg http://www.brendangregg.com/

    • eBPF • IOVisor Project https://www.iovisor.org/ • Sergey Klyaus: “Dynamic Tracing with DTrace & SystemTap” https://myaut.github.io/dtrace-stap-book/ • SystemTap beginners guide https://sourceware.org/systemtap/SystemTap_Beginners_Guide/ • PHP Flame Graphs with xdebug trace https://daniellockyer.com/php-flame-graphs/ • Slides: https://speakerdeck.com/tiran/ Resources