Why can't I access 'kill_something_info' probes?

Why can't I access 'kill_something_info' probes?

[Om]

Hi,
I am writing some scriptlets to check trace signals. (I know about the 
signal tapset, but...)

Here is the script.

# This traces kill related syscalls
#
probe kernel.function("sys_kill")
{
	printf("%d sends %d to %d\n", pid(), $sig, $pid)
}

probe kernel.function("kill_something_info")
{
	printf("info->si_signo=%d\n", $info->si_signo)
	printf("info->si_errno=%d\n", $info->si_errno)
}
probe timer.ms(10000)
{
	exit()
}

--End of script.

Errors here...
[root@... signals]# stap -vvvv ./killtrace.stp
SystemTap translator/driver (version 0.6.2/0.127 built 2008-03-27)
Copyright (C) 2005-2008 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
Created temporary directory "/tmp/stapdnhska"
Searched '/usr/share/systemtap/tapset/x86_64/*.stp', found 1
Searched '/usr/share/systemtap/tapset/*.stp', found 37
Pass 1: parsed user script and 38 library script(s) in 
290usr/10sys/307real ms.
control symbols: kts: 0xffffffff81257a00 kte: 0xffffffff8125ac27 stext: 
0xffffffff81009000
parsed 'sys_kill' -> func 'sys_kill'
blacklist regexps:
blfn: 
^(atomic_notifier_call_chain|default_do_nmi|__die|die_nmi|do_debug|do_general_protection|do_int3|do_IRQ|do_page_fault|do_sparc64_fault|do_trap|dummy_nmi_callback|flush_icache_range|ia64_bad_break|ia64_do_page_fault|ia64_fault|io_check_error|mem_parity_error|nmi_watchdog_tick|notifier_call_chain|oops_begin|oops_end|program_check_exception|single_step_exception|sync_regs|unhandled_fault|unknown_nmi_error|.*raw_.*lock.*|.*read_.*lock.*|.*write_.*lock.*|.*spin_.*lock.*|.*rwlock_.*lock.*|.*rwsem_.*lock.*|.*mutex_.*lock.*|raw_.*|.*seq_.*lock.*|.*apic.*|.*APIC.*|.*softirq.*|.*IRQ.*|.*_intr.*|__delay|.*kernel_text.*|get_current|current_.*|.*exception_tables.*|.*setup_rt_frame.*|.*preempt_count.*|preempt_schedule|__switch_to)$
blfn_ret: ^(do_exit|sys_exit|sys_exit_group)$
blfile: ^(kernel/kprobes.c|arch/.*/kernel/kprobes.c)$
pattern 'kernel' matches module 'kernel'
focused on module 'kernel = [0xffffffff81000000-0xffffffff81514720, bias 
0x0] file /usr/lib/debug/lib/modules/2.6.23.17-88.fc7/vmlinux ELF 
machine x86_64 (code 62)
pattern 'sys_kill' matches function 'sys_kill'
selected function sys_kill
probe sys_kill@kernel/signal.c:2073 kernel section=.text 
pc=0xffffffff8104065f
finding location for local 'sig' near address ffffffff8104065f, module 
bias 0
finding location for local 'pid' near address ffffffff8104065f, module 
bias 0
control symbols: kts: 0xffffffff81257a00 kte: 0xffffffff8125ac27 stext: 
0xffffffff81009000
parsed 'kill_something_info' -> func 'kill_something_info'
blacklist regexps:
blfn: 
^(atomic_notifier_call_chain|default_do_nmi|__die|die_nmi|do_debug|do_general_protection|do_int3|do_IRQ|do_page_fault|do_sparc64_fault|do_trap|dummy_nmi_callback|flush_icache_range|ia64_bad_break|ia64_do_page_fault|ia64_fault|io_check_error|mem_parity_error|nmi_watchdog_tick|notifier_call_chain|oops_begin|oops_end|program_check_exception|single_step_exception|sync_regs|unhandled_fault|unknown_nmi_error|.*raw_.*lock.*|.*read_.*lock.*|.*write_.*lock.*|.*spin_.*lock.*|.*rwlock_.*lock.*|.*rwsem_.*lock.*|.*mutex_.*lock.*|raw_.*|.*seq_.*lock.*|.*apic.*|.*APIC.*|.*softirq.*|.*IRQ.*|.*_intr.*|__delay|.*kernel_text.*|get_current|current_.*|.*exception_tables.*|.*setup_rt_frame.*|.*preempt_count.*|preempt_schedule|__switch_to)$
blfn_ret: ^(do_exit|sys_exit|sys_exit_group)$
blfile: ^(kernel/kprobes.c|arch/.*/kernel/kprobes.c)$
pattern 'kernel' matches module 'kernel'
focused on module 'kernel = [0xffffffff81000000-0xffffffff81514720, bias 
0x0] file /usr/lib/debug/lib/modules/2.6.23.17-88.fc7/vmlinux ELF 
machine x86_64 (code 62)
pattern 'kill_something_info' matches function 'kill_something_info'
checking instances of inline kill_something_info
examining inline instance of kill_something_info
selected inline instance of kill_something_info
entry-pc lookup (dwarf_ranges, ignored 2 more) = 0xffffffff81040691 (rc 0)
querying entrypc ffffffff81040691 of instance of inline 
'kill_something_info'
probe kill_something_info@kernel/signal.c:1146 kernel section=.text 
pc=0xffffffff81040691
finding location for local 'info' near address ffffffff81040691, module 
bias 0
finding location for local 'info' near address ffffffff81040691, module 
bias 0
dwarf_builder releasing dwflpp
Eliding unused function print_regs
...
<snip>
...
Eliding unused function stp_print_binary
semantic error: failed to retrieve location attribute for local 'info' 
(dieoffset: 0x334d03): identifier '$info' at ./killtrace.stp:10:32
semantic error: failed to retrieve location attribute for local 'info' 
(dieoffset: 0x334d03): identifier '$info' at ./killtrace.stp:11:32
Pass 2: analyzed script: 3 probe(s), 4 function(s), 0 embed(s), 0 
global(s) in 580usr/150sys/732real ms.
Pass 2: analysis failed.  Try again with more '-v' (verbose) options.
Running rm -rf /tmp/stapdnhska

Version info here..

[root@... signals]# uname -a
Linux mpk12-etclab-158-187 2.6.23.17-88.fc7 #1 SMP Thu May 15 00:02:29 
EDT 2008 x86_64 x86_64 x86_64 GNU/Linux
[root@... signals]# stap
stap     staprun
[root@... signals]# stap -V
SystemTap translator/driver (version 0.6.2/0.127 built 2008-03-27)
Copyright (C) 2005-2008 Red Hat, Inc. and others

kill_something_info is a static function as defined in,
static int kill_something_info(int sig, struct siginfo *info, int pid)
{
...
in kernel/signal.c

Am I doing something wrong? Any pointers would be helpful.

Thanks,
Om

Re: Why can't I access 'kill_something_info' probes?

[Frank Ch. Eigler]

Om <om.turyx@gmail.com> writes:

> I am writing some scriptlets to check trace signals. [...]

OK.

> [...]
> probe kernel.function("kill_something_info")
> {
> 	printf("info->si_signo=%d\n", $info->si_signo)
> 	printf("info->si_errno=%d\n", $info->si_errno)
> }
> [...]
> semantic error: failed to retrieve location attribute for local 'info'
> (dieoffset: 0x334d03): identifier '$info' at ./killtrace.stp:10:32
> semantic error: failed to retrieve location attribute for local 'info'
> (dieoffset: 0x334d03): identifier '$info' at ./killtrace.stp:11:32
> [...]

This is the dreaded "gcc omits debuginfo for inlined functions, especially
their parameters", aka systemtap PR 1155, and various GCC and RH bugzilla #s.

There is little one can do, except:

- try to find some other way to get at the context $info variable data,
  perhaps via a local variable within the function (requiring a statement probe),
  or by saving it from a caller site into a systemtap script-level variable
- try to place a (statement) probe into the caller of this inline function,
  where the same value may be available (perhaps under a different name)
- investigate whether a marker may be available
- recompile the kernel with CFLAGS += -fno-inline-functions-called-once,
  which can reduce the number of functions that are affected by the gcc bug
- recompile the kernel with Alex Oliva's var-tracking branch gcc, which
  can expose a mass of variables


- FChE

Re: Why can't I access 'kill_something_info' probes?

[Wenji Huang]

Om wrote:
> Hi,
> I am writing some scriptlets to check trace signals. (I know about the 
> signal tapset, but...)
> 
> Here is the script.
> 
> # This traces kill related syscalls
> #
> probe kernel.function("sys_kill")
> {
>     printf("%d sends %d to %d\n", pid(), $sig, $pid)
> }
> 
> probe kernel.function("kill_something_info")
> {
>     printf("info->si_signo=%d\n", $info->si_signo)
>     printf("info->si_errno=%d\n", $info->si_errno)
> }
> probe timer.ms(10000)
> {
>     exit()
> }
> 
> --End of script.
> 
> Errors here...
> [root@... signals]# stap -vvvv ./killtrace.stp
> SystemTap translator/driver (version 0.6.2/0.127 built 2008-03-27)
> Copyright (C) 2005-2008 Red Hat, Inc. and others
> This is free software; see the source for copying conditions.
> Created temporary directory "/tmp/stapdnhska"
> Searched '/usr/share/systemtap/tapset/x86_64/*.stp', found 1
> Searched '/usr/share/systemtap/tapset/*.stp', found 37
> Pass 1: parsed user script and 38 library script(s) in 
> 290usr/10sys/307real ms.
> control symbols: kts: 0xffffffff81257a00 kte: 0xffffffff8125ac27 stext: 
> 0xffffffff81009000
> parsed 'sys_kill' -> func 'sys_kill'
> blacklist regexps:
> blfn: 
> ^(atomic_notifier_call_chain|default_do_nmi|__die|die_nmi|do_debug|do_general_protection|do_int3|do_IRQ|do_page_fault|do_sparc64_fault|do_trap|dummy_nmi_callback|flush_icache_range|ia64_bad_break|ia64_do_page_fault|ia64_fault|io_check_error|mem_parity_error|nmi_watchdog_tick|notifier_call_chain|oops_begin|oops_end|program_check_exception|single_step_exception|sync_regs|unhandled_fault|unknown_nmi_error|.*raw_.*lock.*|.*read_.*lock.*|.*write_.*lock.*|.*spin_.*lock.*|.*rwlock_.*lock.*|.*rwsem_.*lock.*|.*mutex_.*lock.*|raw_.*|.*seq_.*lock.*|.*apic.*|.*APIC.*|.*softirq.*|.*IRQ.*|.*_intr.*|__delay|.*kernel_text.*|get_current|current_.*|.*exception_tables.*|.*setup_rt_frame.*|.*preempt_count.*|preempt_schedule|__switch_to)$ 
> 
> blfn_ret: ^(do_exit|sys_exit|sys_exit_group)$
> blfile: ^(kernel/kprobes.c|arch/.*/kernel/kprobes.c)$
> pattern 'kernel' matches module 'kernel'
> focused on module 'kernel = [0xffffffff81000000-0xffffffff81514720, bias 
> 0x0] file /usr/lib/debug/lib/modules/2.6.23.17-88.fc7/vmlinux ELF 
> machine x86_64 (code 62)
> pattern 'sys_kill' matches function 'sys_kill'
> selected function sys_kill
> probe sys_kill@kernel/signal.c:2073 kernel section=.text 
> pc=0xffffffff8104065f
> finding location for local 'sig' near address ffffffff8104065f, module 
> bias 0
> finding location for local 'pid' near address ffffffff8104065f, module 
> bias 0
> control symbols: kts: 0xffffffff81257a00 kte: 0xffffffff8125ac27 stext: 
> 0xffffffff81009000
> parsed 'kill_something_info' -> func 'kill_something_info'
> blacklist regexps:
> blfn: 
> ^(atomic_notifier_call_chain|default_do_nmi|__die|die_nmi|do_debug|do_general_protection|do_int3|do_IRQ|do_page_fault|do_sparc64_fault|do_trap|dummy_nmi_callback|flush_icache_range|ia64_bad_break|ia64_do_page_fault|ia64_fault|io_check_error|mem_parity_error|nmi_watchdog_tick|notifier_call_chain|oops_begin|oops_end|program_check_exception|single_step_exception|sync_regs|unhandled_fault|unknown_nmi_error|.*raw_.*lock.*|.*read_.*lock.*|.*write_.*lock.*|.*spin_.*lock.*|.*rwlock_.*lock.*|.*rwsem_.*lock.*|.*mutex_.*lock.*|raw_.*|.*seq_.*lock.*|.*apic.*|.*APIC.*|.*softirq.*|.*IRQ.*|.*_intr.*|__delay|.*kernel_text.*|get_current|current_.*|.*exception_tables.*|.*setup_rt_frame.*|.*preempt_count.*|preempt_schedule|__switch_to)$ 
> 
> blfn_ret: ^(do_exit|sys_exit|sys_exit_group)$
> blfile: ^(kernel/kprobes.c|arch/.*/kernel/kprobes.c)$
> pattern 'kernel' matches module 'kernel'
> focused on module 'kernel = [0xffffffff81000000-0xffffffff81514720, bias 
> 0x0] file /usr/lib/debug/lib/modules/2.6.23.17-88.fc7/vmlinux ELF 
> machine x86_64 (code 62)
> pattern 'kill_something_info' matches function 'kill_something_info'
> checking instances of inline kill_something_info
> examining inline instance of kill_something_info
> selected inline instance of kill_something_info
> entry-pc lookup (dwarf_ranges, ignored 2 more) = 0xffffffff81040691 (rc 0)
> querying entrypc ffffffff81040691 of instance of inline 
> 'kill_something_info'
> probe kill_something_info@kernel/signal.c:1146 kernel section=.text 
> pc=0xffffffff81040691
> finding location for local 'info' near address ffffffff81040691, module 
> bias 0
> finding location for local 'info' near address ffffffff81040691, module 
> bias 0
> dwarf_builder releasing dwflpp
> Eliding unused function print_regs
> ...
> <snip>
> ...
> Eliding unused function stp_print_binary
> semantic error: failed to retrieve location attribute for local 'info' 
> (dieoffset: 0x334d03): identifier '$info' at ./killtrace.stp:10:32
> semantic error: failed to retrieve location attribute for local 'info' 
> (dieoffset: 0x334d03): identifier '$info' at ./killtrace.stp:11:32
> Pass 2: analyzed script: 3 probe(s), 4 function(s), 0 embed(s), 0 
> global(s) in 580usr/150sys/732real ms.

Seems this function is implicitly inlined. To access parameters of
inline functions is still pending problem for systemtap/gcc. But you can
try marker to get the inline function parameter information.

For your case, I found kill_something_info is just called in sys_kill
and always info.si_signo = sig; info.si_errno = 0 in kill_something_info
entry. So no necessary to do another probe. just sys_kill is enough.

BTW: probe kernel.function("sys_kill").return could be the reference to
the result of signal dispatch.

Regards,
Wenji

Re: Why can't I access 'kill_something_info' probes?

[Om]

Wenji Huang wrote:
> Om wrote:
>> Hi,
>> Eliding unused function stp_print_binary
>> semantic error: failed to retrieve location attribute for local 'info' 
>> (dieoffset: 0x334d03): identifier '$info' at ./killtrace.stp:10:32
>> semantic error: failed to retrieve location attribute for local 'info' 
>> (dieoffset: 0x334d03): identifier '$info' at ./killtrace.stp:11:32
>> Pass 2: analyzed script: 3 probe(s), 4 function(s), 0 embed(s), 0 
>> global(s) in 580usr/150sys/732real ms.
> 
> Seems this function is implicitly inlined. To access parameters of
How do we know that? What should I look for?
> inline functions is still pending problem for systemtap/gcc. But you can
> try marker to get the inline function parameter information.
> 
> For your case, I found kill_something_info is just called in sys_kill
> and always info.si_signo = sig; info.si_errno = 0 in kill_something_info
> entry. So no necessary to do another probe. just sys_kill is enough.
Yeah.. I was curious why I could not probe.
> 
> BTW: probe kernel.function("sys_kill").return could be the reference to
> the result of signal dispatch.
Thanks for the suggestion. I am just poking the kernel. I know the 
values of info->*, but when I got the error, I wanted to know if I was 
doing something wrong. and that gave a little more knowledge :-D

Thanks,
Om.

Re: Why can't I access 'kill_something_info' probes?

[Masami Hiramatsu]

Om wrote:
>> Seems this function is implicitly inlined. To access parameters of
> How do we know that? What should I look for?

if you make sure that the function is not inlined, you can use .call
suffix;

probe kernel.function("kill_something_info").call { ... }

If the function is inlined, this will report an error.

>> inline functions is still pending problem for systemtap/gcc. But you can
>> try marker to get the inline function parameter information.
>>
>> For your case, I found kill_something_info is just called in sys_kill
>> and always info.si_signo = sig; info.si_errno = 0 in kill_something_info
>> entry. So no necessary to do another probe. just sys_kill is enough.
> Yeah.. I was curious why I could not probe.

Actually, you can probe it but can not trace local variables because
current debuginfo doesn't include those information.

Thank you,

-- 
Masami Hiramatsu

Software Engineer
Hitachi Computer Products (America) Inc.
Software Solutions Division

e-mail: mhiramat@redhat.com