tests: [ TIMEOUT ] json-output.histogram-finegrain: ERROR in check_result: Extra data: line 4 column 1 (char 1658)

[vt-alt]

What reproduces the bug? Provide code if possible.

tests/runtime-tests.sh run.

[ RUN      ] json-output.histogram-finegrain
ERROR in check_result:  Extra data: line 4 column 1 (char 1658)
[  TIMEOUT ] json-output.histogram-finegrain
        Command: /usr/src/RPM/BUILD/bpftrace-0.20.1/x86_64-alt-linux/src/bpftrace -q -f json -e 'i:us:100 { @ = hist(@n++,3); if (@n > 1023) { delete(@n); exit(); }}'
        Timeout: 5
        Current output:

{"type": "hist", "data": {"@": [{"min": 0, "max": 0, "count": 1}, {"min": 1, "max": 1, "count": 1}, {"min": 2, "max": 2, "count": 1}, {"min": 3, "max": 3, "count": 1}, {"min": 4, "max": 4, "count": 1}, {"min": 5, "max": 5, "count": 1}, {"min": 6, "max": 6, "count": 1}, {"min": 7, "max": 7, "count": 1}, {"min": 8, "max": 8, "count": 1}, {"min": 9, "max": 9, "count": 1}, {"min": 10, "max": 10, "count": 1}, {"min": 11, "max": 11, "count": 1}, {"min": 12, "max": 12, "count": 1}, {"min": 13, "max": 13, "count": 1}, {"min": 14, "max": 14, "count": 1}, {"min": 15, "max": 15, "count": 1}, {"min": 16, "max": 17, "count": 2}, {"min": 18, "max": 19, "count": 2}, {"min": 20, "max": 21, "count": 2}, {"min": 22, "max": 23, "count": 2}, {"min": 24, "max": 25, "count": 2}, {"min": 26, "max": 27, "count": 2}, {"min": 28, "max": 29, "count": 2}, {"min": 30, "max": 31, "count": 2}, {"min": 32, "max": 35, "count": 4}, {"min": 36, "max": 39, "count": 4}, {"min": 40, "max": 43, "count": 4}, {"min": 44, "max": 47, "count": 4}, {"min": 48, "max": 51, "count": 4}, {"min": 52, "max": 55, "count": 4}, {"min": 56, "max": 59, "count": 4}, {"min": 60, "max": 63, "count": 4}, {"min": 64, "max": 71, "count": 8}, {"min": 72, "max": 79, "count": 8}, {"min": 80, "max": 87, "count": 8}, {"min": 88, "max": 95, "count": 8}, {"min": 96, "max": 103, "count": 8}, {"min": 104, "max": 111, "count": 8}, {"min": 112, "max": 119, "count": 8}, {"min": 120, "max": 127, "count": 8}, {"min": 128, "max": 143, "count": 16}, {"min": 144, "max": 159, "count": 16}, {"min": 160, "max": 175, "count": 16}, {"min": 176, "max": 191, "count": 16}, {"min": 192, "max": 207, "count": 10}]}}
{"type": "map", "data": {"@n": 202}}

bpftrace --info output

System
  OS: Linux 6.6.20-un-def-alt1 #1 SMP PREEMPT_DYNAMIC Sat Mar  2 21:14:32 UTC 2024
  Arch: x86_64

Build
  version: v0.20.1
  LLVM: 17.0.6
  unsafe probe: yes
  bfd: yes
  libdw (DWARF support): yes

Kernel helpers
  probe_read: yes
  probe_read_str: yes
  probe_read_user: yes
  probe_read_user_str: yes
  probe_read_kernel: yes
  probe_read_kernel_str: yes
  get_current_cgroup_id: yes
  send_signal: yes
  override_return: yes
  get_boot_ns: yes
  dpath: yes
  skboutput: yes
  get_tai_ns: yes
  get_func_ip: yes
  jiffies64: yes

Kernel features
  Instruction limit: 1000000
  Loop support: yes
  btf: yes
  module btf: yes
  map batch: yes
  uprobe refcount (depends on Build:bcc bpf_attach_uprobe refcount): yes

Map types
  hash: yes
  percpu hash: yes
  array: yes
  percpu array: yes
  stack_trace: yes
  perf_event_array: yes
  ringbuf: yes

Probe types
  kprobe: yes
  tracepoint: yes
  perf_event: yes
  kfunc: yes
  kprobe_multi: no
  uprobe_multi: yes
  raw_tp_special: yes
  iter: yes

[vt-alt]

I tried build on other box. This reliably reproduces on the box with 20 threads Intel Core CPU but it does not reproduce on the box with AMD Zen. 🤷

[vt-alt]

Well it turned a bit more obscure. If I increase the test timeout value from 5 to 15 it still reports TIMEOUT error but tests finish without failure (exit code 0) OR reports with FAILED:

20:36:42 [ RUN      ] json-output.histogram-finegrain
20:36:47 ERROR in check_result:  Extra data: line 4 column 1 (char 2400)
20:36:47 [  FAILED  ] json-output.histogram-finegrain
20:36:47        Command: /usr/src/RPM/BUILD/bpftrace-0.20.1/x86_64-alt-linux/src/bpftrace -q -f json -e 'i:us:100 { @ = hist(@n++,3); if (@n > 1023) { delete(@n); exit(); }}'
20:36:47        Expected JSON:
20:36:47 {
20:36:47   "type": "hist",
20:36:47   "data": {
20:36:47     "@": [
20:36:47       {
20:36:47         "min": 0,
20:36:47         "max": 0,
20:36:47         "count": 1
20:36:47       },
...
20:36:47       {
20:36:47         "min": 960,
20:36:47         "max": 1023,
20:36:47         "count": 64
20:36:47       }
20:36:47     ]
20:36:47   }
20:36:47 }
20:36:47        Found:
20:36:47 Could not parse JSON: Extra data: line 4 column 1 (char 2400)

This test seems highly unreliable so I will just remove it from our test run.

[viktormalik]

The error is caused by #2902. There's a race condition in that test - if @n is not deleted before bpftrace finishes, it is printed and we get a JSON document with two top-level objects.