cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Marco Matarazzo (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (CASSANDRA-5501) Missing data on SELECT on secondary index
Date Fri, 26 Apr 2013 17:12:17 GMT

    [ https://issues.apache.org/jira/browse/CASSANDRA-5501?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13643037#comment-13643037
] 

Marco Matarazzo commented on CASSANDRA-5501:
--------------------------------------------

Alas, we had to update (and add) data in rows and now the query is correctly returning everything.


I didn't know about the "TRACING ON" command, it's a great tool :-)

I'm going to still post the result of the command, hoping that, apart from the result being
correct, it will give you some clues anyway.

cqlsh:goh_master> select agent_id,name,station_id,trading from agents where station_id='1110129';

 agent_id                             | name           | station_id | trading
--------------------------------------+----------------+------------+---------
 6c8efeb6-7209-11e2-890a-aacc00000216 | Jenny Olifield |    1110129 |    null
 b653d8c4-5fca-11e2-bd3a-aacc00000216 |        mammolo |    1110129 |    null
 cf9df102-7394-11e2-890a-aacc00000216 |         riolla |    1110129 |    null
 f9c0278b-aa5f-11e2-a860-aacc00000216 |       Terrinon |    1110129 |    null
 cf03e58b-6d6a-11e2-890a-aacc00000216 |         Fichte |    1110129 |    null
 7e5d9601-70b5-11e2-a512-aacc00000200 |           miao |    1110129 |    null
 8e50ab8c-63e7-11e2-8c38-aacc00000201 |         Reaper |    1110129 |       0
 bba46192-6c63-11e2-8c38-aacc00000201 |       crafter1 |    1110129 |    null
 5521cda0-7394-11e2-890a-aacc00000216 |           olea |    1110129 |    null
 dc413373-6b06-11e2-8943-aacc00000216 |   Darren Matar |    1110129 |       1
 0e7074ac-64bd-11e2-8c38-aacc00000201 |     Tom Bishop |    1110129 |    null
 02238149-717a-11e2-890a-aacc00000216 |   Capt. Andrew |    1110129 |    null
 d4e5a014-72ac-11e2-890a-aacc00000216 |          pluto |    1110129 |    null
 2a483b11-70b5-11e2-8c38-aacc00000201 |         alexey |    1110129 |    null
 1b462f09-65f3-4148-a1a6-536b52b3bcfa |     Andrea Len |    1110129 |       1
 9a96615a-7a72-11e2-a513-aacc00000216 |          padme |    1110129 |    null
 58670d03-70b6-11e2-8c38-aacc00000201 |         trilly |    1110129 |    null


Tracing session: 1bd92f60-ae93-11e2-a990-2f5b109ee83c

 activity                                                                          | timestamp
   | source       | source_elapsed
-----------------------------------------------------------------------------------+--------------+--------------+----------------
                                                                execute_cql3_query | 19:02:42,519
| 10.10.30.169 |              0
                                               Message received from /10.10.30.169 | 19:02:42,516
| 10.10.30.170 |             21
 Executing indexed scan for [min(-9223372036854775808), min(-9223372036854775808)] | 19:02:42,518
| 10.10.30.170 |           1866
                      Executing single-partition query on agents.agents_station_id | 19:02:42,518
| 10.10.30.170 |           2244
                                                                 Parsing statement | 19:02:42,519
| 10.10.30.169 |             42
                                                      Acquiring sstable references | 19:02:42,519
| 10.10.30.170 |           2787
                                                                Peparing statement | 19:02:42,519
| 10.10.30.169 |            122
                                                         Merging memtable contents | 19:02:42,519
| 10.10.30.170 |           3107
                                                     Determining replicas to query | 19:02:42,519
| 10.10.30.169 |            216
                                                     Key cache hit for sstable 620 | 19:02:42,520
| 10.10.30.170 |           3806
                                        Merging data from memtables and 1 sstables | 19:02:42,520
| 10.10.30.170 |           4135
                                               Read 17 live cells and 0 tombstoned | 19:02:42,521
| 10.10.30.170 |           4826
                                                  Sending message to /10.10.30.170 | 19:02:42,522
| 10.10.30.169 |           2761
                                        Executing single-partition query on agents | 19:02:42,522
| 10.10.30.170 |           5490
                                                      Acquiring sstable references | 19:02:42,522
| 10.10.30.170 |           5782
                                                         Merging memtable contents | 19:02:42,522
| 10.10.30.170 |           6062
                                                     Key cache hit for sstable 443 | 19:02:42,523
| 10.10.30.170 |           6350
                                        Merging data from memtables and 1 sstables | 19:02:42,523
| 10.10.30.170 |           6628
                                                Read 1 live cells and 3 tombstoned | 19:02:42,523
| 10.10.30.170 |           6991
                                        Executing single-partition query on agents | 19:02:42,524
| 10.10.30.170 |           7314
                                                      Acquiring sstable references | 19:02:42,524
| 10.10.30.170 |           7609
                                                         Merging memtable contents | 19:02:42,524
| 10.10.30.170 |           7881
                                                     Key cache hit for sstable 443 | 19:02:42,524
| 10.10.30.170 |           8161
                                        Merging data from memtables and 1 sstables | 19:02:42,525
| 10.10.30.170 |           8428
                                                Read 1 live cells and 5 tombstoned | 19:02:42,525
| 10.10.30.170 |           8760
                                        Executing single-partition query on agents | 19:02:42,525
| 10.10.30.170 |           9070
                                                      Acquiring sstable references | 19:02:42,526
| 10.10.30.170 |           9472
                                                         Merging memtable contents | 19:02:42,526
| 10.10.30.170 |           9950
                                                     Key cache hit for sstable 443 | 19:02:42,527
| 10.10.30.170 |          10635
                                        Merging data from memtables and 1 sstables | 19:02:42,527
| 10.10.30.170 |          10917
                                                Read 1 live cells and 3 tombstoned | 19:02:42,527
| 10.10.30.170 |          11253
                                        Executing single-partition query on agents | 19:02:42,528
| 10.10.30.170 |          11574
                                                      Acquiring sstable references | 19:02:42,528
| 10.10.30.170 |          11832
                                                         Merging memtable contents | 19:02:42,528
| 10.10.30.170 |          12093
                                                     Key cache hit for sstable 443 | 19:02:42,529
| 10.10.30.170 |          12363
                                        Merging data from memtables and 1 sstables | 19:02:42,529
| 10.10.30.170 |          12620
                                                Read 1 live cells and 3 tombstoned | 19:02:42,529
| 10.10.30.170 |          12958
                                        Executing single-partition query on agents | 19:02:42,530
| 10.10.30.170 |          13276
                                                      Acquiring sstable references | 19:02:42,530
| 10.10.30.170 |          13524
                                                         Merging memtable contents | 19:02:42,530
| 10.10.30.170 |          13784
                                                     Key cache hit for sstable 443 | 19:02:42,530
| 10.10.30.170 |          14077
                                        Merging data from memtables and 1 sstables | 19:02:42,531
| 10.10.30.170 |          14340
                                                Read 1 live cells and 4 tombstoned | 19:02:42,531
| 10.10.30.170 |          14670
                                        Executing single-partition query on agents | 19:02:42,531
| 10.10.30.170 |          14975
                                                      Acquiring sstable references | 19:02:42,531
| 10.10.30.170 |          15225
                                                         Merging memtable contents | 19:02:42,532
| 10.10.30.170 |          15272
                                                     Key cache hit for sstable 443 | 19:02:42,532
| 10.10.30.170 |          15311
                                        Merging data from memtables and 1 sstables | 19:02:42,532
| 10.10.30.170 |          15333
                                                Read 1 live cells and 5 tombstoned | 19:02:42,532
| 10.10.30.170 |          15426
                                        Executing single-partition query on agents | 19:02:42,532
| 10.10.30.170 |          15511
                                                      Acquiring sstable references | 19:02:42,532
| 10.10.30.170 |          15527
                                                         Merging memtable contents | 19:02:42,532
| 10.10.30.170 |          15548
                                                     Key cache hit for sstable 443 | 19:02:42,532
| 10.10.30.170 |          15582
                                        Merging data from memtables and 1 sstables | 19:02:42,532
| 10.10.30.170 |          15603
                                                Read 1 live cells and 2 tombstoned | 19:02:42,532
| 10.10.30.170 |          15692
                                        Executing single-partition query on agents | 19:02:42,532
| 10.10.30.170 |          15761
                                                      Acquiring sstable references | 19:02:42,532
| 10.10.30.170 |          15775
                                                         Merging memtable contents | 19:02:42,532
| 10.10.30.170 |          15796
                                                     Key cache hit for sstable 444 | 19:02:42,532
| 10.10.30.170 |          15828
                                                     Key cache hit for sstable 443 | 19:02:42,532
| 10.10.30.170 |          15855
                                        Merging data from memtables and 2 sstables | 19:02:42,532
| 10.10.30.170 |          15873
                                                Read 1 live cells and 4 tombstoned | 19:02:42,532
| 10.10.30.170 |          15987
                                        Executing single-partition query on agents | 19:02:42,532
| 10.10.30.170 |          16055
                                                      Acquiring sstable references | 19:02:42,532
| 10.10.30.170 |          16069
                                                         Merging memtable contents | 19:02:42,532
| 10.10.30.170 |          16090
                                                     Key cache hit for sstable 443 | 19:02:42,532
| 10.10.30.170 |          16124
                                        Merging data from memtables and 1 sstables | 19:02:42,532
| 10.10.30.170 |          16145
                                                Read 1 live cells and 5 tombstoned | 19:02:42,532
| 10.10.30.170 |          16235
                                        Executing single-partition query on agents | 19:02:42,533
| 10.10.30.170 |          16299
                                                      Acquiring sstable references | 19:02:42,533
| 10.10.30.170 |          16313
                                                         Merging memtable contents | 19:02:42,533
| 10.10.30.170 |          16334
                                                     Key cache hit for sstable 445 | 19:02:42,533
| 10.10.30.170 |          16364
                                                     Key cache hit for sstable 444 | 19:02:42,533
| 10.10.30.170 |          16390
                                                     Key cache hit for sstable 443 | 19:02:42,533
| 10.10.30.170 |          16413
                                        Merging data from memtables and 3 sstables | 19:02:42,533
| 10.10.30.170 |          16431
                                                Read 1 live cells and 2 tombstoned | 19:02:42,533
| 10.10.30.170 |          16556
                                        Executing single-partition query on agents | 19:02:42,533
| 10.10.30.170 |          16621
                                                      Acquiring sstable references | 19:02:42,533
| 10.10.30.170 |          16635
                                                         Merging memtable contents | 19:02:42,533
| 10.10.30.170 |          16656
                                                     Key cache hit for sstable 443 | 19:02:42,533
| 10.10.30.170 |          16689
                                        Merging data from memtables and 1 sstables | 19:02:42,533
| 10.10.30.170 |          16709
                                                Read 1 live cells and 2 tombstoned | 19:02:42,533
| 10.10.30.170 |          16799
                                        Executing single-partition query on agents | 19:02:42,533
| 10.10.30.170 |          16866
                                                      Acquiring sstable references | 19:02:42,533
| 10.10.30.170 |          16880
                                                         Merging memtable contents | 19:02:42,533
| 10.10.30.170 |          16901
                                                     Key cache hit for sstable 443 | 19:02:42,533
| 10.10.30.170 |          16938
                                        Merging data from memtables and 1 sstables | 19:02:42,533
| 10.10.30.170 |          16959
                                                Read 1 live cells and 3 tombstoned | 19:02:42,533
| 10.10.30.170 |          17070
                                        Executing single-partition query on agents | 19:02:42,533
| 10.10.30.170 |          17135
                                                      Acquiring sstable references | 19:02:42,533
| 10.10.30.170 |          17149
                                                         Merging memtable contents | 19:02:42,533
| 10.10.30.170 |          17170
                                                     Key cache hit for sstable 443 | 19:02:42,533
| 10.10.30.170 |          17203
                                        Merging data from memtables and 1 sstables | 19:02:42,533
| 10.10.30.170 |          17223
                                                Read 1 live cells and 4 tombstoned | 19:02:42,534
| 10.10.30.170 |          17313
                                        Executing single-partition query on agents | 19:02:42,534
| 10.10.30.170 |          17376
                                                      Acquiring sstable references | 19:02:42,534
| 10.10.30.170 |          17390
                                                         Merging memtable contents | 19:02:42,534
| 10.10.30.170 |          17411
                                                     Key cache hit for sstable 443 | 19:02:42,534
| 10.10.30.170 |          17443
                                        Merging data from memtables and 1 sstables | 19:02:42,534
| 10.10.30.170 |          17463
                                                Read 1 live cells and 5 tombstoned | 19:02:42,534
| 10.10.30.170 |          17549
                                        Executing single-partition query on agents | 19:02:42,534
| 10.10.30.170 |          17611
                                                      Acquiring sstable references | 19:02:42,534
| 10.10.30.170 |          17625
                                                         Merging memtable contents | 19:02:42,534
| 10.10.30.170 |          17649
                                                     Key cache hit for sstable 445 | 19:02:42,534
| 10.10.30.170 |          17679
                                                     Key cache hit for sstable 444 | 19:02:42,534
| 10.10.30.170 |          17704
                                                     Key cache hit for sstable 443 | 19:02:42,534
| 10.10.30.170 |          17727
                                        Merging data from memtables and 3 sstables | 19:02:42,534
| 10.10.30.170 |          17745
                                                Read 1 live cells and 2 tombstoned | 19:02:42,534
| 10.10.30.170 |          17866
                                        Executing single-partition query on agents | 19:02:42,534
| 10.10.30.170 |          17930
                                                      Acquiring sstable references | 19:02:42,534
| 10.10.30.170 |          17944
                                                         Merging memtable contents | 19:02:42,534
| 10.10.30.170 |          17965
                                                     Key cache hit for sstable 443 | 19:02:42,534
| 10.10.30.170 |          17997
                                        Merging data from memtables and 1 sstables | 19:02:42,534
| 10.10.30.170 |          18018
                                                Read 1 live cells and 3 tombstoned | 19:02:42,534
| 10.10.30.170 |          18109
                                        Executing single-partition query on agents | 19:02:42,534
| 10.10.30.170 |          18172
                                                      Acquiring sstable references | 19:02:42,534
| 10.10.30.170 |          18186
                                                         Merging memtable contents | 19:02:42,534
| 10.10.30.170 |          18207
                                                     Key cache hit for sstable 443 | 19:02:42,534
| 10.10.30.170 |          18244
                                        Merging data from memtables and 1 sstables | 19:02:42,535
| 10.10.30.170 |          18264
                                                Read 1 live cells and 5 tombstoned | 19:02:42,535
| 10.10.30.170 |          18349
                                                    Scanned 17 rows and matched 17 | 19:02:42,535
| 10.10.30.170 |          18404
                                               Enqueuing response to /10.10.30.169 | 19:02:42,535
| 10.10.30.170 |          18422
                                                  Sending message to /10.10.30.169 | 19:02:42,544
| 10.10.30.170 |          27416
                                               Message received from /10.10.30.170 | 19:02:42,552
| 10.10.30.169 |          32473
                                            Processing response from /10.10.30.170 | 19:02:42,552
| 10.10.30.169 |          33182
                                                                  Request complete | 19:02:42,553
| 10.10.30.169 |          34298
                
> Missing data on SELECT on secondary index 
> ------------------------------------------
>
>                 Key: CASSANDRA-5501
>                 URL: https://issues.apache.org/jira/browse/CASSANDRA-5501
>             Project: Cassandra
>          Issue Type: Bug
>    Affects Versions: 1.2.4
>         Environment: linux ubuntu 12.04
>            Reporter: Marco Matarazzo
>         Attachments: query_log.txt
>
>
> We have a 3 nodes cluster, and a keyspace with RF = 3.
> From cassandra-cli everything is fine (we actually never use it, I just launched it for
a check in this particular case).
> [default@goh_master] get agents where station_id = ascii(1110129);
> -------------------
> RowKey: 6c8efeb6-7209-11e2-890a-aacc00000216
> => (column=, value=, timestamp=1364580868176000)
> => (column=character_points, value=, timestamp=1361030686890000)
> => (column=component_id, value=0, timestamp=1364580868176000)
> => (column=corporation_id, value=3efc729e-7209-11e2-890a-aacc00000216, timestamp=1361030686890000)
> => (column=entity_id, value=0, timestamp=1364580868176000)
> => (column=manufacturing, value=, timestamp=1361030686890000)
> => (column=model, value=500005, timestamp=1361030686890000)
> => (column=name, value=Jenny Olifield, timestamp=1361030686890000)
> => (column=name_check, value=jenny_olifield, timestamp=1361030686890000)
> => (column=station_id, value=1110129, timestamp=1364580868176000)
> => (column=stats_intellect, value=8, timestamp=1361030686890000)
> => (column=stats_reflexes, value=8, timestamp=1361030686890000)
> => (column=stats_stamina, value=7, timestamp=1361030686890000)
> => (column=stats_technology, value=7, timestamp=1361030686890000)
> => (column=trading, value=, timestamp=1361030686890000)
> -------------------
> RowKey: dc413373-6b06-11e2-8943-aacc00000216
> => (column=, value=, timestamp=1366568185220000)
> => (column=character_points, value=100, timestamp=1364580381651000)
> => (column=component_id, value=, timestamp=1364580381651000)
> => (column=corporation_id, value=574934cc-6b06-11e2-a512-aacc00000200, timestamp=1364580381651000)
> => (column=entity_id, value=0, timestamp=1364580381651000)
> => (column=manufacturing, value=, timestamp=1364580381651000)
> => (column=model, value=500018, timestamp=1364580381651000)
> => (column=name, value=Darren Matar, timestamp=1364580381651000)
> => (column=name_check, value=darren_matar, timestamp=1364580381651000)
> => (column=station_id, value=1110129, timestamp=1364580381651000)
> => (column=stats_intellect, value=10, timestamp=1364580381651000)
> => (column=stats_reflexes, value=10, timestamp=1364580381651000)
> => (column=stats_stamina, value=10, timestamp=1364580381651000)
> => (column=stats_technology, value=10, timestamp=1364580381651000)
> => (column=trading, value=1, timestamp=1366568185220000)
> -------------------
> RowKey: 0e7074ac-64bd-11e2-8c38-aacc00000201
> => (column=, value=, timestamp=1364828039093000)
> => (column=character_points, value=, timestamp=1361030686760000)
> => (column=component_id, value=0, timestamp=1364828039093000)
> => (column=corporation_id, value=e398294e-64bc-11e2-8c38-aacc00000201, timestamp=1361030686760000)
> => (column=entity_id, value=0, timestamp=1364828039093000)
> => (column=manufacturing, value=1, timestamp=1362517535613000)
> => (column=model, value=500008, timestamp=1361030686760000)
> => (column=name, value=Tom Bishop, timestamp=1361030686760000)
> => (column=name_check, value=tom_bishop, timestamp=1361030686760000)
> => (column=station_id, value=1110129, timestamp=1364828039093000)
> => (column=stats_intellect, value=9, timestamp=1361030686760000)
> => (column=stats_reflexes, value=7, timestamp=1361030686760000)
> => (column=stats_stamina, value=5, timestamp=1361030686760000)
> => (column=stats_technology, value=9, timestamp=1361030686760000)
> => (column=trading, value=, timestamp=1361030686760000)
> -------------------
> RowKey: 1b462f09-65f3-4148-a1a6-536b52b3bcfa
> => (column=, value=, timestamp=1366568185096000)
> => (column=character_points, value=100, timestamp=1364580381537000)
> => (column=component_id, value=, timestamp=1364580381537000)
> => (column=corporation_id, value=1d2a8803-d139-4b50-85eb-92cb1082de2e, timestamp=1364580381537000)
> => (column=entity_id, value=0, timestamp=1364580381537000)
> => (column=manufacturing, value=, timestamp=1364580381537000)
> => (column=model, value=500003, timestamp=1364580381537000)
> => (column=name, value=Andrea Len, timestamp=1364580381537000)
> => (column=name_check, value=andrea_len, timestamp=1364580381537000)
> => (column=station_id, value=1110129, timestamp=1364580381537000)
> => (column=stats_intellect, value=10, timestamp=1364580381537000)
> => (column=stats_reflexes, value=10, timestamp=1364580381537000)
> => (column=stats_stamina, value=10, timestamp=1364580381537000)
> => (column=stats_technology, value=10, timestamp=1364580381537000)
> => (column=trading, value=1, timestamp=1366568185096000)
> 4 Rows Returned.
> From CQLSH, hovewer, the result is different, and 2 rows are missing.
> cqlsh:goh_master> select agent_id,name,station_id from agents where station_id='1110129';
>  agent_id                             | name           | station_id
> --------------------------------------+----------------+------------
>  6c8efeb6-7209-11e2-890a-aacc00000216 | Jenny Olifield |    1110129
>  0e7074ac-64bd-11e2-8c38-aacc00000201 |     Tom Bishop |    1110129
> cqlsh:goh_master> select agent_id, name, station_id from agents where agent_id = '1b462f09-65f3-4148-a1a6-536b52b3bcfa';
>  agent_id                             | name       | station_id
> --------------------------------------+------------+------------
>  1b462f09-65f3-4148-a1a6-536b52b3bcfa | Andrea Len |    1110129
> Updating one column makes the single row reappear in the index, but just for that row
and that columns/index.
> cqlsh:goh_master> update agents set station_id = '1110129' where agent_id = '1b462f09-65f3-4148-a1a6-536b52b3bcfa';
> cqlsh:goh_master> select agent_id,name,station_id from agents where station_id='1110129';
>  agent_id                             | name           | station_id
> --------------------------------------+----------------+------------
>  6c8efeb6-7209-11e2-890a-aacc00000216 | Jenny Olifield |    1110129
>  0e7074ac-64bd-11e2-8c38-aacc00000201 |     Tom Bishop |    1110129
>  1b462f09-65f3-4148-a1a6-536b52b3bcfa |     Andrea Len |    1110129
> Updating one columns does not make all the row re-appear on all indexes (as it would
be somewhat expected), but just on the updated one.
> cqlsh:goh_master> select * from agents where name = 'Andrea Len';
> cqlsh:goh_master> 
> Running nodetool rebuild_index on all three nodes apparently DOES NOT fixes the problem,
neither do nodetool repair.
> We also used COPY TO to dump the entire row to check for hidden spaces or anything like
that, but we can't see anything:
> ....
> dc413373-6b06-11e2-8943-aacc00000216,100,,574934cc-6b06-11e2-a512-aacc00000200,0,,500018,Darren
Matar,darren_matar,1110129,10,10,10,10,1
> 1b462f09-65f3-4148-a1a6-536b52b3bcfa,100,,1d2a8803-d139-4b50-85eb-92cb1082de2e,0,,500003,Andrea
Len,andrea_len,1110129,10,10,10,10,1
> ....
> Logs shows no error. I lowered log level to DEBUG and the only thing that I see when
I launch the query is just:
> DEBUG [Thrift:16] 2013-04-22 10:47:27,727 CassandraServer.java (line 1703) execute_cql3_query
> DEBUG [Thrift:16] 2013-04-22 10:47:27,737 Tracing.java (line 167) request complete
> In attachment, a log of the query with TRACE level log (in the meantime other rows were
added, but the result doesn't change). 
> I don't know how the internal mechanism of Cassandra works, so this could absolutely
be no related, but the two columns that are not coming out have a more recent timestamp as
it can be seen from cassandra-cli, and this CF has two sstables on disk, ...-435 and ...-436,
and with log level lowered to trace, it seems to me that -436 get skipped due to bloom filter.
I am really guessing here, I admit.
> The very same skipping is shown in logs when i try to rebuild indexes, btw.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira

Mime
View raw message