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