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

Tue Mar 21 12:48:35 PDT 2017

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.

>
> Dale
>
>
> _______________________________________________
> Glass mailing list
> Glass at lists.gemtalksystems.com
> http://lists.gemtalksystems.com/mailman/listinfo/glass
>
>

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