Uploaded image for project: 'Apache Cassandra'
  1. Apache Cassandra
  2. CASSANDRA-5975

Filtering on Secondary Index Takes a Long Time Even with Limit 1, Trace Log Filled with Looping Messages

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Normal
    • Resolution: Fixed
    • 1.2.10, 2.0.1
    • Feature/2i Index
    • None
    • Ubuntu, Single Node

    • Normal

    Description

      After creating a table with 300,000 keys. Attempting to filter on a column with a secondary index causes an rpc timeout. Using a limit statement does not alleviate the problem. The tracing log appears to be filled with the same set of messages repeated over and over until the query times out.

      The data was created with the attached script and the command

      python create_data.py --num-keys 300000 --num-columns 50 --keyspace 'ks' --columnfamily cf_300000_keys_50_cols --create-index y -v 3
      

      The query causing the delay is

      select * from cf_300000_keys_50_cols where color = 'green' limit 1;
      

      An excerpt of the trace log

      Tracing session: cedbead0-14d7-11e3-915e-999f6c86239a
      
       activity                                                                          | timestamp    | source       | source_elapsed
      -----------------------------------------------------------------------------------+--------------+--------------+----------------
                                                                      execute_cql3_query | 20:31:27,230 | 10.196.1.106 |              0
             Parsing select * from cf_300000_keys_50_cols where color = 'green' limit 1; | 20:31:27,230 | 10.196.1.106 |             31
                                                                      Peparing statement | 20:31:27,230 | 10.196.1.106 |            219
                                                           Determining replicas to query | 20:31:27,230 | 10.196.1.106 |            563
       Executing indexed scan for [min(-9223372036854775808), min(-9223372036854775808)] | 20:31:27,232 | 10.196.1.106 |           1816
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,232 | 10.196.1.106 |           2036
                                                            Acquiring sstable references | 20:31:27,232 | 10.196.1.106 |           2201
                                                             Merging memtable tombstones | 20:31:27,232 | 10.196.1.106 |           2345
                                                             Key cache hit for sstable 3 | 20:31:27,232 | 10.196.1.106 |           2493
                                             Seeking to partition beginning in data file | 20:31:27,232 | 10.196.1.106 |           2555
                                                             Key cache hit for sstable 1 | 20:31:27,234 | 10.196.1.106 |           3742
                                             Seeking to partition beginning in data file | 20:31:27,234 | 10.196.1.106 |           3806
                                              Merging data from memtables and 2 sstables | 20:31:27,236 | 10.196.1.106 |           5805
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,236 | 10.196.1.106 |           5977
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,236 | 10.196.1.106 |           6166
                                                            Acquiring sstable references | 20:31:27,236 | 10.196.1.106 |           6319
                                                             Merging memtable tombstones | 20:31:27,236 | 10.196.1.106 |           6382
                                                             Key cache hit for sstable 3 | 20:31:27,236 | 10.196.1.106 |           6421
                                             Seeking to partition beginning in data file | 20:31:27,236 | 10.196.1.106 |           6423
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,237 | 10.196.1.106 |           7060
                                                  Bloom filter allows skipping sstable 1 | 20:31:27,237 | 10.196.1.106 |           7218
                                              Merging data from memtables and 1 sstables | 20:31:27,237 | 10.196.1.106 |           7358
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,238 | 10.196.1.106 |           7644
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,238 | 10.196.1.106 |           7855
                                                            Acquiring sstable references | 20:31:27,238 | 10.196.1.106 |           8008
                                                             Merging memtable tombstones | 20:31:27,238 | 10.196.1.106 |           8072
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,238 | 10.196.1.106 |           8225
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,238 | 10.196.1.106 |           8284
                                                             Key cache hit for sstable 1 | 20:31:27,238 | 10.196.1.106 |           8367
                                             Seeking to partition beginning in data file | 20:31:27,238 | 10.196.1.106 |           8468
                                              Merging data from memtables and 1 sstables | 20:31:27,239 | 10.196.1.106 |           8968
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,239 | 10.196.1.106 |           9234
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,239 | 10.196.1.106 |           9405
                                                            Acquiring sstable references | 20:31:27,239 | 10.196.1.106 |           9547
                                                             Merging memtable tombstones | 20:31:27,240 | 10.196.1.106 |           9608
                                                             Key cache hit for sstable 3 | 20:31:27,240 | 10.196.1.106 |           9700
                                       Seeking to partition indexed section in data file | 20:31:27,240 | 10.196.1.106 |           9884
                                                             Key cache hit for sstable 1 | 20:31:27,240 | 10.196.1.106 |          10005
                                       Seeking to partition indexed section in data file | 20:31:27,240 | 10.196.1.106 |          10175
                                              Merging data from memtables and 2 sstables | 20:31:27,240 | 10.196.1.106 |          10323
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,249 | 10.196.1.106 |          19358
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,249 | 10.196.1.106 |          19516
                                                            Acquiring sstable references | 20:31:27,249 | 10.196.1.106 |          19580
                                                             Merging memtable tombstones | 20:31:27,250 | 10.196.1.106 |          19670
                                                             Key cache hit for sstable 3 | 20:31:27,250 | 10.196.1.106 |          19765
                                             Seeking to partition beginning in data file | 20:31:27,250 | 10.196.1.106 |          19884
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,250 | 10.196.1.106 |          20357
                                                  Bloom filter allows skipping sstable 1 | 20:31:27,250 | 10.196.1.106 |          20514
                                              Merging data from memtables and 1 sstables | 20:31:27,250 | 10.196.1.106 |          20576
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,251 | 10.196.1.106 |          20864
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,251 | 10.196.1.106 |          21072
                                                            Acquiring sstable references | 20:31:27,251 | 10.196.1.106 |          21137
                                                             Merging memtable tombstones | 20:31:27,251 | 10.196.1.106 |          21315
                                                             Key cache hit for sstable 3 | 20:31:27,251 | 10.196.1.106 |          21461
                                       Seeking to partition indexed section in data file | 20:31:27,252 | 10.196.1.106 |          21599
                                                             Key cache hit for sstable 1 | 20:31:27,252 | 10.196.1.106 |          21761
                                       Seeking to partition indexed section in data file | 20:31:27,252 | 10.196.1.106 |          21909
                                              Merging data from memtables and 2 sstables | 20:31:27,252 | 10.196.1.106 |          21977
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,261 | 10.196.1.106 |          30678
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,261 | 10.196.1.106 |          31153
                                                            Acquiring sstable references | 20:31:27,261 | 10.196.1.106 |          31156
                                                             Merging memtable tombstones | 20:31:27,261 | 10.196.1.106 |          31221
                                                             Key cache hit for sstable 3 | 20:31:27,261 | 10.196.1.106 |          31259
                                             Seeking to partition beginning in data file | 20:31:27,261 | 10.196.1.106 |          31261
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,264 | 10.196.1.106 |          33808
                                                  Bloom filter allows skipping sstable 1 | 20:31:27,264 | 10.196.1.106 |          33875
                                              Merging data from memtables and 1 sstables | 20:31:27,264 | 10.196.1.106 |          33877
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,264 | 10.196.1.106 |          34313
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,264 | 10.196.1.106 |          34488
                                                            Acquiring sstable references | 20:31:27,264 | 10.196.1.106 |          34552
                                                             Merging memtable tombstones | 20:31:27,265 | 10.196.1.106 |          34642
                                                             Key cache hit for sstable 3 | 20:31:27,265 | 10.196.1.106 |          34792
                                       Seeking to partition indexed section in data file | 20:31:27,265 | 10.196.1.106 |          34851
                                                             Key cache hit for sstable 1 | 20:31:27,265 | 10.196.1.106 |          35007
                                       Seeking to partition indexed section in data file | 20:31:27,265 | 10.196.1.106 |          35066
                                              Merging data from memtables and 2 sstables | 20:31:27,265 | 10.196.1.106 |          35272
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,274 | 10.196.1.106 |          44333
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,274 | 10.196.1.106 |          44529
                                                            Acquiring sstable references | 20:31:27,275 | 10.196.1.106 |          44686
                                                             Merging memtable tombstones | 20:31:27,275 | 10.196.1.106 |          44752
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,275 | 10.196.1.106 |          44766
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,275 | 10.196.1.106 |          45021
                                                             Key cache hit for sstable 1 | 20:31:27,275 | 10.196.1.106 |          45163
                                             Seeking to partition beginning in data file | 20:31:27,275 | 10.196.1.106 |          45241
                                              Merging data from memtables and 1 sstables | 20:31:27,276 | 10.196.1.106 |          45719
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,276 | 10.196.1.106 |          45985
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,276 | 10.196.1.106 |          46171
                                                            Acquiring sstable references | 20:31:27,276 | 10.196.1.106 |          46235
                                                             Merging memtable tombstones | 20:31:27,276 | 10.196.1.106 |          46325
                                                             Key cache hit for sstable 3 | 20:31:27,276 | 10.196.1.106 |          46501
                                       Seeking to partition indexed section in data file | 20:31:27,276 | 10.196.1.106 |          46561
                                                             Key cache hit for sstable 1 | 20:31:27,277 | 10.196.1.106 |          46652
                                       Seeking to partition indexed section in data file | 20:31:27,277 | 10.196.1.106 |          46853
                                              Merging data from memtables and 2 sstables | 20:31:27,277 | 10.196.1.106 |          46922
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,286 | 10.196.1.106 |          56025
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,286 | 10.196.1.106 |          56198
                                                            Acquiring sstable references | 20:31:27,286 | 10.196.1.106 |          56264
                                                             Merging memtable tombstones | 20:31:27,286 | 10.196.1.106 |          56352
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,286 | 10.196.1.106 |          56439
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,286 | 10.196.1.106 |          56543
                                                             Key cache hit for sstable 1 | 20:31:27,287 | 10.196.1.106 |          56631
                                             Seeking to partition beginning in data file | 20:31:27,287 | 10.196.1.106 |          56634
                                              Merging data from memtables and 1 sstables | 20:31:27,287 | 10.196.1.106 |          57194
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,287 | 10.196.1.106 |          57494
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,288 | 10.196.1.106 |          57672
                                                            Acquiring sstable references | 20:31:27,288 | 10.196.1.106 |          57736
                                                             Merging memtable tombstones | 20:31:27,288 | 10.196.1.106 |          57922
                                                             Key cache hit for sstable 3 | 20:31:27,288 | 10.196.1.106 |          58047
                                       Seeking to partition indexed section in data file | 20:31:27,288 | 10.196.1.106 |          58200
                                                             Key cache hit for sstable 1 | 20:31:27,288 | 10.196.1.106 |          58351
                                       Seeking to partition indexed section in data file | 20:31:27,289 | 10.196.1.106 |          58783
                                              Merging data from memtables and 2 sstables | 20:31:27,289 | 10.196.1.106 |          58790
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,299 | 10.196.1.106 |          69455
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,300 | 10.196.1.106 |          69641
                                                            Acquiring sstable references | 20:31:27,300 | 10.196.1.106 |          69707
                                                             Merging memtable tombstones | 20:31:27,300 | 10.196.1.106 |          69713
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,300 | 10.196.1.106 |          69806
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,300 | 10.196.1.106 |          69904
                                                             Key cache hit for sstable 1 | 20:31:27,300 | 10.196.1.106 |          69994
                                             Seeking to partition beginning in data file | 20:31:27,300 | 10.196.1.106 |          70297
                                              Merging data from memtables and 1 sstables | 20:31:27,301 | 10.196.1.106 |          70778
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,301 | 10.196.1.106 |          71044
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,301 | 10.196.1.106 |          71271
                                                            Acquiring sstable references | 20:31:27,301 | 10.196.1.106 |          71335
                                                             Merging memtable tombstones | 20:31:27,301 | 10.196.1.106 |          71424
                                                             Key cache hit for sstable 3 | 20:31:27,301 | 10.196.1.106 |          71583
                                       Seeking to partition indexed section in data file | 20:31:27,302 | 10.196.1.106 |          71645
                                                             Key cache hit for sstable 1 | 20:31:27,302 | 10.196.1.106 |          71882
                                       Seeking to partition indexed section in data file | 20:31:27,302 | 10.196.1.106 |          71940
                                              Merging data from memtables and 2 sstables | 20:31:27,302 | 10.196.1.106 |          72030
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,311 | 10.196.1.106 |          81217
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,311 | 10.196.1.106 |          81369
                                                            Acquiring sstable references | 20:31:27,311 | 10.196.1.106 |          81515
                                                             Merging memtable tombstones | 20:31:27,312 | 10.196.1.106 |          81661
                                                             Key cache hit for sstable 3 | 20:31:27,312 | 10.196.1.106 |          81812
                                             Seeking to partition beginning in data file | 20:31:27,312 | 10.196.1.106 |          81873
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,312 | 10.196.1.106 |          82409
                                                  Bloom filter allows skipping sstable 1 | 20:31:27,312 | 10.196.1.106 |          82479
                                              Merging data from memtables and 1 sstables | 20:31:27,312 | 10.196.1.106 |          82481
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,313 | 10.196.1.106 |          82860
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,313 | 10.196.1.106 |          83035
                                                            Acquiring sstable references | 20:31:27,313 | 10.196.1.106 |          83099
                                                             Merging memtable tombstones | 20:31:27,313 | 10.196.1.106 |          83217
                                                             Key cache hit for sstable 3 | 20:31:27,313 | 10.196.1.106 |          83307
                                       Seeking to partition indexed section in data file | 20:31:27,313 | 10.196.1.106 |          83410
                                                             Key cache hit for sstable 1 | 20:31:27,314 | 10.196.1.106 |          83588
                                       Seeking to partition indexed section in data file | 20:31:27,314 | 10.196.1.106 |          83652
                                              Merging data from memtables and 2 sstables | 20:31:27,314 | 10.196.1.106 |          83742
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,338 | 10.196.1.106 |         108372
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,345 | 10.196.1.106 |         115180
                                                            Acquiring sstable references | 20:31:27,345 | 10.196.1.106 |         115183
                                                             Merging memtable tombstones | 20:31:27,345 | 10.196.1.106 |         115188
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,345 | 10.196.1.106 |         115194
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,345 | 10.196.1.106 |         115197
                                                             Key cache hit for sstable 1 | 20:31:27,345 | 10.196.1.106 |         115203
                                             Seeking to partition beginning in data file | 20:31:27,345 | 10.196.1.106 |         115205
                                              Merging data from memtables and 1 sstables | 20:31:27,347 | 10.196.1.106 |         116821
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,348 | 10.196.1.106 |         117631
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,348 | 10.196.1.106 |         117997
                                                            Acquiring sstable references | 20:31:27,348 | 10.196.1.106 |         118000
                                                             Merging memtable tombstones | 20:31:27,348 | 10.196.1.106 |         118007
                                                             Key cache hit for sstable 3 | 20:31:27,348 | 10.196.1.106 |         118014
                                       Seeking to partition indexed section in data file | 20:31:27,348 | 10.196.1.106 |         118017
                                                             Key cache hit for sstable 1 | 20:31:27,348 | 10.196.1.106 |         118023
                                       Seeking to partition indexed section in data file | 20:31:27,348 | 10.196.1.106 |         118025
                                              Merging data from memtables and 2 sstables | 20:31:27,348 | 10.196.1.106 |         118030
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,356 | 10.196.1.106 |         126375
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,356 | 10.196.1.106 |         126418
                                                            Acquiring sstable references | 20:31:27,356 | 10.196.1.106 |         126421
                                                             Merging memtable tombstones | 20:31:27,356 | 10.196.1.106 |         126427
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,357 | 10.196.1.106 |         126695
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,357 | 10.196.1.106 |         126699
                                                             Key cache hit for sstable 1 | 20:31:27,357 | 10.196.1.106 |         126705
                                             Seeking to partition beginning in data file | 20:31:27,357 | 10.196.1.106 |         126708
                                              Merging data from memtables and 1 sstables | 20:31:27,357 | 10.196.1.106 |         127265
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,357 | 10.196.1.106 |         127519
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,358 | 10.196.1.106 |         127686
                                                            Acquiring sstable references | 20:31:27,358 | 10.196.1.106 |         127694
                                                             Merging memtable tombstones | 20:31:27,358 | 10.196.1.106 |         127700
                                                             Key cache hit for sstable 3 | 20:31:27,358 | 10.196.1.106 |         127708
                                       Seeking to partition indexed section in data file | 20:31:27,358 | 10.196.1.106 |         127710
                                                             Key cache hit for sstable 1 | 20:31:27,358 | 10.196.1.106 |         127716
                                       Seeking to partition indexed section in data file | 20:31:27,358 | 10.196.1.106 |         127718
                                              Merging data from memtables and 2 sstables | 20:31:27,358 | 10.196.1.106 |         127722
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,366 | 10.196.1.106 |         135976
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,366 | 10.196.1.106 |         136018
                                                            Acquiring sstable references | 20:31:27,366 | 10.196.1.106 |         136020
                                                             Merging memtable tombstones | 20:31:27,366 | 10.196.1.106 |         136026
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,366 | 10.196.1.106 |         136032
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,366 | 10.196.1.106 |         136035
                                                             Key cache hit for sstable 1 | 20:31:27,366 | 10.196.1.106 |         136040
                                             Seeking to partition beginning in data file | 20:31:27,366 | 10.196.1.106 |         136043
                                              Merging data from memtables and 1 sstables | 20:31:27,367 | 10.196.1.106 |         136852
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,367 | 10.196.1.106 |         137046
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,367 | 10.196.1.106 |         137154
                                                            Acquiring sstable references | 20:31:27,367 | 10.196.1.106 |         137159
                                                             Merging memtable tombstones | 20:31:27,367 | 10.196.1.106 |         137165
                                                             Key cache hit for sstable 3 | 20:31:27,367 | 10.196.1.106 |         137172
                                       Seeking to partition indexed section in data file | 20:31:27,367 | 10.196.1.106 |         137175
                                                             Key cache hit for sstable 1 | 20:31:27,367 | 10.196.1.106 |         137181
                                       Seeking to partition indexed section in data file | 20:31:27,367 | 10.196.1.106 |         137183
                                              Merging data from memtables and 2 sstables | 20:31:27,367 | 10.196.1.106 |         137187
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,375 | 10.196.1.106 |         145161
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,375 | 10.196.1.106 |         145195
                                                            Acquiring sstable references | 20:31:27,375 | 10.196.1.106 |         145198
                                                             Merging memtable tombstones | 20:31:27,375 | 10.196.1.106 |         145203
                                                             Key cache hit for sstable 3 | 20:31:27,375 | 10.196.1.106 |         145212
                                             Seeking to partition beginning in data file | 20:31:27,375 | 10.196.1.106 |         145214
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,376 | 10.196.1.106 |         146059
                                                  Bloom filter allows skipping sstable 1 | 20:31:27,376 | 10.196.1.106 |         146063
                                              Merging data from memtables and 1 sstables | 20:31:27,376 | 10.196.1.106 |         146066
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,376 | 10.196.1.106 |         146295
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,376 | 10.196.1.106 |         146416
                                                            Acquiring sstable references | 20:31:27,376 | 10.196.1.106 |         146419
                                                             Merging memtable tombstones | 20:31:27,376 | 10.196.1.106 |         146425
                                                             Key cache hit for sstable 3 | 20:31:27,376 | 10.196.1.106 |         146433
                                       Seeking to partition indexed section in data file | 20:31:27,376 | 10.196.1.106 |         146435
                                                             Key cache hit for sstable 1 | 20:31:27,376 | 10.196.1.106 |         146441
                                       Seeking to partition indexed section in data file | 20:31:27,376 | 10.196.1.106 |         146443
                                              Merging data from memtables and 2 sstables | 20:31:27,376 | 10.196.1.106 |         146447
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,384 | 10.196.1.106 |         153664
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,384 | 10.196.1.106 |         153708
                                                            Acquiring sstable references | 20:31:27,384 | 10.196.1.106 |         153711
                                                             Merging memtable tombstones | 20:31:27,384 | 10.196.1.106 |         153717
                                                             Key cache hit for sstable 3 | 20:31:27,384 | 10.196.1.106 |         153899
                                             Seeking to partition beginning in data file | 20:31:27,384 | 10.196.1.106 |         153902
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,384 | 10.196.1.106 |         154556
                                                  Bloom filter allows skipping sstable 1 | 20:31:27,384 | 10.196.1.106 |         154566
                                              Merging data from memtables and 1 sstables | 20:31:27,384 | 10.196.1.106 |         154568
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,385 | 10.196.1.106 |         155041
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,385 | 10.196.1.106 |         155112
                                                            Acquiring sstable references | 20:31:27,385 | 10.196.1.106 |         155156
                                                             Merging memtable tombstones | 20:31:27,385 | 10.196.1.106 |         155163
                                                             Key cache hit for sstable 3 | 20:31:27,385 | 10.196.1.106 |         155171
                                       Seeking to partition indexed section in data file | 20:31:27,385 | 10.196.1.106 |         155173
                                                             Key cache hit for sstable 1 | 20:31:27,385 | 10.196.1.106 |         155179
                                       Seeking to partition indexed section in data file | 20:31:27,385 | 10.196.1.106 |         155181
                                              Merging data from memtables and 2 sstables | 20:31:27,385 | 10.196.1.106 |         155185
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,393 | 10.196.1.106 |         163321
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,393 | 10.196.1.106 |         163365
                                                            Acquiring sstable references | 20:31:27,393 | 10.196.1.106 |         163367
                                                             Merging memtable tombstones | 20:31:27,393 | 10.196.1.106 |         163373
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,393 | 10.196.1.106 |         163379
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,393 | 10.196.1.106 |         163382
                                                             Key cache hit for sstable 1 | 20:31:27,393 | 10.196.1.106 |         163387
                                             Seeking to partition beginning in data file | 20:31:27,393 | 10.196.1.106 |         163389
                                              Merging data from memtables and 1 sstables | 20:31:27,394 | 10.196.1.106 |         164206
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,394 | 10.196.1.106 |         164397
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,394 | 10.196.1.106 |         164562
                                                            Acquiring sstable references | 20:31:27,394 | 10.196.1.106 |         164570
                                                             Merging memtable tombstones | 20:31:27,394 | 10.196.1.106 |         164576
                                                             Key cache hit for sstable 3 | 20:31:27,394 | 10.196.1.106 |         164584
                                       Seeking to partition indexed section in data file | 20:31:27,394 | 10.196.1.106 |         164587
                                                             Key cache hit for sstable 1 | 20:31:27,395 | 10.196.1.106 |         164593
                                       Seeking to partition indexed section in data file | 20:31:27,395 | 10.196.1.106 |         164595
                                              Merging data from memtables and 2 sstables | 20:31:27,395 | 10.196.1.106 |         164599
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,403 | 10.196.1.106 |         172818
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,403 | 10.196.1.106 |         172860
                                                            Acquiring sstable references | 20:31:27,403 | 10.196.1.106 |         172862
                                                             Merging memtable tombstones | 20:31:27,403 | 10.196.1.106 |         172868
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,403 | 10.196.1.106 |         172967
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,403 | 10.196.1.106 |         172971
                                                             Key cache hit for sstable 1 | 20:31:27,403 | 10.196.1.106 |         172979
                                             Seeking to partition beginning in data file | 20:31:27,403 | 10.196.1.106 |         172982
                                              Merging data from memtables and 1 sstables | 20:31:27,404 | 10.196.1.106 |         173735
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,404 | 10.196.1.106 |         173923
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,404 | 10.196.1.106 |         174088
                                                            Acquiring sstable references | 20:31:27,404 | 10.196.1.106 |         174096
                                                             Merging memtable tombstones | 20:31:27,404 | 10.196.1.106 |         174102
                                                             Key cache hit for sstable 3 | 20:31:27,404 | 10.196.1.106 |         174110
                                       Seeking to partition indexed section in data file | 20:31:27,404 | 10.196.1.106 |         174112
                                                             Key cache hit for sstable 1 | 20:31:27,404 | 10.196.1.106 |         174119
                                       Seeking to partition indexed section in data file | 20:31:27,404 | 10.196.1.106 |         174121
                                              Merging data from memtables and 2 sstables | 20:31:27,404 | 10.196.1.106 |         174124
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,414 | 10.196.1.106 |         183917
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,414 | 10.196.1.106 |         183959
                                                            Acquiring sstable references | 20:31:27,414 | 10.196.1.106 |         183961
                                                             Merging memtable tombstones | 20:31:27,414 | 10.196.1.106 |         183967
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,414 | 10.196.1.106 |         183973
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,414 | 10.196.1.106 |         183976
                                                             Key cache hit for sstable 1 | 20:31:27,414 | 10.196.1.106 |         183982
                                             Seeking to partition beginning in data file | 20:31:27,414 | 10.196.1.106 |         183984
                                              Merging data from memtables and 1 sstables | 20:31:27,415 | 10.196.1.106 |         184807
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,415 | 10.196.1.106 |         184994
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,415 | 10.196.1.106 |         185105
                                                            Acquiring sstable references | 20:31:27,415 | 10.196.1.106 |         185108
                                                             Merging memtable tombstones | 20:31:27,415 | 10.196.1.106 |         185114
                                                             Key cache hit for sstable 3 | 20:31:27,415 | 10.196.1.106 |         185134
                                       Seeking to partition indexed section in data file | 20:31:27,415 | 10.196.1.106 |         185136
                                                             Key cache hit for sstable 1 | 20:31:27,415 | 10.196.1.106 |         185142
                                       Seeking to partition indexed section in data file | 20:31:27,415 | 10.196.1.106 |         185144
                                              Merging data from memtables and 2 sstables | 20:31:27,415 | 10.196.1.106 |         185148
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,423 | 10.196.1.106 |         193586
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,424 | 10.196.1.106 |         193635
                                                            Acquiring sstable references | 20:31:27,424 | 10.196.1.106 |         193638
                                                             Merging memtable tombstones | 20:31:27,424 | 10.196.1.106 |         193643
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,424 | 10.196.1.106 |         193649
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,424 | 10.196.1.106 |         193652
                                                             Key cache hit for sstable 1 | 20:31:27,424 | 10.196.1.106 |         193657
                                             Seeking to partition beginning in data file | 20:31:27,424 | 10.196.1.106 |         193660
                                              Merging data from memtables and 1 sstables | 20:31:27,424 | 10.196.1.106 |         194274
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,424 | 10.196.1.106 |         194483
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,425 | 10.196.1.106 |         194597
                                                            Acquiring sstable references | 20:31:27,425 | 10.196.1.106 |         194605
                                                             Merging memtable tombstones | 20:31:27,425 | 10.196.1.106 |         194611
                                                             Key cache hit for sstable 3 | 20:31:27,425 | 10.196.1.106 |         194619
                                       Seeking to partition indexed section in data file | 20:31:27,425 | 10.196.1.106 |         194621
                                                             Key cache hit for sstable 1 | 20:31:27,425 | 10.196.1.106 |         194627
                                       Seeking to partition indexed section in data file | 20:31:27,425 | 10.196.1.106 |         194629
                                              Merging data from memtables and 2 sstables | 20:31:27,425 | 10.196.1.106 |         194633
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,433 | 10.196.1.106 |         203042
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,433 | 10.196.1.106 |         203084
                                                            Acquiring sstable references | 20:31:27,433 | 10.196.1.106 |         203086
                                                             Merging memtable tombstones | 20:31:27,433 | 10.196.1.106 |         203092
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,433 | 10.196.1.106 |         203097
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,433 | 10.196.1.106 |         203100
                                                             Key cache hit for sstable 1 | 20:31:27,433 | 10.196.1.106 |         203106
                                             Seeking to partition beginning in data file | 20:31:27,433 | 10.196.1.106 |         203108
                                              Merging data from memtables and 1 sstables | 20:31:27,434 | 10.196.1.106 |         203598
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,434 | 10.196.1.106 |         203942
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,434 | 10.196.1.106 |         204112
                                                            Acquiring sstable references | 20:31:27,434 | 10.196.1.106 |         204120
                                                             Merging memtable tombstones | 20:31:27,434 | 10.196.1.106 |         204126
                                                             Key cache hit for sstable 3 | 20:31:27,434 | 10.196.1.106 |         204134
                                       Seeking to partition indexed section in data file | 20:31:27,434 | 10.196.1.106 |         204136
                                                             Key cache hit for sstable 1 | 20:31:27,434 | 10.196.1.106 |         204142
                                       Seeking to partition indexed section in data file | 20:31:27,434 | 10.196.1.106 |         204144
                                              Merging data from memtables and 2 sstables | 20:31:27,434 | 10.196.1.106 |         204148
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,441 | 10.196.1.106 |         211397
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,441 | 10.196.1.106 |         211439
                                                            Acquiring sstable references | 20:31:27,441 | 10.196.1.106 |         211441
                                                             Merging memtable tombstones | 20:31:27,441 | 10.196.1.106 |         211447
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,442 | 10.196.1.106 |         211546
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,442 | 10.196.1.106 |         211732
                                                             Key cache hit for sstable 1 | 20:31:27,442 | 10.196.1.106 |         211737
                                             Seeking to partition beginning in data file | 20:31:27,442 | 10.196.1.106 |         211739
                                              Merging data from memtables and 1 sstables | 20:31:27,442 | 10.196.1.106 |         212484
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,443 | 10.196.1.106 |         212809
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,443 | 10.196.1.106 |         212918
                                                            Acquiring sstable references | 20:31:27,443 | 10.196.1.106 |         212921
                                                             Merging memtable tombstones | 20:31:27,443 | 10.196.1.106 |         212927
                                                             Key cache hit for sstable 3 | 20:31:27,443 | 10.196.1.106 |         212934
                                       Seeking to partition indexed section in data file | 20:31:27,443 | 10.196.1.106 |         212936
                                                             Key cache hit for sstable 1 | 20:31:27,443 | 10.196.1.106 |         212943
                                       Seeking to partition indexed section in data file | 20:31:27,443 | 10.196.1.106 |         212945
                                              Merging data from memtables and 2 sstables | 20:31:27,443 | 10.196.1.106 |         212949
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,451 | 10.196.1.106 |         220911
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,451 | 10.196.1.106 |         220954
                                                            Acquiring sstable references | 20:31:27,451 | 10.196.1.106 |         220956
                                                             Merging memtable tombstones | 20:31:27,451 | 10.196.1.106 |         220962
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,451 | 10.196.1.106 |         220968
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,451 | 10.196.1.106 |         220971
                                                             Key cache hit for sstable 1 | 20:31:27,451 | 10.196.1.106 |         220976
                                             Seeking to partition beginning in data file | 20:31:27,451 | 10.196.1.106 |         220979
                                              Merging data from memtables and 1 sstables | 20:31:27,452 | 10.196.1.106 |         221774
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,452 | 10.196.1.106 |         221965
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,452 | 10.196.1.106 |         222093
                                                            Acquiring sstable references | 20:31:27,452 | 10.196.1.106 |         222101
                                                             Merging memtable tombstones | 20:31:27,452 | 10.196.1.106 |         222108
                                                             Key cache hit for sstable 3 | 20:31:27,452 | 10.196.1.106 |         222115
                                       Seeking to partition indexed section in data file | 20:31:27,452 | 10.196.1.106 |         222118
                                                             Key cache hit for sstable 1 | 20:31:27,452 | 10.196.1.106 |         222124
                                       Seeking to partition indexed section in data file | 20:31:27,452 | 10.196.1.106 |         222126
                                              Merging data from memtables and 2 sstables | 20:31:27,452 | 10.196.1.106 |         222130
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,460 | 10.196.1.106 |         230378
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,460 | 10.196.1.106 |         230420
                                                            Acquiring sstable references | 20:31:27,460 | 10.196.1.106 |         230422
                                                             Merging memtable tombstones | 20:31:27,460 | 10.196.1.106 |         230428
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,461 | 10.196.1.106 |         230527
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,461 | 10.196.1.106 |         230619
                                                             Key cache hit for sstable 1 | 20:31:27,461 | 10.196.1.106 |         230624
                                             Seeking to partition beginning in data file | 20:31:27,461 | 10.196.1.106 |         230627
                                              Merging data from memtables and 1 sstables | 20:31:27,461 | 10.196.1.106 |         231223
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,461 | 10.196.1.106 |         231419
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,461 | 10.196.1.106 |         231531
                                                            Acquiring sstable references | 20:31:27,461 | 10.196.1.106 |         231540
                                                             Merging memtable tombstones | 20:31:27,461 | 10.196.1.106 |         231545
                                                             Key cache hit for sstable 3 | 20:31:27,461 | 10.196.1.106 |         231553
                                       Seeking to partition indexed section in data file | 20:31:27,461 | 10.196.1.106 |         231555
                                                             Key cache hit for sstable 1 | 20:31:27,461 | 10.196.1.106 |         231562
                                       Seeking to partition indexed section in data file | 20:31:27,461 | 10.196.1.106 |         231564
                                              Merging data from memtables and 2 sstables | 20:31:27,461 | 10.196.1.106 |         231568
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,470 | 10.196.1.106 |         239976
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,470 | 10.196.1.106 |         240020
                                                            Acquiring sstable references | 20:31:27,470 | 10.196.1.106 |         240022
                                                             Merging memtable tombstones | 20:31:27,470 | 10.196.1.106 |         240028
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,470 | 10.196.1.106 |         240034
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,470 | 10.196.1.106 |         240037
                                                             Key cache hit for sstable 1 | 20:31:27,470 | 10.196.1.106 |         240054
                                             Seeking to partition beginning in data file | 20:31:27,470 | 10.196.1.106 |         240093
                                              Merging data from memtables and 1 sstables | 20:31:27,470 | 10.196.1.106 |         240585
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,471 | 10.196.1.106 |         240885
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,471 | 10.196.1.106 |         240993
                                                            Acquiring sstable references | 20:31:27,471 | 10.196.1.106 |         240997
                                                             Merging memtable tombstones | 20:31:27,471 | 10.196.1.106 |         241003
                                                             Key cache hit for sstable 3 | 20:31:27,471 | 10.196.1.106 |         241011
                                       Seeking to partition indexed section in data file | 20:31:27,471 | 10.196.1.106 |         241013
                                                             Key cache hit for sstable 1 | 20:31:27,471 | 10.196.1.106 |         241019
                                       Seeking to partition indexed section in data file | 20:31:27,471 | 10.196.1.106 |         241020
                                              Merging data from memtables and 2 sstables | 20:31:27,471 | 10.196.1.106 |         241028
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,479 | 10.196.1.106 |         249225
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,479 | 10.196.1.106 |         249265
                                                            Acquiring sstable references | 20:31:27,479 | 10.196.1.106 |         249267
                                                             Merging memtable tombstones | 20:31:27,479 | 10.196.1.106 |         249273
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,479 | 10.196.1.106 |         249279
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,479 | 10.196.1.106 |         249282
                                                             Key cache hit for sstable 1 | 20:31:27,479 | 10.196.1.106 |         249287
                                             Seeking to partition beginning in data file | 20:31:27,479 | 10.196.1.106 |         249289
                                              Merging data from memtables and 1 sstables | 20:31:27,479 | 10.196.1.106 |         249296
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,479 | 10.196.1.106 |         249558
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,480 | 10.196.1.106 |         249655
                                                            Acquiring sstable references | 20:31:27,480 | 10.196.1.106 |         249658
                                                             Merging memtable tombstones | 20:31:27,480 | 10.196.1.106 |         249755
                                                             Key cache hit for sstable 3 | 20:31:27,480 | 10.196.1.106 |         249763
                                       Seeking to partition indexed section in data file | 20:31:27,480 | 10.196.1.106 |         249765
                                                             Key cache hit for sstable 1 | 20:31:27,480 | 10.196.1.106 |         249772
                                       Seeking to partition indexed section in data file | 20:31:27,480 | 10.196.1.106 |         249774
                                              Merging data from memtables and 2 sstables | 20:31:27,480 | 10.196.1.106 |         249778
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,487 | 10.196.1.106 |         257542
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,487 | 10.196.1.106 |         257575
                                                            Acquiring sstable references | 20:31:27,488 | 10.196.1.106 |         257610
                                                             Merging memtable tombstones | 20:31:27,488 | 10.196.1.106 |         257616
                                                  Bloom filter allows skipping sstable 3 | 20:31:27,488 | 10.196.1.106 |         257622
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,488 | 10.196.1.106 |         257625
                                                             Key cache hit for sstable 1 | 20:31:27,488 | 10.196.1.106 |         257631
                                             Seeking to partition beginning in data file | 20:31:27,488 | 10.196.1.106 |         257633
                                              Merging data from memtables and 1 sstables | 20:31:27,488 | 10.196.1.106 |         258473
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,489 | 10.196.1.106 |         259067
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,489 | 10.196.1.106 |         259197
                                                            Acquiring sstable references | 20:31:27,489 | 10.196.1.106 |         259200
                                                             Merging memtable tombstones | 20:31:27,489 | 10.196.1.106 |         259206
                                                             Key cache hit for sstable 3 | 20:31:27,489 | 10.196.1.106 |         259214
                                       Seeking to partition indexed section in data file | 20:31:27,489 | 10.196.1.106 |         259216
                                                             Key cache hit for sstable 1 | 20:31:27,489 | 10.196.1.106 |         259222
                                       Seeking to partition indexed section in data file | 20:31:27,489 | 10.196.1.106 |         259224
                                              Merging data from memtables and 2 sstables | 20:31:27,489 | 10.196.1.106 |         259319
                                                      Read 3 live and 0 tombstoned cells | 20:31:27,497 | 10.196.1.106 |         267071
                              Executing single-partition query on cf_300000_keys_50_cols | 20:31:27,497 | 10.196.1.106 |         267135
                                                            Acquiring sstable references | 20:31:27,497 | 10.196.1.106 |         267137
                                                             Merging memtable tombstones | 20:31:27,497 | 10.196.1.106 |         267143
                                                             Key cache hit for sstable 3 | 20:31:27,497 | 10.196.1.106 |         267151
                                             Seeking to partition beginning in data file | 20:31:27,497 | 10.196.1.106 |         267154
                                                  Bloom filter allows skipping sstable 2 | 20:31:27,498 | 10.196.1.106 |         267943
                                                  Bloom filter allows skipping sstable 1 | 20:31:27,498 | 10.196.1.106 |         267957
                                              Merging data from memtables and 1 sstables | 20:31:27,498 | 10.196.1.106 |         267960
                                                      Read 1 live and 0 tombstoned cells | 20:31:27,498 | 10.196.1.106 |         268176
                        Executing single-partition query on cf_300000_keys_50_cols.color | 20:31:27,498 | 10.196.1.106 |         268271
                                                            Acquiring sstable references | 20:31:27,498 | 10.196.1.106 |         268274
                                                             Merging memtable tombstones | 20:31:27,498 | 10.196.1.106 |         268280
                                                             Key cache hit for sstable 3 | 20:31:27,498 | 
      ...
      

      Attachments

        1. 5975-1.2-branch.txt
          2 kB
          Alex Liu
        2. 5975-v2.txt
          8 kB
          Aleksey Yeschenko
        3. 5975-v2.txt
          8 kB
          Aleksey Yeschenko
        4. 5975-v2-extra-tracing.txt
          10 kB
          Aleksey Yeschenko
        5. create_data.py
          12 kB
          Russell Spitzer
        6. patch.txt
          8 kB
          Alex Liu
        7. trace.log
          2.32 MB
          Russell Spitzer

        Activity

          People

            aleksey Aleksey Yeschenko
            rspitzer Russell Spitzer
            Aleksey Yeschenko
            Sylvain Lebresne
            Votes:
            0 Vote for this issue
            Watchers:
            9 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: