[Glass] Help confirming understanding Seaside multi ajax requests, session locking and retries
Dale Henrichs via Glass
glass at lists.gemtalksystems.com
Tue Mar 21 13:02:19 PDT 2017
On 03/21/2017 12:48 PM, Mariano Martinez Peck wrote:
>
>
> On Tue, Mar 21, 2017 at 4:26 PM, Dale Henrichs via Glass
> <glass at lists.gemtalksystems.com
> <mailto:glass at lists.gemtalksystems.com>> 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 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?
>>
> 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.gemtalksystems.com/mailman/private/glass/attachments/20170321/dfc54c48/attachment-0001.html>
More information about the Glass
mailing list