zfs discuss - Jul 2006 - ON build on Blade 1500 ATA disk extremely slow

I''ve recently started doing ON nightly builds on zfs filesystems on the
internal ATA disk of a Blade 1500 running snv_42.  Unfortunately, the
builds are extremely slow compared to building on an external IEEE 1394
disk attached to the same machine:

ATA disk:

==== Elapsed build time (DEBUG) ===
real 21:40:57.7
user  4:32:15.6
sys   8:22:24.1

IEEE 1394 disk:

==== Elapsed build time (DEBUG) ===
real  6:14:11.4
user  4:28:54.1
sys     36:04.1

Running kernel profile with lockstat (lockstat -kIW -D 20 sleep 300), I
find in the ATA case:

Profiling interrupt: 29117 events in 300.142 seconds (97 events/sec)

Count indv cuml rcnt     nsec Hottest CPU+PIL        Caller                  
-------------------------------------------------------------------------------
15082  52%  52% 0.00     1492 cpu[0]                 (usermode)              
 9565  33%  85% 0.00      318 cpu[0]                 usec_delay              

compared to IEEE 1394:

Profiling interrupt: 29195 events in 300.969 seconds (97 events/sec)

Count indv cuml rcnt     nsec Hottest CPU+PIL        Caller                  
-------------------------------------------------------------------------------
20042  69%  69% 0.00     2000 cpu[0]                 (usermode)              
 5414  19%  87% 0.00      317 cpu[0]                 usec_delay              

At other times, the kernel time can be even as high as 80%.  Unfortunately,
I''ve not been able to investigate how usec_delay is called since
there''s no
fbt provider for that function (nor for the alternative entry point
drv_usecwait found in uts/sun4[uv]/cpu/common_asm.s), so I''m a bit
stuck
how to further investigate this.  I suspect that the dad(7D) driver is the
culprit, but it is only included in the closed tarball.  In the EDU S9
sources, I find that dcd_flush_cache() calls drv_usecwait(1000000), which
might be the cause of this.

How should I proceed to further investigate this, and can this be fixed
somehow?  This way, the machine is almost unusable as a build machine.

	Rainer

-----------------------------------------------------------------------------
Rainer Orth, Faculty of Technology, Bielefeld University

On Tue, 2006-07-25 at 13:45, Rainer Orth wrote:
> At other times, the kernel time can be even as high as 80%.  Unfortunately,
> I''ve not been able to investigate how usec_delay is called since
there''s no
> fbt provider for that function (nor for the alternative entry point
> drv_usecwait found in uts/sun4[uv]/cpu/common_asm.s), so I''m a bit
stuck
> how to further investigate this.  I suspect that the dad(7D) driver is the
> culprit, but it is only included in the closed tarball.  In the EDU S9
> sources, I find that dcd_flush_cache() calls drv_usecwait(1000000), which
> might be the cause of this.
In the future, you can try:

# lockstat -s 10 -I sleep 10

which aggregates on the full stack trace, not just the caller, during
profiling interrupts.  (-s 10 sets the stack depth; tweak up or down to
taste).
> How should I proceed to further investigate this, and can this be fixed
> somehow?  This way, the machine is almost unusable as a build machine.
you''ve rediscovered 

6421427 netra x1 slagged by NFS over ZFS leading to long spins in the
ATA driver code

I''ve updated the bug to indicate that this wass seen on the Sun Blade
1500 as well.

						- Bill

Bill,
> In the future, you can try:
> 
> # lockstat -s 10 -I sleep 10
> 
> which aggregates on the full stack trace, not just the caller, during
> profiling interrupts.  (-s 10 sets the stack depth; tweak up or down to
> taste).
nice.  Perhaps lockstat(1M) should be updated to include something like
this in the EXAMPLES section.
> > How should I proceed to further investigate this, and can this be
fixed
> > somehow?  This way, the machine is almost unusable as a build machine.
> 
> you''ve rediscovered 
> 
> 6421427 netra x1 slagged by NFS over ZFS leading to long spins in the
> ATA driver code
> 
> I''ve updated the bug to indicate that this wass seen on the Sun
Blade
> 1500 as well.
Ok, thanks.  One important difference compared to that CR is that those
were local accesses to the FS, but the stack traces from lockstat are
identical.

Any word when this might be fixed?

Thanks.
	Rainer

-----------------------------------------------------------------------------
Rainer Orth, Faculty of Technology, Bielefeld University

On Tue, 2006-07-25 at 14:36, Rainer Orth wrote:
>  Perhaps lockstat(1M) should be updated to include something like
> this in the EXAMPLES section.
I filed 6452661 with this suggestion.
> Any word when this might be fixed?
I can''t comment in terms of time, but the engineer working on it has a
partially tested fix; he needs to complete testing and integrate the
fix..  not clear how long this will take. 

					- Bill

Bill,
> On Tue, 2006-07-25 at 14:36, Rainer Orth wrote:
> >  Perhaps lockstat(1M) should be updated to include something like
> > this in the EXAMPLES section.
> 
> I filed 6452661 with this suggestion.
excellent, thanks.
> > Any word when this might be fixed?
> 
> I can''t comment in terms of time, but the engineer working on it
has a
> partially tested fix; he needs to complete testing and integrate the
> fix..  not clear how long this will take. 
No problem: I can use that IEEE 1394 disk for now.  Good to know that this
is being worked on, though.

	Rainer

-----------------------------------------------------------------------------
Rainer Orth, Faculty of Technology, Bielefeld University