The reason rfs3_{write|create} waiting longer in txg_wait_open is because
there is a syncing txg taking longer to complete.

You may want to trace and track the syncing txg to get the reason for the
delay.

--
Prabahar.

On Sun, Nov 23, 2008 at 05:51:44PM -0800, Amer Ather wrote:
> IHAC who is seeing very slow NFS transactions over ZFS. rfs3_write(), 
> rfs3_create() and others are taking in the order of 17-20 seconds to 
> complete. Profiling these transactions showing most of the time is spent 
> in txg_wait_open() - waiting for transaction group to open.
> 
> We tried "zfs_nocacheflush: but it did n't help. iostat showing good 
> service time (<10ms).
> 
> System is running Solaris 10 - 137137-09
> 
> 00000301b616ec00      3000813e168      3017b9e3798   2  59      6002296f966
>    PC: cv_wait+0x38    CMD:
>    mv camshot_081118_000029.jpg camshot_081118_000059.jpg 
> camshot_081118_000129.j
>    p
>    stack pointer for thread 301b616ec00: 2a104a9ceb1
>    [ 000002a104a9ceb1 cv_wait+0x38() ]
>      txg_wait_open+0x54()
>      zfs_write+0x34c()
>      fop_write+0x20()
>      write+0x268()
>      syscall_trap32+0xcc()
> 
> Timing txg_wait_open() shows:
> 
> txg_wait_open delay
>    DELAY
>             value  ------------- Distribution ------------- count
>        4294967296 |                                         0
>        8589934592 |@                                        1
>       17179869184 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  33
>       34359738368 |                                         0
> 
> txg_wait_open delay
>    DELAY
>             value  ------------- Distribution ------------- count
>         134217728 |                                         0
>         268435456 |@@                                       2
>         536870912 |                                         0
>        1073741824 |                                         0
>        2147483648 |@                                        1
>        4294967296 |                                         0
>        8589934592 |@@@@@@@                                  7
>       17179869184 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@           29
>       34359738368 |                                         0
> 
> DTrace script:
> #!/usr/sbin/dtrace -qs
> fbt::txg_wait_open:entry
> {
>   self->t = timestamp;
> }
> fbt::txg_wait_open:return
> /self->t/
> {
>    @a["DELAY"] = quantize(timestamp - self->t);
> }
> tick-5sec {
>        printf("\ntxg_wait_open delay");
>        printa(@a);
>        trunc(@a);
> }
> 
> 
> I have also profiled rfs3_write(), rfs3_create() and other using DTrace 
> and taken time delta and stack at each frame on all functions called by 
> rfs3_* and see txg_wait_open() is the one taking majority of the time.
> 
> Thanks,
> Amer.
> _______________________________________________
> zfs-discuss mailing list
> zfs-discuss@opensolaris.org
> http://mail.opensolaris.org/mailman/listinfo/zfs-discuss
_______________________________________________
zfs-discuss mailing list
zfs-discuss@opensolaris.org
http://mail.opensolaris.org/mailman/listinfo/zfs-discuss

Reply via email to