Failure "string too long for FTF trace...

[JayKickliter]

I'm running magic-trace on a heavily parallelized rust program:

$ magic-trace attach -multi-thread  -pid <PID>
[ Attached. Press Ctrl-C to stop recording. ]
^C[ Got signal, detaching... ]
[ Snapshot taken. ]
[ perf record: Woken up 68 times to write data ]
[ perf record: Captured and wrote 428.635 MB /tmp/magic_trace.tmp.82fe48/perf.data ]
[ Finished recording. ]
[ Decoding, this takes a while... ]
(monitor.ml.Error
 (Failure "string too long for FTF trace: 805614 is over the limit of 32kb")
 ("Raised at Stdlib.failwith in file \"stdlib.ml\", line 29, characters 17-33"
  "Called from Tracing_zero__Writer.set_string_slot in file \"vendor/tracing/zero/writer.ml\", line 156, characters 7-89"
  "Called from Tracing_zero__Writer.intern_string in file \"vendor/tracing/zero/writer.ml\", line 180, characters 2-32"
  "Called from Base__Hashtbl.find_or_add.(fun) in file \"src/hashtbl.ml\", line 416, characters 20-30"
  "Called from Tracing__Trace.allocate_pid in file \"vendor/tracing/src/trace.ml\", line 70, characters 57-86"
  "Called from Magic_trace_lib__Trace_writer.allocate_pid in file \"src/trace_writer.ml\" (inlined), line 160, characters 2-22"
  "Called from Magic_trace_lib__Trace_writer.create_thread in file \"src/trace_writer.ml\", line 527, characters 23-43"
  "Called from Base__Hashtbl.find_or_add.(fun) in file \"src/hashtbl.ml\", line 416, characters 20-30"
  "Called from Base__Hashtbl.find_or_add in file \"src/hashtbl.ml\" (inlined), line 409, characters 2-211"
  "Called from Magic_trace_lib__Trace_writer.write_event in file \"src/trace_writer.ml\", line 946, characters 4-87"
  "Called from Async_kernel__Pipe.iter_without_pushback.(fun).loop in file \"src/pipe.ml\", line 894, characters 10-13"
  "Called from Async_kernel__Job_queue.run_jobs in file \"src/job_queue.ml\", line 167, characters 6-47"
  "Caught by monitor Monitor.protect"))

perf

$ perf --version
perf version 5.15.111

CPU

$ cat /proc/cpuinfo
processor	: 0
vendor_id	: GenuineIntel
cpu family	: 6
model		: 106
model name	: Intel(R) Xeon(R) Gold 5318Y CPU @ 2.10GHz
stepping	: 6
microcode	: 0xd0003a5
cpu MHz		: 802.835
cache size	: 36864 KB
physical id	: 0
siblings	: 48
core id		: 0
cpu cores	: 24
apicid		: 0
initial apicid	: 0
fpu		: yes
fpu_exception	: yes
cpuid level	: 27
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch cpuid_fault epb cat_l3 invpcid_single intel_ppin ssbd mba ibrs ibpb stibp ibrs_enhanced tpr_shadow vnmi flexpriority ept vpid ept_ad fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid cqm rdt_a avx512f avx512dq rdseed adx smap avx512ifma clflushopt clwb intel_pt avx512cd sha_ni avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local split_lock_detect wbnoinvd dtherm ida arat pln pts avx512vbmi umip pku ospke avx512_vbmi2 gfni vaes vpclmulqdq avx512_vnni avx512_bitalg tme avx512_vpopcntdq la57 rdpid fsrm md_clear pconfig flush_l1d arch_capabilities
vmx flags	: vnmi preemption_timer posted_intr invvpid ept_x_only ept_ad ept_1gb flexpriority apicv tsc_offset vtpr mtf vapic ept vpid unrestricted_guest vapic_reg vid ple shadow_vmcs pml ept_mode_based_exec tsc_scaling
bugs		: spectre_v1 spectre_v2 spec_store_bypass swapgs mmio_stale_data eibrs_pbrsb
bogomips	: 4200.00
clflush size	: 64
cache_alignment	: 64
address sizes	: 46 bits physical, 57 bits virtual
power management:

^ repeats 96 times

[Xyene]

It sounds like your process has a very (805614-byte) commandline as per /proc/${tid}/cmdline, and we're running into the trace file format interned string limit of 32000 bytes.

magic-trace/src/trace_writer.ml

Lines 517 to 527 in 79a3bba

	let name =
	match thread.pid with
	| None -> default_name
	| Some pid ->
	(match Process_info.cmdline_of_pid pid with
	| None -> default_name
	| Some cmdline ->
	let concat_cmdline = String.concat ~sep:" " cmdline in
	[%string "%{concat_cmdline} %{default_name}"])
	in
	let track_group_id = allocate_pid t ~name in

magic-trace/vendor/tracing/src/trace.ml

Lines 68 to 72 in 79a3bba

	let allocate_pid t ~name =
	t.koid_counter <- t.koid_counter + 1;
	TW.set_process_name t.writer ~pid:t.koid_counter ~name:(intern_string_cached t name);
	t.koid_counter
	;;

magic-trace/vendor/tracing/zero/writer.ml

Lines 152 to 163 in 79a3bba

	let set_string_slot t ~string_id s =
	let str_len = String.length s in
	(* maximum string length defined in spec, somewhat less than 2**15 *)
	if str_len >= 32000
	then failwithf "string too long for FTF trace: %i is over the limit of 32kb" str_len ();
	(* String record *)
	let rtype = 2 in
	let rsize = 1 + round_words_for str_len in
	ensure_capacity t (rsize * 8);
	write_int64 t (rtype lor (rsize lsl 4) lor (string_id lsl 16) lor (str_len lsl 32));
	write_string_stream t s
	;;

We should fix this by truncating the command line if it's too long, but in the interim you may be able to work around this by either patching magic-trace to not display commandlines, or by modifying your application to have shorter commandlines.

[Xyene]

Could you please give #290 a try? You can get a prebuilt binary from the GitHub action run: https://github.com/janestreet/magic-trace/actions/runs/7468274830/job/20323383802

[JayKickliter]

#290 fixed it for me. Thank you!