Looks like you're hanging on a consistency point operation, but the sysstat output starts after that last CP was logged. This looks very similar to the ":s" CP bug, but can't say for sure. You have a long running CP operation, you NVRAM has filled up waiting for the operation to complete, but with no "s" after the "#", then it's not processing special files. It's doing something else.
Could be one of these bugs:
651573 Inefficient pre-fetching of metadata blocks delays WAFL consistency point 651597 Inefficient pre-fetching of metadata blocks delays WAFL consistency point 651926 Inefficient pre-fetching of metadata blocks delays WAFL consistency point 651929 Inefficient pre-fetching of metadata blocks delays WAFL consistency point 655724 Inefficient pre-fetching of metadata blocks delays WAFL consistency point 657018 Inefficient pre-fetching of metadata blocks delays WAFL consistency point 650554 Inefficient pre-fetching of metadata blocks delays WAFL consistency point
On Apr 10, 2013, at 6: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