ミューテックスチェック
今回はカーネルミューテックスに関するリソース情報を取得する方法を紹介しようと思います。ユーザがこの情報を使うというか気にする必要はほとんどないとは思います。カーネルデベロッパでも、
カーネルミューテックスに関する情報はlockstat(1)コマンドはカーネルのロック情報およびプロファイリング統計情報を取得して表示するためのコマンドです。-Hでミューテックスのホールド時間、
% sudo lockstat -H '*' lockstat: warning: * exited with code 127 lockstat: warning: 34632 dynamic variable drops with non-empty dirty list lockstat: warning: ran out of data records (use -n for more) Adaptive mutex hold: 235 events in 0.016 seconds (14558 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 28 12% 12% 0.00 653 process lock sys_sigprocmask+0x61 28 12% 24% 0.00 23481 pmap vmspace_fork+0x8d9 26 11% 35% 0.00 653 select mtxpool pipe_poll+0x1c3 26 11% 46% 0.00 654 select mtxpool kern_select+0xc8b 26 11% 57% 0.00 1733 pipe mutex kern_select+0x7df 13 6% 63% 0.00 613 ttymtx ttydev_poll+0x1f 13 6% 68% 0.00 723 cdev devfs_poll_f+0x36 12 5% 73% 0.00 606 ttymtx ttydev_read+0x20 12 5% 78% 0.00 613 cdev devfs_read_f+0x5c 6 3% 81% 0.00 576 vm page free queue _pmap_allocpte+0xaf 4 2% 83% 0.00 958 pmap vmspace_fork+0x5e7 2 1% 83% 0.00 625 vm page free queue uma_small_alloc+0x47 2 1% 84% 0.00 1085 vm page free queue get_pv_entry+0x6a 2 1% 85% 0.00 844 vm page free queue pmap_remove_pte+0x23f 2 1% 86% 0.00 886 vm page free queue vm_fault_hold+0x5b6 2 1% 87% 0.00 1946 vm page vm_fault+0x78 2 1% 88% 0.00 1048 process_ctor uma_zalloc_arg+0x6cc 2 1% 89% 0.00 597 process lock sys_ktimer_create+0x4b 2 1% 89% 0.00 1070 pmap pv chunk list pmap_try_insert_pv_entry+0x23 2 1% 90% 0.00 638 pmap pv chunk list pmap_remove_pte+0x23f 2 1% 91% 0.00 648 itimer keg_fetch_slab+0x16e 2 1% 92% 0.00 485 itimer kern_ktimer_create+0x330 2 1% 93% 0.00 1020 cdev devfs_ioctl_f+0x39 1 0% 93% 0.00 606 vm page free queue pmap_remove+0x5fc 1 0% 94% 0.00 586 vm page free queue pmap_pinit_type+0x33 1 0% 94% 0.00 2006 vm page vm_fault_hold+0x1221 1 0% 94% 0.00 643 vm active pagequeue vm_fault_hold+0x61b 1 0% 95% 0.00 584 ui_vmsize vm_map_delete+0x1bc 1 0% 95% 0.00 621 vm active pagequeue vm_fault_hold+0x212f 1 0% 96% 0.00 801 vm inactive pagequeue release_page+0xd2 1 0% 96% 0.00 825 process lock sys_ktimer_settime+0x4d 1 0% 97% 0.00 676 sigacts sys_sigaction+0x61 1 0% 97% 0.00 565 swapdev vm_map_delete+0x1bc 1 0% 97% 0.00 3168 itimer lock sys_ktimer_settime+0x4d 1 0% 98% 0.00 506 itimer uma_zalloc_arg+0x44e 1 0% 98% 0.00 2212 invlgn pmap_remove+0x5e9 1 0% 99% 0.00 3003 eventhandler proc_ctor+0x41 1 0% 99% 0.00 3360 pmap vm_fault_hold+0x1fe1 1 0% 100% 0.00 618 pmap vm_fault_hold+0x312 1 0% 100% 0.00 1927 process lock sys_sigaction+0x61 ------------------------------------------------------------------------------- Spin lock hold: 15 events in 0.016 seconds (929 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 3 20% 20% 0.00 1291 et_hw_mtx cpu_idle+0x56 2 13% 33% 0.00 1513 et_hw_mtx cpu_activeclock+0x7b 2 13% 47% 0.00 1342 et_hw_mtx timercb+0xb7 1 7% 53% 0.00 876 turnstile chain pmap_delayed_invl_finished+0xde 1 7% 60% 0.00 7453 smp rendezvous dtrace_sync+0x77 1 7% 67% 0.00 36588 smp rendezvous dtrace_xcall+0xb2 1 7% 73% 0.00 2126 sched lock 2 handleevents+0x105 1 7% 80% 0.00 699 et_hw_mtx callout_reset_sbt_on+0x2f1 1 7% 87% 0.00 2516 callout dtrace_state_clean+0x138 1 7% 93% 0.00 572 callout intr_event_execute_handlers+0x20f 1 7% 100% 0.00 683 callout realtimer_settime+0x29d ------------------------------------------------------------------------------- R/W writer hold: 474 events in 0.016 seconds (29364 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 283 60% 60% 0.00 662 pmap pv list pmap_remove+0x497 156 33% 93% 0.00 1018 pmap pv list pmap_copy+0x65c 14 3% 96% 0.00 1175 vm object fork1+0x5ec 13 3% 98% 0.00 925 pmap pv list vmspace_fork+0x8d9 1 0% 99% 0.00 507 vm object sys_munmap+0xff 1 0% 99% 0.00 518 vm object vmspace_fork+0x70a 1 0% 99% 0.00 644 vm object vm_map_process_deferred+0x5d 1 0% 99% 0.00 3123 vm object vm_fault_hold+0x2212 1 0% 99% 0.00 575 vm object unlock_and_deallocate+0x276 1 0% 100% 0.00 8179 vm object vm_fault+0x78 1 0% 100% 0.00 725 pmap pv list vm_map_delete+0x18d 1 0% 100% 0.00 1324 pmap pv list vm_fault_hold+0x1fe1 ------------------------------------------------------------------------------- R/W reader hold: 3 events in 0.016 seconds (186 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 2 67% 67% 0.00 3623 vm object vm_fault+0x78 1 33% 100% 0.00 2622 vm object vm_fault_hold+0x2652 ------------------------------------------------------------------------------- SX shared hold: 100 events in 0.016 seconds (6195 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 48 48% 48% 0.00 651 devfsmount VOP_GETATTR_APV+0x87 48 48% 96% 0.00 757 devfsmount devfs_getattr+0x1e 2 2% 98% 0.00 5757300 vm map (user) fork1+0x5ec 2 2% 100% 0.00 1301 dtrace_lock dtrace_ioctl+0xf24 ------------------------------------------------------------------------------- SX exclusive hold: 20 events in 0.016 seconds (1239 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 15 75% 75% 0.00 688 vm map (user) useracc+0x76 2 10% 85% 0.00 17497 vm map (user) unlock_and_deallocate+0x289 2 10% 95% 0.00 1141 filedesc structure sys_ioctl+0x171 1 5% 100% 0.00 4835 vm map (user) vm_fault_hold+0x267e ------------------------------------------------------------------------------- %
% sudo lockstat -C '*' lockstat: warning: * exited with code 127 Thread lock spin: 21 events in 0.004 seconds (5679 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 2 10% 10% 0.00 43 sleepq chain sleepq_broadcast+0x96 1 5% 14% 0.00 38 sched lock 3 sched_idletd+0xcc 1 5% 19% 0.00 31 sched lock 3 umtx_thread_cleanup+0x12f 1 5% 24% 0.00 41 sched lock 3 thread_exit+0x2a8 1 5% 29% 0.00 53 sched lock 3 thread_wait+0x20 1 5% 33% 0.00 27 sched lock 1 ast+0x30a 1 5% 38% 0.00 35 sched lock 1 ast+0x4c 1 5% 43% 0.00 32 sched lock 2 statclock_cnt+0x126 1 5% 48% 0.00 118 sched lock 3 statclock_cnt+0x126 1 5% 52% 0.00 32 sched lock 3 ruxagg+0x23 1 5% 57% 0.00 29 sched lock 1 fork1+0x218f 1 5% 62% 0.00 32 sched lock 1 fork1+0x1138 1 5% 67% 0.00 34 sched lock 1 statclock_cnt+0x126 1 5% 71% 0.00 47 sched lock 0 statclock_cnt+0x126 1 5% 76% 0.00 67 sched lock 0 sched_idletd+0xcc 1 5% 81% 0.00 23 sched lock 1 sched_userret+0x3a 1 5% 86% 0.00 38 sched lock 1 sched_exit_thread+0x20 1 5% 90% 0.00 949 sched lock 1 sched_idletd+0xcc 1 5% 95% 0.00 40 sched lock 1 sleepq_add+0xf8 1 5% 100% 0.00 24 sched lock 1 sleepq_catch_signals+0x5d ------------------------------------------------------------------------------- %
lockstat(1)は引数にコマンドを与えることで、
% sudo lockstat sleep 5 Adaptive mutex block: 3 events in 5.008 seconds (1 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 1 33% 33% 0.00 3701 uhci0 usb_process+0x167 1 33% 67% 0.00 6356 ehci0 usb_process+0x167 1 33% 100% 0.00 5934 ATA state lock ata_interrupt+0x7c ------------------------------------------------------------------------------- Thread lock spin: 3047 events in 5.008 seconds (608 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 557 18% 18% 0.00 75 sched lock 0 critical_exit+0x58 547 18% 36% 0.00 51 sched lock 0 intr_event_schedule_thread+0x7f 545 18% 54% 0.00 51 sched lock 0 ithread_loop+0x197 519 17% 71% 0.00 102 sched lock 0 statclock_cnt+0x126 193 6% 77% 0.00 33 sched lock 0 ruxagg+0x23 165 5% 83% 0.00 59 sched lock 0 sleepq_add+0xf8 141 5% 88% 0.00 125 sleepq chain ruxagg+0x23 132 4% 92% 0.00 147 sleepq chain sleepq_timeout+0x1d 81 3% 95% 0.00 33 sched lock 0 sleepq_timedwait+0x2f 59 2% 96% 0.00 35 sched lock 0 sleepq_catch_signals+0x5d 25 1% 97% 0.00 31 sched lock 0 sleepq_wait+0x2f 23 1% 98% 0.00 55 sleepq chain sleepq_signal+0x9c 10 0% 98% 0.00 44 sched lock 0 sched_userret+0x3a 6 0% 99% 0.00 34 sched lock 0 ast+0x4c 5 0% 99% 0.00 217 sleepq chain sleepq_broadcast+0x96 5 0% 99% 0.00 33 sleepq chain tdsigwakeup+0xd2 5 0% 99% 0.00 31 sleepq chain signotify+0xf1 5 0% 99% 0.00 33 sched lock 0 sched_sync+0x8a1 4 0% 99% 0.00 42 sched lock 0 kern_yield+0x105 3 0% 99% 0.00 30 turnstile lock turnstile_unpend+0x282 3 0% 100% 0.00 29 sched lock 0 turnstile_unpend+0x68 3 0% 100% 0.00 100 sched lock 0 turnstile_wait+0x351 3 0% 100% 0.00 34 sched lock 0 propagate_priority+0xb9 2 0% 100% 0.00 53 sched lock 0 umtx_thread_cleanup+0x12f 1 0% 100% 0.00 39 sched lock 0 ast+0x30a 1 0% 100% 0.00 106 sched lock 0 fork1+0x1138 1 0% 100% 0.00 58 sched lock 0 fork1+0x218f 1 0% 100% 0.00 22 sched lock 0 thread_exit+0x2a8 1 0% 100% 0.00 255 sched lock 0 thread_wait+0x20 1 0% 100% 0.00 40 sched lock 0 sched_exit_thread+0x20 ------------------------------------------------------------------------------- %
オプションを指定すると、
% sudo lockstat -H -D 10 -s 50 sleep 5 lockstat: warning: 17484 dynamic variable drops with non-empty dirty list lockstat: warning: 4909 dynamic variable drops with non-empty dirty list lockstat: warning: ran out of data records (use -n for more) Adaptive mutex hold: 1120 events in 5.014 seconds (223 events/sec) ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 519 46% 46% 0.00 922 reseed mutex random_kthread+0x78 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@@ 394 fork_exit+0x85 2048 |@@@@@ 98 0xffffffff80f8467e 4096 |@ 26 8192 | 0 16384 | 1 ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 172 15% 62% 0.00 10171 process lock sys_getrusage+0x1d nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@ 75 amd64_syscall+0x4ce 2048 |@ 6 0xffffffff80f8442b 4096 | 2 8192 | 2 16384 |@@@@@ 34 32768 |@@@@@@@@ 51 65536 | 2 ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 92 8% 70% 0.00 765 select mtxpool kern_poll+0x71b nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 84 sys_poll+0x61 2048 |@@ 8 amd64_syscall+0x4ce 0xffffffff80f8442b ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 48 4% 74% 0.00 1309 sellck kern_poll+0x296 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@ 21 sys_poll+0x61 2048 |@@@@@@@@@@@ 19 amd64_syscall+0x4ce 4096 |@@@@@ 8 0xffffffff80f8442b ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 44 4% 78% 0.00 9447 Giant softclock_call_cc+0x1bc nsec ------ Time Distribution ------ count Stack 8192 |@@@@@@ 9 softclock+0x94 16384 |@@@@@@@@@@@@@@@@@@@@@@@ 34 intr_event_execute_handlers+0x20f 32768 | 1 ithread_loop+0xc6 fork_exit+0x85 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 34 3% 81% 0.00 807 IP reassembly pfslowtimo+0x54 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@@@@ 28 softclock_call_cc+0x18a 2048 |@@@@ 5 softclock+0x94 4096 | 1 intr_event_execute_handlers+0x20f ithread_loop+0xc6 fork_exit+0x85 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 32 3% 84% 0.00 4113 pipe mutex kern_poll+0x650 nsec ------ Time Distribution ------ count Stack 4096 |@@@@@@@@@@@@@@@ 16 sys_poll+0x61 8192 |@@@@@@@@@@@@@@@ 16 amd64_syscall+0x4ce 0xffffffff80f8442b ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 21 2% 86% 0.00 7637 msgbuf lock softclock_call_cc+0x1bc nsec ------ Time Distribution ------ count Stack 8192 |@@@@@@@@@@@@@@@@@@@@@@ 16 softclock+0x94 16384 |@@@@@@@ 5 intr_event_execute_handlers+0x20f ithread_loop+0xc6 fork_exit+0x85 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 15 1% 87% 0.00 619 select mtxpool pipe_poll+0x1c3 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 15 kern_poll+0x650 sys_poll+0x61 amd64_syscall+0x4ce 0xffffffff80f8442b ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 7 1% 88% 0.00 1001 Global Softdep Lock softdep_process_worklist+0xd5 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@ 5 softdep_flush+0x17f 2048 |@@@@@@@@ 2 fork_exit+0x85 0xffffffff80f8467e ------------------------------------------------------------------------------- Spin lock hold: 6971 events in 5.014 seconds (1390 events/sec) ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 521 7% 7% 0.00 9556302 sched lock 0 fork_exit+0x85 nsec ------ Time Distribution ------ count Stack 65536 | 1 0xffffffff80f8467e 131072 | 0 262144 | 0 524288 | 0 1048576 | 1 2097152 | 6 4194304 | 0 8388608 | 8 16777216 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 505 ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 521 7% 15% 0.00 649 callout intr_event_execute_handlers+0x20f nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 504 ithread_loop+0xc6 2048 | 16 fork_exit+0x85 4096 | 1 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 515 7% 22% 0.00 5013 callout dtrace_state_clean+0x138 nsec ------ Time Distribution ------ count Stack 1024 |@@ 46 softclock_call_cc+0x18a 2048 | 3 softclock+0x94 4096 | 0 intr_event_execute_handlers+0x20f 8192 |@@@@@@@@@@@@@@@@@@@@@@@@@ 441 ithread_loop+0xc6 16384 |@ 20 fork_exit+0x85 32768 | 5 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 489 7% 29% 0.00 755 callout softclock+0x94 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 463 intr_event_execute_handlers+0x20f 2048 |@ 23 ithread_loop+0xc6 4096 | 0 fork_exit+0x85 8192 | 0 0xffffffff80f8467e 16384 | 3 ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 464 7% 36% 0.00 724 et_hw_mtx callout_reset_sbt_on+0x2f1 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 436 dtrace_state_clean+0x138 2048 |@ 24 softclock_call_cc+0x18a 4096 | 3 softclock+0x94 8192 | 0 intr_event_execute_handlers+0x20f 16384 | 1 ithread_loop+0xc6 fork_exit+0x85 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 438 6% 42% 0.00 1303 et_hw_mtx cpu_idle+0x56 nsec ------ Time Distribution ------ count Stack 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 414 sched_idletd+0x3d3 4096 |@ 24 fork_exit+0x85 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 421 6% 48% 0.00 3294 sched lock 0 handleevents+0x105 nsec ------ Time Distribution ------ count Stack 2048 | 1 timercb+0xb7 4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@ 366 lapic_handle_timer+0x9f 8192 |@@ 41 0xffffffff80f84d3c 16384 | 9 acpi_cpu_idle+0x2e2 32768 | 3 cpu_idle_acpi+0x3f 65536 | 1 cpu_idle+0x95 sched_idletd+0x3d3 fork_exit+0x85 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 418 6% 54% 0.00 7028 callout handleevents+0x17c nsec ------ Time Distribution ------ count Stack 4096 | 2 timercb+0xb7 8192 |@@@@@@@@@@@@@@@@@@@@@@@@@ 350 lapic_handle_timer+0x9f 16384 |@@@@ 62 0xffffffff80f84d3c 32768 | 3 acpi_cpu_idle+0x2e2 65536 | 1 cpu_idle_acpi+0x3f cpu_idle+0x95 sched_idletd+0x3d3 fork_exit+0x85 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 416 6% 60% 0.00 990 et_hw_mtx callout_process+0x2d6 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@ 359 handleevents+0x17c 2048 |@@@ 50 timercb+0xb7 4096 | 1 lapic_handle_timer+0x9f 8192 | 0 0xffffffff80f84d3c 16384 | 6 acpi_cpu_idle+0x2e2 cpu_idle_acpi+0x3f cpu_idle+0x95 sched_idletd+0x3d3 fork_exit+0x85 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 411 6% 66% 0.00 1097 entropy harvest mutex swi_sched+0x40 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@ 290 callout_process+0x322 2048 |@@@@@@@@ 115 handleevents+0x17c 4096 | 2 timercb+0xb7 8192 | 0 lapic_handle_timer+0x9f 16384 | 4 0xffffffff80f84d3c acpi_cpu_idle+0x2e2 cpu_idle_acpi+0x3f cpu_idle+0x95 sched_idletd+0x3d3 fork_exit+0x85 0xffffffff80f8467e ------------------------------------------------------------------------------- R/W writer hold: 50 events in 5.014 seconds (10 events/sec) ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 21 42% 42% 0.00 593 vm object vm_map_madvise+0x254 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 20 sys_madvise+0x85 2048 |@ 1 amd64_syscall+0x4ce 0xffffffff80f8442b ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 7 14% 56% 0.00 7349 Per-Filesystem Softdep Lock softdep_flush+0x17f nsec ------ Time Distribution ------ count Stack 8192 |@@@@@@@@@@@@@@@@@@@@@@@@@ 6 fork_exit+0x85 16384 |@@@@ 1 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 7 14% 70% 0.00 1270 Per-Filesystem Softdep Lock _sleep+0x1d8 nsec ------ Time Distribution ------ count Stack 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 7 softdep_flush+0x254 fork_exit+0x85 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 7 14% 84% 0.00 2140 Per-Filesystem Softdep Lock fork_exit+0x85 nsec ------ Time Distribution ------ count Stack 2048 |@@@@@@@@ 2 0xffffffff80f8467e 4096 |@@@@@@@@@@@@@@@@@@@@@ 5 ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 5 10% 94% 0.00 4303 pmap pv list vm_pageout+0x19b9 nsec ------ Time Distribution ------ count Stack 4096 |@@@@@@ 1 fork_exit+0x85 8192 |@@@@@@@@@@@@@@@@@@@@@@@@ 4 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 1 2% 96% 0.00 1328 vm object vm_map_insert+0x437 nsec ------ Time Distribution ------ count Stack 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 vm_map_find+0x1a0 vm_mmap_object+0x4ef sys_mmap+0x449 amd64_syscall+0x4ce 0xffffffff80f8442b ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 1 2% 98% 0.00 3250 vm object vm_fault_hold+0x2212 nsec ------ Time Distribution ------ count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 vm_fault+0x78 trap_pfault+0xf9 trap+0x316 0xffffffff80f84141 ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 1 2% 100% 0.00 794 pmap pv list vm_fault_hold+0x1fe1 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 vm_fault+0x78 trap_pfault+0xf9 trap+0x316 0xffffffff80f84141 ------------------------------------------------------------------------------- R/W reader hold: 5 events in 5.014 seconds (1 events/sec) ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 3 60% 60% 0.00 9320 vm object vm_fault+0x78 nsec ------ Time Distribution ------ count Stack 8192 |@@@@@@@@@@ 1 trap_pfault+0xf9 16384 |@@@@@@@@@@@@@@@@@@@@ 2 trap+0x316 0xffffffff80f84141 ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 1 20% 80% 0.00 1970 udp udp_input+0x6b9 nsec ------ Time Distribution ------ count Stack 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 ip_input+0x15f netisr_dispatch_src+0xa5 ether_demux+0x12a ether_nh_input+0x322 netisr_dispatch_src+0xa5 ether_input+0x26 vmxnet3_rxq_eof+0x708 vmxnet3_legacy_intr+0x110 intr_event_execute_handlers+0x20f ithread_loop+0xc6 fork_exit+0x85 0xffffffff80f8467e ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 1 20% 100% 0.00 2754 if_addr_lock ip_input+0x59d nsec ------ Time Distribution ------ count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 netisr_dispatch_src+0xa5 ether_demux+0x12a ether_nh_input+0x322 netisr_dispatch_src+0xa5 ether_input+0x26 vmxnet3_rxq_eof+0x708 vmxnet3_legacy_intr+0x110 intr_event_execute_handlers+0x20f ithread_loop+0xc6 fork_exit+0x85 0xffffffff80f8467e ------------------------------------------------------------------------------- SX shared hold: 5 events in 5.014 seconds (1 events/sec) ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 2 40% 40% 0.00 34230 dtrace_lock dtrace_ioctl+0x1d72 nsec ------ Time Distribution ------ count Stack 32768 |@@@@@@@@@@@@@@@ 1 devfs_ioctl_f+0x13f 65536 |@@@@@@@@@@@@@@@ 1 kern_ioctl+0x2d4 sys_ioctl+0x171 amd64_syscall+0x4ce 0xffffffff80f8442b ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 2 40% 80% 0.00 1327 dtrace_lock dtrace_ioctl+0xf24 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@ 1 devfs_ioctl_f+0x13f 2048 |@@@@@@@@@@@@@@@ 1 kern_ioctl+0x2d4 sys_ioctl+0x171 amd64_syscall+0x4ce 0xffffffff80f8442b ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 1 20% 100% 0.00 16030 vm map (user) vm_map_find+0x1f7 nsec ------ Time Distribution ------ count Stack 16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 vm_mmap_object+0x4ef sys_mmap+0x449 amd64_syscall+0x4ce 0xffffffff80f8442b ------------------------------------------------------------------------------- SX exclusive hold: 43 events in 5.014 seconds (9 events/sec) ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 30 70% 70% 0.00 14593 filedesc structure sys_poll+0x61 nsec ------ Time Distribution ------ count Stack 8192 |@@@@ 4 amd64_syscall+0x4ce 16384 |@@@@@@@@@@@@@@ 14 0xffffffff80f8442b 32768 |@@@@@@@@@@@@ 12 ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 4 9% 79% 0.00 785 vm map (user) useracc+0x76 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4 userland_sysctl+0x8c sys___sysctl+0x74 amd64_syscall+0x4ce 0xffffffff80f8442b ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 4 9% 88% 0.00 2157 filedesc structure sys_ioctl+0x171 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@ 1 amd64_syscall+0x4ce 2048 | 0 0xffffffff80f8442b 4096 |@@@@@@@@@@@@@@@@@@@@@@ 3 ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 3 7% 95% 0.00 25791 vm map (user) unlock_and_deallocate+0x289 nsec ------ Time Distribution ------ count Stack 32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 vm_fault_hold+0x2212 vm_fault+0x78 trap_pfault+0xf9 trap+0x316 0xffffffff80f84141 ------------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 2 5% 100% 0.00 889 vm map (user) useracc+0x76 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@ 1 userland_sysctl+0xba 2048 |@@@@@@@@@@@@@@@ 1 sys___sysctl+0x74 amd64_syscall+0x4ce 0xffffffff80f8442b ------------------------------------------------------------------------------- %
こんな感じでコマンドを指定するだけでロック情報を詳しく取得することができます。DTraceの機能が統合されさまざまなポイントに観測点を設けることができるようになったおかげで、
開発者であればこれは垂涎モノの機能なわけですが、
勉強会
第59回 12月21日(水)19:00~FreeBSD勉強会会 (日程変更の可能性あり)
ストレージシステムの基盤として使われることの多いZFS。いったん運用を開始あるとあとはボリュームの管理や、
参加申請はこちらから。