[jira] [Commented] (SOLR-10226) JMX metric avgTimePerRequest broken
[ https://issues.apache.org/jira/browse/SOLR-10226?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15899784#comment-15899784 ] ASF subversion and git services commented on SOLR-10226: Commit 242ddfb148eda45347ff34d2b16958a835c340a5 in lucene-solr's branch refs/heads/branch_6x from [~ab] [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=242ddfb ] SOLR-10226 JMX metric avgTimePerRequest broken. > JMX metric avgTimePerRequest broken > --- > > Key: SOLR-10226 > URL: https://issues.apache.org/jira/browse/SOLR-10226 > Project: Solr > Issue Type: Bug > Security Level: Public(Default Security Level. Issues are Public) > Components: metrics >Affects Versions: 6.4.1 >Reporter: Bojan Smid >Assignee: Andrzej Bialecki > Fix For: 6.5, master (7.0) > > Attachments: SOLR-10226.patch, SOLR-10226.patch > > > JMX Metric avgTimePerRequest (of > org.apache.solr.handler.component.SearchHandler) doesn't appear to behave > correctly anymore. It was a cumulative value in pre-6.4 versions. Since > totalTime metric was removed (which was a base for monitoring calculations), > avgTimePerRequest seems like possible alternative to calculate "time spent in > requests since last measurement", but it behaves strangely after 6.4. > I did a simple test on gettingstarted collection (just unpacked the Solr > 6.4.1 version and started it with "bin/solr start -e cloud -noprompt"). The > query I used was: > http://localhost:8983/solr/gettingstarted/select?indent=on=*:*=json > I run it 30 times in a row (with approx 1 sec between executions). > At the same time I was looking (with jconsole) at bean > solr/gettingstarted_shard2_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler > Here is how metric was changing over time (first number is "requests" metric, > second number is "avgTimePerRequest"): > 10 6.6033 > 12 5.9557 > 13 0.9015---> 13th req would need negative duration if this was > cumulative > 15 6.7315 > 16 7.4873 > 17 0.8458---> same case with 17th request > 23 6.1076 > At the same time bean > solr/gettingstarted_shard1_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler > also showed strange values: > 65.13482 > 810.5694 > 90.504 > 10 0.344 > 12 8.8121 > 18 3.3531 > CC [~ab] -- This message was sent by Atlassian JIRA (v6.3.15#6346) - To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (SOLR-10226) JMX metric avgTimePerRequest broken
[ https://issues.apache.org/jira/browse/SOLR-10226?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15899783#comment-15899783 ] ASF subversion and git services commented on SOLR-10226: Commit 2d51a42d3cae3eddc89f407cd3611fa2cd5d55d0 in lucene-solr's branch refs/heads/master from [~ab] [ https://git-wip-us.apache.org/repos/asf?p=lucene-solr.git;h=2d51a42 ] SOLR-10226 JMX metric avgTimePerRequest broken. > JMX metric avgTimePerRequest broken > --- > > Key: SOLR-10226 > URL: https://issues.apache.org/jira/browse/SOLR-10226 > Project: Solr > Issue Type: Bug > Security Level: Public(Default Security Level. Issues are Public) > Components: metrics >Affects Versions: 6.4.1 >Reporter: Bojan Smid >Assignee: Andrzej Bialecki > Fix For: 6.5, master (7.0) > > Attachments: SOLR-10226.patch, SOLR-10226.patch > > > JMX Metric avgTimePerRequest (of > org.apache.solr.handler.component.SearchHandler) doesn't appear to behave > correctly anymore. It was a cumulative value in pre-6.4 versions. Since > totalTime metric was removed (which was a base for monitoring calculations), > avgTimePerRequest seems like possible alternative to calculate "time spent in > requests since last measurement", but it behaves strangely after 6.4. > I did a simple test on gettingstarted collection (just unpacked the Solr > 6.4.1 version and started it with "bin/solr start -e cloud -noprompt"). The > query I used was: > http://localhost:8983/solr/gettingstarted/select?indent=on=*:*=json > I run it 30 times in a row (with approx 1 sec between executions). > At the same time I was looking (with jconsole) at bean > solr/gettingstarted_shard2_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler > Here is how metric was changing over time (first number is "requests" metric, > second number is "avgTimePerRequest"): > 10 6.6033 > 12 5.9557 > 13 0.9015---> 13th req would need negative duration if this was > cumulative > 15 6.7315 > 16 7.4873 > 17 0.8458---> same case with 17th request > 23 6.1076 > At the same time bean > solr/gettingstarted_shard1_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler > also showed strange values: > 65.13482 > 810.5694 > 90.504 > 10 0.344 > 12 8.8121 > 18 3.3531 > CC [~ab] -- This message was sent by Atlassian JIRA (v6.3.15#6346) - To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (SOLR-10226) JMX metric avgTimePerRequest broken
[ https://issues.apache.org/jira/browse/SOLR-10226?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15897818#comment-15897818 ] Bojan Smid commented on SOLR-10226: --- I tested the patch quickly, metric totalTime is now there, but there is one small problem - it is expressed in ns. To be backward compatible it should be in ms. > JMX metric avgTimePerRequest broken > --- > > Key: SOLR-10226 > URL: https://issues.apache.org/jira/browse/SOLR-10226 > Project: Solr > Issue Type: Bug > Security Level: Public(Default Security Level. Issues are Public) > Components: metrics >Affects Versions: 6.4.1 >Reporter: Bojan Smid >Assignee: Andrzej Bialecki > Attachments: SOLR-10226.patch > > > JMX Metric avgTimePerRequest (of > org.apache.solr.handler.component.SearchHandler) doesn't appear to behave > correctly anymore. It was a cumulative value in pre-6.4 versions. Since > totalTime metric was removed (which was a base for monitoring calculations), > avgTimePerRequest seems like possible alternative to calculate "time spent in > requests since last measurement", but it behaves strangely after 6.4. > I did a simple test on gettingstarted collection (just unpacked the Solr > 6.4.1 version and started it with "bin/solr start -e cloud -noprompt"). The > query I used was: > http://localhost:8983/solr/gettingstarted/select?indent=on=*:*=json > I run it 30 times in a row (with approx 1 sec between executions). > At the same time I was looking (with jconsole) at bean > solr/gettingstarted_shard2_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler > Here is how metric was changing over time (first number is "requests" metric, > second number is "avgTimePerRequest"): > 10 6.6033 > 12 5.9557 > 13 0.9015---> 13th req would need negative duration if this was > cumulative > 15 6.7315 > 16 7.4873 > 17 0.8458---> same case with 17th request > 23 6.1076 > At the same time bean > solr/gettingstarted_shard1_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler > also showed strange values: > 65.13482 > 810.5694 > 90.504 > 10 0.344 > 12 8.8121 > 18 3.3531 > CC [~ab] -- This message was sent by Atlassian JIRA (v6.3.15#6346) - To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (SOLR-10226) JMX metric avgTimePerRequest broken
[ https://issues.apache.org/jira/browse/SOLR-10226?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15897711#comment-15897711 ] Bojan Smid commented on SOLR-10226: --- Thanks for looking into this and patching it so quickly :). >From what I see, "totalTime" was removed in SOLR-8785. Having it back solves >my problem (actually, any monitoring solution would need such cumulative total >time). Re avgTimePerRequest - I agree with what you suggest, decayed value >makes much more sense (non-decayed would only be useful as a hack to get to >totalTime). > JMX metric avgTimePerRequest broken > --- > > Key: SOLR-10226 > URL: https://issues.apache.org/jira/browse/SOLR-10226 > Project: Solr > Issue Type: Bug > Security Level: Public(Default Security Level. Issues are Public) > Components: metrics >Affects Versions: 6.4.1 >Reporter: Bojan Smid >Assignee: Andrzej Bialecki > Attachments: SOLR-10226.patch > > > JMX Metric avgTimePerRequest (of > org.apache.solr.handler.component.SearchHandler) doesn't appear to behave > correctly anymore. It was a cumulative value in pre-6.4 versions. Since > totalTime metric was removed (which was a base for monitoring calculations), > avgTimePerRequest seems like possible alternative to calculate "time spent in > requests since last measurement", but it behaves strangely after 6.4. > I did a simple test on gettingstarted collection (just unpacked the Solr > 6.4.1 version and started it with "bin/solr start -e cloud -noprompt"). The > query I used was: > http://localhost:8983/solr/gettingstarted/select?indent=on=*:*=json > I run it 30 times in a row (with approx 1 sec between executions). > At the same time I was looking (with jconsole) at bean > solr/gettingstarted_shard2_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler > Here is how metric was changing over time (first number is "requests" metric, > second number is "avgTimePerRequest"): > 10 6.6033 > 12 5.9557 > 13 0.9015---> 13th req would need negative duration if this was > cumulative > 15 6.7315 > 16 7.4873 > 17 0.8458---> same case with 17th request > 23 6.1076 > At the same time bean > solr/gettingstarted_shard1_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler > also showed strange values: > 65.13482 > 810.5694 > 90.504 > 10 0.344 > 12 8.8121 > 18 3.3531 > CC [~ab] -- This message was sent by Atlassian JIRA (v6.3.15#6346) - To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (SOLR-10226) JMX metric avgTimePerRequest broken
[
https://issues.apache.org/jira/browse/SOLR-10226?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15897649#comment-15897649
]
Andrzej Bialecki commented on SOLR-10226:
--
You're right - the {{Timer}} implementation that was used in Solr 6.3 and
earlier internally used {{Histogram}}, which did not apply decaying to the
total accumulated value. When we upgraded this class to a newer version from
Codahale Metrics the underlying new implementation of {{Histogram}} does apply
decaying to this value...
Anyway, we have to add back a simple counter to track the total value as
"totalTime", which somehow disappeared for no good reason. From that you will
be able again to calculate the non-decaying average time.
The question is what to do with avgTimePerRequest. In my opinion, moving
forward we should keep the decaying avgTimePerRequest because it more correctly
represents the recent state of the system as opposed to the cumulative
non-decayed value, which doesn't really reflect anything in particular (there
could have been extended periods of idle time followed by recent high activity,
and the value would be still low even though the recent load was high).
CC [~otis].
> JMX metric avgTimePerRequest broken
> ---
>
> Key: SOLR-10226
> URL: https://issues.apache.org/jira/browse/SOLR-10226
> Project: Solr
> Issue Type: Bug
> Security Level: Public(Default Security Level. Issues are Public)
> Components: metrics
>Affects Versions: 6.4.1
>Reporter: Bojan Smid
>Assignee: Andrzej Bialecki
>
> JMX Metric avgTimePerRequest (of
> org.apache.solr.handler.component.SearchHandler) doesn't appear to behave
> correctly anymore. It was a cumulative value in pre-6.4 versions. Since
> totalTime metric was removed (which was a base for monitoring calculations),
> avgTimePerRequest seems like possible alternative to calculate "time spent in
> requests since last measurement", but it behaves strangely after 6.4.
> I did a simple test on gettingstarted collection (just unpacked the Solr
> 6.4.1 version and started it with "bin/solr start -e cloud -noprompt"). The
> query I used was:
> http://localhost:8983/solr/gettingstarted/select?indent=on=*:*=json
> I run it 30 times in a row (with approx 1 sec between executions).
> At the same time I was looking (with jconsole) at bean
> solr/gettingstarted_shard2_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler
> Here is how metric was changing over time (first number is "requests" metric,
> second number is "avgTimePerRequest"):
> 10 6.6033
> 12 5.9557
> 13 0.9015---> 13th req would need negative duration if this was
> cumulative
> 15 6.7315
> 16 7.4873
> 17 0.8458---> same case with 17th request
> 23 6.1076
> At the same time bean
> solr/gettingstarted_shard1_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler
> also showed strange values:
> 65.13482
> 810.5694
> 90.504
> 10 0.344
> 12 8.8121
> 18 3.3531
> CC [~ab]
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
-
To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org
For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (SOLR-10226) JMX metric avgTimePerRequest broken
[ https://issues.apache.org/jira/browse/SOLR-10226?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15895573#comment-15895573 ] Bojan Smid commented on SOLR-10226: --- I think avgTimePerRequest in previous versions didn't have decay/sampling applied on it. I am looking at one Solr 6.3 node which was up for the past 2 months (I checked few other setups, different Solr version, but saw the same behavior). Here are the stats from its standard handler: requests:1791464 totalTime:564718.746333 avgTimePerRequest:0.3152275157820643 Both requests and totalTime metrics are cumulative and avgTimePerRequest shows exactly value totalTime/requests, therefore there was no decay/sampling applied in calculation of avgTime before 6.4. When it comes to previously posted sample, there was something like 30-60 sec or so between the requests (the time I needed to write down the numbers). I just did another test, fresh values (this time just 3-5 sec between the requests): 1 85.3 2 41.2 3 26.1 4 17.0 6 11.08 7 7.43 8 4.98 9 3.62 11 3.28 (few min pause) 13 8.12 14 3.33 (few min pause) 15 9.69 16 4.09 Does decay/sampling explain the behavior even with these short periods between the requests (ranging from few sec to few min)? > JMX metric avgTimePerRequest broken > --- > > Key: SOLR-10226 > URL: https://issues.apache.org/jira/browse/SOLR-10226 > Project: Solr > Issue Type: Bug > Security Level: Public(Default Security Level. Issues are Public) > Components: metrics >Affects Versions: 6.4.1 >Reporter: Bojan Smid > > JMX Metric avgTimePerRequest (of > org.apache.solr.handler.component.SearchHandler) doesn't appear to behave > correctly anymore. It was a cumulative value in pre-6.4 versions. Since > totalTime metric was removed (which was a base for monitoring calculations), > avgTimePerRequest seems like possible alternative to calculate "time spent in > requests since last measurement", but it behaves strangely after 6.4. > I did a simple test on gettingstarted collection (just unpacked the Solr > 6.4.1 version and started it with "bin/solr start -e cloud -noprompt"). The > query I used was: > http://localhost:8983/solr/gettingstarted/select?indent=on=*:*=json > I run it 30 times in a row (with approx 1 sec between executions). > At the same time I was looking (with jconsole) at bean > solr/gettingstarted_shard2_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler > Here is how metric was changing over time (first number is "requests" metric, > second number is "avgTimePerRequest"): > 10 6.6033 > 12 5.9557 > 13 0.9015---> 13th req would need negative duration if this was > cumulative > 15 6.7315 > 16 7.4873 > 17 0.8458---> same case with 17th request > 23 6.1076 > At the same time bean > solr/gettingstarted_shard1_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler > also showed strange values: > 65.13482 > 810.5694 > 90.504 > 10 0.344 > 12 8.8121 > 18 3.3531 > CC [~ab] -- This message was sent by Atlassian JIRA (v6.3.15#6346) - To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
[jira] [Commented] (SOLR-10226) JMX metric avgTimePerRequest broken
[ https://issues.apache.org/jira/browse/SOLR-10226?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15894980#comment-15894980 ] Andrzej Bialecki commented on SOLR-10226: -- At what intervals did you check these numbers? Previous versions of Solr used a very old version of the code, which supposedly used a similar exponentially decaying sampling (with a strong bias towards the most recent 5 min window). The new code uses an exponentially decaying reservoir sampling with the same bias so theoretically results should be the same... So, both in the new and in the old code these values would be exponentially decaying over time, so if you don't make any requests for a while the rates will fall down. If you could please capture the timestamps at which you made the requests and observations it would be very helpful - thank you! > JMX metric avgTimePerRequest broken > --- > > Key: SOLR-10226 > URL: https://issues.apache.org/jira/browse/SOLR-10226 > Project: Solr > Issue Type: Bug > Security Level: Public(Default Security Level. Issues are Public) > Components: metrics >Affects Versions: 6.4.1 >Reporter: Bojan Smid > > JMX Metric avgTimePerRequest (of > org.apache.solr.handler.component.SearchHandler) doesn't appear to behave > correctly anymore. It was a cumulative value in pre-6.4 versions. Since > totalTime metric was removed (which was a base for monitoring calculations), > avgTimePerRequest seems like possible alternative to calculate "time spent in > requests since last measurement", but it behaves strangely after 6.4. > I did a simple test on gettingstarted collection (just unpacked the Solr > 6.4.1 version and started it with "bin/solr start -e cloud -noprompt"). The > query I used was: > http://localhost:8983/solr/gettingstarted/select?indent=on=*:*=json > I run it 30 times in a row (with approx 1 sec between executions). > At the same time I was looking (with jconsole) at bean > solr/gettingstarted_shard2_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler > Here is how metric was changing over time (first number is "requests" metric, > second number is "avgTimePerRequest"): > 10 6.6033 > 12 5.9557 > 13 0.9015---> 13th req would need negative duration if this was > cumulative > 15 6.7315 > 16 7.4873 > 17 0.8458---> same case with 17th request > 23 6.1076 > At the same time bean > solr/gettingstarted_shard1_replica2:type=/select,id=org.apache.solr.handler.component.SearchHandler > also showed strange values: > 65.13482 > 810.5694 > 90.504 > 10 0.344 > 12 8.8121 > 18 3.3531 > CC [~ab] -- This message was sent by Atlassian JIRA (v6.3.15#6346) - To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
