[
https://issues.apache.org/jira/browse/CASSANDRA-16196?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17213234#comment-17213234
]
Adam Holmberg commented on CASSANDRA-16196:
-------------------------------------------
I let this spin for quite a while and it never reproduced, but I think I see
what's happening after resorting to static analysis. Here is what I think is
happening.
The test
[waits|https://github.com/apache/cassandra-dtest/blob/1c8e5bcd5040af279205cd69bb5276ed854540e6/disk_balance_test.py#L335]
for {{compactionstats}} pending tasks to be zero after commanding a
compaction. However because SSTable cleanup is [scheduled in the background
asynchronously|https://github.com/apache/cassandra/blob/2ae1ec5dd2d98178f3ab4b3ed64a87147e713560/src/java/org/apache/cassandra/io/sstable/format/SSTableReader.java#L2036-L2064],
the pending tasks can go to zero while the deletes are still happening. If we
get to the disk balance assertion while those are still running, we may find
only one disk cleaned up so far.
There is evidence of this in the log file of David's CI run.
{{INFO [CompactionExecutor:9] 2020-10-06 20:26:27,227 CompactionTask.java:251
- Compacted (35c63db2-0812-11eb-85ce-07703ff33f2a) 5 sstables to
[/tmp/dtest-qrvo6g7p/test/node2/data2/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-137-big,/tmp/dtest-qrvo6g7p/test/node2/data2/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-142-big,/tmp/dtest-qrvo6g7p/test/node2/data2/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-147-big,/tmp/dtest-qrvo6g7p/test/node2/data2/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-152-big,/tmp/dtest-qrvo6g7p/test/node2/data2/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-156-big,]
to level=0. 4.364MiB to 4.364MiB (~100% of original) in 271ms. Read
Throughput = 16.100MiB/s, Write Throughput = 16.100MiB/s, Row Throughput =
~40,010/s. 20,005 total partitions merged to 20,005. Partition merge counts
were {1:20005, }
INFO [NonPeriodicTasks:1] 2020-10-06 20:26:27,243 SSTable.java:111 - Deleting
sstable:
/tmp/dtest-qrvo6g7p/test/node2/data3/system_schema/functions-96489b7980be3e14a70166a0b9159450/na-4-big
INFO [CompactionExecutor:7] 2020-10-06 20:26:27,271 CompactionTask.java:251 -
Compacted (35c63db0-0812-11eb-85ce-07703ff33f2a) 5 sstables to
[/tmp/dtest-qrvo6g7p/test/node2/data0/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-138-big,/tmp/dtest-qrvo6g7p/test/node2/data0/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-145-big,/tmp/dtest-qrvo6g7p/test/node2/data0/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-151-big,/tmp/dtest-qrvo6g7p/test/node2/data0/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-157-big,/tmp/dtest-qrvo6g7p/test/node2/data0/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-161-big,]
to level=0. 4.326MiB to 4.326MiB (~100% of original) in 314ms. Read
Throughput = 13.766MiB/s, Write Throughput = 13.766MiB/s, Row Throughput =
~39,660/s. 19,830 total partitions merged to 19,830. Partition merge counts
were {1:19830, }
INFO [CompactionExecutor:10] 2020-10-06 20:26:27,286 CompactionTask.java:251 -
Compacted (35c63db3-0812-11eb-85ce-07703ff33f2a) 5 sstables to
[/tmp/dtest-qrvo6g7p/test/node2/data3/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-141-big,/tmp/dtest-qrvo6g7p/test/node2/data3/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-144-big,/tmp/dtest-qrvo6g7p/test/node2/data3/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-149-big,/tmp/dtest-qrvo6g7p/test/node2/data3/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-153-big,/tmp/dtest-qrvo6g7p/test/node2/data3/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-158-big,]
to level=0. 4.404MiB to 4.404MiB (~100% of original) in 329ms. Read
Throughput = 13.368MiB/s, Write Throughput = 13.368MiB/s, Row Throughput =
~40,374/s. 20,187 total partitions merged to 20,187. Partition merge counts
were {1:20187, }
INFO [CompactionExecutor:8] 2020-10-06 20:26:27,287 CompactionTask.java:251 -
Compacted (35c63db4-0812-11eb-85ce-07703ff33f2a) 5 sstables to
[/tmp/dtest-qrvo6g7p/test/node2/data4/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-139-big,/tmp/dtest-qrvo6g7p/test/node2/data4/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-146-big,/tmp/dtest-qrvo6g7p/test/node2/data4/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-150-big,/tmp/dtest-qrvo6g7p/test/node2/data4/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-154-big,/tmp/dtest-qrvo6g7p/test/node2/data4/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-159-big,]
to level=0. 4.335MiB to 4.335MiB (~100% of original) in 330ms. Read
Throughput = 13.117MiB/s, Write Throughput = 13.117MiB/s, Row Throughput =
~39,746/s. 19,873 total partitions merged to 19,873. Partition merge counts
were {1:19873, }
INFO [CompactionExecutor:6] 2020-10-06 20:26:27,287 CompactionTask.java:251 -
Compacted (35c63db1-0812-11eb-85ce-07703ff33f2a) 6 sstables to
[/tmp/dtest-qrvo6g7p/test/node2/data1/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-140-big,/tmp/dtest-qrvo6g7p/test/node2/data1/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-143-big,/tmp/dtest-qrvo6g7p/test/node2/data1/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-148-big,/tmp/dtest-qrvo6g7p/test/node2/data1/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-155-big,/tmp/dtest-qrvo6g7p/test/node2/data1/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-160-big,]
to level=0. 4.381MiB to 4.386MiB (~100% of original) in 331ms. Read
Throughput = 13.227MiB/s, Write Throughput = 13.242MiB/s, Row Throughput =
~40,210/s. 20,105 total partitions merged to 20,105. Partition merge counts
were {1:20105, }}}
The compacted files were all ~4.4MiB so we would expect the disks to be
balanced. As the compactions finish, we see table deletions continue, but the
server only gets through those on {{disk2}} for the keyspace in question,
before the test fails the assertion and the server is killed.
{{INFO [NonPeriodicTasks:1] 2020-10-06 20:26:28,182 SSTable.java:111 -
Deleting sstable:
/tmp/dtest-qrvo6g7p/test/node2/data3/system/available_ranges_v2-4224a0882ac93d0c889dfbb5f0facda0/na-4-big
INFO [NonPeriodicTasks:1] 2020-10-06 20:26:28,185 SSTable.java:111 - Deleting
sstable:
/tmp/dtest-qrvo6g7p/test/node2/data2/system/available_ranges_v2-4224a0882ac93d0c889dfbb5f0facda0/na-3-big
INFO [NonPeriodicTasks:1] 2020-10-06 20:26:28,213 SSTable.java:111 - Deleting
sstable:
/tmp/dtest-qrvo6g7p/test/node2/data2/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-122-big
INFO [NonPeriodicTasks:1] 2020-10-06 20:26:28,224 SSTable.java:111 - Deleting
sstable:
/tmp/dtest-qrvo6g7p/test/node2/data2/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-123-big
INFO [NonPeriodicTasks:1] 2020-10-06 20:26:28,260 SSTable.java:111 - Deleting
sstable:
/tmp/dtest-qrvo6g7p/test/node2/data2/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-120-big
INFO [NonPeriodicTasks:1] 2020-10-06 20:26:28,287 SSTable.java:111 - Deleting
sstable:
/tmp/dtest-qrvo6g7p/test/node2/data2/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-121-big
DEBUG [GossipStage:1] 2020-10-06 20:26:28,316 Gossiper.java:471 - Convicting
/127.0.0.1:7000 with status LEFT - alive true
INFO [GossipStage:1] 2020-10-06 20:26:28,316 Gossiper.java:1211 - InetAddress
/127.0.0.1:7000 is now DOWN
INFO [NonPeriodicTasks:1] 2020-10-06 20:26:28,320 SSTable.java:111 - Deleting
sstable:
/tmp/dtest-qrvo6g7p/test/node2/data2/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-124-big
INFO [NonPeriodicTasks:1] 2020-10-06 20:26:28,379 SSTable.java:111 - Deleting
sstable:
/tmp/dtest-qrvo6g7p/test/node2/data0/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-116-big
INFO [NonPeriodicTasks:1] 2020-10-06 20:26:28,478 SSTable.java:111 - Deleting
sstable:
/tmp/dtest-qrvo6g7p/test/node2/data0/keyspace1/standard1-8e445040081111ebac99afe4a7391731/na-117-big
<end of log>
}}
This can be corroborated in the assertion message, which shows 4575645 as the
measured for the second volume, which is 4.364MiB, the same size as the file
output from the compaction message in the previous snippet.
Since there is no final deterministic message that can tell us when tidying is
done, the test change I'm proposing takes a couple size samples to make sure
we're not still cleaning up.
[patch|https://github.com/apache/cassandra-dtest/compare/master...aholmberg:CASSANDRA-16196?expand=1]
[ci|https://app.circleci.com/pipelines/github/aholmberg/cassandra?branch=CASSANDRA-16196]
> Fix flaky test test_disk_balance_after_boundary_change_lcs -
> disk_balance_test.TestDiskBalance
> ----------------------------------------------------------------------------------------------
>
> Key: CASSANDRA-16196
> URL: https://issues.apache.org/jira/browse/CASSANDRA-16196
> Project: Cassandra
> Issue Type: Bug
> Components: Test/dtest/python
> Reporter: David Capwell
> Assignee: Adam Holmberg
> Priority: Normal
> Fix For: 4.0-beta
>
>
> https://app.circleci.com/pipelines/github/dcapwell/cassandra/622/workflows/adcd463c-156a-43c7-a9bc-7f3e4938dbe8/jobs/3514
> {code}
> error_message = '' if 'error_message' not in kwargs else
> kwargs['error_message']
> assert vmin > vmax * (1.0 - error) or vmin == vmax, \
> > "values not within {:.2f}% of the max: {} ({})".format(error *
> > 100, args, error_message)
> E AssertionError: values not within 10.00% of the max: (8022760,
> 9192165, 4575645, 9235566, 9091014) (node2)
> tools/assertions.py:206: AssertionError
> {code}
> Marking as distinct issue after chat in CASSANDRA-14030
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org
For additional commands, e-mail: commits-h...@cassandra.apache.org
