Pathological case identified from contest

DISCUSSION Con Kolivas 3 participants 9 messages Oct 17, 2002 – Oct 20, 2002 VFS

Share & tools

Con Kolivas

author

2002-10-17 02:07 UTC #0 lore raw

I found a pathological case in 2.5 while running contest with process_load recently after checking the results which showed a bad result for 2.5.43-mm1:

2.5.43-mm1              101.38  72%     42      31%
2.5.43-mm1              102.90  75%     34      28%
2.5.43-mm1              504.12  14%     603     85%
2.5.43-mm1              96.73   77%     34      26%

This was very strange so I looked into it further

The default for process_load is this command:

process_load --processes $nproc --recordsize 8192 --injections 2

where $nproc=4*num_cpus

When I changed recordsize to 16384, many of the 2.5 kernels started exhibiting the same behaviour. While the machine was apparently still alive and would respond to my request to abort, the kernel compile would all but stop while process_load just continued without allowing anything to happen from kernel compilation for up to 5 minutes at a time. This doesnt happen with any 2.4 kernels.

I'm not sure what to make of this. Suggestion?

Con

Andrew Morton

2002-10-17 02:43 UTC #1 lore raw

Quoted 15 lines · Con Kolivas

I found a pathological case in 2.5 while running contest with process_load recently after checking the results which showed a bad result for 2.5.43-mm1:
2.5.43-mm1              101.38  72%     42      31%
2.5.43-mm1              102.90  75%     34      28%
2.5.43-mm1              504.12  14%     603     85%
2.5.43-mm1              96.73   77%     34      26%
This was very strange so I looked into it further
The default for process_load is this command:
process_load --processes $nproc --recordsize 8192 --injections 2

Quoted 8 lines

where $nproc=4*num_cpus
When I changed recordsize to 16384, many of the 2.5 kernels started exhibiting the same behaviour. While the machine was apparently still alive and would respond to my request to abort, the kernel compile would all but stop while process_load just continued without allowing anything to happen from kernel compilation for up to 5 minutes at a time. This doesnt happen with any 2.4 kernels.

Well it doesn't happen on my test machine (UP or SMP). I tried various recordsizes. It's probably related to HZ, memory bandwidth and the precise timing at which things happen.

The test describes itself thusly:

* This test generates a load which simulates a process-loaded system. *

 *  The test creates a ring of processes, each connected to its predecessor
 *  and successor by a pipe.  After the ring is created, the parent process
 *  injects some dummy data records into the ring and then joins.  The
 *  processes pass the data records around the ring until they are killed.

It'll be starvation in the CPU scheduler I expect. For some reason the ring of piping processes is just never giving a timeslice to anything else. Or maybe something to do with the exceptional wakeup strategy which pipes use.

Don't now, sorry. One for the kernel/*.c guys.

Con Kolivas

author

2002-10-17 04:20 UTC #2 lore raw

Quoting Andrew Morton <[email protected]>:

Quoted 42 lines

Quoted 3 lines · Con Kolivas
I found a pathological case in 2.5 while running contest with process_load recently after checking the results which showed a bad result for
2.5.43-mm1:
Quoted 8 lines
2.5.43-mm1              101.38  72%     42      31%
2.5.43-mm1              102.90  75%     34      28%
2.5.43-mm1              504.12  14%     603     85%
2.5.43-mm1              96.73   77%     34      26%
This was very strange so I looked into it further
Quoted 7 lines
The default for process_load is this command:
process_load --processes $nproc --recordsize 8192 --injections 2
where $nproc=4*num_cpus
When I changed recordsize to 16384, many of the 2.5 kernels started
exhibiting
Quoted 2 lines
the same behaviour. While the machine was apparently still alive and would respond to my request to abort, the kernel compile would all but stop
while
Quoted 1 line
process_load just continued without allowing anything to happen from
kernel
Quoted 1 line
compilation for up to 5 minutes at a time. This doesnt happen with any 2.4
kernels.
Quoted 1 line
Well it doesn't happen on my test machine (UP or SMP). I tried various recordsizes. It's probably related to HZ, memory bandwidth and the precise timing at which things happen.
The test describes itself thusly:
* This test generates a load which simulates a process-loaded system. *
 *  The test creates a ring of processes, each connected to its predecessor
 *  and successor by a pipe.  After the ring is created, the parent process
 *  injects some dummy data records into the ring and then joins.  The
 *  processes pass the data records around the ring until they are killed.

Quoted 8 lines

*
It'll be starvation in the CPU scheduler I expect. For some reason the ring of piping processes is just never giving a timeslice to anything else. Or maybe something to do with the exceptional wakeup strategy which pipes use.
Don't now, sorry. One for the kernel/*.c guys.

Ok well I've done some profiling as suggested by wli and it shows pretty much what I find in the results - it gets stuck while doing process_load and never moves on.

recordsize 8192 kern profile:

c01223ac 76997    4.48583     do_anonymous_page
c0188694 135835   7.91373     __generic_copy_from_user
c0188610 345071   20.1038     __generic_copy_to_user
c0105298 801429   46.6911     poll_idle
sysprofile:
00000000 160258   5.03854     (no symbol)             /lib/i686/libc-2.2.5.so
c0188610 345071   10.8491     __generic_copy_to_user

/home/con/kernel/linux-2.5.43/vmlinux
c0105298 801429 25.1971 poll_idle
/home/con/kernel/linux-2.5.43/vmlinux
00000000 1132668 35.6113 (no symbol)
/usr/lib/gcc-lib/i686-pc-linux-gnu/2.95.3/cc1

Normal run consistent with doing kernel compilation most of the time.

recordsize 16384 kernprofile:

c0111ef4 403545   4.3407      do_schedule
c0105298 558704   6.00965     poll_idle
c0188694 2571995  27.6655     __generic_copy_from_user
c0188610 4489796  48.2941     __generic_copy_to_user

sysprofile:
c0111ef4 403545 4.24896 do_schedule
/home/con/kernel/linux-2.5.43/vmlinux
c0105298 558704 5.88264 poll_idle
/home/con/kernel/linux-2.5.43/vmlinux
c0188694 2571995 27.0807 __generic_copy_from_user
/home/con/kernel/linux-2.5.43/vmlinux
c0188610 4489796 47.2734 __generic_copy_to_user
/home/con/kernel/linux-2.5.43/vmlinux

I had to abort the run with recordsize 16384 but you can see it's just stuck in process_load copying data between forked processes.

Can someone else on lkml decipher why it gets stuck here?

Con

Con Kolivas

author

2002-10-17 07:10 UTC #3 lore raw

Quoting Con Kolivas <[email protected]>:

Quoted 96 lines

Quoting Andrew Morton <[email protected]>:
Quoted 3 lines
Quoted 2 lines · Con Kolivas
I found a pathological case in 2.5 while running contest with
process_load
Quoted 10 lines
Quoted 1 line
recently after checking the results which showed a bad result for
2.5.43-mm1:
Quoted 8 lines
2.5.43-mm1              101.38  72%     42      31%
2.5.43-mm1              102.90  75%     34      28%
2.5.43-mm1              504.12  14%     603     85%
2.5.43-mm1              96.73   77%     34      26%
This was very strange so I looked into it further
Quoted 9 lines
Quoted 7 lines
The default for process_load is this command:
process_load --processes $nproc --recordsize 8192 --injections 2
where $nproc=4*num_cpus
When I changed recordsize to 16384, many of the 2.5 kernels started
exhibiting
Quoted 1 line
the same behaviour. While the machine was apparently still alive and
would
Quoted 5 lines
Quoted 1 line
respond to my request to abort, the kernel compile would all but stop
while
Quoted 1 line
process_load just continued without allowing anything to happen from
kernel
Quoted 1 line
compilation for up to 5 minutes at a time. This doesnt happen with any
2.4
Quoted 7 lines
kernels.
Quoted 1 line
Well it doesn't happen on my test machine (UP or SMP). I tried various recordsizes. It's probably related to HZ, memory bandwidth and the precise timing at which things happen.
Quoted 5 lines
The test describes itself thusly:
* This test generates a load which simulates a process-loaded system. *
* The test creates a ring of processes, each connected to its
predecessor
Quoted 1 line
* and successor by a pipe. After the ring is created, the parent
process
Quoted 10 lines
* injects some dummy data records into the ring and then joins. The
* processes pass the data records around the ring until they are killed. *
It'll be starvation in the CPU scheduler I expect. For some reason the ring of piping processes is just never giving a timeslice to anything else. Or maybe something to do with the exceptional wakeup strategy which pipes use.
Don't now, sorry. One for the kernel/*.c guys.
Ok well I've done some profiling as suggested by wli and it shows pretty much
what I find in the results - it gets stuck while doing process_load and never
moves on.
recordsize 8192 kern profile:
c01223ac 76997    4.48583     do_anonymous_page
c0188694 135835   7.91373     __generic_copy_from_user
c0188610 345071   20.1038     __generic_copy_to_user
c0105298 801429   46.6911     poll_idle
sysprofile:
00000000 160258 5.03854 (no symbol)
/lib/i686/libc-2.2.5.so
c0188610 345071 10.8491 __generic_copy_to_user
/home/con/kernel/linux-2.5.43/vmlinux
c0105298 801429 25.1971 poll_idle
/home/con/kernel/linux-2.5.43/vmlinux
00000000 1132668 35.6113 (no symbol)
/usr/lib/gcc-lib/i686-pc-linux-gnu/2.95.3/cc1
Normal run consistent with doing kernel compilation most of the time.
recordsize 16384 kernprofile:
c0111ef4 403545   4.3407      do_schedule
c0105298 558704   6.00965     poll_idle
c0188694 2571995  27.6655     __generic_copy_from_user
c0188610 4489796  48.2941     __generic_copy_to_user
sysprofile:
c0111ef4 403545 4.24896 do_schedule
/home/con/kernel/linux-2.5.43/vmlinux
c0105298 558704 5.88264 poll_idle
/home/con/kernel/linux-2.5.43/vmlinux
c0188694 2571995 27.0807 __generic_copy_from_user
/home/con/kernel/linux-2.5.43/vmlinux
c0188610 4489796 47.2734 __generic_copy_to_user
/home/con/kernel/linux-2.5.43/vmlinux

Quoted 5 lines

I had to abort the run with recordsize 16384 but you can see it's just stuck in
process_load copying data between forked processes.
Can someone else on lkml decipher why it gets stuck here?

Well this has become more common with 2.5.43-mm2. I had to abort the process_load run 3 times when benchmarking it. Going back to other kernels and trying them it didnt happen so I dont think its my hardware failing or something like that.

Con

Andrew Morton

2002-10-17 07:29 UTC #4 lore raw

Quoted 6 lines · Con Kolivas

...
Well this has become more common with 2.5.43-mm2. I had to abort the process_load run 3 times when benchmarking it. Going back to other kernels and trying them it didnt happen so I dont think its my hardware failing or something like that.

No, it's a bug in either the pipe code or the CPU scheduler I'd say.

You could try backing out to the 2.5.40 pipe implementation; not sure if that would tell us much though.

Here's a backout patch:

 fs/pipe.c                 |  323 +++++++++++++++++++++++++---------------------
 include/linux/pipe_fs_i.h |    2 
 2 files changed, 183 insertions(+), 142 deletions(-)

include/linux/pipe_fs_i.h renamed from include/linux/pipe_fs_i.h~pipe-backout +2 -0

@@ -9,6 +9,7 @@ struct pipe_inode_info {
 	unsigned int start;
 	unsigned int readers;
 	unsigned int writers;
+	unsigned int waiting_readers;
 	unsigned int waiting_writers;
 	unsigned int r_counter;
 	unsigned int w_counter;

@@ -27,6 +28,7 @@ struct pipe_inode_info {
 #define PIPE_LEN(inode)		((inode).i_pipe->len)
 #define PIPE_READERS(inode)	((inode).i_pipe->readers)
 #define PIPE_WRITERS(inode)	((inode).i_pipe->writers)
+#define PIPE_WAITING_READERS(inode)	((inode).i_pipe->waiting_readers)
 #define PIPE_WAITING_WRITERS(inode)	((inode).i_pipe->waiting_writers)
 #define PIPE_RCOUNTER(inode)	((inode).i_pipe->r_counter)
 #define PIPE_WCOUNTER(inode)	((inode).i_pipe->w_counter)

fs/pipe.c renamed from fs/pipe.c~pipe-backout +181 ~~-142~~

410 lines not on this page · raw message

Rik van Riel

2002-10-17 17:09 UTC #5 lore raw

Quoted 1 line · Andrew Morton

No, it's a bug in either the pipe code or the CPU scheduler I'd say.

The scheduler definately seems to have a big error here.

Say we're doing a pipe test with 3 processes. On an idle system this would result in each process getting 33% of the CPU and using the other 66% of the time sleeping. Of course, this makes all 3 processes "interactive", since they sleep twice as much as they run.

Now introduce 1 CPU hog in competition to this load, this CPU hog never sleeps so it is quickly marked as cpu hog and will end up on the expired array after one timeslice (150 ms?).

The pipe processes will have the CPU all to themselves until STARVATION_LIMIT (2 seconds) time has passed.

This means that the CPU hog will get 7.5% of the CPU, while the pipe processes get the other 92.5% of the CPU, or 30.8% each, almost 4 times as much as the CPU hog.

This could either mean the sleep average isn't a useful way to measure CPU priority or the way we measure the sleep average needs to be changed somewhat...

kind regards,

Rik

Signature · 3 lines

Bravely reimplemented by the knights who say "NIH".
http://www.surriel.com/		http://distro.conectiva.com/
Current spamtrap:  <a href=mailto:"[email protected]">[email protected]</a>

Con Kolivas

author

2002-10-20 02:53 UTC #6 lore raw

In reply to Andrew Morton

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Quoted 11 lines · you

Quoted 5 lines · Con Kolivas
...
Well this has become more common with 2.5.43-mm2. I had to abort the process_load run 3 times when benchmarking it. Going back to other kernels and trying them it didnt happen so I dont think its my hardware failing or something like that.
No, it's a bug in either the pipe code or the CPU scheduler I'd say.
You could try backing out to the 2.5.40 pipe implementation; not sure if that would tell us much though.

I massaged the patch a little for it to apply and it _is_ the offending code. Backing out the pipe changes fixed the problem. I was unable to reproduce the holdup I was seeing with process_load even at higher data sizes. Now what?

Con
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.0.7 (GNU/Linux)

iD8DBQE9shwEF6dfvkL3i1gRAkQgAJ9J3uKeQ5AT3vCPPbGKgk0xuW4V1gCfXBJ3 93vaP5XLpT/WRGAqcVOxVkU=
=OluT
-----END PGP SIGNATURE-----

Andrew Morton

2002-10-20 02:59 UTC #7 lore raw

Quoted 12 lines · Con Kolivas

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Quoted 7 lines · you
Quoted 5 lines · Con Kolivas
...
Well this has become more common with 2.5.43-mm2. I had to abort the process_load run 3 times when benchmarking it. Going back to other kernels and trying them it didnt happen so I dont think its my hardware failing or something like that.

Quoted 9 lines

Quoted 4 lines
No, it's a bug in either the pipe code or the CPU scheduler I'd say.
You could try backing out to the 2.5.40 pipe implementation; not sure if that would tell us much though.
I massaged the patch a little for it to apply and it _is_ the offending code. Backing out the pipe changes fixed the problem. I was unable to reproduce the holdup I was seeing with process_load even at higher data sizes. Now what?

Try Manfred's pipe fix I guess?

fs/pipe.c +2 -2

@@ -109,7 +109,7 @@
 			break;
 		}
 		if (do_wakeup) {
-			wake_up_interruptible(PIPE_WAIT(*inode));
+			wake_up_interruptible_sync(PIPE_WAIT(*inode));
  			kill_fasync(PIPE_FASYNC_WRITERS(*inode), SIGIO, POLL_OUT);
 		}
 		pipe_wait(inode);

@@ -117,7 +117,7 @@
 	up(PIPE_SEM(*inode));
 	/* Signal writers asynchronously that there is more room.  */
 	if (do_wakeup) {
-		wake_up_interruptible_sync(PIPE_WAIT(*inode));
+		wake_up_interruptible(PIPE_WAIT(*inode));
 		kill_fasync(PIPE_FASYNC_WRITERS(*inode), SIGIO, POLL_OUT);
 	}
 	if (ret > 0)

Con Kolivas

author

2002-10-20 06:21 UTC #8 lore raw

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Quoted 17 lines · Andrew Morton

Quoted 16 lines · Con Kolivas
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Quoted 11 lines · you
Quoted 5 lines · Con Kolivas
...
Well this has become more common with 2.5.43-mm2. I had to abort the process_load run 3 times when benchmarking it. Going back to other kernels and trying them it didnt happen so I dont think its my hardware failing or something like that.
No, it's a bug in either the pipe code or the CPU scheduler I'd say.
You could try backing out to the 2.5.40 pipe implementation; not sure if that would tell us much though.

Quoted 7 lines

Quoted 4 lines
I massaged the patch a little for it to apply and it _is_ the offending code. Backing out the pipe changes fixed the problem. I was unable to reproduce the holdup I was seeing with process_load even at higher data sizes. Now what?
Try Manfred's pipe fix I guess?

Well *that* makes sense. Tried it and it fixed it thank you.

Cheers,
Con
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.0.7 (GNU/Linux)

iD8DBQE9skzBF6dfvkL3i1gRAtbyAKCg6bIWNnEbZeFnRT2mcS7TkkBtsQCfatyT m4Q37qYkOZ389DlcvluL9vA=
=PXfw
-----END PGP SIGNATURE-----