From owner-freebsd-questions@FreeBSD.ORG Thu Dec 14 22:45:22 2006 Return-Path: X-Original-To: freebsd-questions@freebsd.org Delivered-To: freebsd-questions@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [69.147.83.52]) by hub.freebsd.org (Postfix) with ESMTP id 8922216A944 for ; Thu, 14 Dec 2006 22:45:22 +0000 (UTC) (envelope-from freebsd@sopwith.solgatos.com) Received: from schitzo.solgatos.com (pool-71-245-104-192.ptldor.fios.verizon.net [71.245.104.192]) by mx1.FreeBSD.org (Postfix) with ESMTP id 70E2543E3B for ; Thu, 14 Dec 2006 22:40:20 +0000 (GMT) (envelope-from freebsd@sopwith.solgatos.com) Received: from schitzo.solgatos.com (localhost.home.localnet [127.0.0.1]) by schitzo.solgatos.com (8.13.8/8.13.6) with ESMTP id kBEMfSuM013422 for ; Thu, 14 Dec 2006 14:41:29 -0800 Received: from sopwith.solgatos.com (uucp@localhost) by schitzo.solgatos.com (8.13.8/8.13.4/Submit) with UUCP id kBEMfSlE013405 for freebsd-questions@freebsd.org; Thu, 14 Dec 2006 14:41:28 -0800 Received: from localhost by sopwith.solgatos.com (8.8.8/6.24) id WAA00195; Thu, 14 Dec 2006 22:37:31 GMT Message-Id: <200612142237.WAA00195@sopwith.solgatos.com> To: freebsd-questions@freebsd.org In-reply-to: Your message of "Thu, 14 Dec 2006 13:25:17 EST." <20061214182517.GA94080@xor.obsecurity.org> Date: Thu, 14 Dec 2006 14:37:31 +0000 From: Dieter Subject: Re: processes not getting fair share of available disk I/O X-BeenThere: freebsd-questions@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: User questions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 14 Dec 2006 22:45:22 -0000 > 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