X

Best Practices from Oracle Development's A‑Team

Expanding on requestaudit - Tracing who is doing what...and for how long

Introduction

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).

Main Article

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/612.10 16:48:00.493Audit Request Monitor!csMonitorTotalRequests,47,1,0.39009329676628113,0.21034042537212372,1
>requestaudit/612.10 16:48:00.509Audit Request MonitorRequest Audit Report over the last 120 Seconds for server wcc-base_4444****
requestaudit/612.10 16:48:00.509Audit Request Monitor-Num Requests 47 Errors 1 Reqs/sec. 0.39009329676628113 Avg. Latency (secs) 0.21034042537212372 Max Thread Count 1
requestaudit/612.10 16:48:00.509Audit Request Monitor1Service FLD_BROWSETotal Elapsed Time (secs) 3.5320000648498535Num requests 10Num errors 0Avg. Latency (secs) 0.3531999886035919

requestaudit/612.10 16:48:00.509Audit Request Monitor2Service GET_SEARCH_RESULTSTotal Elapsed Time (secs) 2.694999933242798Num requests 6Num errors 0Avg. Latency (secs) 0.4491666555404663
requestaudit/612.10 16:48:00.509Audit Request Monitor3Service GET_DOC_PAGETotal Elapsed Time (secs) 1.8839999437332153Num requests 5Num errors 1Avg. Latency (secs) 0.376800000667572
requestaudit/612.10 16:48:00.509Audit Request Monitor4Service DOC_INFOTotal Elapsed Time (secs) 0.4620000123977661Num requests 3Num errors 0Avg. Latency (secs) 0.15399999916553497
requestaudit/612.10 16:48:00.509Audit Request Monitor5Service GET_PERSONALIZED_JAVASCRIPTTotal Elapsed Time (secs) 0.4099999964237213Num requests 8Num errors 0Avg. Latency (secs) 0.051249999552965164
requestaudit/612.10 16:48:00.509Audit 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/612.10 16:58:35.431IdcServer-68GET_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/612.10 17:00:44.727IdcServer-81GET_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/612.10 17:15:28.665IdcServer-36GET_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.

Be the first to comment

Comments ( 0 )
Please enter your name.Please provide a valid email address.Please enter a comment.CAPTCHA challenge response provided was incorrect. Please try again.Captcha

Recent Content