Bug 34016

Summary:	AIO is 400x slower under -CURRENT
Product:	Base System	Reporter:	Kip Macy <kip>
Component:	kern	Assignee:	freebsd-bugs (Nobody) <bugs>
Status:	Closed FIXED
Severity:	Affects Only Me
Priority:	Normal
Version:	Unspecified
Hardware:	Any
OS:	Any

Description Kip Macy 2002-01-18 06:00:00 UTC

      I wrote a simple program that uses
the three different completion mechanisms (polling
with aio_error, polling with kevent, and using SIGIO)
to fill up a file by writing 8kb at a time to the 
file and then reading 8kb at a time from the file.

The lower the average latency, the more frequently 
it can send off a new request and the more quickly
it can complete.

It can be found at:
http://www.eventdriven.org/aio_lat_test.tgz

Don't try using the aiotest_sigio (on FreeBSD), the 
siginfo_t doesn't get filled. Yet another PR that I 
have to file.

Here are the results (in ms):
10 32MB files 

4-way Sun server over NFS
Memory: 4096M real, 924M free, 768M swap in use, 7234M
swap free
> uname -a
SunOS orbit 5.8 Generic_108528-11 sun4u sparc
SUNW,Ultra-Enterprise

> ./aiotest_sigio 
write sk_msecs: 112350 max_latency: 560
reads sk_msecs: 119670 max_latency: 780
> ./aiotest_aio_error 
write sk_msecs: 45570 max_latency: 240
reads sk_msecs: 48280 max_latency: 630
> ./aiotest_sigio
write sk_msecs: 117260 max_latency: 410
reads sk_msecs: 124100 max_latency: 600
> ./aiotest_aio_error
write sk_msecs: 45050 max_latency: 780
reads sk_msecs: 46550 max_latency: 1530

10 32MB files

600Mhz Laptop local disk UDMA33

Mem: 68M Active, 134M Inact, 30M Wired, 15M Cache, 35M
Buf, 656K Free
kmacy@netherworld [15:20][~/src/bugs] uname -a
FreeBSD netherworld.eventdriven.org 4.5-RC FreeBSD
4.5-RC #1: Wed Jan 16 21:30:55 PST 2002    
root@netherworld.e
ventdriven.org:/usr/src/sys/compile/NETHERWORLD  i386
kmacy@netherworld [15:08][~/src/bugs/aio]
./aiotest_aio_error 
write sk_msecs: 72890 max_latency: 930
reads sk_msecs: 56830 max_latency: 930
kmacy@netherworld [15:11][~/src/bugs/aio]
./aiotest_kevent 
write sk_msecs: 71300 max_latency: 1380
reads sk_msecs: 54500 max_latency: 1380
kmacy@netherworld [15:14][~/src/bugs/aio]
./aiotest_aio_error
write sk_msecs: 73970 max_latency: 990
reads sk_msecs: 56790 max_latency: 990
kmacy@netherworld [15:17][~/src/bugs/aio]
./aiotest_kevent
write sk_msecs: 73620 max_latency: 980
reads sk_msecs: 59620 max_latency: 1860

2-way 1.0GHZ
FreeBSD weizen.extendedsolutions.com
5.0-20020106-CURRENT FreeBSD 5.0-20020106-CURRENT #3:
Thu Jan 10 18:58:36 PS
T 2002    
root@weizen.extendedsolutions.com:/usr/src/sys/i386/compile/HADES
 i386
Mem: 11M Active, 188M Inact, 111M Wired, 1760K Cache,
111M Buf, 691M Free

(~420x slower)


(~420x slower)
10 1MB files local disk (UDMA33)
> aiotest_aio_error 
write sk_msecs: 959540 max_latency: 29960
reads sk_msecs: 959970 max_latency: 29960

Same machine compiled UP:

> aiotest_aio_error 
write sk_msecs: 810010 max_latency: 29960
reads sk_msecs: 779950 max_latency: 29960
> uname -a
FreeBSD weizen.extendedsolutions.com
5.0-20020106-CURRENT FreeBSD 5.0-20020106-CURRENT #0:
Thu Jan 17 15:36:56 PS
T 2002    
root@weizen.extendedsolutions.com:/usr/src/sys/i386/compile/HADES_UP
 i386

I wrote a simple program that uses
the three different completion mechanisms (polling
with aio_error, polling with kevent, and using SIGIO)
to fill up a file by writing 8kb at a time to the 
file and then reading 8kb at a time from the file.

The lower the average latency, the more frequently 
it can send off a new request.

It can be found at:
http://www.eventdriven.org/aio_lat_test.tgz

Don't try using the aiotest_sigio (on FreeBSD), the 
siginfo_t doesn't get filled. Yet another PR that I 
have to file.

Here are the results (in ms):
10 32MB files 

4-way Sun server over NFS
Memory: 4096M real, 924M free, 768M swap in use, 7234M
swap free
> uname -a
SunOS orbit 5.8 Generic_108528-11 sun4u sparc
SUNW,Ultra-Enterprise

> ./aiotest_sigio 
write sk_msecs: 112350 max_latency: 560
reads sk_msecs: 119670 max_latency: 780
> ./aiotest_aio_error 
write sk_msecs: 45570 max_latency: 240
reads sk_msecs: 48280 max_latency: 630
> ./aiotest_sigio
write sk_msecs: 117260 max_latency: 410
reads sk_msecs: 124100 max_latency: 600
> ./aiotest_aio_error
write sk_msecs: 45050 max_latency: 780
reads sk_msecs: 46550 max_latency: 1530

10 32MB files

600Mhz Laptop local disk UDMA33

Mem: 68M Active, 134M Inact, 30M Wired, 15M Cache, 35M
Buf, 656K Free
kmacy@netherworld [15:20][~/src/bugs] uname -a
FreeBSD netherworld.eventdriven.org 4.5-RC FreeBSD
4.5-RC #1: Wed Jan 16 21:30:55 PST 2002    
root@netherworld.e
ventdriven.org:/usr/src/sys/compile/NETHERWORLD  i386
kmacy@netherworld [15:08][~/src/bugs/aio]
./aiotest_aio_error 
write sk_msecs: 72890 max_latency: 930
reads sk_msecs: 56830 max_latency: 930
kmacy@netherworld [15:11][~/src/bugs/aio]
./aiotest_kevent 
write sk_msecs: 71300 max_latency: 1380
reads sk_msecs: 54500 max_latency: 1380
kmacy@netherworld [15:14][~/src/bugs/aio]
./aiotest_aio_error
write sk_msecs: 73970 max_latency: 990
reads sk_msecs: 56790 max_latency: 990
kmacy@netherworld [15:17][~/src/bugs/aio]
./aiotest_kevent
write sk_msecs: 73620 max_latency: 980
reads sk_msecs: 59620 max_latency: 1860

2-way 1.0GHZ
FreeBSD weizen.extendedsolutions.com
5.0-20020106-CURRENT FreeBSD 5.0-20020106-CURRENT #3:
Thu Jan 10 18:58:36 PS
T 2002    
root@weizen.extendedsolutions.com:/usr/src/sys/i386/compile/HADES
 i386
Mem: 11M Active, 188M Inact, 111M Wired, 1760K Cache,
111M Buf, 691M Free

(~420x slower)


(~420x slower)
10 1MB files local disk (UDMA33)
> aiotest_aio_error 
write sk_msecs: 959540 max_latency: 29960
reads sk_msecs: 959970 max_latency: 29960

Same machine compiled UP:

> aiotest_aio_error 
write sk_msecs: 810010 max_latency: 29960
reads sk_msecs: 779950 max_latency: 29960
> uname -a
FreeBSD weizen.extendedsolutions.com
5.0-20020106-CURRENT FreeBSD 5.0-20020106-CURRENT #0:
Thu Jan 17 15:36:56 PS
T 2002    
root@weizen.extendedsolutions.com:/usr/src/sys/i386/compile/HADES_UP
 i386

How-To-Repeat: run aiotest_aio_error and aiotest_kevent by compiling the
source from:
http://www.eventdriven.org/aio_lat_test.tgz

Comment 1 Alan Cox freebsd_committer

2002-02-03 19:25:33 UTC

State Changed
From-To: open->closed

Fixed in revision 1.112 of kern/vfs_aio.c.