[libtraceevent] hrtimer_expire_entry unknown op '{'

[libtraceevent] hrtimer_expire_entry unknown op '{'

[Sergey Senozhatsky]

Hello,

libtraceevent reports ` unknown op '{' ' while processing hrtimer_expire_entry event

cat /sys/kernel/debug/tracing/events/timer/hrtimer_expire_entry/format

name: hrtimer_expire_entry
ID: 91
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:void * hrtimer;	offset:8;	size:8;	signed:0;
	field:s64 now;	offset:16;	size:8;	signed:1;
	field:void * function;	offset:24;	size:8;	signed:0;

print fmt: "hrtimer=%p function=%pf now=%llu", REC->hrtimer, REC->function, (unsigned long long)(((ktime_t) { .tv64 = REC->now }).tv64)


	-ss

Re: [libtraceevent] hrtimer_expire_entry unknown op '{'

[Steven Rostedt]

On Tue, 5 Nov 2013 12:37:55 +0300
Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:

> Hello,
> 
> libtraceevent reports ` unknown op '{' ' while processing hrtimer_expire_entry event

Yes, we need to port the plugin code from trace-cmd to handle this and
other cases. It's a known issue.

-- Steve

> 
> cat /sys/kernel/debug/tracing/events/timer/hrtimer_expire_entry/format
> 
> name: hrtimer_expire_entry
> ID: 91
> 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:void * hrtimer;	offset:8;	size:8;	signed:0;
> 	field:s64 now;	offset:16;	size:8;	signed:1;
> 	field:void * function;	offset:24;	size:8;	signed:0;
> 
> print fmt: "hrtimer=%p function=%pf now=%llu", REC->hrtimer, REC->function, (unsigned long long)(((ktime_t) { .tv64 = REC->now }).tv64)
> 
> 
> 	-ss

Re: [libtraceevent] hrtimer_expire_entry unknown op '{'

[Sergey Senozhatsky]

On (11/05/13 08:15), Steven Rostedt wrote:
> Date: Tue, 5 Nov 2013 08:15:22 -0500
> From: Steven Rostedt <rostedt@goodmis.org>
> To: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Cc: Arnaldo Carvalho de Melo <acme@redhat.com>, Namhyung Kim
>  <namhyung@kernel.org>, Jon Stanley <jonstanley@gmail.com>, Sasha Levin
>  <sasha.levin@oracle.com>, linux-kernel@vger.kernel.org
> Subject: Re: [libtraceevent] hrtimer_expire_entry unknown op '{'
> X-Mailer: Claws Mail 3.9.2 (GTK+ 2.24.20; x86_64-pc-linux-gnu)
> 
> On Tue, 5 Nov 2013 12:37:55 +0300
> Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:
> 
> > Hello,
> > 
> > libtraceevent reports ` unknown op '{' ' while processing hrtimer_expire_entry event
> 
> Yes, we need to port the plugin code from trace-cmd to handle this and
> other cases. It's a known issue.
> 

oh, sorry for the noise then. thanks.

	-ss

> -- Steve
> 
> > 
> > cat /sys/kernel/debug/tracing/events/timer/hrtimer_expire_entry/format
> > 
> > name: hrtimer_expire_entry
> > ID: 91
> > 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:void * hrtimer;	offset:8;	size:8;	signed:0;
> > 	field:s64 now;	offset:16;	size:8;	signed:1;
> > 	field:void * function;	offset:24;	size:8;	signed:0;
> > 
> > print fmt: "hrtimer=%p function=%pf now=%llu", REC->hrtimer, REC->function, (unsigned long long)(((ktime_t) { .tv64 = REC->now }).tv64)
> > 
> > 
> > 	-ss
> 

Re: [libtraceevent] hrtimer_expire_entry unknown op '{'

[Sergey Senozhatsky]

On (11/05/13 08:15), Steven Rostedt wrote:
> > Hello,
> > 
> > libtraceevent reports ` unknown op '{' ' while processing hrtimer_expire_entry event
> 
> Yes, we need to port the plugin code from trace-cmd to handle this and
> other cases. It's a known issue.
> 

Hello Steven,
sorry if I'm bothering you with already known issue.

I cloned trace-cmd from
git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git

and there seems to be problems with hrtimer events format.

# ./trace-cmd check-events
trace-cmd: No such file or directory
  bad op token {
  bad op token {
  bad op token {
  bad op token {
  function is_writable_pte not defined
  function scsi_trace_parse_cdb not defined
  function scsi_trace_parse_cdb not defined
  function scsi_trace_parse_cdb not defined
  function scsi_trace_parse_cdb not defined
  function jiffies_to_msecs not defined
  function jiffies_to_msecs not defined
  unknown op '{'
  unknown op '{'


trivial strace-ing shows that 'unknown op' comes from hrtimer_expire_entry

stat("/sys/kernel/debug/tracing/events/timer/hrtimer_expire_entry/format", {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
open("/sys/kernel/debug/tracing/events/timer/hrtimer_expire_entry/format", O_RDONLY) = 5
read(5, "name: hrtimer_expire_entry\nID: 9"..., 8192) = 577
read(5, "", 8192)                       = 0
close(5)                                = 0
write(2, "  ", 2)                       = 2
write(2, "unknown op '{'", 14)          = 14
write(2, "\n", 1)                       = 1


./trace-cmd record -e timer ls /bin
./trace-cmd report

     kworker/1:0-3925  [001]  1626.266585: hrtimer_cancel:       hrtimer=0xffff880157c8df80
               X-2175  [000]  1626.266585: hrtimer_cancel:       hrtimer=0xffff880157c0df80
               X-2175  [000]  1626.266586: hrtimer_expire_entry: [FAILED TO PARSE] hrtimer=0xffff880157c0df80 now=1625348004324 function=0xffffffff810cadf0
     kworker/1:0-3925  [001]  1626.266586: hrtimer_expire_entry: [FAILED TO PARSE] hrtimer=0xffff880157c8df80 now=1625348004320 function=0xffffffff810cadf0
     kworker/1:0-3925  [001]  1626.266591: hrtimer_expire_exit:  hrtimer=0xffff880157c8df80
     kworker/1:0-3925  [001]  1626.266592: hrtimer_start:        [FAILED TO PARSE] hrtimer=0xffff880157c8df80 function=0xffffffff810cadf0 expires=1625352000000 softexpires=1625352000000
               X-2175  [000]  1626.266593: hrtimer_expire_exit:  hrtimer=0xffff880157c0df80
               X-2175  [000]  1626.266594: hrtimer_start:        [FAILED TO PARSE] hrtimer=0xffff880157c0df80 function=0xffffffff810cadf0 expires=1625352000000 softexpires=1625352000000
     kworker/1:0-3925  [001]  1626.266596: timer_cancel:         timer=0xffff880157c8ff28
     kworker/1:0-3925  [001]  1626.266598: timer_expire_entry:   timer=0xffff880157c8ff28 function=delayed_work_timer_fn now=4295298633
               X-2175  [000]  1626.266599: timer_cancel:         timer=0xffff880157c0ff28
               X-2175  [000]  1626.266599: timer_expire_entry:   timer=0xffff880157c0ff28 function=delayed_work_timer_fn now=4295298633

thank you,

	-ss


> -- Steve
> 
> > 
> > cat /sys/kernel/debug/tracing/events/timer/hrtimer_expire_entry/format
> > 
> > name: hrtimer_expire_entry
> > ID: 91
> > 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:void * hrtimer;	offset:8;	size:8;	signed:0;
> > 	field:s64 now;	offset:16;	size:8;	signed:1;
> > 	field:void * function;	offset:24;	size:8;	signed:0;
> > 
> > print fmt: "hrtimer=%p function=%pf now=%llu", REC->hrtimer, REC->function, (unsigned long long)(((ktime_t) { .tv64 = REC->now }).tv64)
> > 
> > 
> > 	-ss
> 

Re: [libtraceevent] hrtimer_expire_entry unknown op '{'

[Steven Rostedt]

On Wed, 13 Nov 2013 00:31:52 +0300
Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:

> On (11/05/13 08:15), Steven Rostedt wrote:
> > > Hello,
> > > 
> > > libtraceevent reports ` unknown op '{' ' while processing hrtimer_expire_entry event
> > 
> > Yes, we need to port the plugin code from trace-cmd to handle this and
> > other cases. It's a known issue.
> > 
> 
> Hello Steven,
> sorry if I'm bothering you with already known issue.
> 
> I cloned trace-cmd from
> git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git
> 
> and there seems to be problems with hrtimer events format.
> 
> # ./trace-cmd check-events
> trace-cmd: No such file or directory

Do a make install, or copy all the *.so files into ~/.trace-cmd/plugins/
and that will go away.

-- Steve

>   bad op token {
>   bad op token {
>   bad op token {
>   bad op token {
>   function is_writable_pte not defined
>   function scsi_trace_parse_cdb not defined
>   function scsi_trace_parse_cdb not defined
>   function scsi_trace_parse_cdb not defined
>   function scsi_trace_parse_cdb not defined
>   function jiffies_to_msecs not defined
>   function jiffies_to_msecs not defined
>   unknown op '{'
>   unknown op '{'
> 
> 
> trivial strace-ing shows that 'unknown op' comes from hrtimer_expire_entry
> 
> stat("/sys/kernel/debug/tracing/events/timer/hrtimer_expire_entry/format", {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
> open("/sys/kernel/debug/tracing/events/timer/hrtimer_expire_entry/format", O_RDONLY) = 5
> read(5, "name: hrtimer_expire_entry\nID: 9"..., 8192) = 577
> read(5, "", 8192)                       = 0
> close(5)                                = 0
> write(2, "  ", 2)                       = 2
> write(2, "unknown op '{'", 14)          = 14
> write(2, "\n", 1)                       = 1
> 
> 
> ./trace-cmd record -e timer ls /bin
> ./trace-cmd report
> 
>      kworker/1:0-3925  [001]  1626.266585: hrtimer_cancel:       hrtimer=0xffff880157c8df80
>                X-2175  [000]  1626.266585: hrtimer_cancel:       hrtimer=0xffff880157c0df80
>                X-2175  [000]  1626.266586: hrtimer_expire_entry: [FAILED TO PARSE] hrtimer=0xffff880157c0df80 now=1625348004324 function=0xffffffff810cadf0
>      kworker/1:0-3925  [001]  1626.266586: hrtimer_expire_entry: [FAILED TO PARSE] hrtimer=0xffff880157c8df80 now=1625348004320 function=0xffffffff810cadf0
>      kworker/1:0-3925  [001]  1626.266591: hrtimer_expire_exit:  hrtimer=0xffff880157c8df80
>      kworker/1:0-3925  [001]  1626.266592: hrtimer_start:        [FAILED TO PARSE] hrtimer=0xffff880157c8df80 function=0xffffffff810cadf0 expires=1625352000000 softexpires=1625352000000
>                X-2175  [000]  1626.266593: hrtimer_expire_exit:  hrtimer=0xffff880157c0df80
>                X-2175  [000]  1626.266594: hrtimer_start:        [FAILED TO PARSE] hrtimer=0xffff880157c0df80 function=0xffffffff810cadf0 expires=1625352000000 softexpires=1625352000000
>      kworker/1:0-3925  [001]  1626.266596: timer_cancel:         timer=0xffff880157c8ff28
>      kworker/1:0-3925  [001]  1626.266598: timer_expire_entry:   timer=0xffff880157c8ff28 function=delayed_work_timer_fn now=4295298633
>                X-2175  [000]  1626.266599: timer_cancel:         timer=0xffff880157c0ff28
>                X-2175  [000]  1626.266599: timer_expire_entry:   timer=0xffff880157c0ff28 function=delayed_work_timer_fn now=4295298633
> 
> thank you,
> 
> 	-ss
> 
> 
> > -- Steve
> > 
> > > 
> > > cat /sys/kernel/debug/tracing/events/timer/hrtimer_expire_entry/format
> > > 
> > > name: hrtimer_expire_entry
> > > ID: 91
> > > 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:void * hrtimer;	offset:8;	size:8;	signed:0;
> > > 	field:s64 now;	offset:16;	size:8;	signed:1;
> > > 	field:void * function;	offset:24;	size:8;	signed:0;
> > > 
> > > print fmt: "hrtimer=%p function=%pf now=%llu", REC->hrtimer, REC->function, (unsigned long long)(((ktime_t) { .tv64 = REC->now }).tv64)
> > > 
> > > 
> > > 	-ss
> > 

Re: [libtraceevent] hrtimer_expire_entry unknown op '{'

[Sergey Senozhatsky]

On (11/12/13 16:52), Steven Rostedt wrote:
> > On (11/05/13 08:15), Steven Rostedt wrote:
> > > > Hello,
> > > > 
> > > > libtraceevent reports ` unknown op '{' ' while processing hrtimer_expire_entry event
> > > 
> > > Yes, we need to port the plugin code from trace-cmd to handle this and
> > > other cases. It's a known issue.
> > > 
> > 
> > Hello Steven,
> > sorry if I'm bothering you with already known issue.
> > 
> > I cloned trace-cmd from
> > git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git
> > 
> > and there seems to be problems with hrtimer events format.
> > 
> > # ./trace-cmd check-events
> > trace-cmd: No such file or directory
> 
> Do a make install, or copy all the *.so files into ~/.trace-cmd/plugins/
> and that will go away.
>

oh... thanks a lot!

I just quickly went through http://lwn.net/Articles/341902/
(' Just download it, go into the directory and run "make" ')

thank you once again!

	-ss

> -- Steve
> 
> >   bad op token {
> >   bad op token {
> >   bad op token {
> >   bad op token {
> >   function is_writable_pte not defined
> >   function scsi_trace_parse_cdb not defined
> >   function scsi_trace_parse_cdb not defined
> >   function scsi_trace_parse_cdb not defined
> >   function scsi_trace_parse_cdb not defined
> >   function jiffies_to_msecs not defined
> >   function jiffies_to_msecs not defined
> >   unknown op '{'
> >   unknown op '{'
> > 
> > 
> > trivial strace-ing shows that 'unknown op' comes from hrtimer_expire_entry
> > 
> > stat("/sys/kernel/debug/tracing/events/timer/hrtimer_expire_entry/format", {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
> > open("/sys/kernel/debug/tracing/events/timer/hrtimer_expire_entry/format", O_RDONLY) = 5
> > read(5, "name: hrtimer_expire_entry\nID: 9"..., 8192) = 577
> > read(5, "", 8192)                       = 0
> > close(5)                                = 0
> > write(2, "  ", 2)                       = 2
> > write(2, "unknown op '{'", 14)          = 14
> > write(2, "\n", 1)                       = 1
> > 
> > 
> > ./trace-cmd record -e timer ls /bin
> > ./trace-cmd report
> > 
> >      kworker/1:0-3925  [001]  1626.266585: hrtimer_cancel:       hrtimer=0xffff880157c8df80
> >                X-2175  [000]  1626.266585: hrtimer_cancel:       hrtimer=0xffff880157c0df80
> >                X-2175  [000]  1626.266586: hrtimer_expire_entry: [FAILED TO PARSE] hrtimer=0xffff880157c0df80 now=1625348004324 function=0xffffffff810cadf0
> >      kworker/1:0-3925  [001]  1626.266586: hrtimer_expire_entry: [FAILED TO PARSE] hrtimer=0xffff880157c8df80 now=1625348004320 function=0xffffffff810cadf0
> >      kworker/1:0-3925  [001]  1626.266591: hrtimer_expire_exit:  hrtimer=0xffff880157c8df80
> >      kworker/1:0-3925  [001]  1626.266592: hrtimer_start:        [FAILED TO PARSE] hrtimer=0xffff880157c8df80 function=0xffffffff810cadf0 expires=1625352000000 softexpires=1625352000000
> >                X-2175  [000]  1626.266593: hrtimer_expire_exit:  hrtimer=0xffff880157c0df80
> >                X-2175  [000]  1626.266594: hrtimer_start:        [FAILED TO PARSE] hrtimer=0xffff880157c0df80 function=0xffffffff810cadf0 expires=1625352000000 softexpires=1625352000000
> >      kworker/1:0-3925  [001]  1626.266596: timer_cancel:         timer=0xffff880157c8ff28
> >      kworker/1:0-3925  [001]  1626.266598: timer_expire_entry:   timer=0xffff880157c8ff28 function=delayed_work_timer_fn now=4295298633
> >                X-2175  [000]  1626.266599: timer_cancel:         timer=0xffff880157c0ff28
> >                X-2175  [000]  1626.266599: timer_expire_entry:   timer=0xffff880157c0ff28 function=delayed_work_timer_fn now=4295298633
> > 
> > thank you,
> > 
> > 	-ss
> > 
> > 
> > > -- Steve
> > > 
> > > > 
> > > > cat /sys/kernel/debug/tracing/events/timer/hrtimer_expire_entry/format
> > > > 
> > > > name: hrtimer_expire_entry
> > > > ID: 91
> > > > 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:void * hrtimer;	offset:8;	size:8;	signed:0;
> > > > 	field:s64 now;	offset:16;	size:8;	signed:1;
> > > > 	field:void * function;	offset:24;	size:8;	signed:0;
> > > > 
> > > > print fmt: "hrtimer=%p function=%pf now=%llu", REC->hrtimer, REC->function, (unsigned long long)(((ktime_t) { .tv64 = REC->now }).tv64)
> > > > 
> > > > 
> > > > 	-ss
> > > 
> 

Re: [libtraceevent] hrtimer_expire_entry unknown op '{'

[Steven Rostedt]

On Wed, 13 Nov 2013 01:01:53 +0300
Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:
 
> > Do a make install, or copy all the *.so files into ~/.trace-cmd/plugins/
> > and that will go away.
> >
> 
> oh... thanks a lot!
> 
> I just quickly went through http://lwn.net/Articles/341902/
> (' Just download it, go into the directory and run "make" ')

Hmm, good point. I'll have to update the code to let the user know what
to do if it fails to parse. Something like:

 Failed to parse event hrtimer_expire_entry event
  Do you have all the plugins installed?
   Check /usr/lib/trace-cmd/plugins
   If you compiled it yourself, copy the *.so files to ~/.trace-cmd/plugins

-- Steve

> 
> thank you once again!
>