Bug #6271
dtrace caused excessive fork time
Start date:
2015-09-30
Due date:
% Done:
100%
Estimated time:
Difficulty:
Hard
Tags:
Gerrit CR:
Description
A customer experienced a Manatee outage today during an upgrade. There was a cascading failure upstack, but the root cause was that the postmaster process was spending between 50-90% of its
time in SYS time, and almost all of that was in fork(2):
$ prstat -mLc -p 49133 1
Please wait...
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
49133 postgres 0.4 79 0.0 0.0 0.0 0.0 21 0.1 11 41 173 8 postgres/1
Total: 1 processes, 1 lwps, load averages: 0.43, 0.43, 0.43
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
49133 postgres 0.3 66 0.0 0.0 0.0 0.0 33 0.0 16 25 134 6 postgres/1
Total: 1 processes, 1 lwps, load averages: 0.43, 0.43, 0.43
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
49133 postgres 0.2 44 0.0 0.0 0.0 0.0 56 0.1 15 33 75 3 postgres/1
Total: 1 processes, 1 lwps, load averages: 0.43, 0.43, 0.43
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
49133 postgres 0.3 49 0.0 0.0 0.0 0.0 50 0.0 15 28 113 6 postgres/1
Total: 1 processes, 1 lwps, load averages: 0.43, 0.43, 0.43
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
49133 postgres 0.2 55 0.0 0.0 0.0 0.0 44 0.0 13 23 80 4 postgres/1
Total: 1 processes, 1 lwps, load averages: 0.42, 0.43, 0.43
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
49133 postgres 0.6 98 0.0 0.0 0.0 0.0 1.5 0.1 7 47 256 13 postgres/1
Total: 1 processes, 1 lwps, load averages: 0.42, 0.43, 0.43
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
49133 postgres 0.5 90 0.0 0.0 0.0 0.0 9.6 0.1 7 71 217 12 postgres/1
Total: 1 processes, 1 lwps, load averages: 0.42, 0.43, 0.43
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
49133 postgres 0.6 98 0.0 0.0 0.0 0.0 1.1 0.1 6 62 223 11 postgres/1
...
# dtrace -n 'profile-97/pid == 49133/{ @[stack()] = count(); }' -c 'sleep 30'
dtrace: description 'profile-97' matched 1 probe
dtrace: pid 2204 has exited
unix`mutex_vector_enter
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
genunix`kmem_cache_alloc+0x89
genunix`kmem_zalloc+0x47
fasttrap`fasttrap_meta_create_probe+0x166
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
dtrace`dtrace_enabling_provide+0xaa
dtrace`dtrace_register+0x2f8
fasttrap`fasttrap_provider_lookup+0x2f3
fasttrap`fasttrap_meta_provide+0x93
dtrace`dtrace_helper_provide_one+0xf2
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
dtrace`dtrace_enabling_provide+0xae
dtrace`dtrace_register+0x2f8
fasttrap`fasttrap_provider_lookup+0x2f3
fasttrap`fasttrap_meta_provide+0x93
dtrace`dtrace_helper_provide_one+0xf2
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`hat_page_setattr+0x30
unix`hati_update_pte+0x117
unix`hat_updateattr+0x183
unix`hat_clrattr+0x23
genunix`segvn_dup+0x415
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`sys_rtt_common+0x1b0
unix`_sys_rtt_ints_disabled+0x8
dtrace`dtrace_match_probe+0x8
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
genunix`segvn_dup+0xa4
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
genunix`syscall_mstate+0x124
unix`sys_syscall+0x10e
1
unix`hwblkpagecopy+0x175
unix`ppcopy+0x1c5
genunix`anon_private+0x1df
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
genunix`kmem_zalloc+0xe2
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_delay_default
unix`mutex_vector_enter+0xc5
dtrace`dtrace_probe_lookup+0x7c
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_delay_default
unix`mutex_vector_enter+0xc5
dtrace`dtrace_register+0x2c1
fasttrap`fasttrap_provider_lookup+0x2f3
fasttrap`fasttrap_meta_provide+0x93
dtrace`dtrace_helper_provide_one+0xf2
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_delay_default
unix`lock_set_spl_spin+0xb2
genunix`disp_lock_enter+0x26
unix`disp_getbest+0x28
unix`disp+0x53
unix`swtch+0xba
unix`preempt+0xec
unix`kpreempt+0x98
unix`sys_rtt_common+0x1ba
unix`_sys_rtt_ints_disabled+0x8
dtrace`dtrace_match_probe+0x54
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
1
unix`page_sub_common+0x35
unix`page_sub+0x22
unix`page_get_mnode_freelist+0x375
unix`page_get_freelist+0x16d
unix`page_create_va+0x2ad
genunix`swap_getapage+0x113
genunix`swap_getpage+0x90
genunix`fop_getpage+0x7e
genunix`anon_private+0x160
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0xc5
dtrace`dtrace_helper_provider_register+0x45
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0xc5
dtrace`dtrace_enabling_provide+0x166
dtrace`dtrace_register+0x2f8
fasttrap`fasttrap_provider_lookup+0x2f3
fasttrap`fasttrap_meta_provide+0x93
dtrace`dtrace_helper_provide_one+0xf2
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0xc5
dtrace`dtrace_register+0x2c1
fasttrap`fasttrap_provider_lookup+0x2f3
fasttrap`fasttrap_meta_provide+0x93
dtrace`dtrace_helper_provide_one+0xf2
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
genunix`new_cpu_mstate+0x29
genunix`new_mstate+0x184
unix`trap+0x174
unix`0xfffffffffb8001d6
1
unix`page_numtopp_nolock+0x5a
unix`hat_updateattr+0xef
unix`hat_clrattr+0x23
genunix`segvn_dup+0x415
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_delay_default+0xc
unix`mutex_vector_enter+0xc5
genunix`mod_hold_stub+0x2b
unix`stubs_common_code+0x1f
genunix`forklwp+0x1e4
genunix`cfork+0x690
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_delay_default+0xc
unix`mutex_vector_enter+0xc5
dtrace`dtrace_helper_provider_register+0x39
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
genunix`anon_dup+0x132
genunix`segvn_dup+0x52b
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_owner_running+0x3
dtrace`dtrace_probe_create+0x61
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`page_sub_common+0x44
unix`page_sub+0x22
unix`page_get_mnode_freelist+0x375
unix`page_get_freelist+0x16d
unix`page_create_va+0x2ad
genunix`swap_getapage+0x113
genunix`swap_getpage+0x90
genunix`fop_getpage+0x7e
genunix`anon_private+0x160
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
unix`htable_lookup+0xc6
unix`htable_walk+0x17e
unix`hat_updateattr+0x99
unix`hat_clrattr+0x23
genunix`segvn_dup+0x415
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`hwblkpagecopy+0xa6
unix`ppcopy+0x1c5
genunix`anon_private+0x1df
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
dtrace`dtrace_probe_lookup+0x3b
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
genunix`cpu_update_pct+0x80
genunix`new_mstate+0x73
unix`trap+0x63e
unix`0xfffffffffb8001d6
1
unix`page_lookup_create+0x168
unix`page_lookup+0x21
genunix`swap_getapage+0xea
genunix`swap_getpage+0x90
genunix`fop_getpage+0x7e
genunix`anon_private+0x160
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
unix`mutex_owner_running+0x18
dtrace`dtrace_probe_create+0x61
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_owner_running+0x18
dtrace`dtrace_helpers_duplicate+0x37
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_enter+0x10
genunix`rctl_gp_alloc+0x70
genunix`rctl_set_dup_prealloc+0x49
genunix`cfork+0x200
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_enter+0x10
unix`hat_pte_unmap+0xbc
unix`hat_unload_callback+0x259
unix`hat_unload+0x3e
genunix`anon_private+0x214
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
unix`mutex_enter+0x10
unix`hat_pte_unmap+0xbc
unix`hat_unload_callback+0x259
unix`hat_unload+0x3e
genunix`anon_private+0x214
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0xd23
unix`0xfffffffffb8001d6
unix`0xfffffffffb8540da
genunix`psig+0x440
genunix`post_syscall+0x82d
unix`0xfffffffffb800caa
1
unix`mutex_enter+0x10
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_enter+0x10
unix`hat_unload_callback+0x262
unix`hat_unload+0x3e
genunix`anon_private+0x214
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
unix`mutex_enter+0x10
genunix`kmem_zalloc+0x47
genunix`anon_create+0x81
genunix`anonmap_alloc+0x61
genunix`segvn_dup+0x1bb
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_enter+0x10
genunix`kmem_zalloc+0x47
fasttrap`fasttrap_meta_create_probe+0x166
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_enter+0x10
unix`page_get_mnode_freelist+0x32c
unix`page_get_freelist+0x16d
unix`page_create_va+0x2ad
genunix`swap_getapage+0x113
genunix`swap_getpage+0x90
genunix`fop_getpage+0x7e
genunix`anon_private+0x160
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
unix`mutex_enter+0x10
genunix`segvn_dup+0x52b
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`lgrp_stat_add+0x4c
unix`lgrp_mem_choose+0x439
unix`page_create_va+0x283
genunix`swap_getapage+0x113
genunix`swap_getpage+0x90
genunix`fop_getpage+0x7e
genunix`anon_private+0x160
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
genunix`rctl_set_tearoff+0x78
genunix`task_detach+0x61
genunix`freeproc+0x12d
genunix`waitid+0x47b
genunix`waitsys+0x2f
unix`sys_syscall+0x17a
1
dtrace`dtrace_match_probe+0xc0
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`page_vpadd+0x23
unix`page_do_hashin+0xfd
unix`page_hashin+0x59
unix`page_create_va+0x389
genunix`swap_getapage+0x113
genunix`swap_getpage+0x90
genunix`fop_getpage+0x7e
genunix`anon_private+0x160
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
unix`tsc_read+0x3
unix`mutex_vector_enter+0xc5
dtrace`dtrace_probe_create+0x61
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`tsc_read+0x3
unix`mutex_vector_enter+0xc5
dtrace`dtrace_helpers_duplicate+0x37
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`page_trylock+0x63
unix`page_trylock_cons+0x27
unix`page_get_mnode_freelist+0x185
unix`page_get_freelist+0x16d
unix`page_create_va+0x2ad
genunix`swap_getapage+0x113
genunix`swap_getpage+0x90
genunix`fop_getpage+0x7e
genunix`anon_private+0x160
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
genunix`vmem_hash_insert+0x59
genunix`vmem_seg_alloc+0x12d
genunix`vmem_xalloc+0x28a
genunix`vmem_alloc+0x137
dtrace`dtrace_probe_create+0x77
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
genunix`new_mstate+0xdc
unix`trap+0x63e
unix`0xfffffffffb8001d6
1
genunix`segvn_dup+0x520
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`lgrp_mem_choose+0x92
unix`page_create_va+0x283
genunix`swap_getapage+0x113
genunix`swap_getpage+0x90
genunix`fop_getpage+0x7e
genunix`anon_private+0x160
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
dtrace`dtrace_hash_collisions+0x63
dtrace`dtrace_match+0x267
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`page_vpadd+0x36
unix`page_do_hashin+0xfd
unix`page_hashin+0x59
unix`page_create_va+0x389
genunix`swap_getapage+0x113
genunix`swap_getpage+0x90
genunix`fop_getpage+0x7e
genunix`anon_private+0x160
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
dtrace`dtrace_hash_str+0x2c
dtrace`dtrace_hash_lookup+0x33
dtrace`dtrace_match+0xd0
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
dtrace`dtrace_hash_add+0x3e
dtrace`dtrace_probe_create+0x10f
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
genunix`segvn_dup+0x40
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
genunix`anon_dup+0xaa
genunix`segvn_dup+0x52b
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
dtrace`dtrace_hash_str+0x3f
dtrace`dtrace_match+0x28b
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`htable_lookup+0x44
unix`hati_load_common+0x74
unix`hat_memload+0x75
genunix`segvn_faultpage+0x3bf
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
unix`mutex_vector_enter+0xc5
genunix`mod_hold_stub+0x2b
unix`stubs_common_code+0x1f
genunix`cfork+0x9d3
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
genunix`anon_get_next_ptr+0xbd
genunix`anon_dup+0x160
genunix`segvn_dup+0x52b
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`page_ctr_sub_internal+0xe1
unix`page_ctr_sub+0x76
unix`page_get_mnode_freelist+0x32c
unix`page_get_freelist+0x16d
unix`page_create_va+0x2ad
genunix`swap_getapage+0x113
genunix`swap_getpage+0x90
genunix`fop_getpage+0x7e
genunix`anon_private+0x160
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
unix`strcmp+0x21
dtrace`dtrace_hash_collisions+0x68
dtrace`dtrace_match+0x267
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`strcmp+0x21
dtrace`dtrace_hash_collisions+0x68
dtrace`dtrace_match+0x28b
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`strcmp+0x21
dtrace`dtrace_hash_add+0x78
dtrace`dtrace_probe_create+0xf1
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`page_lookup_create+0xe3
unix`page_lookup+0x21
genunix`swap_getapage+0xea
genunix`swap_getpage+0x90
genunix`fop_getpage+0x7e
genunix`anon_private+0x160
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
unix`bzero+0x3a7
genunix`anon_create+0x81
genunix`anonmap_alloc+0x61
genunix`segvn_dup+0x1bb
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`htable_walk+0xc7
unix`hat_updateattr+0x99
unix`hat_clrattr+0x23
genunix`segvn_dup+0x415
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`strcmp+0x29
dtrace`dtrace_hash_add+0x78
dtrace`dtrace_probe_create+0x10f
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
dtrace`dtrace_hash_add+0x6c
dtrace`dtrace_probe_create+0x10f
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_owner+0xd
genunix`vmem_is_populator+0x2a
unix`hment_free+0x45
unix`hat_pte_unmap+0x161
unix`hat_unload_callback+0x259
unix`hat_unload+0x3e
genunix`anon_private+0x214
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
unix`default_lock_delay+0x3f
unix`mutex_vector_enter+0xc5
dtrace`dtrace_probe_lookup+0x7c
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`page_lookup_create+0xf0
unix`page_lookup+0x21
genunix`swap_getapage+0xea
genunix`swap_getpage+0x90
genunix`fop_getpage+0x7e
genunix`anon_private+0x160
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
genunix`as_segcompar+0x1
genunix`as_addseg+0xb5
genunix`seg_attach+0x2b
genunix`seg_alloc+0xc8
genunix`as_dup+0x103
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`membar_enter+0x3
FSS`fss_wakeup+0x96
genunix`turnstile_wakeup+0xbe
unix`mutex_vector_exit+0x68
dtrace`dtrace_probe_lookup+0xa7
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
genunix`fcnt_add+0x48
genunix`getproc+0x63b
genunix`cfork+0x17f
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
genunix`swapfs_getvp+0x1e
genunix`anon_alloc+0x142
genunix`anon_private+0x106
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
unix`default_lock_delay+0x4e
unix`mutex_vector_enter+0xc5
dtrace`dtrace_probe_create+0x61
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`default_lock_delay+0x4e
unix`mutex_vector_enter+0xc5
dtrace`dtrace_helpers_duplicate+0x37
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`default_lock_delay+0x4e
unix`mutex_vector_enter+0xc5
genunix`mod_hold_stub+0x2b
unix`stubs_common_code+0x1f
genunix`cfork+0x9d3
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`cmt_ev_thread_swtch
unix`swtch+0xe4
genunix`turnstile_block+0x262
unix`mutex_vector_enter+0x3a3
genunix`mod_hold_stub+0x2b
unix`stubs_common_code+0x1f
genunix`cfork+0x9d3
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`default_lock_delay+0x50
unix`mutex_vector_enter+0xc5
dtrace`dtrace_probe_create+0x61
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`default_lock_delay+0x54
unix`mutex_vector_enter+0xc5
dtrace`dtrace_probe_create+0x61
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`x86pte_update+0x48
unix`hati_update_pte+0x51
unix`hat_updateattr+0x183
unix`hat_clrattr+0x23
genunix`segvn_dup+0x415
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_vector_enter+0xfb
dtrace`dtrace_probe_create+0x61
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_vector_enter+0xfb
dtrace`dtrace_probe_lookup+0x7c
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mutex_vector_enter+0xfb
dtrace`dtrace_helper_provider_register+0x39
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
1
unix`mtype_func+0x9f
unix`page_get_mnode_freelist+0x4f
unix`page_get_freelist+0x16d
unix`page_create_va+0x2ad
genunix`swap_getapage+0x113
genunix`swap_getpage+0x90
genunix`fop_getpage+0x7e
genunix`anon_private+0x160
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
1
dtrace`dtrace_match_string+0x20
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
2
dtrace`dtrace_match_string+0x25
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
2
dtrace`dtrace_match_probe+0x6c
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
2
unix`mutex_delay_default
unix`mutex_vector_enter+0xc5
dtrace`dtrace_helper_provider_register+0x39
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
2
unix`mutex_delay_default+0x7
unix`lock_set_spl_spin+0xb2
genunix`disp_lock_enter+0x26
unix`disp_getbest+0x28
unix`disp+0x53
unix`swtch+0xba
unix`preempt+0xec
unix`kpreempt+0x98
unix`sys_rtt_common+0x1ba
unix`_sys_rtt_ints_disabled+0x8
dtrace`dtrace_match_probe+0x40
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
2
unix`mutex_delay_default+0xc
unix`mutex_vector_enter+0xc5
dtrace`dtrace_helpers_duplicate+0x37
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
2
unix`tsc_read+0x3
unix`mutex_vector_enter+0xc5
dtrace`dtrace_probe_lookup+0x7c
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
2
unix`tsc_read+0x3
unix`mutex_vector_enter+0xc5
dtrace`dtrace_helper_provider_register+0x39
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
2
unix`bzero+0x3a7
genunix`as_alloc+0xb1
genunix`as_dup+0x4d
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
2
unix`default_lock_delay+0x3f
unix`mutex_vector_enter+0xc5
dtrace`dtrace_probe_create+0x61
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
2
unix`default_lock_delay+0x3f
unix`mutex_vector_enter+0xc5
dtrace`dtrace_helpers_duplicate+0x37
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
2
unix`default_lock_delay+0x50
unix`mutex_vector_enter+0xc5
genunix`mod_hold_stub+0x2b
unix`stubs_common_code+0x1f
genunix`cfork+0x9d3
genunix`forksys+0x3c
unix`sys_syscall+0x17a
2
unix`default_lock_delay+0x50
unix`mutex_vector_enter+0xc5
dtrace`dtrace_helper_provider_register+0x39
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
2
unix`page_numtopp_nolock+0x130
unix`hat_updateattr+0xef
unix`hat_clrattr+0x23
genunix`segvn_dup+0x415
genunix`as_dup+0x11f
genunix`cfork+0x996
genunix`forksys+0x3c
unix`sys_syscall+0x17a
3
dtrace`dtrace_match_probe+0x54
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
3
unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0xc5
dtrace`dtrace_helpers_duplicate+0x37
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
3
unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0xc5
genunix`mod_hold_stub+0x2b
unix`stubs_common_code+0x1f
genunix`cfork+0x9d3
genunix`forksys+0x3c
unix`sys_syscall+0x17a
3
unix`mutex_enter+0x10
genunix`anon_private+0x106
genunix`segvn_faultpage+0x325
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
3
unix`tsc_read+0x3
unix`mutex_vector_enter+0xc5
genunix`mod_hold_stub+0x2b
unix`stubs_common_code+0x1f
genunix`cfork+0x9d3
genunix`forksys+0x3c
unix`sys_syscall+0x17a
3
unix`strcmp+0x1b
dtrace`dtrace_match_string+0x20
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
3
unix`default_lock_delay+0x3f
unix`mutex_vector_enter+0xc5
genunix`mod_hold_stub+0x2b
unix`stubs_common_code+0x1f
genunix`cfork+0x9d3
genunix`forksys+0x3c
unix`sys_syscall+0x17a
3
unix`default_lock_delay+0x3f
unix`mutex_vector_enter+0xc5
dtrace`dtrace_helper_provider_register+0x39
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
3
unix`strcmp+0x3e
dtrace`dtrace_match_string+0x20
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
3
unix`default_lock_delay+0x4e
unix`mutex_vector_enter+0xc5
dtrace`dtrace_helper_provider_register+0x39
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
3
dtrace`dtrace_match_string+0x29
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
4
unix`mutex_delay_default
unix`mutex_vector_enter+0xc5
genunix`mod_hold_stub+0x2b
unix`stubs_common_code+0x1f
genunix`cfork+0x9d3
genunix`forksys+0x3c
unix`sys_syscall+0x17a
4
genunix`anon_getpage+0x46
genunix`segvn_faultpage+0x168
genunix`segvn_fault+0x8e6
genunix`as_fault+0x37a
unix`pagefault+0x96
unix`trap+0x2c7
unix`0xfffffffffb8001d6
4
unix`strcmp+0x21
dtrace`dtrace_match_string+0x20
dtrace`dtrace_match_probe+0x8d
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
4
unix`strcmp+0x21
dtrace`dtrace_match_string+0x20
dtrace`dtrace_match_probe+0xa2
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
4
unix`strcmp+0x43
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
4
dtrace`dtrace_match_probe+0x64
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
5
dtrace`dtrace_match_probe+0x4d
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
6
dtrace`dtrace_match_probe+0x65
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
6
dtrace`dtrace_match_probe+0x68
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
7
unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0xc5
dtrace`dtrace_probe_lookup+0x7c
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
8
dtrace`dtrace_match_string+0x19
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
8
unix`strcmp+0x1
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
10
dtrace`dtrace_match_probe+0x1b
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
10
unix`strcmp+0x42
dtrace`dtrace_match_string+0x20
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
10
dtrace`dtrace_match_probe+0x38
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
10
dtrace`dtrace_match_string+0x28
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
11
dtrace`dtrace_match+0x119
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
11
unix`strcmp+0xc
dtrace`dtrace_match_string+0x20
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
12
dtrace`dtrace_match_probe+0xc
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
12
unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0xc5
dtrace`dtrace_probe_create+0x61
fasttrap`fasttrap_meta_create_probe+0x2af
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
13
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
13
dtrace`dtrace_match+0xe0
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
13
dtrace`dtrace_match_probe+0x1
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
13
14
dtrace`dtrace_match_probe+0x75
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
14
dtrace`dtrace_match_string+0x1
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
14
dtrace`dtrace_match_probe+0x5c
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
15
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
15
unix`strcmp+0x45
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
15
dtrace`dtrace_match+0x11d
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
18
dtrace`dtrace_match_probe+0x29
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
18
dtrace`dtrace_match_string+0xa
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
18
dtrace`dtrace_match+0xf2
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
19
unix`strcmp+0x29
dtrace`dtrace_match_string+0x20
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
25
unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0xc5
dtrace`dtrace_helper_provider_register+0x39
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
27
unix`strcmp+0x1e
dtrace`dtrace_match_string+0x20
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
48
unix`strcmp+0x21
dtrace`dtrace_match_string+0x20
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
52
unix`strcmp+0x18
dtrace`dtrace_match_string+0x20
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
82
unix`strcmp+0x25
dtrace`dtrace_match_string+0x20
dtrace`dtrace_match_probe+0x78
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
86
dtrace`dtrace_match_probe+0x48
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
95
dtrace`dtrace_match+0x121
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
483
dtrace`dtrace_match_probe+0x40
dtrace`dtrace_match+0xfa
dtrace`dtrace_probe_lookup+0x99
fasttrap`fasttrap_meta_create_probe+0x120
dtrace`dtrace_helper_provide_one+0x1ab
dtrace`dtrace_helper_provide+0x6f
dtrace`dtrace_helper_provider_register+0x163
dtrace`dtrace_helpers_duplicate+0x1df
genunix`cfork+0x9ea
genunix`forksys+0x3c
unix`sys_syscall+0x17a
680
Here's the distribution of fork times for about 30 seconds:
$ dtrace -n 'syscall::fork*:entry{ self->f = timestamp; }' -n 'syscall::fork*:return/self->f/{ @[pid] = quantize(timestamp - self->f); self->f = 0; }' -c 'sleep 30'
dtrace: description 'syscall::fork*:entry' matched 1 probe
dtrace: description 'syscall::fork*:return' matched 1 probe
dtrace: pid 5723 has exited
...
49133
value ------------- Distribution ------------- count
16777216 | 0
33554432 |@ 9
67108864 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 212
134217728 |@@@@@@ 40
268435456 |@@ 12
536870912 | 1
1073741824 | 0
It looks like the fasttrap provider is checking that the probe doesn't already exist. That lookup may end up scanning a hash by module, function, or probe name. All of those sets are large on this system.
Module:
# dtrace -l -n 'postgresql*:::' | awk '{print $3}' | sort | uniq -c | sort -n | tail
1 MODULE
16776 postgres
Function:
# dtrace -l -n 'postgresql*:::' | awk '{print $4}' | sort | uniq -c | sort -n | tail
466 PortalRunMulti
466 PostgresMain
466 ShutdownCLOG
466 ShutdownMultiXact
466 ShutdownSUBTRANS
466 XLogInsert
699 LWLockAcquire
932 LWLockAcquireOrWait
932 ReadBuffer_common
1398 CheckPointBuffers
Probe name:
# dtrace -l -n 'postgresql*:::' | awk '{print $5}' | sort | uniq -c | sort -n | tail
466 lwlock-wait-start
466 multixact-checkpoint-done
466 multixact-checkpoint-start
466 query-execute-done
466 query-execute-start
466 query-rewrite-done
466 query-rewrite-start
466 subtrans-checkpoint-done
466 subtrans-checkpoint-start
932 sort-start
and there are 72 probes to add, so we do this 72 times.
In running a test that creates 500 processes with 100 USDT probes each (each with different function and name), the time to create 1000 processes was found to be ~11.8 ms per fork. Eliminating the lookup eliminated more than 80% of this time, taking it to about 2.2 ms per fork. However, eliminating the helper provider forking entirely eliminated 90% off that, taking it to just 0.3 ms per fork.
Looking more closely at these results with DTrace reveals that much of the 2.2 ms is spent contending on a lock held by the asynchronous cleanup of the provider from the (previous) exiting process. This does not correspond with what we would see in the wild under this condition; modifying the test program to focus on fork time and allowing for settling time after the exit shows a different story: with the helper duplication in place but with the lookup eliminated, the time was ~390 usecs. With the helper duplication eliminated, the time dropped to ~265 usecs. While this is a savings to be sure, it is nothing like the order-of-magnitude difference when contention with provider cleanup is in play.
Updated by