Quantcast

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

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

GLASS mailing list
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@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@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. 

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Help confirming understanding Seaside multi ajax requests, session locking and retries

GLASS mailing list



On 03/21/2017 11:46 AM, Mariano Martinez Peck via Glass wrote:
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@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@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? 

I think your analysis is correct ... you are getting blocked request handling because of parallel AJax requests for the same session : in one case there was a series of 3 locked messages over a span of .22 seconds (gem 12) and another set of 3 that took .21 seconds (gem 7) before the lock was granted ...

You might consider logging the oop of the session object, because it is possible for multiple gems to be in a retry loop for the same session ... I don't see any evidence of this in the above ...

Dale


_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Help confirming understanding Seaside multi ajax requests, session locking and retries

GLASS mailing list


On Tue, Mar 21, 2017 at 4:26 PM, Dale Henrichs via Glass <[hidden email]> wrote:



On 03/21/2017 11:46 AM, Mariano Martinez Peck via Glass wrote:
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@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@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? 

I think your analysis is correct ... you are getting blocked request handling because of parallel AJax requests for the same session : in one case there was a series of 3 locked messages over a span of .22 seconds (gem 12) and another set of 3 that took .21 seconds (gem 7) before the lock was granted ...


Yes, exactly. Ok, I am glad I am understanding the situation :)

 
You might consider logging the oop of the session object, because it is possible for multiple gems to be in a retry loop for the same session ... I don't see any evidence of this in the above ...


mmm I don't understand this. The session should be the same for all gems as all those requests were fired from a given ajax request.


 

Dale


_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass




--

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Help confirming understanding Seaside multi ajax requests, session locking and retries

GLASS mailing list



On 03/21/2017 12:48 PM, Mariano Martinez Peck wrote:


On Tue, Mar 21, 2017 at 4:26 PM, Dale Henrichs via Glass <[hidden email]> wrote:



On 03/21/2017 11:46 AM, Mariano Martinez Peck via Glass wrote:
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@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@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? 

I think your analysis is correct ... you are getting blocked request handling because of parallel AJax requests for the same session : in one case there was a series of 3 locked messages over a span of .22 seconds (gem 12) and another set of 3 that took .21 seconds (gem 7) before the lock was granted ...


Yes, exactly. Ok, I am glad I am understanding the situation :)

 
You might consider logging the oop of the session object, because it is possible for multiple gems to be in a retry loop for the same session ... I don't see any evidence of this in the above ...


mmm I don't understand this. The session should be the same for all gems as all those requests were fired from a given ajax request.

with the session oop logged, your *should* turns into an *is* or *is not* :) ... I was thinking more along the general case, when there are likely to be multiple sessions firing off ajax requests ...

Dale

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Help confirming understanding Seaside multi ajax requests, session locking and retries

GLASS mailing list


On Tue, Mar 21, 2017 at 5:02 PM, Dale Henrichs <[hidden email]> wrote:



On 03/21/2017 12:48 PM, Mariano Martinez Peck wrote:


On Tue, Mar 21, 2017 at 4:26 PM, Dale Henrichs via Glass <[hidden email]> wrote:



On 03/21/2017 11:46 AM, Mariano Martinez Peck via Glass wrote:
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@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@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? 

I think your analysis is correct ... you are getting blocked request handling because of parallel AJax requests for the same session : in one case there was a series of 3 locked messages over a span of .22 seconds (gem 12) and another set of 3 that took .21 seconds (gem 7) before the lock was granted ...


Yes, exactly. Ok, I am glad I am understanding the situation :)

 
You might consider logging the oop of the session object, because it is possible for multiple gems to be in a retry loop for the same session ... I don't see any evidence of this in the above ...


mmm I don't understand this. The session should be the same for all gems as all those requests were fired from a given ajax request.

with the session oop logged, your *should* turns into an *is* or *is not* :) ... I was thinking more along the general case, when there are likely to be multiple sessions firing off ajax requests ...


Ahhh yeah, as for this being a "general logging" yes, that makes sense. And yeah, I had just done it and confirm we are talking about the same session for my particular case.  

Thanks,

--

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass
Loading...