Hi, Sorry to create this duplicate message, the previous one was not formatted as plain text ...
With recent versions of the kernel, ftrace seems to experience some latencies when writing events filter files on a real time kernel. Latencies experienced add a extra minute of runtime with trace-cmd compare to a regular execution and sometimes `trace-cmd` just hangs for multiples minutes. The bug has been tested and reproduced with these version of the kernel (all with real time enable) : 6.12.19, 6.14-rc7, 6.15 and current upstream. The bug has also been reproduced on two machines, both running Ubuntu 24.04 with an upstream kernel, one running with an INTEL(R) XEON(R) GOLD 5512U, the other a Intel(R) Xeon(R) E-2278GE. The bug also appears is virtualised environments (KVM/QEMU). I have run `git-bisect` between v6.12 and v6.15, the faulty commit seems to be this one : a363d27cdbc2bc2d1899b5a1520b64e3590fcd9a To reproduce the bug I used this script : ``` while read file; do echo "0" > $file done ``` And ran it like this : ``` sudo time ./reproduce.sh < events.txt ``` When measuring execution time with `/usr/bin/time`, I have these results : Non RT kernel v6.15 : ``` 0.06user 0.02system 0:08.77elapsed 1%CPU (0avgtext+0avgdata 22928maxresident)k 2016inputs+0outputs (9major+8835minor)pagefaults 0swaps ``` RT kernel v6.15 : ``` 0.00user 0.00system 1:06.96elapsed 0%CPU (0avgtext+0avgdata 6888maxresident)k 0inputs+0outputs (0major+595minor)pagefaults 0swaps ``` RT kernel on a363d27cdbc2bc2d1899b5a1520b64e3590fcd9a : ``` 0.00user 0.00system 0:43.21elapsed 0%CPU (0avgtext+0avgdata 6760maxresident)k 0inputs+0outputs (0major+596minor)pagefaults 0swaps ``` RT kernel on 4aadde89d81fbf4cf3105a61dbc48888b819ecfb : ``` 0.00user 0.00system 0:01.25elapsed 0%CPU (0avgtext+0avgdata 6828maxresident)k 0inputs+0outputs (0major+602minor)pagefaults 0swaps ``` Problematic files were identified with running the following command : `sudo strace -tt trace-cmd record -p function sleep 1`. Here is a extract of the output produced by strace (on v6.15) : ``` ... 07:56:34.868273 openat(AT_FDCWD, "/sys/kernel/tracing/events/osnoise/filter", O_WRONLY) = 4 07:56:34.868401 write(4, "0", 1) = 1 07:56:35.485148 close(4) = 0 07:56:35.485251 openat(AT_FDCWD, "/sys/kernel/tracing/events/page_isolation/filter", O_WRONLY) = 4 07:56:35.485375 write(4, "0", 1) = 1 07:56:36.397172 close(4) = 0 07:56:36.397328 openat(AT_FDCWD, "/sys/kernel/tracing/events/page_pool/filter", O_WRONLY) = 4 07:56:36.397465 write(4, "0", 1) = 1 07:56:36.786157 close(4) = 0 07:56:36.786256 openat(AT_FDCWD, "/sys/kernel/tracing/events/pagemap/filter", O_WRONLY) = 4 07:56:36.786379 write(4, "0", 1) = 1 07:56:37.446188 close(4) = 0 07:56:37.446286 openat(AT_FDCWD, "/sys/kernel/tracing/events/percpu/filter", O_WRONLY) = 4 07:56:37.446403 write(4, "0", 1) = 1 07:56:37.738142 close(4) = 0 ... ``` If you have an idea on how to fix this issue, I am very grateful. -- Julien Flot Siemens AG [www.siemens.com](https://www.siemens.com) Appendix Faulty commit message : ``` commit a363d27cdbc2bc2d1899b5a1520b64e3590fcd9a Author: Mathieu Desnoyers <[mathieu.desnoy...@efficios.com](mailto:mathieu.desnoy...@efficios.com )> Date: Tue Oct 8 21:07:15 2024 -0400 fix tracing: Allow system call tracepoints to handle page faults Use Tasks Trace RCU to protect iteration of system call enter/exit tracepoint probes to allow those probes to handle page faults. In preparation for this change, all tracers registering to system call enter/exit tracepoints should expect those to be called with preemption enabled. This allows tracers to fault-in userspace system call arguments such as path strings within their probe callbacks. Cc: Michael Jeanson <[mjean...@efficios.com](mailto:mjean...@efficios.com)> Cc: Masami Hiramatsu <[mhira...@kernel.org](mailto:mhira...@kernel.org)> Cc: Peter Zijlstra <[pet...@infradea.org](mailto:pet...@infradea.org)> Cc: Alexei Starovoitov <[a...@kernel.org](mailto:a...@kernel.org)> Cc: Yonghong Song <[y...@fb.com](mailto:y...@fb.com)> Cc: Paul E. McKenney <[paul...@kernel.org](mailto:paul...@kernel.org)> Cc: Ingo Molnar <[mi...@redhat.com](mailto:mi...@redhat.com)> Cc: Arnaldo Carvalho de Melo <[a...@kernel.org](mailto:a...@kernel.org)> Cc: Mark Rutland <[mark.rutl...@arm.com](mailto:mark.rutl...@arm.com)> Cc: Alexander Shishkin <[alexander.shish...@linux.intel.com](mailto:alexander.shish...@linux.intel.com )> Cc: Namhyung Kim <[namhy...@kernel.org](mailto:namhy...@kernel.org)> Cc: Andrii Nakryiko <[andrii.nakry...@gmail.com](mailto:andrii.nakry...@gmail.com)> Cc: [b...@vger.kernel.org](mailto:b...@vger.kernel.org) Cc: Joel Fernandes <[j...@joelfernandes.org](mailto:j...@joelfernandes.org)> Link: [https://lore.kernel.org/20241009010718.2050182-6-mathieu.desnoy...@efficios.com](https://lore.kernel.org/20241009010718.2050182-6-mathieu.desnoy...@efficios.com) Signed-off-by: Mathieu Desnoyers <[mathieu.desnoy...@efficios.com](mailto:mathieu.desnoy...@efficios.com )> Signed-off-by: Steven Rostedt (Google) <[rost...@goodmis.org](mailto:rost...@goodmis.org)> include/linux/tracepoint.h | 18 ++++++++++++++++-- init/Kconfig | 1 + 2 files changed, 17 insertions(+), 2 deletions(-) ``` List of files identified as problematic (on v6.15) : ``` /sys/kernel/tracing/events/alarmtimer/filter /sys/kernel/tracing/events/amd_cpu/filter /sys/kernel/tracing/events/avc/filter /sys/kernel/tracing/events/block/filter /sys/kernel/tracing/events/bpf_test_run/filter /sys/kernel/tracing/events/bpf_trace/filter /sys/kernel/tracing/events/bridge/filter /sys/kernel/tracing/events/btrfs/filter /sys/kernel/tracing/events/capability/filter /sys/kernel/tracing/events/cfg80211/filter /sys/kernel/tracing/events/cgroup/filter /sys/kernel/tracing/events/clk/filter /sys/kernel/tracing/events/compaction/filter /sys/kernel/tracing/events/context_tracking/filter /sys/kernel/tracing/events/cpuhp/filter /sys/kernel/tracing/events/cros_ec/filter /sys/kernel/tracing/events/csd/filter /sys/kernel/tracing/events/cxl/filter /sys/kernel/tracing/events/dev/filter /sys/kernel/tracing/events/devfreq/filter /sys/kernel/tracing/events/devlink/filter /sys/kernel/tracing/events/dma/filter /sys/kernel/tracing/events/dma_fence/filter /sys/kernel/tracing/events/drm/filter /sys/kernel/tracing/events/error_report/filter /sys/kernel/tracing/events/exceptions/filter /sys/kernel/tracing/events/ext4/filter /sys/kernel/tracing/events/fib/filter /sys/kernel/tracing/events/fib6/filter /sys/kernel/tracing/events/filelock/filter /sys/kernel/tracing/events/filemap/filter /sys/kernel/tracing/events/fs_dax/filter /sys/kernel/tracing/events/fuse/filter /sys/kernel/tracing/events/gpio/filter /sys/kernel/tracing/events/handshake/filter /sys/kernel/tracing/events/hugetlbfs/filter /sys/kernel/tracing/events/hwmon/filter /sys/kernel/tracing/events/hyperv/filter /sys/kernel/tracing/events/i2c/filter /sys/kernel/tracing/events/icmp/filter /sys/kernel/tracing/events/initcall/filter /sys/kernel/tracing/events/intel_ifs/filter /sys/kernel/tracing/events/intel_iommu/filter /sys/kernel/tracing/events/interconnect/filter /sys/kernel/tracing/events/io_uring/filter /sys/kernel/tracing/events/iocost/filter /sys/kernel/tracing/events/iomap/filter /sys/kernel/tracing/events/iommu/filter /sys/kernel/tracing/events/ipi/filter /sys/kernel/tracing/events/irq/filter /sys/kernel/tracing/events/irq_matrix/filter /sys/kernel/tracing/events/irq_vectors/filter /sys/kernel/tracing/events/jbd2/filter /sys/kernel/tracing/events/kmem/filter /sys/kernel/tracing/events/kvm/filter /sys/kernel/tracing/events/kvmmmu/filter /sys/kernel/tracing/events/libata/filter /sys/kernel/tracing/events/lock/filter /sys/kernel/tracing/events/maple_tree/filter /sys/kernel/tracing/events/mce/filter /sys/kernel/tracing/events/mctp/filter /sys/kernel/tracing/events/mdio/filter /sys/kernel/tracing/events/mei/filter /sys/kernel/tracing/events/memcg/filter /sys/kernel/tracing/events/migrate/filter /sys/kernel/tracing/events/mmap/filter /sys/kernel/tracing/events/mmap_lock/filter /sys/kernel/tracing/events/mmc/filter /sys/kernel/tracing/events/module/filter /sys/kernel/tracing/events/mptcp/filter /sys/kernel/tracing/events/msr/filter /sys/kernel/tracing/events/napi/filter /sys/kernel/tracing/events/neigh/filter /sys/kernel/tracing/events/net/filter /sys/kernel/tracing/events/netlink/filter /sys/kernel/tracing/events/nmi/filter /sys/kernel/tracing/events/notifier/filter /sys/kernel/tracing/events/oom/filter /sys/kernel/tracing/events/osnoise/filter /sys/kernel/tracing/events/page_isolation/filter /sys/kernel/tracing/events/page_pool/filter /sys/kernel/tracing/events/pagemap/filter /sys/kernel/tracing/events/percpu/filter /sys/kernel/tracing/events/power/filter /sys/kernel/tracing/events/printk/filter /sys/kernel/tracing/events/pwm/filter /sys/kernel/tracing/events/qdisc/filter /sys/kernel/tracing/events/qrtr/filter /sys/kernel/tracing/events/ras/filter /sys/kernel/tracing/events/raw_syscalls/filter /sys/kernel/tracing/events/rcu/filter /sys/kernel/tracing/events/regmap/filter /sys/kernel/tracing/events/regulator/filter /sys/kernel/tracing/events/resctrl/filter /sys/kernel/tracing/events/rpm/filter /sys/kernel/tracing/events/rseq/filter /sys/kernel/tracing/events/rtc/filter /sys/kernel/tracing/events/rv/filter /sys/kernel/tracing/events/sched/filter /sys/kernel/tracing/events/scsi/filter /sys/kernel/tracing/events/sd/filter /sys/kernel/tracing/events/signal/filter /sys/kernel/tracing/events/skb/filter /sys/kernel/tracing/events/smbus/filter /sys/kernel/tracing/events/sock/filter /sys/kernel/tracing/events/spi/filter /sys/kernel/tracing/events/swiotlb/filter /sys/kernel/tracing/events/sync_trace/filter /sys/kernel/tracing/events/syscalls/filter /sys/kernel/tracing/events/task/filter /sys/kernel/tracing/events/tcp/filter /sys/kernel/tracing/events/thermal/filter /sys/kernel/tracing/events/thermal_power_allocator/filter /sys/kernel/tracing/events/timer/filter /sys/kernel/tracing/events/timer_migration/filter /sys/kernel/tracing/events/timestamp/filter /sys/kernel/tracing/events/tlb/filter /sys/kernel/tracing/events/udp/filter /sys/kernel/tracing/events/vmalloc/filter /sys/kernel/tracing/events/vmscan/filter /sys/kernel/tracing/events/vsock/filter /sys/kernel/tracing/events/vsyscall/filter /sys/kernel/tracing/events/watchdog/filter /sys/kernel/tracing/events/wbt/filter /sys/kernel/tracing/events/workqueue/filter /sys/kernel/tracing/events/writeback/filter /sys/kernel/tracing/events/x86_fpu/filter /sys/kernel/tracing/events/xdp/filter /sys/kernel/tracing/events/xen/filter /sys/kernel/tracing/events/xhci-hcd/filter ```
