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

Dale Henrichs via Glass glass at lists.gemtalksystems.com
Tue Mar 21 12:26:56 PDT 2017 


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 ...

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

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

More information about the Glass mailing list