topic Re: session flushed; stale data delivered shortly thereafter in Alfresco Archive

session flushed; stale data delivered shortly thereafter

jharrop — Mon, 04 Feb 2008 12:32:26 GMT

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 data

Re: session flushed; stale data delivered shortly thereafter

derek — Wed, 06 Feb 2008 16:00:09 GMT

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.

Re: session flushed; stale data delivered shortly thereafter

jharrop — Thu, 07 Feb 2008 13:43:42 GMT

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.

Re: session flushed; stale data delivered shortly thereafter

jharrop — Fri, 08 Feb 2008 09:57:51 GMT

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

Re: session flushed; stale data delivered shortly thereafter

derek — Fri, 08 Feb 2008 10:16:03 GMT

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.

Re: session flushed; stale data delivered shortly thereafter

jharrop — Fri, 08 Feb 2008 13:37:12 GMT

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

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 ‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Re: session flushed; stale data delivered shortly thereafter

jharrop — Mon, 14 Apr 2008 12:03:24 GMT

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)