On 27-Dec-06, at 5:00 PM, Bill Sommerfeld wrote:
On Wed, 2006-12-27 at 14:09 -0800, Siegfried Nikolaivich wrote:
I have been stuck trying to unzip a file over the network. Each
time I try,
the server machine slows down to a crawl until it is frozen, even
the
ethernet links go down.
by any chance, is this an NFS-exported ZFS filesystem from a SPARC
system with ATA disks? this may be a known bug:
This is indeed an NFS-exported ZFS filesystem, but it's on x86 with
SATA disks using the marvell chipset. The problem also happens on
UFS slices with CIFS.
Are there any DTrace scripts I can run to show me where the
machine is
freezing?
lockstat's kernel profiling would be the first thing I'd use (this
is in
some sense a "dtrace script" as lockstat is now built on top of dtrace
mechanisms)
Thanks, I've tried to analyze the results, but haven't been able to
exactly find the culprit. It seems the system is mostly idle while it
freezes. Could it be the underlying PCI or I/O subsystems? I did
notice that the ethernet links go down/up while transferring the file
(s).
In case anyone's interested, here is most of the output (shortened a
bit):
Profiling interrupt: 3884 events in 20.024 seconds (194 events/sec)
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1935 50% 50% 0.00 9533201069173428 cpu[1] cpu_halt
+0xb2
nsec ------ Time Distribution ------ count Stack
idle+0x89
thread_start+0x8
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1919 49% 99% 0.00 8968 cpu[0] cpu_halt+0xb2
nsec ------ Time Distribution ------ count Stack
1024 | 55 idle+0x89
2048 |@@ 163 thread_start+0x8
4096 |@@@@ 280
8192 |@@@@@@@@ 515
16384 |@@@@@@@@@@ 649
32768 |@@@@ 257
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
2 0% 99% 0.00 13745 cpu[0]+6 gethrtime+0xb
nsec ------ Time Distribution ------ count Stack
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
bge_chip_poll_engine+0x2e
bge_chip_disable_engine+0x50
bge_chip_stop+0xca
bge_chip_factotum+0x108
av_dispatch_softvect+0x62
dosoftint+0x32
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
2 0% 99% 0.00 10151 cpu[0]+6 intr_restore+0x2
nsec ------ Time Distribution ------ count Stack
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 gethrtime+0xa
drv_usecwait+0x7a
bge_chip_poll_engine+0x2e
bge_chip_disable_engine+0x50
bge_chip_stop+0xca
bge_chip_factotum+0x108
av_dispatch_softvect+0x62
dosoftint+0x32
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 99% 0.00 6020 cpu[0]+11 apic_send_ipi+0x73
nsec ------ Time Distribution ------ count Stack
8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 poke_cpu+0x1c
wakeup_cpu+0x77
setbackdq+0x1a9
sleepq_wakeone_chan+0x68
cv_signal+0xa6
taskq_bucket_dispatch+0x95
taskq_dispatch
+0x262
qenable_locked
+0xdf
backenable+0xac
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 99% 0.00 17370 cpu[0]+6 copyb+0x72
nsec ------ Time Distribution ------ count Stack
32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 copymsg+0x21
copymsgchain+0x28
i_dls_link_ether_rx+0x16b
mac_rx+0x46
aggr_recv_cb+0xe2
mac_rx+0x46
bge_receive+0x98
bge_intr+0xaf
av_dispatch_autovect+0x78
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 99% 0.00 9691 cpu[0]+11 disp+0x1ac
nsec ------ Time Distribution ------ count Stack
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 swtch+0xa3
cv_wait+0x68
taskq_thread+0x14f
thread_start+0x8
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 99% 0.00 7722 cpu[0]+6 bcopy+0xa
nsec ------ Time Distribution ------ count Stack
8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 bge_receive_ring
+0x62
bge_receive+0x71
bge_intr+0xaf
av_dispatch_autovect+0x78
intr_thread+0x50
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 99% 0.00 2803 cpu[0]+6 mutex_enter+0x10
nsec ------ Time Distribution ------ count Stack
4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
dld_str_rx_fastpath+0x24
i_dls_link_ether_rx+0x183
mac_rx+0x46
aggr_recv_cb+0xe2
mac_rx+0x46
bge_receive+0x98
bge_intr+0xaf
av_dispatch_autovect+0x78
intr_thread+0x50
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 1133 cpu[0]+5
mv_crpb_done_intr+0x150
nsec ------ Time Distribution ------ count Stack
2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 mv_intr+0xca
av_dispatch_autovect+0x78
intr_thread+0x50
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 13791 cpu[0]+5
mv_crpb_done_intr+0xc9
nsec ------ Time Distribution ------ count Stack
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 mv_subctrl_intr
+0xd9
mv_intr+0xca
av_dispatch_autovect+0x78
intr_thread+0x50
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 7105 cpu[0]+4 mul32+0x6
nsec ------ Time Distribution ------ count Stack
8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 gethrtime+0xa
drv_usecwait+0x7a
bge_chip_poll_engine+0x2e
bge_chip_disable_engine+0x50
bge_chip_stop+0xca
bge_chip_reset
+0x2d4
bge_reset+0xba
bge_restart+0x4c
bge_chip_factotum+0x140
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 21861 cpu[0]+6 bge_send+0x21b
nsec ------ Time Distribution ------ count Stack
32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 bge_m_tx+0x6d
aggr_m_tx+0x65
dls_tx+0xe
str_mdata_fastpath_put+0x1f
tcp_send_data
+0x650
tcp_rput_data
+0x1a95
squeue_enter_chain+0x16e
ip_input+0x18c
ip_rput+0xd9
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 12419 cpu[0]+6 pfrput+0x65
nsec ------ Time Distribution ------ count Stack
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 putnext+0x1f1
dld_str_rx_unitdata+0x2f
i_dls_link_ether_rx+0x153
mac_rx+0x46
aggr_recv_cb+0xe2
mac_rx+0x46
bge_receive+0x98
bge_intr+0xaf
av_dispatch_autovect+0x78
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 12202 cpu[0]+6
tsc_gethrtime_delta+0x24
nsec ------ Time Distribution ------ count Stack
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 gethrtime+0xa
drv_usecwait+0x7a
bge_chip_poll_engine+0x2e
bge_chip_disable_engine+0x50
bge_chip_stop+0xca
bge_chip_factotum+0x108
av_dispatch_softvect+0x62
dosoftint+0x32
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 753 cpu[0]+6
tsc_gethrtime_delta+0x41
nsec ------ Time Distribution ------ count Stack
1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 gethrtime+0xa
drv_usecwait+0x7a
bge_chip_poll_engine+0x2e
bge_chip_disable_engine+0x50
bge_chip_stop+0xca
bge_chip_factotum+0x108
av_dispatch_softvect+0x62
dosoftint+0x32
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 18446744073707043264 cpu[1]
anon_decref+0x27
nsec ------ Time Distribution ------ count Stack
anon_free+0x6d
segvn_free+0x1c1
seg_free+0x3f
segvn_unmap+0x54b
as_free+0xac
relvm+0x1f7
exec_args+0x1c5
elf32exec+0x34c
gexec+0x208
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 18446744073707042749 cpu[1]
kmem_cache_alloc+0x44
nsec ------ Time Distribution ------ count Stack
kmem_zalloc+0x3b
sata_pkt_alloc
+0x22
sata_scsi_init_pkt+0x143
scsi_init_pkt+0x44
sd_initpkt_for_uscsi+0x75
sd_start_cmds+0xa5
sd_core_iostart
+0x87
sd_uscsi_strategy+0xd6
sd_send_scsi_SYNCHRONIZE_CACHE+0x10f
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 18446744073707042811 cpu[1]
rw_enter+0x2b
nsec ------ Time Distribution ------ count Stack
thread_start+0x8
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 18446744073707043769 cpu[1]
rw_write_held+0x3
nsec ------ Time Distribution ------ count Stack
dnode_hold+0x14
dmu_bonus_hold
+0x2e
zfs_zget+0x54
zfs_vget+0x12c
fsop_vget+0xb
nfs3_fhtovp+0x69
rfs3_write+0x6e
common_dispatch
+0x5b8
rfs_dispatch+0x21
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 18446744073707044453 cpu[1]
(usermode)
nsec ------ Time Distribution ------ count Stack
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 18446744073707042731 cpu[1]
kcopy+0x2c
nsec ------ Time Distribution ------ count Stack
uiomove+0x93
struiocopyout+0xa1
kstrgetmsg+0x4d6
sotpi_recvmsg
+0x253
socktpi_read+0x84
fop_read+0x31
read+0x188
read32+0xe
sys_syscall32
+0x101
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 10816 cpu[0] hat_unlock+0x9
nsec ------ Time Distribution ------ count Stack
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
segmap_pageunlock+0xfa
wrip+0x44d
ufs_write+0x211
fop_write+0x31
pwrite64+0x198
sys_syscall32
+0x101
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 18446744073707042246 cpu[1]+11
lock_set+0x4
nsec ------ Time Distribution ------ count Stack
cv_block+0x96
cv_timedwait+0x7c
taskq_d_thread
+0xc5
thread_start+0x8
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 1231 cpu[0] (usermode)
nsec ------ Time Distribution ------ count Stack
2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 3528 cpu[0] deltamap_add+0x19f
nsec ------ Time Distribution ------ count Stack
4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 top_delta+0x61
bmap_write+0xd88
wrip+0x759
ufs_write+0x211
fop_write+0x31
pwrite64+0x198
sys_syscall32
+0x101
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 13765 cpu[0]+4
tsc_gethrtime_delta+0x24
nsec ------ Time Distribution ------ count Stack
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 gethrtime+0xa
drv_usecwait+0x7a
bge_poll_firmware+0x32
bge_chip_reset
+0x172
bge_reset+0xba
bge_restart+0x4c
bge_chip_factotum+0x140
av_dispatch_softvect+0x62
dosoftint+0x32
------------------------------------------------------------------------
-------
Count indv cuml rcnt nsec CPU+PIL Caller
1 0% 100% 0.00 12988 cpu[0]+4 intr_restore+0x2
nsec ------ Time Distribution ------ count Stack
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 gethrtime+0xa
drv_usecwait+0x7a
bge_chip_poll_engine+0x2e
bge_chip_disable_engine+0x50
bge_chip_stop+0xca
bge_chip_reset
+0x2d4
bge_reset+0xba
bge_restart+0x4c
bge_chip_factotum+0x140
------------------------------------------------------------------------
-------
Siegfried
_______________________________________________
networking-discuss mailing list
[email protected]
