Performance Logging

Post date: May 07, 2012 3:17:2 PM

Background

QBO 3's HttpHandler and AbstractObject classes have performance logging built into them. By default, performance logging is turned off in standard website setups, and should remain off unless you are actively engaged in troubleshooting performance issues.

Quick Start

To turn performance logging on, you need to modify the web.config file as follows:

Create a listener to send performance information to, and add the listener to the Performance category source.

...

<add name="PerformanceLog" type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.RollingFlatFileTraceListener,

Microsoft.Practices.EnterpriseLibrary.Logging, Version=5.0.414.0, Culture=neutral, PublicKeyToken=null"

listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.RollingFlatFileTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging, Version=5.0.414.0, Culture=neutral, PublicKeyToken=null"

fileName="performance.log" formatter="Text Formatter" rollInterval="Day" />

...

...

...

</listeners>

</add>

</categorySources>

</loggingConfiguration>

Don't copy and paste this entire block as-is into your web.config file. The ellipsis (...) in the code sample above are placeholders for configuration that already exists in most web.config files. In short, you need to insert or replace the PerformanceLog listener, and add it to the listeners for the Performance category.

Details

QBO 3 leverages the Microsoft Enterprise Template Library (ETL)'s Logging patterns. This does several things, including:

- buffered asynchronous logging: the code does not wait around for the log write
- configurable logging sinks: log to a text file, a database, or a centralized error repository
- ignore logging: code can write to a log with no listeners configured, ignoring the logged item
- tracing within the log (correlate multiple log entries with a single activity)

For performance logging of a call to Valuation.ashx/Summary?ID=X, this is what happens:

- Valuation.ashx's ProcessRequest calls HttpHandler.ProcessRequest
  - HttpHandler.ProcessRequest calls HttpHandler.ProcessQuery
  - HttpHandler.ProcessQuery
    - issues a TraceManager.StartTrace("Performance"), writing a unique string to the Performance logging sink
    - calls ProcessQueryXhtml
    - calls AbstractObject.InvokeXmlReader
      - AbstractObject.InvokeXmlReader calls ExecuteXmlReader
      - ExecuteXmlReader marks a start time, and once the database has returned data,
      - ExecuteXmlReader calls LogPerformance, writing the execution time to the performance log
    - calls the Transform property, to transform the results against an XSLT
      - Transform calls LogPerformance, writing the XSLT load time to the performance log

This creates entries in the performance log akin to:

Message: Start Trace: Activity '28ffd1c2-f95e-4dfe-ad6e-6e47f0f86a2b' in method 'qbo.Application.HttpHandler.ProcessQuery' at 681496160415 ticks

Message: qbo.Mortgage.ValuationObject/ObjectTree took 9 ms to execute

Message: qbo.Mortgage.ValuationObject/ObjectData took 2 ms to execute

Message: qbo.Mortgage.ValuationObject/Navigation took 2 ms to execute

Message: Xslt Templates/Mortgage//Valuation.Summary.xslt load time took 206 ms to execute

Message: End Trace: Activity '28ffd1c2-f95e-4dfe-ad6e-6e47f0f86a2b' in method 'qbo.Application.HttpHandler.ProcessQuery' at 681632296083 ticks (elapsed time: 0.01

Navigating to Valuation.ashx/Summary?ID=X again will produce similar results, minus the loading of Valuation.Summary.xslt (assuming that Xslt caching is turned on).

Logging Performance to Amazon Simple DB

Logging performance is nice, but text files are not particularly useful when it comes to digesting the performance information. The qbo.Logging.Amazon class provides a logging sink that logs to Amazon's Simple DB, which can be queried to find interesting trends. Below is a screen shot of a Visual Studio view of an Amazon Simple DB query of performance data.

Note that the columns are an exact map of the ETL LogEntry structure; all logging has the same basic columns. However, there is a hook for extending these columns via LogEntry.ExtendedProperties.

Interesting columns include:

- ActivityId: this correlates related activity, as described above
- ExecutionTime: this is an extended property QBO adds, allowing you to query for rows where ExecutionTime > X
- MachineName: A1U1Valuation, U1CI, etc.
- Message: this is a full text description of what is being logged (for error logging, this includes a full error message)
- TimeStamp: when the logging activity occurred, formatted so it can be queried alphabetically and remain meaningful
- UserID: PersonID security context used to execute the code

To configure performance logging to Amazon Simple DB, do the following:

- Publish source > qbo3 > ... > Plugins > Amazon > qbo.Logging.Amazon to the target machine(s)
- Set up web.config's loggingConfiguration section to include a listener and category named 'Performance':

...

</listeners>

...

...

</listeners>

</add>

...

</categorySources>

- Note the following interesting attributes of the listener:
  - domain: this is basically the name of the db table to write to
  - accessKey: this is an AWS username; all sites can use the key listed above (it maps to support@quandi
  - s.com, and can only deal with Simple DB)secretKey: this is an AWS password; all sites can use the key listed above
- you can see samples in qbo.ApplicationWeb > web.config

To view performance logging results, you can use the AWSSDK Toolkit for Visual Studio. Once installed, Visual Studio offers an 'AWS Explorer' pane, which you can expand to view Amazon SimpleDB domains, and open a query window for a domain.

Filtering

Logging all performance data is will generate a lot of data. Often, we're interested only in slow-running operations. The qbo.Logging.PerformanceFilter class can be used to limit logging to only those operations that take more than a given amount of time to execute. If used, the default minimum execution time to log is 2500 ms, but this is adjustable in web.config.

Next Steps

The next step is to build web-based dashboards on top of this data, so administrators can:

- Start and stop performance monitoring
- Querying the performance data
- Clear old performance data from the SimpleDB