Skip to main content

Some XCAP http requests are not passed to xcap sbb

6 replies [Last post]
hanliu
Offline
Joined: 2008-10-13
Points: 0

Hi
After the jslee/xdm server run for 1 days or more, I found that some of the HttpRequest Event can not be passed to the XCAP sbb(AggregationSbb)
I have make some print in Servlet-Ra and AggregationSbb

The client had to wait for 20s and get a 200 OK result with zero content
and I check the debug information in server.log and found no error message.
the debug info is below:

who can help me? Thanks in advance

========================================================

2008-10-13 15:43:21,962 INFO [org.mobicents.slee.resource.http.HttpServletRaServlet] Request from 172.20.67.222 /mobicents/resource-lists/us
ers/hanliu@ceopen.cn/buddys
2008-10-13 15:43:21,963 DEBUG [org.mobicents.slee.resource.http.HttpServletRaSessionListener] sessionCreated sessionId = FCD3083689FA96A5ACFAA
7EFEB6DA106
2008-10-13 15:43:21,963 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] addAfterCommitAction org.mobicents.slee.runtime.ActivityCo
ntext$2@42f440 list EDU.oswego.cs.dl.util.concurrent.SyncList@1
2008-10-13 15:43:21,963 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] after adding listLength is 1
2008-10-13 15:43:21,963 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] addAfterCommitAction org.mobicents.slee.runtime.ActivityCo
ntextFactoryImpl$1@1b1d268 list EDU.oswego.cs.dl.util.concurrent.SyncList@42f45f
2008-10-13 15:43:21,963 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] after adding listLength is 2
2008-10-13 15:43:21,963 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] addAfterCommitAction org.mobicents.slee.runtime.CommitDefe
rredEventAction@1f7f4dc list EDU.oswego.cs.dl.util.concurrent.SyncList@9cd69e9
2008-10-13 15:43:21,964 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] after adding listLength is 3
2008-10-13 15:43:21,964 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing prepare actions
2008-10-13 15:43:21,964 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] *** ITERATION
2008-10-13 15:43:21,964 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing action:org.mobicents.slee.runtime.ActivityContex
t$2@42f440
2008-10-13 15:43:21,964 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] *** ITERATION
2008-10-13 15:43:21,964 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing action:org.mobicents.slee.runtime.ActivityContex
tFactoryImpl$1@1b1d268
2008-10-13 15:43:21,964 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] *** ITERATION
2008-10-13 15:43:21,964 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing action:org.mobicents.slee.runtime.CommitDeferred
EventAction@1f7f4dc
:2008-10-13 15:43:22,260 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - first pass <<98><9F><9C><9F><80>,
13 <8D><81><9C><88> 2008 15:43:22>
2008-10-13 15:43:22,260 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule: first pass
2008-10-13 15:43:22,284 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TOReco
veryModule - first pass
2008-10-13 15:43:30,087 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] addAfterCommitAction org.mobicents.slee.runtime.ActivityCo
ntext$2@1b24cb4 list EDU.oswego.cs.dl.util.concurrent.SyncList@1
2008-10-13 15:43:30,087 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] after adding listLength is 1
2008-10-13 15:43:30,087 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] addAfterCommitAction org.mobicents.slee.runtime.CommitDefe
rredEventAction@8d309f list EDU.oswego.cs.dl.util.concurrent.SyncList@1b24cd3
2008-10-13 15:43:30,087 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] after adding listLength is 2
2008-10-13 15:43:30,087 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing prepare actions
2008-10-13 15:43:30,087 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] *** ITERATION
2008-10-13 15:43:30,087 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing action:org.mobicents.slee.runtime.ActivityContex
t$2@1b24cb4
2008-10-13 15:43:30,087 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] *** ITERATION
2008-10-13 15:43:30,087 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing action:org.mobicents.slee.runtime.CommitDeferred
EventAction@8d309f
2008-10-13 15:43:30,088 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] addAfterCommitAction org.mobicents.slee.runtime.ActivityCo
ntext$2@1a187fe list EDU.oswego.cs.dl.util.concurrent.SyncList@1
2008-10-13 15:43:30,088 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] after adding listLength is 1
2008-10-13 15:43:30,088 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing prepare actions
2008-10-13 15:43:30,088 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] *** ITERATION
2008-10-13 15:43:30,088 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing action:org.mobicents.slee.runtime.ActivityContex
t$2@1a187fe
2008-10-13 15:43:30,088 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] addAfterCommitAction org.mobicents.slee.runtime.ActivityCo
ntext$2@1250bc7 list EDU.oswego.cs.dl.util.concurrent.SyncList@1
2008-10-13 15:43:30,088 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] after adding listLength is 1
2008-10-13 15:43:30,089 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing prepare actions
2008-10-13 15:43:30,089 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] *** ITERATION
2008-10-13 15:43:30,089 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing action:org.mobicents.slee.runtime.ActivityContex
t$2@1250bc7
2008-10-13 15:43:30,089 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] addAfterCommitAction org.mobicents.slee.runtime.ActivityCo
ntext$2@1c5360c list EDU.oswego.cs.dl.util.concurrent.SyncList@1
2008-10-13 15:43:30,089 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] after adding listLength is 1
2008-10-13 15:43:30,089 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] addAfterCommitAction org.mobicents.slee.runtime.ActivityCo
ntext$1@5f882e list EDU.oswego.cs.dl.util.concurrent.SyncList@1c5362b
2008-10-13 15:43:30,089 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] after adding listLength is 2
2008-10-13 15:43:30,089 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing prepare actions
2008-10-13 15:43:30,089 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] *** ITERATION
2008-10-13 15:43:30,089 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing action:org.mobicents.slee.runtime.ActivityContex
t$2@1c5360c
2008-10-13 15:43:30,089 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] *** ITERATION
2008-10-13 15:43:30,089 DEBUG [org.mobicents.slee.runtime.transaction.TxLocalEntry] Executing action:org.mobicents.slee.runtime.ActivityContex
t$1@5f882e
2008-10-13 15:43:32,286 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - second pass <<98><9F><9C><9F><80>,
13 <8D><81><9C><88> 2008 15:43:32>
2008-10-13 15:43:32,286 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AtomicActionRecoveryModule: Second pass
2008-10-13 15:43:32,286 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.ActionStatusService_1] - transacti
onType: /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid: 7f000001:965f:48efa79c:21cd4
Status is 7
2008-10-13 15:43:32,293 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.ActionStatusService_1] - transacti
onType: /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid: 7f000001:965f:48efa79c:2b4ac
Status is 7
2008-10-13 15:43:32,299 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.ActionStatusService_1] - transacti
onType: /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid: 7f000001:965f:48efa79c:2352d
Status is 7
2008-10-13 15:43:32,305 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.ActionStatusService_1] - transacti
onType: /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid: 7f000001:965f:48efa79c:34083
Status is 7
2008-10-13 15:43:32,315 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.recovery.ActionStatusService_1] - transacti
onType: /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid: 7f000001:965f:48efa79c:34d2c

Regards,

Han

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
eduardomartins
Offline
Joined: 2005-10-10
Points: 0

can you please describe that test? what were the requests sent, to which users, what rate, what version of the xdm, etc... ?

hanliu
Offline
Joined: 2008-10-13
Points: 0

We are using the code checked out and built from google mobicents ()
and we have made some extra codes to xdm.
The slee version is 1.2.0.GA-SNAPSHOT
xdm version is 1.0.0.BETA2

We have IM clients and a SIP server. They are using mobicents for resource-lists and pres-rules storage.

the IM would GET and PUT some resources to XCAP. the SIP server would send some subscriptions to some document, and when they are changed SIP server got the SIP nofify and tell the client to update.

If the CPU or memory are used up, would some exception are thrown?

the sip is like this
========================================================

-------------------------
REQUEST:
-------------------------
SUBSCRIBE sip:liyongle@ceopen.cn SIP/2.0

Via: SIP/2.0/UDP 172.20.67.222:5070;received=172.20.67.222;branch=z9hG4bK-d8754z-0a250c0fecd89375-1---d8754z-;rport=5070

Max-Forwards: 70

Contact:

To:

From: ;tag=118d9701

Call-ID: YTg0YWNjMWQ2NDllYjg3ZTgxMGMxNTY0MTkxNmQzYTE.

CSeq: 1 SUBSCRIBE

Expires: 3600

Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,NOTIFY

Content-Type: application/resource-lists+xml

Event: xcap-diff

Content-Length: 225




=======================================================

The XCAP request just like this

===============================================================
15:07:06,884 INFO [RequestProcessorSbb] get(resourceSelector=/resource-lists/users/liyongle@ceopen.cn/buddys)
15:07:07,343 INFO [XcapDiffSubscriptionControlSbb] Created subscription: subscriber=sip:liyongle@ceopen.cn,notifier=sip:liyongle@ceopen.cn,eventPackage=xcap-diff,eventId=null,status=active
15:07:25,980 INFO [HttpServletRaServlet] Request from 172.20.67.222 /mobicents/resource-lists/users/liyongle@ceopen.cn/buddys
15:07:25,995 INFO [RequestProcessorSbb] get(resourceSelector=/resource-lists/users/liyongle@ceopen.cn/buddys)
15:07:26,065 INFO [HttpServletRaServlet] Request from 172.20.67.222 /mobicents/resource-lists/users/liyongle@ceopen.cn/buddys
15:07:26,082 INFO [RequestProcessorSbb] get(resourceSelector=/resource-lists/users/liyongle@ceopen.cn/buddys)

17:51:18,333 INFO [RequestProcessorSbb] put(resourceSelector=/resource-lists/users/liru@ceopen.cn/buddys/~~/resource-lists/*[@name='buddys']/list[@name='Group0'],mimetype=application/xcap-el+xml,eTagValidator=null,xcapRoot=/mobicents), nodeSelector=/resource-lists/*[@name='buddys']/list[@name='Group0']
===============================================================

eduardomartins
Offline
Joined: 2005-10-10
Points: 0

Can you try with the new Beta 3 and let me know if same issue exists? If exists we will try to replicate your scenario and look for a possible memory leak.

eduardomartins
Offline
Joined: 2005-10-10
Points: 0

By the way, I'm pretty happy that people are hacking the code, let me know if there is some help needed, and of course, if something you would like to contribute back, either an improvement or something on the roadmap.

hanliu
Offline
Joined: 2008-10-13
Points: 0

Eduardo, Thank you very much for your reply

Yes, this problem may come from many reasons, and we will check and use the latest codes.

By the way, I found that each time a HttpRequestEvent comes, the corresponding XCAP SbbEntity is created. From the profiler we found that the processInitialEvent and removeSbbEntity use a lot of CPU time.

From the jslee 1.1 we are not very clear whether we should do so(actually we only need the onXXX() methods). How could we use a [b]singleton[/b] SbbEntity? That will improve performance.

Thanks

Han

eduardomartins
Offline
Joined: 2005-10-10
Points: 0

A single sbb entity would translate in transaction rollbacks, due "transaction aware" operations on the sbb entity (attach/detach) on concurrent requests. Now that the betas are getting stable we are in process of creating a load test for the XDM Server, but very simple load tests in the current http-servlet RA show very good performance, an average of 2ms to process a request, or around 400 req/s, this on my laptop not a real server.