[
https://issues.apache.org/jira/browse/CASSANDRA-18710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17785915#comment-17785915
]
Jacek Lewandowski edited comment on CASSANDRA-18710 at 11/14/23 2:34 PM:
-------------------------------------------------------------------------
I've managed to reproduce it locally with IntelliJ repeated test runs...
a full fresh log
{noformat}
DEBUG [main] 2023-11-14 15:32:22,442 DefaultSchemaUpdateHandler.java:259 -
Schema updated: SchemaTransformationResult{f8993d42-6a31-30e9-a22b-bb9151fe0d47
--> 0bf91067-a88d-31ab-9f12-21fe9470100b,
diff=KeyspacesDiff{created=[KeyspaceMetadata{name=cql_test_keyspace_alt,
kind=REGULAR, params=KeyspaceParams{durable_writes=true,
replication=ReplicationParams{class=org.apache.cassandra.locator.SimpleStrategy,
replication_factor=1}}, tables=[], views=[], functions=[], types=[]}],
dropped=[], altered=[]}}
INFO [main] 2023-11-14 15:32:22,442 Keyspace.java:366 - Creating replication
strategy cql_test_keyspace_alt params KeyspaceParams{durable_writes=true,
replication=ReplicationParams{class=org.apache.cassandra.locator.SimpleStrategy,
replication_factor=1}}
DEBUG [main] 2023-11-14 15:32:22,442 Keyspace.java:370 - New replication
settings for keyspace cql_test_keyspace_alt - invalidating disk boundary caches
DEBUG [main] 2023-11-14 15:32:22,443 TokenMetadata.java:858 - Starting pending
range calculation for cql_test_keyspace_alt
DEBUG [main] 2023-11-14 15:32:22,443 TokenMetadata.java:863 - Pending range
calculation for cql_test_keyspace_alt completed (took: 0ms)
INFO [main] 2023-11-14 15:32:22,443 CQLTester.java:1004 - CREATE TABLE
cql_test_keyspace_alt.table_59 (pk bigint, PRIMARY KEY (pk))
DEBUG [main] 2023-11-14 15:32:22,445 DefaultSchemaUpdateHandler.java:259 -
Schema updated: SchemaTransformationResult{0bf91067-a88d-31ab-9f12-21fe9470100b
--> 50c5fd2a-1feb-349a-bbd5-9bd9ddf90794, diff=KeyspacesDiff{created=[],
dropped=[],
altered=[KeyspaceDiff{before=KeyspaceMetadata{name=cql_test_keyspace_alt,
kind=REGULAR, params=KeyspaceParams{durable_writes=true,
replication=ReplicationParams{class=org.apache.cassandra.locator.SimpleStrategy,
replication_factor=1}}, tables=[], views=[], functions=[], types=[]},
after=KeyspaceMetadata{name=cql_test_keyspace_alt, kind=REGULAR,
params=KeyspaceParams{durable_writes=true,
replication=ReplicationParams{class=org.apache.cassandra.locator.SimpleStrategy,
replication_factor=1}}, tables=[cql_test_keyspace_alt.table_59], views=[],
functions=[], types=[]}, tables=Diff{created=[cql_test_keyspace_alt.table_59],
dropped=[], altered=[]}, views=Diff{created=[], dropped=[], altered=[]},
types=Diff{created=[], dropped=[], altered=[]}, udfs=Diff{created=[],
dropped=[], altered=[]}, udas=Diff{created=[], dropped=[], altered=[]}}]}}
INFO [main] 2023-11-14 15:32:22,445 Keyspace.java:366 - Creating replication
strategy cql_test_keyspace_alt params KeyspaceParams{durable_writes=true,
replication=ReplicationParams{class=org.apache.cassandra.locator.SimpleStrategy,
replication_factor=1}}
INFO [main] 2023-11-14 15:32:22,445 ColumnFamilyStore.java:495 - Initializing
cql_test_keyspace_alt.table_59
DEBUG [main] 2023-11-14 15:32:22,445 DiskBoundaryManager.java:54 - Refreshing
disk boundary cache for cql_test_keyspace_alt.table_59
DEBUG [main] 2023-11-14 15:32:22,445 DiskBoundaryManager.java:93 - Got local
ranges [] (ringVersion = 0)
DEBUG [main] 2023-11-14 15:32:22,445 DiskBoundaryManager.java:57 - Updating
boundaries from null to
DiskBoundaries{directories=[DataDirectory{location=build/test/cassandra/data}],
positions=null, ringVersion=0, directoriesVersion=0} for
cql_test_keyspace_alt.table_59
INFO [main] 2023-11-14 15:32:22,447 ViewManager.java:127 - Not submitting
build tasks for views in keyspace cql_test_keyspace_alt as storage service is
not initialized
INFO [main] 2023-11-14 15:32:22,464 ColumnFamilyStore.java:1021 - Enqueuing
flush of cql_test_keyspace_alt.table_59, Reason: UNIT_TESTS, Usage: 308.594KiB
(0%) on-heap, 15.625KiB (0%) off-heap
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,471
Flushing.java:154 - Writing Memtable-table_59@1863551891(28.320KiB serialized
bytes, 1000 ops, 308.594KiB (0%) on-heap, 15.625KiB (0%) off-heap), flushed
range = [null, null)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,472
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/cql_test_keyspace_alt/table_59-9f7f9ec082fa11eeac18a3d3983bd6d3/nc-1-big-Data.db
(27.334KiB) for commitlog position CommitLogPosition(segmentId=1699972288965,
position=63990)
INFO [MemtableFlushWriter:2] 2023-11-14 15:32:22,504 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/cql_test_keyspace_alt/table_59-9f7f9ec082fa11eeac18a3d3983bd6d3/nc_txn_flush_9f82ac00-82fa-11ee-ac18-a3d3983bd6d3.log
DEBUG [MemtableFlushWriter:2] 2023-11-14 15:32:22,510
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/cql_test_keyspace_alt/table_59-9f7f9ec082fa11eeac18a3d3983bd6d3/nc-1-big-Data.db')]
(1 sstables, 30.666KiB), biggest 30.666KiB, smallest 30.666KiB
INFO [main] 2023-11-14 15:32:22,532 ColumnFamilyStore.java:1021 - Enqueuing
flush of cql_test_keyspace_alt.table_59, Reason: UNIT_TESTS, Usage: 308.594KiB
(0%) on-heap, 15.625KiB (0%) off-heap
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:22,539
Flushing.java:154 - Writing Memtable-table_59@1109612759(28.320KiB serialized
bytes, 1000 ops, 308.594KiB (0%) on-heap, 15.625KiB (0%) off-heap), flushed
range = [null, null)
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:22,540
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/cql_test_keyspace_alt/table_59-9f7f9ec082fa11eeac18a3d3983bd6d3/nc-2-big-Data.db
(27.620KiB) for commitlog position CommitLogPosition(segmentId=1699972288965,
position=124990)
INFO [MemtableFlushWriter:1] 2023-11-14 15:32:22,572 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/cql_test_keyspace_alt/table_59-9f7f9ec082fa11eeac18a3d3983bd6d3/nc_txn_flush_9f8d0c40-82fa-11ee-ac18-a3d3983bd6d3.log
DEBUG [MemtableFlushWriter:1] 2023-11-14 15:32:22,578
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/cql_test_keyspace_alt/table_59-9f7f9ec082fa11eeac18a3d3983bd6d3/nc-2-big-Data.db')]
(1 sstables, 31.664KiB), biggest 31.664KiB, smallest 31.664KiB
INFO [main] 2023-11-14 15:32:22,596 ColumnFamilyStore.java:1021 - Enqueuing
flush of cql_test_keyspace_alt.table_59, Reason: UNIT_TESTS, Usage: 308.594KiB
(0%) on-heap, 15.625KiB (0%) off-heap
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,603
Flushing.java:154 - Writing Memtable-table_59@746372081(28.320KiB serialized
bytes, 1000 ops, 308.594KiB (0%) on-heap, 15.625KiB (0%) off-heap), flushed
range = [null, null)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,604
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/cql_test_keyspace_alt/table_59-9f7f9ec082fa11eeac18a3d3983bd6d3/nc-3-big-Data.db
(27.444KiB) for commitlog position CommitLogPosition(segmentId=1699972288965,
position=185990)
INFO [MemtableFlushWriter:2] 2023-11-14 15:32:22,636 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/cql_test_keyspace_alt/table_59-9f7f9ec082fa11eeac18a3d3983bd6d3/nc_txn_flush_9f96d040-82fa-11ee-ac18-a3d3983bd6d3.log
DEBUG [MemtableFlushWriter:2] 2023-11-14 15:32:22,643
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/cql_test_keyspace_alt/table_59-9f7f9ec082fa11eeac18a3d3983bd6d3/nc-3-big-Data.db')]
(1 sstables, 31.063KiB), biggest 31.063KiB, smallest 31.063KiB
DEBUG [main] 2023-11-14 15:32:22,644 DefaultSchemaUpdateHandler.java:259 -
Schema updated: SchemaTransformationResult{50c5fd2a-1feb-349a-bbd5-9bd9ddf90794
--> f8993d42-6a31-30e9-a22b-bb9151fe0d47, diff=KeyspacesDiff{created=[],
dropped=[KeyspaceMetadata{name=cql_test_keyspace_alt, kind=REGULAR,
params=KeyspaceParams{durable_writes=true,
replication=ReplicationParams{class=org.apache.cassandra.locator.SimpleStrategy,
replication_factor=1}}, tables=[cql_test_keyspace_alt.table_59], views=[],
functions=[], types=[]}], altered=[]}}
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system_schema.keyspaces, Reason: COMMITLOG_DIRTY, Usage: 500B (0%)
on-heap, 289B (0%) off-heap
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system_schema.dropped_columns, Reason: COMMITLOG_DIRTY, Usage: 252B
(0%) on-heap, 25B (0%) off-heap
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system_schema.columns, Reason: COMMITLOG_DIRTY, Usage: 588B (0%)
on-heap, 178B (0%) off-heap
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system_schema.functions, Reason: COMMITLOG_DIRTY, Usage: 252B (0%)
on-heap, 25B (0%) off-heap
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system_schema.views, Reason: COMMITLOG_DIRTY, Usage: 252B (0%)
on-heap, 25B (0%) off-heap
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system_schema.tables, Reason: COMMITLOG_DIRTY, Usage: 1.059KiB (0%)
on-heap, 806B (0%) off-heap
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system.sstable_activity, Reason: COMMITLOG_DIRTY, Usage: 1.723KiB (0%)
on-heap, 302B (0%) off-heap
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system.sstable_activity_v2, Reason: COMMITLOG_DIRTY, Usage: 1.723KiB
(0%) on-heap, 285B (0%) off-heap
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system_schema.types, Reason: COMMITLOG_DIRTY, Usage: 252B (0%)
on-heap, 25B (0%) off-heap
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system_schema.indexes, Reason: COMMITLOG_DIRTY, Usage: 252B (0%)
on-heap, 25B (0%) off-heap
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system.local, Reason: COMMITLOG_DIRTY, Usage: 412B (0%) on-heap, 124B
(0%) off-heap
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system_schema.column_masks, Reason: COMMITLOG_DIRTY, Usage: 388B (0%)
on-heap, 44B (0%) off-heap
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system_schema.triggers, Reason: COMMITLOG_DIRTY, Usage: 252B (0%)
on-heap, 25B (0%) off-heap
INFO [main] 2023-11-14 15:32:22,646 ColumnFamilyStore.java:1021 - Enqueuing
flush of system_schema.aggregates, Reason: COMMITLOG_DIRTY, Usage: 252B (0%)
on-heap, 25B (0%) off-heap
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:22,654
Flushing.java:154 - Writing Memtable-dropped_columns@1386177589(8B serialized
bytes, 1 ops, 252B (0%) on-heap, 25B (0%) off-heap), flushed range = [null,
null)
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:22,654
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/dropped_columns-5e7583b5f3f43af19a39b7e1d6f5f11f/nc-79-big-Data.db
(36B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,654
Flushing.java:154 - Writing Memtable-keyspaces@1791166461(157B serialized
bytes, 3 ops, 500B (0%) on-heap, 289B (0%) off-heap), flushed range = [null,
null)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,654
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/keyspaces-abac5682dea631c5b535b3d6cffd0fb6/nc-79-big-Data.db
(36B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [MemtableFlushWriter:1] 2023-11-14 15:32:22,712 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/keyspaces-abac5682dea631c5b535b3d6cffd0fb6/nc_txn_flush_9f9e7160-82fa-11ee-ac18-a3d3983bd6d3.log
INFO [MemtableFlushWriter:2] 2023-11-14 15:32:22,712 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/dropped_columns-5e7583b5f3f43af19a39b7e1d6f5f11f/nc_txn_flush_9f9e716a-82fa-11ee-ac18-a3d3983bd6d3.log
DEBUG [MemtableFlushWriter:1] 2023-11-14 15:32:22,718
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/keyspaces-abac5682dea631c5b535b3d6cffd0fb6/nc-79-big-Data.db')]
(1 sstables, 5.271KiB), biggest 5.271KiB, smallest 5.271KiB
DEBUG [MemtableFlushWriter:2] 2023-11-14 15:32:22,723
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/dropped_columns-5e7583b5f3f43af19a39b7e1d6f5f11f/nc-79-big-Data.db')]
(1 sstables, 5.197KiB), biggest 5.197KiB, smallest 5.197KiB
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:22,729
Flushing.java:154 - Writing Memtable-columns@1488862175(168B serialized bytes,
2 ops, 588B (0%) on-heap, 178B (0%) off-heap), flushed range = [null, null)
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:22,729
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/columns-24101c25a2ae3af787c1b40ee1aca33f/nc-79-big-Data.db
(36B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,735
Flushing.java:154 - Writing Memtable-functions@1349119369(8B serialized bytes,
1 ops, 252B (0%) on-heap, 25B (0%) off-heap), flushed range = [null, null)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,735
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/functions-96489b7980be3e14a70166a0b9159450/nc-79-big-Data.db
(36B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [MemtableFlushWriter:1] 2023-11-14 15:32:22,793 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/columns-24101c25a2ae3af787c1b40ee1aca33f/nc_txn_flush_9fa96de0-82fa-11ee-ac18-a3d3983bd6d3.log
INFO [MemtableFlushWriter:2] 2023-11-14 15:32:22,800 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/functions-96489b7980be3e14a70166a0b9159450/nc_txn_flush_9faa5840-82fa-11ee-ac18-a3d3983bd6d3.log
DEBUG [MemtableFlushWriter:1] 2023-11-14 15:32:22,800
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/columns-24101c25a2ae3af787c1b40ee1aca33f/nc-79-big-Data.db')]
(1 sstables, 5.452KiB), biggest 5.452KiB, smallest 5.452KiB
DEBUG [MemtableFlushWriter:2] 2023-11-14 15:32:22,807
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/functions-96489b7980be3e14a70166a0b9159450/nc-79-big-Data.db')]
(1 sstables, 5.365KiB), biggest 5.365KiB, smallest 5.365KiB
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:22,812
Flushing.java:154 - Writing Memtable-views@8599039(8B serialized bytes, 1 ops,
252B (0%) on-heap, 25B (0%) off-heap), flushed range = [null, null)
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:22,812
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/views-9786ac1cdd583201a7cdad556410c985/nc-79-big-Data.db
(36B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,818
Flushing.java:154 - Writing Memtable-tables@419653446(784B serialized bytes, 2
ops, 1.059KiB (0%) on-heap, 806B (0%) off-heap), flushed range = [null, null)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,818
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/tables-afddfb9dbc1e30688056eed6c302ba09/nc-79-big-Data.db
(36B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [MemtableFlushWriter:2] 2023-11-14 15:32:22,873 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/tables-afddfb9dbc1e30688056eed6c302ba09/nc_txn_flush_9fb70270-82fa-11ee-ac18-a3d3983bd6d3.log
INFO [MemtableFlushWriter:1] 2023-11-14 15:32:22,873 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/views-9786ac1cdd583201a7cdad556410c985/nc_txn_flush_9fb5f100-82fa-11ee-ac18-a3d3983bd6d3.log
DEBUG [MemtableFlushWriter:1] 2023-11-14 15:32:22,879
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/views-9786ac1cdd583201a7cdad556410c985/nc-79-big-Data.db')]
(1 sstables, 5.117KiB), biggest 5.117KiB, smallest 5.117KiB
DEBUG [MemtableFlushWriter:2] 2023-11-14 15:32:22,880
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/tables-afddfb9dbc1e30688056eed6c302ba09/nc-79-big-Data.db')]
(1 sstables, 6.767KiB), biggest 6.767KiB, smallest 6.767KiB
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:22,887
Flushing.java:154 - Writing Memtable-sstable_activity@1880603122(56B serialized
bytes, 7 ops, 1.723KiB (0%) on-heap, 302B (0%) off-heap), flushed range =
[null, null)
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:22,887
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/sstable_activity-5a1ff267ace03f128563cfae6103c65e/nc-67-big-Data.db
(379B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,893
Flushing.java:154 - Writing Memtable-sstable_activity_v2@2052919804(56B
serialized bytes, 7 ops, 1.723KiB (0%) on-heap, 285B (0%) off-heap), flushed
range = [null, null)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,893
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/sstable_activity_v2-62efe31f3be8310c8d298963439c1288/nc-67-big-Data.db
(362B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [MemtableFlushWriter:1] 2023-11-14 15:32:22,949 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/sstable_activity-5a1ff267ace03f128563cfae6103c65e/nc_txn_flush_9fc1fef0-82fa-11ee-ac18-a3d3983bd6d3.log
INFO [MemtableFlushWriter:2] 2023-11-14 15:32:22,955 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/sstable_activity_v2-62efe31f3be8310c8d298963439c1288/nc_txn_flush_9fc22600-82fa-11ee-ac18-a3d3983bd6d3.log
DEBUG [MemtableFlushWriter:1] 2023-11-14 15:32:22,961
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/sstable_activity-5a1ff267ace03f128563cfae6103c65e/nc-67-big-Data.db')]
(1 sstables, 5.664KiB), biggest 5.664KiB, smallest 5.664KiB
DEBUG [MemtableFlushWriter:2] 2023-11-14 15:32:22,967
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/sstable_activity_v2-62efe31f3be8310c8d298963439c1288/nc-67-big-Data.db')]
(1 sstables, 5.646KiB), biggest 5.646KiB, smallest 5.646KiB
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:22,972
Flushing.java:154 - Writing Memtable-types@1501615369(8B serialized bytes, 1
ops, 252B (0%) on-heap, 25B (0%) off-heap), flushed range = [null, null)
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:22,972
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/types-5a8b1ca866023f77a0459273d308917a/nc-79-big-Data.db
(36B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,977
Flushing.java:154 - Writing Memtable-indexes@139664805(8B serialized bytes, 1
ops, 252B (0%) on-heap, 25B (0%) off-heap), flushed range = [null, null)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:22,977
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/indexes-0feb57ac311f382fba6d9024d305702f/nc-79-big-Data.db
(36B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [MemtableFlushWriter:1] 2023-11-14 15:32:23,033 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/types-5a8b1ca866023f77a0459273d308917a/nc_txn_flush_9fce8210-82fa-11ee-ac18-a3d3983bd6d3.log
INFO [MemtableFlushWriter:2] 2023-11-14 15:32:23,033 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/indexes-0feb57ac311f382fba6d9024d305702f/nc_txn_flush_9fcf6c70-82fa-11ee-ac18-a3d3983bd6d3.log
DEBUG [MemtableFlushWriter:1] 2023-11-14 15:32:23,040
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/types-5a8b1ca866023f77a0459273d308917a/nc-79-big-Data.db')]
(1 sstables, 5.117KiB), biggest 5.117KiB, smallest 5.117KiB
DEBUG [MemtableFlushWriter:2] 2023-11-14 15:32:23,046
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/indexes-0feb57ac311f382fba6d9024d305702f/nc-79-big-Data.db')]
(1 sstables, 5.197KiB), biggest 5.197KiB, smallest 5.197KiB
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:23,052
Flushing.java:154 - Writing Memtable-local@1883860261(65B serialized bytes, 3
ops, 412B (0%) on-heap, 124B (0%) off-heap), flushed range = [null, null)
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:23,052
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nc-80-big-Data.db
(42B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:23,058
Flushing.java:154 - Writing Memtable-column_masks@399096963(39B serialized
bytes, 2 ops, 388B (0%) on-heap, 44B (0%) off-heap), flushed range = [null,
null)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:23,058
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/column_masks-738cc5ed01683268b9d1853d4bc278af/nc-79-big-Data.db
(36B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [MemtableFlushWriter:1] 2023-11-14 15:32:23,116 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nc_txn_flush_9fda9000-82fa-11ee-ac18-a3d3983bd6d3.log
INFO [MemtableFlushWriter:2] 2023-11-14 15:32:23,116 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/column_masks-738cc5ed01683268b9d1853d4bc278af/nc_txn_flush_9fdb7a60-82fa-11ee-ac18-a3d3983bd6d3.log
DEBUG [MemtableFlushWriter:1] 2023-11-14 15:32:23,122
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nc-80-big-Data.db')]
(1 sstables, 4.984KiB), biggest 4.984KiB, smallest 4.984KiB
DEBUG [MemtableFlushWriter:2] 2023-11-14 15:32:23,122
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/column_masks-738cc5ed01683268b9d1853d4bc278af/nc-79-big-Data.db')]
(1 sstables, 5.197KiB), biggest 5.197KiB, smallest 5.197KiB
DEBUG [CompactionExecutor:1] 2023-11-14 15:32:23,124 Directories.java:551 -
FileStore / (/dev/mapper/vgubuntu-root) has 100743039590 bytes available,
checking if we can write 356 bytes
INFO [CompactionExecutor:1] 2023-11-14 15:32:23,124 CompactionTask.java:167 -
Compacting (9fe71334-82fa-11ee-ac18-a3d3983bd6d3)
[/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nc-80-big-Data.db:level=0,
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nc-77-big-Data.db:level=0,
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nc-79-big-Data.db:level=0,
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nc-78-big-Data.db:level=0,
]
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:23,130
Flushing.java:154 - Writing Memtable-triggers@1778156062(8B serialized bytes, 1
ops, 252B (0%) on-heap, 25B (0%) off-heap), flushed range = [null, null)
INFO [PerDiskMemtableFlushWriter_0:2] 2023-11-14 15:32:23,130
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/triggers-4df70b666b05325195a132b54005fd48/nc-79-big-Data.db
(36B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:23,130
Flushing.java:154 - Writing Memtable-aggregates@368230507(8B serialized bytes,
1 ops, 252B (0%) on-heap, 25B (0%) off-heap), flushed range = [null, null)
INFO [PerDiskMemtableFlushWriter_0:1] 2023-11-14 15:32:23,130
Flushing.java:180 - Completed flushing
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/aggregates-924c55872e3a345bb10c12f37c1ba895/nc-79-big-Data.db
(36B) for commitlog position CommitLogPosition(segmentId=1699972288966,
position=28)
INFO [CompactionExecutor:1] 2023-11-14 15:32:23,184 CompactionTask.java:258 -
Compacted (9fe71334-82fa-11ee-ac18-a3d3983bd6d3) 4 sstables to
[build/test/cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nc-81-big,]
to level=0. 356B to 209B (~58% of original) in 59ms. Read Throughput =
5.821KiB/s, Write Throughput = 3.417KiB/s, Row Throughput = ~2/s. 4 total
partitions merged to 1. Partition merge counts were {4:1, }. Time spent
writing keys = 11ms
INFO [NonPeriodicTasks:1] 2023-11-14 15:32:23,184 BigFormat.java:231 -
Deleting sstable:
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nc-77-big
INFO [NonPeriodicTasks:1] 2023-11-14 15:32:23,184 BigFormat.java:231 -
Deleting sstable:
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nc-79-big
INFO [NonPeriodicTasks:1] 2023-11-14 15:32:23,185 BigFormat.java:231 -
Deleting sstable:
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nc-78-big
INFO [NonPeriodicTasks:1] 2023-11-14 15:32:23,185 BigFormat.java:231 -
Deleting sstable:
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nc-80-big
INFO [MemtableFlushWriter:2] 2023-11-14 15:32:23,193 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/aggregates-924c55872e3a345bb10c12f37c1ba895/nc_txn_flush_9fe7132a-82fa-11ee-ac18-a3d3983bd6d3.log
INFO [MemtableFlushWriter:1] 2023-11-14 15:32:23,193 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/triggers-4df70b666b05325195a132b54005fd48/nc_txn_flush_9fe71320-82fa-11ee-ac18-a3d3983bd6d3.log
INFO [NonPeriodicTasks:1] 2023-11-14 15:32:23,198 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system/local-7ad54392bcdd35a684174e047860b377/nc_txn_compaction_9fe71334-82fa-11ee-ac18-a3d3983bd6d3.log
DEBUG [MemtableFlushWriter:2] 2023-11-14 15:32:23,200
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/aggregates-924c55872e3a345bb10c12f37c1ba895/nc-79-big-Data.db')]
(1 sstables, 5.365KiB), biggest 5.365KiB, smallest 5.365KiB
DEBUG [MemtableFlushWriter:1] 2023-11-14 15:32:23,205
ColumnFamilyStore.java:1349 - Flushed to
[BigTableReader:big(path='/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/system_schema/triggers-4df70b666b05325195a132b54005fd48/nc-79-big-Data.db')]
(1 sstables, 5.197KiB), biggest 5.197KiB, smallest 5.197KiB
DEBUG [MemtablePostFlush:1] 2023-11-14 15:32:23,205 CommitLog.java:362 - Commit
log segment
CommitLogSegment(build/test/cassandra/commitlog/CommitLog-7-1699972288965.log)
is unused
DEBUG [MemtablePostFlush:1] 2023-11-14 15:32:23,205
AbstractCommitLogSegmentManager.java:374 - Segment
CommitLogSegment(build/test/cassandra/commitlog/CommitLog-7-1699972288965.log)
is no longer active and will be deleted now
INFO [NonPeriodicTasks:1] 2023-11-14 15:32:23,217 BigFormat.java:231 -
Deleting sstable:
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/cql_test_keyspace_alt/table_59-9f7f9ec082fa11eeac18a3d3983bd6d3/nc-3-big
INFO [NonPeriodicTasks:1] 2023-11-14 15:32:23,217 BigFormat.java:231 -
Deleting sstable:
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/cql_test_keyspace_alt/table_59-9f7f9ec082fa11eeac18a3d3983bd6d3/nc-2-big
INFO [NonPeriodicTasks:1] 2023-11-14 15:32:23,217 BigFormat.java:231 -
Deleting sstable:
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/cql_test_keyspace_alt/table_59-9f7f9ec082fa11eeac18a3d3983bd6d3/nc-1-big
INFO [NonPeriodicTasks:1] 2023-11-14 15:32:23,229 LogTransaction.java:249 -
Unfinished transaction log, deleting
/home/jlewandowski/dev/cassandra/cassandra-5.0/build/test/cassandra/data/cql_test_keyspace_alt/table_59-9f7f9ec082fa11eeac18a3d3983bd6d3/nc_txn_unknowncompactiontype_9ff40b70-82fa-11ee-ac18-a3d3983bd6d3.log
java.lang.AssertionError:
Expected :9279.0
Actual :8812.5105226
<Click to see difference>
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.failNotEquals(Assert.java:834)
at org.junit.Assert.assertEquals(Assert.java:553)
at org.junit.Assert.assertEquals(Assert.java:683)
at
org.apache.cassandra.io.DiskSpaceMetricsTest.testFlushSize(DiskSpaceMetricsTest.java:120)
at jdk.internal.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at
com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:69)
at
com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38)
at
com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:30)
at
com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
at
com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:232)
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:55)
{noformat}
was (Author: jlewandowski):
I've managed to reproduce it locally with IntelliJ repeated test runs...
> Test failure:
> org.apache.cassandra.io.DiskSpaceMetricsTest.testFlushSize-.jdk17 (from
> org.apache.cassandra.io.DiskSpaceMetricsTest-.jdk17)
> ------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: CASSANDRA-18710
> URL: https://issues.apache.org/jira/browse/CASSANDRA-18710
> Project: Cassandra
> Issue Type: Bug
> Components: Test/unit
> Reporter: Ekaterina Dimitrova
> Assignee: Jacek Lewandowski
> Priority: Normal
> Fix For: 4.1.x, 5.0-beta, 5.0.x, 5.x
>
> Attachments: org.apache.cassandra.io.DiskSpaceMetricsTest.txt
>
>
> Seen here:
> [https://ci-cassandra.apache.org/job/Cassandra-trunk/1644/testReport/org.apache.cassandra.io/DiskSpaceMetricsTest/testFlushSize__jdk17/]
> h3.
> {code:java}
> Error Message
> expected:<7200.0> but was:<1367.83970468544>
> Stacktrace
> junit.framework.AssertionFailedError: expected:<7200.0> but
> was:<1367.83970468544> at
> org.apache.cassandra.io.DiskSpaceMetricsTest.testFlushSize(DiskSpaceMetricsTest.java:119)
> at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
> Method) at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> {code}
>
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
