topic Re: Audit Query Performance in Alfresco Archive

Audit Query Performance

garryw — Fri, 10 Aug 2012 10:29:19 GMT

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 a

Re: Audit Query Performance

afaust — Fri, 10 Aug 2012 14:17:55 GMT

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

Re: Audit Query Performance

garryw — Tue, 14 Aug 2012 09:22:42 GMT

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

Re: Audit Query Performance

afaust — Tue, 14 Aug 2012 09:26:46 GMT

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

Re: Audit Query Performance

garryw — Wed, 15 Aug 2012 08:53:31 GMT

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