tracing: Read user data from futex system call trace event
cover tracing: Read user data from futex system call trace event
We are looking at the performance of futexes and require a bit more information when tracing them.
The two patches here extend the system call reading of user space to create specific handling of the futex system call. It now reads the user space relevant data (the addr, utime and addr2), as well as parses the flags. This adds a little smarts to the trace event as it only shows the parameters that are relevant, as well as parses utime as either a timespec or as val2 depending on the futex_op.
Here's an example of the new output:
futex_requeue-1431 [004] ..... 154.082233: sys_futex(uaddr: 0x7ffcadad2ff8 (0), FUTEX_WAIT, val: 0, timespec: 0x7f0785f83e90 (0.030000000))
futex_requeue-1421 [002] ..... 154.092286: sys_futex(uaddr: 0x7ffcadad2ff8 (0), FUTEX_CMP_REQUEUE, val: 3, val2: 0x7, uaddr2: 0x7ffcadad2ffc (0), val3: 0)
futex_requeue-1421 [002] ..... 154.092321: sys_futex(uaddr: 0x7ffcadad2ffc (0), FUTEX_WAKE, val: 2147483647)
futex_waitv-1433 [006] ..... 154.111394: sys_futex(uaddr: 0x55ed4a768554 (0), FUTEX_WAKE|FUTEX_PRIVATE_FLAG, val: 1)
futex_waitv-1435 [002] ..... 154.128186: sys_futex(uaddr: 0x7f035fa40000 (0), FUTEX_WAKE, val: 1)Steven Rostedt (2):
tracing: Have futex syscall trace event show specific user data
tracing: Update futex syscall trace event to show more commands
----
kernel/trace/trace_syscalls.c | 370 +++++++++++++++++++++++++++++++++++++++++- 1 file changed, 367 insertions(+), 3 deletions(-)
PATCH 1/2 tracing: Have futex syscall trace event show specific user data
From: Steven Rostedt <[email protected]>
Add specific reporting of the futex system call. This allows for debugging the futex code a bit easier. Instead of just showing the values passed into the futex system call, read the value of the user space memory pointed to by the addr parameter.
Also make the op parameter more readable by parsing the values to show what the command is:
futex_requeue_p-3251 [002] ..... 2101.068479: sys_futex(uaddr: 0x55e79a4da834 (0x80000cb1), FUTEX_LOCK_PI|FUTEX_PRIVATE_FLAG, val: 0) futex_requeue_p-3248 [001] ..... 2101.068970: sys_futex(uaddr: 0x7f859072f990 (0xcb2), FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME, val: 3250) futex_requeue_p-3252 [005] ..... 2101.069108: sys_futex(uaddr: 0x55e79a4da838 (0), FUTEX_WAIT_REQUEUE_PI|FUTEX_PRIVATE_FLAG, val: 0, timespec: 0x7ffe61076aa0, uaddr2: 0x55e79a4da834, uaddr2: 94453214586932, val3: 0) futex_requeue_p-3252 [005] ..... 2101.069410: sys_futex(uaddr: 0x55e79a4da834 (0x80000cb1), FUTEX_LOCK_PI|FUTEX_PRIVATE_FLAG, val: 0)
Signed-off-by Steven Rostedt (Google) <[email protected]>
--- kernel/trace/trace_syscalls.c | 266 +++++++++++++++++++++++++++++++++- 1 file changed, 263 insertions(+), 3 deletions(-)
kernel/trace/trace_syscalls.c +263 -3
@@ -11,6 +11,8 @@#include <linux/xarray.h> #include <asm/syscall.h> +#include <uapi/linux/futex.h> +#include "trace_output.h" #include "trace.h"
@@ -237,6 +239,125 @@ sys_enter_openat_print(struct syscall_trace_enter *trace, struct syscall_metadatreturn trace_handle_return (s); } +static const char * __futex_cmds[] = +{ +"FUTEX_WAIT" ,"FUTEX_WAKE" ,"FUTEX_FD" ,"FUTEX_REQUEUE" , +"FUTEX_CMP_REQUEUE" ,"FUTEX_WAKE_OP" ,"FUTEX_LOCK_PI" , +"FUTEX_UNLOCK_PI" ,"FUTEX_TRYLOCK_PI" ,"FUTEX_WAIT_BITSET" , +"FUTEX_WAKE_BITSET" ,"FUTEX_WAIT_REQUEUE_PI" ,"FUTEX_CMP_REQUEUE_PI" , +"FUTEX_LOCK_PI2" , }; + +/* From futex/syscalls.c */ +static __always_inline bool futex_cmd_has_timeout(u32 cmd) +{ +switch (cmd) { +case FUTEX_WAIT : +case FUTEX_LOCK_PI : +case FUTEX_LOCK_PI2 : +case FUTEX_WAIT_BITSET : +case FUTEX_WAIT_REQUEUE_PI : +return true; + } +return false; +} + +static __always_inline bool futex_cmd_has_addr2(u32 cmd) +{ +switch (cmd) { +case FUTEX_REQUEUE : +case FUTEX_CMP_REQUEUE : +case FUTEX_WAKE_OP : +case FUTEX_WAIT_REQUEUE_PI : +return true; + } +return false; +} + +static enum print_line_t +sys_enter_futex_print (struct syscall_trace_enter *trace,struct syscall_metadata *entry, +struct trace_seq *s,struct trace_event *event,int ent_size) +{ +bool done = false; +unsigned int op, cmd; +void *end = (void *)trace + ent_size; +void *ptr; +int i; + +/* Set ptr to the user space copied area */ + ptr = (void *)trace->args +sizeof (unsigned long ) * entry->nb_args; +if (ptr +4 > end) + ptr =NULL ; + +trace_seq_printf (s,"%s(" , entry->name); + +for (i =0 ; !done && i < entry->nb_args; i++) { + +if (trace_seq_has_overflowed (s)) + goto end; + +switch (i) { +case 0 : +trace_seq_printf (s,"uaddr: 0x%lx" , trace->args[i]); +if (ptr) { +u32 val = *(u32 *)ptr; +if (val <10 ) +trace_seq_printf (s," (%u)" , val); +else +trace_seq_printf (s," (0x%x)" , val); + } +continue ; +case 1 : + op = trace->args[i]; + cmd = op &FUTEX_CMD_MASK ; +if (cmd <=FUTEX_LOCK_PI2 ) +trace_seq_printf (s,", %s" , __futex_cmds[cmd]); +else +trace_seq_puts (s,", UNKNOWN" ); + +if (op &FUTEX_PRIVATE_FLAG ) +trace_seq_puts (s,"|FUTEX_PRIVATE_FLAG" ); +if (op &FUTEX_CLOCK_REALTIME ) +trace_seq_puts (s,"|FUTEX_CLOCK_REALTIME" ); +continue ; +case 3 : +if (!futex_cmd_has_timeout (cmd)) { + +if (!futex_cmd_has_addr2 (cmd)) { + done = true; +continue ; + } + +trace_seq_printf (s,", val2: 0x%x" , + (u32 )(long )trace->args[i]); +continue ; + } + +if (!trace->args[i]) +continue ; + +trace_seq_printf (s,", timespec: 0x%lx" , + trace->args[i]); + +continue ; + +case 4 : +if (!futex_cmd_has_addr2 (cmd)) { + done = true; +continue ; + } +trace_seq_printf (s,", uaddr2: 0x%lx" , trace->args[i]); + } + +trace_seq_printf (s,", %s: %lu" , entry->args[i], + trace->args[i]); + } +trace_seq_putc (s,')' ); +end: +trace_seq_putc (s,'\n' ); + +return trace_handle_return (s); +} +static enum print_line_t print_syscall_enter (struct trace_iterator *iter,int flags,struct trace_event *event)
@@ -267,6 +388,10 @@ print_syscall_enter(struct trace_iterator *iter, int flags,if (!tr || !(tr->trace_flags &TRACE_ITER (VERBOSE )))return sys_enter_openat_print (trace, entry, s, event);break ; +case __NR_futex: +if (!tr || !(tr->trace_flags &TRACE_ITER (VERBOSE ))) +return sys_enter_futex_print (trace, entry, s, event, iter->ent_size); +break ;default :break ; }
@@ -437,6 +562,69 @@ sys_enter_openat_print_fmt(struct syscall_metadata *entry, char *buf, int len)return pos; } +static int __init +sys_enter_futex_print_fmt (struct syscall_metadata *entry,char *buf,int len) +{ +int pos =0 ; + + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"\"uaddr: 0x%%lx (0x%%lx) cmd=%%s%%s%%s" ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +" val: 0x%%x timeout/val2: 0x%%llx" ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +" uaddr2: 0x%%lx val3: 0x%%x\", " ); + + pos +=snprintf (buf + pos,LEN_OR_ZERO , +" REC->uaddr," ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +" REC->__value," ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +" __print_symbolic(REC->op & 0x%x, " ,FUTEX_CMD_MASK ); + + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_WAIT\"}, " ,FUTEX_WAIT ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_WAKE\"}, " ,FUTEX_WAKE ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_FD\"}, " ,FUTEX_FD ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_REQUEUE\"}, " ,FUTEX_REQUEUE ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_CMP_REQUEUE\"}, " ,FUTEX_CMP_REQUEUE ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_WAKE_OP\"}, " ,FUTEX_WAKE_OP ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_LOCK_PI\"}, " ,FUTEX_LOCK_PI ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_UNLOCK_PI\"}, " ,FUTEX_UNLOCK_PI ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_TRYLOCK_PI\"}, " ,FUTEX_TRYLOCK_PI ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_WAIT_BITSET\"}, " ,FUTEX_WAIT_BITSET ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_WAKE_BITSET\"}, " ,FUTEX_WAKE_BITSET ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_WAIT_REQUEUE_PI\"}, " ,FUTEX_WAIT_REQUEUE_PI ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_CMP_REQUEUE_PI\"}, " ,FUTEX_CMP_REQUEUE_PI ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +"{%d, \"FUTEX_LOCK_PI2\"})," ,FUTEX_LOCK_PI2 ); + + pos +=snprintf (buf + pos,LEN_OR_ZERO , +" (REC->op & %d) ? \"|FUTEX_PRIVATE_FLAG\" : \"\"," , +FUTEX_PRIVATE_FLAG ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +" (REC->op & %d) ? \"|FUTEX_CLOCK_REALTIME\" : \"\"," , +FUTEX_CLOCK_REALTIME ); + + pos +=snprintf (buf + pos,LEN_OR_ZERO , +" REC->val, REC->utime," ); + + pos +=snprintf (buf + pos,LEN_OR_ZERO , +" REC->uaddr, REC->val3" ); +return pos; +} +static int __init __set_enter_print_fmt (struct syscall_metadata *entry,char *buf,int len) {
@@ -447,6 +635,8 @@ __set_enter_print_fmt(struct syscall_metadata *entry, char *buf, int len)switch (entry->syscall_nr) {case __NR_openat:return sys_enter_openat_print_fmt (entry, buf, len); +case __NR_futex: +return sys_enter_futex_print_fmt (entry, buf, len);default :break ; }
@@ -523,6 +713,21 @@ static void __init free_syscall_print_fmt(struct trace_event_call *call)kfree (call->print_fmt); } +static int __init futex_fields (struct trace_event_call *call,int offset) +{ +char *arg; +int ret; + + arg =kstrdup ("__value" ,GFP_KERNEL ); +if (WARN_ON_ONCE (!arg)) +return -ENOMEM ; + ret =trace_define_field (call,"u32" , arg, offset,sizeof (int ),0 , +FILTER_OTHER ); +if (ret) +kfree (arg); +return ret; +} +static int __init syscall_enter_define_fields (struct trace_event_call *call) {struct syscall_trace_enter trace;
@@ -544,6 +749,9 @@ static int __init syscall_enter_define_fields(struct trace_event_call *call) offset +=sizeof (unsigned long ); } +if (!ret && meta->syscall_nr == __NR_futex) +return futex_fields (call, offset); +if (ret || !meta->user_mask)return ret;
@@ -689,6 +897,48 @@ static int syscall_copy_user_array(char *buf, const char __user *ptr,return 0 ; } +static int +syscall_get_futex (unsigned long *args,char **buffer,int *size,int buf_size) +{ +struct syscall_user_buffer *sbuf; +const char __user *ptr; +char *buf; + +/* buf_size of zero means user doesn't want user space read */ +if (!buf_size) +return -1 ; + +/* If the syscall_buffer is NULL, tracing is being shutdown */ + sbuf =READ_ONCE (syscall_buffer); +if (!sbuf) +return -1 ; + + ptr = (char __user *)args[0 ]; + + *buffer =trace_user_fault_read (&sbuf->buf, ptr,4 ,NULL ,NULL ); +if (!*buffer) +return -1 ; + +/* Add room for the value */ + *size +=4 ; + + buf = *buffer; + +return 0 ; +} + +static void syscall_put_futex (struct syscall_metadata *sys_data, +struct syscall_trace_enter *entry, +char *buffer) +{ +u32 *ptr; + +/* Place the futex key into the storage */ + ptr = (void *)entry->args +sizeof (unsigned long ) * sys_data->nb_args; + + *ptr = *(u32 *)buffer; +} + static char *sys_fault_user(unsigned int buf_size, struct syscall_metadata *sys_data, struct syscall_user_buffer *sbuf,
@@ -905,6 +1155,9 @@ static void ftrace_syscall_enter(void *data, struct pt_regs *regs, long id)if (syscall_get_data (sys_data, args, &user_ptr, &size, user_sizes, &uargs, tr->syscall_buf_sz) <0 )return ; + }else if (syscall_nr == __NR_futex) { +if (syscall_get_futex (args, &user_ptr, &size, tr->syscall_buf_sz) <0 ) +return ; } size +=sizeof (*entry) +sizeof (unsigned long ) * sys_data->nb_args;
@@ -921,6 +1174,9 @@ static void ftrace_syscall_enter(void *data, struct pt_regs *regs, long id)if (mayfault)syscall_put_data (sys_data, entry, user_ptr, size, user_sizes, uargs); +else if (syscall_nr == __NR_futex) +syscall_put_futex (sys_data, entry, user_ptr); +trace_event_buffer_commit (&fbuffer); }
@@ -971,14 +1227,18 @@ static int reg_event_syscall_enter(struct trace_event_file *file, {struct syscall_metadata *sys_data = call->data;struct trace_array *tr = file->tr; +bool enable_faults;int ret =0 ;int num; num = sys_data->syscall_nr;if (WARN_ON_ONCE (num <0 || num >= NR_syscalls))return -ENOSYS ; + + enable_faults = sys_data->user_mask || num == __NR_futex; +guard (mutex)(&syscall_trace_lock); -if (sys_data->user_mask) { +if (enable_faults) { ret =syscall_fault_buffer_enable ();if (ret <0 )return ret;
@@ -986,7 +1246,7 @@ static int reg_event_syscall_enter(struct trace_event_file *file,if (!tr->sys_refcount_enter) { ret =register_trace_sys_enter (ftrace_syscall_enter, tr);if (ret <0 ) { -if (sys_data->user_mask) +if (enable_faults)syscall_fault_buffer_disable ();return ret; }
@@ -1011,7 +1271,7 @@ static void unreg_event_syscall_enter(struct trace_event_file *file,WRITE_ONCE (tr->enter_syscall_files[num],NULL );if (!tr->sys_refcount_enter)unregister_trace_sys_enter (ftrace_syscall_enter, tr); -if (sys_data->user_mask) +if (sys_data->user_mask || num == __NR_futex)syscall_fault_buffer_disable (); }
Signature · 1 line
2.51.0
Re: [PATCH 1/2] tracing: Have futex syscall trace event show specific user data
Quoted 15 lines · Steven Rostedt
From: Steven Rostedt <[email protected]>
Add specific reporting of the futex system call. This allows for debugging the futex code a bit easier. Instead of just showing the values passed into the futex system call, read the value of the user space memory pointed to by the addr parameter.
Also make the op parameter more readable by parsing the values to show what the command is:
futex_requeue_p-3251 [002] ..... 2101.068479: sys_futex(uaddr: 0x55e79a4da834 (0x80000cb1), FUTEX_LOCK_PI|FUTEX_PRIVATE_FLAG, val: 0) futex_requeue_p-3248 [001] ..... 2101.068970: sys_futex(uaddr: 0x7f859072f990 (0xcb2), FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME, val: 3250) futex_requeue_p-3252 [005] ..... 2101.069108: sys_futex(uaddr: 0x55e79a4da838 (0), FUTEX_WAIT_REQUEUE_PI|FUTEX_PRIVATE_FLAG, val: 0, timespec: 0x7ffe61076aa0, uaddr2: 0x55e79a4da834, uaddr2: 94453214586932, val3: 0) futex_requeue_p-3252 [005] ..... 2101.069410: sys_futex(uaddr: 0x55e79a4da834 (0x80000cb1), FUTEX_LOCK_PI|FUTEX_PRIVATE_FLAG, val: 0)
Quoted 4 lines
Signed-off-by Steven Rostedt (Google) <[email protected]>--- kernel/trace/trace_syscalls.c | 266 +++++++++++++++++++++++++++++++++- 1 file changed, 263 insertions(+), 3 deletions(-)
Egads, I really dislike how all sorts of syscall crud is 'duplicated' in this file, rather than near or in the actual syscall definition.
Re: [PATCH 1/2] tracing: Have futex syscall trace event show specific user data
Quoted 16 lines · On Wed, 4 Mar 2026 10:07:48 +0100 Peter Zijlstra <[email protected]> wrote:
Quoted 15 lines · Steven Rostedt
From: Steven Rostedt <[email protected]>
Add specific reporting of the futex system call. This allows for debugging the futex code a bit easier. Instead of just showing the values passed into the futex system call, read the value of the user space memory pointed to by the addr parameter.
Also make the op parameter more readable by parsing the values to show what the command is:
futex_requeue_p-3251 [002] ..... 2101.068479: sys_futex(uaddr: 0x55e79a4da834 (0x80000cb1), FUTEX_LOCK_PI|FUTEX_PRIVATE_FLAG, val: 0) futex_requeue_p-3248 [001] ..... 2101.068970: sys_futex(uaddr: 0x7f859072f990 (0xcb2), FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME, val: 3250) futex_requeue_p-3252 [005] ..... 2101.069108: sys_futex(uaddr: 0x55e79a4da838 (0), FUTEX_WAIT_REQUEUE_PI|FUTEX_PRIVATE_FLAG, val: 0, timespec: 0x7ffe61076aa0, uaddr2: 0x55e79a4da834, uaddr2: 94453214586932, val3: 0) futex_requeue_p-3252 [005] ..... 2101.069410: sys_futex(uaddr: 0x55e79a4da834 (0x80000cb1), FUTEX_LOCK_PI|FUTEX_PRIVATE_FLAG, val: 0)
Quoted 7 lines
Quoted 4 lines
Signed-off-by Steven Rostedt (Google) <[email protected]>--- kernel/trace/trace_syscalls.c | 266 +++++++++++++++++++++++++++++++++- 1 file changed, 263 insertions(+), 3 deletions(-)Egads, I really dislike how all sorts of syscall crud is 'duplicated' in this file, rather than near or in the actual syscall definition.
Now I did copy the futex_cmd_has_timeout() which I could just use the futex one by exporting it. But the rest is due to printing the content.
What exactly is "duplicated"? The code is mostly done to display the data, where as the futex syscall code is about implementing it.
What do you suggest in reuse? Or just move some of theses functions into kernel/futex/syscall.c?
-- Steve
PATCH 2/2 tracing: Update futex syscall trace event to show more commands
In reply to Steven RostedtFrom: Steven Rostedt <[email protected]>
Make the futex syscall trace event a little more smart. Have it read the futex_op instruction to determine what else it can save and print. For the appropriate options, it will read the utime (timespec) parameter and show its output as well as the uaddr2.
futex_requeue_p-1154 [004] ..... 144.568339: sys_futex(uaddr: 0x5652b178d834 (0x482), FUTEX_UNLOCK_PI|FUTEX_PRIVATE_FLAG, val: 0) futex_requeue_p-1162 [002] ..... 144.568696: sys_futex(uaddr: 0x7f763b7fece0 (2), FUTEX_WAIT|FUTEX_PRIVATE_FLAG, val: 2) futex_requeue_p-1151 [000] ..... 144.568700: sys_futex(uaddr: 0x7f763b7fece0 (0), FUTEX_WAKE|FUTEX_PRIVATE_FLAG, val: 1) futex_requeue_p-1162 [002] ..... 144.568705: sys_futex(uaddr: 0x7f763b7fece0 (0), FUTEX_WAKE|FUTEX_PRIVATE_FLAG, val: 1) futex_requeue_p-1151 [000] ..... 144.568715: sys_futex(uaddr: 0x7f764369e990 (0x483), FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME, val: 1155) futex_requeue_p-1155 [005] ..... 144.569420: sys_futex(uaddr: 0x5652b178d838 (0), FUTEX_WAIT_REQUEUE_PI|FUTEX_PRIVATE_FLAG, val: 0, timespec: 0x7ffdacfba500 (143.890024054), uaddr2: 0x5652b178d834 (0), val3: 0) futex_requeue_p-1155 [005] ..... 144.569454: sys_futex(uaddr: 0x5652b178d834 (0), FUTEX_LOCK_PI|FUTEX_PRIVATE_FLAG, val: 0)
Signed-off-by Steven Rostedt (Google) <[email protected]>
--- kernel/trace/trace_syscalls.c | 138 +++++++++++++++++++++++++++++----- 1 file changed, 121 insertions(+), 17 deletions(-)
kernel/trace/trace_syscalls.c +121 -17
@@ -273,10 +273,18 @@ static __always_inline bool futex_cmd_has_addr2(u32 cmd)return false; } +struct futex_data { +u32 val1; +u32 val2; +unsigned long ts1; +unsigned long ts2; +}; +static enum print_line_t sys_enter_futex_print (struct syscall_trace_enter *trace,struct syscall_metadata *entry,struct trace_seq *s,struct trace_event *event,int ent_size) { +struct futex_data *data;bool done = false;unsigned int op, cmd;void *end = (void *)trace + ent_size;
@@ -285,8 +293,10 @@ sys_enter_futex_print(struct syscall_trace_enter *trace, struct syscall_metadata/* Set ptr to the user space copied area */ ptr = (void *)trace->args +sizeof (unsigned long ) * entry->nb_args; -if (ptr +4 > end) - ptr =NULL ; +if (ptr +sizeof (*data) > end) + data =NULL ; +else + data = ptr;trace_seq_printf (s,"%s(" , entry->name);
@@ -298,8 +308,8 @@ sys_enter_futex_print(struct syscall_trace_enter *trace, struct syscall_metadataswitch (i) {case 0 :trace_seq_printf (s,"uaddr: 0x%lx" , trace->args[i]); -if (ptr) { -u32 val = *(u32 *)ptr; +if (data) { +u32 val = data->val1;if (val <10 )trace_seq_printf (s," (%u)" , val);else
@@ -338,6 +348,15 @@ sys_enter_futex_print(struct syscall_trace_enter *trace, struct syscall_metadatatrace_seq_printf (s,", timespec: 0x%lx" , trace->args[i]); +if (!data) +continue ; + +if (!data->ts1 && !data->ts2) { +trace_seq_puts (s," (0)" ); +continue ; + } +trace_seq_printf (s," (%lu.%09lu)" , + data->ts1, data->ts2);continue ;case 4 :
@@ -346,6 +365,12 @@ sys_enter_futex_print(struct syscall_trace_enter *trace, struct syscall_metadatacontinue ; }trace_seq_printf (s,", uaddr2: 0x%lx" , trace->args[i]); + +if (!data) +continue ; + +trace_seq_printf (s," (%x)" , data->val2); +continue ; } trace_seq_printf(s, ", %s: %lu", entry->args[i],
@@ -570,9 +595,9 @@ sys_enter_futex_print_fmt(struct syscall_metadata *entry, char *buf, int len) pos +=snprintf (buf + pos,LEN_OR_ZERO ,"\"uaddr: 0x%%lx (0x%%lx) cmd=%%s%%s%%s" ); pos +=snprintf (buf + pos,LEN_OR_ZERO , -" val: 0x%%x timeout/val2: 0x%%llx" ); +" val: 0x%%x timeout/val2: 0x%%llx (%%lu.%%lu)" ); pos +=snprintf (buf + pos,LEN_OR_ZERO , -" uaddr2: 0x%%lx val3: 0x%%x\", " ); +" uaddr2: 0x%%lx (0x%%lx) val3: 0x%%x\", " ); pos +=snprintf (buf + pos,LEN_OR_ZERO ," REC->uaddr," );
@@ -618,10 +643,12 @@ sys_enter_futex_print_fmt(struct syscall_metadata *entry, char *buf, int len) FUTEX_CLOCK_REALTIME); pos +=snprintf (buf + pos,LEN_OR_ZERO , -" REC->val, REC->utime," ); +" REC->val, REC->utime, REC->__ts1, REC->__ts2," ); pos +=snprintf (buf + pos,LEN_OR_ZERO , -" REC->uaddr, REC->val3" ); +" REC->uaddr," ); + pos +=snprintf (buf + pos,LEN_OR_ZERO , +" REC->__value2, REC->val3" );return pos; }
@@ -724,7 +751,39 @@ static int __init futex_fields(struct trace_event_call *call, int offset) ret =trace_define_field (call,"u32" , arg, offset,sizeof (int ),0 ,FILTER_OTHER );if (ret) -kfree (arg); + goto free; + offset +=sizeof (int ); + + arg =kstrdup ("__value2" ,GFP_KERNEL ); +if (WARN_ON_ONCE (!arg)) +return -ENOMEM ; + ret =trace_define_field (call,"u32" , arg, offset,sizeof (int ),0 , +FILTER_OTHER ); +if (ret) + goto free; + offset +=sizeof (int ); + + arg =kstrdup ("__ts1" ,GFP_KERNEL ); +if (WARN_ON_ONCE (!arg)) +return -ENOMEM ; + ret =trace_define_field (call,"unsigned long" , arg, offset, +sizeof (unsigned long ),0 ,FILTER_OTHER ); +if (ret) + goto free; + offset +=sizeof (long ); + + arg =kstrdup ("__ts2" ,GFP_KERNEL ); +if (WARN_ON_ONCE (!arg)) +return -ENOMEM ; + ret =trace_define_field (call,"unsigned long" , arg, offset, +sizeof (unsigned long ),0 ,FILTER_OTHER ); +if (ret) + goto free; + +return 0 ; + +free: +kfree (arg);return ret; }
@@ -897,11 +956,51 @@ static int syscall_copy_user_array(char *buf, const char __user *ptr,return 0 ; } +struct tp_futex_data { +u32 cmd; +const u32 __user *val1; +const u32 __user *val2; +void __user *timeout; +}; + +static int syscall_copy_futex (char *buf,const char __user *ptr, +size_t size,void *data) +{ +struct tp_futex_data *tp_data = data; +struct futex_data *fdata = (void *)buf; +int cmd = tp_data->cmd &FUTEX_CMD_MASK ; +int ret; + +memset (fdata,0 ,sizeof (*fdata)); + +if (tp_data->val1) { + ret =__copy_from_user (&fdata->val1, tp_data->val1,4 ); +if (ret) +return -1 ; + } + +if (tp_data->val2 &&futex_cmd_has_addr2 (cmd)) { + ret =__copy_from_user (&fdata->val2, tp_data->val2,4 ); +if (ret) +return -1 ; + } + +if (tp_data->timeout &&futex_cmd_has_timeout (cmd)) { +/* Copies both ts1 and ts2 */ + ret =__copy_from_user (&fdata->ts1, tp_data->timeout, +sizeof (long ) *2 ); +if (ret) +return -1 ; + } + +return 0 ; +} +static int syscall_get_futex (unsigned long *args,char **buffer,int *size,int buf_size) {struct syscall_user_buffer *sbuf; -const char __user *ptr; +struct tp_futex_data tp_data;char *buf;/* buf_size of zero means user doesn't want user space read */
@@ -913,14 +1012,18 @@ syscall_get_futex(unsigned long *args, char **buffer, int *size, int buf_size)if (!sbuf)return -1 ; - ptr = (char __user *)args[0 ]; + tp_data.cmd = args[1 ]; + tp_data.val1 = (u32 __user *)args[0 ]; + tp_data.val2 = (u32 __user *)args[4 ]; + tp_data.timeout = (u64 __user *)args[3 ]; - *buffer =trace_user_fault_read (&sbuf->buf, ptr,4 ,NULL ,NULL ); + *buffer =trace_user_fault_read (&sbuf->buf,NULL ,0 , + syscall_copy_futex, &tp_data);if (!*buffer)return -1 ; -/* Add room for the value */ - *size +=4 ; +/* Add room for values */ + *size +=sizeof (struct futex_data ); buf = *buffer;
@@ -931,12 +1034,13 @@ static void syscall_put_futex(struct syscall_metadata *sys_data,struct syscall_trace_enter *entry, char *buffer) { - u32 *ptr; + struct futex_data *fdata = (void *)buffer; +struct futex_data *data;/* Place the futex key into the storage */ - ptr = (void *)entry->args +sizeof (unsigned long ) * sys_data->nb_args; + data = (void *)entry->args +sizeof (unsigned long ) * sys_data->nb_args; - *ptr = *(u32 *)buffer; + *data = *fdata; } static char *sys_fault_user(unsigned int buf_size,
Signature · 1 line
2.51.0
Steven Rostedt
maintainer[PATCH 3/2] tracing: Show TID and flags for PI futex system call trace event
In reply to Steven RostedtFrom: Steven Rostedt <[email protected]>
For the futex system call trace event for FUTEX_LOCK_PI and FUTEX_UNLOCK_PI commands, show the TID from the value (which is usually in hex) as well as translate the flags (DIED and WAITERS).
pi_mutex_hammer-1098 [000] ..... 121.876928: sys_futex(uaddr: 0x560f40cc8180 (0x450) tid: 1104, FUTEX_LOCK_PI|FUTEX_PRIVATE_FLAG, val: 0, timespec: 0x7f2f9d4b1e50 (0.000100000)) pi_mutex_hammer-1128 [000] ..... 121.877120: sys_futex(uaddr: 0x560f40cc8180 (0x8000042a) tid: 1066 (WAITERS), FUTEX_LOCK_PI|FUTEX_PRIVATE_FLAG, val: 0, timespec: 0x7f2f8e493e50 (0.000100000)) pi_mutex_hammer-1106 [000] ..... 121.877242: sys_futex(uaddr: 0x560f40cc8180 (0x80000452) tid: 1106 (WAITERS), FUTEX_UNLOCK_PI|FUTEX_PRIVATE_FLAG, val: 0)
This makes it easier to see the hand off of a mutex and who the owner was.
Signed-off-by Steven Rostedt (Google) <[email protected]>
--- kernel/trace/trace_syscalls.c | 25 +++++++++++++++++++++++-- 1 file changed, 23 insertions(+), 2 deletions(-)
kernel/trace/trace_syscalls.c +23 -2
@@ -300,6 +300,9 @@ sys_enter_futex_print(struct syscall_trace_enter *trace, struct syscall_metadatatrace_seq_printf (s,"%s(" , entry->name); + op = trace->args[1 ]; + cmd = op &FUTEX_CMD_MASK ; +for (i =0 ; !done && i < entry->nb_args; i++) {if (trace_seq_has_overflowed (s))
@@ -314,11 +317,29 @@ sys_enter_futex_print(struct syscall_trace_enter *trace, struct syscall_metadatatrace_seq_printf (s," (%u)" , val); else trace_seq_printf(s, " (0x%x)", val); + +switch (cmd) { +case FUTEX_LOCK_PI : +case FUTEX_UNLOCK_PI : +trace_seq_printf (s," tid: %d" , val &FUTEX_TID_MASK ); + +if (!(val & (FUTEX_OWNER_DIED |FUTEX_WAITERS ))) +break ; + +trace_seq_puts (s," (" ); +if (val &FUTEX_WAITERS ) +trace_seq_puts (s,"WAITERS" ); +if (val &FUTEX_OWNER_DIED ) { +if (op &FUTEX_WAITERS ) +trace_seq_putc (s,'|' ); +trace_seq_puts (s,"DIED" ); + } +trace_seq_putc (s,')' ); +break ; + } }continue ;case 1 : - op = trace->args[i]; - cmd = op &FUTEX_CMD_MASK ;if (cmd <=FUTEX_LOCK_PI2 )trace_seq_printf (s,", %s" , __futex_cmds[cmd]);else
Signature · 1 line
2.51.0