[OpenAFS-devel] performance study

[chas williams - CONTRACTOR]

In message <20050214225610.GA14582@bismuth.club.cc.cmu.edu>,"John S. Bucy" writ
es:
>3.  volserver.  Volume moves seem to be slow and at least the last
>time I brought it up at a celladmin meeting, noone seemed to know why.
>jhutz said (IIRC) that the various pieces had been tested in isolation
>and were ok when tested piecewise, so apparently there's some weird
>interaction in the whole system.

actually i believe its more the fault of filesever.  at one point i 
did some profiling (solaris was the o/s of choice).  the flat profiles
for some volumes moves and long read/write operation are attached at 
the end.  

if afs performed well i would call fileserver highly optimized (since any
afs specific routine is quite a way down on the list).  since afs doesnt
perform well its obviously spending too much time getting data from user
space to the kernel and out the network adapter.  readv/writev is not
the most efficient way to move data in/out the kernel.  but further it
looks like the the scatter/gather in sendmsg/recvmsg isnt very efficient
either.  i would blame most of this on the rx's atomic unit, ~1400 bytes.
need to move 8k?  even if its contiguous in memory, rx is going to break
it into an 6 element iovec.  to get this in/out of the kernel thats 
going to be 9 seperate copies instead of 1.

   %  cumulative    self              self    total
 time   seconds   seconds    calls  ms/call  ms/call name
 16.8      23.98    23.98   304912     0.08     0.08  _so_sendmsg [6]
 16.3      47.21    23.23                            _readv [7]
 15.1      68.80    21.59   545544     0.04     0.04  _so_recvmsg [9]
 11.1      84.71    15.91                            _writev [13]
  5.9      93.18     8.47  2538611     0.00     0.00  _time [25]
  5.5     101.09     7.91                            _mcount (2066)
  3.6     106.21     5.12                            oldarc [29]
  3.5     111.15     4.94   425481     0.01     0.05  rxi_ReceiveAckPacket [8]


   %  cumulative    self              self    total
 time   seconds   seconds    calls  ms/call  ms/call name
 19.8      30.81    30.81   487873     0.06     0.06  _so_sendmsg [7]
 14.4      53.18    22.37   540918     0.04     0.04  _so_recvmsg [12]
  9.8      68.45    15.27                            _readv [17]
  8.9      82.28    13.83                            _writev [18]
  7.3      93.59    11.31                            _mcount (2067)
  5.9     102.80     9.21  2632981     0.00     0.00  _time [25]
  4.8     110.29     7.49                            oldarc [27]
  2.4     114.05     3.76   528660     0.01     0.06  rxi_ReadPacket [9]

   %  cumulative    self              self    total
 time   seconds   seconds    calls  ms/call  ms/call name
 33.8       4.55     4.55                            _writev [3]
 19.6       7.19     2.64    31073     0.08     0.08  _so_recvmsg [9]
 15.7       9.30     2.11    45378     0.05     0.05  _so_sendmsg [12]
  7.1      10.26     0.96   269520     0.00     0.00  _time [19]
  3.3      10.70     0.44                            _mcount (2065)
  2.6      11.05     0.35                            oldarc [22]
  2.4      11.38     0.33   186396     0.00     0.00  fc_ecb_encrypt [21]

   %  cumulative    self              self    total
 time   seconds   seconds    calls  ms/call  ms/call name
 22.1       8.00     8.00   112996     0.07     0.07  _so_sendmsg [9]
 13.8      12.99     4.99   132275     0.04     0.04  _so_recvmsg [16]
 12.4      17.47     4.48                            _readv [17]
  6.8      19.94     2.47                            _mcount (2066)
  6.4      22.26     2.32   534844     0.00     0.00  _time [22]
  4.3      23.83     1.57                            oldarc [23]
  2.7      24.79     0.96   130428     0.01     0.05  rxi_ReadPacket [13]

   %  cumulative    self              self    total
 time   seconds   seconds    calls  ms/call  ms/call name
 25.6       3.15     3.15                            _readv [5]
 17.2       5.27     2.12    22223     0.10     0.10  _so_sendmsg [12]
 12.3       6.78     1.51    46493     0.03     0.03  _so_recvmsg [16]
  7.4       7.69     0.91                            _mcount (2065)
  5.3       8.34     0.65   211308     0.00     0.00  _time [20]
  4.1       8.85     0.51    44031     0.01     0.07  rxi_ReceiveAckPacket [4]