[
https://issues.apache.org/jira/browse/CASSANDRA-21724?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Brandon Williams updated CASSANDRA-21724:
-----------------------------------------
Bug Category: Parent values: Correctness(12982)
Complexity: Low Hanging Fruit
Component/s: Feature/Virtual Tables
Discovered By: User Report
Fix Version/s: 4.1.x
5.0.x
6.x
7.x
Severity: Normal
Status: Open (was: Triage Needed)
> system_views latency virtual tables report values 1000x too small
> (microseconds treated as nanoseconds)
> -------------------------------------------------------------------------------------------------------
>
> Key: CASSANDRA-21724
> URL: https://issues.apache.org/jira/browse/CASSANDRA-21724
> Project: Apache Cassandra
> Issue Type: Bug
> Components: Feature/Virtual Tables
> Reporter: daehyeok kang
> Priority: Normal
> Fix For: 4.1.x, 5.0.x, 6.x, 7.x
>
>
> h3. Summary
> The six latency tables in {{system_views}} report values that are 1000x
> smaller than
> reality. The reservoir stores microseconds, but {{TableMetricTables}}
> converts as if the
> values were nanoseconds. Sub-millisecond latencies round away to {{0}}
> entirely.
> This is a regression introduced by CASSANDRA-16760 in 4.1. It has the same
> root cause as
> CASSANDRA-17877, which fixed the speculative retry path; the same correction
> does not
> appear to have been applied to the virtual tables.
> Affected tables (all built via {{{}LatencyTableMetric{}}},
> TableMetricTables.java:72-77):
> * {{local_read_latency}}
> * {{local_scan_latency}}
> * {{local_write_latency}}
> * {{coordinator_read_latency}}
> * {{coordinator_scan_latency}}
> * {{coordinator_write_latency}}
> In each of those tables, only the {{{}p50th_ms{}}}, {{p99th_ms}} and
> {{max_ms}} columns are
> affected.
> h3. Reproduction
> Captured on a production 5.0.7 node. Both commands were run on that same
> node, seconds
> apart, against the same table.
> {noformat}
> $ KS=shopping_tram; TB=material_v1
> $ nodetool tablehistograms $KS.$TB | awk 'NR<=3 || /^(50%|99%|Max)/'
> shopping_tram/material_v1 histograms
> Percentile Read Latency Write Latency SSTables Partition
> Size Cell Count
> (micros) (micros)
> (bytes)
> 50% 258.00 12.00 2.00
> 642 20
> 99% 1331.00 35.00 7.00
> 2299 72
> Max 14237.00 1331.00 17.00
> 219342 179
> $ cqlsh -e "SELECT * FROM system_views.local_read_latency;" | more
> keyspace_name | table_name | count | max_ms | p50th_ms | p99th_ms |
> per_second
> ---------------+-------------+-------------+--------+----------+----------+------------
> shopping_tram | material_v1 | 36362548949 | 0.014 | 0 | 0.001 |
> 11749.752
> {noformat}
> Side by side:
> || ||tablehistograms (us)||expected (ms)||virtual table||
> |p50|258.00|0.258|0|
> |p99|1331.00|1.331|0.001|
> |max|14237.00|14.237|0.014|
> Every value is exactly 1000x too small, and p50 is lost entirely to the
> 3-decimal
> rounding. {{count}} (36.3 billion) and {{per_second}} (11749) on the same row
> are correct,
> so collection is working and only the output conversion is wrong.
> The practical effect is that any table whose p99 read latency is below 1 ms
> reports
> {{0}} for all three columns. On the node above, most tables in the listing do
> exactly
> that despite billions of recorded reads, which makes these tables unusable
> for latency
> monitoring.
> h3. Root cause
> CASSANDRA-16760 (commit 845077fbc8) moved the ns -> us conversion from the
> read side to
> the write side:
> * Added {{{}ScalingReservoir{}}}, so the reservoir now stores *microseconds*
> ({{{}CassandraMetricsRegistry.DEFAULT_TIMER_UNIT == MICROSECONDS{}}}, line
> 104;
> {{{}createReservoir{}}}, lines 405-416).
> * Removed {{JmxTimer.durationFactor}} (was {{{}1.0 /
> durationUnit.toNanos(1){}}}), which is why JMX and nodetool stayed correct.
> {{ScalingReservoir.getSnapshot()}} does not reverse the scaling:
> {code:java}
> // ScalingReservoir.java:44-54
> public void update(long value) {
> delegate.update(scaleFunc.applyAsLong(value)); // ns -> us, the only
> conversion
> }
> public Snapshot getSnapshot() {
> return delegate.getSnapshot(); // microseconds, no
> reverse
> }
> {code}
> So every direct snapshot consumer now receives microseconds.
> {{TableMetricTables}} was not updated and still applies a nanosecond factor:
> {code:java}
> // TableMetricTables.java:60
> private final static double NS_TO_MS = 0.000001;
> // TableMetricTables.java:150-159
> public void add(SimpleDataSet result, String column, double value) {
> if (column.endsWith(suffix)) // suffix = "_ms"
> value *= NS_TO_MS; // microseconds * 1e-6 -> ms / 1000
> super.add(result, column, value);
> }
> {code}
> The result is then rounded to 3 decimals
> ({{{}Precision.round(value, 3, ROUND_HALF_UP){}}}, line 136), which erases
> anything below 1 ms.
> Running that arithmetic reproduces the observed output exactly:
> {noformat}
> case stored us current observed fixed
> p50 258 0.0 0.0 0.258
> p99 1331 0.001 0.001 1.331
> max 14237 0.014 0.014 14.237
> {noformat}
> {{current}} is {{Precision.round(storedUs * 1e-6, 3, ROUND_HALF_UP)}} and
> matches the
> {{observed}} column from the node above on all three values.
> I verified that no layer between the reservoir and the virtual table reverses
> the scaling:
> {{LatencyMetricsTimer}} (LatencyMetrics.java:236, sums children only),
> {{{}ThreadLocalTimer{}}},
> {{OverrideTimer}} (line 211), {{ThreadLocalHistogram}} (line 85). The cast to
> {{EstimatedHistogramReservoirSnapshot}} in
> {{LatencyMetricsTimer.getSnapshot()}} further
> confirms {{ScalingReservoir}} passes the delegate snapshot through untouched.
> Evidence inside the tree that microseconds is the correct reading:
> * {{TableStatsHolder.java:388}} divides the same metric by 1000 to obtain ms.
> * {{PercentileSpeculativeRetryPolicy.java:60}} carries the comment
> {{"latency snapshot uses a default timer so is in microseconds"}} – added by
> CASSANDRA-17877 when it fixed this same regression on the speculative retry
> path.
> * {{TableMetricTables.java:211}} still says {{"EstimatedHistogram keeping
> them in ns is hard to parse as a human so convert to ms"}}
> h3. Affected versions
> 4.0 is correct: the reservoir stored nanoseconds and {{NS_TO_MS}} was the
> right factor.
> ||Branch||Reservoir unit||Virtual table factor||Verdict||
> |cassandra-4.0|ns (no DEFAULT_TIMER_UNIT, no ScalingReservoir)|NS_TO_MS =
> 1e-6|correct|
> |cassandra-4.1|MICROSECONDS|NS_TO_MS = 1e-6|broken|
> |cassandra-5.0|MICROSECONDS|NS_TO_MS = 1e-6|broken|
> |cassandra-6.0|MICROSECONDS|NS_TO_MS = 1e-6|broken|
> |trunk (7.0)|MICROSECONDS|NS_TO_MS = 1e-6|broken|
> The reproduction above is from a production 5.0.7 node.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
