Problems with h2

h2 is the machine which was up first and thus users like it and feel homely there; h1 came later and takes a bit of the load, but the main load is still on h2 and it's puzzling why it's soo slow. Hardware wise the machine is not exceptionally large, but should be

Symptoms

h2 is one of two Condor submit nodes, the load is shared with HA set-up with h1. Right now h1 is running the negotiator, thus matchmaking is done on h1, while most jobs are submitted on h2.

Current stats:

% uptime
 08:25:03 up 13 days, 11:57, 15 users,  load average: 19.70, 37.23, 39.23

% iostat -x 15
Linux 2.6.27.7-storage (h2)     02/09/09

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           8.53    0.01   42.11   11.06    0.00   38.28

Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
sda               0.33    13.36  9.47 24.88  1720.23  1627.08    97.45     0.36   10.40   1.03   3.54
sda1              0.21     0.14  0.03  0.01     1.93     1.20    82.32     0.00   14.04   8.92   0.03
sda2              0.00     0.00  0.00  0.00     0.00     0.00     6.26     0.00    4.56   4.26   0.00
sda3              0.01     3.28  0.08  0.65     1.63    31.41    45.47     0.00    6.76   4.69   0.34
sda4              0.00     0.00  0.00  0.00     0.00     0.00     2.00     0.00    0.00   0.00   0.00
sda5              0.02     3.44  0.21  2.00     9.28    43.51    23.90     0.03   12.41   2.29   0.51
sda6              0.00     3.47  0.01  1.16     0.18    37.09    31.77     0.01    7.46   3.19   0.37
sda7              0.08     2.59  0.58  0.63    10.65    25.79    29.90     0.01    5.00   3.13   0.38
sda8              0.00     0.00  0.00  0.00     0.00     0.00    19.98     0.00   30.19  30.00   0.00
sda9              0.01     0.44  8.56 20.42  1696.56  1488.08   109.88     0.31   10.68   1.13   3.28

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          17.92    0.00   38.20   25.97    0.00   17.92

Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
sda               0.00    19.97  0.00 50.13     0.00  6186.68   123.41     0.30    5.90   2.15  10.79
sda1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda2              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda3              0.00     4.26  0.00  0.60     0.00    38.88    64.89     0.03   55.56  55.56   3.33
sda4              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda5              0.00     7.06  0.00  3.60     0.00    85.22    23.70     0.00    0.74   0.37   0.13
sda6              0.00     5.73  0.00  0.73     0.00    51.66    70.55     0.00    0.00   0.00   0.00
sda7              0.00     1.53  0.00  0.40     0.00    15.45    38.67     0.00    0.00   0.00   0.00
sda8              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sda9              0.00     1.40  0.00 44.81     0.00  5995.47   133.81     0.26    5.79   2.42  10.85

% netstat -tn | awk '{print $6}' | sort | uniq -c
      1
     47 CLOSE_WAIT
   8920 ESTABLISHED
     14 FIN_WAIT2
      1 Foreign
      4 SYN_SENT
      7 TIME_WAIT

% nfsstat -o all
Server packet stats:
packets    udp        tcp        tcpconn
1          1          0          0

Server rpc stats:
calls      badcalls   badauth    badclnt    xdrcall
1          0          0          0          0

Server reply cache:
hits       misses     nocache
0          0          1

Server file handle cache:
lookup     anon       ncachedir  ncachedir  stale
0          0          0          0          0

Server nfs v3:
null         getattr      setattr      lookup       access       readlink
1       100% 0         0% 0         0% 0         0% 0         0% 0         0%
read         write        create       mkdir        symlink      mknod
0         0% 0         0% 0         0% 0         0% 0         0% 0         0%
remove       rmdir        rename       link         readdir      readdirplus
0         0% 0         0% 0         0% 0         0% 0         0% 0         0%
fsstat       fsinfo       pathconf     commit
0         0% 0         0% 0         0% 0         0%

Client packet stats:
packets    udp        tcp        tcpconn
0          0          0          0

Client rpc stats:
calls      retrans    authrefrsh
418351344   405        13

Client nfs v3:
null         getattr      setattr      lookup       access       readlink
0         0% 39698419  9% 1506477   0% 14595868  3% 30741922  7% 40807     0%
read         write        create       mkdir        symlink      mknod
281981726 67% 26535885  6% 1506773   0% 45541     0% 41580     0% 0         0%
remove       rmdir        rename       link         readdir      readdirplus
580526    0% 5751      0% 68646     0% 821       0% 57560     0% 1261537   0%
fsstat       fsinfo       pathconf     commit
366871    0% 34259     0% 17129     0% 19340899  4%

Client nfs v4:
null         read         write        commit       open         open_conf
0         0% 0         0% 0         0% 0         0% 0         0% 0         0%
open_noat    open_dgrd    close        setattr      fsinfo       renew
0         0% 0         0% 0         0% 0         0% 0         0% 0         0%
setclntid    confirm      lock         lockt        locku        access
0         0% 0         0% 0         0% 0         0% 0         0% 0         0%
getattr      lookup       lookup_root  remove       rename       link
0         0% 0         0% 0         0% 0         0% 0         0% 0         0%
symlink      create       pathconf     statfs       readlink     readdir
0         0% 0         0% 0         0% 0         0% 0         0% 0         0%
server_caps  delegreturn
0         0% 0         0%

Problems

This box seems to be really slow doing open/close operations, see a open/close test page. Sample runs of timeout -1 60 strace -tt -c -p PID would reveal that open or stat would take a long time to respond (of the order of 200-500ms) while the corresponding NFS server was more or less idle.

Solution

One item is to move the log files of certain job types off NFS since these are often opened/closed thus this should already help a bit. However it's not yet clear to me why this machine is so much slower as compared to h1 under somewhat comparable loads.

-- CarstenAulbert - 09 Feb 2009