[Glass] Help confirming understanding Seaside multi ajax requests, session locking and retries
Mariano Martinez Peck via Glass
glass at lists.gemtalksystems.com
Tue Mar 21 13:27:59 PDT 2017
On Tue, Mar 21, 2017 at 5:02 PM, Dale Henrichs <
dale.henrichs at gemtalksystems.com> 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 <
> 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 ...
>
>
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,
--
Mariano
http://marianopeck.wordpress.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.gemtalksystems.com/mailman/private/glass/attachments/20170321/ac097867/attachment-0001.html>
More information about the Glass
mailing list