broken ksnoop tool #4746

dubeyabhishek · 2023-09-21T11:19:51Z

Not getting any output for ksnoop tool. Tried multiple functions in argument, no error/failed message is appearing.
Example run below:

./ksnoop trace "vma_merge(mm)" -d

Debug: Parsing trace 'vma_merge(mm)'
Debug: got func 'vma_merge', args 'mm'
Debug: vma_merge = <ip c00000000046df10, mod vmlinux>
Debug: getting BTF for vmlinux
libbpf: loading kernel BTF '/sys/kernel/btf/vmlinux': 0
Debug: arg #1: <name 'vmi', type id '9646'>
Debug: arg #2: <name 'mm', type id '415'>
Debug: arg #3: <name 'prev', type id '496'>
Debug: arg #4: <name 'addr', type id '1'>
Debug: arg #5: <name 'end', type id '1'>
Debug: return value: type id '496'>
Debug: 'mm' arg, predcate '(null)'
Debug: setting base arg for val mm to 1
Debug: custom trace with 1 args
libbpf: loading object 'ksnoop_bpf' from buffer
libbpf: elf: section(2) .text, size 5704, link 0, flags 6, type=1
libbpf: sec '.text': found program 'ksnoop' at insn offset 0 (0 bytes), code size 713 insns (5704 bytes)
libbpf: elf: section(3) .rel.text, size 176, link 15, flags 40, type=9
libbpf: elf: section(4) kprobe/foo, size 32, link 0, flags 6, type=1
libbpf: sec 'kprobe/foo': found program 'kprobe_entry' at insn offset 0 (0 bytes), code size 4 insns (32 bytes)
libbpf: elf: section(5) .relkprobe/foo, size 16, link 15, flags 40, type=9
libbpf: elf: section(6) kretprobe/foo, size 32, link 0, flags 6, type=1
libbpf: sec 'kretprobe/foo': found program 'kprobe_return' at insn offset 0 (0 bytes), code size 4 insns (32 bytes)
libbpf: elf: section(7) .relkretprobe/foo, size 16, link 15, flags 40, type=9
libbpf: elf: section(8) license, size 13, link 0, flags 3, type=1
libbpf: license of ksnoop_bpf is Dual BSD/GPL
libbpf: elf: section(9) .maps, size 88, link 0, flags 3, type=1
libbpf: elf: section(10) .BTF, size 8893, link 0, flags 0, type=1
libbpf: elf: section(12) .BTF.ext, size 4572, link 0, flags 0, type=1
libbpf: elf: section(15) .symtab, size 1920, link 1, flags 0, type=2
libbpf: looking for externs among 80 symbols...
libbpf: collected 0 externs total
libbpf: map 'ksnoop_func_stack': at sec_idx 9, offset 0.
libbpf: map 'ksnoop_func_stack': found type = 1.
libbpf: map 'ksnoop_func_stack': found key [8], sz = 8.
libbpf: map 'ksnoop_func_stack': found value [11], sz = 144.
libbpf: map 'ksnoop_func_stack': found max_entries = 2048.
libbpf: map 'ksnoop_func_map': at sec_idx 9, offset 32.
libbpf: map 'ksnoop_func_map': found type = 5.
libbpf: map 'ksnoop_func_map': found key [8], sz = 8.
libbpf: map 'ksnoop_func_map': found value [22], sz = 16296.
libbpf: map 'ksnoop_func_map': found max_entries = 64.
libbpf: map 'ksnoop_perf_map': at sec_idx 9, offset 64.
libbpf: map 'ksnoop_perf_map': found type = 4.
libbpf: map 'ksnoop_perf_map': found key_size = 4.
libbpf: map 'ksnoop_perf_map': found value_size = 4.
libbpf: sec '.rel.text': collecting relocation for section(2) '.text'
libbpf: sec '.rel.text': relo #0: insn #6 against 'ksnoop_func_stack'
libbpf: prog 'ksnoop': found map 0 (ksnoop_func_stack, sec 9, off 0) for insn #6
libbpf: sec '.rel.text': relo #1: insn #35 against 'ksnoop_func_stack'
libbpf: prog 'ksnoop': found map 0 (ksnoop_func_stack, sec 9, off 0) for insn #35
libbpf: sec '.rel.text': relo #2: insn #40 against 'ksnoop_func_stack'
libbpf: prog 'ksnoop': found map 0 (ksnoop_func_stack, sec 9, off 0) for insn #40
libbpf: sec '.rel.text': relo #3: insn #85 against 'ksnoop_func_map'
libbpf: prog 'ksnoop': found map 1 (ksnoop_func_map, sec 9, off 32) for insn #85
libbpf: sec '.rel.text': relo #4: insn #146 against 'ksnoop_func_map'
libbpf: prog 'ksnoop': found map 1 (ksnoop_func_map, sec 9, off 32) for insn #146
libbpf: sec '.rel.text': relo #5: insn #490 against 'ksnoop_func_stack'
libbpf: prog 'ksnoop': found map 0 (ksnoop_func_stack, sec 9, off 0) for insn #490
libbpf: sec '.rel.text': relo #6: insn #540 against 'ksnoop_func_map'
libbpf: prog 'ksnoop': found map 1 (ksnoop_func_map, sec 9, off 32) for insn #540
libbpf: sec '.rel.text': relo #7: insn #568 against 'ksnoop_perf_map'
libbpf: prog 'ksnoop': found map 2 (ksnoop_perf_map, sec 9, off 64) for insn #568
libbpf: sec '.rel.text': relo #8: insn #584 against 'ksnoop_perf_map'
libbpf: prog 'ksnoop': found map 2 (ksnoop_perf_map, sec 9, off 64) for insn #584
libbpf: sec '.rel.text': relo #9: insn #635 against 'ksnoop_func_map'
libbpf: prog 'ksnoop': found map 1 (ksnoop_func_map, sec 9, off 32) for insn #635
libbpf: sec '.rel.text': relo #10: insn #665 against 'ksnoop_perf_map'
libbpf: prog 'ksnoop': found map 2 (ksnoop_perf_map, sec 9, off 64) for insn #665
libbpf: sec '.relkprobe/foo': collecting relocation for section(4) 'kprobe/foo'
libbpf: sec '.relkprobe/foo': relo #0: insn #1 against '.text'
libbpf: sec '.relkretprobe/foo': collecting relocation for section(6) 'kretprobe/foo'
libbpf: sec '.relkretprobe/foo': relo #0: insn #1 against '.text'
libbpf: loading kernel BTF '/sys/kernel/btf/vmlinux': 0
libbpf: map 'ksnoop_func_stack': created successfully, fd=4
libbpf: map 'ksnoop_func_map': created successfully, fd=5
libbpf: map 'ksnoop_perf_map': setting size to 8
libbpf: map 'ksnoop_perf_map': created successfully, fd=6
libbpf: sec '.text': found 7 CO-RE relocations
libbpf: CO-RE relocating [70] struct pt_regs: found target candidate [111] struct pt_regs in [vmlinux]
libbpf: prog 'ksnoop': relo #0: <byte_off> [70] struct pt_regs.nip (0:0:1:1 @ offset 256)
libbpf: prog 'ksnoop': relo #0: matching candidate #0 <byte_off> [111] struct pt_regs.nip (0:0:1:1 @ offset 256)
libbpf: prog 'ksnoop': relo #0: patched insn #50 (ALU/ALU64) imm 256 -> 256
libbpf: prog 'ksnoop': relo #1: <byte_off> [70] struct pt_regs.gpr[3] (0:0:1:0:3 @ offset 24)
libbpf: prog 'ksnoop': relo #1: matching candidate #0 <byte_off> [111] struct pt_regs.gpr[3] (0:0:1:0:3 @ offset 24)
libbpf: prog 'ksnoop': relo #1: patched insn #222 (ALU/ALU64) imm 24 -> 24
libbpf: prog 'ksnoop': relo #2: <byte_off> [70] struct pt_regs.gpr[4] (0:0:1:0:4 @ offset 32)
libbpf: prog 'ksnoop': relo #2: matching candidate #0 <byte_off> [111] struct pt_regs.gpr[4] (0:0:1:0:4 @ offset 32)
libbpf: prog 'ksnoop': relo #2: patched insn #226 (ALU/ALU64) imm 32 -> 32
libbpf: prog 'ksnoop': relo #3: <byte_off> [70] struct pt_regs.gpr[5] (0:0:1:0:5 @ offset 40)
libbpf: prog 'ksnoop': relo #3: matching candidate #0 <byte_off> [111] struct pt_regs.gpr[5] (0:0:1:0:5 @ offset 40)
libbpf: prog 'ksnoop': relo #3: patched insn #230 (ALU/ALU64) imm 40 -> 40
libbpf: prog 'ksnoop': relo #4: <byte_off> [70] struct pt_regs.gpr[6] (0:0:1:0:6 @ offset 48)
libbpf: prog 'ksnoop': relo #4: matching candidate #0 <byte_off> [111] struct pt_regs.gpr[6] (0:0:1:0:6 @ offset 48)
libbpf: prog 'ksnoop': relo #4: patched insn #234 (ALU/ALU64) imm 48 -> 48
libbpf: prog 'ksnoop': relo #5: <byte_off> [70] struct pt_regs.gpr[7] (0:0:1:0:7 @ offset 56)
libbpf: prog 'ksnoop': relo #5: matching candidate #0 <byte_off> [111] struct pt_regs.gpr[7] (0:0:1:0:7 @ offset 56)
libbpf: prog 'ksnoop': relo #5: patched insn #238 (ALU/ALU64) imm 56 -> 56
libbpf: prog 'ksnoop': relo #6: <byte_off> [70] struct pt_regs.gpr[3] (0:0:1:0:3 @ offset 24)
libbpf: prog 'ksnoop': relo #6: matching candidate #0 <byte_off> [111] struct pt_regs.gpr[3] (0:0:1:0:3 @ offset 24)
libbpf: prog 'ksnoop': relo #6: patched insn #294 (ALU/ALU64) imm 24 -> 24
libbpf: prog 'kprobe_entry': added 713 insns from sub-prog 'ksnoop'
libbpf: prog 'kprobe_entry': insn #1 relocated, imm 2 points to subprog 'ksnoop' (now at 4 offset)
libbpf: prog 'kprobe_return': added 713 insns from sub-prog 'ksnoop'
libbpf: prog 'kprobe_return': insn #1 relocated, imm 2 points to subprog 'ksnoop' (now at 4 offset)
Debug: Attached kprobe for 'vma_merge'
Debug: Attached kretprobe for 'vma_merge'
TIME CPU PID FUNCTION/ARGS

matthew-olson-intel · 2023-10-03T16:41:13Z

I've reproduced this issue: same symptom, no output, even when attaching to the same function with bpftrace works. Diagnosing.

dubeyabhishek · 2023-10-03T18:35:50Z

In my investigation KSNOOP_IP_FIX macro is causing the issue. Kprobes are preferably attached at ftrace locations. Since, this location might depend on the stack configurations(CFA/CFI etc) so we might not be lucky enough everytime to have exact address match in ksnoop_func_map.

matthew-olson-intel · 2023-10-03T18:47:13Z

I agree; KSNOOP_IP_FIX is definitely related to the problem. On my system, vma_merge is at 0xffffffffb754b5e0, and KSNOOP_IP_FIX only subtracts one byte from 0xffffffffb754b5e5; thus, we're 4 bytes off. We should definitely be doing something more robust than that.

I think in general, we've got two options for fixing ksnoop:

Fix KSNOOP_IP_FIX so that it works in more scenarios.
Make ksnoop attach to tracepoints instead of using kprobes. Most functions that one would want to trace have a tracepoint anyway, so this might be a good compromise.

matthew-olson-intel · 2023-10-03T19:24:48Z

In this case, a quick hack could be to force 16-byte alignment in KSNOOP_IP_FIX (instead of subtracting a number of bytes, which depends on the kernel configuration). This would only be for x86_64, and I'm not sure how many other kernel configurations that hack would work in, though.

matthew-olson-intel · 2023-10-03T20:17:31Z

Ideally, we'd handle this by doing PT_REGS_IP_CORE(ctx) - MCOUNT_INSN_SIZE.

chenhengqi · 2023-10-04T08:30:41Z

cc @alan-maguire

alan-maguire · 2023-10-04T09:19:56Z

seems like we should probably also use bpf_get_func_ip() where available, only falling back to KSNOOP_IP_FIX if that doesn't exist (it didn't when ksnoop originally landed). I also wonder if we can use an CO-RE tricks to infer MCOUNT_INSN_SIZE from a data structure that uses it?

alan-maguire · 2023-10-04T09:29:46Z

something like

if (bpf_core_enum_value_exists(enum bpf_func_id, BPF_FUNC_get_func_ip))
ip = bpf_get_func_ip();
else
ip = KSNOOP_IP_FIX(ctx);

(need to figure out the exact macro for KSNOOP_IP_FIX(), but the above should solve the issue for newer kernels (>5.15 ish) at least..

alan-maguire · 2023-10-04T10:00:20Z

can you try attached patch and see if it helps? (I think it will help for kernels 5.13 and newer). it uses bpf_get_func_ip() where available..
0001-ksnoop-use-bpf_get_func_ip-where-helper-is-available.patch.txt

matthew-olson-intel · 2023-10-04T15:21:55Z

Yeah, @alan-maguire, that patch works. Thanks!

alan-maguire · 2023-10-04T15:54:49Z

Great, thanks for the quick response! So I can file a PR using that fix for now, and we can think about the best solution for the pre-5.13 case. I suggest we leave this issue open regardless so we can track the pre-5.13 aspect too, since it's not really fixed until it's fixed for that case as well. What do you think?

matthew-olson-intel · 2023-10-04T16:21:29Z

Yeah, just tested in a 5.4.0-137-generic kernel in Ubuntu 18.04 (I had a VM handy), and the same issue occurs; to fully fix this problem, we definitely need to do something hacky to account for the MCOUNT_INSN_SIZE offset.

bpf_get_func_ip(ctx) will get the function address; use it where available using the BPF core enum value check for the function. This avoids needing to get the caller IP via KSNOOP_IP_FIX() for more up-to-date kernels. This fixes issue iovisor#4746 for kernels newer than 5.13; an additional followup will be needed to address this for older kernels. Kindly tested by https://github.com/matthew-olson-intel on a recent kernel. Reported-by: dubeyabhishek (https://github.com/dubeyabhishek) Signed-off-by: Alan Maguire <[email protected]>

alan-maguire · 2023-10-05T10:46:51Z

okay sad to say i couldn't come up with anything better than the attached patch. the idea is this - we do a one-off serach for MCOUNT_INSN_SIZE by continually subtracting a byte from the PT_REGS_IP_CORE() instruction pointer value and checking if our map lookup succeeds. When/if it does, we cache the mcount_insn_size value, so it's a one-off cost.
0001-ksnoop-dynamically-determine-MCOUNT_INSN_SIZE-adjust.patch.txt

If you get a chance to give it a spin on your 5.4 kernel that would be great. thanks!

chenhengqi · 2023-10-05T14:26:45Z

Can't we just #define MCOUNT_INSN_SIZE for supported architectures ?

bpf_get_func_ip(ctx) will get the function address; use it where available using the BPF core enum value check for the function. This avoids needing to get the caller IP via KSNOOP_IP_FIX() for more up-to-date kernels. This fixes issue #4746 for kernels newer than 5.13; an additional followup will be needed to address this for older kernels. Kindly tested by https://github.com/matthew-olson-intel on a recent kernel. Reported-by: dubeyabhishek (https://github.com/dubeyabhishek) Signed-off-by: Alan Maguire <[email protected]>

alan-maguire · 2023-10-05T15:56:43Z

would certainly be easier! however it's somewhat config-dependent on x86 at least; if CONFIG_FUNCTION_TRACER is defined, it's 5, otherwise 0. there may be other cases for other arches too, haven't looked yet.

matthew-olson-intel · 2023-10-05T21:57:37Z

I tested that new patch on 5.4, and while it does find the proper IP and correctly identifies MCOUNT_INSN_SIZE as 1 in this case, it doesn't seem to be giving me any output-- further debugging is needed. The map lookup is definitely succeeding, get_trace returns a valid pointer, and I get to the return 0 at the end of the ksnoop BPF function.

alan-maguire · 2023-10-06T14:51:02Z

i haven't been able to reproduce this yet; if you get a chance would you mind attaching the 5.4 kernel config where you see this failure? thanks!

matthew-olson-intel · 2023-10-06T19:37:17Z

Yep, it's just the standard Ubuntu 5.4.0-137-generic config.

config-5.4.0-137-generic.txt

chenhengqi · 2023-10-09T15:19:40Z

would certainly be easier! however it's somewhat config-dependent on x86 at least; if CONFIG_FUNCTION_TRACER is defined, it's 5, otherwise 0. there may be other cases for other arches too, haven't looked yet.

Could we employ CO-RE kconfig here ?

alan-maguire · 2023-10-09T15:33:11Z

we probably could, though it might get a bit messy depending on how things look on other architectures. first order of business is to get a fix that works for the 5.4 case though; the above one doesn't and i'm not sure why yet, so i'll try and reproduce that failure now..

alan-maguire · 2023-10-11T08:50:47Z

Apologies for the delay, but I got set up with Ubuntu 18.04:

Linux bpfubuntu 5.4.0-1100-oracle #109~18.04.1-Ubuntu SMP Fri Apr 21 12:01:52 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

When I run "ksnoop vma_merge" I see it working:

ubuntu@bpfubuntu:~/src/bcc/libbpf-tools$ sudo ksnoop vma_merge
TIME CPU PID FUNCTION/ARGS
67702166171718 0 2565 vma_merge(
mm = *(0xffff938366cce200)
(struct mm_struct){
(struct){
.mmap = (struct vm_area_struct *)0xffff9380437259c0,
.mm_rb = (struct rb_root){
.rb_node = (struct rb_node )0xffff938043725020,
},
.vmacache_seqnum = (u64)12,
.get_unmapped_area = (long unsigned int ()(struct file *, long unsigned int, long unsigned int, long unsigned int, long unsigned int))0xffffffffad639110,
.mmap_base = (long unsigned int)140389935984640,
.mmap_legacy_base = (long unsigned int)47242859184128,
.mmap_compat_base = (long unsigned int)4159741952,
.mmap_compat_legacy_base = (long unsigned int)1432653824,
.task_size = (long unsigned int)140737488351232,
.highest_vm_end = (long unsigned int)140735409319936,

I don't see anything significant in the config diff between mine and yours
config.diff.txt
either which makes it even more of a puzzle..

matthew-olson-intel · 2023-10-11T14:27:29Z

I just tried again this morning (in the same VM), and it's working. In previous attempts, I waited 2 or so minutes (left to get a cup of coffee, etc.), so figured it wasn't working because other VMs had given me samples immediately. However, this morning I left it running for a few more minutes and got a couple of samples in the 5.4 kernel.

I'm sorry about that; I should have left it running for a longer period of time to be really sure it wasn't working. Perhaps in recompense, I can try running it in a BTF-enabled 4.18 kernel to be really sure.

But it looks like everything's all fixed now!

alan-maguire · 2023-10-11T14:42:10Z

no apology necessary! I saw nothing and assumed it was broken for me too. Then triggering some activity led to seeing output. However here's the thing - I didn't have the proposed fix in place, I had built master branch bcc to get a baseline. Without the proposed patch (just using the master branch of bcc) do you see ksnoop output?

matthew-olson-intel · 2023-10-11T15:01:41Z

Yes -- it seems that KSNOOP_IP_FIX does actually work on the 5.4 kernel; I just hadn't actually triggered a vma_merge. I think I just got lucky when I tried it on other idle VMs!

Seems everything's fixed now, then. Case closed!

bpf_get_func_ip(ctx) will get the function address; use it where available using the BPF core enum value check for the function. This avoids needing to get the caller IP via KSNOOP_IP_FIX() for more up-to-date kernels. This fixes issue iovisor#4746 for kernels newer than 5.13; an additional followup will be needed to address this for older kernels. Kindly tested by https://github.com/matthew-olson-intel on a recent kernel. Reported-by: dubeyabhishek (https://github.com/dubeyabhishek) Signed-off-by: Alan Maguire <[email protected]>

dubeyabhishek changed the title ~~trace_handler not invoking in ksnoop~~ broken ksnoop tool Sep 22, 2023

dubeyabhishek closed this as completed Oct 3, 2023

dubeyabhishek reopened this Oct 3, 2023

alan-maguire mentioned this issue Oct 4, 2023

ksnoop: use bpf_get_func_ip() where helper is available #4755

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

broken ksnoop tool #4746

broken ksnoop tool #4746

dubeyabhishek commented Sep 21, 2023

matthew-olson-intel commented Oct 3, 2023

dubeyabhishek commented Oct 3, 2023

matthew-olson-intel commented Oct 3, 2023 •

edited

Loading

matthew-olson-intel commented Oct 3, 2023 •

edited

Loading

matthew-olson-intel commented Oct 3, 2023

chenhengqi commented Oct 4, 2023

alan-maguire commented Oct 4, 2023

alan-maguire commented Oct 4, 2023

alan-maguire commented Oct 4, 2023

matthew-olson-intel commented Oct 4, 2023

alan-maguire commented Oct 4, 2023

matthew-olson-intel commented Oct 4, 2023

alan-maguire commented Oct 5, 2023

chenhengqi commented Oct 5, 2023

alan-maguire commented Oct 5, 2023

matthew-olson-intel commented Oct 5, 2023

alan-maguire commented Oct 6, 2023

matthew-olson-intel commented Oct 6, 2023

chenhengqi commented Oct 9, 2023

alan-maguire commented Oct 9, 2023

alan-maguire commented Oct 11, 2023

matthew-olson-intel commented Oct 11, 2023

alan-maguire commented Oct 11, 2023

matthew-olson-intel commented Oct 11, 2023

broken ksnoop tool #4746

broken ksnoop tool #4746

Comments

dubeyabhishek commented Sep 21, 2023

./ksnoop trace "vma_merge(mm)" -d

matthew-olson-intel commented Oct 3, 2023

dubeyabhishek commented Oct 3, 2023

matthew-olson-intel commented Oct 3, 2023 • edited Loading

matthew-olson-intel commented Oct 3, 2023 • edited Loading

matthew-olson-intel commented Oct 3, 2023

chenhengqi commented Oct 4, 2023

alan-maguire commented Oct 4, 2023

alan-maguire commented Oct 4, 2023

alan-maguire commented Oct 4, 2023

matthew-olson-intel commented Oct 4, 2023

alan-maguire commented Oct 4, 2023

matthew-olson-intel commented Oct 4, 2023

alan-maguire commented Oct 5, 2023

chenhengqi commented Oct 5, 2023

alan-maguire commented Oct 5, 2023

matthew-olson-intel commented Oct 5, 2023

alan-maguire commented Oct 6, 2023

matthew-olson-intel commented Oct 6, 2023

chenhengqi commented Oct 9, 2023

alan-maguire commented Oct 9, 2023

alan-maguire commented Oct 11, 2023

matthew-olson-intel commented Oct 11, 2023

alan-maguire commented Oct 11, 2023

matthew-olson-intel commented Oct 11, 2023

matthew-olson-intel commented Oct 3, 2023 •

edited

Loading

matthew-olson-intel commented Oct 3, 2023 •

edited

Loading