Bug "(event_name cpu-clock)"
shoffmeister opened this issue · 3 comments
shoffmeister commented
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 commented
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 commented
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 commented
Just realised that VMs are mostly not supported. 😢