Skip to contentSkip to conversation

read_all: give more time to wait children finish read action

RFC PATCH New Li Wang 4 participants 10 messages Apr 7, 2018 – Apr 11, 2018

lore
Share & tools
lore

Li Wang

author
#0 lore raw

RFC PATCH 1/1 read_all: give more time to wait children finish read action

1. Some children are still working on the read I/O but parent trys to stopping them after visit_dir() immediately. Although the stop_attemps is 65535, it still sometimes fails, so we get the following worker stalled messges in test.

 # uname -rm
   4.16.0-rc7 ppc64
 # ./read_all -d /sys -q -r 10
   tst_test.c:987: INFO: Timeout per run is 0h 05m 00s
   read_all.c:280: BROK: Worker 26075 is stalled
   read_all.c:280: WARN: Worker 26075 is stalled
   read_all.c:280: WARN: Worker 26079 is stalled
   read_all.c:280: WARN: Worker 26087 is stalled

2. The sched_work() push action in a infinite loop, here I propose to let it in limited times.

Signed-off-by Li Wang <[email protected]>
---
 testcases/kernel/fs/read_all/read_all.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)
testcases/kernel/fs/read_all/read_all.c +7 -3
index b7ed540..ab206e7 100644
@@ -280,6 +280,7 @@ static void stop_workers(void)
 						workers[i].pid);
 					break;
 				}
+				usleep(100);
 			}
 		}
 	}

@@ -306,9 +307,12 @@ static void sched_work(const char *path)
 		if (pushed)
 			break;
 
-		if (++push_attempts > worker_count) {
-			usleep(100);
-			push_attempts = 0;
+		usleep(100);
+		if (++push_attempts > 0xffff) {
+			tst_brk(TBROK,
+				"Attempts %d times but still failed to push %s",
+				push_attempts, path);
+			break;
 		}
 	}
 }
Signature · 1 line
1.9.3
#1 lore raw

RFC PATCH 1/1 read_all: give more time to wait children finish read action

Quoted 4 lines · Li Wang

1. Some children are still working on the read I/O but parent trys to stopping them after visit_dir() immediately. Although the stop_attemps is 65535, it still sometimes fails, so we get the following worker stalled messges in test.

Hi Li,

I got the same message on RHEL6.9Alpha as well, and this patch looks good to me.

Thanks,
Xiao Yang.

Quoted 45 lines
  # uname -rm
    4.16.0-rc7 ppc64
  # ./read_all -d /sys -q -r 10
    tst_test.c:987: INFO: Timeout per run is 0h 05m 00s
    read_all.c:280: BROK: Worker 26075 is stalled
    read_all.c:280: WARN: Worker 26075 is stalled
    read_all.c:280: WARN: Worker 26079 is stalled
    read_all.c:280: WARN: Worker 26087 is stalled

2. The sched_work() push action in a infinite loop, here I propose to let it in limited times.

Signed-off-by Li Wang<[email protected]>
---
  testcases/kernel/fs/read_all/read_all.c | 10 +++++++---
  1 file changed, 7 insertions(+), 3 deletions(-)
testcases/kernel/fs/read_all/read_all.c +7 -3
index b7ed540..ab206e7 100644
@@ -280,6 +280,7 @@ static void stop_workers(void)
  						workers[i].pid);
  					break;
  				}
+				usleep(100);
  			}
  		}
  	}

@@ -306,9 +307,12 @@ static void sched_work(const char *path)
  		if (pushed)
  			break;
 
-		if (++push_attempts>  worker_count) {
-			usleep(100);
-			push_attempts = 0;
+		usleep(100);
+		if (++push_attempts>  0xffff) {
+			tst_brk(TBROK,
+				"Attempts %d times but still failed to push %s",
+				push_attempts, path);
+			break;
  		}
  	}
  }
#2 lore raw

RFC PATCH 1/1 read_all: give more time to wait children finish read action

In reply to Li Wang

Hello,

Quoted 5 lines · Li Wang

1. Some children are still working on the read I/O but parent trys to stopping them after visit_dir() immediately. Although the stop_attemps is 65535, it still sometimes fails, so we get the following worker stalled messges in test.

Quoted 8 lines
 # uname -rm
   4.16.0-rc7 ppc64
 # ./read_all -d /sys -q -r 10
   tst_test.c:987: INFO: Timeout per run is 0h 05m 00s
   read_all.c:280: BROK: Worker 26075 is stalled
   read_all.c:280: WARN: Worker 26075 is stalled
   read_all.c:280: WARN: Worker 26079 is stalled
   read_all.c:280: WARN: Worker 26087 is stalled

wow, three workers have there queues perfectly filled... I guess I accidentally created a brute force box packing algorithm.

Quoted 3 lines

2. The sched_work() push action in a infinite loop, here I propose to let it in limited times.

I think this is moving the problem instead of solving it. Increasing the number of stop_attempts should have the same effect unless the workers are permanently blocked on I/O. However this might be better because it removes the sleep.

Possibly we should actually try to determine if a worker is blocked reading a file and print the file name.

Quoted 19 lines
Signed-off-by Li Wang <[email protected]>
---
 testcases/kernel/fs/read_all/read_all.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)
testcases/kernel/fs/read_all/read_all.c +1 -0
index b7ed540..ab206e7 100644
@@ -280,6 +280,7 @@ static void stop_workers(void)
 						workers[i].pid);
 					break;
 				}
+				usleep(100);
 			}
 		}
 	}

testcases/kernel/fs/read_all/read_all.c static void sched_work(const char *path) · line 311

Quoted 8 lines
testcases/kernel/fs/read_all/read_all.c +2 -3
@@ -306,9 +307,12 @@ static void sched_work(const char *path)
 		if (pushed)
 			break;
 
-		if (++push_attempts > worker_count) {
-			usleep(100);
-			push_attempts = 0;
+		usleep(100);
+		if (++push_attempts > 0xffff) {

Maybe add another f to this.

Quoted 7 lines
testcases/kernel/fs/read_all/read_all.c +4 -0
+			tst_brk(TBROK,
+				"Attempts %d times but still failed to push %s",
+				push_attempts, path);
+			break;
 		}
 	}
 }
Signature · 2 lines
Thank you,
Richard.
author
#3 lore raw

RFC PATCH 1/1 read_all: give more time to wait children finish read action

Hi Richard,

Richard Palethorpe <[email protected]> wrote:

Hello,

Quoted 21 lines
Quoted 5 lines · Li Wang

1. Some children are still working on the read I/O but parent trys to stopping them after visit_dir() immediately. Although the stop_attemps is 65535, it still sometimes fails, so we get the following worker stalled messges in test.

Quoted 8 lines
 # uname -rm
   4.16.0-rc7 ppc64
 # ./read_all -d /sys -q -r 10
   tst_test.c:987: INFO: Timeout per run is 0h 05m 00s
   read_all.c:280: BROK: Worker 26075 is stalled
   read_all.c:280: WARN: Worker 26075 is stalled
   read_all.c:280: WARN: Worker 26079 is stalled
   read_all.c:280: WARN: Worker 26087 is stalled

wow, three workers have there queues perfectly filled... I guess I accidentally created a brute force box packing algorithm.

Quoted 1 line
Quoted 8 lines
Quoted 2 lines

2. The sched_work() push action in a infinite loop, here I propose to let it in limited times.

I think this is moving the problem instead of solving it. Increasing the number of stop_attempts should have the same effect unless the workers are permanently blocked on I/O. However this might be better because it removes the sleep.

​Hmm, not sure if you're fully get my point, maybe I(apologize!) shouldn't fix two
problems in one patch.

For the block I/O issue, I just adding 'usleep(100)​' in stop_workers() function.
You suggest increasing stop_attempts is also accessible, but without sleep it still very fast to finish the loop and probably we need a very large number
for stop_attempt to waste time.

For the second change in sched_work() is just to guarantee we can exist the infinite loop if something wrong with queue_push action.

Quoted 4 lines

Possibly we should actually try to determine if a worker is blocked reading a file and print the file name.

You are right, I'm now still looking for a better way to avoid this block I/O issue.

Quoted 26 lines

Review

Quoted 8 lines
Signed-off-by Li Wang <[email protected]>
---
 testcases/kernel/fs/read_all/read_all.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)
(quoted diff) +0 -0

b/testcases/kernel/fs/read_all/read_all.c

testcases/kernel/fs/read_all/read_all.c static void stop_workers(void) · line 283

Quoted 8 lines

index b7ed540..ab206e7 100644

testcases/kernel/fs/read_all/read_all.c +1 -0
@@ -280,6 +280,7 @@ static void stop_workers(void)
                                              workers[i].pid);
                                      break;
                              }
+                             usleep(100);

​ ​

Quoted 7 lines
testcases/kernel/fs/read_all/read_all.c +0 -0
                      }
              }
      }

@@ -306,9 +307,12 @@ static void sched_work(const char *path)
              if (pushed)
                      break;
Quoted 8 lines

testcases/kernel/fs/read_all/read_all.c static void sched_work(const char *path) · line 311

Quoted 5 lines
testcases/kernel/fs/read_all/read_all.c +2 -3
-             if (++push_attempts > worker_count) {
-                     usleep(100);
-                     push_attempts = 0;
+             usleep(100);
+             if (++push_attempts > 0xffff) {

Maybe add another f to this.

​No need too much attempt, my test says this push action can get pass less than try 20 times.
​

Quoted 15 lines

testcases/kernel/fs/read_all/read_all.c static void sched_work(const char *path) · line 313

Quoted 3 lines
testcases/kernel/fs/read_all/read_all.c +2 -0
+                     tst_brk(TBROK,
+                             "Attempts %d times but still failed to

push %s",

testcases/kernel/fs/read_all/read_all.c static void sched_work(const char *path) · line 318

Quoted 5 lines
testcases/kernel/fs/read_all/read_all.c +2 -0
+                             push_attempts, path);
+                     break;
              }
      }
 }

--
Thank you,
Richard.

Signature · 5 lines
Li Wang
[email protected]
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.linux.it/pipermail/ltp/attachments/20180409/8321b02c/attachment-0001.html>
#4 lore raw

RFC PATCH 1/1 read_all: give more time to wait children finish read action

Quoted 47 lines · Li Wang

Hi Richard,

Richard Palethorpe <[email protected]> wrote:

Hello,

Quoted 21 lines
Quoted 5 lines · Li Wang

1. Some children are still working on the read I/O but parent trys to stopping them after visit_dir() immediately. Although the stop_attemps is 65535, it still sometimes fails, so we get the following worker stalled messges in test.

Quoted 8 lines
 # uname -rm
   4.16.0-rc7 ppc64
 # ./read_all -d /sys -q -r 10
   tst_test.c:987: INFO: Timeout per run is 0h 05m 00s
   read_all.c:280: BROK: Worker 26075 is stalled
   read_all.c:280: WARN: Worker 26075 is stalled
   read_all.c:280: WARN: Worker 26079 is stalled
   read_all.c:280: WARN: Worker 26087 is stalled

wow, three workers have there queues perfectly filled... I guess I accidentally created a brute force box packing algorithm.

Quoted 1 line
Quoted 8 lines
Quoted 2 lines

2. The sched_work() push action in a infinite loop, here I propose to let it in limited times.

I think this is moving the problem instead of solving it. Increasing the number of stop_attempts should have the same effect unless the workers are permanently blocked on I/O. However this might be better because it removes the sleep.

​Hmm, not sure if you're fully get my point, maybe I(apologize!) shouldn't fix two
problems in one patch.

For the block I/O issue, I just adding 'usleep(100)​' in stop_workers() function.
You suggest increasing stop_attempts is also accessible, but without sleep it still very fast to finish the loop and probably we need a very large number
for stop_attempt to waste time.

Quoted 2 lines

For the second change in sched_work() is just to guarantee we can exist the infinite loop if something wrong with queue_push action.

An infinite loop is not a big problem because the test library will timeout, but not knowing what caused the timeout is a problem.

When writing the test I was not sure if timeouts would be a problem, but from your testing it appears that it is.

Quoted 10 lines
Quoted 7 lines

Possibly we should actually try to determine if a worker is blocked reading a file and print the file name.

You are right, I'm now still looking for a better way to avoid this block I/O issue.

Maybe you could add a field to the worker struct containing the current file being read and a timestamp of when it started reading that file. Then we can use that information later to find out if a particular file is taking a long time to read.

Quoted 37 lines
Quoted 28 lines

Review

Quoted 10 lines
Signed-off-by Li Wang <[email protected]>
---
 testcases/kernel/fs/read_all/read_all.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)
(quoted diff) +0 -0

b/testcases/kernel/fs/read_all/read_all.c

Quoted 17 lines

index b7ed540..ab206e7 100644

testcases/kernel/fs/read_all/read_all.c +1 -0
@@ -280,6 +280,7 @@ static void stop_workers(void)
                                              workers[i].pid);
                                      break;
                              }
+                             usleep(100);
 
 
                      }

              }
      }
testcases/kernel/fs/read_all/read_all.c +0 -0
@@ -306,9 +307,12 @@ static void sched_work(const char *path)
              if (pushed)
                      break;
Quoted 8 lines

testcases/kernel/fs/read_all/read_all.c static void sched_work(const char *path) · line 311

Quoted 5 lines
testcases/kernel/fs/read_all/read_all.c +2 -3
-             if (++push_attempts > worker_count) {
-                     usleep(100);
-                     push_attempts = 0;
+             usleep(100);
+             if (++push_attempts > 0xffff) {

Maybe add another f to this.

Quoted 2 lines

​No need too much attempt, my test says this push action can get pass less than try 20 times.

OK, I think this change is good except that using a constant time for the usleep is probably bad. Instead we could use an exponential function; so we can start with a sleep of 1 then double it up to a maximum of 20 times (approximately a second for the final wait).

Quoted 14 lines
Quoted 14 lines

testcases/kernel/fs/read_all/read_all.c static void sched_work(const char *path) · line 313

Quoted 6 lines
testcases/kernel/fs/read_all/read_all.c +2 -0
+                     tst_brk(TBROK,
+                             "Attempts %d times but still failed to

push %s",

Quoted 5 lines
testcases/kernel/fs/read_all/read_all.c +2 -0
+                             push_attempts, path);
+                     break;
              }
      }
 }
Quoted 4 lines
Quoted 4 lines

--
Thank you,
Richard.

--
Thank you,
Richard.

#5 lore raw

RFC PATCH 1/1 read_all: give more time to wait children finish read action

Hi!

Quoted 4 lines

OK, I think this change is good except that using a constant time for the usleep is probably bad. Instead we could use an exponential function; so we can start with a sleep of 1 then double it up to a maximum of 20 times (approximately a second for the final wait).

Actually I was thinking of adding such functionality to the test library exactly because I do not want to reimplement the exponentialy incremented sleep for retry over and overe in each testcase...

Maybe we need TST_RETRY_ON_NONZERO() macro that would build the retry loop around a function passed as a paramter or something like that.

Signature · 2 lines
Cyril Hrubis
[email protected]
#6 lore raw

RFC PATCH 1/1 read_all: give more time to wait children finish read action

Hello,

Quoted 9 lines · Cyril Hrubis

Hi!

Quoted 4 lines

OK, I think this change is good except that using a constant time for the usleep is probably bad. Instead we could use an exponential function; so we can start with a sleep of 1 then double it up to a maximum of 20 times (approximately a second for the final wait).

Actually I was thinking of adding such functionality to the test library exactly because I do not want to reimplement the exponentialy incremented sleep for retry over and overe in each testcase...

Sounds like a good idea.

Quoted 3 lines

Maybe we need TST_RETRY_ON_NONZERO() macro that would build the retry loop around a function passed as a paramter or something like that.

Or TST_RETRY_LOOP, TST_RETRY_WHILE or
TST_RETRY_WITH_EXPONENTIAL_BACKOFF. :-)

Maybe it should not be a magic macro though, but just an inline function which you call in the body of a loop which performs the sleep based on a couple of parameters. I suppose it depends on how nice one can make the macro.

--
Thank you,
Richard.

#7 lore raw

RFC PATCH 1/1 read_all: give more time to wait children finish read action

Hi!

Quoted 10 lines
Quoted 2 lines

Maybe we need TST_RETRY_ON_NONZERO() macro that would build the retry loop around a function passed as a paramter or something like that.

Or TST_RETRY_LOOP, TST_RETRY_WHILE or
TST_RETRY_WITH_EXPONENTIAL_BACKOFF. :-)

Maybe it should not be a magic macro though, but just an inline function which you call in the body of a loop which performs the sleep based on a couple of parameters. I suppose it depends on how nice one can make the macro.

Well, yes. But I would go for simple sleep for the sake of fixing this test for now, then replace it with something better once we settle on on the actual implementation.

Signature · 2 lines
Cyril Hrubis
[email protected]
author
#8 lore raw

RFC PATCH 1/1 read_all: give more time to wait children finish read action

In reply to Richard Palethorpe
Quoted 20 lines · Richard Palethorpe

Hello,

Quoted 9 lines · Cyril Hrubis

Hi!

Quoted 4 lines

OK, I think this change is good except that using a constant time for the usleep is probably bad. Instead we could use an exponential function; so we can start with a sleep of 1 then double it up to a maximum of 20 times (approximately a second for the final wait).

Actually I was thinking of adding such functionality to the test library exactly because I do not want to reimplement the exponentialy incremented sleep for retry over and overe in each testcase...

Sounds like a good idea.

Quoted 3 lines

Maybe we need TST_RETRY_ON_NONZERO() macro that would build the retry loop around a function passed as a paramter or something like that.

Quoted 9 lines

Or TST_RETRY_LOOP, TST_RETRY_WHILE or
TST_RETRY_WITH_EXPONENTIAL_BACKOFF. :-)

Maybe it should not be a magic macro though, but just an inline function which you call in the body of a loop which performs the sleep based on a couple of parameters. I suppose it depends on how nice one can make the macro.

​I have written two new MACROS from this suggestion, and​ will send out the PATCH to
request you comments after finishing my roughly test. Thanks!

Signature · 5 lines
Li Wang
[email protected]
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.linux.it/pipermail/ltp/attachments/20180411/3b465e3e/attachment.html>
author
#9 lore raw

RFC PATCH 1/1 read_all: give more time to wait children finish read action

In reply to Richard Palethorpe
Quoted 9 lines · Richard Palethorpe
Quoted 2 lines

You are right, I'm now still looking for a better way to avoid this block I/O issue.

Maybe you could add a field to the worker struct containing the current file being read and a timestamp of when it started reading that file. Then we can use that information later to find out if a particular file is taking a long time to read.

​I tried to count the reading time of files in children, it shows 0~200 ms has been elapsed for each one.
But for parent, the most slower cost time of stop_worker() is 8ms, and even visit_dir(root_dir)
push all of the files, it takes only 1000ms. That probably can prove that why some
children stalled there.

========
read_all.c:231: INFO:
read(/sys/kernel/debug/tracing/per_cpu/cpu11/snapshot_raw), elapsed_ms = 90: EAGAIN/EWOULDBLOCK
read_all.c:231: INFO:
read(/sys/kernel/debug/tracing/per_cpu/cpu10/trace_pipe), elapsed_ms = 0:
EAGAIN/EWOULDBLOCK
read_all.c:231: INFO:
read(/sys/kernel/debug/tracing/per_cpu/cpu12/trace_pipe), elapsed_ms = 110:
EAGAIN/EWOULDBLOCK
...
read_all.c:231: INFO:
read(/sys/kernel/debug/tracing/per_cpu/cpu9/trace_pipe_raw), elapsed_ms = 160: EAGAIN/EWOULDBLOCK
...
read_all.c:231: INFO:
read(/sys/kernel/debug/tracing/per_cpu/cpu9/trace_pipe_raw), elapsed_ms = 180: EAGAIN/EWOULDBLOCK
read_all.c:231: INFO:
read(/sys/kernel/debug/tracing/per_cpu/cpu11/trace_pipe), elapsed_ms = 0:
EAGAIN/EWOULDBLOCK
...
read_all.c:231: INFO:
read(/sys/kernel/debug/tracing/per_cpu/cpu10/snapshot_raw), elapsed_ms = 130: EAGAIN/EWOULDBLOCK
read_all.c:231: INFO:
read(/sys/kernel/debug/tracing/per_cpu/cpu6/trace_pipe), elapsed_ms = 200:
EAGAIN/EWOULDBLOCK
read_all.c:231: INFO:
read(/sys/kernel/debug/tracing/per_cpu/cpu9/trace_pipe), elapsed_ms = 0:
EAGAIN/EWOULDBLOCK
read_all.c:231: INFO:
read(/sys/kernel/debug/tracing/per_cpu/cpu5/snapshot_raw), elapsed_ms = 0:
EAGAIN/EWOULDBLOCK

Signature · 5 lines
Li Wang
[email protected]
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.linux.it/pipermail/ltp/attachments/20180411/ab351731/attachment.html>