Re: [LTTng-modules PATCH] The msg part of the printk:console event was 1 character too long

Re: [LTTng-modules PATCH] The msg part of the printk:console event was 1 character too long

[Mathieu Desnoyers]

* Yannick Brosseau (yannick.brosseau@gmail.com) wrote:
> Signed-off-by: Yannick Brosseau <yannick.brosseau@gmail.com>
> ---
>  instrumentation/events/lttng-module/printk.h |    2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/instrumentation/events/lttng-module/printk.h b/instrumentation/events/lttng-module/printk.h
> index 4c744f9..f4b6028 100644
> --- a/instrumentation/events/lttng-module/printk.h
> +++ b/instrumentation/events/lttng-module/printk.h
> @@ -19,7 +19,7 @@ TRACE_EVENT_CONDITION(console,
>  
>  	TP_STRUCT__entry(
>  		__dynamic_array_text(char, msg,
> -			min_t(unsigned, end - start, MSG_TRACE_MAX_LEN) + 1)

this was taken from the Linux kernel mainline instrumentation, no ?

Has this been fixed upstream ? If so, can you cite the commit in the
changelog ?

Thanks,

Mathieu

> +			min_t(unsigned, end - start, MSG_TRACE_MAX_LEN))
>  	),
>  
>  	TP_fast_assign(
> -- 
> 1.7.10.4
> 

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [LTTng-modules PATCH] The msg part of the printk:console event was 1 character too long

[Yannick Brosseau]

On 2013-06-28 15:43, Mathieu Desnoyers wrote:
> * Yannick Brosseau (yannick.brosseau@gmail.com) wrote:
>> Signed-off-by: Yannick Brosseau <yannick.brosseau@gmail.com>
>> ---
>>  instrumentation/events/lttng-module/printk.h |    2 +-
>>  1 file changed, 1 insertion(+), 1 deletion(-)
>>
>> diff --git a/instrumentation/events/lttng-module/printk.h b/instrumentation/events/lttng-module/printk.h
>> index 4c744f9..f4b6028 100644
>> --- a/instrumentation/events/lttng-module/printk.h
>> +++ b/instrumentation/events/lttng-module/printk.h
>> @@ -19,7 +19,7 @@ TRACE_EVENT_CONDITION(console,
>>  
>>  	TP_STRUCT__entry(
>>  		__dynamic_array_text(char, msg,
>> -			min_t(unsigned, end - start, MSG_TRACE_MAX_LEN) + 1)
> this was taken from the Linux kernel mainline instrumentation, no ?
>
> Has this been fixed upstream ? If so, can you cite the commit in the
> changelog ?
>
>
It's not changed upstream. From what I see, ftrace does the right thing,
but not LTTng. Will check perf and see if I can reproduce the problem
directly with the upstream kernel.

Re: [LTTng-modules PATCH] The msg part of the printk:console event was 1 character too long

[Mathieu Desnoyers]

* Yannick Brosseau (yannick.brosseau@gmail.com) wrote:
> On 2013-06-28 15:43, Mathieu Desnoyers wrote:
> > * Yannick Brosseau (yannick.brosseau@gmail.com) wrote:
> >> Signed-off-by: Yannick Brosseau <yannick.brosseau@gmail.com>
> >> ---
> >>  instrumentation/events/lttng-module/printk.h |    2 +-
> >>  1 file changed, 1 insertion(+), 1 deletion(-)
> >>
> >> diff --git a/instrumentation/events/lttng-module/printk.h b/instrumentation/events/lttng-module/printk.h
> >> index 4c744f9..f4b6028 100644
> >> --- a/instrumentation/events/lttng-module/printk.h
> >> +++ b/instrumentation/events/lttng-module/printk.h
> >> @@ -19,7 +19,7 @@ TRACE_EVENT_CONDITION(console,
> >>  
> >>  	TP_STRUCT__entry(
> >>  		__dynamic_array_text(char, msg,
> >> -			min_t(unsigned, end - start, MSG_TRACE_MAX_LEN) + 1)
> > this was taken from the Linux kernel mainline instrumentation, no ?
> >
> > Has this been fixed upstream ? If so, can you cite the commit in the
> > changelog ?
> >
> >
> It's not changed upstream. From what I see, ftrace does the right thing,
> but not LTTng. Will check perf and see if I can reproduce the problem
> directly with the upstream kernel.

in 3.9.8, I see:

        TP_STRUCT__entry(
                __dynamic_array(char, msg, end - start + 1)
        ),

(upstream)

which has the +1.

What effect of the off-by-one are you observing exactly ? Are you sure
your fix is the right fix ? I wonder if modifying the TP_fast_assign()
code would not be better. I'm not sure why #if (LINUX_VERSION_CODE >=
KERNEL_VERSION(3,5,0)) has a different code from mainline. CCing Andrew
Gabbasov who contributed this instrumentation.

Thanks,

Mathieu


-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [LTTng-modules PATCH] The msg part of the printk:console event was 1 character too long

[Gabbasov, Andrew]

> From: Mathieu Desnoyers [mathieu.desnoyers@efficios.com]
> Sent: Monday, July 01, 2013 00:20
> To: Yannick Brosseau; Gabbasov, Andrew
> Cc: lttng-dev@lists.lttng.org
> Subject: Re: [lttng-dev] [LTTng-modules PATCH] The msg part of the      printk:console event was 1 character too long
> 
> * Yannick Brosseau (yannick.brosseau@gmail.com) wrote:
> > On 2013-06-28 15:43, Mathieu Desnoyers wrote:
> > > * Yannick Brosseau (yannick.brosseau@gmail.com) wrote:
> > >> Signed-off-by: Yannick Brosseau <yannick.brosseau@gmail.com>
> > >> ---
> > >>  instrumentation/events/lttng-module/printk.h |    2 +-
> > >>  1 file changed, 1 insertion(+), 1 deletion(-)
> > >>
> > >> diff --git a/instrumentation/events/lttng-module/printk.h b/instrumentation/events/lttng-module/printk.h
> > >> index 4c744f9..f4b6028 100644
> > >> --- a/instrumentation/events/lttng-module/printk.h
> > >> +++ b/instrumentation/events/lttng-module/printk.h
> > >> @@ -19,7 +19,7 @@ TRACE_EVENT_CONDITION(console,
> > >>
> > >>    TP_STRUCT__entry(
> > >>            __dynamic_array_text(char, msg,
> > >> -                  min_t(unsigned, end - start, MSG_TRACE_MAX_LEN) + 1)
> > > this was taken from the Linux kernel mainline instrumentation, no ?
> > >
> > > Has this been fixed upstream ? If so, can you cite the commit in the
> > > changelog ?
> > >
> > >
> > It's not changed upstream. From what I see, ftrace does the right thing,
> > but not LTTng. Will check perf and see if I can reproduce the problem
> > directly with the upstream kernel.
> 
> in 3.9.8, I see:
> 
>         TP_STRUCT__entry(
>                 __dynamic_array(char, msg, end - start + 1)
>         ),
> 
> (upstream)
> 
> which has the +1.
> 
> What effect of the off-by-one are you observing exactly ? Are you sure
> your fix is the right fix ? I wonder if modifying the TP_fast_assign()
> code would not be better. I'm not sure why #if (LINUX_VERSION_CODE >=
> KERNEL_VERSION(3,5,0)) has a different code from mainline. CCing Andrew
> Gabbasov who contributed this instrumentation.
> 
> Thanks,
> 
> Mathieu

Hi Mathieu, Yannick,

Actually I also don't see why having +1 is wrong. Trailing zero byte needs
it in the message length. Removing it in entry and not changing
TP_fast_assign (that explicitly adds a zero byte) looks doubtful.
I join to the question what the exact problem is, since my testing
(at least on version 3.5) didn't show any problem.

As for the different implementation code: starting version 3.5
the kernel no longer use circular buffer for storing printk messages,
and handling the message in 2 pieces what it crosses the boundary
is no longer needed. Moreover, log_buf_len becomes not necessarily
the power of 2, and previous implementation (based on what was
in the kernel) just becomes incorrect. So, the newer and simpler
implementation was introduced for later version. It also looks like
this instrumentation needs to be further updated for version 3.10,
since the whole tracepoint (even the parameters set) was changed
there, becoming even more simple.

Thanks.

Best regards,
Andrew

[LTTng-modules PATCH] The msg part of the printk:console event was 1 character too long

[Yannick Brosseau]

Signed-off-by: Yannick Brosseau <yannick.brosseau@gmail.com>
---
 instrumentation/events/lttng-module/printk.h |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/instrumentation/events/lttng-module/printk.h b/instrumentation/events/lttng-module/printk.h
index 4c744f9..f4b6028 100644
--- a/instrumentation/events/lttng-module/printk.h
+++ b/instrumentation/events/lttng-module/printk.h
@@ -19,7 +19,7 @@ TRACE_EVENT_CONDITION(console,
 
 	TP_STRUCT__entry(
 		__dynamic_array_text(char, msg,
-			min_t(unsigned, end - start, MSG_TRACE_MAX_LEN) + 1)
+			min_t(unsigned, end - start, MSG_TRACE_MAX_LEN))
 	),
 
 	TP_fast_assign(
-- 
1.7.10.4