Re: [xwiki-devs] Benchmarking of the RightService

Hi, I did a quick benchmarking on the right service, to see what the benefits of caching is. I measured the time in nano-seconds over the methods checkAccess and hasAccessLevel. The server is run on a virtual machine, so the statistics is not entirely reliable. I have made some interesting observations, however: * hasAccessLevel is called a large number of times per page view. It is called around 20 times as often as checkAccess, which should normally be called once per accessed wiki-document. * The main reason for the large number of calls to hasAccessLevel are these variable initializations in xwikivars.vm: #set($hasEdit = $xwiki.hasAccessLevel("edit")) #set($hasAdmin = $xwiki.hasAccessLevel("admin")) ## Note: In order to know if the user has the right to create a space we compute a space name that doesn't exist and check edit rights on that space #set($hasCreateSpace = $xwiki.hasAccessLevel("edit", "${doc.space}${mathtool.random(0, 999)}.DocumentReservedForInternalXWikiUsage")) ## Note: In order to know if the user has the right to create a page we compute a page name that doesn't exist and check edit rights on that page #set($hasCreatePage = $xwiki.hasAccessLevel("edit", "${doc.space}.DocumentReservedForInternalXWikiUsage${mathtool.random(0, 999)}")) #set($hasGlobalAdmin = $xwiki.hasAccessLevel("admin", $context.user, "XWiki.XWikiPreferences")) ## Note: The document name is not internally used to determine if a user has programming access level. We pass XWiki.XWikiPreferences for consistency with the call for global admin #set($hasProgramming = $xwiki.hasAccessLevel("programming", $context.user, "XWiki.XWikiPreferences")) #set($hasSpaceAdmin = $xwiki.hasAccessLevel("admin", $context.user, "${doc.space}.WebPreferences")) Due to the ugly hack with randomly generated space names and document names for initiating the variables "$hasCreateSpace" and "$hasCreatePage", the caching implementation perform worse than it could, as this will cause many cache misses and waste cache space. However, my new implementation internally operates by computing and caching the rights corresponding to an EntityReference, which may refer to a document, a space, or a wiki. If this is exposed via the API it will be possible to query for the rights on a space and wiki directly. By removing the randomness : #set($hasCreateSpace = $xwiki.hasAccessLevel("edit", "${doc.space}INTERNAL.DocumentReservedForInternalXWikiUsage")) #set($hasCreatePage = $xwiki.hasAccessLevel("edit", "${doc.space}.DocumentReservedForInternalXWikiUsage")) and running a test by reloading the same page over and over, we see the benefit of caching: Original implementation: Statistics for checkAccess: DescriptiveStatistics: n: 2030 min: 522859.0 max: 5.39733259E8 mean: 1.7198616874876842E7 std dev: 3.7962038152575314E7 median: 659100.0 skewness: 4.262358507299374 kurtosis: 30.885271611362477 Statistics for hasAccessLevel: DescriptiveStatistics: n: 39402 min: 69016.0 max: 6.40750283E8 mean: 8595126.655296639 std dev: 2.770284412153291E7 median: 592985.0 skewness: 5.682505086745415 kurtosis: 50.72341779375682 ----------------------------------------- My new implementation: Statistics for checkAccess: DescriptiveStatistics: n: 2030 min: 27763.0 max: 3.01349107E8 mean: 3118090.7699507335 std dev: 1.6890870361759447E7 median: 132935.0 skewness: 8.995243673145804 kurtosis: 105.30119067606974 Statistics for hasAccessLevel: DescriptiveStatistics: n: 33368 min: 26086.0 max: 1.239094745E9 mean: 767290.0766902551 std dev: 1.0969784229187453E7 median: 32915.5 skewness: 55.482434651126056 kurtosis: 5256.531317809735 Considering the skewed nature of the distribution, the mean value cannot be used to predict the delay caused by the right service. Considering that hasAccessLevel seems to be called more than 30 times per page request, a naive interpretation suggests that over 200 ms was polished of the average request time (7.8 ms * 30). This is obviously bogus, since the mean request time was 170.027 ms for the original implementation and 144.743 ms for my new implementation. The requests were performed with 'ab -c 10 -n 1000 -k ': Output for original implementation: Server Software: Apache-Coyote/1.1 Server Hostname: wiki Server Port: 8080 Document Path: /xw/bin/view/Gob/WebHome Document Length: 0 bytes Concurrency Level: 10 Time taken for tests: 170.027 seconds Complete requests: 1000 Failed requests: 0 Write errors: 0 Non-2xx responses: 1000 Keep-Alive requests: 995 Total transferred: 414975 bytes HTML transferred: 0 bytes Requests per second: 5.88 [#/sec] (mean) Time per request: 1700.269 [ms] (mean) Time per request: 170.027 [ms] (mean, across all concurrent requests) Transfer rate: 2.38 [Kbytes/sec] received Connection Times (ms) min mean[+/-sd] median max Connect: 0 0 0.2 0 3 Processing: 445 1694 412.3 1654 3663 Waiting: 445 1694 412.3 1654 3663 Total: 445 1694 412.4 1654 3663 -------------------------------------------------------------------------------- Output for my new implementation: Server Software: Apache-Coyote/1.1 Server Hostname: wiki Server Port: 8080 Document Path: /xw/bin/view/Gob/WebHome Document Length: 0 bytes Concurrency Level: 10 Time taken for tests: 144.743 seconds Complete requests: 1000 Failed requests: 0 Write errors: 0 Non-2xx responses: 1000 Keep-Alive requests: 993 Total transferred: 414965 bytes HTML transferred: 0 bytes Requests per second: 6.91 [#/sec] (mean) Time per request: 1447.426 [ms] (mean) Time per request: 144.743 [ms] (mean, across all concurrent requests) Transfer rate: 2.80 [Kbytes/sec] received Connection Times (ms) min mean[+/-sd] median max Connect: 0 0 0.2 0 4 Processing: 374 1441 428.1 1415 3228 Waiting: 374 1441 428.1 1415 3228 Total: 374 1441 428.1 1415 3228 My implementation needs some more testing, but I will try to upload it to Jira by tomorrow. Best regards, Andreas Jonsson