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

PATCH In review Masami Hiramatsu 4 participants 12 messages Jun 27, 2017 – Jul 3, 2017

Subsystems (2)

Kselftest Tracing

lore

Share & tools

lore

Masami Hiramatsu

author maintainer

2017-06-27 10:29 UTC #0 lore raw

PATCH 1/1 selftests: ftrace: Use md5sum to take less time of checking logs

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 <[email protected]>

---
 .../test.d/ftrace/func_traceonoff_triggers.tc      |    6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc +3 -3

index 9cf3852..7a9ab4f 100644
@@ -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

Shuah Khan

maintainer

2017-06-28 14:00 UTC #1 lore raw

Quoted 6 lines · 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 <[email protected]>

Applied to linux-kselftest next for 4.13-rc1

thanks,
-- Shuah

Quoted 26 lines

---
 .../test.d/ftrace/func_traceonoff_triggers.tc      |    6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc +3 -3

index 9cf3852..7a9ab4f 100644
@@ -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

Steven Rostedt

maintainer

2017-06-28 14:17 UTC #2 lore raw

In reply to Masami Hiramatsu

Quoted 4 lines · On Tue, 27 Jun 2017 19:28:32 +0900 Masami Hiramatsu <[email protected]> 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

Quoted 25 lines

Signed-off-by Masami Hiramatsu <[email protected]>

---
 .../test.d/ftrace/func_traceonoff_triggers.tc      |    6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc +3 -3

index 9cf3852..7a9ab4f 100644
@@ -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

Shuah Khan

maintainer

2017-06-28 14:30 UTC #3 lore raw

Quoted 8 lines · Steven Rostedt

Quoted 4 lines · On Tue, 27 Jun 2017 19:28:32 +0900 Masami Hiramatsu <[email protected]> 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.

Quoted 4 lines

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

Quoted 29 lines

Quoted 26 lines

Signed-off-by Masami Hiramatsu <[email protected]>

---
 .../test.d/ftrace/func_traceonoff_triggers.tc      |    6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc +3 -3

index 9cf3852..7a9ab4f 100644
@@ -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

Steven Rostedt

maintainer

2017-06-28 14:59 UTC #4 lore raw

Quoted 9 lines · On Wed, 28 Jun 2017 08:30:24 -0600 Shuah Khan <[email protected]> wrote:

Quoted 8 lines · Steven Rostedt
Quoted 4 lines · On Tue, 27 Jun 2017 19:28:32 +0900 Masami Hiramatsu <[email protected]> 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.

Quoted 8 lines

Quoted 4 lines
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

Shuah Khan

maintainer

2017-06-28 15:31 UTC #5 lore raw

Quoted 17 lines · Steven Rostedt

Quoted 14 lines · On Wed, 28 Jun 2017 08:30:24 -0600 Shuah Khan <[email protected]> wrote:
Quoted 12 lines · Steven Rostedt
Quoted 4 lines · On Tue, 27 Jun 2017 19:28:32 +0900 Masami Hiramatsu <[email protected]> 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

Quoted 9 lines

Quoted 3 lines
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

Shuah Khan

maintainer

2017-06-29 20:21 UTC #6 lore raw

Quoted 28 lines · Shuah Khan

Quoted 17 lines · Steven Rostedt
Quoted 14 lines · On Wed, 28 Jun 2017 08:30:24 -0600 Shuah Khan <[email protected]> wrote:
Quoted 12 lines · Steven Rostedt
Quoted 4 lines · On Tue, 27 Jun 2017 19:28:32 +0900 Masami Hiramatsu <[email protected]> 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
Quoted 9 lines
Quoted 3 lines
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.

Quoted 5 lines

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

Steven Rostedt

maintainer Acked-by

2017-06-30 14:50 UTC #7 lore raw

On Thu, 29 Jun 2017 14:21:41 -0600
Shuah Khan <[email protected]> wrote:
\

Quoted 5 lines

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) <[email protected]>

-- Steve

Shuah Khan

maintainer

2017-06-30 16:53 UTC #8 lore raw

Quoted 9 lines · Steven Rostedt

On Thu, 29 Jun 2017 14:21:41 -0600
Shuah Khan <[email protected]> wrote:
\
Quoted 5 lines
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.

Quoted 7 lines

I played a little with it.
Acked-by Steven Rostedt (VMware) <[email protected]>
-- Steve

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

-- Shuah

Masami Hiramatsu

author maintainer

2017-07-03 04:19 UTC #9 lore raw

Quoted 12 lines · On Fri, 30 Jun 2017 10:53:15 -0600 Shuah Khan <[email protected]> wrote:

Quoted 11 lines · Steven Rostedt
On Thu, 29 Jun 2017 14:21:41 -0600
Shuah Khan <[email protected]> wrote:
\
Quoted 5 lines
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.

Quoted 7 lines

Quoted 5 lines
Acked-by Steven Rostedt (VMware) <[email protected]>
-- Steve
Thanks. Applied your Ack now to linux-kselftest next.

Thanks Steve and Shuah!

Signature · 1 line

Masami Hiramatsu <[email protected]>

Denys Vlasenko

2017-06-30 18:51 UTC #10 lore raw

In reply to Masami Hiramatsu

Quoted 15 lines · 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 <[email protected]>
---
 .../test.d/ftrace/func_traceonoff_triggers.tc      |    6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)
tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc +0 -0
index 9cf3852..7a9ab4f 100644

tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc if [ $on != "0" ]; then · line 108

Quoted 8 lines

tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc +2 -2

@@ -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

Steven Rostedt

maintainer

2017-06-30 19:03 UTC #11 lore raw

Quoted 28 lines · On Fri, 30 Jun 2017 20:50:45 +0200 Denys Vlasenko <[email protected]>…

Quoted 15 lines · 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 <[email protected]>
---
 .../test.d/ftrace/func_traceonoff_triggers.tc      |    6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)
tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc +0 -0
index 9cf3852..7a9ab4f 100644
tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc if [ $on != "0" ]; then · line 108
Quoted 8 lines
tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc +2 -2
@@ -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:

Quoted 1 line

                        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