[Glass] Help confirming understanding Seaside multi ajax requests, session locking and retries

Tue Mar 21 11:46:21 PDT 2017

Hi guys,

This is a continuation from my email "Workaround to browser maximum
connection limit ?".

Sorry for the long post.

Long short story, I have an ajax request which, on response, fires a bunch
of other Ajax requests, say 30. I added some  logging.

1)

1) WASession > handle:  I added this log:

handle: aRequestContext
  "acquire a lock on the receiver to prevent two separate gems from
processing requests for the
same session at the same time"

  | result |
  result := System _lock: self kind: 3 autoRelease: true.
  result ~~ 1
    ifTrue: [
      "lock denied - presumably the request will be retried"
      *GsFile*
*        gciLogServer:*
*          DateAndTime now greaseString,  '--AJAX TRACING: Session was
locked to gem--' , System session asString.*
      ^ WASessionLockNotAcquiredException
        signal: 'Session lock denied: ' , result printString ].
*  GsFile*
*    gciLogServer:*
*      DateAndTime now greaseString, '--AJAX TRACING: Session was granted
to gem--' , System session asString.*
  ^ super handle: aRequestContext

2) On #seasideProcessRequestWithRetry: aNativeRequest resultBlock:
resultBlock I simply added this on top:

  *GsFile*
*    gciLogServer:*
*     DateAndTime now greaseString,  '--AJAX TRACING: request received in
Gem--' , System session asString.*

-----

When I perform the mentioned scenario, this is the output I get:

[debrisdemo at quuveserver1 logs]$ grep -h -r "AJAX TRACING" *.log | sort
2017-03-21T14:39:09.431559085845947-04:00--AJAX TRACING: request received
in Gem--7
2017-03-21T14:39:09.467015981674194-04:00--AJAX TRACING: Session was
granted to gem--7
2017-03-21T14:39:10.62080311775208-04:00--AJAX TRACING: request received in
Gem--6
2017-03-21T14:39:10.64005494117737-04:00--AJAX TRACING: Session was granted
to gem--6
2017-03-21T14:39:10.85535597801208-04:00--AJAX TRACING: request received in
Gem--11
2017-03-21T14:39:10.87811708450317-04:00--AJAX TRACING: Session was granted
to gem--11
2017-03-21T14:39:11.02185392379761-04:00--AJAX TRACING: request received in
Gem--10
2017-03-21T14:39:11.04404211044312-04:00--AJAX TRACING: Session was granted
to gem--10
2017-03-21T14:39:11.22076201438904-04:00--AJAX TRACING: request received in
Gem--13
2017-03-21T14:39:11.24725008010864-04:00--AJAX TRACING: Session was granted
to gem--13
2017-03-21T14:39:11.42476797103882-04:00--AJAX TRACING: request received in
Gem--16
2017-03-21T14:39:11.45253300666809-04:00--AJAX TRACING: Session was granted
to gem--16
2017-03-21T14:39:11.62133288383484-04:00--AJAX TRACING: request received in
Gem--12
2017-03-21T14:39:11.64478993415833-04:00--AJAX TRACING: Session was granted
to gem--12
2017-03-21T14:39:11.82197690010071-04:00--AJAX TRACING: request received in
Gem--8
2017-03-21T14:39:11.85350799560547-04:00--AJAX TRACING: Session was granted
to gem--8
2017-03-21T14:39:11.85737299919128-04:00--AJAX TRACING: request received in
Gem--12
2017-03-21T14:39:11.86467099189758-04:00--AJAX TRACING: Session was locked
to gem--12
2017-03-21T14:39:11.96560001373291-04:00--AJAX TRACING: request received in
Gem--12
2017-03-21T14:39:11.97410011291504-04:00--AJAX TRACING: Session was granted
to gem--12
2017-03-21T14:39:12.02348208427429-04:00--AJAX TRACING: request received in
Gem--14
2017-03-21T14:39:12.05155491828918-04:00--AJAX TRACING: Session was locked
to gem--14
2017-03-21T14:39:12.06332397460938-04:00--AJAX TRACING: request received in
Gem--14
2017-03-21T14:39:12.07150888442993-04:00--AJAX TRACING: Session was locked
to gem--14
2017-03-21T14:39:12.17223906517029-04:00--AJAX TRACING: request received in
Gem--14
2017-03-21T14:39:12.17896389961243-04:00--AJAX TRACING: Session was granted
to gem--14
2017-03-21T14:39:12.220547914505-04:00--AJAX TRACING: request received in
Gem--9
2017-03-21T14:39:12.24168992042542-04:00--AJAX TRACING: Session was granted
to gem--9
2017-03-21T14:39:12.41850304603577-04:00--AJAX TRACING: request received in
Gem--7
2017-03-21T14:39:12.42668199539185-04:00--AJAX TRACING: Session was granted
to gem--7
2017-03-21T14:39:12.62308788299561-04:00--AJAX TRACING: request received in
Gem--15
2017-03-21T14:39:12.64607095718384-04:00--AJAX TRACING: Session was granted
to gem--15
2017-03-21T14:39:12.81803488731384-04:00--AJAX TRACING: request received in
Gem--6
2017-03-21T14:39:12.82674098014832-04:00--AJAX TRACING: Session was locked
to gem--6
2017-03-21T14:39:12.83830094337463-04:00--AJAX TRACING: request received in
Gem--6
2017-03-21T14:39:12.84903788566589-04:00--AJAX TRACING: Session was locked
to gem--6
2017-03-21T14:39:12.94985294342041-04:00--AJAX TRACING: request received in
Gem--6
2017-03-21T14:39:12.96094799041748-04:00--AJAX TRACING: Session was granted
to gem--6
2017-03-21T14:39:13.01887798309326-04:00--AJAX TRACING: request received in
Gem--11
2017-03-21T14:39:13.03113889694214-04:00--AJAX TRACING: Session was granted
to gem--11
2017-03-21T14:39:13.21864295005798-04:00--AJAX TRACING: request received in
Gem--10
2017-03-21T14:39:13.23133301734924-04:00--AJAX TRACING: Session was granted
to gem--10
2017-03-21T14:39:13.41963505744934-04:00--AJAX TRACING: request received in
Gem--16
2017-03-21T14:39:13.42692899703979-04:00--AJAX TRACING: Session was granted
to gem--16
2017-03-21T14:39:13.61887907981873-04:00--AJAX TRACING: request received in
Gem--13
2017-03-21T14:39:13.63217806816101-04:00--AJAX TRACING: Session was granted
to gem--13
2017-03-21T14:39:13.81860589981079-04:00--AJAX TRACING: request received in
Gem--12
2017-03-21T14:39:13.83476805686951-04:00--AJAX TRACING: Session was locked
to gem--12
2017-03-21T14:39:13.84605598449707-04:00--AJAX TRACING: request received in
Gem--12
2017-03-21T14:39:13.85418105125427-04:00--AJAX TRACING: Session was locked
to gem--12
2017-03-21T14:39:13.95503401756287-04:00--AJAX TRACING: request received in
Gem--12
2017-03-21T14:39:13.96259903907776-04:00--AJAX TRACING: Session was locked
to gem--12
2017-03-21T14:39:14.02077507972717-04:00--AJAX TRACING: request received in
Gem--8
2017-03-21T14:39:14.03395390510559-04:00--AJAX TRACING: Session was granted
to gem--8
2017-03-21T14:39:14.06341910362244-04:00--AJAX TRACING: request received in
Gem--12
2017-03-21T14:39:14.07168793678284-04:00--AJAX TRACING: Session was granted
to gem--12
2017-03-21T14:39:14.21781396865845-04:00--AJAX TRACING: request received in
Gem--9
2017-03-21T14:39:14.22855997085571-04:00--AJAX TRACING: Session was locked
to gem--9
2017-03-21T14:39:14.24069690704346-04:00--AJAX TRACING: request received in
Gem--9
2017-03-21T14:39:14.25109100341797-04:00--AJAX TRACING: Session was locked
to gem--9
2017-03-21T14:39:14.35198497772217-04:00--AJAX TRACING: request received in
Gem--9
2017-03-21T14:39:14.35910391807556-04:00--AJAX TRACING: Session was granted
to gem--9
2017-03-21T14:39:14.42120099067688-04:00--AJAX TRACING: request received in
Gem--14
2017-03-21T14:39:14.4332959651947-04:00--AJAX TRACING: Session was locked
to gem--14
2017-03-21T14:39:14.44424510002136-04:00--AJAX TRACING: request received in
Gem--14
2017-03-21T14:39:14.45895600318909-04:00--AJAX TRACING: Session was locked
to gem--14
2017-03-21T14:39:14.55992603302002-04:00--AJAX TRACING: request received in
Gem--14
2017-03-21T14:39:14.57152605056763-04:00--AJAX TRACING: Session was granted
to gem--14
2017-03-21T14:39:14.61931705474854-04:00--AJAX TRACING: request received in
Gem--7
2017-03-21T14:39:14.63577008247375-04:00--AJAX TRACING: Session was locked
to gem--7
2017-03-21T14:39:14.64788508415222-04:00--AJAX TRACING: request received in
Gem--7
2017-03-21T14:39:14.65792894363403-04:00--AJAX TRACING: Session was locked
to gem--7
2017-03-21T14:39:14.75875997543335-04:00--AJAX TRACING: request received in
Gem--7
2017-03-21T14:39:14.76701188087463-04:00--AJAX TRACING: Session was locked
to gem--7
2017-03-21T14:39:14.81798911094666-04:00--AJAX TRACING: request received in
Gem--6
2017-03-21T14:39:14.82505297660828-04:00--AJAX TRACING: Session was granted
to gem--6
2017-03-21T14:39:14.86797404289246-04:00--AJAX TRACING: request received in
Gem--7
2017-03-21T14:39:14.87749290466309-04:00--AJAX TRACING: Session was locked
to gem--7
2017-03-21T14:39:14.97828602790833-04:00--AJAX TRACING: request received in
Gem--7
2017-03-21T14:39:14.9875009059906-04:00--AJAX TRACING: Session was granted
to gem--7
2017-03-21T14:39:15.0185809135437-04:00--AJAX TRACING: request received in
Gem--15
2017-03-21T14:39:15.02768397331238-04:00--AJAX TRACING: Session was locked
to gem--15
2017-03-21T14:39:15.03932905197144-04:00--AJAX TRACING: request received in
Gem--15
2017-03-21T14:39:15.0463490486145-04:00--AJAX TRACING: Session was locked
to gem--15
2017-03-21T14:39:15.14704990386963-04:00--AJAX TRACING: request received in
Gem--15
2017-03-21T14:39:15.15435194969177-04:00--AJAX TRACING: Session was granted
to gem--15
2017-03-21T14:39:15.21826410293579-04:00--AJAX TRACING: request received in
Gem--11
2017-03-21T14:39:15.23047399520874-04:00--AJAX TRACING: Session was locked
to gem--11
2017-03-21T14:39:15.24233388900757-04:00--AJAX TRACING: request received in
Gem--11
2017-03-21T14:39:15.25115609169006-04:00--AJAX TRACING: Session was granted
to gem--11
2017-03-21T14:39:15.41745400428772-04:00--AJAX TRACING: request received in
Gem--10
2017-03-21T14:39:15.42503094673157-04:00--AJAX TRACING: Session was granted
to gem--10
2017-03-21T14:39:15.61884593963623-04:00--AJAX TRACING: request received in
Gem--12
2017-03-21T14:39:15.62951707839966-04:00--AJAX TRACING: Session was granted
to gem--12
2017-03-21T14:39:15.81818103790283-04:00--AJAX TRACING: request received in
Gem--16
2017-03-21T14:39:15.82529711723328-04:00--AJAX TRACING: Session was granted
to gem--16
[debrisdemo at quuveserver1 logs]$

And these are the conclusions I got so far:

1) Requests are being correctly load balanced across Gems by nginx on a
round robin strategy.

2) The most important conclusion here (please confirm!) is that there are a
few locks. I mean, there is NOT a lock PER request (which is what I
imagined). There are less. I THINK this could happen if a request
processing is very fast, then maybe for the time the next requests comes,
we have already released the lock. And hence, the few locks I see in above
lines are due to "long enough" requests that caused next requests to
abort/wait/retry. For example, starting from the top, the first one big was
the one on gem 8 which locked the gem 12.

Does this sounds correct?

Thanks a lot in advance and sorry for the long post. Maybe it helps others
with the analysis.

-- 
Mariano
http://marianopeck.wordpress.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.gemtalksystems.com/mailman/private/glass/attachments/20170321/c1e05c78/attachment.html>