9 Jun
2010
9 Jun
'10
10:38 p.m.
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