Bug "(event_name cpu-clock)"

[shoffmeister]

Running

./magic-trace run glxinfo64 -- -B

I get

Intel PT support not found. magic-trace will continue and use sampling instead.
Warning: [-callgraph-mode] is defaulting to [Dwarf] which may have high overhead and decoding time. For more info: https://magic-trace.org/w/b
[ Snapshot taken. ]
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.127 MB /tmp/magic_trace.tmp.72c3de/perf.data (12 samples) ]
[ Finished recording. ]
[ Decoding, this takes a while... ]
Warning: Debug info is unavailable, so filenames and line numbers will not be available in the trace.
See https://github.com/janestreet/magic-trace/wiki/Compiling-code-for-maximum-compatibility-with-magic-trace for more info.
(monitor.ml.Error
 ("BUG: exception raised while parsing perf output. Please report this to https://github.com/janestreet/magic-trace/issues/"
  (exn
   ("Unexpected event type when parsing perf output" (event_name cpu-clock)))
  (perf_output
   ("   5488/5488     1539.632720267:     100000 cpu-clock:uH: "
    "\t    7fb9b09ba370 [unknown] (/usr/lib64/libexpat.so.1.8.10)"
    "\t    7fb9b09bd38c [unknown] (/usr/lib64/libexpat.so.1.8.10)"
    "\t    7fb9b09bd4e3 [unknown] (/usr/lib64/libexpat.so.1.8.10)"
    "\t    7fb9b09beb7c [unknown] (/usr/lib64/libexpat.so.1.8.10)"
    "\t    7fb9b09c332c [unknown] (/usr/lib64/libexpat.so.1.8.10)"
    "\t    7fb9b09c46c5 [unknown] (/usr/lib64/libexpat.so.1.8.10)"
    "\t    7fb9b09c6b2f XML_ParseBuffer+0x7f (/usr/lib64/libexpat.so.1.8.10)"
    "\t    7fb9b0abca85 [unknown] (/usr/lib64/libGLX_mesa.so.0.0.0)"
    "\t    7fb9b0abe63a [unknown] (/usr/lib64/libGLX_mesa.so.0.0.0)"
    "\t    7fb9b0ab870a [unknown] (/usr/lib64/libGLX_mesa.so.0.0.0)"
    "\t    7fb9b0aaceae [unknown] (/usr/lib64/libGLX_mesa.so.0.0.0)"
    "\t    7fb9b0a9e6e8 [unknown] (/usr/lib64/libGLX_mesa.so.0.0.0)"
    "\t    7fb9b0a9a4c8 [unknown] (/usr/lib64/libGLX_mesa.so.0.0.0)"
    "\t    56458a6b7894 [unknown] ([unknown])"
    "\t    7fb9b0c35149 __libc_start_call_main+0x79 (/usr/lib64/libc.so.6)"
    "\t    7fb9b0c3520a __libc_start_main@@GLIBC_2.34+0x8a (/usr/lib64/libc.so.6)"
    "\t    56458a6b8354 [unknown] ([unknown])")))
 ("Raised at Base__Error.raise in file \"src/error.ml\" (inlined), line 9, characters 14-30"
  "Called from Base__Error.raise_s in file \"src/error.ml\", line 10, characters 19-40"
  "Called from Async_kernel__Pipe.map.(fun) in file \"src/pipe.ml\", line 1042, characters 65-70"
  "Called from Async_kernel__Job_queue.run_jobs in file \"src/job_queue.ml\", line 167, characters 6-47"
  "Caught by monitor Monitor.protect"))

This is on

uname -a
Linux fedora 6.5.9-300.fc39.x86_64 #1 SMP PREEMPT_DYNAMIC Wed Oct 25 21:39:20 UTC 2023 x86_64 GNU/Linux

perf --version
perf version 6.5.4

cat /proc/cpuinfo 
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 6
model           : 141
model name      : 11th Gen Intel(R) Core(TM) i7-11800H @ 2.30GHz

which is all Fedora Linux 39 (on VMware Workstation 17.5, running on Windows 11 Professional - which should not matter all that much for the problem I am trying to investigate)

So, this is a bit of a bleeding edge, I guess...

[shoffmeister]

FWIW, I am trying to debug why glxinfo64 -B on this specific virtual machine, under X11, has

1699116495.637695 glXChooseVisual(0x55665a044da0, 0, 0x556658fd2020, 0)                                    = 0x55665a065110 <1.658923>

taking 1.6 seconds on launch of every single X11 application.

[j1ah0ng]

I am also running into this issue with the following log output:

❯ ./magic-trace attach -pid 1284576
Intel PT support not found. magic-trace will continue and use sampling instead.
Warning: [-callgraph-mode] is defaulting to [Dwarf] which may have high overhead and decoding time. For more info: https://magic-trace.org/w/b
[ Attached. Press Ctrl-C to stop recording. ]
^C[ Got signal, detaching... ]
[ Snapshot taken. ]
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.686 MB /tmp/magic_trace.tmp.5d3ea6/perf.data (62 samples) ]
[ Finished recording. ]
[ Decoding, this takes a while... ]
Warning: Debug info is unavailable, so filenames and line numbers will not be available in the trace.
See https://github.com/janestreet/magic-trace/wiki/Compiling-code-for-maximum-compatibility-with-magic-trace for more info.
(monitor.ml.Error
 ("BUG: exception raised while parsing perf output. Please report this to https://github.com/janestreet/magic-trace/issues/"
  (exn
   ("Unexpected event type when parsing perf output" (event_name cpu-clock)))
  (perf_output
   ("1284576/1284576 180054.771181230:     100000 cpu-clock:uH: "
    "\t    5555560adc70 duckdb::MinValue<unsigned long>+0x0 (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    555556bd59ac duckdb::StringUtil::CILessThan+0x3c (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    5555569a6380 duckdb::CaseInsensitiveStringCompare::operator()+0x20 (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    5555569a66d3 std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, duckdb::unique_ptr<duckdb::CatalogEntry, std::default_delete<duckdb::CatalogEntry>, true> >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, duckdb::unique_ptr<duckdb::CatalogEntry, std::default_delete<duckdb::CatalogEntry>, true> > >, duckdb::CaseInsensitiveStringCompare, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, duckdb::unique_ptr<duckdb::CatalogEntry, std::default_delete<duckdb::CatalogEntry>, true> > > >::_M_get_insert_unique_pos+0x73 (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    5555569a64d2 std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, duckdb::unique_ptr<duckdb::CatalogEntry, std::default_delete<duckdb::CatalogEntry>, true> >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, duckdb::unique_ptr<duckdb::CatalogEntry, std::default_delete<duckdb::CatalogEntry>, true> > >, duckdb::CaseInsensitiveStringCompare, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, duckdb::unique_ptr<duckdb::CatalogEntry, std::default_delete<duckdb::CatalogEntry>, true> > > >::_M_emplace_unique<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, duckdb::unique_ptr<duckdb::CatalogEntry, std::default_delete<duckdb::CatalogEntry>, true> > >+0x52 (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    555556995b7f std::map<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, duckdb::unique_ptr<duckdb::CatalogEntry, std::default_delete<duckdb::CatalogEntry>, true>, duckdb::CaseInsensitiveStringCompare, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, duckdb::unique_ptr<duckdb::CatalogEntry, std::default_delete<duckdb::CatalogEntry>, true> > > >::insert<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, duckdb::unique_ptr<duckdb::CatalogEntry, std::default_delete<duckdb::CatalogEntry>, true> > >+0x2f (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    55555697f7ef duckdb::CatalogEntryMap::AddEntry+0x1ef (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    5555569802cb duckdb::CatalogSet::StartChain+0x1eb (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    555556980fca duckdb::CatalogSet::CreateEntryInternal+0xba (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    555556981364 duckdb::CatalogSet::CreateEntry+0x1d4 (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    55555693f53c duckdb::DuckSchemaEntry::AddEntryInternal+0x43c (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    555556940432 duckdb::DuckSchemaEntry::AddEntry+0xd2 (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    5555569402f4 duckdb::DuckSchemaEntry::CreateFunction+0x5f4 (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    555556977611 duckdb::Catalog::CreateFunction+0x61 (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    55555697759b duckdb::Catalog::CreateFunction+0xdb (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    555556fb5ac9 duckdb::ExtensionUtil::RegisterFunction+0x109 (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\t    555557bd2d9b duckdb::ParquetExtension::Load+0x2cb (/home/jiahong.long/.cache/bazel/_bazel_jiahong.long/a191a06ed2c8ea6a71c3b563e1372302/execroot/cruise_ws/bazel-out/k8-dbg/bin/ros/src/sim_analysis/benchmarking/cpp_benchmark)"
    "\tffffffffffffffff [unknown] ([unknown])")))
 ("Raised at Base__Error.raise in file \"src/error.ml\" (inlined), line 9, characters 14-30"
  "Called from Base__Error.raise_s in file \"src/error.ml\", line 10, characters 19-40"
  "Called from Async_kernel__Pipe.map.(fun) in file \"src/pipe.ml\", line 1066, characters 65-70"
  "Called from Async_kernel__Job_queue.run_jobs in file \"src/job_queue.ml\", line 180, characters 6-47"
  "Caught by monitor Monitor.protect"))

with my process-under-test launched via bazel run -c dbg. The binary is statically linked against DuckDB v0.10.1 - I'm trying to obtain a call tree to debug a SIGABRT when creating a new table in DuckDB with a nested struct, and using the duckdb::Appender API to insert said nested struct.

Platform details (bog-standard GCP worker):

❯ uname -a
Linux cs-zpezm92n-medium-gpu-homedir-701320 5.15.0-1058-gcp #66~20.04.1-Ubuntu SMP Tue Apr 16 06:42:32 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux
❯ perf --version
perf version 5.15.148
❯ lscpu
Architecture:                       x86_64
CPU op-mode(s):                     32-bit, 64-bit
Byte Order:                         Little Endian
Address sizes:                      46 bits physical, 48 bits virtual
CPU(s):                             32
On-line CPU(s) list:                0-31
Thread(s) per core:                 2
Core(s) per socket:                 16
Socket(s):                          1
NUMA node(s):                       1
Vendor ID:                          GenuineIntel
CPU family:                         6
Model:                              79
Model name:                         Intel(R) Xeon(R) CPU @ 2.20GHz
Stepping:                           0
CPU MHz:                            2199.998
BogoMIPS:                           4399.99
Virtualization:                     VT-x
Hypervisor vendor:                  KVM
Virtualization type:                full
L1d cache:                          512 KiB
L1i cache:                          512 KiB
L2 cache:                           4 MiB
L3 cache:                           55 MiB
NUMA node0 CPU(s):                  0-31
Vulnerability Gather data sampling: Not affected
Vulnerability Itlb multihit:        Not affected
Vulnerability L1tf:                 Mitigation; PTE Inversion; VMX flush not necessary
                                    , SMT vulnerable
Vulnerability Mds:                  Mitigation; Clear CPU buffers; SMT Host state unkn
                                    own
Vulnerability Meltdown:             Mitigation; PTI
Vulnerability Mmio stale data:      Vulnerable: Clear CPU buffers attempted, no microc
                                    ode; SMT Host state unknown
Vulnerability Retbleed:             Mitigation; IBRS
Vulnerability Spec rstack overflow: Not affected
Vulnerability Spec store bypass:    Mitigation; Speculative Store Bypass disabled via 
                                    prctl and seccomp
Vulnerability Spectre v1:           Mitigation; usercopy/swapgs barriers and __user po
                                    inter sanitization
Vulnerability Spectre v2:           Mitigation; IBRS, IBPB conditional, STIBP conditio
                                    nal, RSB filling, PBRSB-eIBRS Not affected
Vulnerability Srbds:                Not affected
Vulnerability Tsx async abort:      Mitigation; Clear CPU buffers; SMT Host state unkn
                                    own
Flags:                              fpu vme de pse tsc msr pae mce cx8 apic sep mtrr p
                                    ge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss
                                     ht syscall nx pdpe1gb rdtscp lm constant_tsc rep_
                                    good nopl xtopology nonstop_tsc cpuid tsc_known_fr
                                    eq pni pclmulqdq vmx ssse3 fma cx16 pcid sse4_1 ss
                                    e4_2 x2apic movbe popcnt aes xsave avx f16c rdrand
                                     hypervisor lahf_lm abm 3dnowprefetch invpcid_sing
                                    le pti ssbd ibrs ibpb stibp tpr_shadow vnmi flexpr
                                    iority ept vpid ept_ad fsgsbase tsc_adjust bmi1 hl
                                    e avx2 smep bmi2 erms invpcid rtm rdseed adx smap 
                                    xsaveopt arat md_clear arch_capabilities

[j1ah0ng]

Just realised that VMs are mostly not supported. 😢