Hyland Community
Help
cancel
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results for 
Search instead for 
Did you mean: 

session flushed; stale data delivered shortly thereafter

jharrop
Champ in-the-making
Champ in-the-making

‎02-04-2008 07:32 AM

Hi, I need some help please.

I'm finding that after a transaction commits, I have to wait some 5 seconds before the new data is available to a second transaction.

I'd like to understand why this is happening, and whether there is anything I can do to ensure that the state is synchronized with the database immediately  (or if it is, that the second transaction gets the fresh data - though hibernate.cache.use_query_cache=false made no difference).

In this specific case, the first transaction uses JCR to make a node versionable, checks it out, and modifies its contents.  The second transaction tries to read the new contents.

First transaction 

20:15:23,299 http-8080-Processor22 INFO  [org.alfresco.jcr.session.SessionImpl.init(SessionImpl.java:191)] 18c0e26b-d30a-11dc-97ba-415da2aefe8f
20:15:23,303 http-8080-Processor22 INFO  [org.alfresco.jcr.session.SessionImpl$OuterTransaction.begin(SessionImpl.java:923)] relying on existing
20:15:24,457 http-8080-Processor22 INFO  [org.plutext.server.io.ChunkingSaveToJCR.save(ChunkingSaveToJCR.java:158)] Wrote out:
<?xml version="1.0" encoding="UTF-8"?>
<Types xmlns="http://schemas.openxmlformats.org/package/2006/content-types">
:
  <Override PartName="/skeleton.xml" ContentType="application/plutext-skeleton"/>
:
</Types>
20:15:24,475 http-8080-Processor22 INFO  [org.docx4j.openpackaging.io.SaveToJCR.saveRawXmlPart(SaveToJCR.java:277)]  made mix:versionable
20:15:24,527 http-8080-Processor22 INFO  [org.alfresco.jcr.session.SessionImpl.save(SessionImpl.java:449)] save() .. 
20:15:24,528 http-8080-Processor22 INFO  [org.alfresco.jcr.session.SessionImpl$OuterTransaction.begin(SessionImpl.java:923)] relying on existing 
20:15:24,592 http-8080-Processor22 INFO  [org.alfresco.repo.version.VersionServiceImpl.createVersion(VersionServiceImpl.java:299)] Creating version.. using$Proxy3
20:15:24,819 http-8080-Processor22 INFO  [org.alfresco.repo.node.db.DbNodeServiceImpl.createAssociation(DbNodeServiceImpl.java:1384)] creating assocs
20:15:24,994 http-8080-Processor22 INFO  [org.docx4j.openpackaging.io.SaveToJCR.saveRawXmlPart(SaveToJCR.java:360)] PUT SUCCESS: [Content_Types].xml(/app:company_home/app:user_homes/sys:Jason_x0027_s_x0020_Home_x0020_Space/cm:FEB27.docx/cm:_x005b_Content_Types_x005d_.xml) VERSION 1.0

20:15:25,575 http-8080-Processor22 INFO  [org.alfresco.repo.node.db.hibernate.HibernateNodeDaoServiceImpl.flush(HibernateNodeDaoServiceImpl.java:340)] flushing‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Later in the same transaction, I load that resource again, and the content is as expected (ie its the content I just wrote):

20:15:34,713 http-8080-Processor22 INFO  [org.plutext.server.io.ChunkingLoadFromJCR.deprecatedGetDocumentFromJCRPart(ChunkingLoadFromJCR.java:258)] Fetching cm:_x005b_Content_Types_x005d_.xml
20:15:34,724 http-8080-Processor22 INFO  [org.docx4j.JcrNodeMapper.AlfrescoJcrNodeMapper.getJcrData(AlfrescoJcrNodeMapper.java:50)] getting {http://www.alfresco.org/model/content/1.0}content
getting {http://www.alfresco.org/model/content/1.0}content
20:15:34,730 http-8080-Processor22 WARN  [org.docx4j.openpackaging.io.Load.debugPrint(Load.java:54)] <?xml version="1.0" encoding="UTF-8"?>
<Types xmlns="http://schemas.openxmlformats.org/package/2006/content-types">
:
  <Override ContentType="application/plutext-skeleton" PartName="/skeleton.xml"/>
:
</Types>
‍‍‍‍‍‍‍‍‍‍

Second transaction

But next, in a new session - 2.7 sec later - the data retrieved is what it was before the first transaction took place:

20:15:37,478 http-8080-Processor24 INFO  [org.alfresco.jcr.session.SessionImpl.init(SessionImpl.java:191)] 2138b389-d30a-11dc-97ba-415da2aefe8f  

20:15:37,699 http-8080-Processor24 WARN  [org.docx4j.openpackaging.io.Load.debugPrint(Load.java:54)] <?xml version="1.0" encoding="UTF-8"?>
   
<Types xmlns="http://schemas.openxmlformats.org/package/2006/content-types">
: 
   // Where is my data?!
:
</Types> 
‍‍‍‍‍‍‍‍‍‍

Third transaction

But if you wait a little bit longer  - 5 secs is enough - and a new session can see the results of the first transaction.

20:16:06,168 http-8080-Processor24 INFO  [org.alfresco.jcr.session.SessionImpl.init(SessionImpl.java:191)] 324f657a-d30a-11dc-97ba-415da2aefe8f

20:16:06,304 http-8080-Processor24 INFO  [org.alfresco.repo.webdav.plutext.GetMethod.executeImpl(GetMethod.java:300)] 1.0
20:16:06,312 http-8080-Processor24 INFO  [org.alfresco.repo.webdav.plutext.GetMethod.executeImpl(GetMethod.java:301)] <Types xmlns="http://schemas.openxmlformats.org/package/2006/content-types"><Default ContentType="application/vnd.openxmlformats-package.relationships+xml" Extension="rels" />
:
    <Override ContentType="application/plutext-skeleton" PartName="/skeleton.xml" />
:
</Types>
‍‍‍‍‍‍‍‍‍

Each of the transactions is using RetryingTransactionHelper's doInTransaction.

thanks

Jason
Labels:
0 Kudos
6 REPLIES 6

derek
Star Contributor
Star Contributor

‎02-06-2008 11:00 AM

Hi,
The first and second transactions appear to be accessing the content from a different (JCR) API compared to the third transaction (WebDAV).

Is the second transaction running synchronously after the first?
If you put a pause in the second transaction, does the data become available?
What version of the product are you developing against?
Are the different access methods going against the same machine?

Switch on debugging for:
   log4j.logger.org.alfresco.util.transaction.SpringAwareUserTransaction

We have many instances where we commit and then immediately retrieve data.  I'm not aware of anything that would be introducing a fundamental delay in the system.
0 Kudos

jharrop
Champ in-the-making
Champ in-the-making

‎02-07-2008 08:43 AM

Hi Derek

Thanks for your reply.

The first and second transactions appear to be accessing the content from a different (JCR) API compared to the third transaction (WebDAV).

Yes that is correct.  The third transaction (WebDAV) is only there to demonstrate that the data does in fact become available later. You can disregard it.

Is the second transaction running synchronously after the first?

Yes, the second transaction is via a web service, which the client does not invoke until after it has received a response from the first.

If you put a pause in the second transaction, does the data become available?

At present, I have the delay on the client.  That is, the client waits 5 secs before invoking the web service.  This is enough for the data to become available.

I imagine putting the delay in the second transaction would amount to the same thing.

What version of the product are you developing against?

2.9B head from 11 Jan 08

Are the different access methods going against the same machine?

This is one client talking to a single Alfresco server running on a second machine.  The first transaction is a GET request which results in some JCR processing in order to generate the response.

The second transaction is invoked via a web service call.

Switch on debugging for:
   log4j.logger.org.alfresco.util.transaction.SpringAwareUserTransaction

I've done that, but today I'm having trouble replicating the behaviour.  This is a bit of a surprise, because previously, the behaviour happened consistently.  I've tried reverting to a WAR file from 2 days ago, and I can't replicate it with that either. 

Needless to say, I've captured logs of what happens during the transactions when things work - let me know if that's of any interest to you.

Otherwise, I guess I'll leave that debugging on, and wait to see whether it happens again.  I'm going to install things on another server tomorrow, so it will be interesting to see whether the problem shows up there.
0 Kudos

jharrop
Champ in-the-making
Champ in-the-making

‎02-08-2008 04:57 AM

Hi Derek

.. today I'm having trouble replicating the behaviour.  This is a bit of a surprise, because previously, the behaviour happened consistently.

Otherwise, I guess I'll leave that debugging on, and wait to see whether it happens again.  I'm going to install things on another server tomorrow, so it will be interesting to see whether the problem shows up there.

The behaviour seems to reproduce consistently on a new server built from svn today.  The log is too large to post here - shall I open an issue and attach there?

thanks

Jason
0 Kudos

derek
Star Contributor
Star Contributor

‎02-08-2008 05:16 AM

I imagine putting the delay in the second transaction would amount to the same thing.
Could you verify that the data is not there immediately after saving the JCR session using another JCR session.

Before you create a JIRA issue, can you go through the logs and locate the start of the JCR save and locate the transaction begin and end that apply to it?

If you can verify that a second sequential JCR session doesn't see the first's data, then we probably have an issue in the JCR save code.  Are you using JCR-RMI?

If this goes nowhere then a JIRA issue will be needed so I can take a look at the logs.  It would be helpful if you could identify the different events in the logs.  I can't see that the fundamental commit doesn't actually commit - but JCR may partake in existing transactions or it may start its own with the session.
0 Kudos

jharrop
Champ in-the-making
Champ in-the-making

‎02-08-2008 08:37 AM

can you go through the logs and locate the start of the JCR save and locate the transaction begin and end that apply to it?

If you can verify that a second sequential JCR session doesn't see the first's data, then we probably have an issue in the JCR save code.

Ok, now we are getting somewhere Smiley Happy

What is happening is that the first interaction with the client is 'completing' in the following sense:

12:37:37,231 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.WebDAVMethod$1.execute(WebDAVMethod.java:146)] .executeImpl() returned. 
12:37:37,231 http-8080-Processor23 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:305)] Completing transaction for [UserTransaction] ‍‍


But, that transaction doesn't actually commit until 12:37:44,532  (ie 7.3 sec later!).

12:37:44,532 http-8080-Processor23 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:457)] Committed user transaction: org.alfresco.util.transaction.SpringAwareUserTransaction@1ed2fe7    <——- end of first transaction!
12:37:44,539 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.WebDAVMethod.execute(WebDAVMethod.java:156)] .. doInTransaction() returned. 
12:37:44,540 http-8080-Processor23 DEBUG [org.alfresco.repo.webdav.plutext.WebDAVServlet.service(WebDAVServlet.java:221)] GET took 27452ms to execute‍‍‍

And in the meantime, the second interaction with the user occurs (and so, not surprisingly (at least now), it retrieves stale data).  I've attached a larger but still edited portion of the logs at the end of this message.

So, the question is, why the delay before the commit?

To explore that, I ran the first user interaction only (ie not the second).  


13:16:36,833 http-8080-Processor24 INFO  [org.alfresco.repo.webdav.plutext.WebDAVServlet.createMethod(WebDAVServlet.java:235)] createMethod invoked.
13:16:36,835 http-8080-Processor24 INFO  [org.alfresco.repo.webdav.plutext.WebDAVServlet.createMethod(WebDAVServlet.java:241)] WebDAV request GET on path /alfresco/plutextwebdav/User%20Homes/jason/SEC7.docx
13:16:36,835 http-8080-Processor24 INFO  [org.alfresco.repo.webdav.plutext.WebDAVServlet.createMethod(WebDAVServlet.java:270)] invoking setDetails.
13:16:36,836 http-8080-Processor24 INFO  [org.alfresco.repo.webdav.plutext.WebDAVMethod.setDetails(WebDAVMethod.java:65)] m_davHelper set; org.alfresco.repo.webdav.plutext.WebDAVHelper
13:16:36,836 http-8080-Processor24 INFO  [org.alfresco.repo.webdav.WebDAVMethod.execute(WebDAVMethod.java:154)] about to invoke doInTransaction() ..
13:16:36,837 http-8080-Processor24 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.prepareTransactionInfo(TransactionAspectSupport.java:275)] Getting transaction for [UserTransaction]
13:16:36,838 http-8080-Processor24 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.begin(SpringAwareUserTransaction.java:378)] Began user transaction: org.alfresco.util.transaction.SpringAwareUserTransaction@491682
13:16:36,838 http-8080-Processor24 INFO  [org.alfresco.repo.webdav.WebDAVMethod$1.execute(WebDAVMethod.java:144)] about to invoke executeImpl() ..
13:16:36,838 http-8080-Processor24 INFO  [org.alfresco.repo.webdav.plutext.GetMethod.executeImpl(GetMethod.java:207)] Executing GET ..
:
:
13:16:51,531 http-8080-Processor24 INFO  [org.alfresco.repo.webdav.WebDAVMethod$1.execute(WebDAVMethod.java:146)] .executeImpl() returned.
13:16:51,531 http-8080-Processor24 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:305)] Completing transaction for [UserTransaction]
13:16:54,312 Thread-25 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.prepareTransactionInfo(TransactionAspectSupport.java:275)] Getting transaction for [UserTransaction]
13:16:54,313 Thread-25 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.begin(SpringAwareUserTransaction.java:378)] Began user transaction: org.alfresco.util.transaction.SpringAwareUserTransaction@28fa5f
13:16:54,315 Thread-25 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:305)] Completing transaction for [UserTransaction]
13:16:54,316 Thread-25 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:457)] Committed user transaction: org.alfresco.util.transaction.SpringAwareUserTransaction@28fa5f
13:16:54,883 http-8080-Processor24 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:457)] Committed user transaction: org.alfresco.util.transaction.SpringAwareUserTransaction@491682
13:16:54,883 http-8080-Processor24 INFO  [org.alfresco.repo.webdav.WebDAVMethod.execute(WebDAVMethod.java:156)] .. doInTransaction() returned.
13:16:54,884 http-8080-Processor24 DEBUG [org.alfresco.repo.webdav.plutext.WebDAVServlet.service(WebDAVServlet.java:221)] GET took 18051ms to execute‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Even with no other user requests to deal with, there is still a 3.3 sec delay between .executeImpl() returning back to execute() in the RetryingTransactionCallback object, and the actual commit. 

I hope this is enough for you to be able to deduce what is happening.

Are you using JCR-RMI?

No.  Everything is running within the Alfresco webapp.

thanks,

Jason


# First "transaction" with client

12:37:17,088 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.plutext.WebDAVServlet.createMethod(WebDAVServlet.java:235)] createMethod invoked.
12:37:17,089 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.plutext.WebDAVServlet.createMethod(WebDAVServlet.java:241)] WebDAV request GET on path /alfresco/plutextwebdav/User%20Homes/jason/TIMING8.docx
12:37:17,092 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.plutext.WebDAVServlet.createMethod(WebDAVServlet.java:270)] invoking setDetails.
12:37:17,092 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.plutext.WebDAVMethod.setDetails(WebDAVMethod.java:65)] m_davHelper set; org.alfresco.repo.webdav.plutext.WebDAVHelper
12:37:17,093 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.WebDAVMethod.execute(WebDAVMethod.java:154)] about to invoke doInTransaction() .. 
12:37:17,094 http-8080-Processor23 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.prepareTransactionInfo(TransactionAspectSupport.java:275)] Getting transaction for [UserTransaction]
12:37:17,094 http-8080-Processor23 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.begin(SpringAwareUserTransaction.java:378)] Began user transaction: org.alfresco.util.transaction.SpringAwareUserTransaction@1ed2fe7  <—— start of first transaction
12:37:17,095 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.WebDAVMethod$1.execute(WebDAVMethod.java:144)] about to invoke executeImpl() .. 
12:37:17,095 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.plutext.GetMethod.executeImpl(GetMethod.java:207)] Executing GET ..

12:37:17,113 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.plutext.GetMethod.executeImpl(GetMethod.java:227)] its a docx which needs to be zipped up ..
12:37:17,113 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.plutext.Helper.getJcrSession(Helper.java:42)] Getting JCR Repository and Session
12:37:17,114 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.plutext.Helper.getJcrSession(Helper.java:55)] JCR Repository and Session .. SUCCESS .. returning Session
:
12:37:37,230 http-8080-Processor23 INFO  [org.plutext.server.io.ChunkingSaveToZipFile.save(ChunkingSaveToZipFile.java:156)] …Done!
12:37:37,231 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.WebDAVMethod$1.execute(WebDAVMethod.java:146)] .executeImpl() returned. 
12:37:37,231 http-8080-Processor23 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:305)] Completing transaction for [UserTransaction]  <—– but, it doesn't commit until 12:37:44,532  (ie 7.3 sec later!)

# Second "transaction" with client (comprising two SOAP requests, which both use JCR)

12:37:39,096 http-8080-Processor22 DEBUG [org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:266)] Enter: JavaProvider::invoke (org.alfresco.repo.webservice.axis.SpringBeanRPCProvider@a10a6b)
12:37:39,297 http-8080-Processor22 DEBUG [org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:352)] Exit: JavaProvider::invoke (org.alfresco.repo.webservice.axis.SpringBeanRPCProvider@a10a6b)
12:37:39,735 http-8080-Processor22 DEBUG [org.apache.ws.axis.security.WSDoAllReceiver.invoke(WSDoAllReceiver.java:107)] WSDoAllReceiver: enter invoke() with msg type: null
12:37:39,742 http-8080-Processor22 DEBUG [org.apache.ws.axis.security.WSDoAllReceiver.invoke(WSDoAllReceiver.java:137)] Received SOAP request: 
12:37:39,762 Thread-25 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.prepareTransactionInfo(TransactionAspectSupport.java:275)] Getting transaction for [UserTransaction]
12:37:39,763 Thread-25 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.begin(SpringAwareUserTransaction.java:378)] Began user transaction: org.alfresco.util.transaction.SpringAwareUserTransaction@8303e5
:
12:37:39,810 http-8080-Processor22 INFO  [org.alfresco.repo.webservice.PlutextWebService.getJcrSession(PlutextWebService.java:152)] Getting JCR Repository and Session
12:37:39,811 http-8080-Processor22 INFO  [org.alfresco.repo.webservice.PlutextWebService.getJcrSession(PlutextWebService.java:165)] JCR Repository and Session .. SUCCESS .. returning Session
:
12:37:40,659 Thread-25 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:457)] Committed user transaction: org.alfresco.util.transaction.SpringAwareUserTransaction@8303e5


12:37:41,166 http-8080-Processor25 DEBUG [org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:266)] Enter: JavaProvider::invoke
 (org.alfresco.repo.webservice.axis.SpringBeanRPCProvider@a10a6b)
12:37:41,174 http-8080-Processor25 DEBUG [org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:352)] Exit: JavaProvider::invoke (org.alfresco.repo.webservice.axis.SpringBeanRPCProvider@a10a6b)
12:37:41,564 http-8080-Processor25 DEBUG [org.apache.ws.axis.security.WSDoAllReceiver.invoke(WSDoAllReceiver.java:107)] WSDoAllReceiver: enter invoke() with msg type: null
12:37:41,569 http-8080-Processor25 DEBUG [org.apache.ws.axis.security.WSDoAllReceiver.invoke(WSDoAllReceiver.java:137)] Received SOAP request: 
12:37:41,606 http-8080-Processor25 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.prepareTransactionInfo(TransactionAspectSupport.java:275)] Getting transaction for [UserTransaction]
12:37:41,607 http-8080-Processor25 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.begin(SpringAwareUserTransaction.java:378)] Began user transaction: org.alfresco.util.transaction.SpringAwareUserTransaction@950fe4
12:37:41,607 http-8080-Processor25 INFO  [org.alfresco.repo.webservice.PlutextWebService.getJcrSession(PlutextWebService.java:152)] Getting JCR Repository and Session
12:37:41,608 http-8080-Processor25 INFO  [org.alfresco.repo.webservice.PlutextWebService.getJcrSession(PlutextWebService.java:165)] JCR Repository and Session .. SUCCESS .. returning Session
:
12:37:41,695 http-8080-Processor25 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:305)] Completing transaction for [UserTransaction]
12:37:41,697 http-8080-Processor25 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:457)] Committed user transaction: org.alfresco.util.transaction.SpringAwareUserTransaction@950fe4
12:37:41,697 http-8080-Processor25 DEBUG [org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:352)] Exit: JavaProvider::invoke (org.alfresco.repo.webservice.axis.SpringBeanRPCProvider@a8d1a4)

# Only after the second "transaction" completes, does the first one (1ed2fe7)

12:37:44,532 http-8080-Processor23 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:457)] Committed user transaction: org.alfresco.util.transaction.SpringAwareUserTransaction@1ed2fe7    <——- end of first transaction!
12:37:44,539 http-8080-Processor23 INFO  [org.alfresco.repo.webdav.WebDAVMethod.execute(WebDAVMethod.java:156)] .. doInTransaction() returned. 
12:37:44,540 http-8080-Processor23 DEBUG [org.alfresco.repo.webdav.plutext.WebDAVServlet.service(WebDAVServlet.java:221)] GET took 27452ms to execute ‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍
0 Kudos

jharrop
Champ in-the-making
Champ in-the-making

‎04-14-2008 08:03 AM

I never did figure out why there was a long pause in that transaction.

Now I'm looking at another case where there are long pauses I can't explain.  In this case, my web service is invoked and it does some stuff using the jcr interface (all running as part of the alfresco webapp).  It completes some 16.9 seconds later - but for 12.5 seconds its not obvious what is happening.  I have verbose:gc turned on; you can see that although there are some gc pauses, these don't account for the delay.

Below is the log output, plus a bit of commentary.  I've emboldened the first few timestamps where the major delays occur.  Can anyone shed any light on what might be happening?

thanks

Jason

By way of introduction, axis receives SOAP request, and transaction debb starts  (will commit 16.9 sec later)

11:28:54,691 http-8080-Processor25 DEBUG [org.apache.ws.axis.security.WSDoAllReceiver.invoke(WSDoAllReceiver.java:223)] Processed received SOAP request
11:28:54,710 http-8080-Processor25 DEBUG [org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:266)] Enter: JavaProvider::invoke (org.alfresco.repo.webservice.axis.SpringBeanRPCProvider@e73995)
11:28:54,710 DEBUG [org.apache.axis.providers.java.JavaProvider] Enter: JavaProvider::invoke (org.alfresco.repo.webservice.axis.SpringBeanRPCProvider@e73995)
11:28:54,711 http-8080-Processor25 INFO  [org.alfresco.repo.webservice.PlutextWebService.checkinWithComment(PlutextWebService.java:347)] in subclass
11:28:54,711 INFO  [org.alfresco.repo.webservice.PlutextWebService] in subclass
11:28:54,713 http-8080-Processor25 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.prepareTransactionInfo(TransactionAspectSupport.java:275)] Getting transaction for [UserTransaction]
11:28:54,713 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Getting transaction for [UserTransaction]
11:28:54,715 http-8080-Processor25 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.begin(SpringAwareUserTransaction.java:389)] Began user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@debb, status=0]

3.1 + 2 second pause (pause before starting 1b1a17a, and after finishing it - what was the purpose of that transaction anyway??):

11:28:54,814 http-8080-Processor25 INFO  [org.plutext.server.AbstractWebService.checkinWithComment(AbstractWebService.java:858)] CP EachBlock
11:28:54,814 INFO  [org.plutext.server.AbstractWebService] CP EachBlock
[Full GC 64266K->42534K(518464K), 0.5407530 secs]
11:28:57,900 Thread-23 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.prepareTransactionInfo(TransactionAspectSupport.java:275)] Getting transaction for [UserTransaction]
11:28:57,900 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Getting transaction for [UserTransaction]
11:28:57,901 Thread-23 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.begin(SpringAwareUserTransaction.java:389)] Began user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1b1a17a, status=0]
11:28:57,901 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Began user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1b1a17a, status=0]
11:28:57,903 Thread-23 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:305)] Completing transaction for [UserTransaction]
11:28:57,903 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Completing transaction for [UserTransaction]
11:28:57,907 Thread-23 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:468)] Committed user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1b1a17a, status=3]
11:28:57,907 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Committed user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1b1a17a, status=3]
[GC 89126K->48396K(518464K), 0.0544980 secs]
[Full GC 74421K->51268K(518464K), 0.6105590 secs]
11:29:00,023 DefaultScheduler_Worker-8 DEBUG [org.quartz.core.JobRunShell.run(JobRunShell.java:201)] Calling execute on job DEFAULT.openOfficeConnectionTesterJobDetail
11:29:00,023 DEBUG [org.quartz.core.JobRunShell] Calling execute on job DEFAULT.openOfficeConnectionTesterJobDetail
unmarshalled
11:29:00,659 http-8080-Processor25 DEBUG [org.docx4j.wml.SdtPr.getId(SdtPr.java:228)] found id

1.3 sec pause

11:29:00,974 INFO  [org.plutext.server.io.ChunkingSaveToJCR] Set cm:name and cm:title: sub597355377.xml
11:29:00,988 http-8080-Processor25 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.prepareTransactionInfo(TransactionAspectSupport.java:275)] Getting transaction for [UserTransaction]
11:29:00,988 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Getting transaction for [UserTransaction]
11:29:00,989 http-8080-Processor25 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.begin(SpringAwareUserTransaction.java:389)] Began user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1d61c3b, status=0]
11:29:00,989 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Began user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1d61c3b, status=0]
11:29:01,045 http-8080-Processor25 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:305)] Completing transaction for [UserTransaction]
11:29:01,045 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Completing transaction for [UserTransaction]
11:29:01,046 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Committed user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1d61c3b, status=3]
11:29:02,349 http-8080-Processor25 INFO  [org.plutext.server.io.ChunkingSaveToJCR.saveRawXmlPart(ChunkingSaveToJCR.java:381)] PUT SUCCESS: sub597355377.xml VERSION 1.0

In the time interval 00,974 to 02,349, I setProperty cm:content, saved the jcr session, then did a checkin

additional 0.3 sec pause around GC time, then 0.6 sec:

11:29:02,589 INFO  [org.plutext.server.io.ChunkingSaveToJCR] Set cm:name and cm:title: sub1714367612.xml
11:29:02,594 http-8080-Processor25 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.prepareTransactionInfo(TransactionAspectSupport.java:275)] Getting transaction for [UserTransaction]
11:29:02,594 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Getting transaction for [UserTransaction]
11:29:02,595 http-8080-Processor25 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.begin(SpringAwareUserTransaction.java:389)] Began user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1615795, status=0]
11:29:02,595 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Began user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1615795, status=0]
11:29:02,616 http-8080-Processor25 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:305)] Completing transaction for [UserTransaction]
11:29:02,616 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Completing transaction for [UserTransaction]
11:29:02,616 http-8080-Processor25 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:468)] Committed user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1615795, status=3]
11:29:02,616 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Committed user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1615795, status=3]
[GC 97860K->52720K(518464K), 0.0193260 secs]
11:29:02,946 Thread-23 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.prepareTransactionInfo(TransactionAspectSupport.java:275)] Getting transaction for [UserTransaction]
11:29:02,946 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Getting transaction for [UserTransaction]
11:29:02,955 Thread-23 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.begin(SpringAwareUserTransaction.java:389)] Began user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1ecade2, status=0]
11:29:02,955 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Began user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1ecade2, status=0]
11:29:02,958 Thread-23 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:305)] Completing transaction for [UserTransaction]
11:29:02,958 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Completing transaction for [UserTransaction]
11:29:02,959 Thread-23 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:468)] Committed user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1ecade2, status=3]
11:29:02,959 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Committed user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1ecade2, status=3]
11:29:03,569 http-8080-Processor25 INFO  [org.plutext.server.io.ChunkingSaveToJCR.saveRawXmlPart(ChunkingSaveToJCR.java:381)] PUT SUCCESS: sub1714367612.xml VERSION 1.0

0.35 sec pause


11:29:06,199 INFO  [org.plutext.server.io.ChunkingSaveToJCR]  it is mix:versionable .. so checkout
11:29:06,551 http-8080-Processor25 INFO  [org.plutext.server.io.ChunkingSaveToJCR.saveRawXmlPart(ChunkingSaveToJCR.java:363)] Set cm:name and cm:title: skeleton.xml

all i did here was a checkout, then write a property

1.3 sec pause


11:29:06,602 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Committed user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1ebd825, status=3]
[GC 99662K->53295K(518464K), 0.0157370 secs]
11:29:07,899 http-8080-Processor25 INFO  [org.plutext.server.io.ChunkingSaveToJCR.saveRawXmlPart(ChunkingSaveToJCR.java:381)] PUT SUCCESS: skeleton.xml VERSION 1.3

1.4 sec pause

11:29:08,340 http-8080-Processor25 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:468)] Committed user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@5c1bd9, status=3]
11:29:08,340 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Committed user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@5c1bd9, status=3]
[GC 99887K->53407K(518464K), 0.0179880 secs]
11:29:09,723 http-8080-Processor25 INFO  [org.plutext.server.JcrVersionMapper.AlfrescoJcrVersionMapper.plutextVersion(AlfrescoJcrVersionMapper.java:37)] JCR version number: 1.1


1.9 sec pause (in which transaction debb commits)

11:29:09,783 http-8080-Processor25 DEBUG [org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:305)] Completing transaction for [UserTransaction]
11:29:09,783 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Completing transaction for [UserTransaction]
[GC 99999K->53965K(518464K), 0.0159440 secs]

11:29:11,658 http-8080-Processor25 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:468)] Committed user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@debb, status=3]

11:29:11,658 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] Committed user transaction: UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@debb, status=3]
11:29:11,659 http-8080-Processor25 DEBUG [org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:352)] Exit: JavaProvider::invoke (org.alfresco.repo.webservice.axis.SpringBeanRPCProvider@e73995)
11:29:11,659 DEBUG [org.apache.axis.providers.java.JavaProvider] Exit: JavaProvider::invoke (org.alfresco.repo.webservice.axis.SpringBeanRPCProvider@e73995)
0 Kudos
Getting started

Tags

Find what you came for

We want to make your experience in Hyland Connect as valuable as possible, so we put together some helpful links.

Copyright © 2025 Khoros, LLC