[git patches] IDE update

[git patches] IDE update

[Bartlomiej Zolnierkiewicz]

Hi,

Please pull from:
rsync://rsync.kernel.org/pub/scm/linux/kernel/git/bart/ide-2.6.git

diffstat+changelog below

Bartlomiej


  drivers/ide/Makefile        |    1 -
  drivers/ide/ide-lib.c       |   13 +++++--------
  drivers/ide/pci/alim15x3.c  |   10 +++++-----
  drivers/ide/pci/amd74xx.c   |    7 +++++--
  drivers/ide/pci/cs5530.c    |    4 ++--
  drivers/ide/pci/cy82c693.c  |    8 ++++----
  drivers/ide/pci/it8172.c    |    4 ++--
  drivers/ide/pci/ns87415.c   |    2 +-
  drivers/ide/pci/opti621.c   |    2 +-
  drivers/ide/pci/sc1200.c    |    2 +-
  drivers/ide/pci/sl82c105.c  |    6 +++---
  drivers/ide/pci/slc90e66.c  |    2 +-
  drivers/ide/pci/triflex.c   |    2 +-
  drivers/ide/pci/via82cxxx.c |    4 ++--
  include/linux/pci_ids.h     |    1 +
  15 files changed, 34 insertions(+), 34 deletions(-)

commit 10e047b40aafefef1fdc8ea4ea7837b9557a9400
tree 4105ba774c775cdf53fb5fd3e07158b15218cb27
parent 21e2c01dc3e38d466eda5871645878d2c3a33261
author Adrian Bunk <bunk@stusta.de> Sun, 03 Jul 2005 17:44:10 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 17:44:10 +0200

[PATCH] drivers/ide/Makefile: kill dead CONFIG_BLK_DEV_IDE_TCQ entry

This patch kills the dead CONFIG_BLK_DEV_IDE_TCQ entry.

Signed-off-by: Adrian Bunk <bunk@stusta.de>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit 21e2c01dc3e38d466eda5871645878d2c3a33261
tree a2a4fb15b2295e635de9f734f720f783c97a6513
parent 13bbbf28fb914da6707aad44a073651f5c9d13a5
author Rob Punkunus <rpunkunus@nvidia.com> Sun, 03 Jul 2005 17:37:18 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 17:37:18 +0200

[PATCH] amd74xx: support MCP55 device IDs

From: Rob Punkunus <rpunkunus@nvidia.com>

Rob Punkunus recently submitted a patch to enable support for MCP51/MCP55 in
the amd74xx driver. This patch was whitespace-corrupted and didn't apply to
2.6.12 since MCP51 support was merged in the 2.6.12-rc series.

Gentoo would like to support this hardware for our upcoming release media, so
I fixed the patch, and here it is :)

Signed-off-by: Daniel Drake <dsd@gentoo.org>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit 13bbbf28fb914da6707aad44a073651f5c9d13a5
tree 16cea5674a7da7aa1b318685598a87d7dc806ba1
parent f3718d3e135117f80de0ff219be91544baa75599
author Denis Vlasenko <vda@ilport.com.ua> Sun, 03 Jul 2005 17:09:13 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 17:09:13 +0200

[PATCH] ide: fix line break in ide messages

From: Denis Vlasenko <vda@ilport.com.ua>

* printk("\n") is misplaced, resulting in stray empty line in kernel log
* cleanups nerby: some back-to-back printks are combined, etc

Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit f3718d3e135117f80de0ff219be91544baa75599
tree 48c98f74b12e7669b787bd9c75edf8fd20e07912
parent d6904ab66f74cb99793e3919fc589dd0163a7740
author Herbert Xu <herbert@gondor.apana.org.au> Sun, 03 Jul 2005 16:42:18 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 16:42:18 +0200

[PATCH] ide: hotplug mark __devinit via82cxxx.c

From: Herbert Xu <herbert@gondor.apana.org.au>

mark the __init section __devinit.
Splitted up from the Debian kernel patch.

Signed-off-by: maximilian attems <janitor@sternwelten.at>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit d6904ab66f74cb99793e3919fc589dd0163a7740
tree f68e6b3b5603d67b92a3276b35c623054c3ecdf9
parent 97319630b21c2022a55d51a6cfbf53cbb84a2f42
author Herbert Xu <herbert@gondor.apana.org.au> Sun, 03 Jul 2005 16:40:31 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 16:40:31 +0200

[PATCH] ide: hotplug mark __devinit triflex.c

From: Herbert Xu <herbert@gondor.apana.org.au>

mark the __init section __devinit.
Splitted up from the Debian kernel patch.

Signed-off-by: maximilian attems <janitor@sternwelten.at>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit 97319630b21c2022a55d51a6cfbf53cbb84a2f42
tree 5d831d1f2a2c264e1d3dc55f6f2f967b7c7c010c
parent 34a6224691e638dd36b393aa439d021a19578fcc
author Herbert Xu <herbert@gondor.apana.org.au> Sun, 03 Jul 2005 16:38:51 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 16:38:51 +0200

[PATCH] ide: hotplug mark __devinit slc90e66.c

From: Herbert Xu <herbert@gondor.apana.org.au>

mark the __init section __devinit.
Splitted up from the Debian kernel patch.

Signed-off-by: maximilian attems <janitor@sternwelten.at>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit 34a6224691e638dd36b393aa439d021a19578fcc
tree 0c6fb291d2d9657f83c7bb0427eacad8f6f05d81
parent 6a6e1b1cf41b0bf35fffbf18787e8d8f865b66d6
author Herbert Xu <herbert@gondor.apana.org.au> Sun, 03 Jul 2005 16:36:56 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 16:36:56 +0200

[PATCH] ide: hotplug mark __devinit sl82c105.c

From: Herbert Xu <herbert@gondor.apana.org.au>

mark the __init section __devinit.
Splitted up from the Debian kernel patch.

Signed-off-by: maximilian attems <janitor@sternwelten.at>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit 6a6e1b1cf41b0bf35fffbf18787e8d8f865b66d6
tree ead647e67974ce09bf14b194be6ad99787a0c176
parent 9307145700e869dd410d565477f98377e93e9160
author Herbert Xu <herbert@gondor.apana.org.au> Sun, 03 Jul 2005 16:35:07 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 16:35:07 +0200

[PATCH] ide: hotplug mark __devinit sc1200.c

From: Herbert Xu <herbert@gondor.apana.org.au>

mark the __init section __devinit.
Splitted up from the Debian kernel patch.

Signed-off-by: maximilian attems <janitor@sternwelten.at>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit 9307145700e869dd410d565477f98377e93e9160
tree bb887910e3dcef3b084a078004548268786d8166
parent c20530ed26e5b9e3b188b4088d0a5ab1d773a529
author Herbert Xu <herbert@gondor.apana.org.au> Sun, 03 Jul 2005 16:33:16 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 16:33:16 +0200

[PATCH] ide: hotplug mark __devinit opti621.c

From: Herbert Xu <herbert@gondor.apana.org.au>

mark the __init section __devinit.
Splitted up from the Debian kernel patch.

Signed-off-by: maximilian attems <janitor@sternwelten.at>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit c20530ed26e5b9e3b188b4088d0a5ab1d773a529
tree 5c68ff26c3c1fe342cc095a1a53b2d1aedada684
parent a380a8849f90ba81a5ff0c325fd5d8125c70b3bb
author Herbert Xu <herbert@gondor.apana.org.au> Sun, 03 Jul 2005 16:31:04 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 16:31:04 +0200

[PATCH] ide: hotplug mark __devinit ns87415.c

From: Herbert Xu <herbert@gondor.apana.org.au>

mark the __init section __devinit.
Splitted up from the Debian kernel patch.

Signed-off-by: maximilian attems <janitor@sternwelten.at>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit a380a8849f90ba81a5ff0c325fd5d8125c70b3bb
tree 5c0ee15020ff929536331d9a00a76cbfac0bf035
parent ddbc9fb47252f9b6966bfe9b0aa27bfeaa585cca
author Herbert Xu <herbert@gondor.apana.org.au> Sun, 03 Jul 2005 16:28:44 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 16:28:44 +0200

[PATCH] ide: hotplug mark __devinit it8172.c

From: Herbert Xu <herbert@gondor.apana.org.au>

mark the __init section __devinit.
Splitted up from the Debian kernel patch.

Signed-off-by: maximilian attems <janitor@sternwelten.at>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit ddbc9fb47252f9b6966bfe9b0aa27bfeaa585cca
tree 41eefbf36f12c095303eb0811c8e28ea6af895db
parent 88de8e996f16b958721368ed9b4fd4e29cdb923e
author Herbert Xu <herbert@gondor.apana.org.au> Sun, 03 Jul 2005 16:25:46 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 16:25:46 +0200

[PATCH] ide: hotplug mark __devinit cy82c693.c

From: Herbert Xu <herbert@gondor.apana.org.au>

mark the __init section __devinit.
Splitted up from the Debian kernel patch.

Signed-off-by: maximilian attems <janitor@sternwelten.at>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit 88de8e996f16b958721368ed9b4fd4e29cdb923e
tree 24f89d1a1f739a4c48376e11b8a73c1f46a71ccb
parent e895f926cd8b6d50a42cc985d470bdc9a70caeed
author Herbert Xu <herbert@gondor.apana.org.au> Sun, 03 Jul 2005 16:23:08 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 16:23:08 +0200

[PATCH] ide: hotplug mark __devinit cs5530.c

From: Herbert Xu <herbert@gondor.apana.org.au>

mark the __init section __devinit.
Splitted up from the Debian kernel patch.

Signed-off-by: maximilian attems <janitor@sternwelten.at>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit e895f926cd8b6d50a42cc985d470bdc9a70caeed
tree 8c2bc70f185842dfcd795f06afdb33d65e193d51
parent c2f12589bfc4119f2c331ecea8cca4945ed48497
author Herbert Xu <herbert@gondor.apana.org.au> Sun, 03 Jul 2005 16:15:41 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 16:15:41 +0200

[PATCH] ide: hotplug mark __devinit amd74xx.c

From: Herbert Xu <herbert@gondor.apana.org.au>

mark the __init section __devinit.
Splitted up from the Debian kernel patch.

Signed-off-by: maximilian attems <janitor@sternwelten.at>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------
commit c2f12589bfc4119f2c331ecea8cca4945ed48497
tree d00d17e062b845f35c79b456a70e8d3b45b3b556
parent 1d6bebf2ecf92924492c491d9c3a72edba95f907
author Herbert Xu <herbert@gondor.apana.org.au> Sun, 03 Jul 2005 16:06:13 +0200
committer Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl> Sun, 03 Jul 2005 16:06:13 +0200

[PATCH] ide: hotplug mark __devinit alim15x3.c

From: Herbert Xu <herbert@gondor.apana.org.au>

mark the __init section __devinit.
Splitted up from the Debian kernel patch.

see the thread about the pci hotplug crash on a stratus box.
http://marc.theaimsgroup.com/?l=linux-kernel&m=111930108613386&w=2

Signed-off-by: maximilian attems <janitor@sternwelten.at>
Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@elka.pw.edu.pl>
--------------------------

RE: [git patches] IDE update

[Al Boldi]

Bartlomiej Zolnierkiewicz wrote: {
Please pull from:
rsync://rsync.kernel.org/pub/scm/linux/kernel/git/bart/ide-2.6.git
}

Does it fix the idedriver int/dma problem?

Al

Re: [git patches] IDE update

[Bartlomiej Zolnierkiewicz]

On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
> Bartlomiej Zolnierkiewicz wrote: {
> Please pull from:
> rsync://rsync.kernel.org/pub/scm/linux/kernel/git/bart/ide-2.6.git
> }
> 
> Does it fix the idedriver int/dma problem?

What is the "int/dma problem"?

RE: [git patches] IDE update

[Al Boldi]

Bartlomiej Zolnierkiewicz wrote: {
What is the "int/dma problem"?
}

Hdparm -tT gives 38mb/s in 2.4.31
Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle

Hdparm -tT gives 28mb/s in 2.6.12
Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT

It feels like DMA is not being applied properly in 2.6.12.

Your comments please.

Thanks!

Re: [git patches] IDE update

[Bartlomiej Zolnierkiewicz]

On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
> Bartlomiej Zolnierkiewicz wrote: {
> What is the "int/dma problem"?
> }
> 
> Hdparm -tT gives 38mb/s in 2.4.31
> Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
> 
> Hdparm -tT gives 28mb/s in 2.6.12
> Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
> 
> It feels like DMA is not being applied properly in 2.6.12.
> 
> Your comments please.

Are earlier 2.6.x kernels okay?

dmesg output?

Bartlomiej

RE: [git patches] IDE update

[Al Boldi]

Bartlomiej Zolnierkiewicz wrote: {
> On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
> Hdparm -tT gives 38mb/s in 2.4.31
> Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
> 
> Hdparm -tT gives 28mb/s in 2.6.12
> Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
> 
> It feels like DMA is not being applied properly in 2.6.12.

Are earlier 2.6.x kernels okay?

dmesg output?
}

Same on 2.6.10,11,12.
No errors though, only sluggish system.

Re: [git patches] IDE update

[Ondrej Zary]

Al Boldi wrote:
> Bartlomiej Zolnierkiewicz wrote: {
> 
>>On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
>>Hdparm -tT gives 38mb/s in 2.4.31
>>Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
>>
>>Hdparm -tT gives 28mb/s in 2.6.12
>>Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
>>
>>It feels like DMA is not being applied properly in 2.6.12.
> 
> 
> Are earlier 2.6.x kernels okay?
> 
> dmesg output?
> }
> 
> Same on 2.6.10,11,12.
> No errors though, only sluggish system.

Something like this http://lkml.org/lkml/2005/6/13/1 ?

-- 
Ondrej Zary

Re: [git patches] IDE update

[Bartlomiej Zolnierkiewicz]

On 7/4/05, Ondrej Zary <linux@rainbow-software.org> wrote:
> Al Boldi wrote:
> > Bartlomiej Zolnierkiewicz wrote: {
> >
> >>On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
> >>Hdparm -tT gives 38mb/s in 2.4.31
> >>Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
> >>
> >>Hdparm -tT gives 28mb/s in 2.6.12
> >>Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
> >>
> >>It feels like DMA is not being applied properly in 2.6.12.
> >
> >
> > Are earlier 2.6.x kernels okay?
> >
> > dmesg output?
> > }
> >
> > Same on 2.6.10,11,12.
> > No errors though, only sluggish system.

What about earlier kernels?

Please try to narrow down the problem to a specific kernel version.

> Something like this http://lkml.org/lkml/2005/6/13/1 ?

It doesn't seem like IDE regression but...

Bartlomiej

RE: [git patches] IDE update

[Al Boldi]

Bartlomiej Zolnierkiewicz wrote: {
> >
> >>On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
> >>Hdparm -tT gives 38mb/s in 2.4.31
> >>Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
> >>
> >>Hdparm -tT gives 28mb/s in 2.6.12
> >>Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
> >>
> >>It feels like DMA is not being applied properly in 2.6.12.
> >
> > Same on 2.6.10,11,12.
> > No errors though, only sluggish system.

What about earlier kernels?
Please try to narrow down the problem to a specific kernel version.
}

Don't know about 2.6.0-2.6.9, but 2.4.31 is ok.

Bartlomiej,
When you compare 2.4.31 with 2.6.12 don't you see this problem on your
machine?
If you have a fast system the slowdown won't show, but your IOWAIT will be
higher anyway!
It feels like running on PIO instead of DMA.

Re: [git patches] IDE update

[Bartlomiej Zolnierkiewicz]

On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
> Bartlomiej Zolnierkiewicz wrote: {
> > >
> > >>On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
> > >>Hdparm -tT gives 38mb/s in 2.4.31
> > >>Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
> > >>
> > >>Hdparm -tT gives 28mb/s in 2.6.12
> > >>Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
> > >>
> > >>It feels like DMA is not being applied properly in 2.6.12.
> > >
> > > Same on 2.6.10,11,12.
> > > No errors though, only sluggish system.
> 
> What about earlier kernels?
> Please try to narrow down the problem to a specific kernel version.
> }
> 
> Don't know about 2.6.0-2.6.9, but 2.4.31 is ok.

2.4 -> 2.6 means zillions of changes.
 
> Bartlomiej,
> When you compare 2.4.31 with 2.6.12 don't you see this problem on your
> machine?

Unfortunately I've never encountered this problem on any machine.

> If you have a fast system the slowdown won't show, but your IOWAIT will be
> higher anyway!

AFAIK high iowait is a known block layer problem

> It feels like running on PIO instead of DMA.

Re: [git patches] IDE update

[André Tomt]

Al Boldi wrote:
> Bartlomiej Zolnierkiewicz wrote: {
> 
>>>>On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
>>>>Hdparm -tT gives 38mb/s in 2.4.31
>>>>Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
>>>>
>>>>Hdparm -tT gives 28mb/s in 2.6.12
>>>>Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT

The "hdparm doesn't get as high scores as in 2.4" is a old discussed to 
death "problem" on LKML. So far nobody has been able to show it affects 
anything  but that pretty useless quasi-benchmark.

>>>>It feels like DMA is not being applied properly in 2.6.12.
>>>
>>>Same on 2.6.10,11,12.
>>>No errors though, only sluggish system.

Really sluggish or just "benchmark-sluggish"? If the former, try 
selecting a different IO elevator/sheduler. If the latter it doesn't 
matter much, at least not with the very simple hdparm test :-)

>> 
>> What about earlier kernels?
>> Please try to narrow down the problem to a specific kernel version.
>> }
> 
> Don't know about 2.6.0-2.6.9, but 2.4.31 is ok.
> 
> Bartlomiej,
> When you compare 2.4.31 with 2.6.12 don't you see this problem on your
> machine?
> If you have a fast system the slowdown won't show, but your IOWAIT will be
> higher anyway!

Nothing wrong with 73% iowait, I'd even consider it very low while 
putting load on a harddrive. Its just time spent waiting for data to be 
returned from disk, and thus I usually expect no lower than ~98-99% 
while stressing any disk. Harddisks are _slow as snails_ compared to cpu 
cycles ;-)

Beware 2.4 didn't export that statistic at all to userspace, so 0% 
iowait gets reported from most 2.6-ready reporting tools on 2.4.

IOWAIT block layer problem

[Al Boldi]

André Tomt wrote: {
>>>>On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
>>>>Hdparm -tT gives 38mb/s in 2.4.31
>>>>Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
>>>>
>>>>Hdparm -tT gives 28mb/s in 2.6.12
>>>>Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT

The "hdparm doesn't get as high scores as in 2.4" is a old discussed to
death "problem" on LKML. So far nobody has been able to show it affects
anything  but that pretty useless quasi-benchmark.

>>>No errors though, only sluggish system.

Really sluggish or just "benchmark-sluggish"?
If the former, try selecting a different IO elevator/sheduler.

> When you compare 2.4.31 with 2.6.12 don't you see this problem on your 
> machine?
> If you have a fast system the slowdown won't show, but your IOWAIT 
> will be higher anyway!

Nothing wrong with 73% iowait
Beware 2.4 didn't export that statistic at all to userspace, so 0% iowait
gets reported from most 2.6-ready reporting tools on 2.4.

}

1. hdparm only gives you an indicator.
2. Really sluggish, as in unresponsive to commands.
3. Tried all IO elevators/shedulers to no avail.
4. In 2.4 IOWAIT is added to sys, as in 8% IOWAIT.

Re: [git patches] IDE update

[Ondrej Zary]

André Tomt wrote:
> Al Boldi wrote:
> 
>> Bartlomiej Zolnierkiewicz wrote: {
>>
>>>>> On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
>>>>> Hdparm -tT gives 38mb/s in 2.4.31
>>>>> Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
>>>>>
>>>>> Hdparm -tT gives 28mb/s in 2.6.12
>>>>> Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
> 
> 
> The "hdparm doesn't get as high scores as in 2.4" is a old discussed to 
> death "problem" on LKML. So far nobody has been able to show it affects 
> anything  but that pretty useless quasi-benchmark.
> 

No, it's not a problem with hdparm. hdparm only shows that there is 
_really_ a problem:

2.6.12
root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
count=1048576
1048576+0 records in
1048576+0 records out

real    0m32.339s
user    0m1.500s
sys     0m14.560s

2.4.26
root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
count=1048576
1048576+0 records in
1048576+0 records out

real    0m23.858s
user    0m1.750s
sys     0m15.180s

-- 
Ondrej Zary

Re: [git patches] IDE update

[Jens Axboe]

On Tue, Jul 05 2005, Ondrej Zary wrote:
> André Tomt wrote:
> >Al Boldi wrote:
> >
> >>Bartlomiej Zolnierkiewicz wrote: {
> >>
> >>>>>On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
> >>>>>Hdparm -tT gives 38mb/s in 2.4.31
> >>>>>Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
> >>>>>
> >>>>>Hdparm -tT gives 28mb/s in 2.6.12
> >>>>>Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
> >
> >
> >The "hdparm doesn't get as high scores as in 2.4" is a old discussed to 
> >death "problem" on LKML. So far nobody has been able to show it affects 
> >anything  but that pretty useless quasi-benchmark.
> >
> 
> No, it's not a problem with hdparm. hdparm only shows that there is 
> _really_ a problem:
> 
> 2.6.12
> root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
> count=1048576
> 1048576+0 records in
> 1048576+0 records out
> 
> real    0m32.339s
> user    0m1.500s
> sys     0m14.560s
> 
> 2.4.26
> root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
> count=1048576
> 1048576+0 records in
> 1048576+0 records out
> 
> real    0m23.858s
> user    0m1.750s
> sys     0m15.180s

Perhaps some read-ahead bug. What happens if you use bs=128k for
instance?

-- 
Jens Axboe

Re: [git patches] IDE update

[Ondrej Zary]

Jens Axboe wrote:
> On Tue, Jul 05 2005, Ondrej Zary wrote:
> 
>>André Tomt wrote:
>>
>>>Al Boldi wrote:
>>>
>>>
>>>>Bartlomiej Zolnierkiewicz wrote: {
>>>>
>>>>
>>>>>>>On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
>>>>>>>Hdparm -tT gives 38mb/s in 2.4.31
>>>>>>>Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
>>>>>>>
>>>>>>>Hdparm -tT gives 28mb/s in 2.6.12
>>>>>>>Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
>>>
>>>
>>>The "hdparm doesn't get as high scores as in 2.4" is a old discussed to 
>>>death "problem" on LKML. So far nobody has been able to show it affects 
>>>anything  but that pretty useless quasi-benchmark.
>>>
>>
>>No, it's not a problem with hdparm. hdparm only shows that there is 
>>_really_ a problem:
>>
>>2.6.12
>>root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
>>count=1048576
>>1048576+0 records in
>>1048576+0 records out
>>
>>real    0m32.339s
>>user    0m1.500s
>>sys     0m14.560s
>>
>>2.4.26
>>root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
>>count=1048576
>>1048576+0 records in
>>1048576+0 records out
>>
>>real    0m23.858s
>>user    0m1.750s
>>sys     0m15.180s
> 
> 
> Perhaps some read-ahead bug. What happens if you use bs=128k for
> instance?
> 
Nothing - it's still the same.

root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=128k 
count=4096
4096+0 records in
4096+0 records out

real    0m32.832s
user    0m0.040s
sys     0m15.670s

-- 
Ondrej Zary

Re: [git patches] IDE update

[Jens Axboe]

On Tue, Jul 05 2005, Ondrej Zary wrote:
> Jens Axboe wrote:
> >On Tue, Jul 05 2005, Ondrej Zary wrote:
> >
> >>André Tomt wrote:
> >>
> >>>Al Boldi wrote:
> >>>
> >>>
> >>>>Bartlomiej Zolnierkiewicz wrote: {
> >>>>
> >>>>
> >>>>>>>On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
> >>>>>>>Hdparm -tT gives 38mb/s in 2.4.31
> >>>>>>>Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
> >>>>>>>
> >>>>>>>Hdparm -tT gives 28mb/s in 2.6.12
> >>>>>>>Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
> >>>
> >>>
> >>>The "hdparm doesn't get as high scores as in 2.4" is a old discussed to 
> >>>death "problem" on LKML. So far nobody has been able to show it affects 
> >>>anything  but that pretty useless quasi-benchmark.
> >>>
> >>
> >>No, it's not a problem with hdparm. hdparm only shows that there is 
> >>_really_ a problem:
> >>
> >>2.6.12
> >>root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
> >>count=1048576
> >>1048576+0 records in
> >>1048576+0 records out
> >>
> >>real    0m32.339s
> >>user    0m1.500s
> >>sys     0m14.560s
> >>
> >>2.4.26
> >>root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
> >>count=1048576
> >>1048576+0 records in
> >>1048576+0 records out
> >>
> >>real    0m23.858s
> >>user    0m1.750s
> >>sys     0m15.180s
> >
> >
> >Perhaps some read-ahead bug. What happens if you use bs=128k for
> >instance?
> >
> Nothing - it's still the same.
> 
> root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=128k 
> count=4096
> 4096+0 records in
> 4096+0 records out
> 
> real    0m32.832s
> user    0m0.040s
> sys     0m15.670s

Can you post full dmesg of 2.4 and 2.6 kernel boot? What does hdparm
-I/-i say for both kernels?

-- 
Jens Axboe

Re: [git patches] IDE update

[Ondrej Zary]

[-- Attachment #1: Type: text/plain, Size: 1983 bytes --]

Jens Axboe wrote:
> On Tue, Jul 05 2005, Ondrej Zary wrote:
> 
>>Jens Axboe wrote:
>>
>>>On Tue, Jul 05 2005, Ondrej Zary wrote:
>>>
>>>
>>>>André Tomt wrote:
>>>>
>>>>
>>>>>Al Boldi wrote:
>>>>>
>>>>>
>>>>>
>>>>>>Bartlomiej Zolnierkiewicz wrote: {
>>>>>>
>>>>>>
>>>>>>
>>>>>>>>>On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
>>>>>>>>>Hdparm -tT gives 38mb/s in 2.4.31
>>>>>>>>>Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
>>>>>>>>>
>>>>>>>>>Hdparm -tT gives 28mb/s in 2.6.12
>>>>>>>>>Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
>>>>>
>>>>>
>>>>>The "hdparm doesn't get as high scores as in 2.4" is a old discussed to 
>>>>>death "problem" on LKML. So far nobody has been able to show it affects 
>>>>>anything  but that pretty useless quasi-benchmark.
>>>>>
>>>>
>>>>No, it's not a problem with hdparm. hdparm only shows that there is 
>>>>_really_ a problem:
>>>>
>>>>2.6.12
>>>>root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
>>>>count=1048576
>>>>1048576+0 records in
>>>>1048576+0 records out
>>>>
>>>>real    0m32.339s
>>>>user    0m1.500s
>>>>sys     0m14.560s
>>>>
>>>>2.4.26
>>>>root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
>>>>count=1048576
>>>>1048576+0 records in
>>>>1048576+0 records out
>>>>
>>>>real    0m23.858s
>>>>user    0m1.750s
>>>>sys     0m15.180s
>>>
>>>
>>>Perhaps some read-ahead bug. What happens if you use bs=128k for
>>>instance?
>>>
>>
>>Nothing - it's still the same.
>>
>>root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=128k 
>>count=4096
>>4096+0 records in
>>4096+0 records out
>>
>>real    0m32.832s
>>user    0m0.040s
>>sys     0m15.670s
> 
> 
> Can you post full dmesg of 2.4 and 2.6 kernel boot? What does hdparm
> -I/-i say for both kernels?
> 

The 2.4.26 kernel is the one from Slackware 10.0 bootable install CD.
dmesg outputs attached, hdparm -i and hdparm -I shows the same in both
kernels (compared using diff) - attached too.

-- 
Ondrej Zary


[-- Attachment #2: dmesg2426.txt --]
[-- Type: text/plain, Size: 5775 bytes --]

Linux version 2.4.26 (root@tree) (gcc version 3.3.4) #6 Mon Jun 14 19:07:27 PDT 2004
BIOS-provided physical RAM map:
 BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
 BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
 BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
 BIOS-e820: 0000000000100000 - 0000000007ff0000 (usable)
 BIOS-e820: 0000000007ff0000 - 0000000007ff3000 (ACPI NVS)
 BIOS-e820: 0000000007ff3000 - 0000000008000000 (ACPI data)
 BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
127MB LOWMEM available.
On node 0 totalpages: 32752
zone(0): 4096 pages.
zone(1): 28656 pages.
zone(2): 0 pages.
Kernel command line: BOOT_IMAGE=/kernels/bare.i/bzImage initrd=initrd.img load_ramdisk=1 prompt_ramdisk=0 ramdisk_size=6464 rw root=/dev/ram SLACK_KERNEL=bare.i
Initializing CPU#0
Detected 225.001 MHz processor.
Console: colour VGA+ 80x25
Calibrating delay loop... 448.92 BogoMIPS
Memory: 123608k/131008k available (1844k kernel code, 7012k reserved, 618k data, 120k init, 0k highmem)
Checking if this processor honours the WP bit even in supervisor mode... Ok.
Dentry cache hash table entries: 16384 (order: 5, 131072 bytes)
Inode cache hash table entries: 8192 (order: 4, 65536 bytes)
Mount cache hash table entries: 512 (order: 0, 4096 bytes)
Buffer cache hash table entries: 4096 (order: 2, 16384 bytes)
Page-cache hash table entries: 32768 (order: 5, 131072 bytes)
CPU:     After generic, caps: 0080a135 00000000 00000000 00000004
CPU:             Common caps: 0080a135 00000000 00000000 00000004
CPU: Cyrix M II 3x Core/Bus Clock stepping 04
Checking 'hlt' instruction... OK.
POSIX conformance testing by UNIFIX
mtrr: v1.40 (20010327) Richard Gooch (rgooch@atnf.csiro.au)
mtrr: detected mtrr type: Cyrix ARR
PCI: PCI BIOS revision 2.10 entry at 0xfb020, last bus=0
PCI: Using configuration type 1
PCI: Probing PCI hardware
PCI: Probing PCI hardware (bus 00)
PCI: Using IRQ router PIIX/ICH [8086/7110] at 00:07.0
PCI: Device 00:3a not found by BIOS
PCI: Device 00:3b not found by BIOS
Limiting direct PCI/PCI transfers.
Linux NET4.0 for Linux 2.4
Based upon Swansea University Computer Society NET3.039
Initializing RT netlink socket
Starting kswapd
VFS: Disk quotas vdquot_6.5.1
Journalled Block Device driver loaded
pty: 512 Unix98 ptys configured
Serial driver version 5.05c (2001-07-08) with HUB-6 MANY_PORTS MULTIPORT SHARE_IRQ SERIAL_PCI enabled
ttyS00 at 0x03f8 (irq = 4) is a 16550A
ttyS01 at 0x02f8 (irq = 3) is a 16550A
Real Time Clock Driver v1.10f
Floppy drive(s): fd0 is 1.44M
FDC 0 is a post-1991 82077
RAMDISK driver initialized: 16 RAM disks of 6464K size 1024 blocksize
loop: loaded (max 8 devices)
Uniform Multi-Platform E-IDE driver Revision: 7.00beta4-2.4
ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
PIIX4: IDE controller at PCI slot 00:07.1
PIIX4: chipset revision 1
PIIX4: not 100% native mode: will probe irqs later
    ide0: BM-DMA at 0xf000-0xf007, BIOS settings: hda:pio, hdb:pio
    ide1: BM-DMA at 0xf008-0xf00f, BIOS settings: hdc:pio, hdd:pio
hda: WDC WD300BB-00AUA1, ATA DISK drive
blk: queue c03b3360, I/O limit 4095Mb (mask 0xffffffff)
hdd: MSI CD-RW MS-8340S, ATAPI CD/DVD-ROM drive
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
ide1 at 0x170-0x177,0x376 on irq 15
hda: attached ide-disk driver.
hda: host protected area => 1
hda: 58633344 sectors (30020 MB) w/2048KiB Cache, CHS=3649/255/63, UDMA(33)
hdd: attached ide-cdrom driver.
hdd: ATAPI 48X CD-ROM CD-R/RW drive, 2048kB Cache, UDMA(33)
Uniform CD-ROM driver Revision: 3.12
Partition check:
 hda: hda2 hda3 < hda5 hda6 hda7 >
SCSI subsystem driver Revision: 1.00
kmod: failed to exec /sbin/modprobe -s -k scsi_hostadapter, errno = 2
kmod: failed to exec /sbin/modprobe -s -k scsi_hostadapter, errno = 2
kmod: failed to exec /sbin/modprobe -s -k scsi_hostadapter, errno = 2
md: linear personality registered as nr 1
md: raid0 personality registered as nr 2
md: raid1 personality registered as nr 3
md: raid5 personality registered as nr 4
raid5: measuring checksumming speed
   8regs     :   319.600 MB/sec
   32regs    :   228.800 MB/sec
   pII_mmx   :   334.800 MB/sec
   p5_mmx    :   380.800 MB/sec
raid5: using function: p5_mmx (380.800 MB/sec)
md: md driver 0.90.0 MAX_MD_DEVS=256, MD_SB_DISKS=27
md: Autodetecting RAID arrays.
md: autorun ...
md: ... autorun DONE.
LVM version 1.0.8(17/11/2003)
Initializing Cryptographic API
NET4: Linux TCP/IP 1.0 for NET4.0
IP Protocols: ICMP, UDP, TCP, IGMP
IP: routing cache hash table of 512 buckets, 4Kbytes
TCP: Hash tables configured (established 8192 bind 16384)
Linux IP multicast router 0.06 plus PIM-SM
NET4: Unix domain sockets 1.0/SMP for Linux NET4.0.
RAMDISK: Compressed image found at block 0
Freeing initrd memory: 2607k freed
EXT2-fs warning: checktime reached, running e2fsck is recommended
VFS: Mounted root (ext2 filesystem).
Freeing unused kernel memory: 120k freed
usb.c: registered new driver usbdevfs
usb.c: registered new driver hub
uhci.c: USB Universal Host Controller Interface driver v1.1
PCI: Found IRQ 11 for device 00:07.2
uhci.c: USB UHCI at I/O 0x6400, IRQ 11
usb.c: new USB bus registered, assigned bus number 1
hub.c: USB hub found
hub.c: 2 ports detected
usb.c: registered new driver usbkbd
usbkbd.c: :USB HID Boot Protocol keyboard driver
usb.c: registered new driver hiddev
usb.c: registered new driver hid
hid-core.c: v1.8.1 Andreas Gal, Vojtech Pavlik <vojtech@suse.cz>
hid-core.c: USB HID support drivers
mice: PS/2 mouse device common for all mice
Initializing USB Mass Storage driver...
usb.c: registered new driver usb-storage
USB Mass Storage support registered.
kjournald starting.  Commit interval 5 seconds
EXT3 FS 2.4-0.9.19, 19 August 2002 on ide0(3,6), internal journal
EXT3-fs: mounted filesystem with ordered data mode.


[-- Attachment #3: dmesg2612.txt --]
[-- Type: text/plain, Size: 8344 bytes --]

Linux version 2.6.12-pentium (root@pentium) (gcc version 3.3.5) #3 Sun Jul 3 11:27:42 CEST 2005
BIOS-provided physical RAM map:
 BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
 BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
 BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
 BIOS-e820: 0000000000100000 - 0000000007ff0000 (usable)
 BIOS-e820: 0000000007ff0000 - 0000000007ff3000 (ACPI NVS)
 BIOS-e820: 0000000007ff3000 - 0000000008000000 (ACPI data)
 BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
127MB LOWMEM available.
On node 0 totalpages: 32752
  DMA zone: 4096 pages, LIFO batch:1
  Normal zone: 28656 pages, LIFO batch:15
  HighMem zone: 0 pages, LIFO batch:1
DMI 2.0 present.
ACPI: RSDP (v000 123456                                ) @ 0x000f6c40
ACPI: RSDT (v001 123456 AWRDACPI 0x00000000  0x00000000) @ 0x07ff3000
ACPI: FADT (v001 123456 AWRDACPI 0x00000000  0x00000000) @ 0x07ff3040
ACPI: DSDT (v001 123456 AWRDACPI 0x00001000 MSFT 0x01000007) @ 0x00000000
Allocating PCI resources starting at 08000000 (gap: 08000000:f7ff0000)
Built 1 zonelists
Kernel command line: auto BOOT_IMAGE=Linux2612 ro root=306 video=matroxfb:vesa:0x105,fv:85,left:192
Initializing CPU#0
PID hash table entries: 512 (order: 9, 8192 bytes)
Detected 225.009 MHz processor.
Using tsc for high-res timesource
Console: colour VGA+ 80x25
Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
Memory: 125792k/131008k available (2078k kernel code, 4696k reserved, 944k data, 148k init, 0k highmem)
Checking if this processor honours the WP bit even in supervisor mode... Ok.
Calibrating delay loop... 448.92 BogoMIPS (lpj=2244608)
Mount-cache hash table entries: 512
CPU: After generic identify, caps: 0080a135 00000000 00000000 00000000 00000000 00000000 00000000
CPU: After vendor identify, caps: 0080a135 00000000 00000000 00000000 00000000 00000000 00000000
CPU: After all inits, caps: 0080a135 00000000 00000000 00000004 00000000 00000000 00000000
CPU: Cyrix M II 3x Core/Bus Clock stepping 04
Checking 'hlt' instruction... OK.
ACPI: setting ELCR to 0200 (from 0a00)
NET: Registered protocol family 16
PCI: Using configuration type 1
mtrr: v2.0 (20020519)
ACPI: Subsystem revision 20050309
    ACPI-0216: *** Error: Return object type is incorrect [\_SB_.PCI0.ISA_.UAR1._PRW] (Node c1137fa0), AE_TYPE
    ACPI-0216: *** Error: Return object type is incorrect [\_SB_.PCI0.ISA_.UAR2._PRW] (Node c1137e80), AE_TYPE
    ACPI-0216: *** Error: Return object type is incorrect [\_SB_.PCI0.ISA_.LPT_._PRW] (Node c1137ca0), AE_TYPE
ACPI: Interpreter enabled
ACPI: Using PIC for interrupt routing
ACPI: PCI Root Bridge [PCI0] (0000:00)
PCI: Probing PCI hardware (bus 00)
Boot video device is 0000:00:14.0
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 7 10 11 12 14 15) *9
ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 6 7 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 6 7 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 7 10 *11 12 14 15)
ACPI: Power Resource [PFAN] (on)
Linux Plug and Play Support v0.97 (c) Adam Belay
pnp: PnP ACPI init
pnp: PnP ACPI: found 13 devices
PnPBIOS: Disabled by ACPI PNP
SCSI subsystem initialized
usbcore: registered new driver usbfs
usbcore: registered new driver hub
PCI: Using ACPI for IRQ routing
PCI: If a device doesn't work, try "pci=routeirq".  If it helps, post a report
Limiting direct PCI/PCI transfers.
ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 11
PCI: setting IRQ 11 as level-triggered
ACPI: PCI Interrupt 0000:00:14.0[A] -> Link [LNKA] -> GSI 11 (level, low) -> IRQ 11
matroxfb: Matrox Mystique (PCI) detected
matroxfb: MTRR's turned on
matroxfb: 1024x768x8bpp (virtual: 1024x4096)
matroxfb: framebuffer at 0xE1000000, mapped to 0xc8880000, size 4194304
Console: switching to colour frame buffer device 128x48
fb0: MATROX frame buffer device
ACPI: Power Button (FF) [PWRF]
ACPI: Fan [FAN] (on)
ACPI: CPU0 (power states: C1[C1] C2[C2])
ACPI: Thermal Zone [THRM] (22 C)
isapnp: Scanning for PnP cards...
pnp: CMI8330 quirk - fixing interrupts and dma
isapnp: Card 'AD-CHIPS Audio Adapter'
isapnp: Card '3Com 3C509B EtherLink III'
isapnp: 2 Plug & Play cards detected total
lp: driver loaded but no devices found
Real Time Clock Driver v1.12
Non-volatile memory driver v1.2
PNP: PS/2 Controller [PNP0303:PS2K,PNP0f13:PS2M] at 0x60,0x64 irq 1,12
serio: i8042 AUX port at 0x60,0x64 irq 12
serio: i8042 KBD port at 0x60,0x64 irq 1
Serial: 8250/16550 driver $Revision: 1.90 $ 8 ports, IRQ sharing enabled
ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
parport: PnPBIOS parport detected.
parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE,EPP]
lp0: using parport0 (interrupt-driven).
io scheduler noop registered
io scheduler anticipatory registered
io scheduler deadline registered
io scheduler cfq registered
Floppy drive(s): fd0 is 1.44M
FDC 0 is a post-1991 82077
loop: loaded (max 8 devices)
Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
PIIX4: IDE controller at PCI slot 0000:00:07.1
PIIX4: chipset revision 1
PIIX4: not 100% native mode: will probe irqs later
    ide0: BM-DMA at 0xf000-0xf007, BIOS settings: hda:pio, hdb:pio
    ide1: BM-DMA at 0xf008-0xf00f, BIOS settings: hdc:pio, hdd:pio
Probing IDE interface ide0...
hda: WDC WD300BB-00AUA1, ATA DISK drive
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Probing IDE interface ide1...
hdd: MSI CD-RW MS-8340S, ATAPI CD/DVD-ROM drive
ide1 at 0x170-0x177,0x376 on irq 15
Probing IDE interface ide2...
Probing IDE interface ide3...
Probing IDE interface ide4...
Probing IDE interface ide5...
hda: max request size: 128KiB
hda: 58633344 sectors (30020 MB) w/2048KiB Cache, CHS=58168/16/63, UDMA(33)
hda: cache flushes not supported
 hda: hda2 hda3 < hda5 hda6 hda7 >
hdd: ATAPI 48X CD-ROM CD-R/RW drive, 2048kB Cache, UDMA(33)
Uniform CD-ROM driver Revision: 3.20
usbmon: debugs is not available
USB Universal Host Controller Interface driver v2.2
ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
ACPI: PCI Interrupt 0000:00:07.2[D] -> Link [LNKD] -> GSI 11 (level, low) -> IRQ 11
uhci_hcd 0000:00:07.2: Intel Corporation 82371AB/EB/MB PIIX4 USB
uhci_hcd 0000:00:07.2: new USB bus registered, assigned bus number 1
uhci_hcd 0000:00:07.2: irq 11, io base 0x00006400
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 2 ports detected
Initializing USB Mass Storage driver...
usbcore: registered new driver usb-storage
USB Mass Storage support registered.
pnp: Device 01:01.02 activated.
gameport: NS558 PnP Gameport is pnp01:01.02/gameport0, io 0x200, speed 917kHz
mice: PS/2 mouse device common for all mice
input: PC Speaker
i2c /dev entries driver
piix4_smbus 0000:00:07.3: Found 0000:00:07.3 device
input: AT Translated Set 2 keyboard on isa0060/serio0
Advanced Linux Sound Architecture Driver Version 1.0.9rc2  (Thu Mar 24 10:33:39 2005 UTC).
ALSA device list:
  No soundcards found.
NET: Registered protocol family 2
IP: routing cache hash table of 512 buckets, 4Kbytes
TCP established hash table entries: 8192 (order: 4, 65536 bytes)
TCP bind hash table entries: 8192 (order: 3, 32768 bytes)
TCP: Hash tables configured (established 8192 bind 8192)
NET: Registered protocol family 1
NET: Registered protocol family 17
input: ImPS/2 Generic Wheel Mouse on isa0060/serio1
EXT3-fs: mounted filesystem with ordered data mode.
VFS: Mounted root (ext3 filesystem) readonly.
Freeing unused kernel memory: 148k freed
kjournald starting.  Commit interval 5 seconds
Adding 128480k swap on /dev/hda7.  Priority:-1 extents:1
EXT3 FS on hda6, internal journal
eth0: 3c5x9 found at 0x300, BNC port, address  00 20 af 49 ed b0, IRQ 10.
3c509.c:1.19b 08Nov2002 becker@scyld.com
http://www.scyld.com/network/3c509.html
eth0: Setting Rx mode to 1 addresses.
EXT3 FS on loop0, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting.  Commit interval 5 seconds
mtrr: 0xe1000000,0x800000 overlaps existing 0xe1000000,0x400000
init_special_inode: bogus i_mode (5102)


[-- Attachment #4: hdparmi2612.txt --]
[-- Type: text/plain, Size: 652 bytes --]


/dev/hda:

 Model=WDC WD300BB-00AUA1, FwRev=18.20D18, SerialNo=WD-WMA6W1847372
 Config={ HardSect NotMFM HdSw>15uSec SpinMotCtl Fixed DTR>5Mbs FmtGapReq }
 RawCHS=16383/16/63, TrkSize=57600, SectSize=600, ECCbytes=40
 BuffType=DualPortCache, BuffSize=2048kB, MaxMultSect=16, MultSect=16
 CurCHS=16383/16/63, CurSects=16514064, LBA=yes, LBAsects=58633344
 IORDY=on/off, tPIO={min:120,w/IORDY:120}, tDMA={min:120,rec:120}
 PIO modes:  pio0 pio1 pio2 pio3 pio4 
 DMA modes:  mdma0 mdma1 mdma2 
 UDMA modes: udma0 udma1 *udma2 
 AdvancedPM=no WriteCache=enabled
 Drive conforms to: device does not report version: 

 * signifies the current active mode



[-- Attachment #5: hdparmI2612.txt --]
[-- Type: text/plain, Size: 1536 bytes --]


/dev/hda:

ATA device, with non-removable media
	Model Number:       WDC WD300BB-00AUA1                      
	Serial Number:      WD-WMA6W1847372
	Firmware Revision:  18.20D18
Standards:
	Supported: 5 4 3 2 
	Likely used: 6
Configuration:
	Logical		max	current
	cylinders	16383	16383
	heads		16	16
	sectors/track	63	63
	--
	CHS current addressable sectors:   16514064
	LBA    user addressable sectors:   58633344
	device size with M = 1024*1024:       28629 MBytes
	device size with M = 1000*1000:       30020 MBytes (30 GB)
Capabilities:
	LBA, IORDY(can be disabled)
	bytes avail on r/w long: 40	Queue depth: 1
	Standby timer values: spec'd by Standard, with device specific minimum
	R/W multiple sector transfer: Max = 16	Current = 16
	Recommended acoustic management value: 128, current value: 254
	DMA: mdma0 mdma1 mdma2 udma0 udma1 *udma2 
	     Cycle time: min=120ns recommended=120ns
	PIO: pio0 pio1 pio2 pio3 pio4 
	     Cycle time: no flow control=120ns  IORDY flow control=120ns
Commands/features:
	Enabled	Supported:
	   *	READ BUFFER cmd
	   *	WRITE BUFFER cmd
	   *	Host Protected Area feature set
	   *	Look-ahead
	   *	Write cache
	   *	Power Management feature set
		Security Mode feature set
	   *	SMART feature set
		Automatic Acoustic Management feature set 
		SET MAX security extension
	   *	DOWNLOAD MICROCODE cmd
Security: 
		supported
	not	enabled
	not	locked
	not	frozen
	not	expired: security count
	not	supported: enhanced erase
HW reset results:
	CBLID- above Vih
	Device num = 0 determined by the jumper

Re: [git patches] IDE update

[Jens Axboe]

On Tue, 2005-07-05 at 14:35 +0200, Ondrej Zary wrote:
> >>>>2.4.26
> >>>>root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
> >>>>count=1048576
> >>>>1048576+0 records in
> >>>>1048576+0 records out
> >>>>
> >>>>real    0m23.858s
> >>>>user    0m1.750s
> >>>>sys     0m15.180s
> >>>
> >>>
> >>>Perhaps some read-ahead bug. What happens if you use bs=128k for
> >>>instance?
> >>>
> >>
> >>Nothing - it's still the same.
> >>
> >>root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=128k 
> >>count=4096
> >>4096+0 records in
> >>4096+0 records out
> >>
> >>real    0m32.832s
> >>user    0m0.040s
> >>sys     0m15.670s
> > 
> > 
> > Can you post full dmesg of 2.4 and 2.6 kernel boot? What does hdparm
> > -I/-i say for both kernels?
> > 
> 
> The 2.4.26 kernel is the one from Slackware 10.0 bootable install CD.
> dmesg outputs attached, hdparm -i and hdparm -I shows the same in both
> kernels (compared using diff) - attached too.

Ok, looks alright for both. Your machine is quite slow, perhaps that is
showing the slower performance. Can you try and make HZ 100 in 2.6 and
test again? 2.6.13-recent has it as a config option, otherwise edit
include/asm/param.h appropriately.


-- 
Jens Axboe <axboe@suse.de>

Re: [git patches] IDE update

[Ondrej Zary]

Jens Axboe wrote:
> On Tue, 2005-07-05 at 14:35 +0200, Ondrej Zary wrote:
> 
>>>>>>2.4.26
>>>>>>root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
>>>>>>count=1048576
>>>>>>1048576+0 records in
>>>>>>1048576+0 records out
>>>>>>
>>>>>>real    0m23.858s
>>>>>>user    0m1.750s
>>>>>>sys     0m15.180s
>>>>>
>>>>>
>>>>>Perhaps some read-ahead bug. What happens if you use bs=128k for
>>>>>instance?
>>>>>
>>>>
>>>>Nothing - it's still the same.
>>>>
>>>>root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=128k 
>>>>count=4096
>>>>4096+0 records in
>>>>4096+0 records out
>>>>
>>>>real    0m32.832s
>>>>user    0m0.040s
>>>>sys     0m15.670s
>>>
>>>
>>>Can you post full dmesg of 2.4 and 2.6 kernel boot? What does hdparm
>>>-I/-i say for both kernels?
>>>
>>
>>The 2.4.26 kernel is the one from Slackware 10.0 bootable install CD.
>>dmesg outputs attached, hdparm -i and hdparm -I shows the same in both
>>kernels (compared using diff) - attached too.
> 
> 
> Ok, looks alright for both. Your machine is quite slow, perhaps that is
> showing the slower performance. Can you try and make HZ 100 in 2.6 and
> test again? 2.6.13-recent has it as a config option, otherwise edit
> include/asm/param.h appropriately.
> 

I forgot to write that my 2.6.12 kernel is already compiled with HZ 100 
(it makes the system more responsive).
I've just tried 2.6.8.1 with HZ 1000 and there is no difference in HDD 
performance comparing to 2.6.12.

-- 
Ondrej Zary

Re: [git patches] IDE update

[Jens Axboe]

On Tue, 2005-07-05 at 15:02 +0200, Ondrej Zary wrote:
> > Ok, looks alright for both. Your machine is quite slow, perhaps that is
> > showing the slower performance. Can you try and make HZ 100 in 2.6 and
> > test again? 2.6.13-recent has it as a config option, otherwise edit
> > include/asm/param.h appropriately.
> > 
> 
> I forgot to write that my 2.6.12 kernel is already compiled with HZ 100 
> (it makes the system more responsive).
> I've just tried 2.6.8.1 with HZ 1000 and there is no difference in HDD 
> performance comparing to 2.6.12.

OK, interesting. You could try and boot with profile=2 and do

# readprofile -r
# dd if=/dev/hda of=/dev/null bs=128k 
# readprofile > prof_output

for each kernel and post it here, so we can see if anything sticks out.

-- 
Jens Axboe <axboe@suse.de>

Re: [git patches] IDE update

[Ondrej Zary]

[-- Attachment #1: Type: text/plain, Size: 966 bytes --]

Jens Axboe wrote:
> On Tue, 2005-07-05 at 15:02 +0200, Ondrej Zary wrote:
> 
>>>Ok, looks alright for both. Your machine is quite slow, perhaps that is
>>>showing the slower performance. Can you try and make HZ 100 in 2.6 and
>>>test again? 2.6.13-recent has it as a config option, otherwise edit
>>>include/asm/param.h appropriately.
>>>
>>
>>I forgot to write that my 2.6.12 kernel is already compiled with HZ 100 
>>(it makes the system more responsive).
>>I've just tried 2.6.8.1 with HZ 1000 and there is no difference in HDD 
>>performance comparing to 2.6.12.
> 
> 
> OK, interesting. You could try and boot with profile=2 and do
> 
> # readprofile -r
> # dd if=/dev/hda of=/dev/null bs=128k 
> # readprofile > prof_output
> 
> for each kernel and post it here, so we can see if anything sticks out.
> 
Here are the profiles (used dd with count=4096) from 2.4.26 and 2.6.12 
(nothing from 2.6.8.1 because I don't have the .map file anymore).

-- 
Ondrej Zary

[-- Attachment #2: profile2426.txt --]
[-- Type: text/plain, Size: 4121 bytes --]

   448 default_idle                               5.6000
     4 __switch_to                                0.0192
     1 ret_from_sys_call                          0.0588
     3 handle_IRQ_event                           0.0268
     6 schedule                                   0.0072
     8 __wake_up                                  0.0833
     2 __constant_memcpy                          0.0078
     4 add_page_to_hash_queue                     0.0625
     2 __remove_inode_page                        0.0156
     6 add_to_page_cache_unique                   0.0375
     7 page_cache_read                            0.0398
     2 unlock_page                                0.0179
     7 generic_file_readahead                     0.0168
    11 do_generic_file_read                       0.0101
  1366 file_read_actor                            8.5375
     2 generic_file_read                          0.0048
     1 kmem_slab_destroy                          0.0042
     3 kmem_cache_grow                            0.0057
     2 kmem_cache_alloc                           0.0625
    28 kmem_cache_free                            0.8750
     2 kmem_cache_reap                            0.0042
    12 __kmem_cache_alloc                         0.0536
     4 lru_cache_add                              0.0357
     1 __lru_cache_del                            0.0078
     3 delta_nr_inactive_pages                    0.0312
     5 delta_nr_cache_pages                       0.0521
    17 shrink_cache                               0.0180
     1 refill_inactive                            0.0031
    16 __free_pages_ok                            0.0200
    20 rmqueue                                    0.0284
     6 __alloc_pages                              0.0091
     1 __free_pages                               0.0208
     3 sys_read                                   0.0117
     1 sys_write                                  0.0039
     5 __remove_from_lru_list                     0.0391
     3 __remove_from_queues                       0.0625
     7 __put_unused_buffer_head                   0.0729
     3 get_unused_buffer_head                     0.0234
    24 set_bh_page                                0.2143
    32 create_buffers                             0.1429
     4 try_to_release_page                        0.0500
     4 create_empty_buffers                       0.0417
    24 block_read_full_page                       0.0375
    27 try_to_free_buffers                        0.1055
    10 max_block                                  0.0694
     9 blkdev_get_block                           0.1406
     2 blkdev_direct_IO                           0.0417
     1 blkdev_readpage                            0.0312
     2 init_buffer_head                           0.0312
    25 __constant_c_and_count_memset              0.1736
     2 write_profile                              0.0417
   114 __make_request                             0.0642
    27 generic_make_request                       0.0844
    25 submit_bh                                  0.0977
     5 ide_inb                                    0.3125
     7 ide_outb                                   0.4375
     2 ide_outl                                   0.1250
     1 ide_execute_command                        0.0078
     2 SELECT_DRIVE                               0.0312
     4 ide_start_request                          0.0083
     2 ide_do_request                             0.0050
     2 ide_get_queue                              0.0312
     4 ide_intr                                   0.0139
     6 ide_dma_intr                               0.0312
    30 ide_build_sglist                           0.0481
     5 ide_build_dmatable                         0.0120
     1 __ide_dma_read                             0.0042
     1 __ide_dma_count                            0.0312
     3 __constant_c_and_count_memset              0.0208
    67 idedisk_end_request                        0.3490
     2 __generic_copy_to_user                     0.0312
     0 *unknown*
  2499 total                                      0.0013

[-- Attachment #3: profile2612.txt --]
[-- Type: text/plain, Size: 5090 bytes --]

     1 cpu_idle                                   0.0104
     1 system_call                                0.0200
     1 __wake_up                                  0.0125
     1 copy_mm                                    0.0011
     1 profile_hit                                0.0156
     2 write_profile                              0.0312
     1 current_fs_time                            0.0104
     1 timespec_trunc                             0.0156
     1 __wake_up_bit                              0.0208
     5 handle_IRQ_event                           0.0521
    12 add_to_page_cache                          0.0833
     1 page_waitqueue                             0.0156
     2 __lock_page                                0.0125
    16 find_get_page                              0.2500
     7 do_generic_mapping_read                    0.0049
     8 file_read_actor                            0.0312
     2 __generic_file_aio_read                    0.0038
     1 generic_file_read                          0.0052
     9 mempool_alloc                              0.0331
     2 mempool_alloc_slab                         0.1250
     3 bad_range                                  0.0375
    21 free_hot_cold_page                         0.0772
    22 buffered_rmqueue                           0.0458
     5 zone_watermark_ok                          0.0284
     5 __alloc_pages                              0.0053
     1 __read_page_state                          0.0625
     6 __mod_page_state                           0.3750
     1 get_dirty_limits                           0.0048
     4 test_clear_page_dirty                      0.0179
     2 read_pages                                 0.0074
    11 __do_page_cache_readahead                  0.0312
     2 blockable_page_cache_readahead             0.0125
     1 page_cache_readahead                       0.0030
    20 kmem_cache_alloc                           0.4167
     8 kmem_cache_free                            0.1667
     1 release_pages                              0.0025
     1 __pagevec_lru_add                          0.0039
     2 shrink_slab                                0.0054
     1 pageout                                    0.0037
    43 shrink_list                                0.0401
     6 shrink_cache                               0.0080
     1 refill_inactive_zone                       0.0009
     2 balance_pgdat                              0.0024
     2 blk_queue_bounce                           0.0312
     1 unmap_vmas                                 0.0018
     3 page_referenced                            0.0234
     1 rw_verify_area                             0.0078
     1 vfs_read                                   0.0045
     1 vfs_write                                  0.0045
     1 __clear_page_buffers                       0.0156
     5 alloc_page_buffers                         0.0347
     2 try_to_release_page                        0.0312
    12 create_empty_buffers                       0.0833
    14 block_read_full_page                       0.0219
     4 submit_bh                                  0.0147
     7 drop_buffers                               0.0486
     7 try_to_free_buffers                        0.0486
     1 block_sync_page                            0.0156
     2 recalc_bh_state                            0.0312
     2 alloc_buffer_head                          0.0250
     1 free_buffer_head                           0.0125
     8 bio_alloc_bioset                           0.0179
     2 bio_put                                    0.0417
     3 max_block                                  0.0268
     2 blkdev_get_block                           0.0312
     2 blkdev_readpage                            0.1250
     2 update_atime                               0.0114
     1 __mark_inode_dirty                         0.0024
     2 mb_cache_shrink_fn                         0.0043
     1 radix_tree_preload                         0.0063
   998 __copy_to_user_ll                         15.5938
  1216 acpi_processor_idle                        2.0033
     9 blk_rq_map_sg                              0.0256
     3 get_request                                0.0043
    72 __make_request                             0.0616
     8 generic_make_request                       0.0179
     3 submit_bio                                 0.0170
    61 ide_end_request                            0.4236
     1 start_request                              0.0020
     5 ide_do_request                             0.0060
     2 ide_intr                                   0.0052
     2 ide_inb                                    0.1250
     5 ide_outb                                   0.3125
     1 ide_execute_command                        0.0063
     3 ide_build_sglist                           0.0208
     2 ide_build_dmatable                         0.0066
     1 ide_do_rw_disk                             0.0089
     8 schedule                                   0.0053
     0 *unknown*
  2734 total                                      0.0013

Re: [git patches] IDE update

[Jens Axboe]

[-- Attachment #1: Type: text/plain, Size: 1261 bytes --]

On Tue, Jul 05 2005, Ondrej Zary wrote:
> Jens Axboe wrote:
> >On Tue, 2005-07-05 at 15:02 +0200, Ondrej Zary wrote:
> >
> >>>Ok, looks alright for both. Your machine is quite slow, perhaps that is
> >>>showing the slower performance. Can you try and make HZ 100 in 2.6 and
> >>>test again? 2.6.13-recent has it as a config option, otherwise edit
> >>>include/asm/param.h appropriately.
> >>>
> >>
> >>I forgot to write that my 2.6.12 kernel is already compiled with HZ 100 
> >>(it makes the system more responsive).
> >>I've just tried 2.6.8.1 with HZ 1000 and there is no difference in HDD 
> >>performance comparing to 2.6.12.
> >
> >
> >OK, interesting. You could try and boot with profile=2 and do
> >
> ># readprofile -r
> ># dd if=/dev/hda of=/dev/null bs=128k 
> ># readprofile > prof_output
> >
> >for each kernel and post it here, so we can see if anything sticks out.
> >
> Here are the profiles (used dd with count=4096) from 2.4.26 and 2.6.12 
> (nothing from 2.6.8.1 because I don't have the .map file anymore).

Looks interesting, 2.6 spends oodles of times copying to user space.
Lets check if raw reads perform ok, please try and time this app in 2.4
and 2.6 as well.

# gcc -Wall -O2 -o oread oread.c
# time ./oread /dev/hda

-- 
Jens Axboe


[-- Attachment #2: oread.c --]
[-- Type: text/plain, Size: 644 bytes --]

#include <stdio.h>
#include <unistd.h>
#define __USE_GNU
#include <fcntl.h>
#include <stdlib.h>

#define BS		(131072)
#define BLOCKS		(4096)
#define ALIGN(buf)	(char *) (((unsigned long) (buf) + 4095) & ~(4095))

int main(int argc, char *argv[])
{
	char *buffer;
	int fd, i;

	if (argc < 2) {
		printf("%s: <device>\n", argv[0]);
		return 1;
	}

	fd = open(argv[1], O_RDONLY | O_DIRECT);
	if (fd == -1) {
		perror("open");
		return 2;
	}

	buffer = ALIGN(malloc(BS + 4095));

	for (i = 0; i < BLOCKS; i++) {
		int ret = read(fd, buffer, BS);

		if (!ret)
			break;
		else if (ret < 0) {
			perror("read infile");
			break;
		}
	}

	return 0;
}

Re: [git patches] IDE update

[Ondrej Zary]

[-- Attachment #1: Type: text/plain, Size: 1664 bytes --]

Jens Axboe wrote:
> On Tue, Jul 05 2005, Ondrej Zary wrote:
> 
>>Jens Axboe wrote:
>>
>>>On Tue, 2005-07-05 at 15:02 +0200, Ondrej Zary wrote:
>>>
>>>
>>>>>Ok, looks alright for both. Your machine is quite slow, perhaps that is
>>>>>showing the slower performance. Can you try and make HZ 100 in 2.6 and
>>>>>test again? 2.6.13-recent has it as a config option, otherwise edit
>>>>>include/asm/param.h appropriately.
>>>>>
>>>>
>>>>I forgot to write that my 2.6.12 kernel is already compiled with HZ 100 
>>>>(it makes the system more responsive).
>>>>I've just tried 2.6.8.1 with HZ 1000 and there is no difference in HDD 
>>>>performance comparing to 2.6.12.
>>>
>>>
>>>OK, interesting. You could try and boot with profile=2 and do
>>>
>>># readprofile -r
>>># dd if=/dev/hda of=/dev/null bs=128k 
>>># readprofile > prof_output
>>>
>>>for each kernel and post it here, so we can see if anything sticks out.
>>>
>>
>>Here are the profiles (used dd with count=4096) from 2.4.26 and 2.6.12 
>>(nothing from 2.6.8.1 because I don't have the .map file anymore).
> 
> 
> Looks interesting, 2.6 spends oodles of times copying to user space.
> Lets check if raw reads perform ok, please try and time this app in 2.4
> and 2.6 as well.
> 
> # gcc -Wall -O2 -o oread oread.c
> # time ./oread /dev/hda
> 
oread is faster than dd, but still not as fast as 2.4. In 2.6.12, HDD 
led is blinking, in 2.4 it's solid on during the read.

2.6.12:
root@pentium:/home/rainbow# time ./oread /dev/hda

real    0m25.082s
user    0m0.000s
sys     0m0.680s

2.4.26:
root@pentium:/home/rainbow# time ./oread /dev/hda

real    0m23.513s
user    0m0.000s
sys     0m2.360s

-- 
Ondrej Zary

[-- Attachment #2: profile-oread2426.txt --]
[-- Type: text/plain, Size: 2354 bytes --]

  2016 default_idle                              25.2000
     1 system_call                                0.0156
     2 handle_IRQ_event                           0.0179
     1 schedule                                   0.0012
     1 __run_task_queue                           0.0104
     4 follow_page                                0.0312
     3 get_user_pages                             0.0063
     4 mark_dirty_kiobuf                          0.0357
     1 handle_mm_fault                            0.0048
     2 generic_file_direct_IO                     0.0026
     1 lru_cache_add                              0.0089
     2 init_buffer                                0.0625
    12 set_bh_page                                0.1071
     3 create_buffers                             0.0134
    30 generic_direct_IO                          0.0457
    17 brw_kiovec                                 0.0186
    11 max_block                                  0.0764
     9 blkdev_get_block                           0.1406
     2 blkdev_direct_IO                           0.0417
     1 write_profile                              0.0208
     2 generic_unplug_device                      0.0312
    93 __make_request                             0.0524
    25 generic_make_request                       0.0781
    20 submit_bh                                  0.0781
     5 ide_inb                                    0.3125
    12 ide_outb                                   0.7500
     1 ide_outl                                   0.0625
     1 ide_wait_stat                              0.0030
     4 ide_execute_command                        0.0312
     2 ide_do_request                             0.0050
     4 ide_get_queue                              0.0625
     2 ide_intr                                   0.0069
     2 ide_dma_intr                               0.0104
    10 ide_build_sglist                           0.0160
     1 ide_build_dmatable                         0.0024
     1 __ide_dma_read                             0.0042
     1 __constant_c_and_count_memset              0.0069
     1 __ide_do_rw_disk                           0.0007
    42 idedisk_end_request                        0.2188
     4 __rdtsc_delay                              0.1250
     0 *unknown*
  2356 total                                      0.0013

[-- Attachment #3: profile-oread2612.txt --]
[-- Type: text/plain, Size: 2183 bytes --]

     1 sched_clock                                0.0057
     3 cond_resched_lock                          0.0312
     2 write_profile                              0.0312
     1 __wake_up_bit                              0.0208
     2 __generic_file_aio_read                    0.0038
     1 generic_file_read                          0.0052
     1 mempool_alloc                              0.0037
     1 set_page_dirty                             0.0125
     3 set_page_dirty_lock                        0.0625
     4 __follow_page                              0.0227
     7 get_user_pages                             0.0072
     2 do_wp_page                                 0.0025
     8 __bio_add_page                             0.0227
     5 bio_add_page                               0.1562
     1 bio_set_map_data                           0.0208
     1 update_atime                               0.0057
     1 dio_get_page                               0.0156
     1 dio_bio_submit                             0.0069
     2 dio_bio_complete                           0.0096
     5 submit_page_section                        0.0164
     1 dio_zero_block                             0.0078
    13 do_direct_IO                               0.0150
     2 direct_io_worker                           0.0014
     2 __copy_to_user_ll                          0.0312
  2428 acpi_processor_idle                        4.0000
     4 blk_rq_map_sg                              0.0114
    10 __make_request                             0.0086
     1 generic_make_request                       0.0022
     1 as_set_request                             0.0089
     4 ide_end_request                            0.0278
     6 ide_do_request                             0.0072
     1 ide_intr                                   0.0026
     5 ide_outb                                   0.3125
     1 ide_execute_command                        0.0063
     2 ide_build_sglist                           0.0139
     5 schedule                                   0.0033
     1 io_schedule                                0.0312
     0 *unknown*
  2539 total                                      0.0012

Re: [git patches] IDE update

[Jens Axboe]

On Tue, Jul 05 2005, Ondrej Zary wrote:
> Jens Axboe wrote:
> >On Tue, Jul 05 2005, Ondrej Zary wrote:
> >
> >>Jens Axboe wrote:
> >>
> >>>On Tue, 2005-07-05 at 15:02 +0200, Ondrej Zary wrote:
> >>>
> >>>
> >>>>>Ok, looks alright for both. Your machine is quite slow, perhaps that is
> >>>>>showing the slower performance. Can you try and make HZ 100 in 2.6 and
> >>>>>test again? 2.6.13-recent has it as a config option, otherwise edit
> >>>>>include/asm/param.h appropriately.
> >>>>>
> >>>>
> >>>>I forgot to write that my 2.6.12 kernel is already compiled with HZ 100 
> >>>>(it makes the system more responsive).
> >>>>I've just tried 2.6.8.1 with HZ 1000 and there is no difference in HDD 
> >>>>performance comparing to 2.6.12.
> >>>
> >>>
> >>>OK, interesting. You could try and boot with profile=2 and do
> >>>
> >>># readprofile -r
> >>># dd if=/dev/hda of=/dev/null bs=128k 
> >>># readprofile > prof_output
> >>>
> >>>for each kernel and post it here, so we can see if anything sticks out.
> >>>
> >>
> >>Here are the profiles (used dd with count=4096) from 2.4.26 and 2.6.12 
> >>(nothing from 2.6.8.1 because I don't have the .map file anymore).
> >
> >
> >Looks interesting, 2.6 spends oodles of times copying to user space.
> >Lets check if raw reads perform ok, please try and time this app in 2.4
> >and 2.6 as well.
> >
> ># gcc -Wall -O2 -o oread oread.c
> ># time ./oread /dev/hda
> >
> oread is faster than dd, but still not as fast as 2.4. In 2.6.12, HDD 
> led is blinking, in 2.4 it's solid on during the read.
> 
> 2.6.12:
> root@pentium:/home/rainbow# time ./oread /dev/hda
> 
> real    0m25.082s
> user    0m0.000s
> sys     0m0.680s
> 
> 2.4.26:
> root@pentium:/home/rainbow# time ./oread /dev/hda
> 
> real    0m23.513s
> user    0m0.000s
> sys     0m2.360s

Hmm, still not as fast, not so good. 2.6 shows more idle time than 2.4,
about 20% more. I seem to remember Ken Chen saying that 2.6 direct io
was still a little slower than 2.4, your really slow hardware could be
showing this to a much greater effect.

I'll try and play with this tomorrow!

-- 
Jens Axboe

Re: [git patches] IDE update

[Jens Axboe]

On Tue, Jul 05 2005, Ondrej Zary wrote:
> oread is faster than dd, but still not as fast as 2.4. In 2.6.12, HDD 
> led is blinking, in 2.4 it's solid on during the read.

Oh, and please do test 2.6 by first setting the deadline scheduler for
hda. I can see you are using the 'as' scheduler right now.

# echo deadline > /sys/block/hda/queue/scheduler

Thanks!

-- 
Jens Axboe

Re: [git patches] IDE update

[Ondrej Zary]

Jens Axboe wrote:
> On Tue, Jul 05 2005, Ondrej Zary wrote:
> 
>>oread is faster than dd, but still not as fast as 2.4. In 2.6.12, HDD 
>>led is blinking, in 2.4 it's solid on during the read.
> 
> 
> Oh, and please do test 2.6 by first setting the deadline scheduler for
> hda. I can see you are using the 'as' scheduler right now.
> 
> # echo deadline > /sys/block/hda/queue/scheduler
> 

No change, still >25 seconds.

-- 
Ondrej Zary

Re: [git patches] IDE update

[Linus Torvalds]

On Tue, 5 Jul 2005, Jens Axboe wrote:
> 
> Looks interesting, 2.6 spends oodles of times copying to user space.
> Lets check if raw reads perform ok, please try and time this app in 2.4
> and 2.6 as well.

I think it's just that 2.4.x used to allow longer command queues. I think
MAX_NR_REQUESTS is 1024 in 2.4.x, and just 128 in 2.6.x or something like
that.

Also, the congestion thresholds are questionable: we consider a queue
congested if it is within 12% of full, but then we consider it uncongested
whenever it falls to within 18% of full, which I bet means that for some
streaming loads we have just a 6% "window" that we keep adding new
requests to (we wait when we're almost full, but then we start adding
requests again when we're _still_ almost full). Jens, we talked about this
long ago, but I don't think we ever did any timings.

Making things worse, things like this are only visible on stupid hardware
that has long latencies to get started (many SCSI controllers used to have
horrid latencies), so you'll never even see any difference on a lot of 
hardware.

It's probably worth testing with a bigger request limit. I forget what the 
/proc interfaces are (and am too lazy to look it up), Jens can tell us ;)

		Linus

Re: [git patches] IDE update

[Jens Axboe]

On Tue, Jul 05 2005, Linus Torvalds wrote:
> 
> 
> On Tue, 5 Jul 2005, Jens Axboe wrote:
> > 
> > Looks interesting, 2.6 spends oodles of times copying to user space.
> > Lets check if raw reads perform ok, please try and time this app in 2.4
> > and 2.6 as well.
> 
> I think it's just that 2.4.x used to allow longer command queues. I think
> MAX_NR_REQUESTS is 1024 in 2.4.x, and just 128 in 2.6.x or something like
> that.

But for this case, you only have one command in flight. hdparm is highly
synchronous, my oread case is as well.

> Also, the congestion thresholds are questionable: we consider a queue
> congested if it is within 12% of full, but then we consider it uncongested
> whenever it falls to within 18% of full, which I bet means that for some
> streaming loads we have just a 6% "window" that we keep adding new
> requests to (we wait when we're almost full, but then we start adding
> requests again when we're _still_ almost full). Jens, we talked about this
> long ago, but I don't think we ever did any timings.

In theory, the ioc batching should handle that case. But as you can see
from recent commits, I'm not very happy with how this currently works.
It should not impact this testing, though.

> Making things worse, things like this are only visible on stupid hardware
> that has long latencies to get started (many SCSI controllers used to have
> horrid latencies), so you'll never even see any difference on a lot of 
> hardware.

IDE still has much lower overhead per command than your average SCSI
hardware. SATA with FIS even improves on this, definitely a good thing!

> It's probably worth testing with a bigger request limit. I forget what the 
> /proc interfaces are (and am too lazy to look it up), Jens can tell us ;)

It's /sys/block/<device>/queue/nr_requests now, can be changed at will.

-- 
Jens Axboe

Re: [git patches] IDE update

[Ondrej Zary]

Jens Axboe wrote:
> On Tue, Jul 05 2005, Linus Torvalds wrote:
> 
>>
>>On Tue, 5 Jul 2005, Jens Axboe wrote:
>>
>>>Looks interesting, 2.6 spends oodles of times copying to user space.
>>>Lets check if raw reads perform ok, please try and time this app in 2.4
>>>and 2.6 as well.
>>
>>I think it's just that 2.4.x used to allow longer command queues. I think
>>MAX_NR_REQUESTS is 1024 in 2.4.x, and just 128 in 2.6.x or something like
>>that.
> 
> 
> But for this case, you only have one command in flight. hdparm is highly
> synchronous, my oread case is as well.
> 
> 
>>Also, the congestion thresholds are questionable: we consider a queue
>>congested if it is within 12% of full, but then we consider it uncongested
>>whenever it falls to within 18% of full, which I bet means that for some
>>streaming loads we have just a 6% "window" that we keep adding new
>>requests to (we wait when we're almost full, but then we start adding
>>requests again when we're _still_ almost full). Jens, we talked about this
>>long ago, but I don't think we ever did any timings.
> 
> 
> In theory, the ioc batching should handle that case. But as you can see
> from recent commits, I'm not very happy with how this currently works.
> It should not impact this testing, though.
> 
> 
>>Making things worse, things like this are only visible on stupid hardware
>>that has long latencies to get started (many SCSI controllers used to have
>>horrid latencies), so you'll never even see any difference on a lot of 
>>hardware.
> 
> 
> IDE still has much lower overhead per command than your average SCSI
> hardware. SATA with FIS even improves on this, definitely a good thing!
> 
> 
>>It's probably worth testing with a bigger request limit. I forget what the 
>>/proc interfaces are (and am too lazy to look it up), Jens can tell us ;)
> 
> 
> It's /sys/block/<device>/queue/nr_requests now, can be changed at will.
> 
Tested with default 128, 1024 and 4 (minimum) and no change.

-- 
Ondrej Zary

Re: [git patches] IDE update

[Alan Cox]

On Maw, 2005-07-05 at 20:14, Jens Axboe wrote:
> IDE still has much lower overhead per command than your average SCSI
> hardware. SATA with FIS even improves on this, definitely a good thing!

But SCSI overlaps them while in PATA they are dead time. Thats why PATA
is so demanding of large I/O block sizes

Re: [git patches] IDE update

[Grant Coady]

On Tue, 5 Jul 2005 16:21:26 +0200, Jens Axboe <axboe@suse.de> wrote:
># gcc -Wall -O2 -o oread oread.c
># time ./oread /dev/hda

Executive Summary
``````````````````
Comparing 'oread' with hdparm -tT on latest 2.4 vs 2.6 stable on 
various x86 boxen.  Performance drops for 2.6, sometimes:
        2.4.31-hf1  2.6.12.2
peetoo: 26MB/s   -> 20MB/s,  oread similar    120GB + 80GB
silly:  22MB/s   -> 8.5MB/s, oread similar    13GB
tosh:   35MB/s   -> 23MB/s,  oread similar    40GB 2.5"
pooh:   17MB/s   -> 14MB/s,  oread 30 -> 24   40GB
menace: 11.5MB/s -> 13MB/s,  oread similar     6GB 2.5"

--Grant

The details, config, dmesg, etc from linked resources:

Intel SE440BX-2 with pII 400/100/512/2.0 CPU/FSB/L2/Vccp 
512MB SDRAM on 440BX + PIIX4
  http://scatter.mine.nu/test/linux-2.6/peetoo/

peetoo:~$ uname -r
2.4.31-hf1
peetoo:~$ time /home/share/install/oread /dev/hda

real    0m20.065s
user    0m0.010s
sys     0m0.810s
peetoo:~$ time /home/share/install/oread /dev/hdc

real    0m18.484s
user    0m0.000s
sys     0m0.800s
peetoo:~$ hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   444 MB in  2.00 seconds = 222.00 MB/sec
 Timing buffered disk reads:   84 MB in  3.06 seconds =  27.45 MB/sec
peetoo:~$ hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   456 MB in  2.01 seconds = 226.87 MB/sec
 Timing buffered disk reads:   76 MB in  3.00 seconds =  25.33 MB/sec
peetoo:~$ hdparm -tT /dev/hdc

/dev/hdc:
 Timing cached reads:   464 MB in  2.01 seconds = 230.85 MB/sec
 Timing buffered disk reads:   76 MB in  3.00 seconds =  25.33 MB/sec
peetoo:~$ hdparm -tT /dev/hdc

/dev/hdc:
 Timing cached reads:   460 MB in  2.00 seconds = 230.00 MB/sec
 Timing buffered disk reads:   82 MB in  3.00 seconds =  27.33 MB/sec
- - -
peetoo:~$ uname -r
2.6.12.2b
peetoo:~$ time /home/share/install/oread /dev/hda

real    0m21.428s
user    0m0.003s
sys     0m0.436s
peetoo:~$ time /home/share/install/oread /dev/hdc

real    0m17.588s
user    0m0.001s
sys     0m0.455s

peetoo:~$ cat /sys/block/hda/queue/scheduler
noop [deadline]
peetoo:~$ cat /sys/block/hdc/queue/scheduler
noop [deadline]
peetoo:~$ time /home/share/install/oread /dev/hda

real    0m21.417s
user    0m0.005s
sys     0m0.462s
peetoo:~$ time /home/share/install/oread /dev/hda

real    0m18.626s
user    0m0.006s
sys     0m0.440s
peetoo:~$ time /home/share/install/oread /dev/hdc

real    0m17.555s
user    0m0.005s
sys     0m0.422s
peetoo:~$ df
Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/hda3              2586348    563000   2023348  22% /
/dev/hdc3              2586348   1582716   1003632  62% /usr
/dev/hdc6              2586348   1217568   1368780  48% /usr/src
/dev/hda9             20562504  10821500   9741004  53% /home/install
/dev/hdc9             20562504   3634700  16927804  18% /home/public
/dev/hda10            41446344  39676256   1770088  96% /home/archive
deltree:/home/share    2064256   1042952   1021304  51% /home/share

peetoo:~$ hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   448 MB in  2.00 seconds = 223.81 MB/sec
 Timing buffered disk reads:   62 MB in  3.07 seconds =  20.17 MB/sec
peetoo:~$ hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   472 MB in  2.01 seconds = 234.40 MB/sec
 Timing buffered disk reads:   54 MB in  3.01 seconds =  17.97 MB/sec
peetoo:~$ hdparm -tT /dev/hdc

/dev/hdc:
 Timing cached reads:   456 MB in  2.01 seconds = 226.56 MB/sec
 Timing buffered disk reads:   62 MB in  3.08 seconds =  20.11 MB/sec
peetoo:~$ hdparm -tT /dev/hdc

o o o

EPoX EP-61LXA-M: Intel 440LX chipset with pentiumII/266 
on 66MHz FSB (4 x 66) with 128MB SDRAM
  http://scatter.mine.nu/test/linux-2.6/silly/

root@silly:~# uname -r
2.4.31-hf1
root@silly:~# time /home/share/install/oread /dev/hda

real    0m23.657s
user    0m0.000s
sys     0m1.300s
root@silly:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   356 MB in  2.02 seconds = 176.24 MB/sec
 Timing buffered disk reads:   68 MB in  3.04 seconds =  22.37 MB/sec
root@silly:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   344 MB in  2.00 seconds = 172.00 MB/sec
 Timing buffered disk reads:   68 MB in  3.03 seconds =  22.44 MB/sec
- - -
root@silly:~# uname -r
2.6.12.2a
root@silly:~# time /home/share/install/oread /dev/hda

real    0m23.569s
user    0m0.005s
sys     0m0.563s

root@silly:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   336 MB in  2.00 seconds = 167.77 MB/sec
 Timing buffered disk reads:   50 MB in  3.05 seconds =  16.37 MB/sec
root@silly:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   340 MB in  2.01 seconds = 169.01 MB/sec
 Timing buffered disk reads:   28 MB in  3.22 seconds =   8.70 MB/sec
root@silly:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   336 MB in  2.01 seconds = 167.44 MB/sec
 Timing buffered disk reads:   26 MB in  3.05 seconds =   8.52 MB/sec
root@silly:~# echo deadline > /sys/block/hda/queue/scheduler
root@silly:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   336 MB in  2.01 seconds = 166.77 MB/sec
 Timing buffered disk reads:   26 MB in  3.19 seconds =   8.14 MB/sec
root@silly:~#

o o o

Intel Celeron (coppermine pIII) 500MHz with 192MB SDRAM
on Intel 440BX/ZX + PIIX4E (Toshiba laptop)
  http://scatter.mine.nu/test/linux-2.6/tosh/

root@tosh:~# uname -r
2.4.31-hf1
root@tosh:~# time /home/share/install/oread /dev/hda

real    0m18.079s
user    0m0.000s
sys     0m0.680s
root@tosh:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   516 MB in  2.00 seconds = 258.00 MB/sec
 Timing buffered disk reads:   74 MB in  3.02 seconds =  24.50 MB/sec
root@tosh:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   520 MB in  2.01 seconds = 258.71 MB/sec
 Timing buffered disk reads:   84 MB in  3.03 seconds =  27.72 MB/sec
- - -
root@tosh:~# uname -r
2.6.12.2a
root@tosh:~# time /home/share/install/oread /dev/hda

real    0m17.692s
user    0m0.004s
sys     0m0.319s
root@tosh:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   500 MB in  2.00 seconds = 249.54 MB/sec
 Timing buffered disk reads:   70 MB in  3.03 seconds =  23.11 MB/sec
root@tosh:~# echo deadline > /sys/block/hda/queue/scheduler
root@tosh:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   520 MB in  2.01 seconds = 258.75 MB/sec
 Timing buffered disk reads:   70 MB in  3.06 seconds =  22.88 MB/sec

o o o

Gigabyte GA-5AA Ali Aladdin V AGPset (1542/1543C) with AMD K6-2/500
on 100MHz FSB with 192MB SDRAM
  http://scatter.mine.nu/test/linux-2.6/pooh/

root@pooh:~# uname -r
2.4.31-hf1
root@pooh:~# time /home/share/install/oread /dev/hda

real    0m29.786s
user    0m0.000s
sys     0m0.910s
root@pooh:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   248 MB in  2.00 seconds = 124.00 MB/sec
 Timing buffered disk reads:   54 MB in  3.11 seconds =  17.36 MB/sec
- - -
root@pooh:~# uname -r
2.6.12.2a
root@pooh:~# time /home/share/install/oread /dev/hda

real    0m23.566s
user    0m0.004s
sys     0m0.370s
root@pooh:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   236 MB in  2.02 seconds = 117.02 MB/sec
 Timing buffered disk reads:   44 MB in  3.10 seconds =  14.20 MB/sec

o o o

Gigabyte GA-586TX3: Intel 430TX chipset with AMD K6-2/400
on 66MHz FSB (6 x 66) with 64MB SDRAM
  http://scatter.mine.nu/test/boxen/menace/

root@menace:~# uname -r
2.4.31-hf1
root@menace:~# time /home/share/install/oread /dev/hda

real    0m39.490s
user    0m0.010s
sys     0m1.090s
root@menace:~# time /home/share/install/oread /dev/hda

real    0m39.329s
user    0m0.010s
sys     0m1.090s
root@menace:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   176 MB in  2.03 seconds =  86.70 MB/sec
 Timing buffered disk reads:   36 MB in  3.14 seconds =  11.46 MB/sec
root@menace:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   172 MB in  2.02 seconds =  85.15 MB/sec
 Timing buffered disk reads:   36 MB in  3.13 seconds =  11.50 MB/sec

- - -
root@menace:~# uname -r
2.6.12.2a
root@menace:~# time /home/share/install/oread /dev/hda

real    0m38.861s
user    0m0.004s
sys     0m0.515s
root@menace:~# time /home/share/install/oread /dev/hda

real    0m39.391s
user    0m0.005s
sys     0m0.522s
root@menace:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   172 MB in  2.01 seconds =  85.42 MB/sec
 Timing buffered disk reads:   40 MB in  3.03 seconds =  13.20 MB/sec
root@menace:~# hdparm -tT /dev/hda

/dev/hda:
 Timing cached reads:   168 MB in  2.04 seconds =  82.16 MB/sec
 Timing buffered disk reads:   40 MB in  3.03 seconds =  13.21 MB/sec

Re: [git patches] IDE update

[Linus Torvalds]

On Wed, 6 Jul 2005, Grant Coady wrote:
> 
> Executive Summary

Btw, can you try this same thing (or at least a subset) with a large file
on a filesystem? Does that show the same pattern, or is it always just the 
raw device?

		Linus

RE: [git patches] IDE update

[Al Boldi]

Linus Torvalds wrote: {
On Wed, 6 Jul 2005, Grant Coady wrote:
> 
> Executive Summary

Btw, can you try this same thing (or at least a subset) with a large file on
a filesystem? Does that show the same pattern, or is it always just the raw
device?
}

Linus,
Cat /dev/hda > /dev/null and cat /tmp/tst.dsk > /dev/null show the same
symptoms.
The problem shows most when the cpu is slow and the hd is fast.
When the cpu is fast and the hd is slow the cpu will make up for lost cycles
and the problem will not show!

Re: [git patches] IDE update

[Grant Coady]

On Tue, 5 Jul 2005 17:51:50 -0700 (PDT), Linus Torvalds <torvalds@osdl.org> wrote:
>
>Btw, can you try this same thing (or at least a subset) with a large file
>on a filesystem? Does that show the same pattern, or is it always just the 
>raw device?
>
Sure, take a while longer to vary by block size.  One effect seems 
to be wrong is interaction between /dev/hda and /dev/hdc in 'peetoo', 
the IDE channels not independent?

write:	time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
read:	time dd of=/dev/null bs=1M if=/zeroes

summary		2.4.31-hf1	2.6.12.2
boxen \ time ->	 w 	 r	 w	 r
---------------	----	----	----	----
menace		58.5	50	57	47.5
pooh		24	24	22.5	27
peetoo		33	20	26.5	22
(simultaneuous	57	37.5	52	38.5)
silly		54	24	49	25
tosh		30	19.5	27	19.5

filesystem: reiserfs 3.6, distro: slackware-10.1 + updates
hardware config, etc: http://scatter.mine.nu/test/

--Grant

the long story:
	
root@menace:~# uname -r
2.4.31-hf1
root@menace:~# df
Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/hda3              1991992   1074516    917476  54% /
deltree:/home/share    2064256   1042968   1021288  51% /home/share

root@menace:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m57.830s
user    0m0.050s
sys     0m20.940s
root@menace:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m59.041s
user    0m0.030s
sys     0m21.780s
root@menace:~# time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m49.963s
user    0m0.000s
sys     0m15.510s
- - -
root@menace:~# uname -r
2.6.12.2a
root@menace:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m57.199s
user    0m0.022s
sys     0m15.040s
root@menace:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m56.825s
user    0m0.024s
sys     0m14.893s
root@menace:~# time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m47.560s
user    0m0.017s
sys     0m15.533s
root@menace:~# time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m47.842s
user    0m0.012s
sys     0m15.647s

o o o
root@pooh:~# df
Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/hda3              3084380   2018240   1066140  66% /
/dev/hda6              2056220   1049544   1006676  52% /usr/src
/dev/hda7               256996     34260    222736  14% /usr/local
/dev/hda8               256996     33896    223100  14% /home
/dev/hda14            20562536     32840  20529696   1% /home/pooh
deltree:/home/share    2064256   1042968   1021288  51% /home/share

root@pooh:~# uname -r
2.4.31-hf1
root@pooh:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m23.912s
user    0m0.010s
sys     0m19.820s
root@pooh:~# time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m24.302s
user    0m0.020s
sys     0m16.760s
- - -
root@pooh:~# uname -r
2.6.12.2a
root@pooh:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m22.449s
user    0m0.017s
sys     0m13.576s
root@pooh:~# time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m26.780s
user    0m0.010s
sys     0m13.398s

o o o

peetoo:~$ df
Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/hda3              2586348   1075652   1510696  42% /
/dev/hdc3              2586348   2044228    542120  80% /usr
/dev/hdc6              2586348   1217568   1368780  48% /usr/src
/dev/hda9             20562504  10821500   9741004  53% /home/install
/dev/hdc9             20562504   4329320  16233184  22% /home/public
/dev/hda10            41446344  39676256   1770088  96% /home/archive
deltree:/home/share    2064256   1042968   1021288  51% /home/share

peetoo:~$ uname -r
2.4.31-hf1
peetoo:~$ time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m33.322s
user    0m0.000s
sys     0m13.650s
peetoo:~$ time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m32.983s
user    0m0.010s
sys     0m13.740s
peetoo:~$ time $(dd if=/dev/zero bs=1M count=500 of=/usr/zeroes; sync)
500+0 records in
500+0 records out

real    0m30.775s
user    0m0.000s
sys     0m13.600s
peetoo:~$ time $(dd if=/dev/zero bs=1M count=500 of=/usr/zeroes; sync)
500+0 records in
500+0 records out

real    0m33.077s
user    0m0.010s
sys     0m13.740s
peetoo:~$ time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m18.877s
user    0m0.000s
sys     0m5.600s
peetoo:~$ time dd of=/dev/null bs=1M if=/usr/zeroes
500+0 records in
500+0 records out

real    0m21.413s
user    0m0.000s
sys     0m5.360s
peetoo:~$ time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m18.940s
user    0m0.000s
sys     0m5.390s
peetoo:~$ time dd of=/dev/null bs=1M if=/usr/zeroes
500+0 records in
500+0 records out

real    0m22.120s
user    0m0.000s
sys     0m5.520s
peetoo:~$ time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m36.991s
user    0m0.000s
sys     0m5.810s
peetoo:~$ time $(dd if=/dev/zero bs=1M count=500 of=/usr/zeroes; sync)
500+0 records in
500+0 records out

real    0m57.718s
user    0m0.000s
sys     0m13.580s

	simultaneous:
	peetoo:~$ time dd of=/dev/null bs=1M if=/usr/zeroes
	500+0 records in
	500+0 records out
	
	real    0m38.057s
	user    0m0.010s
	sys     0m5.790s
	peetoo:~$ time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
	500+0 records in
	500+0 records out
	
	real    0m57.164s
	user    0m0.020s
	sys     0m13.660s
- - -
peetoo:~$ uname -r
2.6.12.2b
peetoo:~$ time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m26.779s
user    0m0.017s
sys     0m5.634s
peetoo:~$ time $(dd if=/dev/zero bs=1M count=500 of=/usr/zeroes; sync)
500+0 records in
500+0 records out

real    0m26.112s
user    0m0.017s
sys     0m5.358s
peetoo:~$ time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m21.630s
user    0m0.005s
sys     0m5.405s
peetoo:~$ time dd of=/dev/null bs=1M if=/usr/zeroes
500+0 records in
500+0 records out

real    0m22.489s
user    0m0.013s
sys     0m5.378s

simultaneous with other drive:

peetoo:~$ time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m38.149s
user    0m0.007s
sys     0m5.559s
peetoo:~$ time $(dd if=/dev/zero bs=1M count=500 of=/usr/zeroes; sync)
500+0 records in
500+0 records out

real    0m52.272s
user    0m0.012s
sys     0m5.461s
	- - -
	second terminal:
	peetoo:~$ time dd of=/dev/null bs=1M if=/usr/zeroes
	500+0 records in
	500+0 records out
	
	real    0m38.998s
	user    0m0.006s
	sys     0m5.517s
	peetoo:~$ time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
	500+0 records in
	500+0 records out
	
	real    0m51.610s
	user    0m0.018s
	sys     0m5.470s
o o o

root@silly:~# uname -r
2.4.31-hf1
root@silly:~# df
Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/hda3              3084380    755932   2328448  25% /
/dev/hda5              3084348   1168428   1915920  38% /usr/src
/dev/hda6               256996     39768    217228  16% /usr/local
/dev/hda7               514028     32864    481164   7% /home
deltree:/home/share    2064256   1042968   1021288  51% /home/share
root@silly:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m58.657s
user    0m0.020s
sys     0m16.810s
root@silly:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m50.276s
user    0m0.040s
sys     0m17.240s
root@silly:~# time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m23.814s
user    0m0.010s
sys     0m8.470s
root@silly:~# time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m23.834s
user    0m0.020s
sys     0m8.500s
- - -
root@silly:~# uname -r
2.6.12.2a
root@silly:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m49.564s
user    0m0.021s
sys     0m7.556s
root@silly:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m48.234s
user    0m0.016s
sys     0m7.466s
root@silly:~# time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m24.900s
user    0m0.009s
sys     0m8.430s
root@silly:~# time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m25.205s
user    0m0.015s
sys     0m8.394s

o o o

root@tosh:~# uname -r
2.4.31-hf1
root@tosh:~# df
Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/hda3              4112508   2997808   1114700  73% /
/dev/hda6               124427       996    117007   1% /usr/local
/dev/hda7               124427        99    117904   1% /home
deltree:/home/share    2064256   1042968   1021288  51% /home/share
root@tosh:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m33.789s
user    0m0.040s
sys     0m9.430s
root@tosh:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m27.702s
user    0m0.000s
sys     0m9.940s
root@tosh:~# time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m19.878s
user    0m0.000s
sys     0m4.510s
root@tosh:~# time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m19.288s
user    0m0.000s
sys     0m4.580s
- - -
root@tosh:~# uname -r
2.6.12.2a
root@tosh:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m27.120s
user    0m0.010s
sys     0m4.937s
root@tosh:~# time $(dd if=/dev/zero bs=1M count=500 of=/zeroes; sync)
500+0 records in
500+0 records out

real    0m27.015s
user    0m0.010s
sys     0m4.844s
root@tosh:~# time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m19.301s
user    0m0.006s
sys     0m4.558s
root@tosh:~# time dd of=/dev/null bs=1M if=/zeroes
500+0 records in
500+0 records out

real    0m19.513s
user    0m0.009s
sys     0m4.574s

o o o
end :)

Re: [git patches] IDE update

[Linus Torvalds]

On Wed, 6 Jul 2005, Grant Coady wrote:
>
> Sure, take a while longer to vary by block size.  One effect seems 
> to be wrong is interaction between /dev/hda and /dev/hdc in 'peetoo', 
> the IDE channels not independent?

Well, looking at your numbers for "silly" and "tosh", which were perhaps
the most extreme examples of slowdown on the /dev/hda thing:

	silly:  22MB/s   -> 8.5MB/s, oread similar    13GB
	tosh:   35MB/s   -> 23MB/s,  oread similar    40GB 2.5"

now it says:

> summary		2.4.31-hf1	2.6.12.2
> boxen \ time ->	 w 	 r	 w	 r
> ---------------	----	----	----	----
> silly			54	24	49	25
> tosh			30	19.5	27	19.5

ie here both silly and tosh do equally well on 2.4.x and 2.6.x on reads, 
and seem to perhaps show a bit of slowdown on writes (which I suspect may 
be due to the fact that we try to limit the queues a bit more, but hey, 
that's handwaving).

The point being that the slowdown you see seems to really largely be
limited to the raw partition code. Your filesystem throughput numbers for 
reads are generally _better_ on 2.6.x than on 2.4.x when doing filesystem 
accesses (but the differences aren't all that big).

So my gut feel is that the reason hdparm and dd from the raw partition 
gives different performance is not so much the driver, but probably that 
we've tweaked read-ahead for file access or something like that. Maybe 
the maximum fs-level read-ahead changed?

		Linus

Re: [git patches] IDE update

[Jens Axboe]

[-- Attachment #1: Type: text/plain, Size: 1893 bytes --]

On Tue, Jul 05 2005, Linus Torvalds wrote:
> So my gut feel is that the reason hdparm and dd from the raw partition 
> gives different performance is not so much the driver, but probably that 
> we've tweaked read-ahead for file access or something like that. Maybe 
> the maximum fs-level read-ahead changed?

I don't think this is the case. I butchered a test system here and
successfully got it running a P2 at 375MHz (don't ask, messing with
multipliers and FSB with slot-1 cpu's has been a while) and 2.6 was
still faster.

But! I used hdparm -t solely, 2.6 was always ~5% faster than 2.4. But
using -Tt slowed down the hd speed by about 30%. So it looks like some
scheduler interaction, perhaps the memory timing loops gets it marked as
batch or something?

hdparm really does nothing special - it reads the disk in 2MiB chunks,
calling getitimer() in between to stop at 3 seconds.

bart:~ # uname -a
Linux bart 2.6.13-rc2 #2 SMP Fri Jul 8 09:51:39 CEST 2005 i686 i686 i386
GNU/Linux

bart:~ # hdparm -Tt /dev/hdc

/dev/hdc:
 Timing buffer-cache reads:   380 MB in  2.00 seconds = 190.00 MB/sec
 Timing buffered disk reads:   64 MB in  3.06 seconds =  20.92 MB/sec
bart:~ # hdparm -t /dev/hdc

/dev/hdc:
 Timing buffered disk reads:   88 MB in  3.05 seconds =  28.85 MB/sec

I'm attaching a silly test case that demonstrates the problem by reading
512MiB from a given disk.

bart:~ # ./read_disk /dev/hdc
Disk Throughput: 29 MiB/sec
bart:~ # ./read_disk /dev/hdc 1
Mem Throughput: 102 MiB/sec
Mem Throughput: 101 MiB/sec
Disk Throughput: 21 MiB/sec

Passing an extra argument to the program, makes it do the same priming
loop as hdparm. That part runs at 100% system time, just copying data to
user space and issuing an lseek for each read. Again, if I run this on
my workstation (dual core em64t), it doesn't show the problem.

hdparm strace -tt timings also attached.

-- 
Jens Axboe


[-- Attachment #2: hdparm-with-buffer --]
[-- Type: text/plain, Size: 46074 bytes --]

10:23:13.833131 execve("/sbin/hdparm", ["hdparm", "-Tt", "/dev/hdc"], [/* 50 vars */]) = 0
10:23:13.834044 uname({sys="Linux", node="bart", ...}) = 0
10:23:13.835015 brk(0)                  = 0x8054000
10:23:13.835421 open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or directory)
10:23:13.835813 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40017000
10:23:13.836251 open("/etc/ld.so.cache", O_RDONLY) = 3
10:23:13.836563 fstat64(3, {st_mode=S_IFREG|0644, st_size=23320, ...}) = 0
10:23:13.837038 old_mmap(NULL, 23320, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40018000
10:23:13.837379 close(3)                = 0
10:23:13.837678 open("/lib/tls/libc.so.6", O_RDONLY) = 3
10:23:13.837987 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0PS\1\000"..., 512) = 512
10:23:13.838392 fstat64(3, {st_mode=S_IFREG|0755, st_size=1345609, ...}) = 0
10:23:13.838804 old_mmap(NULL, 1132908, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x4001e000
10:23:13.839152 madvise(0x4001e000, 1132908, MADV_SEQUENTIAL|0x1) = 0
10:23:13.839462 old_mmap(0x40128000, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x109000) = 0x40128000
10:23:13.839901 old_mmap(0x40130000, 10604, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x40130000
10:23:13.840264 close(3)                = 0
10:23:13.841154 set_thread_area({entry_number:-1 -> 6, base_addr:0x40017860, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
10:23:13.841486 munmap(0x40018000, 23320) = 0
10:23:13.841925 stat64("/dev/hdc", {st_mode=S_IFBLK|0660, st_rdev=makedev(22, 0), ...}) = 0
10:23:13.842393 open("/dev/hdc", O_RDONLY|O_NONBLOCK) = 3
10:23:13.842806 fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
10:23:13.843225 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40018000
10:23:13.843537 write(1, "\n", 1)       = 1
10:23:13.844335 write(1, "/dev/hdc:\n", 10) = 10
10:23:13.844974 shmget(IPC_PRIVATE, 2097152, 0600) = 557056
10:23:13.845333 shmctl(557056, IPC_64|SHM_LOCK, 0) = 0
10:23:13.845618 shmat(557056, 0, 0)     = 0x40133000
10:23:13.845939 shmctl(557056, IPC_64|IPC_RMID, 0) = 0
10:23:13.846208 sync()                  = 0
10:23:13.859724 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
10:23:13.860118 rt_sigaction(SIGCHLD, NULL, {SIG_DFL}, 8) = 0
10:23:13.860429 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
10:23:13.860716 nanosleep({3, 0}, {3, 0}) = 0
10:23:16.875595 setitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={1000, 0}}, NULL) = 0
10:23:16.875920 lseek(3, 0, SEEK_SET)   = 0
10:23:16.876192 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:16.961989 write(1, " Timing buffer-cache reads:   ", 30) = 30
10:23:16.963078 sync()                  = 0
10:23:16.968622 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
10:23:16.968978 rt_sigaction(SIGCHLD, NULL, {SIG_DFL}, 8) = 0
10:23:16.969273 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
10:23:16.969561 nanosleep({1, 0}, {1, 0}) = 0
10:23:17.975598 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 910000}}) = 0
10:23:17.975895 lseek(3, 0, SEEK_SET)   = 0
10:23:17.976156 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:17.997351 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 890000}}) = 0
10:23:17.997729 lseek(3, 0, SEEK_SET)   = 0
10:23:17.997996 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.018996 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 870000}}) = 0
10:23:18.019349 lseek(3, 0, SEEK_SET)   = 0
10:23:18.019615 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.040547 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 840000}}) = 0
10:23:18.040900 lseek(3, 0, SEEK_SET)   = 0
10:23:18.041165 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.062054 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 820000}}) = 0
10:23:18.062621 lseek(3, 0, SEEK_SET)   = 0
10:23:18.062892 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.083773 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 800000}}) = 0
10:23:18.084128 lseek(3, 0, SEEK_SET)   = 0
10:23:18.084395 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.105290 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 780000}}) = 0
10:23:18.105681 lseek(3, 0, SEEK_SET)   = 0
10:23:18.105947 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.126852 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 760000}}) = 0
10:23:18.127205 lseek(3, 0, SEEK_SET)   = 0
10:23:18.127471 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.148381 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 740000}}) = 0
10:23:18.148734 lseek(3, 0, SEEK_SET)   = 0
10:23:18.149001 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.169908 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 720000}}) = 0
10:23:18.170261 lseek(3, 0, SEEK_SET)   = 0
10:23:18.170554 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.191453 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 690000}}) = 0
10:23:18.191805 lseek(3, 0, SEEK_SET)   = 0
10:23:18.192071 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.212975 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 670000}}) = 0
10:23:18.213325 lseek(3, 0, SEEK_SET)   = 0
10:23:18.213591 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.234492 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 650000}}) = 0
10:23:18.234844 lseek(3, 0, SEEK_SET)   = 0
10:23:18.235110 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.256039 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 630000}}) = 0
10:23:18.256391 lseek(3, 0, SEEK_SET)   = 0
10:23:18.256658 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.277555 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 610000}}) = 0
10:23:18.277906 lseek(3, 0, SEEK_SET)   = 0
10:23:18.278172 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.299086 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 590000}}) = 0
10:23:18.299437 lseek(3, 0, SEEK_SET)   = 0
10:23:18.299703 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.320774 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 560000}}) = 0
10:23:18.321126 lseek(3, 0, SEEK_SET)   = 0
10:23:18.321394 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.342286 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 540000}}) = 0
10:23:18.342640 lseek(3, 0, SEEK_SET)   = 0
10:23:18.342909 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.363812 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 520000}}) = 0
10:23:18.364168 lseek(3, 0, SEEK_SET)   = 0
10:23:18.364436 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.385347 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 500000}}) = 0
10:23:18.385740 lseek(3, 0, SEEK_SET)   = 0
10:23:18.386006 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.406890 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 480000}}) = 0
10:23:18.407243 lseek(3, 0, SEEK_SET)   = 0
10:23:18.407509 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.428412 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 460000}}) = 0
10:23:18.428987 lseek(3, 0, SEEK_SET)   = 0
10:23:18.429259 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.450135 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 430000}}) = 0
10:23:18.450513 lseek(3, 0, SEEK_SET)   = 0
10:23:18.450778 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.471672 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 410000}}) = 0
10:23:18.472024 lseek(3, 0, SEEK_SET)   = 0
10:23:18.472290 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.493187 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 390000}}) = 0
10:23:18.493539 lseek(3, 0, SEEK_SET)   = 0
10:23:18.493804 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.515121 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 370000}}) = 0
10:23:18.515522 lseek(3, 0, SEEK_SET)   = 0
10:23:18.515788 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.536692 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 350000}}) = 0
10:23:18.537044 lseek(3, 0, SEEK_SET)   = 0
10:23:18.537309 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.558191 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 330000}}) = 0
10:23:18.558544 lseek(3, 0, SEEK_SET)   = 0
10:23:18.558808 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.579710 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 310000}}) = 0
10:23:18.580063 lseek(3, 0, SEEK_SET)   = 0
10:23:18.580352 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.602708 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 280000}}) = 0
10:23:18.603061 lseek(3, 0, SEEK_SET)   = 0
10:23:18.603325 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.624180 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 260000}}) = 0
10:23:18.624530 lseek(3, 0, SEEK_SET)   = 0
10:23:18.624797 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.645731 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 240000}}) = 0
10:23:18.646081 lseek(3, 0, SEEK_SET)   = 0
10:23:18.646346 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.667234 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 220000}}) = 0
10:23:18.667585 lseek(3, 0, SEEK_SET)   = 0
10:23:18.667851 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.688755 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 200000}}) = 0
10:23:18.689106 lseek(3, 0, SEEK_SET)   = 0
10:23:18.689372 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.710936 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 170000}}) = 0
10:23:18.711288 lseek(3, 0, SEEK_SET)   = 0
10:23:18.711554 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.732457 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 150000}}) = 0
10:23:18.732809 lseek(3, 0, SEEK_SET)   = 0
10:23:18.733074 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.753990 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 130000}}) = 0
10:23:18.754343 lseek(3, 0, SEEK_SET)   = 0
10:23:18.754609 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.775530 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 110000}}) = 0
10:23:18.775880 lseek(3, 0, SEEK_SET)   = 0
10:23:18.776145 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.798381 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 90000}}) = 0
10:23:18.798925 lseek(3, 0, SEEK_SET)   = 0
10:23:18.799194 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.819969 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 70000}}) = 0
10:23:18.820345 lseek(3, 0, SEEK_SET)   = 0
10:23:18.820612 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.841526 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 40000}}) = 0
10:23:18.841877 lseek(3, 0, SEEK_SET)   = 0
10:23:18.842142 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.863023 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 20000}}) = 0
10:23:18.863377 lseek(3, 0, SEEK_SET)   = 0
10:23:18.863642 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.884835 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 0}}) = 0
10:23:18.885186 lseek(3, 0, SEEK_SET)   = 0
10:23:18.885505 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.906443 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 980000}}) = 0
10:23:18.906795 lseek(3, 0, SEEK_SET)   = 0
10:23:18.907060 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.927943 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 960000}}) = 0
10:23:18.928295 lseek(3, 0, SEEK_SET)   = 0
10:23:18.928559 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.949465 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 940000}}) = 0
10:23:18.949816 lseek(3, 0, SEEK_SET)   = 0
10:23:18.950081 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.970988 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 910000}}) = 0
10:23:18.971338 lseek(3, 0, SEEK_SET)   = 0
10:23:18.971603 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:18.992499 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 890000}}) = 0
10:23:18.992851 lseek(3, 0, SEEK_SET)   = 0
10:23:18.993115 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.014089 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 870000}}) = 0
10:23:19.014443 lseek(3, 0, SEEK_SET)   = 0
10:23:19.014708 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.035629 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 850000}}) = 0
10:23:19.035982 lseek(3, 0, SEEK_SET)   = 0
10:23:19.036247 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.057130 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 830000}}) = 0
10:23:19.057484 lseek(3, 0, SEEK_SET)   = 0
10:23:19.057749 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.078662 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 810000}}) = 0
10:23:19.079014 lseek(3, 0, SEEK_SET)   = 0
10:23:19.079280 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.100168 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 780000}}) = 0
10:23:19.100546 lseek(3, 0, SEEK_SET)   = 0
10:23:19.100811 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.121707 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 760000}}) = 0
10:23:19.122062 lseek(3, 0, SEEK_SET)   = 0
10:23:19.122327 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.143220 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 740000}}) = 0
10:23:19.143573 lseek(3, 0, SEEK_SET)   = 0
10:23:19.143838 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.164743 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 720000}}) = 0
10:23:19.165096 lseek(3, 0, SEEK_SET)   = 0
10:23:19.165590 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.186449 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 700000}}) = 0
10:23:19.186777 lseek(3, 0, SEEK_SET)   = 0
10:23:19.187019 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.207875 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 680000}}) = 0
10:23:19.208204 lseek(3, 0, SEEK_SET)   = 0
10:23:19.208445 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.229310 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 660000}}) = 0
10:23:19.229639 lseek(3, 0, SEEK_SET)   = 0
10:23:19.229880 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.250799 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 630000}}) = 0
10:23:19.251126 lseek(3, 0, SEEK_SET)   = 0
10:23:19.251366 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.272250 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 610000}}) = 0
10:23:19.272577 lseek(3, 0, SEEK_SET)   = 0
10:23:19.272819 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.293706 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 590000}}) = 0
10:23:19.294033 lseek(3, 0, SEEK_SET)   = 0
10:23:19.294274 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.315140 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 570000}}) = 0
10:23:19.315694 lseek(3, 0, SEEK_SET)   = 0
10:23:19.315945 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.336838 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 550000}}) = 0
10:23:19.337164 lseek(3, 0, SEEK_SET)   = 0
10:23:19.337405 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.358275 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 530000}}) = 0
10:23:19.358603 lseek(3, 0, SEEK_SET)   = 0
10:23:19.358845 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.379706 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 510000}}) = 0
10:23:19.380034 lseek(3, 0, SEEK_SET)   = 0
10:23:19.380299 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.401210 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 480000}}) = 0
10:23:19.401536 lseek(3, 0, SEEK_SET)   = 0
10:23:19.401777 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.422641 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 460000}}) = 0
10:23:19.422969 lseek(3, 0, SEEK_SET)   = 0
10:23:19.423211 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.444095 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 440000}}) = 0
10:23:19.444424 lseek(3, 0, SEEK_SET)   = 0
10:23:19.444666 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.465555 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 420000}}) = 0
10:23:19.465881 lseek(3, 0, SEEK_SET)   = 0
10:23:19.466122 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.486995 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 400000}}) = 0
10:23:19.487321 lseek(3, 0, SEEK_SET)   = 0
10:23:19.487563 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.508435 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 380000}}) = 0
10:23:19.508764 lseek(3, 0, SEEK_SET)   = 0
10:23:19.509006 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.529872 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 360000}}) = 0
10:23:19.530200 lseek(3, 0, SEEK_SET)   = 0
10:23:19.530675 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.551521 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 330000}}) = 0
10:23:19.551848 lseek(3, 0, SEEK_SET)   = 0
10:23:19.552090 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.572968 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 310000}}) = 0
10:23:19.573295 lseek(3, 0, SEEK_SET)   = 0
10:23:19.573537 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.594420 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 290000}}) = 0
10:23:19.594748 lseek(3, 0, SEEK_SET)   = 0
10:23:19.594989 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.615869 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 270000}}) = 0
10:23:19.616197 lseek(3, 0, SEEK_SET)   = 0
10:23:19.616439 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.637311 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 250000}}) = 0
10:23:19.637637 lseek(3, 0, SEEK_SET)   = 0
10:23:19.637878 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.658747 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 230000}}) = 0
10:23:19.659075 lseek(3, 0, SEEK_SET)   = 0
10:23:19.659317 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.680183 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 200000}}) = 0
10:23:19.680538 lseek(3, 0, SEEK_SET)   = 0
10:23:19.680780 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.701661 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 180000}}) = 0
10:23:19.701988 lseek(3, 0, SEEK_SET)   = 0
10:23:19.702229 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.723097 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 160000}}) = 0
10:23:19.723424 lseek(3, 0, SEEK_SET)   = 0
10:23:19.723667 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.744555 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 140000}}) = 0
10:23:19.744883 lseek(3, 0, SEEK_SET)   = 0
10:23:19.745124 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.766000 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 120000}}) = 0
10:23:19.766325 lseek(3, 0, SEEK_SET)   = 0
10:23:19.766567 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.787453 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 100000}}) = 0
10:23:19.787781 lseek(3, 0, SEEK_SET)   = 0
10:23:19.788022 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.810184 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 70000}}) = 0
10:23:19.810536 lseek(3, 0, SEEK_SET)   = 0
10:23:19.810778 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.831605 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 50000}}) = 0
10:23:19.831935 lseek(3, 0, SEEK_SET)   = 0
10:23:19.832177 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.853058 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 30000}}) = 0
10:23:19.853385 lseek(3, 0, SEEK_SET)   = 0
10:23:19.853627 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.874502 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 10000}}) = 0
10:23:19.874839 lseek(3, 0, SEEK_SET)   = 0
10:23:19.875081 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.895976 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 990000}}) = 0
10:23:19.896302 lseek(3, 0, SEEK_SET)   = 0
10:23:19.896544 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.917589 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 970000}}) = 0
10:23:19.917915 lseek(3, 0, SEEK_SET)   = 0
10:23:19.918157 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.939041 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 950000}}) = 0
10:23:19.939368 lseek(3, 0, SEEK_SET)   = 0
10:23:19.939610 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.960527 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 920000}}) = 0
10:23:19.960854 lseek(3, 0, SEEK_SET)   = 0
10:23:19.961095 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:19.981968 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.982293 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.982552 lseek(3, 0, SEEK_SET)   = 0
10:23:19.982789 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.983048 lseek(3, 0, SEEK_SET)   = 0
10:23:19.983278 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.983537 lseek(3, 0, SEEK_SET)   = 0
10:23:19.983768 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.984027 lseek(3, 0, SEEK_SET)   = 0
10:23:19.984257 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.984516 lseek(3, 0, SEEK_SET)   = 0
10:23:19.984745 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.985004 lseek(3, 0, SEEK_SET)   = 0
10:23:19.985234 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.985536 lseek(3, 0, SEEK_SET)   = 0
10:23:19.985768 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.986027 lseek(3, 0, SEEK_SET)   = 0
10:23:19.986257 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.986516 lseek(3, 0, SEEK_SET)   = 0
10:23:19.986747 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.987006 lseek(3, 0, SEEK_SET)   = 0
10:23:19.987235 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.987494 lseek(3, 0, SEEK_SET)   = 0
10:23:19.987724 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.987983 lseek(3, 0, SEEK_SET)   = 0
10:23:19.988213 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.988472 lseek(3, 0, SEEK_SET)   = 0
10:23:19.988702 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.988961 lseek(3, 0, SEEK_SET)   = 0
10:23:19.989191 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.989450 lseek(3, 0, SEEK_SET)   = 0
10:23:19.989680 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 900000}}) = 0
10:23:19.989939 lseek(3, 0, SEEK_SET)   = 0
10:23:19.990169 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.990452 lseek(3, 0, SEEK_SET)   = 0
10:23:19.990682 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.990942 lseek(3, 0, SEEK_SET)   = 0
10:23:19.991172 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.991431 lseek(3, 0, SEEK_SET)   = 0
10:23:19.991661 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.991920 lseek(3, 0, SEEK_SET)   = 0
10:23:19.992150 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.992410 lseek(3, 0, SEEK_SET)   = 0
10:23:19.992640 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.992899 lseek(3, 0, SEEK_SET)   = 0
10:23:19.993129 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.993388 lseek(3, 0, SEEK_SET)   = 0
10:23:19.993618 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.994087 lseek(3, 0, SEEK_SET)   = 0
10:23:19.994322 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.994582 lseek(3, 0, SEEK_SET)   = 0
10:23:19.994811 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.995070 lseek(3, 0, SEEK_SET)   = 0
10:23:19.995300 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.995578 lseek(3, 0, SEEK_SET)   = 0
10:23:19.995808 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.996067 lseek(3, 0, SEEK_SET)   = 0
10:23:19.996296 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.996555 lseek(3, 0, SEEK_SET)   = 0
10:23:19.996785 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.997044 lseek(3, 0, SEEK_SET)   = 0
10:23:19.997274 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.997532 lseek(3, 0, SEEK_SET)   = 0
10:23:19.997762 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.998021 lseek(3, 0, SEEK_SET)   = 0
10:23:19.998251 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.998510 lseek(3, 0, SEEK_SET)   = 0
10:23:19.998740 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.998999 lseek(3, 0, SEEK_SET)   = 0
10:23:19.999228 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.999487 lseek(3, 0, SEEK_SET)   = 0
10:23:19.999716 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 890000}}) = 0
10:23:19.999975 lseek(3, 0, SEEK_SET)   = 0
10:23:20.000205 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.000499 lseek(3, 0, SEEK_SET)   = 0
10:23:20.000730 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.000990 lseek(3, 0, SEEK_SET)   = 0
10:23:20.001220 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.001479 lseek(3, 0, SEEK_SET)   = 0
10:23:20.001711 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.001970 lseek(3, 0, SEEK_SET)   = 0
10:23:20.002201 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.002460 lseek(3, 0, SEEK_SET)   = 0
10:23:20.002690 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.002950 lseek(3, 0, SEEK_SET)   = 0
10:23:20.003180 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.003439 lseek(3, 0, SEEK_SET)   = 0
10:23:20.003670 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.003929 lseek(3, 0, SEEK_SET)   = 0
10:23:20.004160 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.004420 lseek(3, 0, SEEK_SET)   = 0
10:23:20.004650 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.004910 lseek(3, 0, SEEK_SET)   = 0
10:23:20.005140 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.005399 lseek(3, 0, SEEK_SET)   = 0
10:23:20.005645 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.005905 lseek(3, 0, SEEK_SET)   = 0
10:23:20.006136 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.006395 lseek(3, 0, SEEK_SET)   = 0
10:23:20.006626 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.006886 lseek(3, 0, SEEK_SET)   = 0
10:23:20.007117 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.007377 lseek(3, 0, SEEK_SET)   = 0
10:23:20.007607 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.007867 lseek(3, 0, SEEK_SET)   = 0
10:23:20.008098 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.008358 lseek(3, 0, SEEK_SET)   = 0
10:23:20.008589 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.008977 lseek(3, 0, SEEK_SET)   = 0
10:23:20.009212 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.009473 lseek(3, 0, SEEK_SET)   = 0
10:23:20.009703 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 880000}}) = 0
10:23:20.009963 lseek(3, 0, SEEK_SET)   = 0
10:23:20.010193 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.010469 lseek(3, 0, SEEK_SET)   = 0
10:23:20.010699 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.010959 lseek(3, 0, SEEK_SET)   = 0
10:23:20.011188 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.011448 lseek(3, 0, SEEK_SET)   = 0
10:23:20.011678 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.011938 lseek(3, 0, SEEK_SET)   = 0
10:23:20.012168 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.012428 lseek(3, 0, SEEK_SET)   = 0
10:23:20.012658 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.012918 lseek(3, 0, SEEK_SET)   = 0
10:23:20.013148 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.013407 lseek(3, 0, SEEK_SET)   = 0
10:23:20.013638 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.013897 lseek(3, 0, SEEK_SET)   = 0
10:23:20.014127 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.014387 lseek(3, 0, SEEK_SET)   = 0
10:23:20.014617 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.014876 lseek(3, 0, SEEK_SET)   = 0
10:23:20.015106 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.015366 lseek(3, 0, SEEK_SET)   = 0
10:23:20.015618 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.015878 lseek(3, 0, SEEK_SET)   = 0
10:23:20.016108 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.016368 lseek(3, 0, SEEK_SET)   = 0
10:23:20.016598 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.016858 lseek(3, 0, SEEK_SET)   = 0
10:23:20.017088 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.017348 lseek(3, 0, SEEK_SET)   = 0
10:23:20.017578 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.017838 lseek(3, 0, SEEK_SET)   = 0
10:23:20.018068 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.018328 lseek(3, 0, SEEK_SET)   = 0
10:23:20.018558 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.018818 lseek(3, 0, SEEK_SET)   = 0
10:23:20.019048 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.019308 lseek(3, 0, SEEK_SET)   = 0
10:23:20.019538 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.019798 lseek(3, 0, SEEK_SET)   = 0
10:23:20.020028 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 870000}}) = 0
10:23:20.020303 lseek(3, 0, SEEK_SET)   = 0
10:23:20.020534 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.020794 lseek(3, 0, SEEK_SET)   = 0
10:23:20.021024 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.021284 lseek(3, 0, SEEK_SET)   = 0
10:23:20.021514 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.021774 lseek(3, 0, SEEK_SET)   = 0
10:23:20.022005 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.022265 lseek(3, 0, SEEK_SET)   = 0
10:23:20.022495 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.022755 lseek(3, 0, SEEK_SET)   = 0
10:23:20.022986 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.023246 lseek(3, 0, SEEK_SET)   = 0
10:23:20.023476 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.023736 lseek(3, 0, SEEK_SET)   = 0
10:23:20.024094 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.024356 lseek(3, 0, SEEK_SET)   = 0
10:23:20.024586 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.024846 lseek(3, 0, SEEK_SET)   = 0
10:23:20.025075 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.025336 lseek(3, 0, SEEK_SET)   = 0
10:23:20.025582 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.025842 lseek(3, 0, SEEK_SET)   = 0
10:23:20.026072 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.026332 lseek(3, 0, SEEK_SET)   = 0
10:23:20.026562 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.026822 lseek(3, 0, SEEK_SET)   = 0
10:23:20.027053 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.027312 lseek(3, 0, SEEK_SET)   = 0
10:23:20.027543 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.027803 lseek(3, 0, SEEK_SET)   = 0
10:23:20.028034 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.028293 lseek(3, 0, SEEK_SET)   = 0
10:23:20.028524 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 860000}}) = 0
10:23:20.028939 write(1, "372 MB in  1.97 seconds = 188.83"..., 40) = 40
10:23:20.029779 fsync(3)                = 0
10:23:20.030069 ioctl(3, BLKFLSBUF, 0)  = 0
10:23:20.033348 ioctl(3, 0x31f, 0)      = 0
10:23:20.033652 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
10:23:20.033970 rt_sigaction(SIGCHLD, NULL, {SIG_DFL}, 8) = 0
10:23:20.034239 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
10:23:20.034501 nanosleep({1, 0}, {1, 0}) = 0
10:23:21.045684 shmdt(0x40133000)       = 0
10:23:21.049473 ioctl(3, BLKGETSIZE, 0x8053654) = 0
10:23:21.049726 shmget(IPC_PRIVATE, 2097152, 0600) = 589824
10:23:21.050007 shmctl(589824, IPC_64|SHM_LOCK, 0) = 0
10:23:21.050255 shmat(589824, 0, 0)     = 0x40133000
10:23:21.050559 shmctl(589824, IPC_64|IPC_RMID, 0) = 0
10:23:21.050783 sync()                  = 0
10:23:21.059644 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
10:23:21.059968 rt_sigaction(SIGCHLD, NULL, {SIG_DFL}, 8) = 0
10:23:21.060235 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
10:23:21.060513 nanosleep({3, 0}, {3, 0}) = 0
10:23:24.075779 write(1, " Timing buffered disk reads:  ", 30) = 30
10:23:24.076394 setitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={1000, 0}}, NULL) = 0
10:23:24.076668 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={1000, 10000}}) = 0
10:23:24.076927 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:24.180383 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 900000}}) = 0
10:23:24.180709 read(3, ";\n\tudelay(DelayValue);\n\tval = (d"..., 2097152) = 2097152
10:23:24.275463 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 810000}}) = 0
10:23:24.275817 read(3, "r receive packets.\n */\n#define P"..., 2097152) = 2097152
10:23:24.371503 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 710000}}) = 0
10:23:24.371829 read(3, " ? \"h,sg\" : \"sg\"\n\t\t);\n\n#ifdef PH"..., 2097152) = 2097152
10:23:24.466086 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 620000}}) = 0
10:23:24.466410 read(3, "ERN_ERR \"happymeal: Device does "..., 2097152) = 2097152
10:23:24.561413 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 520000}}) = 0
10:23:24.561740 read(3, "\0\3\206(\0\0\0\2#P\v\0349\0\0\3\211(\0\0\0\2#T\vD+\0\0"..., 2097152) = 2097152
10:23:24.656591 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 430000}}) = 0
10:23:24.656917 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:24.750603 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 330000}}) = 0
10:23:24.750932 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:24.848194 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 240000}}) = 0
10:23:24.848731 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:24.944340 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 140000}}) = 0
10:23:24.944667 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:25.040785 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 40000}}) = 0
10:23:25.041108 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:25.135071 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 950000}}) = 0
10:23:25.135398 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:25.229528 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 860000}}) = 0
10:23:25.229854 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:25.324099 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 760000}}) = 0
10:23:25.324425 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:25.418967 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 670000}}) = 0
10:23:25.419297 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:25.516288 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 570000}}) = 0
10:23:25.516612 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:25.610935 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 470000}}) = 0
10:23:25.611263 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:25.705288 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 380000}}) = 0
10:23:25.705634 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:25.799912 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 290000}}) = 0
10:23:25.800237 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:25.895995 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 190000}}) = 0
10:23:25.896319 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:25.992286 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 90000}}) = 0
10:23:25.992613 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:26.085528 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 0}}) = 0
10:23:26.085889 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:26.179350 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 910000}}) = 0
10:23:26.179678 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:26.272786 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 810000}}) = 0
10:23:26.273113 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:26.367078 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 720000}}) = 0
10:23:26.367404 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:26.460888 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 620000}}) = 0
10:23:26.461216 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:26.554987 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 530000}}) = 0
10:23:26.555315 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:26.649288 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 440000}}) = 0
10:23:26.649615 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:26.744671 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 340000}}) = 0
10:23:26.744998 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:26.838041 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 250000}}) = 0
10:23:26.838568 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:26.931709 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 150000}}) = 0
10:23:26.932035 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:27.027930 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 60000}}) = 0
10:23:27.028260 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:27.121558 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 960000}}) = 0
10:23:27.121965 write(1, " 64 MB in  3.05 seconds =  20.98"..., 40) = 40
10:23:27.122753 shmdt(0x40133000)       = 0
10:23:27.126625 fsync(3)                = 0
10:23:27.126890 ioctl(3, BLKFLSBUF, 0)  = 0
10:23:27.220177 ioctl(3, 0x31f, 0)      = 0
10:23:27.220551 close(3)                = 0
10:23:27.220905 munmap(0x40018000, 4096) = 0
10:23:27.221177 exit_group(0)           = ?

[-- Attachment #3: hdparm-only-disk --]
[-- Type: text/plain, Size: 11725 bytes --]

10:22:57.770823 execve("/sbin/hdparm", ["hdparm", "-t", "/dev/hdc"], [/* 50 vars */]) = 0
10:22:57.771705 uname({sys="Linux", node="bart", ...}) = 0
10:22:57.772689 brk(0)                  = 0x8054000
10:22:57.773054 open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or directory)
10:22:57.773452 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40017000
10:22:57.773925 open("/etc/ld.so.cache", O_RDONLY) = 3
10:22:57.774251 fstat64(3, {st_mode=S_IFREG|0644, st_size=23320, ...}) = 0
10:22:57.774737 old_mmap(NULL, 23320, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40018000
10:22:57.775115 close(3)                = 0
10:22:57.775426 open("/lib/tls/libc.so.6", O_RDONLY) = 3
10:22:57.775747 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0PS\1\000"..., 512) = 512
10:22:57.776166 fstat64(3, {st_mode=S_IFREG|0755, st_size=1345609, ...}) = 0
10:22:57.776587 old_mmap(NULL, 1132908, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x4001e000
10:22:57.776948 madvise(0x4001e000, 1132908, MADV_SEQUENTIAL|0x1) = 0
10:22:57.777269 old_mmap(0x40128000, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x109000) = 0x40128000
10:22:57.777722 old_mmap(0x40130000, 10604, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x40130000
10:22:57.778097 close(3)                = 0
10:22:57.778982 set_thread_area({entry_number:-1 -> 6, base_addr:0x40017860, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
10:22:57.779324 munmap(0x40018000, 23320) = 0
10:22:57.779770 stat64("/dev/hdc", {st_mode=S_IFBLK|0660, st_rdev=makedev(22, 0), ...}) = 0
10:22:57.780248 open("/dev/hdc", O_RDONLY|O_NONBLOCK) = 3
10:22:57.780669 fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
10:22:57.781096 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40018000
10:22:57.781421 write(1, "\n", 1)       = 1
10:22:57.782221 write(1, "/dev/hdc:\n", 10) = 10
10:22:57.782860 ioctl(3, BLKGETSIZE, 0x8053654) = 0
10:22:57.783205 shmget(IPC_PRIVATE, 2097152, 0600) = 524288
10:22:57.783544 shmctl(524288, IPC_64|SHM_LOCK, 0) = 0
10:22:57.783836 shmat(524288, 0, 0)     = 0x40133000
10:22:57.784163 shmctl(524288, IPC_64|IPC_RMID, 0) = 0
10:22:57.784443 sync()                  = 0
10:22:57.797834 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
10:22:57.798231 rt_sigaction(SIGCHLD, NULL, {SIG_DFL}, 8) = 0
10:22:57.798536 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
10:22:57.798834 nanosleep({3, 0}, {3, 0}) = 0
10:23:00.805197 write(1, " Timing buffered disk reads:  ", 30) = 30
10:23:00.805870 setitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={1000, 0}}, NULL) = 0
10:23:00.806201 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={1000, 10000}}) = 0
10:23:00.806506 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:00.891530 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 920000}}) = 0
10:23:00.891925 read(3, ";\n\tudelay(DelayValue);\n\tval = (d"..., 2097152) = 2097152
10:23:00.962824 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 850000}}) = 0
10:23:00.963197 read(3, "r receive packets.\n */\n#define P"..., 2097152) = 2097152
10:23:01.033623 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 780000}}) = 0
10:23:01.033994 read(3, " ? \"h,sg\" : \"sg\"\n\t\t);\n\n#ifdef PH"..., 2097152) = 2097152
10:23:01.105972 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 710000}}) = 0
10:23:01.106340 read(3, "ERN_ERR \"happymeal: Device does "..., 2097152) = 2097152
10:23:01.173562 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 640000}}) = 0
10:23:01.173934 read(3, "\0\3\206(\0\0\0\2#P\v\0349\0\0\3\211(\0\0\0\2#T\vD+\0\0"..., 2097152) = 2097152
10:23:01.244453 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 570000}}) = 0
10:23:01.244819 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:01.311869 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 500000}}) = 0
10:23:01.312458 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:01.380664 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 430000}}) = 0
10:23:01.381040 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:01.448160 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 370000}}) = 0
10:23:01.448535 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:01.516988 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 300000}}) = 0
10:23:01.517363 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:01.584412 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 230000}}) = 0
10:23:01.584783 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:01.653234 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 160000}}) = 0
10:23:01.653607 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:01.720721 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 90000}}) = 0
10:23:01.721091 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:01.789568 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={999, 30000}}) = 0
10:23:01.789937 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:01.856968 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 960000}}) = 0
10:23:01.857339 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:01.924354 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 890000}}) = 0
10:23:01.924715 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:01.993331 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 820000}}) = 0
10:23:01.993704 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.060780 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 750000}}) = 0
10:23:02.061152 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.129649 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 690000}}) = 0
10:23:02.130019 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.197036 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 620000}}) = 0
10:23:02.197406 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.266060 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 550000}}) = 0
10:23:02.266431 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.333527 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 480000}}) = 0
10:23:02.333899 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.402453 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 410000}}) = 0
10:23:02.402823 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.469857 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 350000}}) = 0
10:23:02.470227 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.538380 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 280000}}) = 0
10:23:02.538752 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.607039 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 210000}}) = 0
10:23:02.607410 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.677108 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 140000}}) = 0
10:23:02.677479 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.744509 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 70000}}) = 0
10:23:02.745134 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.813384 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={998, 0}}) = 0
10:23:02.813754 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.880829 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 930000}}) = 0
10:23:02.881200 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:02.949803 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 870000}}) = 0
10:23:02.950174 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:03.017326 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 800000}}) = 0
10:23:03.017700 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:03.084622 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 730000}}) = 0
10:23:03.085032 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:03.153619 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 660000}}) = 0
10:23:03.153991 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:03.221053 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 590000}}) = 0
10:23:03.221423 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:03.305029 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 510000}}) = 0
10:23:03.305559 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:03.372482 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 440000}}) = 0
10:23:03.372853 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:03.441417 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 370000}}) = 0
10:23:03.441788 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:03.508725 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 310000}}) = 0
10:23:03.509094 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:03.576150 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 240000}}) = 0
10:23:03.576513 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:03.649065 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 170000}}) = 0
10:23:03.649425 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:03.718380 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 100000}}) = 0
10:23:03.718751 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:03.789756 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={997, 30000}}) = 0
10:23:03.790127 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2097152) = 2097152
10:23:03.857294 getitimer(ITIMER_REAL, {it_interval={1000, 0}, it_value={996, 960000}}) = 0
10:23:03.857859 write(1, " 88 MB in  3.05 seconds =  28.85"..., 40) = 40
10:23:03.858959 shmdt(0x40133000)       = 0
10:23:03.862757 fsync(3)                = 0
10:23:03.863055 ioctl(3, BLKFLSBUF, 0)  = 0
10:23:03.992242 ioctl(3, 0x31f, 0)      = 0
10:23:03.992635 close(3)                = 0
10:23:03.993032 munmap(0x40018000, 4096) = 0
10:23:03.993340 exit_group(0)           = ?

[-- Attachment #4: read_disk.c --]
[-- Type: text/plain, Size: 1400 bytes --]

#include <stdio.h>
#include <unistd.h>
#define __USE_GNU
#include <fcntl.h>
#include <stdlib.h>
#include <sys/time.h>
#include <sys/ioctl.h>
#include <linux/fs.h>

#define BS		(2048*1024)
#define BLOCKS		(256)
#define ALIGN(buf)	(char *) (((unsigned long) (buf) + 4095) & ~(4095))

void print_time(struct timeval *s, int memory)
{
	unsigned long ms, mb;
	struct timeval e;

	mb = BS * BLOCKS / 1024;
	gettimeofday(&e, NULL);
	ms = (e.tv_sec - s->tv_sec) * 1000 + (e.tv_usec - s->tv_usec) / 1000;

	if (memory)
		printf("Mem Throughput: %lu MiB/sec\n", mb / ms);
	else
		printf("Disk Throughput: %lu MiB/sec\n", mb / ms);
}

void read_stuff(int fd, char *buffer, int memory)
{
	struct timeval s;
	int i, ret;

	gettimeofday(&s, NULL);

	for (i = 0; i < BLOCKS; i++) {
		if (memory)
			lseek(fd, 0, SEEK_SET);

		ret = read(fd, buffer, BS);

		if (!ret)
			break;
		else if (ret < 0) {
			perror("read infile");
			break;
		}
	}
	print_time(&s, memory);
}

int main(int argc, char *argv[])
{
	char *buffer;
	int fd, seek;

	if (argc < 2) {
		printf("%s: <device>\n", argv[0]);
		return 1;
	}

	if (argc == 3)
		seek = 1;
	else
		seek = 0;

	fd = open(argv[1], O_RDONLY);
	if (fd == -1) {
		perror("open");
		return 2;
	}

	ioctl(fd, BLKFLSBUF, 0);

	buffer = ALIGN(malloc(BS + 4095));

	if (seek) {
		read_stuff(fd, buffer, 1);
		read_stuff(fd, buffer, 1);
	}

	read_stuff(fd, buffer, 0);
	return 0;
}

Re: [git patches] IDE update

[Ingo Molnar]

* Jens Axboe <axboe@suse.de> wrote:

> But! I used hdparm -t solely, 2.6 was always ~5% faster than 2.4. But 
> using -Tt slowed down the hd speed by about 30%. So it looks like some 
> scheduler interaction, perhaps the memory timing loops gets it marked 
> as batch or something?

to check whether that could be the case, could you try:

	nice -n -20 hdparm -t /dev/hdc

does that produce different results?

	Ingo

Re: [git patches] IDE update

[Jens Axboe]

On Fri, Jul 08 2005, Ingo Molnar wrote:
> 
> * Jens Axboe <axboe@suse.de> wrote:
> 
> > But! I used hdparm -t solely, 2.6 was always ~5% faster than 2.4. But 
> > using -Tt slowed down the hd speed by about 30%. So it looks like some 
> > scheduler interaction, perhaps the memory timing loops gets it marked 
> > as batch or something?
> 
> to check whether that could be the case, could you try:
> 
> 	nice -n -20 hdparm -t /dev/hdc
> 
> does that produce different results?

Same result, see my next mail, it turned out to be a read-ahead bug.

-- 
Jens Axboe

Re: [git patches] IDE update

[Mark Lord]

Note:

hdparm can also use O_DIRECT for the -t timing test.

Eg.  hdparm --direct -t /dev/hda

Re: [git patches] IDE update

[Grant Coady]

On Thu, 07 Jul 2005 18:32:52 -0400, Mark Lord <liml@rtr.ca> wrote:
>
>hdparm can also use O_DIRECT for the -t timing test.

I've not been able to get dual channel I/O speed faster than single 
interface speed, either as 'md' RAID0 or simultaneous reading or 
writing done the other day:

Time to write or read 500MB file:

>summary		2.4.31-hf1	2.6.12.2
>boxen \ time ->	 w 	 r	 w	 r
>---------------	----	----	----	----
...
>peetoo			33	20	26.5	22
>(simultaneuous		57	37.5	52	38.5)

MB/s		2.4.31-hf1	2.6.12.2
		w	r	w	r
single		15	25	19	23
dual		17.5	27	19	26

These timings show very little happening in parallel, is that normal?

Thanks,
--Grant.

Re: [git patches] IDE update

[Erik Slagter]

[-- Attachment #1: Type: text/plain, Size: 636 bytes --]

On Fri, 2005-07-08 at 10:06 +1000, Grant Coady wrote:

> I've not been able to get dual channel I/O speed faster than single 
> interface speed, either as 'md' RAID0 or simultaneous reading or 
> writing done the other day:
> 
> Time to write or read 500MB file:
> 
> >summary		2.4.31-hf1	2.6.12.2
> >boxen \ time ->	 w 	 r	 w	 r
> >---------------	----	----	----	----
> ...
> >peetoo			33	20	26.5	22
> >(simultaneuous		57	37.5	52	38.5)
> 
> MB/s		2.4.31-hf1	2.6.12.2
> 		w	r	w	r
> single		15	25	19	23
> dual		17.5	27	19	26
> 
> These timings show very little happening in parallel, is that normal?

"me too" ;-)

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [git patches] IDE update

[Bill Davidsen]

Ondrej Zary wrote:
> Jens Axboe wrote:
> 
>> On Tue, Jul 05 2005, Ondrej Zary wrote:
>>
>>> André Tomt wrote:
>>>
>>>> Al Boldi wrote:
>>>>
>>>>
>>>>> Bartlomiej Zolnierkiewicz wrote: {
>>>>>
>>>>>
>>>>>>>> On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
>>>>>>>> Hdparm -tT gives 38mb/s in 2.4.31
>>>>>>>> Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
>>>>>>>>
>>>>>>>> Hdparm -tT gives 28mb/s in 2.6.12
>>>>>>>> Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
>>>>
>>>>
>>>>
>>>> The "hdparm doesn't get as high scores as in 2.4" is a old discussed 
>>>> to death "problem" on LKML. So far nobody has been able to show it 
>>>> affects anything  but that pretty useless quasi-benchmark.
>>>>
>>>
>>> No, it's not a problem with hdparm. hdparm only shows that there is 
>>> _really_ a problem:
>>>
>>> 2.6.12
>>> root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
>>> count=1048576
>>> 1048576+0 records in
>>> 1048576+0 records out
>>>
>>> real    0m32.339s
>>> user    0m1.500s
>>> sys     0m14.560s
>>>
>>> 2.4.26
>>> root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
>>> count=1048576
>>> 1048576+0 records in
>>> 1048576+0 records out
>>>
>>> real    0m23.858s
>>> user    0m1.750s
>>> sys     0m15.180s
>>
>>
>>
>> Perhaps some read-ahead bug. What happens if you use bs=128k for
>> instance?
>>
> Nothing - it's still the same.
> 
> root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=128k 
> count=4096
> 4096+0 records in
> 4096+0 records out
> 
> real    0m32.832s
> user    0m0.040s
> sys     0m15.670s
> 
Why is the system time so high? I tried that test here, and got:

oddball:root> time dd if=/dev/hda of=/dev/null bs=128k count=4096
4096+0 records in
4096+0 records out

real    0m37.927s
user    0m0.025s
sys     0m6.547s
oddball:root> uname -rn
oddball.prodigy.com 2.6.11ac7

Now this is one of the slowest CPUs still in use (which I why I test 
responsiveness on it), and it uses far less CPU time.
cat /proc/cpuinfo
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 6
model           : 5
model name      : Pentium II (Deschutes)
stepping        : 1
cpu MHz         : 348.507
cache size      : 512 KB
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 2
wp              : yes
flags           : fpu vme de tsc msr pae mce cx8 apic sep mtrr pge mca 
cmov pat pse36 mmx fxsr
bogomips        : 686.08


The first post said it felt like running PIO, it certainly is using CPU 
like it as well.

Now here's some dmesg from this system...

PIIX4: IDE controller at PCI slot 0000:00:07.1
PIIX4: chipset revision 1
PIIX4: not 100% native mode: will probe irqs later
     ide0: BM-DMA at 0x1080-0x1087, BIOS settings: hda:DMA, hdb:pio
     ide1: BM-DMA at 0x1088-0x108f, BIOS settings: hdc:DMA, hdd:pio
Probing IDE interface ide0...
hda: Maxtor 90845D4, ATA DISK drive
hdb: WDC AC31600H, ATA DISK drive
hdb: Disabling (U)DMA for WDC AC31600H (blacklisted)
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Probing IDE interface ide1...
hdc: NEC CD-ROM DRIVE:28C, ATAPI CD/DVD-ROM drive
ide1 at 0x170-0x177,0x376 on irq 15
hda: max request size: 128KiB
hda: 16514064 sectors (8455 MB) w/512KiB Cache, CHS=16383/16/63, UDMA(33)
hda: cache flushes not supported
  hda: hda1 hda2 hda3 hda4 < hda5 >
hdb: max request size: 128KiB
hdb: 3173184 sectors (1624 MB) w/128KiB Cache, CHS=3148/16/63
hdb: cache flushes not supported
  hdb: hdb1 hdb2 hdb3
hdc: ATAPI 32X CD-ROM drive, 128kB Cache, UDMA(33)
Uniform CD-ROM driver Revision: 3.20


And indeed it does show hda as dma, and hdb as pio (older versions of 
the kernel let me set hdb to dma and it worked fine...). But in the 
posted demsg the BIOS settings show pio for hda. Is this in any way 
relevant, given that UDA(33) appears later?


Ondrei:

PIIX4: IDE controller at PCI slot 00:07.1
PIIX4: chipset revision 1
PIIX4: not 100% native mode: will probe irqs later
     ide0: BM-DMA at 0xf000-0xf007, BIOS settings: hda:pio, hdb:pio
     ide1: BM-DMA at 0xf008-0xf00f, BIOS settings: hdc:pio, hdd:pio
hda: WDC WD300BB-00AUA1, ATA DISK drive
blk: queue c03b3360, I/O limit 4095Mb (mask 0xffffffff)
hdd: MSI CD-RW MS-8340S, ATAPI CD/DVD-ROM drive
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
ide1 at 0x170-0x177,0x376 on irq 15
hda: attached ide-disk driver.
hda: host protected area => 1
hda: 58633344 sectors (30020 MB) w/2048KiB Cache, CHS=3649/255/63, UDMA(33)


Unless Ondrei's CPU is slower than a PI-350, maybe it is running pio for 
some reason, in spite of hdparm -i showing udma2 mode.

I just mentioned it because the CPU usage doesn't seem compatible with 
DMA operation.

Re: [git patches] IDE update

[Ondrej Zary]

Bill Davidsen wrote:
> Ondrej Zary wrote:
> 
>> Jens Axboe wrote:
>>
>>> On Tue, Jul 05 2005, Ondrej Zary wrote:
>>>
>>>> André Tomt wrote:
>>>>
>>>>> Al Boldi wrote:
>>>>>
>>>>>
>>>>>> Bartlomiej Zolnierkiewicz wrote: {
>>>>>>
>>>>>>
>>>>>>>>> On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
>>>>>>>>> Hdparm -tT gives 38mb/s in 2.4.31
>>>>>>>>> Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
>>>>>>>>>
>>>>>>>>> Hdparm -tT gives 28mb/s in 2.6.12
>>>>>>>>> Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> The "hdparm doesn't get as high scores as in 2.4" is a old 
>>>>> discussed to death "problem" on LKML. So far nobody has been able 
>>>>> to show it affects anything  but that pretty useless quasi-benchmark.
>>>>>
>>>>
>>>> No, it's not a problem with hdparm. hdparm only shows that there is 
>>>> _really_ a problem:
>>>>
>>>> 2.6.12
>>>> root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
>>>> count=1048576
>>>> 1048576+0 records in
>>>> 1048576+0 records out
>>>>
>>>> real    0m32.339s
>>>> user    0m1.500s
>>>> sys     0m14.560s
>>>>
>>>> 2.4.26
>>>> root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
>>>> count=1048576
>>>> 1048576+0 records in
>>>> 1048576+0 records out
>>>>
>>>> real    0m23.858s
>>>> user    0m1.750s
>>>> sys     0m15.180s
>>>
>>>
>>>
>>>
>>> Perhaps some read-ahead bug. What happens if you use bs=128k for
>>> instance?
>>>
>> Nothing - it's still the same.
>>
>> root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=128k 
>> count=4096
>> 4096+0 records in
>> 4096+0 records out
>>
>> real    0m32.832s
>> user    0m0.040s
>> sys     0m15.670s
>>
> Why is the system time so high? I tried that test here, and got:
> 
> oddball:root> time dd if=/dev/hda of=/dev/null bs=128k count=4096
> 4096+0 records in
> 4096+0 records out
> 
> real    0m37.927s
> user    0m0.025s
> sys     0m6.547s
> oddball:root> uname -rn
> oddball.prodigy.com 2.6.11ac7
> 
> Now this is one of the slowest CPUs still in use (which I why I test 
> responsiveness on it), and it uses far less CPU time.
> cat /proc/cpuinfo
> processor       : 0
> vendor_id       : GenuineIntel
> cpu family      : 6
> model           : 5
> model name      : Pentium II (Deschutes)
> stepping        : 1
> cpu MHz         : 348.507
> cache size      : 512 KB
> fdiv_bug        : no
> hlt_bug         : no
> f00f_bug        : no
> coma_bug        : no
> fpu             : yes
> fpu_exception   : yes
> cpuid level     : 2
> wp              : yes
> flags           : fpu vme de tsc msr pae mce cx8 apic sep mtrr pge mca 
> cmov pat pse36 mmx fxsr
> bogomips        : 686.08
> 
> 
> The first post said it felt like running PIO, it certainly is using CPU 
> like it as well.
> 
> Now here's some dmesg from this system...
> 
> PIIX4: IDE controller at PCI slot 0000:00:07.1
> PIIX4: chipset revision 1
> PIIX4: not 100% native mode: will probe irqs later
>     ide0: BM-DMA at 0x1080-0x1087, BIOS settings: hda:DMA, hdb:pio
>     ide1: BM-DMA at 0x1088-0x108f, BIOS settings: hdc:DMA, hdd:pio
> Probing IDE interface ide0...
> hda: Maxtor 90845D4, ATA DISK drive
> hdb: WDC AC31600H, ATA DISK drive
> hdb: Disabling (U)DMA for WDC AC31600H (blacklisted)
> ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
> Probing IDE interface ide1...
> hdc: NEC CD-ROM DRIVE:28C, ATAPI CD/DVD-ROM drive
> ide1 at 0x170-0x177,0x376 on irq 15
> hda: max request size: 128KiB
> hda: 16514064 sectors (8455 MB) w/512KiB Cache, CHS=16383/16/63, UDMA(33)
> hda: cache flushes not supported
>  hda: hda1 hda2 hda3 hda4 < hda5 >
> hdb: max request size: 128KiB
> hdb: 3173184 sectors (1624 MB) w/128KiB Cache, CHS=3148/16/63
> hdb: cache flushes not supported
>  hdb: hdb1 hdb2 hdb3
> hdc: ATAPI 32X CD-ROM drive, 128kB Cache, UDMA(33)
> Uniform CD-ROM driver Revision: 3.20
> 
> 
> And indeed it does show hda as dma, and hdb as pio (older versions of 
> the kernel let me set hdb to dma and it worked fine...). But in the 
> posted demsg the BIOS settings show pio for hda. Is this in any way 
> relevant, given that UDA(33) appears later?

I've had AC31600H drive too and it used to run fine in DMA mode for ages 
(at least in Windows). No idea why it is blacklisted.

> 
> Ondrei:
> 
> PIIX4: IDE controller at PCI slot 00:07.1
> PIIX4: chipset revision 1
> PIIX4: not 100% native mode: will probe irqs later
>     ide0: BM-DMA at 0xf000-0xf007, BIOS settings: hda:pio, hdb:pio
>     ide1: BM-DMA at 0xf008-0xf00f, BIOS settings: hdc:pio, hdd:pio
> hda: WDC WD300BB-00AUA1, ATA DISK drive
> blk: queue c03b3360, I/O limit 4095Mb (mask 0xffffffff)
> hdd: MSI CD-RW MS-8340S, ATAPI CD/DVD-ROM drive
> ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
> ide1 at 0x170-0x177,0x376 on irq 15
> hda: attached ide-disk driver.
> hda: host protected area => 1
> hda: 58633344 sectors (30020 MB) w/2048KiB Cache, CHS=3649/255/63, UDMA(33)
> 
> 
> Unless Ondrei's CPU is slower than a PI-350, maybe it is running pio for 
> some reason, in spite of hdparm -i showing udma2 mode.
> 
> I just mentioned it because the CPU usage doesn't seem compatible with 
> DMA operation.
> 
Yes, the CPU is slower. It's Cyrix MII PR300 (225MHz):

root@pentium:/home/rainbow# cat /proc/cpuinfo
processor       : 0
vendor_id       : CyrixInstead
cpu family      : 6
model           : 2
model name      : M II 3x Core/Bus Clock
stepping        : 4
cpu MHz         : 225.004
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 1
wp              : yes
flags           : fpu de tsc msr cx8 pge cmov mmx cyrix_arr
bogomips        : 448.92

With PIO, it's much slower.

-- 
Ondrej Zary

Re: [git patches] IDE update

[Bartlomiej Zolnierkiewicz]

On 7/6/05, Bill Davidsen <davidsen@tmr.com> wrote:
> Ondrej Zary wrote:
> > Jens Axboe wrote:
> >
> >> On Tue, Jul 05 2005, Ondrej Zary wrote:
> >>
> >>> André Tomt wrote:
> >>>
> >>>> Al Boldi wrote:
> >>>>
> >>>>
> >>>>> Bartlomiej Zolnierkiewicz wrote: {
> >>>>>
> >>>>>
> >>>>>>>> On 7/4/05, Al Boldi <a1426z@gawab.com> wrote:
> >>>>>>>> Hdparm -tT gives 38mb/s in 2.4.31
> >>>>>>>> Cat /dev/hda > /dev/null gives 2% user 33% sys 65% idle
> >>>>>>>>
> >>>>>>>> Hdparm -tT gives 28mb/s in 2.6.12
> >>>>>>>> Cat /dev/hda > /dev/null gives 2% user 25% sys 0% idle 73% IOWAIT
> >>>>
> >>>>
> >>>>
> >>>> The "hdparm doesn't get as high scores as in 2.4" is a old discussed
> >>>> to death "problem" on LKML. So far nobody has been able to show it
> >>>> affects anything  but that pretty useless quasi-benchmark.
> >>>>
> >>>
> >>> No, it's not a problem with hdparm. hdparm only shows that there is
> >>> _really_ a problem:
> >>>
> >>> 2.6.12
> >>> root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
> >>> count=1048576
> >>> 1048576+0 records in
> >>> 1048576+0 records out
> >>>
> >>> real    0m32.339s
> >>> user    0m1.500s
> >>> sys     0m14.560s
> >>>
> >>> 2.4.26
> >>> root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=512
> >>> count=1048576
> >>> 1048576+0 records in
> >>> 1048576+0 records out
> >>>
> >>> real    0m23.858s
> >>> user    0m1.750s
> >>> sys     0m15.180s
> >>
> >>
> >>
> >> Perhaps some read-ahead bug. What happens if you use bs=128k for
> >> instance?
> >>
> > Nothing - it's still the same.
> >
> > root@pentium:/home/rainbow# time dd if=/dev/hda of=/dev/null bs=128k
> > count=4096
> > 4096+0 records in
> > 4096+0 records out
> >
> > real    0m32.832s
> > user    0m0.040s
> > sys     0m15.670s
> >
> Why is the system time so high? I tried that test here, and got:
> 
> oddball:root> time dd if=/dev/hda of=/dev/null bs=128k count=4096
> 4096+0 records in
> 4096+0 records out
> 
> real    0m37.927s
> user    0m0.025s
> sys     0m6.547s
> oddball:root> uname -rn
> oddball.prodigy.com 2.6.11ac7
> 
> Now this is one of the slowest CPUs still in use (which I why I test
> responsiveness on it), and it uses far less CPU time.
> cat /proc/cpuinfo
> processor       : 0
> vendor_id       : GenuineIntel
> cpu family      : 6
> model           : 5
> model name      : Pentium II (Deschutes)
> stepping        : 1
> cpu MHz         : 348.507
> cache size      : 512 KB
> fdiv_bug        : no
> hlt_bug         : no
> f00f_bug        : no
> coma_bug        : no
> fpu             : yes
> fpu_exception   : yes
> cpuid level     : 2
> wp              : yes
> flags           : fpu vme de tsc msr pae mce cx8 apic sep mtrr pge mca
> cmov pat pse36 mmx fxsr
> bogomips        : 686.08
> 
> 
> The first post said it felt like running PIO, it certainly is using CPU
> like it as well.
> 
> Now here's some dmesg from this system...
> 
> PIIX4: IDE controller at PCI slot 0000:00:07.1
> PIIX4: chipset revision 1
> PIIX4: not 100% native mode: will probe irqs later
>      ide0: BM-DMA at 0x1080-0x1087, BIOS settings: hda:DMA, hdb:pio
>      ide1: BM-DMA at 0x1088-0x108f, BIOS settings: hdc:DMA, hdd:pio
> Probing IDE interface ide0...
> hda: Maxtor 90845D4, ATA DISK drive
> hdb: WDC AC31600H, ATA DISK drive
> hdb: Disabling (U)DMA for WDC AC31600H (blacklisted)
> ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
> Probing IDE interface ide1...
> hdc: NEC CD-ROM DRIVE:28C, ATAPI CD/DVD-ROM drive
> ide1 at 0x170-0x177,0x376 on irq 15
> hda: max request size: 128KiB
> hda: 16514064 sectors (8455 MB) w/512KiB Cache, CHS=16383/16/63, UDMA(33)
> hda: cache flushes not supported
>   hda: hda1 hda2 hda3 hda4 < hda5 >
> hdb: max request size: 128KiB
> hdb: 3173184 sectors (1624 MB) w/128KiB Cache, CHS=3148/16/63
> hdb: cache flushes not supported
>   hdb: hdb1 hdb2 hdb3
> hdc: ATAPI 32X CD-ROM drive, 128kB Cache, UDMA(33)
> Uniform CD-ROM driver Revision: 3.20
> 
> 
> And indeed it does show hda as dma, and hdb as pio (older versions of
> the kernel let me set hdb to dma and it worked fine...). But in the
> posted demsg the BIOS settings show pio for hda. Is this in any way
> relevant, given that UDA(33) appears later?

BIOS setting is irrelevant and ~14MB/s for UDMA33 is OK.
CPU cycles are wasted somewhere else...

Re: [git patches] IDE update

[Bill Davidsen]

Bartlomiej Zolnierkiewicz wrote:

> BIOS setting is irrelevant and ~14MB/s for UDMA33 is OK.
> CPU cycles are wasted somewhere else...

After seeing how poorly Linux copes with bad info coming out of ACPI, I 
no longer assume that BIOS information is ignored. Thought it was worth 
mentioning.

-- 
    -bill davidsen (davidsen@tmr.com)
"The secret to procrastination is to put things off until the
  last possible moment - but no longer"  -me

Re: [git patches] IDE update

[Jeff Garzik]

Bartlomiej Zolnierkiewicz wrote:
> 
> Hi,
> 
> Please pull from:
> rsync://rsync.kernel.org/pub/scm/linux/kernel/git/bart/ide-2.6.git
> 
> diffstat+changelog below
> 
> Bartlomiej
> 
> 
>  drivers/ide/Makefile        |    1 -
>  drivers/ide/ide-lib.c       |   13 +++++--------
>  drivers/ide/pci/alim15x3.c  |   10 +++++-----
>  drivers/ide/pci/amd74xx.c   |    7 +++++--
>  drivers/ide/pci/cs5530.c    |    4 ++--
>  drivers/ide/pci/cy82c693.c  |    8 ++++----
>  drivers/ide/pci/it8172.c    |    4 ++--
>  drivers/ide/pci/ns87415.c   |    2 +-
>  drivers/ide/pci/opti621.c   |    2 +-
>  drivers/ide/pci/sc1200.c    |    2 +-
>  drivers/ide/pci/sl82c105.c  |    6 +++---
>  drivers/ide/pci/slc90e66.c  |    2 +-
>  drivers/ide/pci/triflex.c   |    2 +-
>  drivers/ide/pci/via82cxxx.c |    4 ++--
>  include/linux/pci_ids.h     |    1 +
>  15 files changed, 34 insertions(+), 34 deletions(-)

FWIW, we should encourage the janitors to submit patches larger than 
simply one patch per file.  Spreading the -same- logical change across 
multiple patches is really taking the "split it up" mantra too far.

We want logical changes separated...  but this just spams the log IMO.

All of the __devinit changes could have been rolled into a single patch, 
since its going to a single maintainer (Bart).

	Jeff