Date: Thu, 14 Dec 2006 14:37:31 +0000 From: Dieter <freebsd@sopwith.solgatos.com> To: freebsd-questions@freebsd.org Subject: Re: processes not getting fair share of available disk I/O Message-ID: <200612142237.WAA00195@sopwith.solgatos.com> In-Reply-To: Your message of "Thu, 14 Dec 2006 13:25:17 EST." <20061214182517.GA94080@xor.obsecurity.org>
next in thread | previous in thread | raw e-mail | index | archive | help
> Sorry, yes. Nothing else contended for it though, so it doesn't
> appear to be a source of performance problems - it is probably a
> secondary effect from something else. I guess you're running some old
> version of FreeBSD since those line numbers don't correspond to
> anything reasonable in the current 6.x source, so I dunno what
> exactly.
FreeBSD 6.0
> > > The rest looks fine at a quick glance too.
> >=20
> > What should I be looking for? Do I need to collect stats for a long
> > period of time, or is a few seconds enough? Dd can kill the transfer
> > in about 3 seconds.
>
> You need to make sure your sampling while the system is in the bad
> state.
>
> A mutex that has a lot of acquisitions and a lot of contention for
> those acquisitions is a performance bottleneck. Nothing below falls
> into that class - in particular it's definitely not Giant causing
> performance loss to the filesystem.
Aren't the numbers (other than max and avg) going to depend a lot on how
long I collect data? Are you looking for one or two locks that have
contention a couple orders of magnitude higher than everything else?
> Still looks like it's a driver and/or hardware problem, but you'd need
> specialized knowledge to proceed with debugging it.
Maybe I didn't beat on it hard enough. Data below is with two processes
reading data from Ethernet and writing to disk. (common Ethernet, different
disks) and a loop with 3 copies of dd writing from /dev/zero to disks,
and then 3 copies of dd reading the files back and writing to /dev/null.
This ground away for a few minutes.
Writing
5 users Load 2.47 1.73 0.90 Dec 14 13:17
Mem:KB REAL VIRTUAL VN PAGER SWAP PAGER
Tot Share Tot Share Free in out in out
Act 868496 3520 893416 7564 176776 count
All 1835548 3856 1622626k 8056 pages
zfod Interrupts
Proc:r p d s w Csw Trp Sys Int Sof Flt cow 4582 total
4 44 13796 4 205713128 13 676116 wire 998 0: clk
449292 act 1: atkb
32.3%Sys 31.5%Intr 0.0%User 0.0%Nice 36.2%Idl 710892 inact 32 3: sio1
| | | | | | | | | | 4024 cache 4: sio0
================++++++++++++++++ 172752 free 7: ppc0
daefr stray 7
Namei Name-cache Dir-cache prcfr 128 8: rtc
Calls hits % hits % react 79 10: ohc
pdwak 3251 11: fwo
pdpgs 14: ata
Disks ad2 ad4 ad6 ad8 ad10 da0 cd0 intrn 94 15: ata
KB/t 128 0.00 128 128 128 128 0.00 218608 buf
tps 47 0 39 37 12 8 0 24 dirtybuf
MB/s 5.84 0.00 4.87 4.63 1.46 0.97 0.00 100000 desiredvnodes
% busy 91 0 78 69 19 8 0 917 numvnodes
522 freevnodes
Reading
5 users Load 1.38 1.59 0.91 Dec 14 13:18
Mem:KB REAL VIRTUAL VN PAGER SWAP PAGER
Tot Share Tot Share Free in out in out
Act 868496 3520 893416 7564 61148 count
All 2007260 3856 1623531k 8056 pages
zfod Interrupts
Proc:r p d s w Csw Trp Sys Int Sof Flt cow 4878 total
3 45 15319 5 199813154 37 675864 wire 1002 0: clk
449312 act 1: atkb
74.8%Sys 25.2%Intr 0.0%User 0.0%Nice 0.0%Idl 828676 inact 36 3: sio1
| | | | | | | | | | 58184 cache 4: sio0
=====================================+++++++++++ 2964 free 7: ppc0
daefr stray 7
Namei Name-cache Dir-cache prcfr 128 8: rtc
Calls hits % hits % 313 react 253 10: ohc
pdwak 3307 11: fwo
pdpgs 14: ata
Disks ad2 ad4 ad6 ad8 ad10 da0 cd0 intrn 152 15: ata
KB/t 112 0.00 105 99.66 128 128 0.00 218400 buf
tps 87 0 154 171 10 7 0 11 dirtybuf
MB/s 9.52 0.00 15.81 16.64 1.22 0.85 0.00 100000 desiredvnodes
% busy 14 0 45 37 17 7 0 917 numvnodes
522 freevnodes
interrupt total rate
irq0: clk 5582359 999
irq1: atkbd0 2 0
irq3: sio1 96973 17
irq4: sio0 702 0
irq7: ppc0 65 0
stray irq7 1 0
irq8: rtc 714413 127
irq10: ohci0 ohci1+ 154972 27
irq11: fwohci0 bge* 3104534 556
irq14: ata0 57 0
irq15: ata1 109476 19
Total 9763554 1748
Mutex stats sorted by each column after grepping out lines with 0 for both
cnt_hold and cnt_lock:
max total count avg cnt_hold cnt_lock name
777739 1228310 104279 11 493 22 /usr/src/sys/amd64/amd64/pmap.c:1562 (vm page queue mutex)
114852 371203 93626 3 205 1 /usr/src/sys/kern/vfs_cluster.c:387 (vnode interlock)
112622 271200 44 6163 41 0 /usr/src/sys/vm/vm_pageout.c:717 (Giant)
101485 1566968 3306 473 201 2 /usr/src/sys/kern/kern_synch.c:236 (Giant)
53150 9174512 3555905 2 432 103 /usr/src/sys/kern/kern_lock.c:168 (lockbuilder mtxpool)
53150 2562700 676529 3 448 92 /usr/src/sys/kern/vfs_vnops.c:799 (vnode interlock)
39794 5458189 712768 7 215 0 /usr/src/sys/kern/vfs_bio.c:3364 (vm object)
36998 1149211 146203 7 0 2 /usr/src/sys/vm/vm_fault.c:295 (vm object)
28823 4952110 2239392 2 175 277 /usr/src/sys/kern/kern_lock.c:570 (lockbuilder mtxpool)
27277 2278961 183643 12 646 2494 /usr/src/sys/kern/vfs_bio.c:3082 (vm object)
209 20679080 434199 47 0 1676 /usr/src/sys/netinet/tcp_input.c:742 (inp)
330 16173519 2794378 5 3428 4416 /usr/src/sys/kern/kern_intr.c:546 (Giant)
53150 9174512 3555905 2 432 103 /usr/src/sys/kern/kern_lock.c:168 (lockbuilder mtxpool)
23947 7735265 1626257 4 143 35 /usr/src/sys/sys/buf.h:292 (lockbuilder mtxpool)
21112 6948480 1789668 3 1902 12 /usr/src/sys/kern/vfs_bio.c:2350 (vnode interlock)
5427 5478084 1379072 3 5190 7504 /usr/src/sys/kern/vfs_bio.c:1397 (buf queue lock)
39794 5458189 712768 7 215 0 /usr/src/sys/kern/vfs_bio.c:3364 (vm object)
9131 5161862 866362 5 2644 0 /usr/src/sys/netinet/tcp_usrreq.c:598 (tcp)
28823 4952110 2239392 2 175 277 /usr/src/sys/kern/kern_lock.c:570 (lockbuilder mtxpool)
53150 9174512 3555905 2 432 103 /usr/src/sys/kern/kern_lock.c:168 (lockbuilder mtxpool)
330 16173519 2794378 5 3428 4416 /usr/src/sys/kern/kern_intr.c:546 (Giant)
28823 4952110 2239392 2 175 277 /usr/src/sys/kern/kern_lock.c:570 (lockbuilder mtxpool)
29 2928936 1830950 1 0 982 /usr/src/sys/kern/subr_taskqueue.c:158 (taskqueue)
68 2840022 1825301 1 596 0 /usr/src/sys/kern/subr_taskqueue.c:219 (taskqueue)
21112 6948480 1789668 3 1902 12 /usr/src/sys/kern/vfs_bio.c:2350 (vnode interlock)
23947 7735265 1626257 4 143 35 /usr/src/sys/sys/buf.h:292 (lockbuilder mtxpool)
17719 2988611 1622737 1 2 1 /usr/src/sys/kern/kern_descrip.c:2100 (sleep mtxpool)
3107 2595890 1400092 1 2082 120 /usr/src/sys/kern/vfs_bio.c:309 (needsbuffer lock)
5427 5478084 1379072 3 5190 7504 /usr/src/sys/kern/vfs_bio.c:1397 (buf queue lock)
21503 54061 5 10812 4 0 /usr/src/sys/kern/vfs_syscalls.c:124 (Giant)
112622 271200 44 6163 41 0 /usr/src/sys/vm/vm_pageout.c:717 (Giant)
10000 32387 12 2698 2 0 /usr/src/sys/kern/kern_condvar.c:134 (Giant)
101485 1566968 3306 473 201 2 /usr/src/sys/kern/kern_synch.c:236 (Giant)
3967 6848 19 360 6 0 /usr/src/sys/kern/uipc_usrreq.c:932 (Giant)
24665 213993 771 277 14 2 /usr/src/sys/amd64/amd64/pmap.c:2481 (vm page queue mutex)
382 8658 35 247 1 0 /usr/src/sys/kern/kern_linker.c:1044 (Giant)
241 19374 111 174 19 0 /usr/src/sys/fs/devfs/devfs_vnops.c:285 (Giant)
158 5632 54 104 1 0 /usr/src/sys/netinet/tcp_usrreq.c:367 (inp)
9599 1452414 16256 89 660 2 /usr/src/sys/kern/kern_sysctl.c:1280 (Giant)
5427 5478084 1379072 3 5190 7504 /usr/src/sys/kern/vfs_bio.c:1397 (buf queue lock)
9881 3243923 344723 9 3513 798 /usr/src/sys/kern/vfs_bio.c:1665 (buf queue lock)
330 16173519 2794378 5 3428 4416 /usr/src/sys/kern/kern_intr.c:546 (Giant)
9131 5161862 866362 5 2644 0 /usr/src/sys/netinet/tcp_usrreq.c:598 (tcp)
3107 2595890 1400092 1 2082 120 /usr/src/sys/kern/vfs_bio.c:309 (needsbuffer lock)
21112 6948480 1789668 3 1902 12 /usr/src/sys/kern/vfs_bio.c:2350 (vnode interlock)
3322 1550577 816324 1 1842 3565 /usr/src/sys/kern/vfs_bio.c:351 (needsbuffer lock)
12965 4489813 201822 22 1417 216 /usr/src/sys/kern/vfs_bio.c:2756 (vm object)
12720 1470457 393778 3 1379 59 /usr/src/sys/vm/vm_page.c:805 (vm page queue mutex)
2293 1211654 636673 1 756 475 /usr/src/sys/kern/vfs_bio.c:1297 (buf queue lock)
9599 1452414 16256 89 660 2 /usr/src/sys/kern/kern_sysctl.c:1280 (Giant)
27277 2278961 183643 12 646 2494 /usr/src/sys/kern/vfs_bio.c:3082 (vm object)
10570 2016434 957652 2 604 616 /usr/src/sys/geom/geom_io.c:67 (bio queue)
68 2840022 1825301 1 596 0 /usr/src/sys/kern/subr_taskqueue.c:219 (taskqueue)
8107 1694351 179893 9 557 703 /usr/src/sys/kern/vfs_bio.c:1456 (vm object)
9295 895983 433202 2 532 0 /usr/src/sys/kern/uipc_socket.c:1255 (so_rcv)
10185 1503986 59111 25 525 0 /usr/src/sys/kern/vfs_cluster.c:133 (vnode interlock)
8449 774938 433203 1 498 0 /usr/src/sys/kern/uipc_socket.c:1011 (so_rcv)
777739 1228310 104279 11 493 22 /usr/src/sys/amd64/amd64/pmap.c:1562 (vm page queue mutex)
53150 2562700 676529 3 448 92 /usr/src/sys/kern/vfs_vnops.c:799 (vnode interlock)
5427 5478084 1379072 3 5190 7504 /usr/src/sys/kern/vfs_bio.c:1397 (buf queue lock)
330 16173519 2794378 5 3428 4416 /usr/src/sys/kern/kern_intr.c:546 (Giant)
3322 1550577 816324 1 1842 3565 /usr/src/sys/kern/vfs_bio.c:351 (needsbuffer lock)
1022 1140950 634114 1 251 2963 /usr/src/sys/kern/vfs_bio.c:1413 (vnode interlock)
27277 2278961 183643 12 646 2494 /usr/src/sys/kern/vfs_bio.c:3082 (vm object)
445 561708 183643 3 14 2218 /usr/src/sys/kern/vfs_bio.c:3101 (vm page queue mutex)
209 20679080 434199 47 0 1676 /usr/src/sys/netinet/tcp_input.c:742 (inp)
109 2146035 432575 4 0 1655 /usr/src/sys/netinet/tcp_input.c:1280 (so_rcv)
29 2928936 1830950 1 0 982 /usr/src/sys/kern/subr_taskqueue.c:158 (taskqueue)
153 1522915 434200 3 0 887 /usr/src/sys/netinet/tcp_input.c:615 (tcp)
9881 3243923 344723 9 3513 798 /usr/src/sys/kern/vfs_bio.c:1665 (buf queue lock)
8107 1694351 179893 9 557 703 /usr/src/sys/kern/vfs_bio.c:1456 (vm object)
10570 2016434 957652 2 604 616 /usr/src/sys/geom/geom_io.c:67 (bio queue)
3002 618696 185831 3 294 600 /usr/src/sys/kern/vfs_bio.c:1905 (system map)
51 194792 58564 3 414 598 /usr/src/sys/kern/kern_timeout.c:258 (Giant)
356 101934 58584 1 9 570 /usr/src/sys/vm/vm_pager.c:463 (vnode interlock)
2293 1211654 636673 1 756 475 /usr/src/sys/kern/vfs_bio.c:1297 (buf queue lock)
5259 1545316 576373 2 75 421 /usr/src/sys/sys/buf.h:272 (lockbuilder mtxpool)
141 1947944 919505 2 0 393 /usr/src/sys/dev/bge/if_bge.c:2916 (bge0)
116 160008 91419 1 167 303 /usr/src/sys/netinet/tcp_subr.c:1404 (tcp)
and "dev"
141 1947944 919505 2 0 393 /usr/src/sys/dev/bge/if_bge.c:2916 (bge0)
125 382918 95532 4 0 95 /usr/src/sys/dev/ata/ata-all.c:327 (ATA state lock)
50 1318021 869962 1 0 77 /usr/src/sys/dev/bge/if_bge.c:3245 (bge0)
756 2652763 191065 13 27 25 /usr/src/sys/dev/ata/ata-queue.c:168 (ATA queue lock)
10088 2005842 1038913 1 18 18 /usr/src/sys/kern/kern_conf.c:62 (cdev)
392 190336 95533 1 2 4 /usr/src/sys/dev/ata/ata-queue.c:80 (ATA queue lock)
752 1886893 164765 11 91 0 /usr/src/sys/dev/ata/ata-queue.c:185 (ATA state lock)
241 19374 111 174 19 0 /usr/src/sys/fs/devfs/devfs_vnops.c:285 (Giant)
112 52387 915 57 46 0 /usr/src/sys/dev/bge/if_bge.c:3088 (bge0)
62 4436750 434942 10 341 0 /usr/src/sys/dev/bge/if_bge.c:3321 (bge0)
debug.mutex.prof.reset: 0
debug.mutex.prof.stats:
debug.mutex.prof.collisions: 467
debug.mutex.prof.hashsize: 1009
debug.mutex.prof.rejected: 0
debug.mutex.prof.maxrecords: 1000
debug.mutex.prof.records: 1815
debug.mutex.prof.acquisitions: 235953337
debug.mutex.prof.enable: 1
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200612142237.WAA00195>