Look what you started - 

Re sysstat: Yes (although not such a sustained CP time) - yours show CP type '#' 
# continuation of CP from previous interval, and the NVLog for the next CP is now full, so that the next CP will be of type B. 

we had a case open on a 8.1 3270 cluster which experienced a latency spike.

The assigned engineer after several iterations explained it was the slow CPs on our SATA aggregate which was killing us.
The fact is NVRAM is shared across aggregates and the weakest link will be your slowest aggregate (SATA in our case).
The CPs will "starve out" other IO (for the WHOLE CLUSTER - not just the SATA) until they are complete (data preservation is the prime directive) - I have a Perf Advisor snapshot showing IO cratering during the CP.

This realization, that mixing SATA with SAS/FC in the same cluster can lead to NVRAM/CP inducing latency spikes for the whole cluster (imagine an oracle dump to the SATA aggr tipping over hundreds of VMs on the SAS aggr) - has lead us to migrate the SATA to a physically separate 2240 cluster.

Keep in mind, there can also be bugs (some not public) which may contribute to these issues.

Disclaimer: No one I know has access to the source code to ONTAP so I could be completely wrong - this is pieced together from semi-transparent info exchange with technical support and several years of inductive reasoning in this space.

Fletcher.

On Apr 10, 2013, at 3:46 PM, Peta Thames <petathames@gmail.com> wrote:

Hi all,

Has anyone seen this pattern in a sysstat before?

TOASTERa> sysstat -u 1
 CPU   Total     Net   kB/s    Disk   kB/s    Tape   kB/s  Cache  Cache    CP  CP  Disk
       ops/s      in    out    read  write    read  write    age    hit  time  ty  util
 29%   36942       1      0     264      0       0      0     7s    91%  100%  #   100%
 29%   36896       1      0    1616      0       0      0     7s    90%  100%  #   100%
 28%   36658       1      0      32     24       0      0     7s   100%  100%  #   100%
 28%   36625       1      0     108      0       0      0     7s    97%  100%  #   100%
 27%   36318       1      0     136      8       0      0     7s   100%  100%  #   100%
 28%   36391       1      0     364    144       0      0     7s    97%  100%  #   100%
 25%   30387       1      0      88      0       0      0     7s    98%  100%  #   100%
 21%   24450       1      0       8      0       0      0     7s   100%  100%  #   100%
 20%   22042       1      0      24    672       0      0     7s   100%  100%  #   100%
 18%   19781       1      0     284      8       0      0     7s    69%  100%  #   100%
 18%   19636       1      0       0      0       0      0     7s   100%  100%  #   100%
 16%   18066       1      0      24     24       0      0     7s   100%  100%  #   100%
 15%   16999       1      0      56      0       0      0     7s    56%  100%  #   100%
 15%   16622       1      0   11040   6496       0      0     7s    46%  100%  #   1824%
 14%   15947       1      0      24     32       0      0     7s   100%  100%  #   100%
 14%   15448       0      0       0      0       0      0     7s   100%  100%  #   100%
 14%   15902       0      0    3304   4532       0      0     7s    88%  100%  #   100%
 14%   15800       0      0      32     24       0      0     7s   100%  100%  #   100%
 15%   16651       0      0       0      0       0      0     7s   100%  100%  #   100%
 CPU   Total     Net   kB/s    Disk   kB/s    Tape   kB/s  Cache  Cache    CP  CP  Disk
       ops/s      in    out    read  write    read  write    age    hit  time  ty  util
 14%   15778       0      0    1520   2932       0      0     7s   100%  100%  #   100%
 13%   14311       0      1      28     24       0      0     7s   100%  100%  #   100%
 12%   12153       0      0       0      0       0      0     7s   100%  100%  #   100%
 12%   11993       0      0       8      0       0      0     7s   100%  100%  #   100%
 12%   12134       0      0    7368   5996       0      0     7s    18%  100%  #   100%
 13%   11981       0      0   20356  14956       0      0     7s   100%  100%  #   100%
 12%   11978       0      0       0      0       0      0     7s   100%  100%  #   100%
 11%   11617       0      0      24     24       0      0     7s   100%  100%  #   100%
 12%   11708       0      0       8      0       0      0     7s   100%  100%  #   100%
 11%   11630       0      0   11936  17872       0      0     7s   100%  100%  #   100%
 11%   11639       0      0      24     32       0      0     7s   100%  100%  #   100%
 12%   11791       0      0      12      0       0      0     7s    87%  100%  #   100%
 22%   11874       0      0   64452  92188       0      0     7s   100%  100%  #   100%
 12%   12015       0      0      32     24       0      0     7s   100%  100%  #   100%
 12%   11954       0      0     556      0       0      0     7s    85%  100%  #   100%
 12%   11899       0      0       0      8       0      0     7s   100%  100%  #   100%
 13%   13408       0      0   23816  35600       0      0     7s    91%  100%  #   100%
 13%   14610       0      0       0      0       0      0     7s   100%  100%  #   100%
 14%   15355       0      0    1248      0       0      0     7s    72%  100%  #   100%
 14%   15584       0      0   18652  15224       0      0     7s    98%  100%  #   100%
 CPU   Total     Net   kB/s    Disk   kB/s    Tape   kB/s  Cache  Cache    CP  CP  Disk
       ops/s      in    out    read  write    read  write    age    hit  time  ty  util
 14%   15397       0      0       0      8       0      0     7s   100%  100%  #   100%
 15%   15859       0      1       0      0       0      0     7s   100%  100%  #   100%
 14%   15557       0      0    4944   4568       0      0     7s   100%  100%  #   100%
 14%   15559       0      0       8      0       0      0     7s   100%  100%  #   100%
 14%   15603       0      0       0      0       0      0     7s   100%  100%  #   100%
 14%   15507       0      0    3652   4724       0      0     7s   100%  100%  #   100%
 14%   15593       0      0      20      0       0      0     7s    75%  100%  #   100%
 12%   12571       0      0     268      0       0      0     7s   100%  100%  #   100%
 10%    9962       0      0      92   2072       0      0     7s    96%  100%  #   100%
  9%    8521       0      0       0      0       0      0     7s   100%  100%  #   100%
  8%    7680       0      0       4      8       0      0     7s   100%  100%  #   100%
  8%    7459       0      0      24     24       0      0     7s   100%  100%  #   100%
  8%    7050       0      0    2580   1600       0      0     7s   100%  100%  #   100%
  8%    6961       0      0       8      0       0      0     7s   100%  100%  #   100%
  8%    6954       0      0      24     24       0      0     7s   100%  100%  #   100%
  7%    6936       0      0     584   2400       0      0     7s   100%  100%  #   100%
  8%    7043       0      0     248      0       0      0     7s     0%  100%  #   100%
  7%    6946       0      0      24     24       0      0     7s   100%  100%  #   100%
  8%    7320       0      0    1860   7252       0      0     7s   100%  100%  #   100%
 55%   19882       2      2   89920  29733       0      0     1     86%   99%  B    45%
 CPU   Total     Net   kB/s    Disk   kB/s    Tape   kB/s  Cache  Cache    CP  CP  Disk
       ops/s      in    out    read  write    read  write    age    hit  time  ty  util
 88%   17409      31    187  267319 196942       0      0     6s    83%  100%  :    89%
 87%   16064      11    249  304646 192912       0      0     1     78%  100%  :    85%
 85%    6274      70     86  322234 233245       0      0     1     81%  100%  #    87%
 85%   12486      18    340  236474 102383       0      0     3s    82%  100%  B    73%
 98%   13842       3     29  247937 255188       0      0     2s    85%  100%  :    80%
 99%   17878       1      1  348355 223367       0      0     3s    84%  100%  #    86%
 99%    4117       1      1  359628 269212       0      0     3s    78%  100%  #    92%
 83%   12622      10     31  252272 170064       0      0     2s    83%  100%  B    73%
 94%   19321       4     10  248864 249292       0      0     2s    88%  100%  :    96%
 99%   15893       0      0  318375 261482       0      0     2s    85%  100%  :    89%
 88%   13326      34     76  284960 194032       0      0     2s    82%  100%  B    90%
 86%   11106      73    104  267760 231524       0      0     2s    81%  100%  :   100%
 72%   11160       0      0  206927 128869       0      0     3s    75%  100%  :   100%
 63%   11304       0      0  220736  25276       0      0     3s    67%  100%  :   100%
 68%   11216       0      0  193324  15184       0      0     3s    66%  100%  :   100%
 65%   11343       0      0  175120  12588       0      0     3s    60%  100%  :   100%
 52%    7384       0      0  205780 104564       0      0     3s    61%  100%  #   100%
 83%    7205       0      0  261108 178256       0      0     3s    74%  100%  B    90%
 75%   11256       0      0  225164  96332       0      0     3s    76%  100%  :    93%
 99%    6279       0      0  296056 251191       0      0     2s    87%  100%  :    90%
 CPU   Total     Net   kB/s    Disk   kB/s    Tape   kB/s  Cache  Cache    CP  CP  Disk
       ops/s      in    out    read  write    read  write    age    hit  time  ty  util
 65%    8616       0      0  220068 165749       0      0     2s    76%   73%  :    71%
 89%    5443       0      1  338684 239932       0      0     3s    80%   94%  F    87%
 95%    6726       0      0  379242 240750       0      0     3s    79%  100%  :    91%
 83%    8721       1      0  342940 113394       0      0     2s    82%   61%  :    89%
 77%   11971       1      0  314356     24       0      0     2s    85%    0%  -    92%

... and back to normal.

Looking in Perf Advisor, it was during an extremely short, sharp latency spike that impacted every volume on every aggregate at exact the same time.  It was the fourth of four spikes that had happened a few minutes apart during the previous 20 mins. 

It looks like the NVRAM flush got stuck somehow but I have no idea what would cause that.

We're running ONTAP 8.0.2 7-mode on a very busy FAS3170.

Thanks,
Peta
_______________________________________________
Toasters mailing list
Toasters@teaparty.net
http://www.teaparty.net/mailman/listinfo/toasters