2002-11-07 22:47:42

by Con Kolivas

[permalink] [raw]
Subject: [BENCHMARK] 2.5.46-mm1 with contest

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

Here are contest results showing 2.5.46-mm1 with preempt enabled. The other
kernels have it disabled.

noload:
Kernel [runs] Time CPU% Loads LCPU% Ratio
2.5.44-mm6 [3] 75.7 91 0 0 1.06
2.5.46 [2] 74.1 92 0 0 1.04
2.5.46-mm1 [5] 74.0 93 0 0 1.04

cacherun:
Kernel [runs] Time CPU% Loads LCPU% Ratio
2.5.44-mm6 [3] 69.3 99 0 0 0.97
2.5.46 [2] 67.9 99 0 0 0.95
2.5.46-mm1 [5] 68.9 99 0 0 0.96

process_load:
Kernel [runs] Time CPU% Loads LCPU% Ratio
2.5.44-mm6 [3] 190.6 36 166 63 2.67
2.5.45 [5] 91.0 75 33 27 1.27
2.5.46 [1] 92.9 74 36 29 1.30
2.5.46-mm1 [5] 82.7 82 21 21 1.16

Much improved

ctar_load:
Kernel [runs] Time CPU% Loads LCPU% Ratio
2.5.44-mm6 [3] 97.3 79 1 5 1.36
2.5.46 [1] 98.3 80 1 7 1.38
2.5.46-mm1 [5] 95.3 80 1 5 1.33

xtar_load:
Kernel [runs] Time CPU% Loads LCPU% Ratio
2.5.44-mm6 [3] 207.6 37 2 7 2.91
2.5.46 [1] 113.5 67 1 8 1.59
2.5.46-mm1 [5] 227.1 34 3 7 3.18

Whatever was causing this to be high in 2.5.44-mm6 is still there now.

io_load:
Kernel [runs] Time CPU% Loads LCPU% Ratio
2.5.44-mm6 [3] 284.1 28 20 10 3.98
2.5.46 [1] 600.5 13 48 12 8.41
2.5.46-mm1 [5] 134.3 58 6 8 1.88

Big change here. IO load is usually the one we feel the most.

read_load:
Kernel [runs] Time CPU% Loads LCPU% Ratio
2.5.44-mm6 [3] 104.3 73 7 4 1.46
2.5.46 [1] 103.5 75 7 4 1.45
2.5.46-mm1 [5] 103.2 74 6 4 1.45

list_load:
Kernel [runs] Time CPU% Loads LCPU% Ratio
2.5.44-mm6 [3] 95.3 75 1 20 1.33
2.5.46 [1] 96.8 74 2 22 1.36
2.5.46-mm1 [5] 101.4 70 1 22 1.42

mem_load:
Kernel [runs] Time CPU% Loads LCPU% Ratio
2.5.44-mm6 [3] 226.9 33 50 2 3.18
2.5.46 [3] 148.0 51 34 2 2.07
2.5.46-mm1 [5] 180.5 41 35 1 2.53

And this remains relatively high but better than 2.5.44-mm6

Unfortunately I've only run this with preempt enabled so far and I believe
many of the improvements are showing this effect.

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

iD8DBQE9yu7eF6dfvkL3i1gRAqGIAJ9f6XFfwO0sQOVBn5qZPfAFY5JdlwCggOZt
WXizAEgC23W+AURXApih9xc=
=MCT0
-----END PGP SIGNATURE-----


2002-11-07 23:41:34

by Robert Love

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest

On Thu, 2002-11-07 at 17:53, Con Kolivas wrote:

> io_load:
> Kernel [runs] Time CPU% Loads LCPU% Ratio
> 2.5.44-mm6 [3] 284.1 28 20 10 3.98
> 2.5.46 [1] 600.5 13 48 12 8.41
> 2.5.46-mm1 [5] 134.3 58 6 8 1.88
>
> Big change here. IO load is usually the one we feel the most.

Nice.

> Unfortunately I've only run this with preempt enabled so far and I believe
> many of the improvements are showing this effect.

Since your aim is desktop performance, I would like it if you always ran
with kernel preemption enabled. That is what we are targeting for
desktop performance.

Good job,

Robert Love

2002-11-07 23:52:15

by Andrew Morton

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest

Robert Love wrote:
>
> On Thu, 2002-11-07 at 17:53, Con Kolivas wrote:
>
> > io_load:
> > Kernel [runs] Time CPU% Loads LCPU% Ratio
> > 2.5.44-mm6 [3] 284.1 28 20 10 3.98
> > 2.5.46 [1] 600.5 13 48 12 8.41
> > 2.5.46-mm1 [5] 134.3 58 6 8 1.88
> >
> > Big change here. IO load is usually the one we feel the most.
>
> Nice.

Mysterious.

> > Unfortunately I've only run this with preempt enabled so far and I believe
> > many of the improvements are showing this effect.
>
> Since your aim is desktop performance, I would like it if you always ran
> with kernel preemption enabled. That is what we are targeting for
> desktop performance.

I'd be interested in average-of-five runs both with and without
preemption.



Preemption seemed to do odd things to process_load as well. gcc gained
10% and the "load" lost 40%. But the %LCPU fell only 25%, which is
probably dodgy accounting. I wonder what's up with all that.

2002-11-07 23:57:29

by Robert Love

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest

On Thu, 2002-11-07 at 18:58, Andrew Morton wrote:

> Robert Love wrote:
> >
> > On Thu, 2002-11-07 at 17:53, Con Kolivas wrote:
> >
> > > io_load:
> > > Kernel [runs] Time CPU% Loads LCPU% Ratio
> > > 2.5.44-mm6 [3] 284.1 28 20 10 3.98
> > > 2.5.46 [1] 600.5 13 48 12 8.41
> > > 2.5.46-mm1 [5] 134.3 58 6 8 1.88
> > >
> > > Big change here. IO load is usually the one we feel the most.
> >
> > Nice.
>
> Mysterious.

Why? We are preempting during the generic file write/read routines, I
bet, which can otherwise be long periods of latency. CPU is up and I
bet the throughput is down, but his test is getting the attention it
wants.

Robert Love

2002-11-08 00:03:44

by Benjamin LaHaise

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest

On Thu, Nov 07, 2002 at 03:58:48PM -0800, Andrew Morton wrote:
> > Nice.
>
> Mysterious.

Nah, that's the allocator changes kicking in.

-ben
--
"Do you seek knowledge in time travel?"

2002-11-08 00:30:08

by Alan Willis

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest

> Why? We are preempting during the generic file write/read routines, I
> bet, which can otherwise be long periods of latency. CPU is up and I
> bet the throughput is down, but his test is getting the attention it
> wants.

I'm curious, would running contest after a fresh boot and with profile=2
provide a profile that tells exactly where time is being spent? Since
about 2.5.45 I've had some strange slow periods, and starting aterm
would take a while, redrawing windows in X would slow down, it 'feels'
like my workstation becomes a laptop that is just waking up. Sometimes
this is after only a few minutes of inactivity, or after switching
virtual desktops in kde, or when I have alot of aterm instances running.
Normal activity for me involves untarring and compiling lots of
software on a regular basis, on a 1.2Ghz celeron and 256mb of mem. I'm
using 2.5.46+reiser4 patches at the moment. I'll boot to 2.5.46-mm1
shortly, but I'd love to use reiser4 with akpm's tree though.

Would oprofile help figure out why aterm gets so effing slow at times?
I guess I need to sit down and figure out how to use it.

-alan


2002-11-08 00:41:34

by Andrew Morton

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest

Alan Willis wrote:
>
> > Why? We are preempting during the generic file write/read routines, I
> > bet, which can otherwise be long periods of latency. CPU is up and I
> > bet the throughput is down, but his test is getting the attention it
> > wants.
>
> I'm curious, would running contest after a fresh boot and with profile=2
> provide a profile that tells exactly where time is being spent? Since
> about 2.5.45 I've had some strange slow periods, and starting aterm
> would take a while, redrawing windows in X would slow down, it 'feels'
> like my workstation becomes a laptop that is just waking up. Sometimes
> this is after only a few minutes of inactivity, or after switching
> virtual desktops in kde, or when I have alot of aterm instances running.

- Run `vmstat 1', and see if the slowdowns coincide with any unusual
IO activity.

- Could be the scheduler. Try
renice -19 $(pidof X) $(pidof aterm) $(pidof other stuff)

2002-11-08 05:58:30

by Con Kolivas

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest

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

Ok well I guess some more data is required to interpret this.

>On Thu, 2002-11-07 at 18:58, Andrew Morton wrote:
>> Robert Love wrote:
>> > On Thu, 2002-11-07 at 17:53, Con Kolivas wrote:
>> > > io_load:
>> > > Kernel [runs] Time CPU% Loads LCPU% Ratio
>> > > 2.5.44-mm6 [3] 284.1 28 20 10 3.98
>> > > 2.5.46 [1] 600.5 13 48 12 8.41
>> > > 2.5.46-mm1 [5] 134.3 58 6 8 1.88
>> > >
>> > > Big change here. IO load is usually the one we feel the most.
>> >
>> > Nice.
>>
>> Mysterious.
>
>Why? We are preempting during the generic file write/read routines, I
>bet, which can otherwise be long periods of latency. CPU is up and I
>bet the throughput is down, but his test is getting the attention it
>wants.

Here are the results with 2.5.46-mm1 with and without preempt (2.5.46-mmnp)
only where they _differ_ for clarity:

process_load:
Kernel [runs] Time CPU% Loads LCPU% Ratio
2.5.44-mm6 [3] 190.6 36 166 63 2.67
2.5.46 [1] 92.9 74 36 29 1.30
2.5.46-mm1 [5] 82.7 82 21 21 1.16
2.5.46-mmnp [3] 93.8 72 37 29 1.31

Note that 2.5.46-mm1 without preempt here is comparable to 2.5.46 vanilla.
Also, this one is prone to the process_load getting stuck endlessly piping
data around and me having to kill the run. These were the 3 successful runs.
Are the changes that fixed this problem in 2.5.44-mm6 backed out in
2.5.46-mm1? Also it seems interesting to me that preempt manages to break out
of this loop and is not prone to that hang.

io_load:
Kernel [runs] Time CPU% Loads LCPU% Ratio
2.5.44-mm6 [3] 284.1 28 20 10 3.98
2.5.46 [1] 600.5 13 48 12 8.41
2.5.46-mm1 [5] 134.3 58 6 8 1.88
2.5.46-mmnp [4] 357.6 22 27 11 5.01

I guess this is the one we were most interested in and no doubt it takes less
time with preempt enabled

A few more things to clarify that were queried: Only the kernel compilation
time and cpu% are accurate. The "Loads" field takes the total number of
iterations done by the load over the duration of the load running and divides
it by the time the load ran over the kernel compilation time. Thus it is not
reliably accurate enough because the duration the load runs beyond kernel
compilation time is variable :- It takes a variable length of time to kill
the load. The load cpu% (lcpu%) is that spit out by "time load" and as I said
this runs for longer than the kernel compilation so will be an overestimate.
I haven't found a way around this. It seems to be routine that loads done
drops disproportionately when kernel compilation shortens. This seems to be
more a load accounting problem (dont have a fix for that). Furthermore, since
kernel compilation is -j4 and the load is one task all at the same nice level
it would seem to be ideal for kernel compilation time to increase by 5/4 (and
ratio to equal 1.25) , and concomitantly for cpu% to drop to 4/5 (80%) of
noload.

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

iD8DBQE9y1PeF6dfvkL3i1gRAkNXAJ47qgYAd9mygNpF7KDnzyuR6xjX3ACeORH7
Eo3HgfvJ7hJe1ykoaPEEQyQ=
=2L0b
-----END PGP SIGNATURE-----

2002-11-08 21:06:37

by Alan Willis

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest

Ok, it just happened again. Everything got slow, changing desktops,
starting new aterms,. etc. I flipped to a tty, and started a vmstat
log,
and went back into X, and reprioritised stuff with a terminal that was
just bearably slow enough to work. After renicing X stuff got a bit
better. A little. After renicing my aterms, it got slightly better
still.

alan@aries:~$ sudo renice -19 `pgrep X`
499: old priority 0, new priority -19
alan@aries:~$ sudo renice -19 `pgrep aterm`
686: old priority 0, new priority -19
818: old priority 0, new priority -19
1030: old priority 0, new priority -19
1130: old priority 0, new priority -19
1202: old priority 0, new priority -19
1691: old priority 0, new priority -19
1762: old priority 0, new priority -19
2013: old priority 0, new priority -19
2164: old priority 0, new priority -19
2281: old priority 0, new priority -19
2406: old priority 0, new priority -19
2490: old priority 0, new priority -19
2558: old priority 0, new priority -19
2559: old priority 0, new priority -19
2838: old priority 0, new priority -19
3050: old priority 0, new priority -19
3056: old priority 0, new priority -19
3158: old priority 0, new priority -19

After flipping back to my vmstat log tty, I found that vmstat had
segfaulted instead of run, I didnt see it because I ran it in the
background and ran a tail of the file it was supposed to log to. I'm
using procps 2.0.7 as distributed in RH8.0, which I assume is too old a
version. I attached an strace of it running if anyone is curious.

To give an example ofhow intermitently slow this is, I took one of my
reniced aterms, and tried running aterm with the options I usually use.
I started another instance of aterm elsewhere, and in my current terminal,
I ran the following:

alan@aries:~$ time /usr/local/bin/aterm -tr -trsb -fade 60 -bg blue -fg -e
exit

real 0m0.924s
user 0m0.017s
sys 0m0.014s
alan@aries:~$ time /usr/local/bin/aterm -tr -trsb -fade 60 -bg blue -fg -e
exit

real 0m4.895s
user 0m0.018s
sys 0m0.018s
alan@aries:~$ time /usr/local/bin/aterm -tr -trsb -fade 60 -bg blue -fg -e
exit
real 0m1.436s
user 0m0.014s
sys 0m0.018s
alan@aries:~$ time /usr/local/bin/aterm -tr -trsb -fade 60 -bg blue -fg -e
exit

real 0m0.797s
user 0m0.017s
sys 0m0.017s
alan@aries:~$ time /usr/local/bin/aterm -tr -trsb -fade 60 -bg blue -fg -e
exit

real 0m1.122s
user 0m0.017s
sys 0m0.019s

I had enough time to run aterm this way about four times before I got
that other instance of aterm to give me a usable prompt.

I'll go upgrade my procps so I have a working vmstat for you next time,
sorry about that. Whose shall I use? (riel/rml or calahan, or both?)

-alan

> Alan Willis wrote:
>>
>> > Why? We are preempting during the generic file write/read routines,
>> I bet, which can otherwise be long periods of latency. CPU is up
>> and I bet the throughput is down, but his test is getting the
>> attention it wants.
>>
>> I'm curious, would running contest after a fresh boot and with
>> profile=2
>> provide a profile that tells exactly where time is being spent? Since
>> about 2.5.45 I've had some strange slow periods, and starting aterm
>> would take a while, redrawing windows in X would slow down, it 'feels'
>> like my workstation becomes a laptop that is just waking up.
>> Sometimes this is after only a few minutes of inactivity, or after
>> switching virtual desktops in kde, or when I have alot of aterm
>> instances running.
>
> - Run `vmstat 1', and see if the slowdowns coincide with any unusual
> IO activity.
>
> - Could be the scheduler. Try
> renice -19 $(pidof X) $(pidof aterm) $(pidof other stuff)



Attachments:
vmstat-strace.log (21.31 kB)

2002-11-08 21:14:27

by Andrew Morton

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest

Alan Willis wrote:
>
> Ok, it just happened again.

That's good.

> I'll go upgrade my procps so I have a working vmstat for you next time,
> sorry about that. Whose shall I use? (riel/rml or calahan, or both?)

Either should do. The surriel.com/procps one is presumably more
redhatty, but whatever. Also, run top and see if something is burning
CPU. /proc/meminfo, /proc/slabinfo, all that stuff. The clues will
be in there somewhere - it's a matter of hunting around...

2002-11-11 20:57:06

by Andrew Morton

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest

Alan Willis wrote:
>
> Attached are the slabinfo, meminfo, and output of vmstat 1. My system
> was almost unusable at the time, so I got what I could. I don't have
> anything in my crontab. This morning my system had been sitting
> quietly all weekend, I did a few things, and then removed a large
> directory and untarred 2.5.47, less than a minute after which my system
> got unbearably slow.
>
> It should be noted that I have a 2.5.46 + reiser4 patches, which I think
> made a few changes under mm/. I also had a reiser4 partition mounted at
> the time, with slightly under 1 million empty files in it. I hadn't
> accessed it in a while though.
>


MemTotal: 251332 kB
MemFree: 1748 kB
MemShared: 0 kB
Buffers: 352 kB
Cached: 30040 kB

This is presumably active mmapped memory. executable text.

SwapCached: 41748 kB
Active: 165064 kB

That's a lot of active memory.

Inactive: 976 kB
HighTotal: 0 kB
HighFree: 0 kB
LowTotal: 251332 kB
LowFree: 1748 kB
SwapTotal: 1028152 kB
SwapFree: 834084 kB
Dirty: 0 kB
Writeback: 0 kB
Mapped: 164592 kB

That's an awful lot of mapped memory. Have you been altering
/proc/sys/vm/swappiness? Has some application run berzerk
and used tons of memory?

Slab: 7592 kB
Committed_AS: 423120 kB
PageTables: 1996 kB
ReverseMaps: 69425
HugePages_Total: 15
HugePages_Free: 15
Hugepagesize: 4096 kB

You've lost 60 megabytes in hugepages! Bill's patch (which is in .47)
changes the initial number of hugetlb pages to zero, which is rather
kinder.

So I don't _think_ there's a leak here. It could be that your
normal workload fits OK ito 256 megs, but thrashes when it is
squeezed into 196 megs.

Suggest you do `echo 0 > /proc/sys/vm/nr_hugepages' and retest.

2002-11-11 21:10:02

by Alan Willis

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest


> That's an awful lot of mapped memory. Have you been altering
> /proc/sys/vm/swappiness? Has some application run berzerk
> and used tons of memory?
>
> Slab: 7592 kB
> Committed_AS: 423120 kB
> PageTables: 1996 kB
> ReverseMaps: 69425
> HugePages_Total: 15
> HugePages_Free: 15
> Hugepagesize: 4096 kB

vm.swappiness was set to 0

>
> You've lost 60 megabytes in hugepages! Bill's patch (which is in .47)
> changes the initial number of hugetlb pages to zero, which is rather
> kinder.
>
> So I don't _think_ there's a leak here. It could be that your
> normal workload fits OK ito 256 megs, but thrashes when it is
> squeezed into 196 megs.
>
> Suggest you do `echo 0 > /proc/sys/vm/nr_hugepages' and retest.

Done, vm.nr_hugepages = 0 # from 15

I'll stick to 2.5.46 for a while yet I guess, to be sure.

-alan



2002-11-11 21:25:26

by Andrew Morton

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest

Alan Willis wrote:
>
> > That's an awful lot of mapped memory. Have you been altering
> > /proc/sys/vm/swappiness? Has some application run berzerk
> > and used tons of memory?
> >
> > Slab: 7592 kB
> > Committed_AS: 423120 kB
> > PageTables: 1996 kB
> > ReverseMaps: 69425
> > HugePages_Total: 15
> > HugePages_Free: 15
> > Hugepagesize: 4096 kB
>
> vm.swappiness was set to 0

OK ;)

That sucker really works. I run my desktop machines (768M and 256M)
at swappiness=80% or 90%. I end up with 10-20 megs in swap after a
day or two, which seems about right. The default of 60 is probably a
little too unswappy.

> I'll stick to 2.5.46 for a while yet I guess, to be sure.

Thanks.

2002-11-12 19:22:37

by Denis Vlasenko

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest

On 11 November 2002 19:32, Andrew Morton wrote:
> That sucker really works. I run my desktop machines (768M and 256M)
> at swappiness=80% or 90%. I end up with 10-20 megs in swap after a
> day or two, which seems about right. The default of 60 is probably a
> little too unswappy.

I think swappiness should depend also on mem/disk latency ratio.
Imagine you have 32Gb IDE 'disk' made internally of tons of DRAM chips
(such things exist). I suppose you would like to swap more to it,
since access times are not ~10 ms, they are more like 10 us.

Hand tuning for optimal performance is doomed to be periodically
obsoleted by technology jumps. Today RAM is 1000000 times faster
than mass storage. Nobody knows what will happen in five years.
--
vda

2002-11-12 20:07:24

by Alan Willis

[permalink] [raw]
Subject: Re: [BENCHMARK] 2.5.46-mm1 with contest


Still running 2.5.46, put more memory in this machine (I need it
anyway, 256mb for what I do is truly masochistic) and now I have 384Mb.
This time when pressuring memory (ever setup KDevelop for the first
time and index your documentation? not pretty) things got a bit
sluggish, then I tuned vm.swappiness to 50 (from 0). About a minute
later it began swapping a bit
more, and things are much better. When vm.swappiness was at 0, 1300 bytes
were swapped. As I'm writing this, (vm.swappiness at 100) 39448 bytes are
swapped, after less than five minutes.

-alan


> On 11 November 2002 19:32, Andrew Morton wrote:
>> That sucker really works. I run my desktop machines (768M and 256M)
>> at swappiness=80% or 90%. I end up with 10-20 megs in swap after a
>> day or two, which seems about right. The default of 60 is probably a
>> little too unswappy.
>
> I think swappiness should depend also on mem/disk latency ratio.
> Imagine you have 32Gb IDE 'disk' made internally of tons of DRAM chips
> (such things exist). I suppose you would like to swap more to it,
> since access times are not ~10 ms, they are more like 10 us.
>
> Hand tuning for optimal performance is doomed to be periodically
> obsoleted by technology jumps. Today RAM is 1000000 times faster
> than mass storage. Nobody knows what will happen in five years.
> --
> vda