Expanding on requestaudit - Tracing who is doing what...and for how long
- by Kyle Hatlestad
One of the most helpful tracing sections in WebCenter Content (and one that is on by default) is the requestaudit tracing. This tracing section summarizes the top service requests happening in the server along with how they are performing. By default, it has 2 different rotations. One happens every 2 minutes (listing up to 5 services) and another happens every 60 minutes (listing up to 20 services). These traces provide the total time for all the requests against that service along with the number of requests and its average request time. This information can provide a good start in possibly troubleshooting performance issues or tracking a particular issue.
>requestaudit/6 12.10 16:48:00.493 Audit Request Monitor !csMonitorTotalRequests,47,1,0.39009329676628113,0.21034042537212372,1>requestaudit/6 12.10 16:48:00.509 Audit Request Monitor Request Audit Report over the last 120 Seconds for server wcc-base_4444****requestaudit/6 12.10 16:48:00.509 Audit Request Monitor -Num Requests 47 Errors 1 Reqs/sec. 0.39009329676628113 Avg. Latency (secs) 0.21034042537212372 Max Thread Count 1requestaudit/6 12.10 16:48:00.509 Audit Request Monitor 1 Service FLD_BROWSE Total Elapsed Time (secs) 3.5320000648498535 Num requests 10 Num errors 0 Avg. Latency (secs) 0.3531999886035919
requestaudit/6 12.10 16:48:00.509 Audit Request Monitor 2 Service GET_SEARCH_RESULTS Total Elapsed Time (secs) 2.694999933242798 Num requests 6 Num errors 0 Avg. Latency (secs) 0.4491666555404663requestaudit/6 12.10 16:48:00.509 Audit Request Monitor 3 Service GET_DOC_PAGE Total Elapsed Time (secs) 1.8839999437332153 Num requests 5 Num errors 1 Avg. Latency (secs) 0.376800000667572requestaudit/6 12.10 16:48:00.509 Audit Request Monitor 4 Service DOC_INFO Total Elapsed Time (secs) 0.4620000123977661 Num requests 3 Num errors 0 Avg. Latency (secs) 0.15399999916553497requestaudit/6 12.10 16:48:00.509 Audit Request Monitor 5 Service GET_PERSONALIZED_JAVASCRIPT Total Elapsed Time (secs) 0.4099999964237213 Num requests 8 Num errors 0 Avg. Latency (secs) 0.051249999552965164requestaudit/6 12.10 16:48:00.509 Audit Request Monitor ****End Audit Report*****
To change the default rotation or size of output, these can be set as configuration variables for the server:
RequestAuditIntervalSeconds1 – Used for the shorter of the two summary intervals (default is 120 seconds)RequestAuditIntervalSeconds2 – Used for the longer of the two summary intervals (default is 3600 seconds)RequestAuditListDepth1 – Number of services listed for the first request audit summary interval (default is 5)RequestAuditListDepth2 – Number of services listed for the second request audit summary interval (default is 20)
If you want to get more granular, you can enable 'Full Verbose Tracing' from the System Audit Information page and now you will get an audit entry for each and every service request.
>requestaudit/6 12.10 16:58:35.431 IdcServer-68 GET_USER_INFO [dUser=bob][StatusMessage=You are logged in as 'bob'.] 0.08765099942684174(secs)
What's nice is it reports who executed the service and how long that particular request took. In some cases, depending on the service, additional information will be added to the tracing relevant to that service.
>requestaudit/6 12.10 17:00:44.727 IdcServer-81 GET_SEARCH_RESULTS [dUser=bob][QueryText=%28+dDocType+%3cmatches%3e+%60Document%60+%29][StatusCode=0][StatusMessage=Success] 0.4696030020713806(secs)
You can even go into more detail and insert any additional data into the tracing. You simply need to add this configuration variable with a comma separated list of variables from local data to insert.
RequestAuditAdditionalVerboseFieldsList=TotalRows,path
In this case, for any search results, the number of items the user found is traced:
>requestaudit/6 12.10 17:15:28.665 IdcServer-36 GET_SEARCH_RESULTS [TotalRows=224][dUser=bob][QueryText=%28+dDocType+%3cmatches%3e+%60Application%60+%29][Sta...
I also recently ran into the case where services were being called from a client through RIDC. All of the services were being executed as the same user, but they wanted to correlate the requests coming from the client to the ones being executed on the server. So what we did was add a new field to the request audit list:
RequestAuditAdditionalVerboseFieldsList=ClientToken
And then in the RIDC client, ClientToken was added to the binder along with a unique value that could be traced for that request. Now they had a way of tracing on both ends and identifying exactly which client request resulted in which request on the server.
