Extracting Perfmon data from the VS2008 Load Test Repository

Ok. You are performing load tests with VS2008 TSTE and you've enabled the logging of perfmon metrics in your test by tweaking the "Timing Details Storage" property of the Run Settings in your load test. Every 5 seconds the perfmon metrics you specified are being stored to the load test repository and after the run you get some metrics. That's great and all but what if you want more detailed statistics such as average AND standard deviation.

Or better yet! You want at that data to generate graphs of the metrics over the duration of the test. Sure, you can do this by firing up good 'ol Perfmon and logging the values or you can just get them from your load test repository with some SQL. Why have Perfmon logging when VS2008 already does this for you?

I have a need for just such an action and I've been working on the SQL statements to extract the data I need. It's not complete, but this is a major step forward to allowing me to finish up the SPs I want to collect the data dynamically for consumption by managers and other QA folks.

Looking at the handy dandy schema of the load test repository (located here for all to gander) I have created some SQL statements that take care of the leg work for me.

   1:  SELECT LoadTestPerformanceCounterInstance.InstanceId, 

   2:         LoadTestPerformanceCounterCategory.CategoryName, 

   3:         LoadTestPerformanceCounter.CounterName, 

   4:         LoadTestPerformanceCounterInstance.InstanceName, LoadTestPerformanceCounterCategory.MachineName, 

   5:         AVG(LoadTestPerformanceCounterSample.ComputedValue) AS AverageValue,

   6:         stdev(LoadTestPerformanceCounterSample.ComputedValue) as StdDev,

   7:         count(LoadTestPerformanceCounterSample.ComputedValue) as Count

   8:  FROM  LoadTestPerformanceCounterCategory INNER JOIN

   9:                 LoadTestPerformanceCounter INNER JOIN

  10:                 LoadTestPerformanceCounterInstance ON LoadTestPerformanceCounter.LoadTestRunId = LoadTestPerformanceCounterInstance.LoadTestRunId AND 

  11:                 LoadTestPerformanceCounter.CounterId = LoadTestPerformanceCounterInstance.CounterId ON 

  12:                 LoadTestPerformanceCounterCategory.CounterCategoryId = LoadTestPerformanceCounter.CounterCategoryId AND 

  13:                 LoadTestPerformanceCounterCategory.LoadTestRunId = LoadTestPerformanceCounter.LoadTestRunId INNER JOIN

  14:                 LoadTestPerformanceCounterSample ON LoadTestPerformanceCounterInstance.LoadTestRunId = LoadTestPerformanceCounterSample.LoadTestRunId AND 

  15:                 LoadTestPerformanceCounterInstance.InstanceId = LoadTestPerformanceCounterSample.InstanceId

  16:  WHERE (LoadTestPerformanceCounter.LoadTestRunId = 83)

  17:  GROUP BY LoadTestPerformanceCounterCategory.CategoryName, LoadTestPerformanceCounter.CounterName, LoadTestPerformanceCounterInstance.InstanceName, 

  18:                 LoadTestPerformanceCounterInstance.InstanceId, LoadTestPerformanceCounterCategory.MachineName

  19:  ORDER BY LoadTestPerformanceCounterInstance.InstanceId

In the above example, the reference to LoadTestRunId is hard coded to a previous run that I have in my results repository. For all my other SPs I use the GUID of the test and will convert the above SQL statement to reference GUID all in good time. The query above returns results like this:

   1:  0     .NET CLR Memory     Gen 0 heap size                             w3wp     10.0.0.11     944824777.209431     185400315.203616     721

   2:  1     .NET CLR Memory     Large Object Heap size                      w3wp     10.0.0.11     86994000.5298197     29625345.9051784     721

   3:  2     .NET CLR Memory     # Gen 0 Collections                         w3wp     10.0.0.11     132.608876560333     69.5129454689118     721

   4:  3     .NET CLR Memory     Gen 2 heap size                             w3wp     10.0.0.11     197119053.001387     78824416.0154383     721

   5:  4     .NET CLR Memory     Allocated Bytes/sec                         w3wp     10.0.0.11     63521791.4160888     91335026.9218956     721

   6:  5     .NET CLR Memory     # Gen 2 Collections                         w3wp     10.0.0.11     29.5104022191401     12.1351287581502     721

   7:  6     .NET CLR Memory     Promoted Memory from Gen 0                  w3wp     10.0.0.11     42540355.2815534     13356693.0175676     721

   8:  7     .NET CLR Memory     # Induced GC                                w3wp     10.0.0.11     0                    0                    721

   9:  8     .NET CLR Memory     Gen 0 Promoted Bytes/Sec                    w3wp     10.0.0.11     418557.084366331     1120132.98732717     721

  10:  9     .NET CLR Memory     Promoted Memory from Gen 1                  w3wp     10.0.0.11     21740368.0721221     25126733.8606902     721

  11:  10    .NET CLR Memory     # GC Handles                                w3wp     10.0.0.11     3750.73370319001     216.191892870829     721

  12:  11    .NET CLR Memory     # Gen 1 Collections                         w3wp     10.0.0.11     70.0693481276005     35.4698332819129     721

  13:  12    .NET CLR Memory     Gen 1 heap size                             w3wp     10.0.0.11     62394980.9237171     31034211.4233198     721

  14:  13    .NET CLR Memory     Finalization Survivors                      w3wp     10.0.0.11     8217.1040221914      3024.02383909951     721

  15:  14    .NET CLR Memory     Promoted Finalization-Memory from Gen 0     w3wp     10.0.0.11     11415345.6768377     11434973.2174913     721

  16:  15    .NET CLR Memory     % Time in GC                                w3wp     10.0.0.11     3.48545611573799     6.73310861817717     721

The first column is the InstanceId of the perfmon counter and the information for the counter is split up into three separate columns (CategoryName, CounterName and InstanceName) but the column that ties them all together is the InstanceId.

Ok. That's fine and dandy but what about graphing the metrics over the duration of the load test?

Well, that's another SQL query I wrote that is in the alpha stage of development. In the above example I displayed 15 out of 466 metrics that were logged. Let's choose to graph the .NET CLR Memory Gen 2 heap size for w3wp. This particular metric happens to be InstanceId #3 this time around and we can use it in the SQL statement below to extract the data that can eventually be used to graph the results.

   1:  SELECT LoadTestPerformanceCounterInstance.InstanceName,

   2:         LoadTestPerformanceCounterSample.ComputedValue

   3:  FROM  LoadTestPerformanceCounterInstance INNER JOIN

   4:        LoadTestPerformanceCounterSample ON LoadTestPerformanceCounterInstance.LoadTestRunId = LoadTestPerformanceCounterSample.LoadTestRunId AND 

   5:        LoadTestPerformanceCounterInstance.InstanceId = LoadTestPerformanceCounterSample.InstanceId

   6:  WHERE (LoadTestPerformanceCounterInstance.LoadTestRunId = 83) AND (LoadTestPerformanceCounterInstance.InstanceId = 3)

   7:  ORDER BY LoadTestPerformanceCounterSample.TestRunIntervalId

This query yields the results of:

   1:  w3wp    0

   2:  w3wp    0

   3:  w3wp    96

   4:  w3wp    3231264

   5:  w3wp    2.170597E+07

   6:  w3wp    2.170597E+07

   7:  w3wp    2.170597E+07

   8:  w3wp    2.976022E+07

   9:  w3wp    2.976022E+07

  10:  w3wp    2.976022E+07

  11:  w3wp    2.976022E+07

  12:  w3wp    4.127677E+07

  13:  w3wp    4.127677E+07

  14:  w3wp    4.127677E+07

and so on and so on until all 722 metrics are displayed. We can take those 722 metrics and copypasta into Excel and generate a quick and dirty graph:



Viola! Quick and dirty graph from Excel!

I'll need to change the column output to show more details on the metrics to display all three columns to better identify the perfmon metric and also display the time that the metric was taken.

After I do all that I'll need to write some code to generate graphs on the fly. I'm thinking that this project on SourceForge will fit the bill nicely and there seems to be a bunch of examples out on the 'net how to use ZedGraph to it's fullest.

Oh yeah! Almost forgot. I need to double check the results between the first query and the individual information for InstanceId 3 metric (the .NET CLR Gen 2 heap size for w3wp). The first query output says the average value is 197119053.001387. Take the average of output that I did the copypasta into Excel gonkulates to an average of 197119053.4. The difference between the two? A measly 0.355. I'm thinking that is good 'nuff for government work.

Now I just need to finish up the queries and get them into SPs and integrate them with the other code that I've written that does automagic before/after comparison of transaction response times (more on that at a later date).

Collecting daily LT Metrics

Last night I wrote a stored procedure to automagically collect the latest LT results and insert the values into a database that I created on my local SQL Server 2005 Express.

This SP finds the latest LT that has been run, crunches the numbers and inserts them into two tables, LoadTestHistory and LoadTestHistoryDetails. I used the GUID generated by VS2008 in the Load Test Repository Store as the primary/foreign key between the two tables.

It's a bit rough and could probably use some more polish:

   1:  set ANSI_NULLS ON

   2:  set QUOTED_IDENTIFIER ON

   3:  GO

   4:  ALTER PROCEDURE [dbo].[UpdateLoadTestHistory]

   5:  AS

   6:  BEGIN

   7:   

   8:    SET NOCOUNT ON;

   9:   

  10:    declare @AlreadyExists    as int

  11:   

  12:    declare @latestLoadTest   as int

  13:    declare @loadTestGUID     as nvarchar(36)

  14:    declare @StartTime        as datetime

  15:    declare @EndTime          as datetime

  16:    declare @Duration         as int

  17:   

  18:    select @latestLoadTest = max(LoadTestRunId)

  19:    from LoadTest.dbo.LoadTestRun

  20:    where EndTime is not null

  21:   

  22:    select @loadTestGUID   = RunId,

  23:           @StartTime      = StartTime,

  24:           @EndTime        = EndTime,

  25:           @Duration       = RunDuration

  26:    from LoadTest.dbo.LoadTestRun

  27:    where LoadTestRunId = @latestLoadTest

  28:   

  29:    select @AlreadyExists = count(*)

  30:    from dbo.LoadTestHistory

  31:    where LoadTestGUID = @loadTestGUID

  32:   

  33:    if (@AlreadyExists = 0) 

  34:      begin

  35:   

  36:        begin transaction

  37:   

  38:        begin try

  39:   

  40:          insert into dbo.LoadTestHistory

  41:          values (@LoadTestGUID,

  42:                  @StartTime,

  43:                  @EndTime,

  44:                  @Duration)

  45:   

  46:          SELECT @loadTestGUID                                as LoadTestGUID,

  47:                 WebLoadTestTransaction.TransactionName, 

  48:                 LoadTestTransactionSummaryData.Average, 

  49:                 STDEV(LoadTestTransactionDetail.ElapsedTime) as StdDev, 

  50:                 LoadTestTransactionSummaryData.Minimum, 

  51:                 LoadTestTransactionSummaryData.Maximum, 

  52:                 LoadTestTransactionSummaryData.Percentile90, 

  53:                 LoadTestTransactionSummaryData.Percentile95, 

  54:                 LoadTestTransactionSummaryData.TransactionCount

  55:          INTO   #tmpLoadTestHistory

  56:          FROM   LoadTest.dbo.LoadTestTransactionDetail INNER JOIN

  57:                 LoadTest.dbo.WebLoadTestTransaction ON LoadTest.dbo.LoadTestTransactionDetail.LoadTestRunId = LoadTest.dbo.WebLoadTestTransaction.LoadTestRunId AND 

  58:                 LoadTest.dbo.LoadTestTransactionDetail.TransactionId = LoadTest.dbo.WebLoadTestTransaction.TransactionId INNER JOIN

  59:                 LoadTest.dbo.LoadTestTransactionSummaryData ON LoadTest.dbo.WebLoadTestTransaction.LoadTestRunId = LoadTest.dbo.LoadTestTransactionSummaryData.LoadTestRunId AND 

  60:                 LoadTest.dbo.WebLoadTestTransaction.TransactionId = LoadTest.dbo.LoadTestTransactionSummaryData.TransactionId

  61:          WHERE  (LoadTestTransactionDetail.LoadTestRunId = @latestLoadTest)

  62:          GROUP BY WebLoadTestTransaction.TransactionName, LoadTestTransactionSummaryData.Average, LoadTestTransactionSummaryData.Minimum, 

  63:                   LoadTestTransactionSummaryData.Maximum, LoadTestTransactionSummaryData.Percentile90, LoadTestTransactionSummaryData.Percentile95, 

  64:                   LoadTestTransactionSummaryData.TransactionCount

  65:          ORDER BY WebLoadTestTransaction.TransactionName

  66:   

  67:          insert dbo.LoadTestHistoryDetails

  68:          select LoadTestGUID, TransactionName, Average, StdDev, Minimum, Maximum, Percentile90, Percentile95, TransactionCount

  69:          from #tmpLoadTestHistory

  70:   

  71:          drop table #tmpLoadTestHistory

  72:   

  73:          commit transaction

  74:        end try

  75:   

  76:        begin catch

  77:          rollback transaction

  78:        end catch

  79:      end

  80:  END

And it works like a champ!

I tested it with this bit of SQL:

   1:  use LoadTestResults

   2:  go

   3:   

   4:  truncate table dbo.LoadTestHistory

   5:  truncate table dbo.LoadTestHistoryDetails

   6:  go

   7:   

   8:  dbo.UpdateLoadTestHistory

   9:  go

  10:   

  11:  select dbo.LoadTestHistory.LoadTestGUID, 

  12:         StartTime, 

  13:         EndTime, 

  14:         Duration, 

  15:         TransactionName, 

  16:         Average, 

  17:         StdDev,

  18:         Minimum,

  19:         Maximum,

  20:         [90th],

  21:         [95th],

  22:         TransactionCount

  23:  from dbo.LoadTestHistory, dbo.LoadTestHistoryDetails

  24:  where dbo.LoadTestHistory.LoadTestGUID = dbo.LoadTestHistoryDetails.LoadTestGUID

And the results come out for all to enjoy:

   1:  LoadTestGUID                         StartTime               EndTime                 Duration TransactionName            Average          StdDev            Minimum Maximum 90th  95th  TransactionCount

   2:  0ebdf821-454f-4c50-8e3a-a82a291adb97 2008-07-03 16:21:33.280 2008-07-03 16:31:33.280 600      someTransaction.Details    3.4155221238938  0.583565372475793 1.526   4.952   4.161 4.35  226

   3:  0ebdf821-454f-4c50-8e3a-a82a291adb97 2008-07-03 16:21:33.280 2008-07-03 16:31:33.280 600      someTransaction.FirstHit   3.42468584070796 0.79565610855916  1.636   11.888  4.053 4.285 226

   4:  0ebdf821-454f-4c50-8e3a-a82a291adb97 2008-07-03 16:21:33.280 2008-07-03 16:31:33.280 600      someTransaction.LookupName 3.46306194690266 0.606631255863035 2.087   5.15    4.285 4.411 226