Robert Milkowski wrote On 08/01/06 11:41,:
Hello Robert,
Monday, July 31, 2006, 12:48:30 AM, you wrote:
RM> Hello ZFS,
RM> System was rebooted and after reboot server again
RM> System is snv_39, SPARC, T2000
RM> bash-3.00# ptree
RM> 7 /lib/svc/bin/svc.startd -s
RM> 163 /sbin/sh /lib/svc/method/fs-local
RM> 254 /usr/sbin/zfs mount -a
RM> [...]
RM> bash-3.00# zfs list|wc -l
RM> 46
RM> Using df I can see most file systems are already mounted.
RM>
::ps!grep zfs
RM> R 254 163 7 7 0 0x4a004000 00000600219e1800 zfs
00000600219e1800::walk thread|::findstack -v
RM> stack pointer for thread 300013026a0: 2a10069ebb1
RM> [ 000002a10069ebb1 cv_wait+0x40() ]
RM> 000002a10069ec61 txg_wait_synced+0x54(3000052f0d0, 2f2216d,
RM> 3000107fb90, 3000052f110, 3000052f112, 3000052f0c8)
RM> 000002a10069ed11 zil_replay+0xbc(60022609c08, 600226a1840,
RM> 600226a1870, 700d13d8, 7ba2d000, 60006821200)
RM> 000002a10069ee01 zfs_domount+0x1f0(7ba35000, 700d1000, 60021a8bae0, 1, 0,
0)
RM> 000002a10069eed1 zfs_mount+0x160(600225f6080, 1868800, 2a10069f9d8,
60021a8bae0, 2f, 0)
RM> 000002a10069efb1 domount+0x9b0(2a10069f8b0, 1, 600225f6080, 0, 0, 0)
RM> 000002a10069f121 mount+0x110(600013fbcf8, 2a10069fad8, 0, 0, ff38e40c,
100)
RM> 000002a10069f221 syscall_ap+0x44(2a0, ffbfeca0, 1118bf4, 600013fbc40, 15,
0)
RM> 000002a10069f2e1 syscall_trap32+0xcc(52b3c8, ffbfeca0, 100, ff38e40c, 0,
0)
RM> # iostat -xnz 1
RM> extended device statistics
RM> r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device
RM> 3.0 513.0 192.0 2822.1 0.0 2.1 0.0 4.0 0 95
RM> c4t600C0FF00000000009258F3E4C4C5601d0
RM> extended device statistics
RM> r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device
RM> 7.0 598.1 388.6 1832.9 0.0 2.0 0.0 3.4 0 93
RM> c4t600C0FF00000000009258F3E4C4C5601d0
RM> ^C
RM> bash-3.00#
RM> However for many seconds no IOs at all are issued.
RM> # mpstat 1
RM> [...]
RM> CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl
RM> 0 0 0 74 209 109 0 0 0 0 0 0 0 1 0 99
RM> 1 0 0 0 1 0 0 0 0 0 0 0 0 0 0 100
RM> 2 0 0 0 1 0 0 0 0 0 0 0 0 0 0 100
RM> 3 0 0 0 1 0 0 0 0 0 0 0 0 100 0 0
RM> 4 0 0 0 1 0 0 0 0 0 0 0 0 0 0 100
RM> 5 0 0 0 6 1 8 0 0 0 0 0 0 0 0 100
RM> 6 0 0 0 1 0 0 0 0 0 0 0 0 0 0 100
RM> 7 0 0 0 1 0 0 0 0 0 0 0 0 0 0 100
RM> 8 3 0 1 7 0 12 0 0 2 0 245 1 1 0 98
RM> 9 0 0 0 1 0 0 0 0 0 0 0 0 0 0 100
RM> 10 0 0 0 1 0 0 0 0 0 0 0 0 0 0 100
RM> 11 0 0 0 1 0 0 0 0 0 0 0 0 0 0 100
RM> 12 0 0 0 1 0 0 0 0 0 0 0 0 0 0 100
RM> 13 0 0 0 6 0 10 0 0 0 0 0 0 0 0 100
RM> 14 0 0 0 3 0 2 1 0 0 0 188 0 1 0 99
RM> 15 0 0 0 1 0 0 0 0 0 0 0 0 0 0 100
RM> 16 0 0 0 8 1 12 0 0 0 0 0 0 0 0 100
RM> 17 0 0 0 7 0 12 0 0 0 0 0 0 0 0 100
RM> 18 0 0 0 23 0 43 0 0 1 0 0 0 0 0 100
RM> 19 0 0 0 9 0 16 0 0 0 0 0 0 0 0 100
RM> 20 0 0 0 8 0 14 0 0 0 0 0 0 0 0 100
RM> 21 0 0 0 7 2 8 0 1 0 0 1 0 1 0 99
RM> 22 0 0 17 38 34 7 0 1 1 0 5 0 0 0 100
RM> 23 0 0 0 7 0 12 0 0 0 0 0 0 0 0 100
RM> 24 0 0 0 4 0 6 0 1 0 0 0 0 0 0 100
RM> 25 0 0 1 5 0 8 0 1 0 0 0 0 0 0 100
RM> 26 0 0 0 2 0 2 0 0 0 0 0 0 0 0 100
RM> 27 0 0 0 2 0 2 0 0 0 0 0 0 0 0 100
RM> 28 0 0 0 2 0 2 0 0 1 0 0 0 0 0 100
RM> 29 0 0 0 1 0 0 0 0 0 0 0 0 0 0 100
RM> 30 0 0 0 1 0 0 0 0 0 0 0 0 0 0 100
RM> 31 0 0 0 6 0 8 0 0 0 0 0 0 0 0 100
RM> ^C
RM> bash-3.00#
RM> # dtrace -n fbt:::entry'{self->t=timestamp;}' -n
RM> fbt:::return'/self->t/[EMAIL PROTECTED](timestamp-self->t);self->t=0;}' -n
tick-5s'{printa(@);exit(0);}'
RM> [...]
RM> syscall_mstate 12636328
RM> callout_schedule_1 14428108
RM> hwblkclr 16656308
RM> avl_rotation 17196252
RM> page_pptonum 19457456
RM> sfmmu_mlist_enter 20078508
RM> sfmmu_mlist_exit 20804176
RM> page_numtomemseg_nolock 23377972
RM> avl_insert 23727512
RM> avl_insert_here 25281752
RM> sfmmu_mlspl_enter 32277524
RM> kmem_cache_alloc 38497240
RM> xc_serv 94880184
RM> disp_getwork 118366960
RM> disp_anywork 191004096
RM> space_map_seg_compare 573117700
RM> resume 7059674296
RM> #
RM> bash-3.00# dtrace -n
RM> fbt::space_map_seg_compare:entry'[EMAIL PROTECTED]()]=count();}'
RM> dtrace: description 'fbt::space_map_seg_compare:entry' matched 1 probe
RM> ^C
RM> genunix`avl_find+0x38
RM> zfs`space_map_add+0x12c
RM> zfs`space_map_load+0x214
RM> zfs`metaslab_activate+0x3c
RM> zfs`metaslab_group_alloc+0x1b0
RM> zfs`metaslab_alloc_dva+0x10c
RM> zfs`metaslab_alloc+0x2c
RM> zfs`zio_dva_allocate+0x50
RM> zfs`zio_write_compress+0x1e4
RM> zfs`arc_write+0xbc
RM> zfs`dbuf_sync+0x6b0
RM> zfs`dnode_sync+0x300
RM> zfs`dmu_objset_sync_dnodes+0x68
RM> zfs`dmu_objset_sync+0x50
RM> zfs`dsl_dataset_sync+0xc
RM> zfs`dsl_pool_sync+0x60
RM> zfs`spa_sync+0xe0
RM> zfs`txg_sync_thread+0x130
RM> unix`thread_start+0x4
RM> 316769
RM> genunix`avl_find+0x38
RM> zfs`space_map_remove+0x98
RM> zfs`space_map_load+0x214
RM> zfs`metaslab_activate+0x3c
RM> zfs`metaslab_group_alloc+0x1b0
RM> zfs`metaslab_alloc_dva+0x10c
RM> zfs`metaslab_alloc+0x2c
RM> zfs`zio_dva_allocate+0x50
RM> zfs`zio_write_compress+0x1e4
RM> zfs`arc_write+0xbc
RM> zfs`dbuf_sync+0x6b0
RM> zfs`dnode_sync+0x300
RM> zfs`dmu_objset_sync_dnodes+0x68
RM> zfs`dmu_objset_sync+0x50
RM> zfs`dsl_dataset_sync+0xc
RM> zfs`dsl_pool_sync+0x60
RM> zfs`spa_sync+0xe0
RM> zfs`txg_sync_thread+0x130
RM> unix`thread_start+0x4
RM> 404210
RM> bash-3.00#
RM> Above was running for 3-4seconds
RM> I can see some progress - I mean it mounts another filesystem in every
RM> 3-10 minutes.
RM> However overall it could take even over an hour to boot server before
RM> zfs mount -a mounts actually all file systems. Also with default
RM> Solaris configs during this stage you can't login either from console
RM> or ssh and no messages are issued. That is bad also as you don't know
RM> what is going on. We had to reboot again, boot to single user, run
RM> sshd, login via ssh and let boot process to proceed in order to see
RM> why server won't boot.
RM> Using zpool status all pools are ok and no errors at all are reported.
RM> Summary:
RM> 1. zfs mount -a shouldn't "sleep" 1h!
RM> 2. one virtual CPU core of T2000 1GH is consumed for
RM> most of the time during zfs mount -a - why is it so CPU
RM> intensive? On that server CPU became limiting in that way
RM> that usually no IOs were issued to disks during mount.
RM> When it happened on faster CPU disks were doing 100MB/s,
RM> but still it took 10-20 minutes to zfs mount disks.
RM> 3. I thought zfs mount problem so it exits earlier was already
RM> addressed. So this is completely new or still something wrong is
RM> going on. I'm thinking about
RM> http://bugs.opensolaris.org/bugdatabase/view_bug.do?bug_id=6377670
RM> 4. Would be better if zfs mount -a would actually do it in parallel
RM> as it looks like it mounts in serial fashion right now
RM> Above behavior is really BAD and it makes ZFS looks like fsck is
RM> actually build-in - I know it isn't.
RM>
Any ideas?
It looks to me like the mount code before replaying the log flushes all
transactions in the group (txg_wait_synced()) to get some consistency.
This then takes a very long time - searching the space map perhaps because
it's nearly full. Is it?
If this is true, I'm not sure what can be done - I'm not a SPA expert.
However, a bug should be raised as this isn't acceptable behaviour.
Neil
_______________________________________________
zfs-discuss mailing list
zfs-discuss@opensolaris.org
http://mail.opensolaris.org/mailman/listinfo/zfs-discuss
