This is fairly widely known, but though I should document it since we often get trace log files with default settings, and that isn't enough to assess performance or throughput.
The default SSO logging (generally) does not include [PreciseTime]. And if you want better graphs, or better resolution in the SSO products trace logs, then you should add [PreciseTime] [SrcFile] and [Function] to your SSO trace log configuration.
Graphs & Stats with default [Time] (1sec) resolution
The default for most SSO products is still to use [Date] and [Time], so often with a first cut at trace analysis we get a graph that looks like this :
Generally most transactions take less than a sec, so the graph and also any estimate of av transaction time is pretty useless. Even the transactions that took "2 sec" are probably unlucky enough to have occurred at over a timeframe of : 02:24.994 to 02:25.001 - but all we see is 2:24 to 2:25 , so we can only (badly) guess the transaction time must have taken between 1 - 2 sec.
Graphs & Stats with [PreciseTime] (millisec) resolution
If we add [PreciseTime] to the trace log then we get a better estimate of av transaction time, and a better understanding of distribution of request transaction times for example :
We can see two spikes of transaction times, and a small number that took longer. Not show but we also include a summary of min max and av transaction times which then also have much more accurate values.
Additional Graphs for [PreciseTime] (millisec) resolution
Also if we add [PreciseTime][SrcFile] and [Function] to the trace log then we can also tell from the time gaps between each trace line "where" the thread spent time in processing.
So we can produce a pdf report with a graph like this :
Which identifies which trace log steps (effectively thread state transitions) are taking the most time. That is a first step for identifying bottlenecks.
Additionally, given [SrcFile] (roughly) identifies the state of processing of the request, we can also show how many worker threads are in the same state at the same time. for example :
This helps identify delays and bottlenecks in processing. if we want to improve throughput, we review this graph, pick the major bottleneck (hopefully) find a configuration change to allow it to have greater throughput.
(A common example of a policy server bottleneck and it's resolution, if we have a single LDAPBank, we often find in this graph, that all worker threads are queued up in a state waiting to get access to the one LDAPBank. Adding more LDAPBanks allows more threads to proceed in parallel, that decreases the number of threads in this [SrcFile] "wait" state, and increases the overall throughput of the server)
How to add PreciseTime, SrcFile and Function to the trace logging.
The data items for SSO log file configuration are fairly simple. There will be a configuration file eg :
| Server | Trace config file location |
|---|
| Policy Server | /opt/ca/siteminder/config/smtracedefault.txt |
| Web Agent | C:\Program Files\CA\webagent\win32\config\WebAgentTrace.conf |
Access Gateway (formerly Secure Proxy Server) | /opt/ca/secure-proxy/proxy-engine/conf/SecureProxyTrace.conf |
The last two lines of the .conf file are the important ones they will look something like :
components: AgentFramework, HTTPAgent, WebAgent, AgentFunc, Agent_Con_Manager
data: Date, Time, PreciseTime, Pid, Tid, SrcFile, Function, TransactionID, IPAddr, IPPort, AgentName, Resource, User, Message
(note that last line will probably auto-wrap on your screen - it will be one line in the file)
We want to add and make sure that last data: line then contains [PreciseTime, SrcFile and Function. eg:
data: Date, Time, PreciseTime, Pid, Tid, SrcFile, Function, TransactionID, IPAddr, IPPort, AgentName, Resource, User, Message
And that is all you need to do, when you next start trace logging, it will have the new values.
SMTraceAnalysisTool - where do you get it?
The policy trace analysis tool is available from the CA communities site here:
Siteminder Policy Trace Analysis
It has settings to parse the following log types :
x Policy Server Trace Log
x Policy Server smps (stats) Log
x SM Agent trace log
x SPS Agent trace log
x FWS Agent trace log
x SM SDK trace log
x ASA Websphere agent trace log
x ASA Weblogic agent trace log
x WWSI trace log
x CA Directory Query trace log
Hope that helps with your transaction analysis.
Cheers - Mark
PS: I believe there is also an enhancement request to add these fields to the default trace logs, I will hunt up the link for that as well.