[PATCH] selftests: ftrace: Use md5sum to take less time of checking logs

[PATCH] selftests: ftrace: Use md5sum to take less time of checking logs

[Masami Hiramatsu]

Use md5sum so that it takes less time of checking
trace logs update. Since busybox tail/cat takes too
long time to read the trace log, this uses md5sum
to check whether trace log is updated or not.

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 .../test.d/ftrace/func_traceonoff_triggers.tc      |    6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
index 9cf3852..7a9ab4f 100644
--- a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
+++ b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
@@ -103,11 +103,11 @@ if [ $on != "0" ]; then
     fail "Tracing is not off"
 fi
 
-line1=`cat trace | tail -1`
+csum1=`md5sum trace`
 sleep $SLEEP_TIME
-line2=`cat trace | tail -1`
+csum2=`md5sum trace`
 
-if [ "$line1" != "$line2" ]; then
+if [ "$csum1" != "$csum2" ]; then
     fail "Tracing file is still changing"
 fi
 

Re: [PATCH] selftests: ftrace: Use md5sum to take less time of checking logs

[Shuah Khan]

On 06/27/2017 04:28 AM, Masami Hiramatsu wrote:
> Use md5sum so that it takes less time of checking
> trace logs update. Since busybox tail/cat takes too
> long time to read the trace log, this uses md5sum
> to check whether trace log is updated or not.
> 
> Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>

Applied to linux-kselftest next for 4.13-rc1

thanks,
-- Shuah

> ---
>  .../test.d/ftrace/func_traceonoff_triggers.tc      |    6 +++---
>  1 file changed, 3 insertions(+), 3 deletions(-)
> 
> diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> index 9cf3852..7a9ab4f 100644
> --- a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> +++ b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> @@ -103,11 +103,11 @@ if [ $on != "0" ]; then
>      fail "Tracing is not off"
>  fi
>  
> -line1=`cat trace | tail -1`
> +csum1=`md5sum trace`
>  sleep $SLEEP_TIME
> -line2=`cat trace | tail -1`
> +csum2=`md5sum trace`
>  
> -if [ "$line1" != "$line2" ]; then
> +if [ "$csum1" != "$csum2" ]; then
>      fail "Tracing file is still changing"
>  fi
>  
> 
> 
> 

Re: [PATCH] selftests: ftrace: Use md5sum to take less time of checking logs

[Steven Rostedt]

On Tue, 27 Jun 2017 19:28:32 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> Use md5sum so that it takes less time of checking
> trace logs update. Since busybox tail/cat takes too
> long time to read the trace log, this uses md5sum
> to check whether trace log is updated or not.

How much faster is md5sum? I can see this causing issues in other
environments.

-- Steve

> 
> Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> ---
>  .../test.d/ftrace/func_traceonoff_triggers.tc      |    6 +++---
>  1 file changed, 3 insertions(+), 3 deletions(-)
> 
> diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> index 9cf3852..7a9ab4f 100644
> --- a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> +++ b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> @@ -103,11 +103,11 @@ if [ $on != "0" ]; then
>      fail "Tracing is not off"
>  fi
>  
> -line1=`cat trace | tail -1`
> +csum1=`md5sum trace`
>  sleep $SLEEP_TIME
> -line2=`cat trace | tail -1`
> +csum2=`md5sum trace`
>  
> -if [ "$line1" != "$line2" ]; then
> +if [ "$csum1" != "$csum2" ]; then
>      fail "Tracing file is still changing"
>  fi
>  

Re: [PATCH] selftests: ftrace: Use md5sum to take less time of checking logs

[Shuah Khan]

On 06/28/2017 08:17 AM, Steven Rostedt wrote:
> On Tue, 27 Jun 2017 19:28:32 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
>> Use md5sum so that it takes less time of checking
>> trace logs update. Since busybox tail/cat takes too
>> long time to read the trace log, this uses md5sum
>> to check whether trace log is updated or not.
> 
> How much faster is md5sum? I can see this causing issues in other
> environments.
> 
> -- Steve

Sorry Steve. I pulled this into linux-ksefltest next. Are you concerned
about any specific environments? I can try this out and see if it is a
problem.

thanks,
-- Shuah

> 
>>
>> Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
>> ---
>>  .../test.d/ftrace/func_traceonoff_triggers.tc      |    6 +++---
>>  1 file changed, 3 insertions(+), 3 deletions(-)
>>
>> diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
>> index 9cf3852..7a9ab4f 100644
>> --- a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
>> +++ b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
>> @@ -103,11 +103,11 @@ if [ $on != "0" ]; then
>>      fail "Tracing is not off"
>>  fi
>>  
>> -line1=`cat trace | tail -1`
>> +csum1=`md5sum trace`
>>  sleep $SLEEP_TIME
>> -line2=`cat trace | tail -1`
>> +csum2=`md5sum trace`
>>  
>> -if [ "$line1" != "$line2" ]; then
>> +if [ "$csum1" != "$csum2" ]; then
>>      fail "Tracing file is still changing"
>>  fi
>>  
> 
> 
> 

Re: [PATCH] selftests: ftrace: Use md5sum to take less time of checking logs

[Steven Rostedt]

On Wed, 28 Jun 2017 08:30:24 -0600
Shuah Khan <shuah@kernel.org> wrote:

> On 06/28/2017 08:17 AM, Steven Rostedt wrote:
> > On Tue, 27 Jun 2017 19:28:32 +0900
> > Masami Hiramatsu <mhiramat@kernel.org> wrote:
> >   
> >> Use md5sum so that it takes less time of checking
> >> trace logs update. Since busybox tail/cat takes too
> >> long time to read the trace log, this uses md5sum
> >> to check whether trace log is updated or not.  
> > 
> > How much faster is md5sum? I can see this causing issues in other
> > environments.
> > 
> > -- Steve  
> 
> Sorry Steve. I pulled this into linux-ksefltest next. Are you concerned
> about any specific environments? I can try this out and see if it is a
> problem.

Yes please. I should probably do some playing too. I would like to fix
that test anyway, as it is one of the longer ones as I do a lot of
"paranoid checks". That is, I may go overboard in testing if tracing is
off or not, by checking to make sure its off using different tactics.

-- Steve

Re: [PATCH] selftests: ftrace: Use md5sum to take less time of checking logs

[Shuah Khan]

On 06/28/2017 08:59 AM, Steven Rostedt wrote:
> On Wed, 28 Jun 2017 08:30:24 -0600
> Shuah Khan <shuah@kernel.org> wrote:
> 
>> On 06/28/2017 08:17 AM, Steven Rostedt wrote:
>>> On Tue, 27 Jun 2017 19:28:32 +0900
>>> Masami Hiramatsu <mhiramat@kernel.org> wrote:
>>>   
>>>> Use md5sum so that it takes less time of checking
>>>> trace logs update. Since busybox tail/cat takes too
>>>> long time to read the trace log, this uses md5sum
>>>> to check whether trace log is updated or not.  
>>>
>>> How much faster is md5sum? I can see this causing issues in other
>>> environments.
>>>
>>> -- Steve  
>>
>> Sorry Steve. I pulled this into linux-ksefltest next. Are you concerned
>> about any specific environments? I can try this out and see if it is a
>> problem.
> 
> Yes please. I should probably do some playing too. I would like to fix
> that test anyway, as it is one of the longer ones as I do a lot of
> "paranoid checks". That is, I may go overboard in testing if tracing is
> off or not, by checking to make sure its off using different tactics.
> 

Please let me know how your trials go. I have a few things I have to get
to before I get around to trying this patch.

thanks,
-- Shuah

Re: [PATCH] selftests: ftrace: Use md5sum to take less time of checking logs

[Shuah Khan]

On 06/28/2017 09:30 AM, Shuah Khan wrote:
> On 06/28/2017 08:59 AM, Steven Rostedt wrote:
>> On Wed, 28 Jun 2017 08:30:24 -0600
>> Shuah Khan <shuah@kernel.org> wrote:
>>
>>> On 06/28/2017 08:17 AM, Steven Rostedt wrote:
>>>> On Tue, 27 Jun 2017 19:28:32 +0900
>>>> Masami Hiramatsu <mhiramat@kernel.org> wrote:
>>>>   
>>>>> Use md5sum so that it takes less time of checking
>>>>> trace logs update. Since busybox tail/cat takes too
>>>>> long time to read the trace log, this uses md5sum
>>>>> to check whether trace log is updated or not.  
>>>>
>>>> How much faster is md5sum? I can see this causing issues in other
>>>> environments.
>>>>
>>>> -- Steve  
>>>
>>> Sorry Steve. I pulled this into linux-ksefltest next. Are you concerned
>>> about any specific environments? I can try this out and see if it is a
>>> problem.
>>
>> Yes please. I should probably do some playing too. I would like to fix
>> that test anyway, as it is one of the longer ones as I do a lot of
>> "paranoid checks". That is, I may go overboard in testing if tracing is
>> off or not, by checking to make sure its off using different tactics.
>>
> 
> Please let me know how your trials go. I have a few things I have to get
> to before I get around to trying this patch.
> 
> thanks,
> -- Shuah

Hi Steve/Masami,

I tested this patch on my test system running 4.12-rc7 and didn't see any
problems. I am going to leave this in the linux-kselftest next for 4.13-rc1.
Please let me if you think I should drop it.

thanks,
-- Shuah

Re: [PATCH] selftests: ftrace: Use md5sum to take less time of checking logs

[Steven Rostedt]

On Thu, 29 Jun 2017 14:21:41 -0600
Shuah Khan <shuah@kernel.org> wrote:
\
> Hi Steve/Masami,
> 
> I tested this patch on my test system running 4.12-rc7 and didn't see any
> problems. I am going to leave this in the linux-kselftest next for 4.13-rc1.
> Please let me if you think I should drop it.

I played a little with it.

Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

-- Steve

Re: [PATCH] selftests: ftrace: Use md5sum to take less time of checking logs

[Shuah Khan]

On 06/30/2017 08:49 AM, Steven Rostedt wrote:
> On Thu, 29 Jun 2017 14:21:41 -0600
> Shuah Khan <shuah@kernel.org> wrote:
> \
>> Hi Steve/Masami,
>>
>> I tested this patch on my test system running 4.12-rc7 and didn't see any
>> problems. I am going to leave this in the linux-kselftest next for 4.13-rc1.
>> Please let me if you think I should drop it.
> 
> I played a little with it.
> 
> Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> 
> -- Steve
> 
> 

Thanks. Applied your Ack now to linux-kselftest next.

-- Shuah

Re: [PATCH] selftests: ftrace: Use md5sum to take less time of checking logs

[Masami Hiramatsu]

On Fri, 30 Jun 2017 10:53:15 -0600
Shuah Khan <shuah@kernel.org> wrote:

> On 06/30/2017 08:49 AM, Steven Rostedt wrote:
> > On Thu, 29 Jun 2017 14:21:41 -0600
> > Shuah Khan <shuah@kernel.org> wrote:
> > \
> >> Hi Steve/Masami,
> >>
> >> I tested this patch on my test system running 4.12-rc7 and didn't see any
> >> problems. I am going to leave this in the linux-kselftest next for 4.13-rc1.
> >> Please let me if you think I should drop it.
> > 
> > I played a little with it.
> > 
> > Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> > 
> > -- Steve
> > 
> > 
> 
> Thanks. Applied your Ack now to linux-kselftest next.

Thanks Steve and Shuah!

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH] selftests: ftrace: Use md5sum to take less time of checking logs

[Denys Vlasenko]

On Tue, Jun 27, 2017 at 12:28 PM, Masami Hiramatsu <mhiramat@kernel.org> wrote:
> Use md5sum so that it takes less time of checking
> trace logs update. Since busybox tail/cat takes too
> long time to read the trace log, this uses md5sum
> to check whether trace log is updated or not.
>
> Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> ---
>  .../test.d/ftrace/func_traceonoff_triggers.tc      |    6 +++---
>  1 file changed, 3 insertions(+), 3 deletions(-)
>
> diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> index 9cf3852..7a9ab4f 100644
> --- a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> +++ b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> @@ -103,11 +103,11 @@ if [ $on != "0" ]; then
>      fail "Tracing is not off"
>  fi
>
> -line1=`cat trace | tail -1`
> +csum1=`md5sum trace`
>  sleep $SLEEP_TIME
> -line2=`cat trace | tail -1`
> +csum2=`md5sum trace`

If you replace that with "tail -1 <trace", this code
in busybox will be used:

                        off_t current = lseek(fd, 0, SEEK_END);
                        if (current > 0) {
...
#if 1 /* This is technically incorrect for *LONG* strings, but very useful */
                                /* Optimizing count-lines case if the
file is seekable.
                                 * We assume the lines are <64k.
                                 * (Users complain that tail takes too long
                                 * on multi-gigabyte files) */
                                off = (count | 0xf); /* for small
counts, be more paranoid */
                                if (off > (INT_MAX / (64*1024)))
                                        off = (INT_MAX / (64*1024));
                                current -= off * (64*1024);
                                if (current < 0)
                                        current = 0;
                                xlseek(fd, current, SEEK_SET);
#endif

Example: "tail -1 10GB_FILE" seeks back ~1 mbyte and looks for the last line:

lseek(3, 0, SEEK_END)                   = 10991787403
lseek(3, 10990804363, SEEK_SET)         = 10990804363
read(3, "\0\0020d\340\326\0\0\0\0020e\6\364\0\0\0\0020eMI\0\0\0\0020el\210\0\0"...,
8192) = 8192
read(3, "\0\0021\"p\321\0\0\0\0021\"\216\31\0\0\0\0021\"\254q\0\0\0\0021\"\367u\0\0"...,
8192) = 8192
read(3, "\0\0021\342\216\302\0\0\0\0021\342\2243\0\0\0\0021\342\266T\0\0\0\0021\342\326\v\0\0"...,
8192) = 8192
...
read(3, "\0\0\2\211\3272\211\0\0\0\2\211\3277\235\0\0\0\2\211\327mx\0\0\0\2\211\327\224\22\0"...,
11841) = 11841
read(3, "\0\2\212\357\366\306\0\0\0\2\212\360`\232\0\0\0\2\212\360w\262\0\0\0\2\212\360\354\365\0\0"...,
12512) = 12512
read(3, "\0\2\214uL\3\0\0\0\2\214unc\0\0\0\2\214w_\373\0\0\0\2\214wn\6\0\0"...,
11176) = 8424
read(3, "", 2752)                       = 0

Re: [PATCH] selftests: ftrace: Use md5sum to take less time of checking logs

[Steven Rostedt]

On Fri, 30 Jun 2017 20:50:45 +0200
Denys Vlasenko <vda.linux@googlemail.com> wrote:

> On Tue, Jun 27, 2017 at 12:28 PM, Masami Hiramatsu <mhiramat@kernel.org> wrote:
> > Use md5sum so that it takes less time of checking
> > trace logs update. Since busybox tail/cat takes too
> > long time to read the trace log, this uses md5sum
> > to check whether trace log is updated or not.
> >
> > Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> > ---
> >  .../test.d/ftrace/func_traceonoff_triggers.tc      |    6 +++---
> >  1 file changed, 3 insertions(+), 3 deletions(-)
> >
> > diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> > index 9cf3852..7a9ab4f 100644
> > --- a/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> > +++ b/tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc
> > @@ -103,11 +103,11 @@ if [ $on != "0" ]; then
> >      fail "Tracing is not off"
> >  fi
> >
> > -line1=`cat trace | tail -1`
> > +csum1=`md5sum trace`
> >  sleep $SLEEP_TIME
> > -line2=`cat trace | tail -1`
> > +csum2=`md5sum trace`  
> 
> If you replace that with "tail -1 <trace", this code
> in busybox will be used:
> 
>                         off_t current = lseek(fd, 0, SEEK_END);

The trace file is a kernel pseudo file that prevents lseek. Now what
you could do is:

 cat trace > tempfile
 csum1=`tail -1 <tempfile`

But then we need to make sure to clean up the files.

-- Steve