I spent the weekend mired in a post-mortem covering four hours of erratic system behavior at a client. I used LogParser to normalize and slurp the 400,000+ log entries from redundant application servers into a single SQL database table for analysis, and hacked together a visualization tool based on the SIMILE Timeline project. I started piecing things together by plotting little color-coded stories on the timeline, and I quickly got to the point where I needed to be able to build complex and dynamic queries against the log data. For example:
- When did server X fail over to server Y?
- What errors were logged each time X failed over to Y?
- What order were services stopped and started whenever server X failed over to server Y?
- What errors were logged by service A on server X and service B on server Y between 6:15 and 6:40AM on 1-3-2009?
The filter criteria kept growing incrementally larger and more complex. Looking at the simple schema of the data table created by LogParser:
capturing the various filter combinations in stored procedures wouldn't have been hard, but trying to cover all of the possibilities would have taken a bit of work and distracted me from the task at hand. I'm no SQL maven, and I really wasn't sure how complicated my filtering would need to become to build the stories I wanted to see.
Thankfully, my bag of tricks contains a SQL technique that allows me to filter a data set on an arbitrarily complex set of criteria expressed as XML. For example, instead of writing SQL to query the data directly:
select *
from logentries
where (
eventtype = 'error' and
hostname = 'server X'
);
I can express the same thing as a simple XML document and pass it to a stored procedure:
<filters>
<filter>
<eventtype>
error
</eventtype>
<hostname>
server X
</hostname>
</filter>
</filters>
The stored procedure is capable of processing any combination of filter vectors, and will process multiple <filter /> criteria in a single pass. This allows for more complex filters to be defined as collections of simple <filter /> elements. For instance, this query:
select *
from logentries
where (
eventtype = 'error' and
(
( hostname = 'server X' and source = 'service A' ) or
( hostname = 'server Y' and source = 'service B' )
) and
localinstant between
'1-3-2009 6:15' and '1-3-2009 6:45'
);
is expressed by this XML:
<filters>
<filter>
<eventtype>
error
</eventtype>
<hostname>
server X
</hostname>
<source>
service A
</source>
<start>
1-3-2009 6:15
</start>
<end>
1-3-2009 6:45
</end>
</filter>
<filter>
<eventtype>
error
</eventtype>
<hostname>
server Y
</hostname>
<source>
service B
</source>
<start>
1-3-2009 6:15
</start>
<end>
1-3-2009 6:45
</end>
</filter>
</filters>
Here's the magical stored procedure:
create procedure [dbo].[sp_SelectLogTimelineFromXMLFilter](
@filterXml nText
)
as
-- procedure result
declare @result int;
set @result = 0;
-- XML doc handle
declare @hDoc int;
-- sproc error code
declare @err int;
-- parse XML document
exec @err = sp_xml_preparedocument @hDoc output, @filterXml;
if( 0 < @err )
begin
raiserror(
'Unable to prepare XML filter document',
10,
@err
);
return 1;
end
select e.*, x.label, x.color
from logentries as e
inner join openxml(
@hDoc,
'/filters/filter',
1
)
with(
hostname varchar( 256 ) './hostname',
useridentity varchar( 256 ) './useridentity',
eventtype varchar( 256 ) './eventtype',
eventid int './eventid',
source varchar( 256 ) './source',
[message] varchar( 256 ) './message',
startinstant datetime './start',
endinstant datetime './end',
label varchar( 256 ) './@label',
color varchar( 32 ) './@color'
) as x on(
( x.hostname is null or
e.hostname like x.hostname ) and
( x.useridentity is null or
e.useridentity like x.useridentity ) and
( x.eventtype is null or
e.eventtype like x.eventtype ) and
( x.eventid is null or
e.eventid = x.eventid ) and
( x.source is null or
e.source like x.source ) and
( x.category is null or
e.category like x.category ) and
( x.[message] is null
or e.[message] like x.[message] ) and
( x.startinstant is null or
e.localinstant between
x.startinstant and x.endinstant )
)
order by localinstant;
-- unload XML document
exec @err = sp_xml_removedocument @hDoc;
-- NOTE: bug in sp_xml_removedocument on SQL 2000
-- causes it to return 1 on success, not 0
-- fixed in SQL 2005
if( 1 < @err )
begin
raiserror(
'Unable to remove filter XML document',
10,
1
);
return 1;
end
return @result;
The procedure accepts an XML document in its @filterXml parameter. The magic starts on line 31, where the logentries table is inner-joined against each <filter /> element in the XML document. The with() clause starting on line 36 defines how the filter XML maps onto fields for the join operation using XPath expressions. For instance, line 43:
startdate datetime './start',
defines a field named startdate of type datetime mapped to the <start /> child element of the <filter /> element.
Line 47 starts the definition of the join criteria. If the criteria value is null - or unspecified in the XML document - all results for that criteria are returned. Otherwise, the value supplied in the filter XML is used to limit the data returned from the query. In addition, for varchar() fields I use the LIKE operator for a bit of flexibility.
Using XML to define the filter criteria has a few immediate benefits to my spelunking efforts:
- Building XML from HTTP request data is a breeze. So enabling the timeline to display dynamic sets of log data took little more than adding form elements to the timeline web page.
- A single story containing multiple time ranges and arbitrarily complex filter vectors can be captured in a single XML document. Rather than having to make multiple queries to obtain all of the data necessary to define a timeline, the XML document is processed in a single query.
- The XML document defining a timeline can be persisted to a file or database table. This made event timelines easy to build, save, reload, and edit.
In short, this technique saved me from writing a bunch of one-off SQL and allowed me to focus on making sense of the data.