Using the SqlTraceListener

This is part 4 in a series introducing the Ukadc.Diagnostics project which is currently hosted on codeplex at www.codeplex.com/UkadcDiagnostics.

I've always been a fan of logging to databases and had a lot of success with it in the enterprise. There's no better place to put logging information for in-flight and post-mortem analysis across disparate applications with an end-to-end view of the process. Of course, many people recoil in horror at such a thought and perhaps that isn't so surprising. After all, most enterprise apps sink or swim at the database and the thought of this additional load sends them running, screaming for a DBA. But it can work... yes, even in production. What's more, if things get too much, you can always turn down the volume.

But persuading you of this isn't the goal of this post; I'd merely encourage you to give it a try during development and maybe even system testing. Where better to start with than Ukadc.Diagnostics' SqlTraceListener.

First things first we need to create a database. You've done that already? Good. Next we need to create a table to store the logging information and here's the script to create the one I'll be using in this example.

USE LoggingDB

CREATE TABLE [dbo].[LogStore](
    [LogId] [int] IDENTITY(1,1) NOT NULL,
    [Source] [varchar](50) COLLATE Latin1_General_CI_AS NULL,
    [ActivityId] [uniqueidentifier] NOT NULL,
    [ProcessId] [int] NOT NULL,
    [ThreadId] [varchar](50) COLLATE Latin1_General_CI_AS NOT NULL,
    [EventType] [varchar](50) COLLATE Latin1_General_CI_AS NOT NULL,
    [Message] [varchar](8000) COLLATE Latin1_General_CI_AS NULL,
    [LogTime] [datetime] NOT NULL,
CONSTRAINT [PK_LogStore] PRIMARY KEY CLUSTERED
(
    [LogId] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY]

Note that the database is called LoggingDB and the table is called LogStore.

Right we're ready. Let's hook our example console application from the previous posts up to a SqlTraceListener. We'll begin by adding a connection string to the configuration file in the standard connectionStrings section:

<connectionStrings>
    <add name="log" connectionString="Data Source=localhost; Integrated Security=SSPI; Initial Catalog=LoggingDB" />
</connectionStrings>

I called it Log.

Now we add a SqlTraceListener to the listeners in the system.diagnostics section:

<system.diagnostics>
    <sources>
        <source name="primes" switchValue="All">
            <listeners>
                <add
                    name="console"
                    type="Ukadc.Diagnostics.Listeners.SqlTraceListener, Ukadc.Diagnostics"
                    initializeData="sqlSettings" />
            </listeners>
        </source>
    </sources>
</system.diagnostics>

Note how the initializeData attribute is "sqlSettings" - this is a key to a seperate piece of config over in the ukadc.diagnostics section because we need way more information than we can sensibly fit into a tiny xml attribute. And here's how it looks:

<ukadc.diagnostics>
    <sqlTraceListeners>
        <sqlTraceListener name="sqlSettings" connectionStringName="log"
            commandText="INSERT INTO LogStore VALUES(@Source, @ActivityId, @ProcessId, @ThreadId, @EventType, @Message, @LogTime)"
            commandType="Text">
            <parameters>
                <parameter name="@Source" propertyToken="{Source}" />
                <parameter name="@ActivityId" propertyToken="{ActivityId}" />
                <parameter name="@ProcessId" propertyToken="{ProcessId}" />
                <parameter name="@ThreadId" propertyToken="{ThreadId}" />
                <parameter name="@EventType" propertyToken="{EventType}" callToString="true"/>
                <parameter name="@Message" propertyToken="{Message}" />
                <parameter name="@LogTime" propertyToken="{DateTime}" />
            </parameters>
        </sqlTraceListener>
    </sqlTraceListeners>
</ukadc.diagnostics>

(don't forget to add the section to your config if you haven't already: <section name="ukadc.diagnostics" type="Ukadc.Diagnostics.Configuration.UkadcDiagnosticsSection, Ukadc.Diagnostics"/>)

In this case we're using a SQL Text command but you could happily use a stored procedure if that's your preferred flavour. The parameters section should be fairly self explanatory and we've already looked at tokens. Note that you could use a combined token (multiple tokens in a string) by creating the combined token in the tokens configurations section as follows:

<tokens>
    <token name="{Process}" format="{ProcessName} ({ProcessId})" />
</tokens>

And then adding your {Process} as a parameter to the Sql Listener. In fact, this {Process} token could be used in another combined token or with any other listener or property filter. Sweeet.

And we're done, ready to log to the database. And here's the output from the example console application as seen from Sql Server Management Studio:

Easy peasy. And incredibly useful, especially in a server environment where you have multiple related server based applications logging to the same database. For a more advanced (and useful) example of the SqlTraceListener in action head over to the project site and read the Quick Reference Example - it even explains how to make the most of the ActivityId which is being frivolously wasted in our example console app.

Assuming you've read that example (off you go...) let's consider some of the power it offers. We can now pull all errors from the database with a simple query:

SELECT * FROM LogStore WHERE EventType = 'Error' OR EventType = 'Critical'

We could even use this data to perform analysis on exactly what errors are occuring most frequently (this isn't a lesson in T-SQL so I won't bore you with some relatively simple group by queries).

Another tip is to write the ActivityId (what? you haven't read the Quick Reference Example yet?) to the HTML comments of all your HTML pages. Then you can simply view source and grab the ActivityId from any page and paste it into a query to view all logging events related to the creation of that page (even crossing process boundaries by propagating the activity id as detailed in the Quick Reference Example). Additionally you can make sure the ActivityId is presented in any error dialog so that the user can use it as a common key when talking to operations and performing post-mortem on a problem.

Furthermore, if you've appropriately logged some Start and Stop operations at key touch points, we can write a query that does some T-SQL kung fu to give us the min, max and average call times for each operation. Here's an example query that can do just that:

With DepthView(LogId, Source, ActivityId, ProcessId, ThreadId, EventType, Message, LogTime, Depth) AS
(
    select
        ols1.LogId, ols1.Source, ols1.ActivityId, ols1.ProcessId, ols1.ThreadId, ols1.EventType, ols1.Message, ols1.LogTime,
        COALESCE((SELECT SUM(CASE WHEN ols2.EventType = 'Start' THEN 1 WHEN ols2.EventType = 'Stop' THEN -1 ELSE 0 END)
    FROM LogStore ols2
    WHERE ols2.LogId <= ols1.logid AND ols2.ActivityId = ols1.ActivityId AND ols1.Message = ols2.Message), 0)
    AS Depth
    from
        LogStore ols1
)

SELECT
    list.Operation,
    AVG(list.CallTime) as 'Average CallTime (ms)',
    MAX(list.CallTime) as 'Max CallTime (ms)',
    MIN(list.CallTime) as 'Min CallTime (ms)',
    COUNT(list.Operation) as '# Calls'
FROM
(
    SELECT
        t1.[Message] as 'Operation',
        DATEDIFF (ms, t1.[LogTime], t2.[LogTime]) as 'CallTime'
    FROM DepthView t1
        LEFT OUTER JOIN DepthView t2
            ON t2.Depth = t1.Depth-1 AND t2.EventType = 'Stop'
                AND t2.ActivityId = t1.ActivityId
                AND t2.ThreadId = t1.ThreadId
                AND t2.LogId > t1.LogId
                AND t2.[Message] = t1.[Message]
    WHERE t1.EventType = 'Start'
) list
GROUP BY list.Operation


This query uses Common Table Expressions (CTEs) so will only work on SQL 2005+ and it can work your database pretty hard so you'll at least want to add an index to the ActivityId column. Thanks to Simon Ince and Jon Swift for their help with this query.

Here are some example results:

Next we'll look at how you can use Ukadc.Diagnostics TraceListeners with Enterprise Library's logging functionality.