systemtap probe point’s context variables or target variables
背景
在systemtap language reference手册的第三章有这么一段话 :
The probe handler is interpreted relative to the context of each event. For events associated with kernel code, this context may include variables defined in the source code at that location. These target variables (or ``context variables’’) are presented to the script as variables whose names are prefixed with a dollar sign ($). They may be accessed only if the compiler used to compile the kernel preserved them, despite optimization. This is the same constraint imposed by a debugger when working with optimized code. Other events may have very little context.
前面已经接触过类似的话题, 例如通过$$vars来输出probe points对应的target variables.
参考下文第二部分.
http://blog.163.com/digoal@126/blog/static/163877040201381044416754/
本文将对context variables做一次详细的分析. 主要来自stapprobes的man手册(本文末尾).
下面要介绍一下本文的测试事件例子.
用到的事件是kprocess.create
[root@db-172-16-3-39 ~]# stap -l 'kproce**'
kprocess.create
对应的函数
[root@db-172-16-3-39 ~]# grep -r kprocess.create /usr/share/systemtap/
/usr/share/systemtap/tapset/kprocess.stp: * probe kprocess.create - Fires whenever a new process or thread is successfully created
/usr/share/systemtap/tapset/kprocess.stp:probe kprocess.create = kernel.function("copy_process").return {
对应的代码
[root@db-172-16-3-39 ~]# stap -l 'kernel.function("copy_process")'
kernel.function("copy_process@kernel/fork.c:1107")
源文件如下
/usr/src/debug/kernel-2.6.18/linux-2.6.18-348.12.1.el5.x86_64/kernel/fork.c
对应的函数如下(截取部分内容)
static struct task_struct *copy_process(unsigned long clone_flags,
unsigned long stack_start,
struct pt_regs *regs,
unsigned long stack_size,
int __user *parent_tidptr,
int __user *child_tidptr,
int pid)
{
int retval;
struct task_struct *p = NULL;
... 略去部分内容
源文件中定义的全局变量如下, 在测试 @var(“varname@src/file.c”) 时用到
/*
* Protected counters by write_lock_irq(&tasklist_lock)
*/
unsigned long total_forks; /* Handle normal Linux uptimes. */
int nr_threads; /* The idle threads do not count.. */
int max_threads; /* tunable limit on nr_threads */
下面对手册中描述的用法举例说明.
1. $var, 这个很好理解, 就是输出probe point所在范围内的变量值. 如果是int类型的将输出64位数字, 如果是char *类型, 则可以使用kernel_string或者user_string函数输出该地址对应的字符串.
如果不是数字也不是字符串, 可以用@cast进行转换.
测试用到$pid. 它是int类型
[root@db-172-16-3-39 ~]# cat test.stp
probe kprocess.create {
printf("%d\n", $pid)
exit()
}
[root@db-172-16-3-39 ~]# stap test.stp
18498
字符串类型参考此文, 这里就不举例了.
http://blog.163.com/digoal@126/blog/static/16387704020138352516878/
2. @var(“varname”) 与$var一样的效果.
[root@db-172-16-3-39 ~]# cat test.stp
probe kprocess.create {
printf("%d, %d\n", $pid, @var("pid"))
exit()
}
[root@db-172-16-3-39 ~]# stap test.stp
18756, 18756
如果使用了一个不存在的本地变量, 那么会打印出可选的本地变量
[root@db-172-16-3-39 ~]# stap --vp 5 test.stp
Parsed kernel "/lib/modules/2.6.18-348.12.1.el5/build/.config", containing 1977 tuples
Parsed kernel /lib/modules/2.6.18-348.12.1.el5/build/Module.symvers, which contained 3546 vmlinux exports
Searched: " /usr/share/systemtap/tapset/x86_64/*.stp ", found: 4, processed: 4
Searched: " /usr/share/systemtap/tapset/*.stp ", found: 81, processed: 81
Pass 1: parsed user script and 85 library script(s) using 146808virt/23700res/3008shr/21404data kb, in 160usr/10sys/172real ms.
semantic error: unable to find local 'current' near pc 0xffffffff8001f5c0 in copy_process kernel/fork.c ( (alternatives: $clone_flags $stack_start $regs $stack_size $parent_tidptr $child_tidptr $pid $retval $p): identifier '$current' at test.stp:2:20
source: printf("%d, \n", $current[1])
^
Pass 2: analysis failed. Try again with another '--vp 01' option.
3. @var(“varname@src/file.c”)
输出事件触发时, 该源文件的全局变量的值.
[root@db-172-16-3-39 ~]# cat test.stp
probe kprocess.create {
printf("%d, %d\n", $pid, @var("pid"))
printf("global variables in fork.c: %d, %d, %d\n", @var("max_threads@kernel/fork.c"), @var("total_forks@kernel/fork.c"), @var("nr_threads@kernel/fork.c"))
exit()
}
[root@db-172-16-3-39 ~]# stap test.stp
18896, 18896
global variables in fork.c: 127569, 6473035, 254
如果使用了一个不存在的全局变量, 会打印出可选的全局变量 :
[root@db-172-16-3-39 ~]# stap --vp 5 test.stp
Parsed kernel "/lib/modules/2.6.18-348.12.1.el5/build/.config", containing 1977 tuples
Parsed kernel /lib/modules/2.6.18-348.12.1.el5/build/Module.symvers, which contained 3546 vmlinux exports
Searched: " /usr/share/systemtap/tapset/x86_64/*.stp ", found: 4, processed: 4
Searched: " /usr/share/systemtap/tapset/*.stp ", found: 81, processed: 81
Pass 1: parsed user script and 85 library script(s) using 146872virt/23700res/3008shr/21468data kb, in 160usr/10sys/171real ms.
semantic error: unable to find global 'current' in kernel/fork.c kernel/fork.c ( (alternatives: $console_printk $hex_asc $_cpu_pda $cpu_possible_map $cpu_online_map $mmu_cr4_features $boot_cpu_data $node_data $mp_ioapics $skip_ioapic_setup $cpu_callout_map $bios_cpu_apicid $memnode $mem_section $malloc_sizes $vm_area_cachep $files_cachep $fs_cachep $sighand_cachep $xtime $time_status $time_maxerror $time_esterror $time_adjust $leap_second $jiffies $per_cpu__rcu_data $per_cpu__rcu_bh_data $total_forks $nr_threads $per_cpu__process_counts $tasklist_lock $mmlist_lock $root_user $init_task $init_mm $vfsmount_lock $policy_zone $dcache_lock $irq_desc $mm_tracking_struct $init_level4_pgt $__supported_pte_mask $pgd_lock $pgd_list $protection_map $zone_table $per_cpu__vm_event_states $vm_stat $swapper_space $number_of_cpusets $mmap_min_addr $security_ops $swap_token_mm $anon_vma_cachep $ioport_resource $bad_dma_address $dma_ops $genl_sock $taskstats_cache $delayacct_on $delayacct_cache $idt_table $cpu_gdt_descr $max_threads $__crc_tasklist_lock $__kcrctab_tasklist_lock $__kstrtab_tasklist_lock $__ksymtab_tasklist_lock $mm_flags_hash $mm_flags_lock $task_struct_cachep $signal_cachep $mm_cachep $__crc_free_task $__kcrctab_free_task $__kstrtab_free_task $__ksymtab_free_task $__crc___put_task_struct $__kcrctab___put_task_struct $__kstrtab___put_task_struct $__ksymtab___put_task_struct $init_task_aux $default_dump_filter $__setup_str_coredump_filter_setup $__setup_coredump_filter_setup $__crc_mmput $__kcrctab_mmput $__kstrtab_mmput $__ksymtab_mmput $__crc_get_task_mm $__kcrctab_get_task_mm $__kstrtab_get_task_mm $__ksymtab_get_task_mm $__crc_copy_fs_struct $__kcrctab_copy_fs_struct $__kstrtab_copy_fs_struct $__ksymtab_copy_fs_struct $__crc_unshare_files $__kcrctab_unshare_files $__kstrtab_unshare_files $__ksymtab_unshare_files $console_printk $hex_asc $_cpu_pda $cpu_possible_map $cpu_online_map $mmu_cr4_features $boot_cpu_data $node_data $mp_ioapics $skip_ioapic_setup $cpu_callout_map $bios_cpu_apicid $memnode $mem_section $malloc_sizes $vm_area_cachep $files_cachep $fs_cachep $sighand_cachep $xtime $time_status $time_maxerror $time_esterror $time_adjust $leap_second $jiffies $per_cpu__rcu_data $per_cpu__rcu_bh_data $total_forks $nr_threads $per_cpu__process_counts $tasklist_lock $mmlist_lock $root_user $init_task $init_mm $vfsmount_lock $policy_zone $dcache_lock $irq_desc $mm_tracking_struct $init_level4_pgt $__supported_pte_mask $pgd_lock $pgd_list $protection_map $zone_table $per_cpu__vm_event_states $vm_stat $swapper_space $number_of_cpusets $mmap_min_addr $security_ops $swap_token_mm $anon_vma_cachep $ioport_resource $bad_dma_address $dma_ops $genl_sock $taskstats_cache $delayacct_on $delayacct_cache $idt_table $cpu_gdt_descr $max_threads $__crc_tasklist_lock $mm_flags_hash $mm_flags_lock $__crc_free_task $__crc___put_task_struct $__crc_mmput $__crc_get_task_mm $__crc_copy_fs_struct $__crc_unshare_files): identifier '@var' at test.stp:2:20
source: printf("%d, \n", @var("current@kernel/fork.c")[1])
^
Pass 2: analysis failed. Try again with another '--vp 01' option.
4. $var->field
在源文件中除了数字和字符串, 还有其他类型, 例如结构, 指针等. 这些类型中的member或field可以通过$var->field来输出.
注意由于.点符号在systemtap中是字符串的连接符号, 所以结构的member也使用->来表示, 而不是.点符号.
[root@db-172-16-3-39 ~]# cat test.stp
probe kprocess.create {
printf(".is string's concat operator : %s\n", "i" . " am digoal")
exit()
}
[root@db-172-16-3-39 ~]# stap test.stp
.is string's concat operator : i am digoal
取结构中的数据,本例的copy_process的返回值类型为static struct task_struct *
结构中包含pid, wchar, rchar, utime等值, 下面stp脚本可以取到.
[root@db-172-16-3-39 ~]# cat test.stp
probe kprocess.create {
printf("pid:%d, pid:%d, rchar:%d, wchar:%d, utime:%d, mempolicy:%d\n", $pid, $return->pid, $return->rchar, $return->wchar, $return->utime, $return->mempolicy)
exit()
}
[root@db-172-16-3-39 ~]# stap test.stp
然后开启一个进程.
[pg94@db-172-16-3-39 ~]$ psql
psql (9.4devel)
Type "help" for help.
digoal=#
可以看到 stap返回值 :
pid:7402, pid:7402, rchar:0, wchar:0, utime:0, mempolicy:0
如果指定了一个结构中不存在的member, 那么会返回可选的member :
[root@db-172-16-3-39 ~]# stap --vp 5 test.stp
Parsed kernel "/lib/modules/2.6.18-348.12.1.el5/build/.config", containing 1977 tuples
Parsed kernel /lib/modules/2.6.18-348.12.1.el5/build/Module.symvers, which contained 3546 vmlinux exports
Searched: " /usr/share/systemtap/tapset/x86_64/*.stp ", found: 4, processed: 4
Searched: " /usr/share/systemtap/tapset/*.stp ", found: 81, processed: 81
Pass 1: parsed user script and 85 library script(s) using 147760virt/23716res/3008shr/22356data kb, in 160usr/10sys/172real ms.
semantic error: unable to find member 'p' for struct pt_regs (alternatives: r15 r14 r13 r12 rbp rbx r11 r10 r9 r8 rax rcx rdx rsi rdi orig_rax rip cs eflags rsp ss): operator '->' at test.stp:2:25
source: printf("%d, \n", $regs->p[1])
^
Pass 2: analysis failed. Try again with another '--vp 01' option.
5. $return, 只有当被探测到函数有返回值时才有用, 上面的例子已经用到了.
6. $var[N], N是数字. 指函数中的数组变量.
例如这里用到的是/usr/src/debug/kernel-2.6.18/linux-2.6.18-348.12.1.el5.x86_64/net/ipv4/icmp.c 中的一个结构中包含的数组.
struct icmp_bxm {
struct sk_buff *skb;
int offset;
int data_len;
struct {
struct icmphdr icmph;
__u32 times[3];
} data;
int head_len;
struct ip_options replyopts;
unsigned char optbuf[40];
};
函数 :
static void icmp_push_reply(struct icmp_bxm *icmp_param,
struct ipcm_cookie *ipc, struct rtable *rt)
{
struct sk_buff *skb;
if (ip_append_data(icmp_socket->sk, icmp_glue_bits, icmp_param,
icmp_param->data_len+icmp_param->head_len,
icmp_param->head_len,
ipc, rt, MSG_DONTWAIT) < 0)
ip_flush_pending_frames(icmp_socket->sk);
else if ((skb = skb_peek(&icmp_socket->sk->sk_write_queue)) != NULL) {
struct icmphdr *icmph = skb->h.icmph;
unsigned int csum = 0;
struct sk_buff *skb1;
skb_queue_walk(&icmp_socket->sk->sk_write_queue, skb1) {
csum = csum_add(csum, skb1->csum);
}
csum = csum_partial_copy_nocheck((void *)&icmp_param->data,
(char *)icmph,
icmp_param->head_len, csum);
icmph->checksum = csum_fold(csum);
skb->ip_summed = CHECKSUM_NONE;
ip_push_pending_frames(icmp_socket->sk);
}
}
这个探针如下 :
[root@db-172-16-3-39 ~]# stap -l 'kernel.function("**")'|grep icmp_push_reply
kernel.function("icmp_push_reply@net/ipv4/icmp.c:347")
测试 :
[root@db-172-16-3-39 ~]# cat test.stp
probe kernel.function("icmp_push_reply@net/ipv4/icmp.c:347") {
for (i=0; i<$1; i++) {
printf("%d, ", $icmp_param->data->times[i])
}
printf("end\n")
exit()
}
[root@db-172-16-3-39 ~]# stap --vp 5 test.stp 10
Parsed kernel "/lib/modules/2.6.18-348.12.1.el5/build/.config", containing 1977 tuples
Parsed kernel /lib/modules/2.6.18-348.12.1.el5/build/Module.symvers, which contained 3546 vmlinux exports
Searched: " /usr/share/systemtap/tapset/x86_64/*.stp ", found: 4, processed: 4
Searched: " /usr/share/systemtap/tapset/*.stp ", found: 81, processed: 81
Pass 1: parsed user script and 85 library script(s) using 146796virt/23700res/3008shr/21392data kb, in 160usr/10sys/173real ms.
WARNING: For probing a particular line, use a .statement() probe, not .function(): keyword at test.stp:1:1
source: probe kernel.function("icmp_push_reply@net/ipv4/icmp.c:347") {
^
2147839040, 4294967295, 2149938976, 8, 0, 0, 2, 2, 0, 0, end
下半部分是操作符 :
1. $$vars
[root@db-172-16-3-39 ~]# cat test.stp
probe kernel.function("icmp_push_reply@net/ipv4/icmp.c:347") {
printf("$$vars: %s\n", $$vars)
printf("%x\n", $icmp_param)
exit()
}
[root@db-172-16-3-39 ~]# stap --vp 5 test.stp
Parsed kernel "/lib/modules/2.6.18-348.12.1.el5/build/.config", containing 1977 tuples
Parsed kernel /lib/modules/2.6.18-348.12.1.el5/build/Module.symvers, which contained 3546 vmlinux exports
Searched: " /usr/share/systemtap/tapset/x86_64/*.stp ", found: 4, processed: 4
Searched: " /usr/share/systemtap/tapset/*.stp ", found: 81, processed: 81
Pass 1: parsed user script and 85 library script(s) using 147760virt/23716res/3008shr/22356data kb, in 160usr/10sys/172real ms.
WARNING: For probing a particular line, use a .statement() probe, not .function(): keyword at test.stp:1:1
source: probe kernel.function("icmp_push_reply@net/ipv4/icmp.c:347") {
^
$$vars: icmp_param=0xffff810133953dc8 ipc=0xffff810133953d68 rt=0xffff8101af062b40 skb=?
ffff810133953dc8
2. parms, vars中分子出来的本地变量, 函数参数, 函数返回值.
3. 取变量地址.
& $EXPR
4. 判断变量是否存在.
@defined($EXPR)
@defined($foo->bar) ? $foo->bar : 0
5. 输出结构包括第一层member的表达式.
$EXPR$ expands to a string with all of $EXPR’s members, equivalent to
sprintf("{.a=%i, .b=%u, .c={...}, .d=[...]}",
$EXPR->a, $EXPR->b)
例如 :
[root@db-172-16-3-39 ~]# cat test.stp
probe kernel.function("icmp_push_reply@net/ipv4/icmp.c:347") {
printf("%s\n", $icmp_param$)
exit()
}
[root@db-172-16-3-39 ~]# stap --vp 5 test.stp
Parsed kernel "/lib/modules/2.6.18-348.12.1.el5/build/.config", containing 1977 tuples
Parsed kernel /lib/modules/2.6.18-348.12.1.el5/build/Module.symvers, which contained 3546 vmlinux exports
Searched: " /usr/share/systemtap/tapset/x86_64/*.stp ", found: 4, processed: 4
Searched: " /usr/share/systemtap/tapset/*.stp ", found: 81, processed: 81
Pass 1: parsed user script and 85 library script(s) using 146800virt/23704res/3008shr/21396data kb, in 170usr/10sys/172real ms.
WARNING: For probing a particular line, use a .statement() probe, not .function(): keyword at test.stp:1:1
source: probe kernel.function("icmp_push_reply@net/ipv4/icmp.c:347") {
^
{.skb=0xffff8102207e1080, .offset=0, .data_len=56, .data={...}, .head_len=8, .replyopts={...}, .optbuf=[...]}
6. 输出结构包括所有层member的值的表达式.
$EXPR$$
expands to a string with all of $var’s members and submembers, equivalent to
sprintf("{.a=%i, .b=%u, .c={.x=%p, .y=%c}, .d=[%i, ...]}",
$EXPR->a, $EXPR->b, $EXPR->c->x, $EXPR->c->y, $EXPR->d[0])
例如 :
[root@db-172-16-3-39 ~]# cat test.stp
probe kernel.function("icmp_push_reply@net/ipv4/icmp.c:347") {
printf("%s\n", $icmp_param$$)
exit()
}
[root@db-172-16-3-39 ~]# stap --vp 5 test.stp
Parsed kernel "/lib/modules/2.6.18-348.12.1.el5/build/.config", containing 1977 tuples
Parsed kernel /lib/modules/2.6.18-348.12.1.el5/build/Module.symvers, which contained 3546 vmlinux exports
Searched: " /usr/share/systemtap/tapset/x86_64/*.stp ", found: 4, processed: 4
Searched: " /usr/share/systemtap/tapset/*.stp ", found: 81, processed: 81
Pass 1: parsed user script and 85 library script(s) using 146800virt/23700res/3008shr/21396data kb, in 160usr/10sys/173real ms.
WARNING: For probing a particular line, use a .statement() probe, not .function(): keyword at test.stp:1:1
source: probe kernel.function("icmp_push_reply@net/ipv4/icmp.c:347") {
^
{.skb=0xffff81022fc1a2c0, .offset=0, .data_len=56, .data={.icmph={.type='\000', .code='\000', .checksum=0, .un={.echo={.id=9086, .sequence=31749}, .gateway=2080711550, .frag={.__unused=9086, .mtu=31749}}}, .times=[2147839040, ...]}, .head_len=8, .replyopts={.faddr=0, .optlen='\000', .srr='\000', .rr='\000', .ts='\000', .is_setbyuser=0, .is_data=1, .is_strictroute=0, .srr_is_hit=0, .is_changed=0, .rr_needaddr=0, .ts_needtime=0, .ts_needaddr=0, .router_alert='\000', .cipso='\000', .rhel_alloc_flag=0, .__data
参考
1. https://sourceware.org/systemtap/langref/Components_SystemTap_script.html
- man stap
TYPECASTING
Once a pointer has been saved into a script integer variable, the translator loses the type information neces-
sary to access members from that pointer. Using the @cast() operator tells the translator how to read a point-
er.
@cast(p, "type_name"[, "module"])->member
This will interpret p as a pointer to a struct/union named type_name and dereference the member value. Further
->subfield expressions may be appended to dereference more levels. NOTE: the same dereferencing operator ->
is used to refer to both direct containment or pointer indirection. Systemtap automatically determines which.
The optional module tells the translator where to look for information about that type. Multiple modules may
be specified as a list with : separators. If the module is not specified, it will default either to the probe
module for dwarf probes, or to "kernel" for functions and all other probes types.
The translator can create its own module with type information from a header surrounded by angle brackets, in
case normal debuginfo is not available. For kernel headers, prefix it with "kernel" to use the appropriate
build system. All other headers are build with default GCC parameters into a user module. Multiple headers
may be specified in sequence to resolve a codependency.
@cast(tv, "timeval", "<sys/time.h>")->tv_sec
@cast(task, "task_struct", "kernel<linux/sched.h>")->tgid
@cast(task, "task_struct",
"kernel<linux/sched.h><linux/fs_struct.h>")->fs->umask
Values acquired by @cast may be pretty-printed by the $ " and " $$ suffix operators, the same way as described
in the CONTEXT VARIABLES section of the stapprobes(3stap) manual page.
When in guru mode, the translator will also allow scripts to assign new values to members of typecasted point-
ers.
Typecasting is also useful in the case of void* members whose type may be determinable at runtime.
probe foo {
if ($var->type == 1) {
value = @cast($var->data, "type1")->bar
} else {
value = @cast($var->data, "type2")->baz
}
print(value)
}
3. man stapprobes
CONTEXT VARIABLES
Many of the source-level context variables, such as function parameters, locals, globals visible in the compi-
lation unit, may be visible to probe handlers. They may refer to these variables by prefixing their name with
"$" within the scripts. In addition, a special syntax allows limited traversal of structures, pointers, and
arrays. More syntax allows pretty-printing of individual variables or their groups. See also @cast.
$var refers to an in-scope variable "var". If it’s an integer-like type, it will be cast to a 64-bit int for
systemtap script use. String-like pointers (char *) may be copied to systemtap string values using the
kernel_string or user_string functions.
@var("varname")
an alternative syntax for $varname
@var("varname@src/file.c")
refers to the global (either file local or external) variable varname defined when the file src/file.c
was compiled. The CU in which the variable is resolved is the first CU in the module of the probe point
which matches the given file name at the end and has the shortest file name path (e.g. given
@var("foo@bar/baz.c") and CUs with file name paths src/sub/module/bar/baz.c and src/bar/baz.c the second
CU will be chosen to resolve the (file) global variable foo
$var->field traversal via a structure’s or a pointer’s field. This
generalized indirection operator may be repeated to follow more levels. Note that the . operator is
not used for plain structure members, only -> for both purposes. (This is because "." is reserved for
string concatenation.)
$return
is available in return probes only for functions that are declared with a return value.
$var[N]
indexes into an array. The index given with a literal number or even an arbitrary numeric expression.
A number of operators exist for such basic context variable expressions:
$$vars expands to a character string that is equivalent to
sprintf("parm1=%x ... parmN=%x var1=%x ... varN=%x",
parm1, ..., parmN, var1, ..., varN)
for each variable in scope at the probe point. Some values may be printed as =? if their run-time location
cannot be found.
$$locals
expands to a subset of $$vars for only local variables.
$$parms
expands to a subset of $$vars for only function parameters.
$$return
is available in return probes only. It expands to a string that is equivalent to sprintf("return=%x",
$return) if the probed function has a return value, or else an empty string.
& $EXPR
expands to the address of the given context variable expression, if it is addressable.
@defined($EXPR)
expands to 1 or 0 iff the given context variable expression is resolvable, for use in conditionals such
as
@defined($foo->bar) ? $foo->bar : 0
$EXPR$ expands to a string with all of $EXPR’s members, equivalent to
sprintf("{.a=%i, .b=%u, .c={...}, .d=[...]}",
$EXPR->a, $EXPR->b)
$EXPR$$
expands to a string with all of $var’s members and submembers, equivalent to
sprintf("{.a=%i, .b=%u, .c={.x=%p, .y=%c}, .d=[%i, ...]}",
$EXPR->a, $EXPR->b, $EXPR->c->x, $EXPR->c->y, $EXPR->d[0])
For ".return" probes, context variables other than the "$return" value itself are only available for the func-
tion call parameters. The expressions evaluate to the entry-time values of those variables, since that is when
a snapshot is taken. Other local variables are not generally accessible, since by the time a ".return" probe
hits, the probed function will have already returned.
Arbitrary entry-time expressions can also be saved for ".return" probes using the @entry(expr) operator. For
example, one can compute the elapsed time of a function:
probe kernel.function("do_filp_open").return {
println( get_timeofday_us() - @entry(get_timeofday_us()) )
}