Dear all,
on one of our applications based on RestXQ services running on 9.0.2 we experience a strange behaviour related to concurrency.
It is a stateless service running on a server with http-local set to true. So no database access. We removed all accesses to sessions and the code doesn't even write to files or other external resources. It's really only computation.
When I run multiple requests, I can clearly see that they are accepted simultaneously (up to 8 which matches PARALLEL). They even complete out of order according to the session id reported in the log. [1]
The strange thing is: performance seems to be as if calls were executed serially. If T is the time to complete one call then the pattern is T + T + T + T + T.
I have to add that the algorithm is rather complex. Lots of functions (possibly inlined, private and the main one even recursive) which filter and transform a large XML request into a possibly large XML output.
If I simplify the called RestXQ to something like [2] then I get a log like [3] which shows a pattern like the one I'm expecting T+d+d+d+d where d is just a slight overhead (orders of magnitude smaller).
My question is what do I have to check in order to understand where the hard synchronization of the calls occurs? Might this be related to non-deterministic functions? What else?
I've tried to isolate parts of the code but I'm unable to get predictable results.
Thank you very much for all the hints you will be able to provide!
Regards,
Marco.
[1]
17:10:19.204 127.0.0.1:58038 admin REQUEST [POST] http://localhost:8081/rate-selector/select-matching-rates 17:10:19.204 127.0.0.1:58040 admin REQUEST [POST] http://localhost:8081/rate-selector/select-matching-rates 17:10:19.205 127.0.0.1:58042 admin REQUEST [POST] http://localhost:8081/rate-selector/select-matching-rates 17:10:19.205 127.0.0.1:58044 admin REQUEST [POST] http://localhost:8081/rate-selector/select-matching-rates 17:10:19.208 127.0.0.1:58046 admin REQUEST [POST] http://localhost:8081/rate-selector/select-matching-rates 17:10:21.325 127.0.0.1:58040 admin 200 2121.01 ms 17:10:23.174 127.0.0.1:58046 admin 200 3965.74 ms 17:10:25.035 127.0.0.1:58038 admin 200 5830.63 ms 17:10:26.889 127.0.0.1:58044 admin 200 7683.76 ms 17:10:28.739 127.0.0.1:58042 admin 200 9534.46 ms
[2]
(:~ : Test concurrency :) declare %rest:path("/test") %rest:POST("{$body}") function rs:test($body as node()) { <a>{$body}{fold-left(1 to 10000000, 0, function($acc, $next){ $acc + math:sqrt($next)})}</a> };
[3]
17:48:02.782 127.0.0.1:48262 admin REQUEST [POST] http://localhost:8081/rate-selector/test 17:48:02.783 127.0.0.1:48252 admin REQUEST [POST] http://localhost:8081/rate-selector/test 17:48:02.783 127.0.0.1:48258 admin REQUEST [POST] http://localhost:8081/rate-selector/test 17:48:02.784 127.0.0.1:48260 admin REQUEST [POST] http://localhost:8081/rate-selector/test 17:48:02.784 127.0.0.1:48254 admin REQUEST [POST] http://localhost:8081/rate-selector/test 17:48:04.428 127.0.0.1:48262 admin 200 1646.03 ms 17:48:04.509 127.0.0.1:48260 admin 200 1725.45 ms 17:48:04.710 127.0.0.1:48254 admin 200 1926.27 ms 17:48:04.772 127.0.0.1:48258 admin 200 1988.41 ms 17:48:04.904 127.0.0.1:48252 admin 200 2120.33 ms