From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mx-out.tlen.pl (mx-out.tlen.pl [193.222.135.158]) by sourceware.org (Postfix) with ESMTPS id 6804E3858407 for ; Tue, 22 Mar 2022 09:48:13 +0000 (GMT) DMARC-Filter: OpenDMARC Filter v1.4.1 sourceware.org 6804E3858407 Received: (wp-smtpd smtp.tlen.pl 14553 invoked from network); 22 Mar 2022 10:48:09 +0100 Received: from public-gprs408086.centertel.pl (HELO localhost) (vibrys@o2.pl@[37.47.225.87]) (envelope-sender ) by smtp.tlen.pl (WP-SMTPD) with ECDHE-RSA-AES256-GCM-SHA384 encrypted SMTP for ; 22 Mar 2022 10:48:09 +0100 References: <87mtl0aqhn.fsf@redhat.com> User-agent: mu4e 1.4.13; emacs 27.2 From: Matt Vibrys To: "Frank Ch. Eigler" , systemtap@sourceware.org Subject: Re: non-working .return probepoint from modules In-reply-to: Message-ID: Date: Tue, 22 Mar 2022 10:48:08 +0100 MIME-Version: 1.0 Content-Type: text/plain X-WP-MailID: 6b676edb0471c8bcdf3e3db8ebb8da9b X-WP-AV: skaner antywirusowy Poczty o2 X-WP-SPAM: NO 0000000 [odPU] X-Spam-Status: No, score=-0.9 required=5.0 tests=BAYES_00, DKIM_SIGNED, DKIM_VALID, DKIM_VALID_AU, DKIM_VALID_EF, FREEMAIL_FROM, KAM_LOTSOFHASH, RCVD_IN_MSPIKE_H4, RCVD_IN_MSPIKE_WL, SPF_HELO_NONE, SPF_PASS, TXREP, T_SCC_BODY_TEXT_LINE autolearn=ham autolearn_force=no version=3.4.4 X-Spam-Checker-Version: SpamAssassin 3.4.4 (2020-01-24) on server2.sourceware.org X-BeenThere: systemtap@sourceware.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Systemtap mailing list List-Unsubscribe: , List-Archive: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 22 Mar 2022 09:48:17 -0000 Matt Vibrys via Systemtap writes: > Frank Ch. Eigler writes: > >>>> The output below provides function calls, but it's silent about it's >>>> returns. Why so?: >> >> Good question, I wonder too! >> >>>> gmm@MY-HOST:~/user$ sudo /opt/systemtap-4.6/bin/stap -vv /home/gmm/user/scripts/drm.stp >>>> Systemtap translator/driver (version 4.6/0.176, non-git sources) >>>> [...] >> >> This is good, it contains the module-insertion fix PR28557. >> The stap console trace looks okay. >> >>> For better insight I've used drm module drm_ioctl function >>> instead. The problem persists, ie .return "locks nothing": >>> #+begin_src systemtap >>> probe module("drm").function("drm_ioctl") >>> { >>> printf("-->. %s %s %s\n", thread_indent(0), ppfunc(), $$parms); >>> } >>> >>> probe module("drm").function("drm_ioctl").return >>> { >>> printf("<--\n"); >>> } >> >> Would you consider rerunning a bit more pass-5 runtime side >> tracing such as >> >> % sudo stap -DDEBUG_KPROBES -DDEBUG_SYMBOLS [...] >> >> >> - FChE > > Hi Frank, > thank You for response. > > here's the output: > #+begin_src bash > prompt$ sudo /opt/systemtap-4.6/bin/stap -vv -DDEBUG_KPROBES -DDEBUG_SYMBOLS ~/user/scripts/drm.stp > Systemtap translator/driver (version 4.6/0.176, non-git sources) > Copyright (C) 2005-2021 Red Hat, Inc. and others > This is free software; see the source for copying conditions. > tested kernel versions: 2.6.32 ... 5.15.0-rc7 > enabled features: BPF PYTHON3 LIBVIRT LIBXML2 NLS > Created temporary directory "/tmp/staprnTrv2" > Session arch: x86_64 release: 5.13.0-22-generic > Build tree: "/lib/modules/5.13.0-22-generic/build" > Kernel symbol table /lib/modules/5.13.0-22-generic/build/System.map unavailable, (No such file or directory) > Searched for library macro files: "/opt/systemtap-4.6/share/systemtap/tapset/linux", found: 7, processed: 7 > Searched for library macro files: "/opt/systemtap-4.6/share/systemtap/tapset", found: 11, processed: 11 > Searched: "/opt/systemtap-4.6/share/systemtap/tapset/linux/x86_64", found: 20, processed: 20 > Searched: "/opt/systemtap-4.6/share/systemtap/tapset/linux", found: 407, processed: 407 > Searched: "/opt/systemtap-4.6/share/systemtap/tapset/x86_64", found: 1, processed: 1 > Searched: "/opt/systemtap-4.6/share/systemtap/tapset", found: 34, processed: 34 > Pass 1: parsed user script and 480 library scripts using 121164virt/100540res/6252shr/94384data kb, in 100usr/20sys/115real ms. > derive-probes (location #0): module("drm").function("drm_ioctl") of keyword at /home/gmm/user/scripts/drm.stp:16:1 > probe drm_ioctl@/build/linux-hwe-5.13-ADyN9x/linux-hwe-5.13-5.13.0/drivers/gpu/drm/drm_ioctl.c:811 module=drm reloc=.text pc=0x143b0 > derive-probes (location #0): module("drm").function("drm_ioctl").return of keyword at /home/gmm/user/scripts/drm.stp:21:1 > probe drm_ioctl@/build/linux-hwe-5.13-ADyN9x/linux-hwe-5.13-5.13.0/drivers/gpu/drm/drm_ioctl.c:811 module=drm reloc=.text pc=0x143b0 > Pass 2: analyzed script: 2 probes, 12 functions, 1 embed, 2 globals using 124932virt/105328res/7236shr/98152data kb, in 130usr/0sys/135real ms. > function recursion-analysis: max-nesting 4 non-recursive > probe 0 ('module("drm").function("drm_ioctl@/build/linux-hwe-5.13-ADyN9x/linux-hwe-5.13-5.13.0/drivers/gpu/drm/drm_ioctl.c:811")') locks __private__opt_systemtap_4_6_share_systemtap_tapset_indent_stp__indent_counters[rw] __private__opt_systemtap_4_6_share_systemtap_tapset_indent_stp__indent_timestamps[rw] > 5 statements for probe probe_6335 > probe 1 ('module("drm").function("drm_ioctl@/build/linux-hwe-5.13-ADyN9x/linux-hwe-5.13-5.13.0/drivers/gpu/drm/drm_ioctl.c:811").return') locks nothing > 1 statements for probe probe_6337 > dump_unwindsyms drm index=0 base=0x10000 > Found build-id in drm, length 20, start at 0x10 > Pass 3: translated to C into "/tmp/staprnTrv2/stap_33df05986440b0b57b4062d608cf18eb_4656_src.c" using 124932virt/105456res/7364shr/98152data kb, in 120usr/10sys/121real ms. > Pass 4: using cached /root/.systemtap/cache/14/stapconf_14af95633f25eea4f38d1eb6ef710bb1_799.h > Running env -uARCH -uKBUILD_EXTMOD -uCROSS_COMPILE -uKBUILD_IMAGE -uKCONFIG_CONFIG -uINSTALL_PATH -uLD_LIBRARY_PATH PATH=/usr/bin:/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin make -C /lib/modules/5.13.0-22-generic/build M=/tmp/staprnTrv2 modules CONFIG_DEBUG_INFO= CONFIG_DEBUG_INFO_BTF_MODULES= ARCH=x86_64 --no-print-directory -j21 > CC [M] /tmp/staprnTrv2/stap_33df05986440b0b57b4062d608cf18eb_4656_src.o > CC [M] /tmp/staprnTrv2/stap_33df05986440b0b57b4062d608cf18eb_4656_aux_0.o > CC [M] /tmp/staprnTrv2/stap_symbols.o > LD [M] /tmp/staprnTrv2/stap_33df05986440b0b57b4062d608cf18eb_4656.o > MODPOST /tmp/staprnTrv2/Module.symvers > CC [M] /tmp/staprnTrv2/stap_33df05986440b0b57b4062d608cf18eb_4656.mod.o > LD [M] /tmp/staprnTrv2/stap_33df05986440b0b57b4062d608cf18eb_4656.ko > Spawn waitpid result (0x0): 0 > Pass 4: compiled C into "stap_33df05986440b0b57b4062d608cf18eb_4656.ko" in 1400usr/360sys/1637real ms. > Cleaning cache, interval reached 61190 s > 300 s. > Copying /tmp/staprnTrv2/stap_33df05986440b0b57b4062d608cf18eb_4656.ko to /root/.systemtap/cache/33/stap_33df05986440b0b57b4062d608cf18eb_4656.ko > Copying /tmp/staprnTrv2/stap_33df05986440b0b57b4062d608cf18eb_4656_src.c to /root/.systemtap/cache/33/stap_33df05986440b0b57b4062d608cf18eb_4656.c > Copying /tmp/staprnTrv2/stapconf_14af95633f25eea4f38d1eb6ef710bb1_799.h to /root/.systemtap/cache/14/stapconf_14af95633f25eea4f38d1eb6ef710bb1_799.h > Pass 5: starting run. > Running /opt/systemtap-4.6/bin/staprun -v -R /tmp/staprnTrv2/stap_33df05986440b0b57b4062d608cf18eb_4656.ko > staprun:insert_module:191 Module stap_33df05986440b0b57b4062d608cf18e_10362 inserted from file /tmp/staprnTrv2/stap_33df05986440b0b57b4062d608cf18eb_4656.ko > _stp_set_stext:44: found kernel _stext load address: 0xffffffff8bc00000 > _stp_kmodule_update_address:1115: module drm section .altinstr_aux address 0xffffffffc05684e2 > _stp_kmodule_update_address:1115: module drm section .altinstr_replacement address 0xffffffffc0568075 > _stp_kmodule_update_address:1115: module drm section .altinstructions address 0xffffffffc057cb54 > _stp_kmodule_update_address:1115: module drm section .bss address 0xffffffffc0588d80 > _stp_kmodule_update_address:1115: module drm section .data address 0xffffffffc0587000 > _stp_kmodule_update_address:1115: module drm section .data..read_mostly address 0xffffffffc05886f4 > _stp_kmodule_update_address:1115: module drm section .data.once address 0xffffffffc05886ec > _stp_kmodule_update_address:1115: module drm section .gnu.linkonce.this_module address 0xffffffffc0588a00 > _stp_kmodule_update_address:1115: module drm section .init.text address 0x0 > _stp_kmodule_update_address:1102: module drm special section .note.gnu.build-id address 0xffffffffc0569000 > _stp_kmodule_update_address:1115: module drm section .parainstructions address 0xffffffffc057c608 > _stp_kmodule_update_address:1115: module drm section .ref.data address 0xffffffffc0588780 > _stp_kmodule_update_address:1115: module drm section .rodata address 0xffffffffc056b080 > _stp_kmodule_update_address:1115: module drm section .rodata.str1.1 address 0xffffffffc057d760 > _stp_kmodule_update_address:1115: module drm section .rodata.str1.8 address 0xffffffffc05801c0 > _stp_kmodule_update_address:1115: module drm section .smp_locks address 0xffffffffc057c3ac > _stp_kmodule_update_address:1115: module drm section .static_call.text address 0xffffffffc0568518 > _stp_kmodule_update_address:1115: module drm section .static_call_sites address 0xffffffffc05889e0 > _stp_kmodule_update_address:1115: module drm section .text address 0xffffffffc0534000 > _stp_kmodule_update_address:1115: module drm section .text.unlikely address 0xffffffffc0568191 > _stp_kmodule_update_address:1115: module drm section ___srcu_struct_ptrs address 0xffffffffc05855b0 > _stp_kmodule_update_address:1115: module drm section __bpf_raw_tp_map address 0xffffffffc0588700 > _stp_kmodule_update_address:1115: module drm section __bug_table address 0xffffffffc0587ae0 > _stp_kmodule_update_address:1115: module drm section __dyndbg address 0xffffffffc05889a8 > _stp_kmodule_update_address:1115: module drm section __jump_table address 0xffffffffc0586000 > _stp_kmodule_update_address:1115: module drm section __kcrctab address 0xffffffffc056a86c > _stp_kmodule_update_address:1115: module drm section __kcrctab_gpl address 0xffffffffc056aff0 > _stp_kmodule_update_address:1115: module drm section __ksymtab address 0xffffffffc0569054 > _stp_kmodule_update_address:1115: module drm section __ksymtab_gpl address 0xffffffffc056a6e0 > _stp_kmodule_update_address:1115: module drm section __ksymtab_strings address 0xffffffffc0577430 > _stp_kmodule_update_address:1115: module drm section __mcount_loc address 0xffffffffc057a6a4 > _stp_kmodule_update_address:1115: module drm section __param address 0xffffffffc05855b8 > _stp_kmodule_update_address:1115: module drm section __tracepoints address 0xffffffffc05888a0 > _stp_kmodule_update_address:1115: module drm section __tracepoints_ptrs address 0xffffffffc0585680 > _stp_kmodule_update_address:1115: module drm section __tracepoints_strings address 0xffffffffc0585690 > _stp_kmodule_update_address:1115: module drm section _ftrace_events address 0xffffffffc0588760 > _stp_module_check:775: build-id validation [drm] > _stp_build_id_check:731: build-id validation [drm] 4c8ebf4428e1562c2877a2be4c5f804cf306d2a3 vs. notes@=ffffffffc0569010 4c8ebf4428e1562c2877a2be4c5f804cf306d2a3 > stapkp_init:756: looking up 2 probes > stapkp_init:770: found 2 probes > stapkp_register_probe:364: stapkp_register_probe module drm addr 0x4350 reg 0 > stapkp_register_probe:364: stapkp_register_probe module drm addr 0x4350 reg 0 > _stp_kmodule_relocate:38: drm, .text, 4350 > _stp_kmodule_relocate:57: address=ffffffffc0538350 > stapkp_arch_register_kprobe:230: +kprobe (null)+0 > stapkp_register_kprobe:258: stapkp_register_kprobe module drm addr 0x4350 rc 0 > -->. 0 myapp-test(10402): drm_ioctl filp=0xffff994332d2f200 cmd=0xc0406400 arg=0x19cf740 > -->. 0 myapp-test(10402): drm_ioctl filp=0xffff994332d2f200 cmd=0xc0406400 arg=0x19cf740 > -->. 0 myapp-test(10402): drm_ioctl filp=0xffff994332d2f200 cmd=0xc0106401 arg=0x7ffcb3a8ad10 > -->. 0 myapp-test(10402): drm_ioctl filp=0xffff994332d2f200 cmd=0xc0106401 arg=0x7ffcb3a8ad10 > -->. 0 myapp-test(10402): drm_ioctl filp=0xffff994332d2f200 cmd=0xc0086441 arg=0x19cf898 > -->. 0 myapp-test(10402): drm_ioctl filp=0xffff994332d2f200 cmd=0xc0086441 arg=0x19cf818 > -->. 0 myapp-test(10402): drm_ioctl filp=0xffff994332d2f200 cmd=0xc0086441 arg=0x19cf858 > -->. 0 myapp-test(10402): drm_ioctl filp=0xffff994332d2f200 cmd=0xc0086441 arg=0x19cf7d8 > -->. 0 myapp-test(10402): drm_ioctl filp=0xffff994332d2f500 cmd=0xc0406400 arg=0x19cd590 > -->. 0 myapp-test(10402): drm_ioctl filp=0xffff994332d2f500 cmd=0xc0406400 arg=0x19cd590 > -->. 0 myapp-test(10402): drm_ioctl filp=0xffff994332d2f500 cmd=0xc0106401 arg=0x7ffcb3a8ad10 > -->. 0 myapp-test(10402): drm_ioctl filp=0xffff994332d2f500 cmd=0xc0106401 arg=0x7ffcb3a8ad10 > -->. 0 myapp-test(10402): drm_ioctl filp=0xffff994332d2f500 cmd=0xc0086441 arg=0x19cf588 > C-c C-cstapkp_batch_unregister_probes:514: -kprobe * 1 > stapio:cleanup_and_exit:352 detach=0 > stapio:cleanup_and_exit:369 closing control channel > staprun:remove_module:292 Module stap_33df05986440b0b57b4062d608cf18e_10362 removed. > Spawn waitpid result (0x0): 0 > Pass 5: run completed in 20usr/90sys/50060real ms. > Running rm -rf /tmp/staprnTrv2 > Spawn waitpid result (0x0): 0 > Removed temporary directory "/tmp/staprnTrv2" > #+end_src > > regards, > Matt hi systemtap team any ideas? regards, Mat