scylla-cluster-tests
scylla-cluster-tests copied to clipboard
Published
20 hours ago •
scylladb
scylladb
fix(full scan thread): Added missing fetch-next-page to fetch_result_pages
fetch_result_pages had a "while" loop where a call to result.fetch_next_page() is missing. Adding it back. Fixes: #8287
Testing
- [ ]
PR pre-checks (self review)
- [x] I added the relevant
backportlabels - [x] I didn't leave commented-out/debugging code
Reminders
- Add New configuration option and document them (in
sdcm/sct_config.py) - Add unit tests to cover my changes (under
unit-test/folder) - Update the Readme/doc folder relevant to this change (if needed)
@fruch, It looks like a bug in the code. But I'm guessing that this was deleted because the scan can be too big. And we are just getting command responses and not fetching all the data. I'm not sure if it was deleted just to speedup testing 1.5 years ago or not @yarongilor could you please test this change before merging?
@fruch, It looks like a bug in the code. But I'm guessing that this was deleted because the scan can be too big. And we are just getting command responses and not fetching all the data. I'm not sure if it was deleted just to speedup testing 1.5 years ago or not @yarongilor could you please test this change before merging?
Tested in longevity-50gb-3days-test
Passed ok like:
< t:2024-09-16 15:53:36,511 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s
< t:2024-09-16 15:53:36,714 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 100 result pages..
< t:2024-09-16 16:02:44,137 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s
< t:2024-09-16 16:02:44,367 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 1000 result pages..
< t:2024-09-16 16:07:13,960 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s
< t:2024-09-16 16:07:14,186 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 100 result pages..
< t:2024-09-16 16:08:40,183 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s
< t:2024-09-16 16:08:40,716 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 1000 result pages..
< t:2024-09-16 16:11:53,966 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s
< t:2024-09-16 16:11:54,143 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 0 result pages..
< t:2024-09-16 19:19:36,428 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s
< t:2024-09-16 19:19:36,712 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 1000 result pages..
< t:2024-09-16 19:43:05,067 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s
< t:2024-09-16 19:43:05,372 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 1000 result pages..
< t:2024-09-16 19:53:25,368 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s
< t:2024-09-16 19:53:25,545 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 1000 result pages..
< t:2024-09-16 20:06:34,270 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s
< t:2024-09-16 20:06:34,504 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 0 result pages..
@fruch, It looks like a bug in the code. But I'm guessing that this was deleted because the scan can be too big. And we are just getting command responses and not fetching all the data. I'm not sure if it was deleted just to speedup testing 1.5 years ago or not @yarongilor could you please test this change before merging?
Tested in longevity-50gb-3days-test
Running with the suggested fix of missing line, it resulted "almost" OK, except encountering another issue of the query "timeout" being ignored, or it is OK since it is per single page. Using a debug-mode print, it seems the query run for 3 hours , reading 23032 pages:
< t:2024-09-16 16:11:53,966 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s
< t:2024-09-16 16:11:54,143 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 0 result pages..
< t:2024-09-16 16:11:54,375 f:scan_operation_thread.py l:194 c:FullScanOperation p:DEBUG > [page 1] Has more pages: True
< t:2024-09-16 19:12:20,783 f:scan_operation_thread.py l:194 c:FullScanOperation p:DEBUG > [page 23031] Has more pages: True
< t:2024-09-16 19:12:20,847 f:scan_operation_thread.py l:194 c:FullScanOperation p:DEBUG > [page 23032] Has more pages: False
@roydahan , @fruch , although it sounds impressing for scylla to run a 3-hours paged-query (during nemesis), is it reasonable for testing? or should we limit the duration of such a paged-query in test?
@fruch, It looks like a bug in the code. But I'm guessing that this was deleted because the scan can be too big. And we are just getting command responses and not fetching all the data. I'm not sure if it was deleted just to speedup testing 1.5 years ago or not @yarongilor could you please test this change before merging?
Tested in longevity-50gb-3days-test
Running with the suggested fix of missing line, it resulted "almost" OK, except encountering another issue of the query "timeout" being ignored, or it is OK since it is per single page. Using a debug-mode print, it seems the query run for 3 hours , reading 23032 pages:
< t:2024-09-16 16:11:53,966 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s < t:2024-09-16 16:11:54,143 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 0 result pages.. < t:2024-09-16 16:11:54,375 f:scan_operation_thread.py l:194 c:FullScanOperation p:DEBUG > [page 1] Has more pages: True< t:2024-09-16 19:12:20,783 f:scan_operation_thread.py l:194 c:FullScanOperation p:DEBUG > [page 23031] Has more pages: True < t:2024-09-16 19:12:20,847 f:scan_operation_thread.py l:194 c:FullScanOperation p:DEBUG > [page 23032] Has more pages: False@roydahan , @fruch , although it sounds impressing for scylla to run a 3-hours paged-query (during nemesis), is it reasonable for testing? or should we limit the duration of such a paged-query in test?
I don't know if it's reasonable, it depend on the purpose of those full scans, they are supposed to read all of the data ? we will need more data on the effect of it on the test.
@fruch, It looks like a bug in the code. But I'm guessing that this was deleted because the scan can be too big. And we are just getting command responses and not fetching all the data. I'm not sure if it was deleted just to speedup testing 1.5 years ago or not @yarongilor could you please test this change before merging?
Tested in longevity-50gb-3days-test
Running with the suggested fix of missing line, it resulted "almost" OK, except encountering another issue of the query "timeout" being ignored, or it is OK since it is per single page. Using a debug-mode print, it seems the query run for 3 hours , reading 23032 pages:
< t:2024-09-16 16:11:53,966 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s < t:2024-09-16 16:11:54,143 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 0 result pages.. < t:2024-09-16 16:11:54,375 f:scan_operation_thread.py l:194 c:FullScanOperation p:DEBUG > [page 1] Has more pages: True< t:2024-09-16 19:12:20,783 f:scan_operation_thread.py l:194 c:FullScanOperation p:DEBUG > [page 23031] Has more pages: True < t:2024-09-16 19:12:20,847 f:scan_operation_thread.py l:194 c:FullScanOperation p:DEBUG > [page 23032] Has more pages: False@roydahan , @fruch , although it sounds impressing for scylla to run a 3-hours paged-query (during nemesis), is it reasonable for testing? or should we limit the duration of such a paged-query in test?
I don't know if it's reasonable, it depend on the purpose of those full scans, they are supposed to read all of the data ? we will need more data on the effect of it on the test.
Well, it sounds a valid use case for a customer to have a full-scan to read all table data. The long full-scan didn't have any impact on test metrics. And since test now passes ok, i think we can merge it.
@fruch, It looks like a bug in the code. But I'm guessing that this was deleted because the scan can be too big. And we are just getting command responses and not fetching all the data. I'm not sure if it was deleted just to speedup testing 1.5 years ago or not @yarongilor could you please test this change before merging?
Tested in longevity-50gb-3days-test
Running with the suggested fix of missing line, it resulted "almost" OK, except encountering another issue of the query "timeout" being ignored, or it is OK since it is per single page. Using a debug-mode print, it seems the query run for 3 hours , reading 23032 pages:
< t:2024-09-16 16:11:53,966 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s < t:2024-09-16 16:11:54,143 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 0 result pages.. < t:2024-09-16 16:11:54,375 f:scan_operation_thread.py l:194 c:FullScanOperation p:DEBUG > [page 1] Has more pages: True< t:2024-09-16 19:12:20,783 f:scan_operation_thread.py l:194 c:FullScanOperation p:DEBUG > [page 23031] Has more pages: True < t:2024-09-16 19:12:20,847 f:scan_operation_thread.py l:194 c:FullScanOperation p:DEBUG > [page 23032] Has more pages: False@roydahan , @fruch , although it sounds impressing for scylla to run a 3-hours paged-query (during nemesis), is it reasonable for testing? or should we limit the duration of such a paged-query in test?
I don't know if it's reasonable, it depend on the purpose of those full scans, they are supposed to read all of the data ? we will need more data on the effect of it on the test.
Well, it sounds a valid use case for a customer to have a full-scan to read all table data. The long full-scan didn't have any impact on test metrics. And since test now passes ok, i think we can merge it.
maybe we should consider bigger page sizes ? if you want it realistic ?
also won't it gonna hold the test from ending ? or this flow can be stopped gracefully ?
@fruch, It looks like a bug in the code. But I'm guessing that this was deleted because the scan can be too big. And we are just getting command responses and not fetching all the data. I'm not sure if it was deleted just to speedup testing 1.5 years ago or not @yarongilor could you please test this change before merging?
to me it seems like it was dropped by mistake in, and no one noticed it: https://github.com/scylladb/scylla-cluster-tests/pull/5710
@yarongilor on 4h case doesn't really cut it as for testing the effect of it on all of the cases it's enabled. lets try at least 2-3 more cases it's enabled in.
@fruch, It looks like a bug in the code. But I'm guessing that this was deleted because the scan can be too big. And we are just getting command responses and not fetching all the data. I'm not sure if it was deleted just to speedup testing 1.5 years ago or not @yarongilor could you please test this change before merging?
to me it seems like it was dropped by mistake in, and no one noticed it: #5710
@yarongilor on 4h case doesn't really cut it as for testing the effect of it on all of the cases it's enabled. lets try at least 2-3 more cases it's enabled in.
@fruch , are you sure testing is needed? as noted above, it should have been thoroughly tested before https://github.com/scylladb/scylla-cluster-tests/pull/5710.
@fruch, It looks like a bug in the code. But I'm guessing that this was deleted because the scan can be too big. And we are just getting command responses and not fetching all the data. I'm not sure if it was deleted just to speedup testing 1.5 years ago or not @yarongilor could you please test this change before merging?
to me it seems like it was dropped by mistake in, and no one noticed it: #5710
@yarongilor on 4h case doesn't really cut it as for testing the effect of it on all of the cases it's enabled. lets try at least 2-3 more cases it's enabled in.
@fruch , are you sure testing is needed? as noted above, it should have been thoroughly tested before https://github.com/scylladb/scylla-cluster-tests/pull/5710.
A bit naive to assume that some that weren't used for 2 years, are still working as expected.
Also can you point to where that thoroughly tested took place ?
Testing: 10gb-3h passed ok with output like:
< t:2024-10-27 18:09:05,695 f:scan_operation_thread.py l:100 c:FullScanOperation p:INFO > FullscanOperationBase starts
< t:2024-10-27 18:09:05,695 f:scan_operation_thread.py l:104 c:FullScanOperation p:INFO > FullscanOperationBase scan_event: <class 'sdcm.sct_events.database.FullScanEvent'>
< t:2024-10-27 18:09:05,695 f:scan_operation_thread.py l:109 c:FullScanOperation p:INFO > FullscanOperationBase init finished
< t:2024-10-27 18:09:05,695 f:scan_operation_thread.py l:100 c:FullPartitionScanOperation p:INFO > FullscanOperationBase starts
< t:2024-10-27 18:09:05,696 f:scan_operation_thread.py l:104 c:FullPartitionScanOperation p:INFO > FullscanOperationBase scan_event: <class 'sdcm.sct_events.database.FullPartitionScanReversedOrderEvent'>
< t:2024-10-27 18:09:05,696 f:scan_operation_thread.py l:109 c:FullPartitionScanOperation p:INFO > FullscanOperationBase init finished
< t:2024-10-27 18:09:05,696 f:scan_operation_thread.py l:100 c:FullScanAggregatesOperation p:INFO > FullscanOperationBase starts
< t:2024-10-27 18:09:05,696 f:scan_operation_thread.py l:104 c:FullScanAggregatesOperation p:INFO > FullscanOperationBase scan_event: <class 'sdcm.sct_events.database.FullScanAggregateEvent'>
< t:2024-10-27 18:09:05,697 f:scan_operation_thread.py l:109 c:FullScanAggregatesOperation p:INFO > FullscanOperationBase init finished
< t:2024-10-27 18:13:19,273 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s
< t:2024-10-27 18:13:21,836 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=8882088)
< t:2024-10-27 18:13:42,017 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggered
< t:2024-10-27 18:13:52,104 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s
< t:2024-10-27 18:13:52,180 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 1000 result pages..
< t:2024-10-27 18:15:19,941 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s
< t:2024-10-27 18:15:20,025 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 0 result pages..
< t:2024-10-27 18:19:03,384 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s
< t:2024-10-27 18:19:08,258 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=10000000)
< t:2024-10-27 18:19:28,436 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggered
< t:2024-10-27 18:19:38,520 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s
< t:2024-10-27 18:19:38,643 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 0 result pages..
< t:2024-10-27 18:23:32,373 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s
< t:2024-10-27 18:23:37,120 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=10000000)
< t:2024-10-27 18:23:57,295 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggered
< t:2024-10-27 18:24:07,400 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s
< t:2024-10-27 18:24:12,747 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=10000000)
< t:2024-10-27 18:24:32,971 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggered
< t:2024-10-27 18:24:43,071 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s
< t:2024-10-27 18:24:47,182 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=10000000)
< t:2024-10-27 18:25:07,379 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggered
longevity-large-partition-200k-pks-4days-gce
runs ok as well, like:
< t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------
----------+---------+----------------------------------------------------------------------------------+
< t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | op_type | duration | exceptions | nemesis_at_start | nemes
is_at_end | success | cmd |
< t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------
----------+---------+----------------------------------------------------------------------------------+
< t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanReversedOrderEvent | 0.286191463470459 | | None |
None | True | select pk,ck from scylla_bench.test where pk = 167 order by ck asc limit 138231 |
< t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanEvent | 0.20973515510559082 | | None |
None | True | select pk,ck from scylla_bench.test where pk = 167 |
< t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------
----------+---------+----------------------------------------------------------------------------------+
< t:2024-10-28 07:42:32,327 f:operations_thread.py l:140 c:ScanOperationThread p:DEBUG > Operation instance map: {'table_and_aggregate': <function ScanOperationThread.__init__.<locals>.<la
mbda> at 0x73289845a3b0>, 'random': <function ScanOperationThread.__init__.<locals>.<lambda> at 0x732898559360>, 'table': <function ScanOperationThread.__init__.<locals>.<lambda> at 0x732898
55bf40>, 'partition': <function ScanOperationThread.__init__.<locals>.<lambda> at 0x73289866d630>, 'aggregate': <function ScanOperationThread.__init__.<locals>.<lambda> at 0x7328985f8670>}
< t:2024-10-28 07:42:32,327 f:operations_thread.py l:147 c:ScanOperationThread p:DEBUG > Going to run operation FullPartitionScanOperation
< t:2024-10-28 07:42:59,972 f:operations_thread.py l:150 c:ScanOperationThread p:DEBUG > Thread operations queue depleted.
< t:2024-10-28 07:42:59,973 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > Thread stats:
< t:2024-10-28 07:42:59,973 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------
----------+---------+----------------------------------------------------------------------------------------------------------------+
< t:2024-10-28 07:42:59,973 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | op_type | duration | exceptions | nemesis_at_start | nemes
is_at_end | success | cmd |
< t:2024-10-28 07:42:59,973 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------
----------+---------+----------------------------------------------------------------------------------------------------------------+
...
< t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanEvent | 4.7430033683776855 | | NodetoolDecommission |
NodetoolDecommission | True | select pk,ck from scylla_bench.test where pk = 29 |
< t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanReversedOrderEvent | 1.1897552013397217 | | NodetoolDecommission |
NodetoolDecommission | True | select pk,ck from scylla_bench.test where pk = 955 and ck < 59720 order by ck asc BYPASS CACHE |
< t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanEvent | 0.4158589839935303 | | NodetoolDecommission |
NodetoolDecommission | True | select pk,ck from scylla_bench.test where pk = 955 and ck < 59720 BYPASS CACHE |
< t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanReversedOrderEvent | 1.2938134670257568 | | None |
None | True | select pk,ck from scylla_bench.test where pk = 1026 and ck < 163993 order by ck asc |
< t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanEvent | 1.4889512062072754 | | None |
None | True | select pk,ck from scylla_bench.test where pk = 1026 and ck < 163993
@fruch , anything else to validate in addition?
Testing: 10gb-3h passed ok with output like:
< t:2024-10-27 18:09:05,695 f:scan_operation_thread.py l:100 c:FullScanOperation p:INFO > FullscanOperationBase starts < t:2024-10-27 18:09:05,695 f:scan_operation_thread.py l:104 c:FullScanOperation p:INFO > FullscanOperationBase scan_event: <class 'sdcm.sct_events.database.FullScanEvent'> < t:2024-10-27 18:09:05,695 f:scan_operation_thread.py l:109 c:FullScanOperation p:INFO > FullscanOperationBase init finished < t:2024-10-27 18:09:05,695 f:scan_operation_thread.py l:100 c:FullPartitionScanOperation p:INFO > FullscanOperationBase starts < t:2024-10-27 18:09:05,696 f:scan_operation_thread.py l:104 c:FullPartitionScanOperation p:INFO > FullscanOperationBase scan_event: <class 'sdcm.sct_events.database.FullPartitionScanReversedOrderEvent'> < t:2024-10-27 18:09:05,696 f:scan_operation_thread.py l:109 c:FullPartitionScanOperation p:INFO > FullscanOperationBase init finished < t:2024-10-27 18:09:05,696 f:scan_operation_thread.py l:100 c:FullScanAggregatesOperation p:INFO > FullscanOperationBase starts < t:2024-10-27 18:09:05,696 f:scan_operation_thread.py l:104 c:FullScanAggregatesOperation p:INFO > FullscanOperationBase scan_event: <class 'sdcm.sct_events.database.FullScanAggregateEvent'> < t:2024-10-27 18:09:05,697 f:scan_operation_thread.py l:109 c:FullScanAggregatesOperation p:INFO > FullscanOperationBase init finished < t:2024-10-27 18:13:19,273 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s < t:2024-10-27 18:13:21,836 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=8882088) < t:2024-10-27 18:13:42,017 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggered < t:2024-10-27 18:13:52,104 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s < t:2024-10-27 18:13:52,180 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 1000 result pages.. < t:2024-10-27 18:15:19,941 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s < t:2024-10-27 18:15:20,025 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 0 result pages.. < t:2024-10-27 18:19:03,384 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s < t:2024-10-27 18:19:08,258 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=10000000) < t:2024-10-27 18:19:28,436 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggered < t:2024-10-27 18:19:38,520 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s < t:2024-10-27 18:19:38,643 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 0 result pages.. < t:2024-10-27 18:23:32,373 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s < t:2024-10-27 18:23:37,120 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=10000000) < t:2024-10-27 18:23:57,295 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggered < t:2024-10-27 18:24:07,400 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s < t:2024-10-27 18:24:12,747 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=10000000) < t:2024-10-27 18:24:32,971 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggered < t:2024-10-27 18:24:43,071 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s < t:2024-10-27 18:24:47,182 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=10000000) < t:2024-10-27 18:25:07,379 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggeredlongevity-large-partition-200k-pks-4days-gce
runs ok as well, like:
< t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------ ----------+---------+----------------------------------------------------------------------------------+ < t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | op_type | duration | exceptions | nemesis_at_start | nemes is_at_end | success | cmd | < t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------ ----------+---------+----------------------------------------------------------------------------------+ < t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanReversedOrderEvent | 0.286191463470459 | | None | None | True | select pk,ck from scylla_bench.test where pk = 167 order by ck asc limit 138231 | < t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanEvent | 0.20973515510559082 | | None | None | True | select pk,ck from scylla_bench.test where pk = 167 | < t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------ ----------+---------+----------------------------------------------------------------------------------+ < t:2024-10-28 07:42:32,327 f:operations_thread.py l:140 c:ScanOperationThread p:DEBUG > Operation instance map: {'table_and_aggregate': <function ScanOperationThread.__init__.<locals>.<la mbda> at 0x73289845a3b0>, 'random': <function ScanOperationThread.__init__.<locals>.<lambda> at 0x732898559360>, 'table': <function ScanOperationThread.__init__.<locals>.<lambda> at 0x732898 55bf40>, 'partition': <function ScanOperationThread.__init__.<locals>.<lambda> at 0x73289866d630>, 'aggregate': <function ScanOperationThread.__init__.<locals>.<lambda> at 0x7328985f8670>} < t:2024-10-28 07:42:32,327 f:operations_thread.py l:147 c:ScanOperationThread p:DEBUG > Going to run operation FullPartitionScanOperation < t:2024-10-28 07:42:59,972 f:operations_thread.py l:150 c:ScanOperationThread p:DEBUG > Thread operations queue depleted. < t:2024-10-28 07:42:59,973 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > Thread stats: < t:2024-10-28 07:42:59,973 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------ ----------+---------+----------------------------------------------------------------------------------------------------------------+ < t:2024-10-28 07:42:59,973 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | op_type | duration | exceptions | nemesis_at_start | nemes is_at_end | success | cmd | < t:2024-10-28 07:42:59,973 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------ ----------+---------+----------------------------------------------------------------------------------------------------------------+ ... < t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanEvent | 4.7430033683776855 | | NodetoolDecommission | NodetoolDecommission | True | select pk,ck from scylla_bench.test where pk = 29 | < t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanReversedOrderEvent | 1.1897552013397217 | | NodetoolDecommission | NodetoolDecommission | True | select pk,ck from scylla_bench.test where pk = 955 and ck < 59720 order by ck asc BYPASS CACHE | < t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanEvent | 0.4158589839935303 | | NodetoolDecommission | NodetoolDecommission | True | select pk,ck from scylla_bench.test where pk = 955 and ck < 59720 BYPASS CACHE | < t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanReversedOrderEvent | 1.2938134670257568 | | None | None | True | select pk,ck from scylla_bench.test where pk = 1026 and ck < 163993 order by ck asc | < t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanEvent | 1.4889512062072754 | | None | None | True | select pk,ck from scylla_bench.test where pk = 1026 and ck < 163993@fruch , anything else to validate in addition?
The large partition run you are pointing to runs for 18 minutes, that far from being a proof for the effect of this change
Testing: 10gb-3h passed ok with output like:
< t:2024-10-27 18:09:05,695 f:scan_operation_thread.py l:100 c:FullScanOperation p:INFO > FullscanOperationBase starts < t:2024-10-27 18:09:05,695 f:scan_operation_thread.py l:104 c:FullScanOperation p:INFO > FullscanOperationBase scan_event: <class 'sdcm.sct_events.database.FullScanEvent'> < t:2024-10-27 18:09:05,695 f:scan_operation_thread.py l:109 c:FullScanOperation p:INFO > FullscanOperationBase init finished < t:2024-10-27 18:09:05,695 f:scan_operation_thread.py l:100 c:FullPartitionScanOperation p:INFO > FullscanOperationBase starts < t:2024-10-27 18:09:05,696 f:scan_operation_thread.py l:104 c:FullPartitionScanOperation p:INFO > FullscanOperationBase scan_event: <class 'sdcm.sct_events.database.FullPartitionScanReversedOrderEvent'> < t:2024-10-27 18:09:05,696 f:scan_operation_thread.py l:109 c:FullPartitionScanOperation p:INFO > FullscanOperationBase init finished < t:2024-10-27 18:09:05,696 f:scan_operation_thread.py l:100 c:FullScanAggregatesOperation p:INFO > FullscanOperationBase starts < t:2024-10-27 18:09:05,696 f:scan_operation_thread.py l:104 c:FullScanAggregatesOperation p:INFO > FullscanOperationBase scan_event: <class 'sdcm.sct_events.database.FullScanAggregateEvent'> < t:2024-10-27 18:09:05,697 f:scan_operation_thread.py l:109 c:FullScanAggregatesOperation p:INFO > FullscanOperationBase init finished < t:2024-10-27 18:13:19,273 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s < t:2024-10-27 18:13:21,836 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=8882088) < t:2024-10-27 18:13:42,017 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggered < t:2024-10-27 18:13:52,104 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s < t:2024-10-27 18:13:52,180 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 1000 result pages.. < t:2024-10-27 18:15:19,941 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s < t:2024-10-27 18:15:20,025 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 0 result pages.. < t:2024-10-27 18:19:03,384 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s < t:2024-10-27 18:19:08,258 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=10000000) < t:2024-10-27 18:19:28,436 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggered < t:2024-10-27 18:19:38,520 f:scan_operation_thread.py l:123 c:FullScanOperation p:DEBUG > Will run command SELECT * from keyspace1.standard1 BYPASS CACHE USING TIMEOUT 300s < t:2024-10-27 18:19:38,643 f:scan_operation_thread.py l:188 c:FullScanOperation p:DEBUG > Will fetch up to 0 result pages.. < t:2024-10-27 18:23:32,373 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s < t:2024-10-27 18:23:37,120 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=10000000) < t:2024-10-27 18:23:57,295 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggered < t:2024-10-27 18:24:07,400 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s < t:2024-10-27 18:24:12,747 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=10000000) < t:2024-10-27 18:24:32,971 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggered < t:2024-10-27 18:24:43,071 f:scan_operation_thread.py l:462 c:FullScanAggregatesOperation p:DEBUG > Will run command SELECT count(*) FROM keyspace1.standard1 BYPASS CACHE USING TIMEOUT 1800s < t:2024-10-27 18:24:47,182 f:scan_operation_thread.py l:504 c:FullScanAggregatesOperation p:DEBUG > Fullscan aggregation result: Row(count=10000000) < t:2024-10-27 18:25:07,379 f:scan_operation_thread.py l:533 c:FullScanAggregatesOperation p:INFO > mapreduce_service_requests_dispatched_to_other_nodes was triggeredlongevity-large-partition-200k-pks-4days-gce runs ok as well, like:
< t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------ ----------+---------+----------------------------------------------------------------------------------+ < t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | op_type | duration | exceptions | nemesis_at_start | nemes is_at_end | success | cmd | < t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------ ----------+---------+----------------------------------------------------------------------------------+ < t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanReversedOrderEvent | 0.286191463470459 | | None | None | True | select pk,ck from scylla_bench.test where pk = 167 order by ck asc limit 138231 | < t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanEvent | 0.20973515510559082 | | None | None | True | select pk,ck from scylla_bench.test where pk = 167 | < t:2024-10-28 07:37:32,225 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------ ----------+---------+----------------------------------------------------------------------------------+ < t:2024-10-28 07:42:32,327 f:operations_thread.py l:140 c:ScanOperationThread p:DEBUG > Operation instance map: {'table_and_aggregate': <function ScanOperationThread.__init__.<locals>.<la mbda> at 0x73289845a3b0>, 'random': <function ScanOperationThread.__init__.<locals>.<lambda> at 0x732898559360>, 'table': <function ScanOperationThread.__init__.<locals>.<lambda> at 0x732898 55bf40>, 'partition': <function ScanOperationThread.__init__.<locals>.<lambda> at 0x73289866d630>, 'aggregate': <function ScanOperationThread.__init__.<locals>.<lambda> at 0x7328985f8670>} < t:2024-10-28 07:42:32,327 f:operations_thread.py l:147 c:ScanOperationThread p:DEBUG > Going to run operation FullPartitionScanOperation < t:2024-10-28 07:42:59,972 f:operations_thread.py l:150 c:ScanOperationThread p:DEBUG > Thread operations queue depleted. < t:2024-10-28 07:42:59,973 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > Thread stats: < t:2024-10-28 07:42:59,973 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------ ----------+---------+----------------------------------------------------------------------------------------------------------------+ < t:2024-10-28 07:42:59,973 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | op_type | duration | exceptions | nemesis_at_start | nemes is_at_end | success | cmd | < t:2024-10-28 07:42:59,973 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > +-------------------------------------+---------------------+------------+------------------+------ ----------+---------+----------------------------------------------------------------------------------------------------------------+ ... < t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanEvent | 4.7430033683776855 | | NodetoolDecommission | NodetoolDecommission | True | select pk,ck from scylla_bench.test where pk = 29 | < t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanReversedOrderEvent | 1.1897552013397217 | | NodetoolDecommission | NodetoolDecommission | True | select pk,ck from scylla_bench.test where pk = 955 and ck < 59720 order by ck asc BYPASS CACHE | < t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanEvent | 0.4158589839935303 | | NodetoolDecommission | NodetoolDecommission | True | select pk,ck from scylla_bench.test where pk = 955 and ck < 59720 BYPASS CACHE | < t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanReversedOrderEvent | 1.2938134670257568 | | None | None | True | select pk,ck from scylla_bench.test where pk = 1026 and ck < 163993 order by ck asc | < t:2024-10-28 10:44:46,103 f:operations_thread.py l:156 c:ScanOperationThread p:DEBUG > | FullPartitionScanEvent | 1.4889512062072754 | | None | None | True | select pk,ck from scylla_bench.test where pk = 1026 and ck < 163993@fruch , anything else to validate in addition?
The large partition run you are pointing to runs for 18 minutes, that far from being a proof for the effect of this change
@fruch , right, the first run failed on setup.. the next one (https://argus.scylladb.com/tests/scylla-cluster-tests/2b80deba-d8fc-4c5e-ba35-9607972de1eb) ran for 8 hours, which should be sufficient to verify the expected results of full scan.
BTW a side note is that the above run seems to experience issues with the full-partition-scan reversed query mode. So it may be a good opportunity for a followup fix, once this PR is merged. The logs shows stuff like:
< t:2024-10-28 12:32:25,769 f:scan_operation_thread.py l:328 c:FullPartitionScanOperation p:DEBUG > Randomly formed normal query is: select pk,ck from scylla_bench.test where pk = 19 and ck > 37116 BYPASS CACHE
< t:2024-10-28 12:32:25,769 f:scan_operation_thread.py l:329 c:FullPartitionScanOperation p:DEBUG > [scan: 114, type: gt] Randomly formed reversed query is: select pk,ck from scylla_bench.test where pk = 19 and ck > 37116 order by ck asc limit 175854 BYPASS CACHE
< t:2024-10-28 12:32:25,851 f:scan_operation_thread.py l:352 c:FullPartitionScanOperation p:DEBUG > Will run command "select pk,ck from scylla_bench.test where pk = 19 and ck > 37116 order by ck asc limit 175854 BYPASS CACHE"
< t:2024-10-28 12:32:25,852 f:scan_operation_thread.py l:338 c:FullPartitionScanOperation p:DEBUG > Will fetch up to 0 result pages.."
< t:2024-10-28 12:32:25,962 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:26,071 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:26,181 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:26,282 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:26,373 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:26,474 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:26,567 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:26,661 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:26,765 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:26,854 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:26,955 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:27,052 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:27,144 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:27,237 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:27,687 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:27,800 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:27,830 f:scan_operation_thread.py l:346 c:FullPartitionScanOperation p:DEBUG > Fetched a total of 0 pages
< t:2024-10-28 12:32:27,858 f:scan_operation_thread.py l:430 c:FullPartitionScanOperation p:DEBUG > Average gt scans duration of 15 executions is: 206.56503701210022
< t:2024-10-28 12:32:27,858 f:scan_operation_thread.py l:433 c:FullPartitionScanOperation p:DEBUG > Executing the normal query: select pk,ck from scylla_bench.test where pk = 19 and ck > 37116 BYPASS CACHE
< t:2024-10-28 12:32:27,983 f:scan_operation_thread.py l:352 c:FullPartitionScanOperation p:DEBUG > Will run command "select pk,ck from scylla_bench.test where pk = 19 and ck > 37116 BYPASS CACHE"
< t:2024-10-28 12:32:27,984 f:scan_operation_thread.py l:338 c:FullPartitionScanOperation p:DEBUG > Will fetch up to 0 result pages.."
< t:2024-10-28 12:32:28,086 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:28,205 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:28,325 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:28,442 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:28,544 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:28,643 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:28,758 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:28,858 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:28,957 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:29,061 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:29,160 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:29,265 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:29,367 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:29,467 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:29,583 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:29,689 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:32:29,728 f:scan_operation_thread.py l:346 c:FullPartitionScanOperation p:DEBUG > Fetched a total of 0 pages
< t:2024-10-28 12:32:29,804 f:scan_operation_thread.py l:384 c:FullPartitionScanOperation p:DEBUG > Comparing scan queries output files by: diff -y --suppress-common-lines /tmp/tmpczc7tjix /tmp/tmp5x8slhip
< t:2024-10-28 12:32:30,910 f:scan_operation_thread.py l:395 c:FullPartitionScanOperation p:WARNING > Normal and reversed queries output differs: output results in /home/ubuntu/sct-results/20241028-071611-231345/fullscans/partition_range_scan_diff_2024_10_28-12_32_29.log
< t:2024-10-28 12:32:30,923 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > ls -alh /tmp/tmpczc7tjix /tmp/tmp5x8slhip command output is:
< t:2024-10-28 12:32:30,923 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > -rw------- 1 ubuntu ubuntu 0 Oct 28 12:27 /tmp/tmp5x8slhip
< t:2024-10-28 12:32:30,923 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > -rw------- 1 ubuntu ubuntu 1.5M Oct 28 12:32 /tmp/tmpczc7tjix
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > head /tmp/tmpczc7tjix /tmp/tmp5x8slhip command output is:
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > ==> /tmp/tmpczc7tjix <==
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 19199999
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 19199998
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 19199997
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 19199996
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 19199995
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 19199994
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 19199993
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 19199992
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 19199991
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 19199990
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG >
< t:2024-10-28 12:32:30,937 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > ==> /tmp/tmp5x8slhip <==
< t:2024-10-28 12:37:32,340 f:scan_operation_thread.py l:328 c:FullPartitionScanOperation p:DEBUG > Randomly formed normal query is: select pk,ck from scylla_bench.test where pk = 1968
< t:2024-10-28 12:37:32,340 f:scan_operation_thread.py l:329 c:FullPartitionScanOperation p:DEBUG > [scan: 116, type: no_filter] Randomly formed reversed query is: select pk,ck from scylla_bench.test where pk = 1968 order by ck asc
< t:2024-10-28 12:37:32,429 f:scan_operation_thread.py l:352 c:FullPartitionScanOperation p:DEBUG > Will run command "select pk,ck from scylla_bench.test where pk = 1968 order by ck asc "
< t:2024-10-28 12:37:32,429 f:scan_operation_thread.py l:338 c:FullPartitionScanOperation p:DEBUG > Will fetch up to 100 result pages.."
< t:2024-10-28 12:37:32,638 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:37:32,825 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 1
< t:2024-10-28 12:37:33,015 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 2
< t:2024-10-28 12:37:33,207 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 3
< t:2024-10-28 12:37:33,386 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 4
< t:2024-10-28 12:37:33,586 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 5
< t:2024-10-28 12:37:33,779 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 6
< t:2024-10-28 12:37:34,437 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 7
< t:2024-10-28 12:37:34,639 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 8
< t:2024-10-28 12:37:34,832 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 9
< t:2024-10-28 12:37:35,010 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 10
< t:2024-10-28 12:37:35,185 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 11
< t:2024-10-28 12:37:35,359 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 12
< t:2024-10-28 12:37:35,543 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 13
< t:2024-10-28 12:37:35,724 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 14
< t:2024-10-28 12:37:35,904 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 15
< t:2024-10-28 12:37:36,089 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 16
< t:2024-10-28 12:37:36,277 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 17
< t:2024-10-28 12:37:36,484 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 18
< t:2024-10-28 12:37:36,678 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 19
< t:2024-10-28 12:37:36,685 f:scan_operation_thread.py l:346 c:FullPartitionScanOperation p:DEBUG > Fetched a total of 20 pages
< t:2024-10-28 12:37:36,719 f:scan_operation_thread.py l:430 c:FullPartitionScanOperation p:DEBUG > Average no_filter scans duration of 13 executions is: 208.71172264906076
< t:2024-10-28 12:37:36,720 f:scan_operation_thread.py l:433 c:FullPartitionScanOperation p:DEBUG > Executing the normal query: select pk,ck from scylla_bench.test where pk = 1968
< t:2024-10-28 12:37:36,833 f:scan_operation_thread.py l:352 c:FullPartitionScanOperation p:DEBUG > Will run command "select pk,ck from scylla_bench.test where pk = 1968 "
< t:2024-10-28 12:37:36,834 f:scan_operation_thread.py l:338 c:FullPartitionScanOperation p:DEBUG > Will fetch up to 100 result pages.."
< t:2024-10-28 12:37:37,118 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:37:37,346 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 1
< t:2024-10-28 12:37:37,576 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 2
< t:2024-10-28 12:37:37,806 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 3
< t:2024-10-28 12:37:38,033 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 4
< t:2024-10-28 12:37:38,270 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 5
< t:2024-10-28 12:37:38,500 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 6
< t:2024-10-28 12:37:38,736 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 7
< t:2024-10-28 12:37:38,963 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 8
< t:2024-10-28 12:37:39,197 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 9
< t:2024-10-28 12:37:39,445 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 10
< t:2024-10-28 12:37:39,982 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 11
< t:2024-10-28 12:37:40,325 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 12
< t:2024-10-28 12:37:40,572 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 13
< t:2024-10-28 12:37:40,810 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 14
< t:2024-10-28 12:37:41,045 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 15
< t:2024-10-28 12:37:41,295 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 16
< t:2024-10-28 12:37:41,534 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 17
< t:2024-10-28 12:37:41,758 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 18
< t:2024-10-28 12:37:41,999 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 19
< t:2024-10-28 12:37:42,003 f:scan_operation_thread.py l:346 c:FullPartitionScanOperation p:DEBUG > Fetched a total of 20 pages
< t:2024-10-28 12:37:42,091 f:scan_operation_thread.py l:384 c:FullPartitionScanOperation p:DEBUG > Comparing scan queries output files by: diff -y --suppress-common-lines /tmp/tmpsxrx1q20 /tmp/tmpwgc1ixqa
< t:2024-10-28 12:37:51,059 f:scan_operation_thread.py l:395 c:FullPartitionScanOperation p:WARNING > Normal and reversed queries output differs: output results in /home/ubuntu/sct-results/20241028-071611-231345/fullscans/partition_range_scan_diff_2024_10_28-12_37_42.log
< t:2024-10-28 12:37:51,073 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > ls -alh /tmp/tmpsxrx1q20 /tmp/tmpwgc1ixqa command output is:
< t:2024-10-28 12:37:51,073 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > -rw------- 1 ubuntu ubuntu 4.0M Oct 28 12:37 /tmp/tmpsxrx1q20
< t:2024-10-28 12:37:51,073 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > -rw------- 1 ubuntu ubuntu 0 Oct 28 12:32 /tmp/tmpwgc1ixqa
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > head /tmp/tmpsxrx1q20 /tmp/tmpwgc1ixqa command output is:
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > ==> /tmp/tmpsxrx1q20 <==
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 1968199999
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 1968199998
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 1968199997
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 1968199996
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 1968199995
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 1968199994
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 1968199993
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 1968199992
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 1968199991
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 1968199990
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG >
< t:2024-10-28 12:37:51,087 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > ==> /tmp/tmpwgc1ixqa <==
< t:2024-10-28 12:42:52,383 f:scan_operation_thread.py l:328 c:FullPartitionScanOperation p:DEBUG > Randomly formed normal query is: select pk,ck from scylla_bench.test where pk = 437 and ck < 178089 and ck > 122918
< t:2024-10-28 12:42:52,383 f:scan_operation_thread.py l:329 c:FullPartitionScanOperation p:DEBUG > [scan: 118, type: lt_and_gt] Randomly formed reversed query is: select pk,ck from scylla_bench.test where pk = 437 and ck < 178089 and ck > 122918 order by ck asc limit 46728
< t:2024-10-28 12:42:52,466 f:scan_operation_thread.py l:352 c:FullPartitionScanOperation p:DEBUG > Will run command "select pk,ck from scylla_bench.test where pk = 437 and ck < 178089 and ck > 122918 order by ck asc limit 46728 "
< t:2024-10-28 12:42:52,466 f:scan_operation_thread.py l:338 c:FullPartitionScanOperation p:DEBUG > Will fetch up to 100 result pages.."
< t:2024-10-28 12:42:52,820 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:42:53,114 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 1
< t:2024-10-28 12:42:53,357 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 2
< t:2024-10-28 12:42:53,602 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 3
< t:2024-10-28 12:42:53,776 f:scan_operation_thread.py l:346 c:FullPartitionScanOperation p:DEBUG > Fetched a total of 4 pages
< t:2024-10-28 12:42:53,809 f:scan_operation_thread.py l:430 c:FullPartitionScanOperation p:DEBUG > Average lt_and_gt scans duration of 17 executions is: 233.56022893681245
< t:2024-10-28 12:42:53,809 f:scan_operation_thread.py l:433 c:FullPartitionScanOperation p:DEBUG > Executing the normal query: select pk,ck from scylla_bench.test where pk = 437 and ck < 178089 and ck > 122918
< t:2024-10-28 12:42:53,919 f:scan_operation_thread.py l:352 c:FullPartitionScanOperation p:DEBUG > Will run command "select pk,ck from scylla_bench.test where pk = 437 and ck < 178089 and ck > 122918 "
< t:2024-10-28 12:42:53,919 f:scan_operation_thread.py l:338 c:FullPartitionScanOperation p:DEBUG > Will fetch up to 100 result pages.."
< t:2024-10-28 12:42:53,988 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:42:54,059 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 1
< t:2024-10-28 12:42:54,131 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 2
< t:2024-10-28 12:42:54,202 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 3
< t:2024-10-28 12:42:54,448 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 4
< t:2024-10-28 12:42:54,596 f:scan_operation_thread.py l:346 c:FullPartitionScanOperation p:DEBUG > Fetched a total of 5 pages
< t:2024-10-28 12:42:54,660 f:scan_operation_thread.py l:384 c:FullPartitionScanOperation p:DEBUG > Comparing scan queries output files by: diff -y --suppress-common-lines /tmp/tmp6h_exdfn /tmp/tmpt77xta5n
< t:2024-10-28 12:42:54,784 f:scan_operation_thread.py l:395 c:FullPartitionScanOperation p:WARNING > Normal and reversed queries output differs: output results in /home/ubuntu/sct-results/20241028-071611-231345/fullscans/partition_range_scan_diff_2024_10_28-12_42_54.log
< t:2024-10-28 12:42:54,798 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > ls -alh /tmp/tmp6h_exdfn /tmp/tmpt77xta5n command output is:
< t:2024-10-28 12:42:54,798 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > -rw------- 1 ubuntu ubuntu 457K Oct 28 12:42 /tmp/tmp6h_exdfn
< t:2024-10-28 12:42:54,798 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > -rw------- 1 ubuntu ubuntu 0 Oct 28 12:37 /tmp/tmpt77xta5n
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > head /tmp/tmp6h_exdfn /tmp/tmpt77xta5n command output is:
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > ==> /tmp/tmp6h_exdfn <==
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 437178088
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 437178087
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 437178086
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 437178085
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 437178084
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 437178083
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 437178082
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 437178081
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 437178080
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > 437178079
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG >
< t:2024-10-28 12:42:54,811 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > ==> /tmp/tmpt77xta5n <==
< t:2024-10-28 12:47:56,293 f:scan_operation_thread.py l:328 c:FullPartitionScanOperation p:DEBUG > Randomly formed normal query is: select pk,ck from scylla_bench.test where pk = 1591 BYPASS CACHE
< t:2024-10-28 12:47:56,293 f:scan_operation_thread.py l:329 c:FullPartitionScanOperation p:DEBUG > [scan: 120, type: no_filter] Randomly formed reversed query is: select pk,ck from scylla_bench.test where pk = 1591 order by ck asc BYPASS CACHE
< t:2024-10-28 12:47:56,390 f:scan_operation_thread.py l:352 c:FullPartitionScanOperation p:DEBUG > Will run command "select pk,ck from scylla_bench.test where pk = 1591 order by ck asc BYPASS CACHE"
< t:2024-10-28 12:47:56,391 f:scan_operation_thread.py l:338 c:FullPartitionScanOperation p:DEBUG > Will fetch up to 100 result pages.."
< t:2024-10-28 12:47:56,517 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:47:56,632 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 1
< t:2024-10-28 12:47:56,733 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 2
< t:2024-10-28 12:47:56,832 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 3
< t:2024-10-28 12:47:56,931 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 4
< t:2024-10-28 12:47:57,029 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 5
< t:2024-10-28 12:47:57,133 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 6
< t:2024-10-28 12:47:57,231 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 7
< t:2024-10-28 12:47:57,329 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 8
< t:2024-10-28 12:47:57,431 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 9
< t:2024-10-28 12:47:57,535 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 10
< t:2024-10-28 12:47:57,645 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 11
< t:2024-10-28 12:47:57,745 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 12
< t:2024-10-28 12:47:58,235 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 13
< t:2024-10-28 12:47:58,351 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 14
< t:2024-10-28 12:47:58,458 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 15
< t:2024-10-28 12:47:58,560 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 16
< t:2024-10-28 12:47:58,662 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 17
< t:2024-10-28 12:47:58,756 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 18
< t:2024-10-28 12:47:58,855 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 19
< t:2024-10-28 12:47:58,859 f:scan_operation_thread.py l:346 c:FullPartitionScanOperation p:DEBUG > Fetched a total of 20 pages
< t:2024-10-28 12:47:58,890 f:scan_operation_thread.py l:430 c:FullPartitionScanOperation p:DEBUG > Average no_filter scans duration of 14 executions is: 219.9979032278061
< t:2024-10-28 12:47:58,890 f:scan_operation_thread.py l:433 c:FullPartitionScanOperation p:DEBUG > Executing the normal query: select pk,ck from scylla_bench.test where pk = 1591 BYPASS CACHE
< t:2024-10-28 12:47:58,967 f:scan_operation_thread.py l:352 c:FullPartitionScanOperation p:DEBUG > Will run command "select pk,ck from scylla_bench.test where pk = 1591 BYPASS CACHE"
< t:2024-10-28 12:47:58,967 f:scan_operation_thread.py l:338 c:FullPartitionScanOperation p:DEBUG > Will fetch up to 100 result pages.."
< t:2024-10-28 12:47:59,072 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 0
< t:2024-10-28 12:47:59,178 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 1
< t:2024-10-28 12:47:59,279 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 2
< t:2024-10-28 12:47:59,379 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 3
< t:2024-10-28 12:47:59,483 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 4
< t:2024-10-28 12:47:59,583 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 5
< t:2024-10-28 12:47:59,683 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 6
< t:2024-10-28 12:47:59,789 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 7
< t:2024-10-28 12:47:59,884 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 8
< t:2024-10-28 12:47:59,983 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 9
< t:2024-10-28 12:48:00,085 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 10
< t:2024-10-28 12:48:00,185 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 11
< t:2024-10-28 12:48:00,290 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 12
< t:2024-10-28 12:48:00,388 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 13
< t:2024-10-28 12:48:00,795 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 14
< t:2024-10-28 12:48:00,904 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 15
< t:2024-10-28 12:48:01,003 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 16
< t:2024-10-28 12:48:01,111 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 17
< t:2024-10-28 12:48:01,214 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 18
< t:2024-10-28 12:48:01,314 f:scan_operation_thread.py l:574 c:PagedResultHandler p:DEBUG > Will fetch the next page: 19
< t:2024-10-28 12:48:01,319 f:scan_operation_thread.py l:346 c:FullPartitionScanOperation p:DEBUG > Fetched a total of 20 pages
< t:2024-10-28 12:48:01,402 f:scan_operation_thread.py l:384 c:FullPartitionScanOperation p:DEBUG > Comparing scan queries output files by: diff -y --suppress-common-lines /tmp/tmpsrnpphfq /tmp/tmpfgnbfumo
< t:2024-10-28 12:48:10,217 f:scan_operation_thread.py l:395 c:FullPartitionScanOperation p:WARNING > Normal and reversed queries output differs: output results in /home/ubuntu/sct-results/20241028-071611-231345/fullscans/partition_range_scan_diff_2024_10_28-12_48_01.log
< t:2024-10-28 12:48:10,231 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > ls -alh /tmp/tmpsrnpphfq /tmp/tmpfgnbfumo command output is:
< t:2024-10-28 12:48:10,231 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > -rw------- 1 ubuntu ubuntu 0 Oct 28 12:42 /tmp/tmpfgnbfumo
< t:2024-10-28 12:48:10,231 f:scan_operation_thread.py l:402 c:FullPartitionScanOperation p:DEBUG > -rw------- 1 ubuntu ubuntu 4.0M Oct 28 12:48 /tmp/tmpsrnpphfq
it could be opened separately in a new SCT issue (have to confirm no scylla issue as well).