Auditrail and Performance

[holden]

Hello everyone!

We need to track the actions done by the uses (a.k.a audit) and for that reason we decided to activate the Auditrail.

We estimate about 200 users simultaneously accessing the application and we are intended to log some of the high level actions such as document deleted, document checked out, new user created, etc. (Please, do not panic… we are not intended to log all what the node service does!)

We are really aware that if activate the Auditrail, it will directly affect the performance of the application; however we would like to maintain an acceptable response time. Summarizing, the question we have are:

:arrow: Has anyone tested the Auditrail on where hundred of users are accessing the repository simultaneously? Does the Auditrail really slow down the system? Is it possible to measure the slow down in a percentage term (such as 20% slower, 50%slower)?

:arrow: How fast is query later the database in order to retrieve some logged actions? We have noticed that logged data "live" in the arg_1, arg_2, … columns. So later, when a query should be made to retrieve some specific information, the LIKE operator should be use in order to get the desired rows. For instance, if you want to retrieve all the spaces copied, the WHERE clause of the SQL sentence will look like this

WHERE Service='FileFolderService' AND method='copy' AND fail='0' AND return_val LIKE '%isFolder=yes%'‍

Look at the restriction

 LIKE '%isFolder=yes%'.‍

The % is on the beginning of the guard. This SQL statement will be definitely slow.  Is there any better solution?


Any help/advice/experience tale/idea,  will be really welcome
Thanks

Holden

[holden]

I have finally used JMeter to perform a kind of performance test just to have an idea of the impact on the response time when Auditrail is enabled.  Auditrail was configured to log just three service methods: Login/Logout, Upload document and User creation.

The results obtained are displayed below

Operartion……………AuditrailDisabled…AuditrailEnabled…..%Difference
Login/logout……………….18ms…………………21ms……………….+15%…..
Upload Document……….154ms……………….215ms……………….+28%…..
User Creation…………….234ms………………619ms………………..+62%….

The commonest operations (login/logout/upload) do not reveal such a big impact on performance (taking into acccount that implementing any kind of logging service in a system will have a direct side-effect on performance and consequently in the response time ).

The greater impact is on the user creation which takes 60% more time than when it is executed with the Auditrail service off. However, user creation is not a real core operation in Alfresco.

Any comments are really welcome

Holden

[kevinr]

Audit trail does indeed have a performance overhead, as you would expect constantly writing the operations to another set of the DB tables. I think the amount of logging is set quite high by default, it is very configurable so you can adjust how much auditing you really need to balance against the performance overhead.

Thanks,

Kevin

[andy]

Hi

The numbers you quote are pretty typical of what I was getting when I tested this. So long as you only audit write operations. Once you start auditing read there is a much bigger overhead (as you turn a read into a write)

As far as using like. Your observation is true. It is not going to give the best query performance. The DB schema is indexed appropriately and other constraints should help (date etc). The arg columns hold a wide range of unstructured data. Some calls will provide data that is easy to query others not. Quite often there are a few ways of doing the slice and dice which may take a bit of investigation to work out the best query.

The default is to log all write operations.

Creating a user via the UI in the default config will create a person, a user, a home space and maybe some holders for user config information. It does more than create folder or create content for example.

Do you have some example queries/use cases?

Andy

[holden]

Hi,

First of all thanks for the info provided. Replying to the last post …

Background about what we need
As any ordinary application we should meet some functional requirements. In our case we should provide a kind of artefact that let users access the information logged by Alfresco for the entire repository. For instance, a user should be able to query the "log file" and retrieve the name of all documents uploaded yesterday or watch the name of the documents that were deleted two weeks ago.

Data to be logged
The main data to be recovered for each operation is
Date
User
Status (ok/error)
Related Data

The related data is the most subjective info to retrieve because it depends on the type of operation. It is basically any kind of information related to the operation such as name of the document uploaded, name of the new user created, name of the topic created, etc.

Operations to be logged:
Please find next the operations we would like to log. Along with each operation you will find the SQL clause that should be applied in order to get the log entries for such operation.

The SQL commands are just a first approach. They put emphasis on the WHERE clause instead of the fields to be retrieved. Maybe for some cases the join clause can be avoided, but this first approach is intended to determine if it is possible to retrieve the data related to each operation.

:arrow: Upload Content

 select * from alf_audit_fact fact
  join alf_audit_date date on fact.audit_date_id = date.id
  join alf_audit_source source on fact.audit_source_id = source.id
  where Service='FileFolderService' and method='create' and fail ='0' and arg_3= '{http://www.alfresco.org/model/content/1.0}content'‍‍‍‍

:arrow: Download Content

Not implemented by Alfresco. As far I understood, downloading a document does not involve any Service and consequently the action cannot be logged. Any suggestion to get this action logged?

:arrow: Move Content

select * from alf_audit_fact fact
  join alf_audit_date date on fact.audit_date_id = date.id
  join alf_audit_source source on fact.audit_source_id = source.id
  where Service='FileFolderService' and method='move' and fail='0' and return_val like '%isFolder=false%'‍‍‍‍

:arrow: Copy Content

select * from alf_audit_fact fact
  join alf_audit_date date on fact.audit_date_id = date.id
  join alf_audit_source source on fact.audit_source_id = source.id
  where Service='FileFolderService' and method='copy' and fail='0' and return_val like '%isFolder=false%'‍‍‍‍

:arrow: Delete Content

Implemented by Alfresco but not working properly. No log is generated when a content is deleted.

:arrow: Checkout Content

select * from alf_audit_fact fact
  join alf_audit_date date on fact.audit_date_id = date.id
  join alf_audit_source source on fact.audit_source_id = source.id
  where Service='CheckoutCheckinService' and method='checkout' and fail='0'‍‍‍‍

:arrow: Checkin Content

select * from alf_audit_fact fact
  join alf_audit_date date on fact.audit_date_id = date.id
  join alf_audit_source source on fact.audit_source_id = source.id
  where Service='CheckoutCheckinService' and method='checkin' and fail='0'‍‍‍‍

:arrow: New space created

select * from alf_audit_fact fact
  join alf_audit_date date on fact.audit_date_id = date.id
  join alf_audit_source source on fact.audit_source_id = source.id
  where Service='FileFolderService' and method='create' and fail ='0' and arg_3='{http://www.alfresco.org/model/content/1.0}folder'‍‍‍‍

:arrow: Discussion topic created

select * from alf_audit_fact fact
  join alf_audit_date date on fact.audit_date_id = date.id
  join alf_audit_source source on fact.audit_source_id = source.id
  where Service='FileFolderService' and method='create' and arg_3='{http://www.alfresco.org/model/forum/1.0}topic'‍‍‍‍

:arrow: Discussion topic deleted

Likewise delete content.

:arrow: Message posted:

select * from alf_audit_fact fact
  join alf_audit_date date on fact.audit_date_id = date.id
  join alf_audit_source source on fact.audit_source_id = source.id
  where Service='FileFolderService' and method='create' and arg_3='{http://www.alfresco.org/model/forum/1.0}post'‍‍‍‍

:arrow: Message deleted: What it was posted is not logged.

Likewise Discussion topic deleted.

:arrow: Login:

select * from alf_audit_fact fact
  join alf_audit_date date on fact.audit_date_id = date.id
  join alf_audit_source source on fact.audit_source_id = source.id
  where Service='AuthenticationService' and method='authenticate'‍‍‍‍

:arrow: Create User:

select * from alf_audit_fact fact
  join alf_audit_date date on fact.audit_date_id = date.id
  join alf_audit_source source on fact.audit_source_id = source.id
 Service='PersonService' and method='createPerson' and fail='0' ‍‍‍‍

:arrow: Email sent by the system:

Some extra implementation is required for our side.

:arrow: Own services operations :

We have created some services that need to log certain operations. Some implementation is required for our side.

Comments/suggestions/critics are welcome
Holden

[kevinr]

Download Content

      Not implemented by Alfresco. As far I understood, downloading a document does not involve any Service and consequently the action cannot be logged. Any suggestion to get this action logged?

ContentService.getReader() is called by the DownloadContentServlet and is an auditable method that you can use to log.

Hope this is useful,

Kevin

[andy]

Hi

I had added the details for how to audit getting content to the audit page on the Wiki. There are a number of operations that could go via the FileFolderService or either the ContentService or the NodeService. You could query for both possibilities or you could configure FileFolderService to also trigger auditing in the services it uses (auditInternal="true").

The Audit API allows for creating your own entries in the audit log.

Delete should be audited. Can you describe your issue in more detail?
It may help to list which service calls have actullay been audited from alf_audit_source.

Andy

[holden]

Hi Andy,

Thanks again for the reply.  This time I divided this post in two parts:

About "auditInternal"
I would like to make a remark on the "auditInternal" flag you mentioned in the last post. I think that the functionality of this flag is not explained in the  http://wiki.alfresco.com/wiki/Audit. If you look at this WIKI page about auditrail, you will find "The auditInternal attribute is not used at the moment". Anyway, after reading your last post I guess it is used to trigger auditing in all the inner services of a service …

The delete Issue
First of all, I would like to give you some background information on where I am performing the test:

-Alfresco version: Version: Community Network - v2.1.0 (dev)
-Database: MySQL 4.1.21 -community
-WebServer: Tomcat 5.5

Now my current configuration in the auditConfig.xml

     …
    <Service name="FileFolderService" mode="none" enabled="true">
        <Method name="rename" mode="all"/>
        <Method name="move" mode="all"/>
        <Method name="copy" mode="all" auditInternal="true" enabled="true" />
        <Method name="create" mode="all" enabled="true"/>
        <Method name="delete" mode="all" auditInternal="true" enabled="true"/>
        <Method name="makeFolders" mode="all"/>
        <Method name="getWriter" mode="all" enabled="true"/>
    </Service>
   …
‍‍‍‍‍‍‍‍‍‍‍‍

Looking at the alf_audit_source table, I notice that there is no entry for Service="FileFolderService"  Method="delete". However I have one entry for the Service="NodeService" Method="delete".

So, when I delete a content, I only get a new entry on the alf_audit_fact table which is for the "nodeService" (method="deleteNode"). 

Holden

[andy]

Hi

Applications can call NodeServce.delete() or FileFolderService.delete(). Both are part of the public service API. Our UI may go direct to the NodeService - which is perfectly OK;  it would be better if it were consistent and use the FileFolderService in this case. If FileFolderService.delete() had been called you would see it, as you will find other FileFolder related methods in the audit trail. I would expect CIFS, FTP and WebDav to do the delete using the FileFolderService.

There is overlap between the FileFolderService and the NodeService and the ContentService. So to audit delete via all entry point (including web dav) you will need to check both.

FileFolderService now uses the non public "nodeService" under the hood so calls to FileFolderService will not be audited as NodeService.delete even with the audit internal flag. This was changed when we added the security layer around the FileFolderService rather than relying on the underlying services for enforcing security (as some other services do)


Andy

[archana_bonkanp]

we have enabled audit in our application 4 months back in the below code in auditconfig.xml file

<Audit xmlns="http://www.alfresco.org/model/audit/1.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" enabled="true" auditInternal="false" mode="all">

it worked fine till yesterday ,but suddenly thowed audotexception error.
Please help us in solving the same

The error is

ERROR [org.springframework.web.context.ContextLoader] Context initialization failed
org.alfresco.repo.audit.AuditException: Failed to audit exception
   at org.alfresco.repo.audit.AuditComponentImpl.auditImpl(AuditComponentImpl.java:275)
   at org.alfresco.repo.audit.AuditComponentImpl.audit(AuditComponentImpl.java:191)
   at org.alfresco.repo.audit.AuditMethodInterceptor.invoke(AuditMethodInterceptor.java:69)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:176)
   at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:107)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:176)
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:210)
   at $Proxy43.createPackage(Unknown Source)
   at org.alfresco.repo.workflow.WorkflowInterpreter.executeCommand(WorkflowInterpreter.java:1275)
   at org.alfresco.repo.workflow.WorkflowInterpreter.access$100(WorkflowInterpreter.java:83)
   at org.alfresco.repo.workflow.WorkflowInterpreter$1$1.doWork(WorkflowInterpreter.java:288)
   at org.alfresco.repo.workflow.WorkflowInterpreter$1$1.doWork(WorkflowInterpreter.java:286)
   at org.alfresco.repo.transaction.TransactionUtil.executeInTransaction(TransactionUtil.java:189)
   at org.alfresco.repo.transaction.TransactionUtil.executeInUserTransaction(TransactionUtil.java:89)
   at org.alfresco.repo.workflow.WorkflowInterpreter$1.doWork(WorkflowInterpreter.java:284)
   at org.alfresco.repo.workflow.WorkflowInterpreter$1.doWork(WorkflowInterpreter.java:282)
   at org.alfresco.repo.security.authentication.AuthenticationUtil.runAs(AuthenticationUtil.java:260)
   at org.alfresco.repo.workflow.WorkflowInterpreter.interpretCommand(WorkflowInterpreter.java:280)
   at org.alfresco.repo.workflow.WorkflowInterpreter.onBootstrap(WorkflowInterpreter.java:149)
   at org.alfresco.util.AbstractLifecycleBean.onApplicationEvent(AbstractLifecycleBean.java:62)
   at org.springframework.context.event.SimpleApplicationEventMulticaster$1.run(SimpleApplicationEventMulticaster.java:77)
   at org.springframework.core.task.SyncTaskExecutor.execute(SyncTaskExecutor.java:49)
   at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:75)
   at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:241)
   at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:349)
   at org.springframework.web.context.support.AbstractRefreshableWebApplicationContext.refresh(AbstractRefreshableWebApplicationContext.java:156)
   at org.springframework.web.context.ContextLoader.createWebApplicationContext(ContextLoader.java:246)
   at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:184)
   at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:49)
   at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:3764)
   at org.apache.catalina.core.StandardContext.start(StandardContext.java:4216)
   at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:760)
   at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:740)
   at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:544)
   at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:825)
   at org.apache.catalina.startup.HostConfig.deployWARs(HostConfig.java:714)
   at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:490)
   at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1138)
   at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:311)
   at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:120)
   at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1022)
   at org.apache.catalina.core.StandardHost.start(StandardHost.java:736)
   at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1014)
   at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:443)
   at org.apache.catalina.core.StandardService.start(StandardService.java:448)
   at org.apache.catalina.core.StandardServer.start(StandardServer.java:700)
   at org.apache.catalina.startup.Catalina.start(Catalina.java:552)
   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
   at java.lang.reflect.Method.invoke(Method.java:585)
   at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:295)
   at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:433)
Caused by: org.hibernate.exception.GenericJDBCException: could not insert: [org.alfresco.repo.audit.hibernate.AuditDateImpl]
   at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)
   at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)
   at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
   at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:40)
   at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2108)
   at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2588)
   at org.hibernate.action.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:48)
   at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:248)
   at org.hibernate.event.def.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:290)
   at org.hibernate.event.def.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:180)
   at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:108)
   at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.saveWithGeneratedOrRequestedId(DefaultSaveOrUpdateEventListener.java:186)
   at org.hibernate.event.def.DefaultSaveEventListener.saveWithGeneratedOrRequestedId(DefaultSaveEventListener.java:33)
   at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsTransient(DefaultSaveOrUpdateEventListener.java:175)
   at org.hibernate.event.def.DefaultSaveEventListener.performSaveOrUpdate(DefaultSaveEventListener.java:27)
   at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:70)
   at org.hibernate.impl.SessionImpl.fireSave(SessionImpl.java:535)
   at org.hibernate.impl.SessionImpl.save(SessionImpl.java:523)
   at org.hibernate.impl.SessionImpl.save(SessionImpl.java:519)
   at org.alfresco.repo.audit.hibernate.HibernateAuditDAO.getAuditDate(HibernateAuditDAO.java:317)
   at org.alfresco.repo.audit.hibernate.HibernateAuditDAO.audit0(HibernateAuditDAO.java:149)
   at org.alfresco.repo.audit.hibernate.HibernateAuditDAO.audit(HibernateAuditDAO.java:139)
   at org.alfresco.repo.audit.AuditComponentImpl.auditImpl(AuditComponentImpl.java:260)
   … 52 more
Caused by: java.sql.SQLException: Data truncated for column 'date_only' at row 1
   at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:946)
   at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2870)
   at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1573)
   at com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1160)
   at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:685)
   at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1400)
   at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1314)
   at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1299)
   at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:101)
   at org.hibernate.id.IdentityGenerator$GetGeneratedKeysDelegate.executeAndExtract(IdentityGenerator.java:73)
   at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:33)
   … 71 more
07:27:44,156 ERROR [org.apache.catalina.core.ContainerBase.[Catalina].[localhost]