From oak-issues-return-67993-archive-asf-public=cust-asf.ponee.io@jackrabbit.apache.org Wed Jan 30 14:51:04 2019 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx-eu-01.ponee.io (Postfix) with SMTP id 3E806180652 for ; Wed, 30 Jan 2019 15:51:04 +0100 (CET) Received: (qmail 81757 invoked by uid 500); 30 Jan 2019 14:51:03 -0000 Mailing-List: contact oak-issues-help@jackrabbit.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: oak-dev@jackrabbit.apache.org Delivered-To: mailing list oak-issues@jackrabbit.apache.org Received: (qmail 81746 invoked by uid 99); 30 Jan 2019 14:51:03 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 30 Jan 2019 14:51:03 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id ECC6EC27A5 for ; Wed, 30 Jan 2019 14:51:02 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -109.001 X-Spam-Level: X-Spam-Status: No, score=-109.001 tagged_above=-999 required=6.31 tests=[ENV_AND_HDR_SPF_MATCH=-0.5, KAM_ASCII_DIVIDERS=0.8, KAM_NUMSUBJECT=0.5, RCVD_IN_DNSWL_MED=-2.3, SPF_PASS=-0.001, USER_IN_DEF_SPF_WL=-7.5, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id 2-O2IlDp8TSh for ; Wed, 30 Jan 2019 14:51:01 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTP id 13D0C61010 for ; Wed, 30 Jan 2019 14:51:01 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id 8CA4FE2697 for ; Wed, 30 Jan 2019 14:51:00 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id 3DA82243B4 for ; Wed, 30 Jan 2019 14:51:00 +0000 (UTC) Date: Wed, 30 Jan 2019 14:51:00 +0000 (UTC) From: "Paul Chibulcuteanu (JIRA)" To: oak-issues@jackrabbit.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (OAK-8011) Benchmark on QUERY_DURATION metrics implemented in OAK-7904 MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/OAK-8011?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16756186#comment-16756186 ] Paul Chibulcuteanu commented on OAK-8011: ----------------------------------------- [~tmueller], I ran some benchmark tests locally with the two mentioned cases: * specifying the oak.query.timerDisabled system prop * without specifying the oak.query.timerDisabled system prop The results show that there is no impact on performance. I used the LoginTest the most. I would wait for your reply before closing this issue. Here are the results and various modes run {code} LoginTest, Timer enabled, Oak-Composite-Store FIXTURE,1 minute: java -Dwarmup=5 -Druntime=60 -Dprofile=true -cp oak-benchmarks-1.12-SNAPSHOT.jar org.apache.jackrabbit.oak.run.Main benchmark LoginTest Oak-Composite-Store Apache Jackrabbit Oak 1.12-SNAPSHOT # LoginTest C min 10% 50% 90% max N Oak-Composite-Store 1 611 615 649 703 874 92 LoginTest, Timer disabled, Oak-Composite-Store FIXTURE, 1 minute: java -Doak.query.timerDisabled -Dwarmup=5 -Druntime=60 -Dprofile=true -cp oak-benchmarks-1.12-SNAPSHOT.jar org.apache.jackrabbit.oak.run.Main benchmark LoginTest Oak-Composite-Store Apache Jackrabbit Oak 1.12-SNAPSHOT # LoginTest C min 10% 50% 90% max N Oak-Composite-Store 1 595 621 647 719 889 91 LoginTest, Timer enabled, Oak-Composite-Store FIXTURE,10 minutes: java -Dwarmup=5 -Druntime=600 -Dprofile=true -cp oak-benchmarks-1.12-SNAPSHOT.jar org.apache.jackrabbit.oak.run.Main benchmark LoginTest Oak-Composite-Store Apache Jackrabbit Oak 1.12-SNAPSHOT # LoginTest C min 10% 50% 90% max N Oak-Composite-Store 1 606 615 662 791 1000 867 LoginTest, Timer disabled, Oak-Composite-Store FIXTURE, 10 minutes: java -Doak.query.timerDisabled -Dwarmup=5 -Druntime=600 -Dprofile=true -cp oak-benchmarks-1.12-SNAPSHOT.jar org.apache.jackrabbit.oak.run.Main benchmark LoginTest Oak-Composite-Store Apache Jackrabbit Oak 1.12-SNAPSHOT # LoginTest C min 10% 50% 90% max N Oak-Composite-Store 1 620 653 705 788 1218 840 LoginTest, Timer enabled, Oak-Composite-Memory-Store FIXTURE, 10 minutes: java -Dwarmup=5 -Druntime=600 -Dprofile=true -cp oak-benchmarks-1.12-SNAPSHOT.jar org.apache.jackrabbit.oak.run.Main benchmark LoginTest Oak-Composite-Memory-Store Apache Jackrabbit Oak 1.12-SNAPSHOT # LoginTest C min 10% 50% 90% max N Oak-Composite-Memory-Store 1 583 593 621 734 1335 923 LoginTest, Timer disabled, Oak-Composite-Memory-Store FIXTURE, 10 minutes: java -Doak.query.timerDisabled -Dwarmup=5 -Druntime=600 -Dprofile=true -cp oak-benchmarks-1.12-SNAPSHOT.jar org.apache.jackrabbit.oak.run.Main benchmark LoginTest Oak-Composite-Memory-Store Apache Jackrabbit Oak 1.12-SNAPSHOT # LoginTest C min 10% 50% 90% max N Oak-Composite-Memory-Store 1 578 590 611 669 913 961 GetPrincipalTest, Timer enabled, Oak-Composite-Store FIXTURE, 1 minute: java -Dwarmup=5 -Druntime=60 -Dprofile=true -cp oak-benchmarks-1.12-SNAPSHOT.jar org.apache.jackrabbit.oak.run.Main benchmark GetPrincipalTest Oak-Composite-Store Apache Jackrabbit Oak 1.12-SNAPSHOT # GetPrincipalTest C min 10% 50% 90% max N Setup 10000 users Oak-Composite-Store 1 106 112 123 143 188 478 GetPrincipalTest, Timer disabled, Oak-Composite-Store FIXTURE, 1 minute: java -Doak.query.timerDisabled -Dwarmup=5 -Druntime=60 -Dprofile=true -cp oak-benchmarks-1.12-SNAPSHOT.jar org.apache.jackrabbit.oak.run.Main benchmark GetPrincipalTest Oak-Composite-Store Apache Jackrabbit Oak 1.12-SNAPSHOT # GetPrincipalTest C min 10% 50% 90% max N Setup 10000 users Oak-Composite-Store 1 105 116 124 142 173 473 OrderedIndexQueryStandardIndexTest, Timer enabled, Oak-Composite-Store FIXTURE, 1 minute: java -Dwarmup=5 -Druntime=60 -Dprofile=true -cp oak-benchmarks-1.12-SNAPSHOT.jar org.apache.jackrabbit.oak.run.Main benchmark OrderedIndexQueryStandardIndexTest Oak-Composite-Store Apache Jackrabbit Oak 1.12-SNAPSHOT # OrderedIndexQueryStandardI C min 10% 50% 90% max N Oak-Composite-Store 1 0 0 0 0 12 1262384 OrderedIndexQueryStandardIndexTest, Timer disabled, Oak-Composite-Store FIXTURE, 1 minute: java -Doak.query.timerDisabled -Dwarmup=5 -Druntime=60 -Dprofile=true -cp oak-benchmarks-1.12-SNAPSHOT.jar org.apache.jackrabbit.oak.run.Main benchmark OrderedIndexQueryStandardIndexTest Oak-Composite-Store Apache Jackrabbit Oak 1.12-SNAPSHOT # OrderedIndexQueryStandardI C min 10% 50% 90% max N Oak-Composite-Store 1 0 0 0 0 13 1143689 OrderedIndexQueryNoIndexTest, Timer enabled, Oak-Composite-Store FIXTURE, 1 minute: java -Dwarmup=5 -Druntime=60 -Dprofile=true -cp oak-benchmarks-1.12-SNAPSHOT.jar org.apache.jackrabbit.oak.run.Main benchmark OrderedIndexQueryNoIndexTest Oak-Composite-Store # OrderedIndexQueryNoIndexTe C min 10% 50% 90% max N Oak-Composite-Store 1 0 0 0 1 12 137439 OrderedIndexQueryNoIndexTest, Timer disabled, Oak-Composite-Store FIXTURE, 1 minute: java -Doak.query.timerDisabled -Dwarmup=5 -Druntime=60 -Dprofile=true -cp oak-benchmarks-1.12-SNAPSHOT.jar org.apache.jackrabbit.oak.run.Main benchmark OrderedIndexQueryNoIndexTest Oak-Composite-Store Apache Jackrabbit Oak 1.12-SNAPSHOT # OrderedIndexQueryNoIndexTe C min 10% 50% 90% max N Oak-Composite-Store 1 0 0 0 1 8 148341 {code} > Benchmark on QUERY_DURATION metrics implemented in OAK-7904 > ----------------------------------------------------------- > > Key: OAK-8011 > URL: https://issues.apache.org/jira/browse/OAK-8011 > Project: Jackrabbit Oak > Issue Type: Task > Components: indexing, query > Reporter: Paul Chibulcuteanu > Priority: Major > Fix For: 1.12 > > > As part of OAK-7904, there are some possible performance concerns on adding additional metrics in code which is executed a lot. > See [~tmueller]'s comment: > {code} > Some comments on overhead of measuring: > We measure here very common, and very fast operations. I don't know how fast next() could be, but if everything is in memory, it could be faster than 600 ns. I measured the fastest measured operation was processed at 0.091904 milliseconds , that would be 91904 nanoseconds. Measures was this divided by 256, so just 359 nanoseconds. > System.nanoTime() can be slower than that, according to this older article it can be 650 nanoseconds. We need to call it twice to measure, so 1'300 nanoseconds. Meaning, measuring in the worst case seens so far slows down the operation by factor 4.6 (worst case seen so far). > What we could do is use org.apache.jackrabbit.oak.stats Clock.Fast, which has a much lower overhead than calling System.nanoTime(). The name "Fast" is somewhat of a misnomer: the clock isn't really faster than other clocks, it's just less overhead. So getting the current time is fast. Resolution is low, but that wouldn't be a problem in our case, it's just that most of the time, operations would be 0 ns, and rarely 100s of ns. On average, that would even out (same as with the sampling it is using right now). The problems with Clock.Fast are: > Hard to get a hand on this instance. > It uses a thread pool executor service, which is problematic. If the same service is used by other threads that take milliseconds, then the clock is extremely inaccurate. I would be better to use a simple, separate daemon thread. > {code} > Seeing that there is the possibility to enable/disable the metrics stats two separate benchmark tests can be run: > * specifying the _oak.query.timerDisabled_ system prop > * without specifying the _oak.query.timerDisabled_ system prop -- This message was sent by Atlassian JIRA (v7.6.3#76005)