coolbole / memcached-session-manager

Automatically exported from code.google.com/p/memcached-session-manager
0 stars 0 forks source link

Improve session locking for parallel requests (in 1 tomcat) #196

Open GoogleCodeExporter opened 9 years ago

GoogleCodeExporter commented 9 years ago
Given a non-sticky setup and session locking in place currently parallel 
requests (running in the same tomcat) don't share a session lock.

Additionally, with lockingMode "auto" requests are not registered as readonly 
requests if there's still a request active for the same session (indicated by 
log output like "FINE: Session xyz is still used by another request, skipping 
backup and (optional) lock handling/release.").

Originally reported here: 
https://groups.google.com/forum/#!topic/memcached-session-manager/FonXe0j6uqU

Here's a full log output:

Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke
FINE: >>>>>> Request starting: GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxslow (requestedSessionId 
24467C542B9AD943769F8FDC458392E8) ==================
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.MemcachedSessionService 
loadFromMemcached
FINE: Loading session from memcached: 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke
FINE: >>>>>> Request starting: GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxfast=1 (requestedSessionId 
24467C542B9AD943769F8FDC458392E8) ==================
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.ReadOnlyRequestsCache 
isReadOnlyRequest
FINE: Asked for readonly request: GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxslow (true)
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke
FINE: >>>>>> Request starting: GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxfast=3 (requestedSessionId 
24467C542B9AD943769F8FDC458392E8) ==================
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.MemcachedSessionService 
loadFromMemcached
FINE: Loading session from memcached: 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke
FINE: >>>>>> Request starting: GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxfast=2 (requestedSessionId 
24467C542B9AD943769F8FDC458392E8) ==================
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.ReadOnlyRequestsCache 
isReadOnlyRequest
FINE: Asked for readonly request: GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxfast=1 (false)
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.MemcachedSessionService 
loadFromMemcached
FINE: Loading session from memcached: 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy lock
FINE: Locking session 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategyAuto 
onBeforeLoadFromMemcached
FINE: Not getting lock for readonly request GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxslow
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.MemcachedSessionService 
loadFromMemcached
FINE: Loading session from memcached: 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy acquireLock
FINE: Locked session 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.ReadOnlyRequestsCache 
isReadOnlyRequest
FINE: Asked for readonly request: GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxfast=3 (false)
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy lock
FINE: Locked session 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.MemcachedSessionService 
loadFromMemcached
FINE: Found session with id 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.ReadOnlyRequestsCache 
isReadOnlyRequest
FINE: Asked for readonly request: GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxfast=2 (false)
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy lock
FINE: Locking session 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy lock
FINE: Locking session 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.MemcachedSessionService 
loadFromMemcached
FINE: Found session with id 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 10 millis now...
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.MemcachedSessionService 
backupSession
FINE: Session 24467C542B9AD943769F8FDC458392E8 is still used by another 
request, skipping backup and (optional) lock handling/release.
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 10 millis now...
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.RequestTrackingHostValve 
logDebugRequestSessionCookie
FINE: Have request session cookie: domain=null, maxAge=-1, path=null, 
value=24467C542B9AD943769F8FDC458392E8, version=0, secure=false
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke
FINE: <<<<<< Request finished: GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxfast=1 ==================
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 20 millis now...
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 20 millis now...
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 40 millis now...
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 40 millis now...
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 80 millis now...
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 80 millis now...
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 160 millis now...
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 160 millis now...
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 320 millis now...
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 320 millis now...
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 500 millis now...
Feb 16, 2014 11:45:33 PM de.javakaffee.web.msm.LockingStrategy 
checkTimeoutAndWait
FINE: Could not aquire lock for session 24467C542B9AD943769F8FDC458392E8, 
waiting 500 millis now...
Feb 16, 2014 11:45:34 PM de.javakaffee.web.msm.LockingStrategy lock
WARNING: Reached timeout when trying to aquire lock for session 
24467C542B9AD943769F8FDC458392E8. Will use this session without this lock.
Feb 16, 2014 11:45:34 PM de.javakaffee.web.msm.LockingStrategy lock
WARNING: Reached timeout when trying to aquire lock for session 
24467C542B9AD943769F8FDC458392E8. Will use this session without this lock.
Feb 16, 2014 11:45:34 PM de.javakaffee.web.msm.MemcachedSessionService 
loadFromMemcached
FINE: Found session with id 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:34 PM de.javakaffee.web.msm.MemcachedSessionService 
backupSession
FINE: Session 24467C542B9AD943769F8FDC458392E8 is still used by another 
request, skipping backup and (optional) lock handling/release.
Feb 16, 2014 11:45:34 PM de.javakaffee.web.msm.RequestTrackingHostValve 
logDebugRequestSessionCookie
FINE: Have request session cookie: domain=null, maxAge=-1, path=null, 
value=24467C542B9AD943769F8FDC458392E8, version=0, secure=false
Feb 16, 2014 11:45:34 PM de.javakaffee.web.msm.MemcachedSessionService 
loadFromMemcached
FINE: Found session with id 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:34 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke
FINE: <<<<<< Request finished: GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxfast=3 ==================
Feb 16, 2014 11:45:34 PM de.javakaffee.web.msm.MemcachedSessionService 
backupSession
FINE: Session 24467C542B9AD943769F8FDC458392E8 is still used by another 
request, skipping backup and (optional) lock handling/release.
Feb 16, 2014 11:45:34 PM de.javakaffee.web.msm.RequestTrackingHostValve 
logDebugRequestSessionCookie
FINE: Have request session cookie: domain=null, maxAge=-1, path=null, 
value=24467C542B9AD943769F8FDC458392E8, version=0, secure=false
Feb 16, 2014 11:45:34 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke
FINE: <<<<<< Request finished: GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxfast=2 ==================
Feb 16, 2014 11:45:38 PM de.javakaffee.web.msm.BackupSessionService 
backupSession
FINE: Starting for session id 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:38 PM de.javakaffee.web.msm.BackupSessionService 
backupSession
FINE: Session attributes were not accessed since last backup/check, therefore 
we can skip this
Feb 16, 2014 11:45:38 PM de.javakaffee.web.msm.LockingStrategy 
onAfterBackupSession
FINE: Stored session validity info for session 24467C542B9AD943769F8FDC458392E8
Feb 16, 2014 11:45:38 PM de.javakaffee.web.msm.ReadOnlyRequestsCache 
readOnlyRequest
FINE: Registering readonly request: GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxslow
Feb 16, 2014 11:45:38 PM de.javakaffee.web.msm.LockingStrategy pingSession
FINE: The session was ping'ed successfully.
Feb 16, 2014 11:45:38 PM de.javakaffee.web.msm.RequestTrackingHostValve 
logDebugRequestSessionCookie
FINE: Have request session cookie: domain=null, maxAge=-1, path=null, 
value=24467C542B9AD943769F8FDC458392E8, version=0, secure=false
Feb 16, 2014 11:45:38 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke
FINE: <<<<<< Request finished: GET 
/msm-sample-webapp-1.0-SNAPSHOT/AjaxServlet?ajaxslow ==================

Original issue reported on code.google.com by martin.grotzke on 16 Feb 2014 at 11:15