Jonathan Malek

I explained in a previous post how you can use the Microsoft Log Parser to dice up Autonomy IDOL search logs.  If you’ve exhausted the typical checks for performance problems in your IDOL installation, it might help to narrow down when the problems occur, and look for cluster periods of slow performance.  That’s a great opportunity to use the Log Parser again.

The first step is to level the playing field on timing information; the content GRL and the DAH GRL show duration information in milliseconds mixed with seconds.  I’m sure there is a clever way to correct that in-stream, but I took the brute-force approach: create separate files from first the rows with seconds, then those with milliseconds, and finally produce a single file from the results.

logparser -i:xml -o:csv “select *, mul(to_real(extract_prefix([autn:duration], 0, ‘ s’)), 1000) as milliseconds into over_1_second.csv from http://server:port/?action=grl&format=xml&tail=10000 where [autn:duration] like ‘% s’”

Then the rows under 1 second:

logparser -i:xml -o:csv “select *, to_real(extract_prefix([autn:duration], 0, ‘ ms’)) as milliseconds into under_1_second.csv from http://server:port/?action=grl&format=xml&tail=10000 where [autn:duration] like ‘% ms’”

Then merge the two files into a single file:

logparser -i:csv -o:csv “select milliseconds, [autn:time], [autn:thread], [autn:status], [autn:action], [autn:request], [autn:client] into merged.csv from *.csv”

These three basic steps serve as the basis for most log analysis I do, so I’ve added them into a script.  The result, merge.csv is a flattened file that contains the data we need.  If you are going to script this, don’t forget to escape the percents, i.e. like ‘%% s’.

Next, we run a quant operation on the logs.  I’ve found that a half-hour period makes for a good range to view the average query performance:

logparser -i:csv -o:csv “select quantize(to_timestamp([autn:time], ‘dd MMM yy hh:mm:ss’), 1800) as period, avg(milliseconds) from merged.csv group by period order by period”

The 1800 constant there is seconds, i.e. half an hour.  The result is a list, here’s a short snippet:

This report shows clearly that around 11pm, we see a sharp decline in performance.  You might also want to add a count(*) clause to the query to highlight the system activity.

Much has been written about the free Microsoft Log Parser, a simple command-line tool that can access and parse log files from a number of sources, execute SQL-like queries against that data, and present results.  Did I mention it’s free?

Autonomy services will drop log files everywhere (literally all over the place), in different formats, and the challenge is to merge all that log data into a single store in order to get a handle on the big picture.  For instance, a single query against the IDOL server shows up in several logs:

1. the GetRequestLog
2. content_index.log
3. possibly the OGS query log (if you have securityinfo)
4. possibly a DAH log (if you’re distributing/mirroring)

How can you aggregate all that information to get a single picture for performance analysis and forensics?  And what about aggregating in other trace information, like application trace logs and IIS logs?  Use the Log Parser.  The first example I’ll give here is a simple query against the GRL–that should provide a view of the current queries that the IDOL is servicing.  I am using the latest version of the Log Parser (2.2, from Jan 2005)–download and install, then either copy to your %SYSTEM32% path, or simply add the install directory to your path, and run the following from a command-line:

That opens a pretty little window for you to scroll through.  You can modify the url with “&tail=[somenumber]” to return a different count of rows (the default is 100).  There are a couple of parameters for the output type (DATAGRID), one is the autoScroll, which is on by default.  This scrolls whenever new data shows up, but does not work with URLs, so you will have to re-run the command-line to get an update.

Let’s look at a slightly more complicated query.  I’m working with a client on query performance, and we’re studying why certain queries take longer than others.  Most queries take under a second, but every once in a while, they take longer.  With a simple query, we can look at exactly the information we need:

select 

    mul(to_real(extract_prefix([autn:duration], 0, ' s')), 1000),

    [autn:request]

from

    http://server:port/?action=grl&format=xml

where

    [autn:duration] like '% s'

We limit this to rows with a duration in the format ’1.62 s’, then turn the value into milliseconds.  Removing the [autn:request] column from the select, and surrounding the mul() operation with an AVG() gives you a handy number on average query time over 1 second.  Make sure to add a more meaningful depth, with something like &tail=10000 to your URL.

I’ll look at more complicated queries next.