Thursday, March 20, 2014

Perfmon was collecting stats... what happened next was...

whackadoodle!

I can't think of any other word to describe it.  Let me know if you've ever seen anything like this from perfmon on a physical windows server.

Perfmon was running locally on a 4 socket, six core per socket server with no Hyper-Threading, logging to tsv file in 15 second intervals.  The results were sent to me for review.

The 24 columns below are for "\Processor(x)\% Processor Time" for 0<=x<=23.

See the zany for yourself below. 


Duplicate times.  Missing per-cpu numbers.  Suspect per-cpu CPU busy reported. And suddenly, 10 minutes later, a return to normal.  I'm thinking major fault at CPU level or maybe a significant memory error.  So I'm hoping to dig details or at least a clue from the system or event log.  But, I'm open to any ideas... because other than that I don't have any.  And I usually have lots of ideas, even if they aren't very helpful :-)

This isn't what I was expecting to see at all.  I thought I was just going to see some of the disk IO and memory management issues I normally deal with on SQL Server configs.  Maybe some spinlocks.  Nothing that would completely throw me for a loop.  Maybe I just need more coffee.

**** Updated with Exhibit 1 for some context.  SQL Server is expected to be the only significant consumer of CPU, memory, or IO resources from this physical Windows server.  Note the way that the two extraordinary timeperiods are the two deviations from SQL Server CPU consumption strongly correlating with "total server CPU consumption." ****



cpu0 cpu1 cpu2 cpu3 cpu4 cpu5 cpu6 cpu7 cpu8 cpu9 cpu10 cpu11 cpu12 cpu13 cpu14 cpu15 cpu16 cpu17 cpu18 cpu19 cpu20 cpu21 cpu22 cpu23
16:47:14 20 18 11 6 4 2 20 12 6 2 1 2 13 15 6 38 17 30 12 13 20 16 11 13
16:47:29 19 18 11 4 2 1 19 11 8 2 1 0 14 14 5 39 14 31 13 16 18 16 11 10
16:47:44 20 16 10 5 3 1 19 11 6 2 2 0 13 14 6 36 17 26 11 12 27 14 9 12
16:47:44 18 18 18 18 18 18 18 18 18 18 18 18 18 18 18 18 18 18 18 18 18 18 18 18
16:47:59 21 17 9 4 2 1 22 12 5 3 1 0 13 17 5 37 15 31 17 14 23 12 6 6
16:47:59 100 46 46 46 46 46 100 46 46 46 46 46 100 100 46 46 46 46 46 46 46 46 46 46
16:48:14 22 20 11 4 2 1 7 16 8 34 21 13 12 15 6 39 19 32 13 14 26 12 8 9
16:48:14 44 100 44
16:48:29 19 19 8 6 4 1 21 14 5 1 1 0 11 14 5 39 17 29 12 14 22 13 5 7
16:48:29 46 46 0 0 0 0 0 46 0 0 0 0 0 46 0 0 46 46 46 46 0 100 0 46
16:48:44 20 19 9 5 2 1 19 12 8 4 2 1 12 14 5 40 16 29 14 10 26 13 9 11
16:48:44 44 100
16:48:59 18 17 9 6 3 1 18 15 7 3 1 0 13 14 8 35 14 22 13 12 24 17 8 8
16:48:59 44 44 100 44
16:49:14 20 18 9 6 4 2 22 13 8 3 0 2 11 12 6 37 19 27 12 13 24 14 5 9
16:49:14 46 46 46 46 46 46 46 100 100 46 46 46 46 46 46 100 46 46 46 46 46 46 46 46
16:49:29 18 16 10 5 2 1 20 12 7 2 2 0 11 14 6 38 18 29 14 12 27 15 7 10
16:49:29
16:49:44 20 15 10 5 2 1 19 9 6 2 3 0 12 14 6 39 20 25 13 13 23 14 5 9
16:49:44 0 0 0 0 0 0 0 0 0 0 0 0 46 46 0 0 0 100 0 46 100 0 0 46
16:49:59 20 14 11 7 2 1 20 15 6 1 0 0 12 14 4 40 14 29 12 14 29 17 8 9
16:49:59 44 44 44 44 44 44 100 44 100 100
16:50:14 25 17 11 5 5 3 19 15 8 3 2 1 12 15 8 37 17 28 13 14 26 16 12 11
16:50:14 46 46 100 0 0 0 100 100 0 0 0 0 0 0 0 46 46 46 100 46 0 0 0 46
16:50:29 20 18 6 6 2 1 23 13 4 2 2 0 13 14 7 38 17 28 13 13 27 13 9 9
16:50:29 44 44 44 44 44 44 44 44 44 44 44 44 44 44 44 44 44 44 44 44 44 44 44 44
16:50:44 21 15 10 3 2 2 20 13 7 2 1 0 13 13 3 38 17 36 11 12 25 16 7 12
16:50:44 0 46 0 0 0 0 0 0 0 0 0 0 0 46 0 100 0 46 46 0 46 46 0 0
16:50:59 14 20 12 10 5 1 18 17 9 4 2 1 6 12 1 52 19 45 8 13 32 25 7 10
16:50:59 44 44 100 44 44 44 44 100 44 44 44 44 44 100 44 44 44 100 44 44 100 44 44 44
16:51:14 15 22 16 12 4 2 18 16 12 6 2 2 7 14 2 52 23 46 3 11 25 32 21 17
16:51:14 44 44 100 44 44 100 44 44
16:51:29 12 24 15 10 4 1 19 17 11 3 2 0 7 14 1 52 22 47 4 11 29 26 12 13
16:51:29 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 100 46 0 0 46 46 0 0 46
16:51:44 16 21 15 13 4 2 20 17 10 3 1 0 7 14 1 52 20 47 5 13 28 30 17 14
16:51:44 44 44 100
16:51:59 16 20 14 7 5 1 20 16 10 4 2 0 6 15 2 52 22 46 5 14 27 28 13 11
16:51:59 0 0 46 0 0 0 0 0 0 0 0 0 46 0 0 0 46 46 0 0 46 46 0 46
16:52:14 15 22 13 10 4 2 19 18 11 3 1 0 7 15 2 51 23 49 3 9 31 31 16 13
16:52:14 44 44 44 44 44 44 44 44 44 44 44 44 44 44 44 100 44 44 44 44 44 44 44 100
16:52:29 14 22 14 10 4 2 19 16 11 5 3 0 6 14 2 51 23 48 3 11 24 28 17 13
16:52:29 0 0 46 0 0 0 46 0 0 0 0 0 0 0 0 100 0 0 0 0 0 0 0 0
16:52:44 15 23 13 14 8 2 21 18 10 4 2 0 5 12 1 52 20 50 5 15 27 30 15 15
16:52:59 13 21 14 10 6 2 20 16 9 4 4 2 7 12 2 49 25 50 6 13 20 29 19 12
16:52:59 100 100 100 100 100
16:53:14 14 20 16 13 7 4 18 18 11 4 1 1 5 14 1 49 22 50 4 11 24 32 24 20
16:53:14 100 100 100 100 100
16:53:29 13 22 17 11 7 2 20 17 13 6 3 2 5 13 2 51 20 50 3 11 26 30 18 13
16:53:29 100 100 100 100 100
16:53:44 14 25 14 15 9 5 20 14 7 4 1 0 5 15 2 53 24 48 5 13 25 27 18 20
16:53:44 100 100 100 100 100 100 100
16:53:59 12 23 13 13 8 4 20 18 14 6 2 0 4 14 2 51 22 50 5 12 23 31 17 13
16:53:59 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
16:54:14 19 23 14 9 6 3 20 16 10 6 2 0 7 13 1 50 21 48 6 17 28 28 16 18
16:54:14 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
16:54:29 14 20 16 10 5 2 19 19 11 5 1 0 6 13 1 53 23 44 4 10 25 32 15 14
16:54:29 100 100 100
16:54:44 15 22 13 9 4 1 19 17 13 7 1 1 8 15 2 51 23 48 7 12 29 30 15 15
16:54:44 100 100
16:54:59 16 23 13 7 3 1 17 16 13 11 3 0 7 14 1 51 24 47 4 10 22 32 15 19
16:54:59 100 100
16:55:14 19 22 19 12 9 8 20 17 12 8 3 1 7 15 2 54 25 45 3 11 25 34 27 17
16:55:14 100 100 100
16:55:29 12 21 16 10 3 1 17 18 15 6 2 1 7 15 2 53 22 48 3 8 24 33 20 20
16:55:29 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
16:55:44 16 21 14 8 4 2 19 17 13 6 1 1 6 14 4 52 19 50 5 8 28 27 17 18
16:55:44 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
16:55:59 14 19 15 12 4 1 17 17 13 6 3 1 5 15 2 52 19 48 2 9 24 34 24 21
16:55:59 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
16:56:14 13 20 17 13 5 3 19 17 13 4 1 1 8 13 2 53 23 47 3 10 28 33 20 14
16:56:14 100 100 100
16:56:29 17 21 13 6 3 1 19 17 9 3 1 0 6 16 2 50 23 45 3 11 29 29 15 12
16:56:29 100 100 100 100 100
16:56:44 17 22 16 8 4 1 17 16 13 4 2 0 9 16 2 53 20 47 4 9 24 29 12 15
16:56:44 100 100
16:56:59 12 21 13 8 5 1 17 19 10 6 2 1 6 13 2 50 21 49 6 13 29 24 9 9
16:56:59 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
16:57:14 15 21 15 10 4 2 18 17 10 5 2 0 5 16 2 56 19 45 6 12 27 26 13 13
16:57:14 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
16:57:29 12 21 16 12 5 1 20 18 10 4 1 0 6 15 1 53 24 47 4 9 28 31 16 17
16:57:29 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
16:57:44 16 22 15 9 5 2 18 19 9 5 1 1 7 16 1 52 23 44 3 10 25 31 17 19
16:57:59 13 21 16 9 5 2 21 15 9 4 1 1 5 12 2 49 24 50 4 9 29 31 18 16
1:53:14 21 25 22 3 5 4 14 3 2 4 4 7 45 3 20 18 63 16 12 10 17 10 23 10
1:53:29 20 15 4 2 2 2 7 2 2 3 0 0 22 12 14 6 45 12 14 5 18 5 2 3
1:53:44 16 34 25 19 25 19 28 20 7 21 9 4 19 30 44 15 45 25 11 15 16 29 21 8
1:53:59 15 6 2 0 0 0 2 1 0 0 0 0 30 8 9 13 39 10 12 4 16 0 1 0
1:53:59 46 46 46 46 46 46 46 46 46 46 46 46 46 46 46 100 100 46 46 46 46 46 46 46
1:54:14 17 5 1 1 2 0 6 3 0 0 0 0 10 15 27 23 67 11 14 6 14 2 2 4
1:54:14 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 100 0 0 0 100 0 0 100
1:54:29 14 6 2 1 0 1 4 1 0 0 0 0 38 15 12 5 28 8 19 4 10 2 1 1
1:54:29 44 44 44 44 44 44 44 44 44 44 44 44 44 100 44 44 44 44 44 44 44 44 44 44
1:54:44 10 6 1 8 1 0 2 1 0 1 0 0 28 5 10 6 33 3 9 4 16 1 0 0
1:54:44 0 0 0 0 0 0 0 0 0 0 0 0 46 0 0 0 0 0 0 0 0 0 0 0
1:54:59 24 3 5 2 7 0 3 0 0 0 0 0 27 17 16 14 28 2 14 9 14 7 3 0
1:54:59 44 100 100 100 44 44
1:55:14 17 3 12 3 22 0 1 0 0 0 0 0 28 24 18 2 18 1 11 3 16 2 2 4
1:55:14 0 0 0 0 0 0 46 0 0 0 0 0 100 0 0 0 0 0 0 0 0 0 0 0
1:55:29 11 4 2 3 4 1 5 1 4 4 2 0 37 15 16 6 29 4 10 12 19 9 11 4
1:55:29 44 100 100
1:55:44 9 2 1 0 0 0 4 1 1 5 0 0 31 9 11 1 34 0 9 2 12 7 1 1
1:55:44 100 46 46 46 46 46 46 46 46 46 46 46 46 46 100 46 46 46 100 46 46 46 46 46
1:55:59 15 7 6 5 6 1 17 3 5 8 0 0 12 30 15 7 61 16 6 16 22 46 10 12
1:55:59 100 100 100
1:56:14 20 12 21 8 15 13 18 6 30 23 4 2 19 32 28 22 52 27 21 18 26 20 22 9
1:56:14 46 0 0 0 0 0 46 0 0 0 0 0 0 46 0 0 100 0 0 46 100 0 0 46
1:56:29 24 16 19 17 15 8 16 15 10 12 2 2 10 34 23 18 61 25 9 19 33 10 15 7
1:56:29 0 0 46 0 0 0 0 100 0 0 0 0 0 0 0 0 100 100 0 46 0 100 0 0
1:56:44 26 5 8 5 6 0 15 29 5 5 1 0 17 18 31 6 58 7 13 11 16 6 0 3
1:56:44 100 2 2 2 2 2 2 2 2 2 2 2 2 2 100 2 100 2 2 2 100 2 2 2
1:56:59 22 12 21 5 6 9 7 0 0 4 0 0 7 13 52 10 62 18 15 13 14 4 3 4
1:56:59 46 46 46 46 46 46 46 46 46 46 46 46 46 46 46 46 100 46 46 100 46 46 46 46
1:57:14 26 5 7 1 0 0 9 1 0 4 0 0 10 14 17 14 62 10 10 11 16 5 3 8
1:57:14 100 44 100 100 44
1:57:29 38 16 13 3 10 2 14 7 6 11 1 0 8 18 16 8 65 38 16 15 16 3 1 2
1:57:29 46 46 46 100 46 46 46 46 46 46 46 46 46 46 46 46 100 46 46 100 100 46 46 46
1:57:44 30 10 9 2 9 0 9 4 0 8 0 0 31 13 6 7 42 2 9 14 16 1 1 2
1:57:44 44 44 100 100
1:57:59 23 26 9 10 10 12 28 2 9 4 3 2 32 7 18 6 46 20 13 20 17 12 7 4
1:57:59 0 0 0 0 0 0 0 0 0 0 0 0 0 0 48 0 100 0 0 0 100 0 100 48
1:58:14 27 29 16 22 20 24 33 12 20 11 7 4 26 21 26 26 60 29 32 20 32 9 23 10
1:58:14 44 44 100 44 44 44 44 100 44 100 44 44 44 100 44 44 44 44 44 44 44 44 44 44
1:58:29 27 8 10 1 3 1 29 3 1 7 1 1 2 24 17 29 55 26 17 5 15 3 7 4
1:58:29 0 0 0 0 0 0 100 0 0 0 0 0 0 0 46 0 46 46 46 0 0 0 0 0
1:58:44 25 31 19 13 17 19 23 26 15 25 15 11 27 25 16 44 51 27 21 15 35 8 14 13
1:58:44 38 38 38 38 100 100 38 38 100 38 38 38 38 38 38 38 100 38 38 38 100 38 38 38
1:58:59 16 13 16 1 5 1 42 4 5 6 0 3 24 22 18 12 52 6 45 7 16 2 4 9
1:58:59 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
1:59:14 21 9 5 1 1 0 44 6 2 15 2 0 13 12 9 12 55 13 16 6 18 4 5 5
1:59:14 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
1:59:29 16 4 7 1 1 0 20 3 4 5 0 6 19 7 6 16 65 1 15 5 16 6 2 2
1:59:29 100 100
1:59:44 22 7 4 1 0 0 27 4 2 4 4 1 23 10 8 3 61 5 14 5 16 2 2 4
1:59:44 100 100
1:59:59 20 14 5 1 1 0 30 1 0 2 0 0 18 10 19 6 61 5 18 2 11 1 2 1
1:59:59 100 100 100
2:00:14 28 8 16 12 11 12 29 20 16 19 3 5 24 26 16 37 56 16 13 11 33 11 16 29
2:00:14 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
2:00:29 7 5 37 35 34 40 49 57 55 57 7 13 6 11 7 59 72 3 13 15 24 5 4 4
2:00:29 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
2:00:44 5 7 38 44 39 44 29 66 63 62 3 4 11 3 6 54 29 2 20 11 15 3 58 8
2:00:44 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
2:00:59 12 23 43 35 19 19 32 53 50 47 8 8 14 17 9 37 14 3 26 12 20 5 9 5
2:00:59 100 100 100 100 100 100 100
2:01:14 21 32 13 6 6 22 27 7 32 7 22 23 7 42 29 9 3 0 7 28 35 9 15 9
2:01:14 100
2:01:29 23 7 5 1 1 0 24 1 10 0 0 0 5 1 0 0 0 0 8 3 15 8 1 2
2:01:44 28 12 2 0 2 0 3 1 0 0 0 0 5 1 0 2 0 0 8 3 9 2 0 1
2:01:44 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
2:01:59 21 6 3 0 2 0 4 0 0 0 0 0 6 1 0 0 0 0 15 4 22 8 13 2
2:01:59 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
2:02:14 10 2 1 1 0 0 1 0 0 0 0 0 2 1 0 0 0 0 10 2 14 2 3 3
2:02:14 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
2:02:29 6 16 18 7 14 19 12 1 19 13 0 12 3 14 17 5 12 14 7 16 24 19 51 14
2:02:29
2:02:44 7 4 0 1 0 1 2 0 0 0 0 0 4 3 1 0 0 0 16 12 16 13 24 6
2:02:44 100
2:02:59 5 7 2 1 0 0 3 1 0 1 0 0 6 2 0 3 0 0 18 7 11 2 6 6
2:02:59 100
2:03:14 6 0 0 0 0 0 1 0 0 0 0 0 4 2 0 0 0 0 22 15 16 2 13 2
2:03:14 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
2:03:29 5 1 0 0 0 0 3 1 0 0 0 0 4 1 0 0 0 0 22 13 18 2 8 3
2:03:29 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
2:03:44 16 11 3 1 6 0 6 1 6 0 0 6 15 2 3 5 0 0 14 27 33 3 24 14
2:03:44 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100 100
2:03:59 19 3 1 0 0 0 12 0 0 0 0 0 14 3 0 0 0 0 1 50 39 4 45 3
2:04:14 17 7 11 2 1 2 20 7 4 1 2 2 19 5 10 6 1 1 5 38 30 8 80 17
2:04:29 2 1 43 2 3 0 2 19 0 9 15 13 10 7 8 0 0 0 6 1 28 2 8 5
2:04:44 9 18 11 5 2 2 12 2 7 9 2 6 5 11 22 11 11 7 8 12 29 5 7 13
2:04:59 34 14 5 19 11 3 10 28 16 55 24 28 31 30 31 8 13 11 19 8 23 27 25 6

1 comment:

  1. I now believe this was a result of NTP time correction.
    Why was the server corrected by 10 minutes *twice* in a 24 hour period?
    The power plan was inadvertently "balanced" rather than "high performance".
    That is now corrected.
    I'll add more comments and update the post in the future as I learn more.

    ReplyDelete