daehyeok kang created CASSANDRA-21724:
-----------------------------------------
Summary: 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
Reporter: daehyeok kang
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]
