First system - Performance issues in directory read operations.

[blongman]

I've set up my first system, and I'm having some serious performance issues with directory read operations - over NFS and locally.

Example:

[root@storage01 /mnt/Primary/qa/datafiles]# time ls -aFl
total 20019979
drwxr-xr-x 2 root wheel 26 Mar 23 10:07 ./
drwxrwxrwx 4 root wheel 5 Mar 23 09:27 ../
-rw-r--r-- 1 root wheel 1073741824 Mar 23 09:38 datafile1.dat
<snipped>
-rw-r--r-- 1 root wheel 1073741824 Mar 23 09:46 datafile9.dat

real 0m13.063s
user 0m0.008s
sys 0m0.002s
[root@storage01 /mnt/Primary/qa/datafiles]#

This is for most directories most of the time.

I'm running on a 64 bit 8 core box with 16 gigs of ram, and three of these:

Model Family: Seagate Barracuda Green (Adv. Format)
Device Model: ST2000DL003-9VT166

Drive write performance seems fine - building a bunch of files to md5sum and test some disk fail scenarios with.

Running default raidz ZFS as my mounted/shared filesystem.

Am I completely missing something? I don't expect lightning directory operations over NFS mounts, but it seems like something here is pretty wrong.

Another question - instructions suggest using a USB stick for for booting - which I am. Is it addressed after boot? If it has any impact on performance, I may just switch to a proper SSD on the SATA bus for this - especially given the apparent fragility of USB Flash. Maybe there is a suggested USB flash that might not suffer from the same fragility?

Thanks,

-Ben

 

[peterh]

you did not mention how many files are in the directories.

In some scenarios ls will consult a userdatabase in order to convert UID/GID to user/group names, this
will take some time for each file, with lot's of files the delay can be significant

Regarding the USB-stick, when the system has booted there will be close to zero reads that affects
performance ( everything is loaded the system is in a "steady-state" )

 

[blongman]

you did not mention how many files are in the directories.

In some scenarios ls will consult a userdatabase in order to convert UID/GID to user/group names, this
will take some time for each file, with lot's of files the delay can be significant

Regarding the USB-stick, when the system has booted there will be close to zero reads that affects
performance ( everything is loaded the system is in a "steady-state" )

24 files in that directory. All owned by root:wheel. Usually after I read a directory, further reads are much faster, but initial reads taking a long time is a bit unsettling.

 

[blongman]

Again tried this. Same directory. Tested at 103 files, and then again at 106 files. All owned by root:wheel:

Code:

real	0m0.013s
user	0m0.007s
sys	0m0.004s
[root@storage01 /mnt/Primary/qa/datafiles]# time ls -aFlh
total 106455865
drwxr-xr-x  2 root  wheel   108B Mar 23 12:01 ./
drwxrwxrwx  4 root  wheel     5B Mar 23 09:27 ../
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:38 datafile1.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:49 datafile10.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:58 datafile100.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:58 datafile101.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:59 datafile102.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:59 datafile103.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 12:01 datafile104.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 12:01 datafile105.dat
-rw-r--r--  1 root  wheel   553M Mar 23 12:06 datafile106.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:49 datafile11.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:51 datafile12.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:51 datafile13.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:57 datafile14.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:57 datafile15.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:58 datafile16.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:59 datafile17.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:00 datafile18.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:00 datafile19.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:38 datafile2.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:05 datafile20.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:06 datafile21.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:06 datafile22.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:07 datafile23.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:08 datafile24.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:09 datafile25.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:13 datafile26.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:14 datafile27.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:15 datafile28.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:15 datafile29.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:39 datafile3.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:17 datafile30.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:17 datafile31.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:22 datafile32.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:23 datafile33.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:25 datafile34.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:25 datafile35.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:26 datafile36.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:26 datafile37.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:27 datafile38.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:32 datafile39.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:40 datafile4.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:33 datafile40.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:33 datafile41.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:35 datafile42.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:35 datafile43.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:37 datafile44.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:38 datafile45.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:39 datafile46.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:40 datafile47.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:45 datafile48.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:46 datafile49.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:40 datafile5.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:48 datafile50.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:49 datafile51.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:50 datafile52.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:51 datafile53.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:52 datafile54.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:52 datafile55.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:54 datafile56.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:54 datafile57.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:59 datafile58.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 10:59 datafile59.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:41 datafile6.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:00 datafile60.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:00 datafile61.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:02 datafile62.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:03 datafile63.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:08 datafile64.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:08 datafile65.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:10 datafile66.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:11 datafile67.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:11 datafile68.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:11 datafile69.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:41 datafile7.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:13 datafile70.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:13 datafile71.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:18 datafile72.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:19 datafile73.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:20 datafile74.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:20 datafile75.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:22 datafile76.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:22 datafile77.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:27 datafile78.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:28 datafile79.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:46 datafile8.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:30 datafile80.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:30 datafile81.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:31 datafile82.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:32 datafile83.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:33 datafile84.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:34 datafile85.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:38 datafile86.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:38 datafile87.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:39 datafile88.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:39 datafile89.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 09:46 datafile9.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:41 datafile90.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:41 datafile91.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:46 datafile92.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:46 datafile93.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:47 datafile94.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:47 datafile95.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:49 datafile96.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:50 datafile97.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:55 datafile98.dat
-rw-r--r--  1 root  wheel   1.0G Mar 23 11:55 datafile99.dat

real	2m37.901s
user	0m0.008s
sys	0m0.005s
[root@storage01 /mnt/Primary/qa/datafiles]# 

First try was fast, but the second one took 2.5 minutes.

 

[peterh]

will ls -n be faster ?

 

[blongman]

I ran multiple runs of:

ls -aFln

in a row, and after about the 4th or 5th one, it got stuck. About minute in now of waiting for it to return.

 

[blongman]

It eventually came back with a file list. Still really strange.

 

[blongman]

I set up a task to do a constant write to the zraid locally (no network involved) and I ran zpool iostat 1 while this was going on. The output patter I got looked like this:

Primary 420G 5.03T 0 101 0 12.7M
Primary 420G 5.03T 0 155 0 19.4M
Primary 420G 5.03T 0 55 0 6.92M
Primary 420G 5.03T 0 76 0 9.60M
Primary 420G 5.03T 0 24 0 3.12M
Primary 420G 5.03T 0 328 0 41.1M
Primary 420G 5.03T 0 31 0 3.80M
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 107 0 13.4M
Primary 420G 5.03T 0 133 0 16.7M
Primary 420G 5.03T 0 108 0 13.6M
Primary 420G 5.03T 0 44 0 5.58M
Primary 420G 5.03T 0 353 0 44.2M
Primary 420G 5.03T 0 5 0 686K
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 10 0 1.34M
Primary 420G 5.03T 0 30 0 3.79M
Primary 420G 5.03T 0 399 0 49.6M
Primary 420G 5.03T 0 260 0 32.6M
Primary 420G 5.03T 0 10 0 1.34M
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 0 0 0
Primary 420G 5.03T 0 48 0 6.03M
Primary 420G 5.03T 0 33 0 4.24M
Primary 420G 5.03T 0 55 0 6.92M
Primary 420G 5.03T 0 58 0 7.37M
Primary 420G 5.03T 0 42 0 5.36M
Primary 420G 5.03T 0 58 0 7.37M
Primary 420G 5.03T 0 10 0 1.34M
Primary 420G 5.03T 0 149 0 18.7M
Primary 420G 5.03T 0 348 0 43.5M

 

[peterh]

check smartctl -a if disks are reporting problems. If not use another disc-controller ( some cheap multiport sata
is probably the best )

 

[blongman]

I have the data, but I don't know how to read it.

I'm using one of these, but have a spare:

LSISAS 1068E LSI LSI00194

I suppose I could have found a card that works for the rest of my systems that FreeNAS isn't happy with.

=== START OF INFORMATION SECTION ===
Model Family: Seagate Barracuda Green (Adv. Format)
Device Model: ST2000DL003-9VT166
Serial Number:
LU WWN Device Id: 5 000c50 0464e4ca9
Firmware Version: CC3C
User Capacity: 2,000,398,934,016 bytes [2.00 TB]
Sector Sizes: 512 bytes logical, 4096 bytes physical
Device is: In smartctl database [for details use: -P show]
ATA Version is: 8
ATA Standard is: ATA-8-ACS revision 4
Local Time is: Sat Mar 24 10:40:06 2012 PDT
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

General SMART Values:
Offline data collection status: (0x82) Offline data collection activity
was completed without error.
Auto Offline Data Collection: Enabled.
Self-test execution status: ( 0) The previous self-test routine completed
without error or no self-test has ever
been run.
Total time to complete Offline
data collection: ( 612) seconds.
Offline data collection
capabilities: (0x7b) SMART execute Offline immediate.
Auto Offline data collection on/off support.
Suspend Offline collection upon new
command.
Offline surface scan supported.
Self-test supported.
Conveyance Self-test supported.
Selective Self-test supported.
SMART capabilities: (0x0003) Saves SMART data before entering
power-saving mode.
Supports SMART auto save timer.
Error logging capability: (0x01) Error logging supported.
General Purpose Logging supported.
Short self-test routine
recommended polling time: ( 1) minutes.
Extended self-test routine
recommended polling time: ( 255) minutes.
Conveyance self-test routine
recommended polling time: ( 2) minutes.
SCT capabilities: (0x30b7) SCT Status supported.
SCT Feature Control supported.
SCT Data Table supported.

SMART Attributes Data Structure revision number: 10
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME FLAG VALUE WORST THRESH TYPE UPDATED WHEN_FAILED RAW_VALUE
1 Raw_Read_Error_Rate 0x000f 100 100 006 Pre-fail Always - 401088
3 Spin_Up_Time 0x0003 084 084 000 Pre-fail Always - 0
4 Start_Stop_Count 0x0032 100 100 020 Old_age Always - 10
5 Reallocated_Sector_Ct 0x0033 100 100 036 Pre-fail Always - 0
7 Seek_Error_Rate 0x000f 100 253 030 Pre-fail Always - 120259182093
9 Power_On_Hours 0x0032 100 100 000 Old_age Always - 281
10 Spin_Retry_Count 0x0013 100 100 097 Pre-fail Always - 0
12 Power_Cycle_Count 0x0032 100 100 020 Old_age Always - 10
183 Runtime_Bad_Block 0x0032 100 100 000 Old_age Always - 0
184 End-to-End_Error 0x0032 100 100 099 Old_age Always - 0
187 Reported_Uncorrect 0x0032 100 100 000 Old_age Always - 0
188 Command_Timeout 0x0032 100 100 000 Old_age Always - 0
189 High_Fly_Writes 0x003a 100 100 000 Old_age Always - 0
190 Airflow_Temperature_Cel 0x0022 076 073 045 Old_age Always - 24 (Min/Max 24/26)
191 G-Sense_Error_Rate 0x0032 100 100 000 Old_age Always - 0
192 Power-Off_Retract_Count 0x0032 100 100 000 Old_age Always - 9
193 Load_Cycle_Count 0x0032 100 100 000 Old_age Always - 10
194 Temperature_Celsius 0x0022 024 040 000 Old_age Always - 24 (0 22 0 0)
195 Hardware_ECC_Recovered 0x001a 100 100 000 Old_age Always - 401088
197 Current_Pending_Sector 0x0012 100 100 000 Old_age Always - 0
198 Offline_Uncorrectable 0x0010 100 100 000 Old_age Offline - 0
199 UDMA_CRC_Error_Count 0x003e 200 200 000 Old_age Always - 0
240 Head_Flying_Hours 0x0000 100 253 000 Old_age Offline - 14963666059545
241 Total_LBAs_Written 0x0000 100 253 000 Old_age Offline - 3939591173
242 Total_LBAs_Read 0x0000 100 253 000 Old_age Offline - 118414

SMART Error Log Version: 1
No Errors Logged

SMART Self-test log structure revision number 1
Num Test_Description Status Remaining LifeTime(hours) LBA_of_first_error
# 1 Short offline Completed without error 00% 272 -
# 2 Short offline Completed without error 00% 248 -
# 3 Short offline Completed without error 00% 224 -
# 4 Short offline Completed without error 00% 200 -
# 5 Short offline Completed without error 00% 176 -
# 6 Short offline Completed without error 00% 152 -
# 7 Short offline Completed without error 00% 128 -
# 8 Short offline Completed without error 00% 104 -
# 9 Short offline Completed without error 00% 80 -

SMART Selective self-test log data structure revision number 1
SPAN MIN_LBA MAX_LBA CURRENT_TEST_STATUS
1 0 0 Not_testing
2 0 0 Not_testing
3 0 0 Not_testing
4 0 0 Not_testing
5 0 0 Not_testing
Selective self-test flags (0x0):
After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.

[root@storage01 ~]#

 

[blongman]

Replacing the LSI card when I'm out at the facility tomorrow. Any other thoughts on what this might be?