Re: [PATCH v2 1/3] tracing/syscalls: Rename variable 'nr' to 'syscall_nr'

[Taeung Song <treeze.taeung@gmail.com>]

On 02/26/2016 09:24 PM, Taeung Song wrote:
> Hi, Arnaldo
>
> On 02/26/2016 03:42 AM, Arnaldo Carvalho de Melo wrote:
>> Em Fri, Feb 26, 2016 at 03:31:19AM +0900, Taeung Song escreveu:
>>> Hi, Arnaldo
>>>
>>> On 02/26/2016 02:57 AM, Arnaldo Carvalho de Melo wrote:
>>>> Em Fri, Feb 26, 2016 at 02:38:57AM +0900, Taeung Song escreveu:
>>>>> There is a problem about duplicated variable name i.e.
>>>>>      # cat
>>>>> /sys/kernel/debug/tracing/events/syscalls/sys_enter_io_getevents/format
>>>>>
>>>>>      name: sys_enter_io_getevents
>>>>>      ID: 739
>>>>>      format:
>>>>>              field:unsigned short common_type; offset:0;  size:2;
>>>>> signed:0;
>>>>>              field:unsigned char common_flags; offset:2;  size:1;
>>>>> signed:0;
>>>>>              field:unsigned char common_preempt_count; offset:3;
>>>>> size:1; signed:0;
>>>>>              field:int common_pid;offset:4;size:4;signed:1;
>>>>>              field:int nr;                     offset:8;  size:4;
>>>>> signed:1;
>>>>>              field:aio_context_t ctx_id;       offset:16; size:8;
>>>>> signed:0;
>>>>>              field:long min_nr;                offset:24; size:8;
>>>>> signed:0;
>>>>>              field:long nr;                    offset:32; size:8;
>>>>> signed:0;
>>>>>              field:struct io_event * events;   offset:40; size:8;
>>>>> signed:0;
>>>>>              field:struct timespec * timeout;  offset:48; size:8;
>>>>> signed:0;
>>>>>
>>>>>              print fmt: "ctx_id: 0x%08lx, min_nr: 0x%08lx, nr:
>>>>> 0x%08lx,
>>>>>                          events: 0x%08lx, timeout: 0x%08lx",
>>>>> ((unsigned long)(REC->ctx_id)),
>>>>>                          ((unsigned long)(REC->min_nr)), ((unsigned
>>>>> long)(REC->nr)),
>>>>>                          ((unsigned long)(REC->events)), ((unsigned
>>>>> long)(REC->timeout))
>>>>>
>>>>> As above 'int nr;' and 'long nr;' variables have
>>>>> duplicated name so problems are occurred in perf-script i.e.
>>>>>
>>>>>      # perf record -e syscalls:*
>>>>>      # perf script -g python
>>>>>      # perf script -s perf-script.py
>>>>>        File "perf-script.py", line 8694
>>>>>          def syscalls__sys_enter_io_getevents(event_name, context,
>>>>> common_cpu,
>>>>>      SyntaxError: duplicate argument 'nr' in function definition
>>>>>      Error running python script perf-script.py
>>>>
>>>> Please test this with 'perf trace', which this patch breaks, this patch
>>>> should make it understand this 3rd variation of the non common list of
>>>> fields in syscall tracepoints:
>>>
>>> OK, I will test it.
>>> But IMHO, I think the bottom change has a problem.
>>> Because sys_enter_io_getevent() has a argument 'long nr'.
>>
>> It doesn't matter
>>
>>> So this if statement must not have strcmp(sc->args->name, "nr") == 0.
>>
>> This is checking for the first variable, if that has that name, it
>> should be discarded, as in the past it wasn't there, so for the tool to
>> work on kernels with "nr" as the first (for the syscall number) variable
>> and for kernels without it, we must check and discard.
>>
>> Now we must check and discard the first "nr" (for kernels with this
>> meaning the syscall number) and also if it is called "syscall_nr").
>> The other fields are taken as the syscall arguments, in the order that
>> they come, that is what what we will match with what is in the
>> raw_syscalls:sys_enter args array:
>>
>> [root@jouet ~]# cat
>> /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/format
>> name: sys_enter
>> ID: 17
>> format:
>>     field:unsigned short common_type;    offset:0;    size:2; signed:0;
>>     field:unsigned char common_flags;    offset:2;    size:1; signed:0;
>>     field:unsigned char common_preempt_count;    offset:3; size:1;
>> signed:0;
>>     field:int common_pid;    offset:4;    size:4;    signed:1;
>>
>>     field:long id;    offset:8;    size:8;    signed:1;
>>     field:unsigned long args[6];    offset:16;    size:48; signed:0;
>>
>> print fmt: "NR %ld (%lx, %lx, %lx, %lx, %lx, %lx)", REC->id,
>> REC->args[0], REC->args[1], REC->args[2], REC->args[3], REC->args[4],
>> REC->args[5]
>> [root@jouet ~]#
>>
>>> + if (sc->args && strcmp(sc->args->name, "syscall_nr") == 0) {
>>>
>>> I think the above instance seem better than the bottom.
>>>
>>> +    if (sc->args && (strcmp(sc->args->name, "syscall_nr") ||
>>> strcmp(sc->args->name, "nr")) == 0) {
>>
>> Right in this 'if' body we do:
>>
>>         sc->args = sc->args->next;
>>         sc->nr_args--;
>>
>> something like that.
>>
>> - Arnaldo
>>
>>> But I'll test again with perf-trace.
>>
>> Right, look at the output of 'perf trace' before and after, so that you
>> can check if, say, we're using that syscall_nr value as the fd for the
>> 'write' syscall ('fd' comes right after 'nr'/'syscall_nr').
>>
>
> Sorry, I'm late.
>
> I tested perf-trace with the bottom change.
> (does not rename it to '__syscall_nr' on kernel)
>
> +        if (sc->args && (strcmp(sc->args->name, "__syscall_nr") ||
> strcmp(sc->args->name, "nr")) == 0) {
>                   sc->args = sc->args->next;
>                   --sc->nr_args;
>           }
>
> But there are some problems as below.
>
> 0.322 ( 0.012 ms): a.out/27045 write(nr: 3, fd: 4196046, buf: 0x4,
> count: 2140 ) = 4
>
> So, I modified the above change. (I'll send it as new patch)
> And then I tested again as below
>
> 0.345 ( 0.016 ms): a.out/27695 write(fd: 3, buf: 0x4006ce, count: 4 ) = 4
>
> And I tested perf-trace with renamed '__syscall_nr' on modified kernel.
> Everything is ok for aught I know.
>
> 0.345 ( 0.016 ms): a.out/27695 write(fd: 3, buf: 0x4006ce, count: 4 ) = 4
>
> I'm writing another patchset. I'll send it soon.
>

     [Result of perf-trace test about exception handling for 'nr' or 
'__syscall_nr']


diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index 20916dd..a252f3a 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -1724,8 +1724,12 @@ static int trace__read_syscall_info(struct trace 
*trace, int id)

          sc->args = sc->tp_format->format.fields;
          sc->nr_args = sc->tp_format->format.nr_fields;
-        /* drop nr field - not relevant here; does not exist on older 
kernels */
-        if (sc->args && strcmp(sc->args->name, "nr") == 0) {
+        /*
+         * We need to check and discard the first variable '__syscall_nr'
+         * or 'nr' that mean the syscall number. It is needless here.
+         * So drop '__syscall_nr' or 'nr' field but does not exist on 
older kernels.
+         */
+        if (sc->args && (!strcmp(sc->args->name, "__syscall_nr") || 
!strcmp(sc->args->name, "nr"))) {
                  sc->args = sc->args->next;
                  --sc->nr_args;
          }


Case 1) => "original environment"
kernel : has 'nr' (4.2.0-30-generic)
builtin-trace.c : not modified

     # perf trace ./a.out
     ...(omitted)...
     0.369 ( 0.099 ms): a.out/3790 write(fd: 3, buf: 0x4006ce, count: 4 
) = 4
     ...(omitted)...

Case 2)
kernel : has 'nr' (4.2.0-30-generic)
builtin-trace.c : modified

     # perf trace ./a.out
     0.269 ( 0.012 ms): a.out/4488 write(fd: 3, buf: 0x4006ce, count: 4 
) = 4

Case 3) => "has some problems"
kernel : has '__syscall_nr' (4.5.0-rc4+)
builtin-trace.c : not modified

     # perf trace ./a.out
     0.288 ( 0.009 ms): a.out/4452 write(__syscall_nr: 3, fd: 4196046, 
buf: 0x4, count: 2140 ) = 4

Case 4) => "final environment"
kernel : has '__syscall_nr' (4.5.0-rc4+)
builtin-trace.c : modified (for '__syscall_nr')


     # perf trace ./a.out
     0.334 ( 0.012 ms): a.out/5517 write(fd: 3, buf: 0x4006ce, count: 4 
) = 4


I'll send modified patchset soon.

Thanks,
Taeung