AnsweredAssumed Answered

Alfresco dead locked on filesystem access operations

Question asked by dmorozov on May 20, 2011
Hello,
We had upgrade to latest version of Tika and Apache POI to solve the issue with memory allocation while documents transformation.
Almost whole the week Alfresco was working without any issues. But today we got dead lock on file system access.

I wondering did anybody faced with such issue?
Here are details:

Tika: 1.0 Snapshort build from trunk
Apache POI 3.8-beta2
OS: Linux Ubuntu
File system settings adjusted to avoid too many open files issue

Thread dump:
"DefaultScheduler_Worker-8" prio=10 tid=0x00007fcc4c8aa800 nid=0x51ab runnable [0x00007fcc5924e000]
   java.lang.Thread.State: RUNNABLE
        at org.apache.poi.util.IOUtils.readFully(IOUtils.java:108)
        at org.apache.poi.poifs.filesystem.NPOIFSFileSystem.<init>(NPOIFSFileSystem.java:261)
        at org.apache.tika.parser.microsoft.OfficeParser.parse(OfficeParser.java:176)
        at org.alfresco.repo.content.TikaOfficeDetectParser.parse(TikaOfficeDetectParser.java:82)

        at org.alfresco.repo.search.impl.lucene.fts.FTSIndexerJob.execute(FTSIndexerJob.java:46)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:216)

Another one:
java.lang.Thread.State: RUNNABLE
        at org.apache.poi.util.IOUtils.readFully(IOUtils.java:108)
        at org.apache.poi.poifs.filesystem.NPOIFSFileSystem.<init>(NPOIFSFileSystem.java:261)
        at org.apache.tika.parser.microsoft.OfficeParser.parse(OfficeParser.java:176)
        at org.alfresco.repo.content.metadata.TikaPoweredMetadataExtracter.extractRaw(TikaPoweredMetadataExtracter.java:241)
        at org.alfresco.repo.content.metadata.AbstractMappingMetadataExtracter.extract(AbstractMappingMetadataExtracter.java:648)

at org.mozilla.javascript.gen.c17.call(file:/alfresco/app/apache-tomcat-6.0.32/webapps/alfresco/WEB-INF/classes/alfresco/templates/webscripts/org/alfresco/repository/upload/upload.post.js)
From upload script

I had about 5 different thread stuck on "at org.apache.poi.util.IOUtils.readFully(IOUtils.java:108)"

I don't know whether it is important but I had at the same time multiple jdbc threads like that:
java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
        at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
        at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
        - locked <0x00007fcd07732500> (a com.mysql.jdbc.util.ReadAheadInputStream)
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2499)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2941)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3489)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568)
        - locked <0x00007fcd0475bdd0> (a java.lang.Object)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2113)
        at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1364)
        - locked <0x00007fcd0475bdd0> (a java.lang.Object)
        at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:169)
        at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:169)
        at com.ibatis.sqlmap.engine.execution.SqlExecutor.executeUpdate(SqlExecutor.java:100)
        at com.ibatis.sqlmap.engine.mapping.statement.MappedStatement.sqlExecuteUpdate(MappedStatement.java:216)
        at com.ibatis.sqlmap.engine.mapping.statement.MappedStatement.executeUpdate(MappedStatement.java:94)
        at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.insert(SqlMapExecutorDelegate.java:393)
        at com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.insert(SqlMapSessionImpl.java:82)
        at org.springframework.orm.ibatis.SqlMapClientTemplate$8.doInSqlMapClient(SqlMapClientTemplate.java:366)
        at org.springframework.orm.ibatis.SqlMapClientTemplate.execute(SqlMapClientTemplate.java:200)
        at org.springframework.orm.ibatis.SqlMapClientTemplate.insert(SqlMapClientTemplate.java:364)
        at org.alfresco.repo.domain.node.ibatis.NodeDAOImpl.insertNodeProperties(NodeDAOImpl.java:552)
        at org.alfresco.repo.domain.node.AbstractNodeDAOImpl.setNodePropertiesImpl(AbstractNodeDAOImpl.java:1751)
        at org.alfresco.repo.domain.node.AbstractNodeDAOImpl.setNodeProperties(AbstractNodeDAOImpl.java:1806)
        at org.alfresco.repo.node.db.DbNodeServiceImpl.addAspectsAndProperties(DbNodeServiceImpl.java:532)
        at org.alfresco.repo.node.db.DbNodeServiceImpl.createNode(DbNodeServiceImpl.java:320)
        at sun.reflect.GeneratedMethodAccessor484.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.alfresco.repo.tenant.MultiTNodeServiceInterceptor.invoke(MultiTNodeServiceInterceptor.java:104)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)

        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.alfresco.repo.tenant.MultiTNodeServiceInterceptor.invoke(MultiTNodeServiceInterceptor.java:104)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)

        at org.alfresco.repo.tenant.MultiTNodeServiceInterceptor.invoke(MultiTNodeServiceInterceptor.java:104)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
/org/alfresco/repository/upload/upload.post.js:349)



I'm not sure that reason was in Tika upgrade.
Another idea is possible problem with MySQL database lock.


Does anybody has any suggestions?

Best Regards,
Denis

Outcomes