Audit Query Performance

[garryw]

Hi,

We have recently started using the auditing with the configuration based upon the default alfresco-access audit application with a couple of extras and the performance of the queries is really slow, taking just over 19 minutes to query directly using the service/api/query url.

There is currently approximately 15000 audit entries spanning across 10 days.  The concerns I have is that over a six month period the data is going to become completely unusable. The main reason behind querying them all is to enable them to be exported/downloaded to a usable format by the user.

Any advise on improving the performance of this would be greatly appreciated.

Thanks

Garry

[afaust]

Hello,

have you enabled web script / FreeMarker debug logging to see what part of the code handling the query URL is taking so long? It would be good to know wether this time is spent in the controller (on the database) or on the template level, before going in for a more thorough investigation analysis.

I wouldn't count 15.000 entries as a sizeable enough data set to warrant a 19 minutes query time, but do not know how complex your audit configuration is (e.g. how much information is associated with these entries).

Do you happen to have a skilled DBA available who can extract some timing measurements / information from your database? Audit queries are fully DB-bound and rely on some basic database comparison features - if the database is maybe lacking an index, this could slow down the query significantly.

By the way, which type of database are you using and what is the version of Alfresco in use?

Regards
Axel

[garryw]

Hi Axel,

Thank you for your reply.

Unfortunately we do not have a dedicated DBA, however I have had a scan through the mysql logs and there weren't any that took a particularly long amount of time.  There are a hell of a lot of queries against alf_prop_class (possibly in the region of around 3000 based on the log file) immediately after the query on alf_audit_app, alf_audit_entry, alf_prop_value etc.

I havent yet enabled web script / Freemarker debug logging, what is the best way to do this and can it be done without restarting tomcat?

We are currently using Alfresco 4.0.d with mysql 5.5.24.

Thanks again for your help.

Garry

[afaust]

Hello,

adjusting the log levels can be done without a restart in Alfresco Enterprise. As far as I know, a restart is required for commuity. For setting the log levels of log4j, please have a look at the base log4j.properties. There are already some comments in there what elements take care of what, e.g. webframework / webscripts. This file can be found in /webapps/alfresco/WEB-INF/classes - either alter it there or place an override in /shared/classes/alfresco/extension (as per best practice).

Regards
Axel

[garryw]

Thanks again for your help.

I have enabled debug logging for the org.springframework.extensions.webscripts package on a development instance we have and although nowhere near the volume of data the query url is still taking around 24 seconds to get 423 records which I believe is pretty excessive.

I have checked the logs for timings and the only entry with a reasonable high timing is below, with the rest of the timings being in milliseconds, and  using Excel sum up to around 3500 milliseconds.
09:19:22,771 DEBUG [org.springframework.extensions.webscripts.AbstractRuntime] Processed script url (GET) /api/audit/query/pf3-audit-access in 1663.4675ms

As an example below are a couple of entries of how much data is associated with each audit entry:

{
    "count": "423",
    "entries":
    [
   {
       "id": "844",
       "application": "pf3-audit-access",
       "user": "garrywatts",
       "time": "2012-08-14T15:03:10.486+01:00",
       "values":
       {
          "path":"\/app:company_home\/st:sites\/cm:test-dev-site\/cm:documentLibrary\/cm:Test OO Doc File.doc"
          ,
          "nodeName":"Test OO Doc File.doc"
          ,
          "action":"READ"
          ,
          "user":"garrywatts"
          ,
          "sub-actions":"readContent"
          ,
          "type":"cm:content"
          ,
          "node":"workspace:\/\/SpacesStore\/9864ea56-cef7-4ff7-92ff-eeb99ed30d37"
          
       }
   },
   {
       "id": "842",
       "application": "pf3-audit-access",
       "user": "garrywatts",
       "time": "2012-08-14T11:32:40.768+01:00",
       "values":
       {
          "path":"\/app:company_home\/app:user_homes\/cm:mjackson"
          ,
          "nodeName":"mjackson"
          ,
          "add":"{{http:\/\/www.alfresco.org\/model\/content\/1.0}name=mjackson, {http:\/\/www.alfresco.org\/model\/content\/1.0}owner=mjackson, {http:\/\/www.alfresco.org\/model\/system\/1.0}node-dbid=1310, {http:\/\/www.alfresco.org\/model\/system\/1.0}store-identifier=SpacesStore, {http:\/\/www.alfresco.org\/model\/system\/1.0}node-uuid=cddaff0b-6bda-4630-a274-de0bb6e56214, {http:\/\/www.alfresco.org\/model\/content\/1.0}modified=Tue Aug 14 11:32:40 BST 2012, {http:\/\/www.alfresco.org\/model\/system\/1.0}locale=en, {http:\/\/www.alfresco.org\/model\/content\/1.0}created=Tue Aug 14 11:32:40 BST 2012, {http:\/\/www.alfresco.org\/model\/system\/1.0}store-protocol=workspace, {http:\/\/www.alfresco.org\/model\/content\/1.0}creator=garrywatts, {http:\/\/www.alfresco.org\/model\/content\/1.0}modifier=garrywatts}"
          ,
          "action":"CREATE"
          ,
          "add":"[{http:\/\/www.alfresco.org\/model\/content\/1.0}ownable]"
          ,
          "user":"garrywatts"
          ,
          "type":"cm:folder"
          ,
          "sub-actions":"createNode updateNodeProperties addNodeAspect"
          ,
          "node":"workspace:\/\/SpacesStore\/cddaff0b-6bda-4630-a274-de0bb6e56214"
          
       }
   },
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

I am really not sure what to look at next with this to identify and solve the problem.

Garry