From owner-freebsd-questions@FreeBSD.ORG Thu Dec 14 17:27:47 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 3674C16A4A0 for ; Thu, 14 Dec 2006 17:27:47 +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 5DE4143E4C for ; Thu, 14 Dec 2006 17:07:54 +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 kBEH9Rcs010039 for ; Thu, 14 Dec 2006 09:09:27 -0800 Received: from sopwith.solgatos.com (uucp@localhost) by schitzo.solgatos.com (8.13.8/8.13.4/Submit) with UUCP id kBEH9RY3010036 for freebsd-questions@freebsd.org; Thu, 14 Dec 2006 09:09:27 -0800 Received: from localhost by sopwith.solgatos.com (8.8.8/6.24) id RAA26563; Thu, 14 Dec 2006 17:07:35 GMT Message-Id: <200612141707.RAA26563@sopwith.solgatos.com> To: freebsd-questions@freebsd.org In-reply-to: Your message of "Thu, 14 Dec 2006 02:41:33 EST." <20061214074133.GA67465@xor.obsecurity.org> Date: Thu, 14 Dec 2006 09:07:35 +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 17:27:47 -0000 > > > Mutex profiling would show if there is a mutex somehow getting in the > > > way of your I/O (e.g. if Giant is somehow being forced). I dont think > > > it would show anything though. You can try to study interrupt issues > > > (e.g. look for an interrupt storm during I/O) with vmstat -i. Other > > > than that you'd probably have to get your hands dirtier in the code. > >=20 > > max total count avg cnt_hold cnt_lock name > > 1158725 1185330 1596 742 0 0 /usr/src= > /sys/amd64/amd64/pmap.c:1563 (pmap) > > 1158721 1166593 1596 730 1 17 /usr/src= > /sys/amd64/amd64/pmap.c:1562 (vm page queue mutex) > > 90598 578551 199304 2 3 4 /usr/src/= > sys/kern/kern_sx.c:157 (lockbuilder mtxpool) > > 83234 967612 124000 7 0 0 /usr/src/= > sys/vm/vm_fault.c:906 (vm object) > > If I'm reading the man page right, pmap holds a lock for over 1 second? > > In total, over 1600 operations. It's not an issue. The man page says: max The longest continuous hold time in microseconds. Which together with the total number, would imply 1 time it took 1.158725 seconds, and the other 1595 times averaged 16.7 usec, which seems unlikely. Am I misinterpreting the man page? > The rest looks fine at a quick glance too. 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. Here are stats with the Ethernet->disk program competing with dd from /dev/zero to a file, sorted by cnt_hold and by cnt_lock. max total count avg cnt_hold cnt_lock name 89 6095988 1089530 5 536 979 /usr/src/sys/kern/kern_intr.c:546 (Giant) 2649 1950594 360310 5 449 0 /usr/src/sys/netinet/tcp_usrreq.c:598 (tcp) 13553 2348809 23610 99 350 2 /usr/src/sys/kern/kern_sysctl.c:1280 (Giant) 36 230008 85274 2 141 241 /usr/src/sys/kern/kern_timeout.c:258 (Giant) 453 300251 180186 1 89 0 /usr/src/sys/kern/uipc_socket.c:1011 (so_rcv) 199878 2351641 4706 499 88 4 /usr/src/sys/kern/kern_synch.c:236 (Giant) 2138 337086 180186 1 85 0 /usr/src/sys/kern/uipc_socket.c:1255 (so_rcv) 67 1120044 722561 1 83 0 /usr/src/sys/kern/subr_taskqueue.c:219 (taskqueue) 57 219660 134214 1 70 102 /usr/src/sys/netinet/tcp_subr.c:1404 (tcp) 73 1830084 180344 10 65 0 /usr/src/sys/dev/bge/if_bge.c:3321 (bge0) 472 272697 180155 1 63 0 /usr/src/sys/kern/uipc_socket.c:1401 (so_rcv) 77 541532 361447 1 48 0 /usr/src/sys/kern/subr_taskqueue.c:204 (taskqueue) 5198 26977 244 110 26 1 /usr/src/sys/kern/kern_exit.c:233 (Giant) 50 545822 361062 1 26 0 /usr/src/sys/net/netisr.c:233 (ip_inq) 1649 287241 102509 2 24 30 /usr/src/sys/kern/vfs_bio.c:1397 (buf queue lock) 20981 212022 9317 22 19 2 /usr/src/sys/vm/vm_fault.c:683 (vm object) 65 26162 3656 7 18 4 /usr/src/sys/kern/kern_conf.c:324 (Giant) 7546 218853 412 531 17 1 /usr/src/sys/amd64/amd64/pmap.c:2481 (vm page queue mutex) 110 13982 244 57 17 0 /usr/src/sys/kern/kern_exit.c:385 (Giant) 491 278319 170512 1 16 2 /usr/src/sys/kern/kern_synch.c:238 (process lock) 52 27355 2279 12 16 9 /usr/src/sys/net/netisr.c:339 (Giant) 576 27530 1379 19 15 5307 /usr/src/sys/kern/kern_conf.c:312 (Giant) 75 75460 1344 56 15 0 /usr/src/sys/dev/bge/if_bge.c:3088 (bge0) 3903 49655 11221 4 11 9 /usr/src/sys/vm/vnode_pager.c:1169 (vm object) 658 88609 48732 1 11 4 /usr/src/sys/kern/vfs_bio.c:309 (needsbuffer lock) 182 198222 127109 1 11 4 /usr/src/sys/vm/vm_fault.c:907 (vm page queue mutex) 5883 382321 103647 3 10 0 /usr/src/sys/kern/vfs_bio.c:2350 (vnode interlock) 273 34597 19322 1 9 4 /usr/src/sys/kern/vfs_bio.c:1297 (buf queue lock) 82 275004 180344 1 9 1 /usr/src/sys/net/if_ethersubr.c:408 (bge0) 576 206209 67474 3 8 22 /usr/src/sys/kern/vfs_bio.c:3365 (vm page queue mutex) max total count avg cnt_hold cnt_lock name 576 27530 1379 19 15 5307 /usr/src/sys/kern/kern_conf.c:312 (Giant) 89 6095988 1089530 5 536 979 /usr/src/sys/kern/kern_intr.c:546 (Giant) 478 192375 123859 1 8 827 /usr/src/sys/vm/vm_fault.c:849 (vm page queue mutex) 155 759634 362384 2 0 427 /usr/src/sys/dev/bge/if_bge.c:2916 (bge0) 58 955483 180013 5 0 257 /usr/src/sys/netinet/tcp_input.c:1280 (so_rcv) 145 8595737 180735 47 0 250 /usr/src/sys/netinet/tcp_input.c:742 (inp) 36 230008 85274 2 141 241 /usr/src/sys/kern/kern_timeout.c:258 (Giant) 615 60464 5683 10 0 187 /usr/src/sys/kern/vfs_bio.c:1456 (vm object) 149 618529 180736 3 0 183 /usr/src/sys/netinet/tcp_input.c:615 (tcp) 29 1155402 723611 1 0 139 /usr/src/sys/kern/subr_taskqueue.c:158 (taskqueue) 57 219660 134214 1 70 102 /usr/src/sys/netinet/tcp_subr.c:1404 (tcp) 54 5116 667 7 0 94 /usr/src/sys/netinet/tcp_usrreq.c:629 (tcp) 499 149258 17011 8 1 49 /usr/src/sys/kern/vfs_bio.c:1665 (buf queue lock) 47 259969 169782 1 0 33 /usr/src/sys/kern/sys_generic.c:1140 (sellck) 36 456802 302786 1 0 31 /usr/src/sys/kern/vfs_subr.c:2814 (vnode interlock) 1649 287241 102509 2 24 30 /usr/src/sys/kern/vfs_bio.c:1397 (buf queue lock) 205 24243 14011 1 6 26 /usr/src/sys/vm/vm_fault.c:344 (vm page queue mutex) 24 276097 180742 1 0 26 /usr/src/sys/net/if.c:2236 (ip_inq) 2811 29673 10778 2 0 25 /usr/src/sys/vm/vm_map.c:2193 (vm object) 576 206209 67474 3 8 22 /usr/src/sys/kern/vfs_bio.c:3365 (vm page queue mutex) 7564 120517 16144 7 4 21 /usr/src/sys/kern/vfs_bio.c:3082 (vm object) 295 40504 22674 1 3 18 /usr/src/sys/kern/vfs_bio.c:1413 (vnode interlock) 276 33918 16144 2 1 14 /usr/src/sys/kern/vfs_bio.c:3101 (vm page queue mutex) 2054 31157 15635 1 4 12 /usr/src/sys/kern/vfs_subr.c:1983 (vnode interlock) 48 1846 883 2 0 12 /usr/src/sys/ufs/ffs/ffs_softdep.c:4724 (Softdep Lock) 661 33248 9645 3 2 11 /usr/src/sys/kern/vfs_cache.c:356 (Name Cache) 563 7078 3920 1 3 11 /usr/src/sys/vm/vm_object.c:1194 (vm object) 274 42309 24962 1 3 10 /usr/src/sys/kern/vfs_bio.c:351 (needsbuffer lock) 27 544145 360697 1 0 10 /usr/src/sys/dev/bge/if_bge.c:3245 (bge0) 3903 49655 11221 4 11 9 /usr/src/sys/vm/vnode_pager.c:1169 (vm object) And all the stats for dev max total count avg cnt_hold cnt_lock name 528 249014 156914 1 0 0 /usr/src/sys/dev/acpica/Osd/OsdSynch.c:301 (ACPI semaphore) 503 151513 10773 14 0 0 /usr/src/sys/dev/ata/ata-queue.c:168 (ATA queue lock) 499 108638 8732 12 0 0 /usr/src/sys/dev/ata/ata-queue.c:185 (ATA state lock) 418 11820 5386 2 0 4 /usr/src/sys/dev/ata/ata-queue.c:80 (ATA queue lock) 320 115812 2637 43 0 0 /usr/src/sys/dev/random/yarrow.c:193 (random reseed) 309 98547 55775 1 3 6 /usr/src/sys/kern/kern_conf.c:62 (cdev) 194 897 5 179 1 0 /usr/src/sys/fs/devfs/devfs_vnops.c:285 (Giant) 155 759634 362384 2 0 427 /usr/src/sys/dev/bge/if_bge.c:2916 (bge0) 138 240285 156914 1 0 0 /usr/src/sys/dev/acpica/Osd/OsdSynch.c:183 (ACPI semaphore) 75 75460 1344 56 15 0 /usr/src/sys/dev/bge/if_bge.c:3088 (bge0) 73 1830084 180344 10 65 0 /usr/src/sys/dev/bge/if_bge.c:3321 (bge0) 62 157 19 8 0 0 /usr/src/sys/fs/devfs/devfs_vnops.c:269 (vnode interlock) 48 151 4 37 0 0 /usr/src/sys/dev/random/yarrow.c:280 (random reseed) 46 22508 5387 4 0 0 /usr/src/sys/dev/ata/ata-all.c:327 (ATA state lock) 32 3642 2421 1 0 0 /usr/src/sys/kern/subr_devstat.c:394 (devstat) 29 282384 180059 1 0 0 /usr/src/sys/dev/bge/if_bge.c:2840 (bge0) 27 544145 360697 1 0 10 /usr/src/sys/dev/bge/if_bge.c:3245 (bge0) 9 27 3 9 0 0 /usr/src/sys/fs/devfs/devfs_vnops.c:245 (session) 5 15 3 5 0 0 /usr/src/sys/fs/devfs/devfs_vnops.c:246 (vnode interlock) 5 5 1 5 0 0 /usr/src/sys/fs/devfs/devfs_vnops.c:157 (vnode interlock) 3 8 3 2 0 0 /usr/src/sys/vm/swap_pager.c:652 (swapdev) 1 406 269 1 0 0 /usr/src/sys/kern/subr_devstat.c:381 (devstat) 1 214 134 1 0 0 /usr/src/sys/dev/acpica/acpi_thermal.c:753 (ACPI thermal zone) 1 207 134 1 0 0 /usr/src/sys/dev/acpica/acpi_thermal.c:745 (ACPI thermal zone) 1 23 15 1 0 0 /usr/src/sys/fs/devfs/devfs_vnops.c:530 (dev_clone) 1 4 3 1 0 0 /usr/src/sys/kern/kern_conf.c:77 (cdev) 1 1 1 1 0 0 /usr/src/sys/vm/swap_pager.c:621 (swapdev)