Easier parsing of Microsoft perfmon logs with regex

In this blog post I discussed perl code use to slice and dice perfmon logs by passing the Excel column name (ie, A, B, XC, AAZ, etc) in the command line. That made slicing and dicing perfmon log files a lot easier but it was still missing something.

With a large perfmon capture I was having to write down a lot of column names to slice out. I decided there had to be a better way and adapted my code to use regular expressions for column selection.

For example, I recently had a capacity study of a server and all that I wanted was the the disk IO and processor usage.

With the new code (below) I can now pull that quite easily:

perfMonLogRegEx.pl somePerfMonLog.csv 14:00:00 15:00:00 "disk|proc"

Now I automagically get the columns that contain the keywords "disk" and "proc." That pulls out the following from my perfmon log:


LogicalDisk(C:)\% Disk Time
LogicalDisk(D:)\% Disk Time
LogicalDisk(_Total)\% Disk Time
LogicalDisk(C:)\% Idle Time
LogicalDisk(D:)\% Idle Time
LogicalDisk(_Total)\% Idle Time
LogicalDisk(C:)\Avg. Disk Queue Length
LogicalDisk(D:)\Avg. Disk Queue Length
LogicalDisk(_Total)\Avg. Disk Queue Length
LogicalDisk(C:)\Avg. Disk sec/Read
LogicalDisk(D:)\Avg. Disk sec/Read
LogicalDisk(_Total)\Avg. Disk sec/Read
LogicalDisk(C:)\Avg. Disk sec/Write
LogicalDisk(D:)\Avg. Disk sec/Write
LogicalDisk(_Total)\Avg. Disk sec/Write
LogicalDisk(C:)\Disk Reads/sec
LogicalDisk(D:)\Disk Reads/sec
LogicalDisk(_Total)\Disk Reads/sec
LogicalDisk(C:)\Disk Writes/sec
LogicalDisk(D:)\Disk Writes/sec
LogicalDisk(_Total)\Disk Writes/sec


Want just the LogicalDisk(_Total) columns? Easy enough:

perfMonLogRegEx.pl somePerfMonLog.csv 14:00:00 15:00:00 "LogicalDisk\(_Total\)"

Notice that I have to escape the parentheses as I am not trying to capture anything from the regex.

And I get:


LogicalDisk(_Total)\% Disk Time
LogicalDisk(_Total)\% Idle Time
LogicalDisk(_Total)\Avg. Disk Queue Length
LogicalDisk(_Total)\Avg. Disk sec/Read
LogicalDisk(_Total)\Avg. Disk sec/Write
LogicalDisk(_Total)\Disk Reads/sec
LogicalDisk(_Total)\Disk Writes/sec


Want all columns between the upper and lower time limits? Easy enough:

perfMonLogRegEx.pl somePerfMonLog.csv 14:00:00 15:00:00 ".*"

The modified perl code for this handy-dandy slicing and dicing is found below and uses the same command line params as the previous code replacing the Excel column names with the regex for column selection.

1:  use strict;  
2:  my $logFile     = shift;  
3:  my $startTime    = &timeIntoSeconds(shift);  
4:  my $endTime     = &timeIntoSeconds(shift);  
5:  my $keyWordRegEx   = shift;   
6:  my @targetColumns  = ();  
7:  my %columnHash = ();  
8:  my %columnNames = ();  
9:  open(LOG, "$logFile") || die "$!";  
10:  while (my $input = <LOG>) {  
11:   chomp($input);  
12:   $input =~ s/\"//g;  
13:   my @columns = split(/\,/, $input);  
14:   if ($input =~ /PDH-CSV 4\.0/i) {  
15:    my $maxColumns = $#columns+1;  
16:    for (my $i = 0; $i < $maxColumns; $i++) {  
17:     if ($columns[$i] =~ qr/$keyWordRegEx/i) {  
18:      push(@targetColumns, ($i+1));  
19:     };  
20:    };  
21:    foreach my $columnNumber (@targetColumns) {  
22:     my @dataArray = ();  
23:     $columnHash{$columnNumber} = \@dataArray;  
24:    };  
25:    print STDOUT "$columns[0]";  
26:    foreach my $columnNumber (sort {$a <=> $b} (keys(%columnHash))) {  
27:     $columnNames{$columnNumber} = $columns[$columnNumber-1];  
28:     print STDOUT ",$columns[$columnNumber-1]";  
29:    };  
30:    print STDOUT "\n";  
31:   } else {  
32:    my ($dateStamp, $timeStamp) = split(/ /, $columns[0]);  
33:    my $metricSeconds = &timeIntoSeconds($timeStamp);  
34:    if ( $metricSeconds >= $startTime && $metricSeconds <= $endTime) {  
35:     print STDOUT "$columns[0]";  
36:     foreach my $columnNumber (sort {$a <=> $b} (keys(%columnHash))) {  
37:      print STDOUT ",$columns[$columnNumber-1]";  
38:     };  
39:     print STDOUT "\n";  
40:    };  
41:   };  
42:   if (($. % 1000) == 0) {  
43:    print STDERR "Working on line $.\n";  
44:   };  
45:  };  
46:  sub timeIntoSeconds() {  
47:   my ($timeStamp) = @_;  
48:   my ($hours, $mins, $sec) = split(/:/, $timeStamp);  
49:   return (($hours * 3600) + ($mins * 60)) + $sec;  
50:  };  

Low Power Consumption Server Gotcha

Something interesting happened this week. I've been fighting an issue where newer 12 and 16 core servers couldn't compete with older 8-core Windows 2003 servers. Turns out there were two gotchas.

The first one is fairly straight forward. A recent Microsoft security patch was installed that affected the way that .NET handles garbage collection. By default the .NET 2.0 CLR can handle up to 8 cores for garbage collection. Subsequent updates increased the number of cores that can handle garbage collection. But with the patch in question hobbled .NETs ability to properly handle garbage collection with more than 8 cores resulting in % time in GC shooting up and negatively effecting server capacity. The hot fix for our problem can be found here. The GC was being passed around to the (n-8) extra cores in the box.

We placed the hotfix in place and viola, the service demand measurements dropped by about 40%.

But still, the capacity of the 12/16 cores was still having issues compared to the original 8-core machines. We suspected that the .NET stack still needed to be further tuned but something interesting happened this week.

It was found that our servers were shipped from the factory in power saving mode. While under low core utilization the core clocks were running anywhere from 800 MHz to 1.1 GHz. It's not until the cores are pushed past 60% that the core clocks are increased up to the maximum of 2.4 GHz. Most of my capacity studies of production traffic were in the 40 to 50% CPU range. Not quite enough to force the core clocks to start jacking up the clock rate.

The result? It appeared that the capacity of the larger machines was less than the 8-core machines. After the core clock was set at the environmentally less friendly rate of 2.4 GHz the measured service demand under production traffic dropped a significant 56.5%. Not too shabby. However, it would have been nice to know about the server issue to begin with to eliminate a lot of confusion and wasted fundage.

I have been calculating capacity requirements based upon the low power consumption clock speed and a lot of extra boxes have been ordered. Now that we know about the power savings issue we can configure the boxes for maximum performance. And the extra boxes? That'll just add a bunch of extra capacity to the application.

Good times!

The Value of Log Analysis

Something that I run into time and time again is capacity planners and load testers that simply have no concept of how to perform log analysis. There is simply no excuse for this issue. Perl has been available for 20+ years and is my bread and butter when it comes to slicing and dicing logs. But if you are not a perl guru, there are plenty of alternatives available to assist the analyst that wants to crunch some log files.

I've heard a lot of good things about Microsoft LogParser. No perl required.

Personally, I prefer perl for slicing and dicing logs but I've been coding perl routines for 13+ years.

But back to log analysis: Example that happened to me earlier this week.

Load test is testing a major install that is going into production shortly and the management is hot and heavy to get this install tested. Load testing is finally done and their results show that the CPU utilization of servers in a particular tier increased by 2% while the arrival rate decreased 15%. The result? CPU service demand measured increased by roughly 22% which has an affect on the number of servers required for production.

This increase of 2% and decrease of arrival rate went missed by the load testing team completely but fortunately was found by myself. The question is this though: What is causing the extra 2% CPU utilization with a 15% decrease in arrival rate.

The load testers have no idea and simply scratch their heads. After watching them flail helplessly I decided to jump into the issue. After all, I did identify the 22% increase in CPU service demand between release versions.

The first place that I looked were the web logs. Because I'm a fanatic about log analysis I've written various perl routines over the years for slicing and dicing log files. I crunch the logs for the baseline and after tests and immediately see the problem: A major web service that was being called in the baseline is no longer being called in the after test. The difference in hits between the two load tests? 15%. The same difference in the arrival rate between tests. Somewhere, something went kaput. Load testers haven't found out what yet as we've been busy all week (and this weekend) hunting down other issues.

But the net result is this: If you are a load tester or capacity analyst, you damned well better be able to perform log analysis, even if it is rudimentary. Whether it is via perl or some other system like splunk, you need to have the tools in your toolbox to get the job done.

In the above example, the load testers did not properly analyze log files to see what was up. No attempt was made. Heck, they didn't even compare the output of Load Runner to ensure that the number of transactions between the two tests were the same. A load tester that cannot perform rudimentary log analysis is useless to me.