cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Terry Ma (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (CASSANDRA-11814) some queries are very slow on a small partition
Date Tue, 17 May 2016 03:37:12 GMT

     [ https://issues.apache.org/jira/browse/CASSANDRA-11814?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Terry Ma updated CASSANDRA-11814:
---------------------------------
    Description: 
we have a cassandra cluster, which has 16 nodes(m4.2xlarge) on aws. 
The total data size is 2.5TB now. There is a very large table named inbox_musical, the schema
is like this: 
{code}
CREATE TABLE feeds.inbox_musical (
    owner_id bigint,
    activity_id bigint,
    insert_time timestamp,
    PRIMARY KEY (owner_id, activity_id)
) WITH CLUSTERING ORDER BY (activity_id DESC)
    AND bloom_filter_fp_chance = 0.1
    AND caching = '{"keys":"ALL", "rows_per_partition":"20"}'
    AND comment = ''
    AND compaction = {'class': 'org.apache.cassandra.db.compaction.LeveledCompactionStrategy'}
    AND compression = {'sstable_compression': 'org.apache.cassandra.io.compress.LZ4Compressor'}
    AND dclocal_read_repair_chance = 0.1
    AND default_time_to_live = 15552000
    AND gc_grace_seconds = 864000
    AND max_index_interval = 2048
    AND memtable_flush_period_in_ms = 0
    AND min_index_interval = 128
    AND read_repair_chance = 0.0
    AND speculative_retry = '99.0PERCENTILE';
{code}

owner_id is the partition key, and activity_id is clustering key.

95% query can return within 10ms. but a few queries read timeout ( > 5s ).

the slow queries is like this:
{code:sql}
SELECT activity_id FROM inbox_musical WHERE owner_id=5582322 ORDER BY activity_id DESC LIMIT
100;
{code}

there are only 230 rows in this partition. but the query takes seconds to complete.

the query tracing:
{code}
 activity                                                                                
                                       | timestamp                  | source       | source_elapsed
---------------------------------------------------------------------------------------------------------------------------------+----------------------------+--------------+----------------
                                                                                         
                    Execute CQL3 query | 2016-05-17 11:21:26.986000 | 172.31.8.188 |     
        0
                                              READ message received from /172.31.8.188 [MessagingService-Incoming-/172.31.8.188]
| 2016-05-17 11:21:26.985000 | 172.31.15.14 |             13
                                                         Executing single-partition query
on inbox_musical [SharedPool-Worker-4] | 2016-05-17 11:21:26.985000 | 172.31.15.14 |     
      115
                                              READ message received from /172.31.8.188 [MessagingService-Incoming-/172.31.8.188]
| 2016-05-17 11:21:26.986000 | 172.31.4.135 |             13
                                                                              Acquiring sstable
references [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |           
137
                                                         Executing single-partition query
on inbox_musical [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |     
      113
                                                                               Merging memtable
tombstones [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |           
161
 Parsing SELECT activity_id FROM inbox_musical WHERE owner_id=5582322 ORDER BY activity_id
DESC LIMIT 100; [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |      
      66
                                                                              Acquiring sstable
references [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |           
136
                                                                           Key cache hit for
sstable 18948 [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |        
   199
                                                                                       Preparing
statement [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |            
99
                                                                               Merging memtable
tombstones [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |           
155
                                                               Seeking to partition beginning
in data file [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |         
  205
                                                                                      Read-repair
DC_LOCAL [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |            142
                                                                Bloom filter allows skipping
sstable 20159 [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |        
   179
                                                                           Key cache hit for
sstable 18924 [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |        
   459
                                                                           reading data from
/172.31.4.135 [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |        
   160
                                                                           Key cache hit for
sstable 20134 [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |        
   195
                                                               Seeking to partition beginning
in data file [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |         
  468
                                                                           reading data from
/172.31.15.14 [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |        
   212
                                                               Seeking to partition beginning
in data file [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |         
  202
                                                                           Key cache hit for
sstable 18547 [SharedPool-Worker-4] | 2016-05-17 11:21:26.986001 | 172.31.15.14 |        
   782
                                                 Sending READ message to /172.31.4.135 [MessagingService-Outgoing-/172.31.4.135]
| 2016-05-17 11:21:26.986001 | 172.31.8.188 |            249
                                                                           Key cache hit for
sstable 19782 [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |        
   376
                                                               Seeking to partition beginning
in data file [SharedPool-Worker-4] | 2016-05-17 11:21:26.986001 | 172.31.15.14 |         
  792
                                                 Sending READ message to /172.31.15.14 [MessagingService-Outgoing-/172.31.15.14]
| 2016-05-17 11:21:26.986001 | 172.31.8.188 |            260
                                                               Seeking to partition beginning
in data file [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |         
  388
                                 Skipped 0/3 non-slice-intersecting sstables, included 0 due
to tombstones [SharedPool-Worker-4] | 2016-05-17 11:21:26.986001 | 172.31.15.14 |        
   963
                                                                           Key cache hit for
sstable 16500 [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |        
   477
                                                                Merging data from memtables
and 3 sstables [SharedPool-Worker-4] | 2016-05-17 11:21:26.986001 | 172.31.15.14 |       
    973
                                                               Seeking to partition beginning
in data file [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |         
  484
                                 Skipped 0/4 non-slice-intersecting sstables, included 0 due
to tombstones [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |        
   573
                                                                Merging data from memtables
and 3 sstables [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |       
    582
                                                                       Read 101 live and 0
tombstone cells [SharedPool-Worker-1] | 2016-05-17 11:21:31.805000 | 172.31.4.135 |      
  819660
                                                                       Enqueuing response
to /172.31.8.188 [SharedPool-Worker-1] | 2016-05-17 11:21:31.831000 | 172.31.4.135 |     
   844972
                                     Sending REQUEST_RESPONSE message to /172.31.8.188 [MessagingService-Outgoing-/172.31.8.188]
| 2016-05-17 11:21:31.868000 | 172.31.4.135 |         882380
                                  REQUEST_RESPONSE message received from /172.31.4.135 [MessagingService-Incoming-/172.31.4.135]
| 2016-05-17 11:21:31.962000 | 172.31.8.188 |         976119
                                                                    Processing response from
/172.31.4.135 [SharedPool-Worker-2] | 2016-05-17 11:21:31.962000 | 172.31.8.188 |        
976166
                                                                                         
                      Request c
                                                                                         
                  omplete | 2016-05-17 11:21:32.014093 | 172.31.8.188 |          28093
{code}

I used jstack to get some stacks when c* is execute query like above. and found it seems c*
take a long time do the following methods:
{code}
"SharedPool-Worker-5" #221 daemon prio=5 os_prio=0 tid=0x00007f177517a000 nid=0x8b6 runnable
[0x00007f1471e5b000]
   java.lang.Thread.State: RUNNABLE
    at org.apache.cassandra.db.RangeTombstoneList.addInternal(RangeTombstoneList.java:689)
    at org.apache.cassandra.db.RangeTombstoneList.insertFrom(RangeTombstoneList.java:649)
    at org.apache.cassandra.db.RangeTombstoneList.add(RangeTombstoneList.java:170)
    at org.apache.cassandra.db.RangeTombstoneList.add(RangeTombstoneList.java:142)
    at org.apache.cassandra.db.DeletionInfo.add(DeletionInfo.java:239)
    at org.apache.cassandra.db.ArrayBackedSortedColumns.delete(ArrayBackedSortedColumns.java:490)
    at org.apache.cassandra.db.ColumnFamily.addAtom(ColumnFamily.java:153)
    at org.apache.cassandra.db.filter.QueryFilter$2.getNext(QueryFilter.java:185)
    at org.apache.cassandra.db.filter.QueryFilter$2.hasNext(QueryFilter.java:157)
    at org.apache.cassandra.utils.MergeIterator$Candidate.advance(MergeIterator.java:146)
    at org.apache.cassandra.utils.MergeIterator$ManyToOne.advance(MergeIterator.java:125)
    at org.apache.cassandra.utils.MergeIterator$ManyToOne.computeNext(MergeIterator.java:99)
    at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)
    at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)
    at org.apache.cassandra.db.filter.SliceQueryFilter.collectReducedColumns(SliceQueryFilter.java:264)
    at org.apache.cassandra.db.filter.QueryFilter.collateColumns(QueryFilter.java:109)
    at org.apache.cassandra.db.filter.QueryFilter.collateOnDiskAtom(QueryFilter.java:82)
    at org.apache.cassandra.db.filter.QueryFilter.collateOnDiskAtom(QueryFilter.java:69)
    at org.apache.cassandra.db.CollationController.collectAllData(CollationController.java:317)
    at org.apache.cassandra.db.CollationController.getTopLevelColumns(CollationController.java:61)
    at org.apache.cassandra.db.ColumnFamilyStore.getTopLevelColumns(ColumnFamilyStore.java:2011)
    at org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore.java:1815)
    at org.apache.cassandra.db.Keyspace.getRow(Keyspace.java:360)
    at org.apache.cassandra.db.SliceFromReadCommand.getRow(SliceFromReadCommand.java:85)
{code}

I executed these query when server was on very low load.

from the tracing it seems that something is very slow between 'Merging data from memtables
and 3 sstables' and 'Read 101 live and 0 tombstone cells'

  was:
we have a cassandra cluster, which has 16 nodes(m4.2xlarge) on aws. 
The total data size is 2.5TB now. There is a very large table named inbox_musical, the schema
is like this: 
{code}
CREATE TABLE feeds.inbox_musical (
    owner_id bigint,
    activity_id bigint,
    insert_time timestamp,
    PRIMARY KEY (owner_id, activity_id)
) WITH CLUSTERING ORDER BY (activity_id DESC)
    AND bloom_filter_fp_chance = 0.1
    AND caching = '{"keys":"ALL", "rows_per_partition":"20"}'
    AND comment = ''
    AND compaction = {'class': 'org.apache.cassandra.db.compaction.LeveledCompactionStrategy'}
    AND compression = {'sstable_compression': 'org.apache.cassandra.io.compress.LZ4Compressor'}
    AND dclocal_read_repair_chance = 0.1
    AND default_time_to_live = 15552000
    AND gc_grace_seconds = 864000
    AND max_index_interval = 2048
    AND memtable_flush_period_in_ms = 0
    AND min_index_interval = 128
    AND read_repair_chance = 0.0
    AND speculative_retry = '99.0PERCENTILE';
{code}

owner_id is the partition key, and activity_id is clustering key.

95% query can return within 10ms. but a few queries read timeout ( > 5s ).

the slow queries is like this:
{code:sql}
SELECT activity_id FROM inbox_musical WHERE owner_id=5582322 ORDER BY activity_id DESC LIMIT
100;
{code}

there are only 230 rows in this partition. but the query takes seconds to complete.

the query tracing:
{code}
 activity                                                                                
                                       | timestamp                  | source       | source_elapsed
---------------------------------------------------------------------------------------------------------------------------------+----------------------------+--------------+----------------
                                                                                         
                    Execute CQL3 query | 2016-05-17 11:21:26.986000 | 172.31.8.188 |     
        0
                                              READ message received from /172.31.8.188 [MessagingService-Incoming-/172.31.8.188]
| 2016-05-17 11:21:26.985000 | 172.31.15.14 |             13
                                                         Executing single-partition query
on inbox_musical [SharedPool-Worker-4] | 2016-05-17 11:21:26.985000 | 172.31.15.14 |     
      115
                                              READ message received from /172.31.8.188 [MessagingService-Incoming-/172.31.8.188]
| 2016-05-17 11:21:26.986000 | 172.31.4.135 |             13
                                                                              Acquiring sstable
references [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |           
137
                                                         Executing single-partition query
on inbox_musical [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |     
      113
                                                                               Merging memtable
tombstones [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |           
161
 Parsing SELECT activity_id FROM inbox_musical WHERE owner_id=5582322 ORDER BY activity_id
DESC LIMIT 100; [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |      
      66
                                                                              Acquiring sstable
references [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |           
136
                                                                           Key cache hit for
sstable 18948 [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |        
   199
                                                                                       Preparing
statement [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |            
99
                                                                               Merging memtable
tombstones [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |           
155
                                                               Seeking to partition beginning
in data file [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |         
  205
                                                                                      Read-repair
DC_LOCAL [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |            142
                                                                Bloom filter allows skipping
sstable 20159 [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |        
   179
                                                                           Key cache hit for
sstable 18924 [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |        
   459
                                                                           reading data from
/172.31.4.135 [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |        
   160
                                                                           Key cache hit for
sstable 20134 [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |        
   195
                                                               Seeking to partition beginning
in data file [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |         
  468
                                                                           reading data from
/172.31.15.14 [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |        
   212
                                                               Seeking to partition beginning
in data file [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |         
  202
                                                                           Key cache hit for
sstable 18547 [SharedPool-Worker-4] | 2016-05-17 11:21:26.986001 | 172.31.15.14 |        
   782
                                                 Sending READ message to /172.31.4.135 [MessagingService-Outgoing-/172.31.4.135]
| 2016-05-17 11:21:26.986001 | 172.31.8.188 |            249
                                                                           Key cache hit for
sstable 19782 [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |        
   376
                                                               Seeking to partition beginning
in data file [SharedPool-Worker-4] | 2016-05-17 11:21:26.986001 | 172.31.15.14 |         
  792
                                                 Sending READ message to /172.31.15.14 [MessagingService-Outgoing-/172.31.15.14]
| 2016-05-17 11:21:26.986001 | 172.31.8.188 |            260
                                                               Seeking to partition beginning
in data file [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |         
  388
                                 Skipped 0/3 non-slice-intersecting sstables, included 0 due
to tombstones [SharedPool-Worker-4] | 2016-05-17 11:21:26.986001 | 172.31.15.14 |        
   963
                                                                           Key cache hit for
sstable 16500 [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |        
   477
                                                                Merging data from memtables
and 3 sstables [SharedPool-Worker-4] | 2016-05-17 11:21:26.986001 | 172.31.15.14 |       
    973
                                                               Seeking to partition beginning
in data file [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |         
  484
                                 Skipped 0/4 non-slice-intersecting sstables, included 0 due
to tombstones [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |        
   573
                                                                Merging data from memtables
and 3 sstables [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |       
    582
                                                                       Read 101 live and 0
tombstone cells [SharedPool-Worker-1] | 2016-05-17 11:21:31.805000 | 172.31.4.135 |      
  819660
                                                                       Enqueuing response
to /172.31.8.188 [SharedPool-Worker-1] | 2016-05-17 11:21:31.831000 | 172.31.4.135 |     
   844972
                                     Sending REQUEST_RESPONSE message to /172.31.8.188 [MessagingService-Outgoing-/172.31.8.188]
| 2016-05-17 11:21:31.868000 | 172.31.4.135 |         882380
                                  REQUEST_RESPONSE message received from /172.31.4.135 [MessagingService-Incoming-/172.31.4.135]
| 2016-05-17 11:21:31.962000 | 172.31.8.188 |         976119
                                                                    Processing response from
/172.31.4.135 [SharedPool-Worker-2] | 2016-05-17 11:21:31.962000 | 172.31.8.188 |        
976166
                                                                                         
                      Request c
                                                                                         
                  omplete | 2016-05-17 11:21:32.014093 | 172.31.8.188 |          28093
{code}

I used jstack to get some stacks when c* is execute query like above. and found it seems c*
take a long time do the following methods:
{code}
"SharedPool-Worker-5" #221 daemon prio=5 os_prio=0 tid=0x00007f177517a000 nid=0x8b6 runnable
[0x00007f1471e5b000]
   java.lang.Thread.State: RUNNABLE
    at org.apache.cassandra.db.RangeTombstoneList.addInternal(RangeTombstoneList.java:689)
    at org.apache.cassandra.db.RangeTombstoneList.insertFrom(RangeTombstoneList.java:649)
    at org.apache.cassandra.db.RangeTombstoneList.add(RangeTombstoneList.java:170)
    at org.apache.cassandra.db.RangeTombstoneList.add(RangeTombstoneList.java:142)
    at org.apache.cassandra.db.DeletionInfo.add(DeletionInfo.java:239)
    at org.apache.cassandra.db.ArrayBackedSortedColumns.delete(ArrayBackedSortedColumns.java:490)
    at org.apache.cassandra.db.ColumnFamily.addAtom(ColumnFamily.java:153)
    at org.apache.cassandra.db.filter.QueryFilter$2.getNext(QueryFilter.java:185)
    at org.apache.cassandra.db.filter.QueryFilter$2.hasNext(QueryFilter.java:157)
    at org.apache.cassandra.utils.MergeIterator$Candidate.advance(MergeIterator.java:146)
    at org.apache.cassandra.utils.MergeIterator$ManyToOne.advance(MergeIterator.java:125)
    at org.apache.cassandra.utils.MergeIterator$ManyToOne.computeNext(MergeIterator.java:99)
    at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)
    at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)
    at org.apache.cassandra.db.filter.SliceQueryFilter.collectReducedColumns(SliceQueryFilter.java:264)
    at org.apache.cassandra.db.filter.QueryFilter.collateColumns(QueryFilter.java:109)
    at org.apache.cassandra.db.filter.QueryFilter.collateOnDiskAtom(QueryFilter.java:82)
    at org.apache.cassandra.db.filter.QueryFilter.collateOnDiskAtom(QueryFilter.java:69)
    at org.apache.cassandra.db.CollationController.collectAllData(CollationController.java:317)
    at org.apache.cassandra.db.CollationController.getTopLevelColumns(CollationController.java:61)
    at org.apache.cassandra.db.ColumnFamilyStore.getTopLevelColumns(ColumnFamilyStore.java:2011)
    at org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore.java:1815)
    at org.apache.cassandra.db.Keyspace.getRow(Keyspace.java:360)
    at org.apache.cassandra.db.SliceFromReadCommand.getRow(SliceFromReadCommand.java:85)
{code}

I executed these query when server was on very low load.


> some queries are very slow on a small partition
> -----------------------------------------------
>
>                 Key: CASSANDRA-11814
>                 URL: https://issues.apache.org/jira/browse/CASSANDRA-11814
>             Project: Cassandra
>          Issue Type: Bug
>          Components: CQL
>         Environment: os: ubuntu server 14.04
> cassandra: 2.2.5 (apt-get installed from datastax repo)
> server: ec2 m4.2xlarge
>            Reporter: Terry Ma
>            Priority: Minor
>              Labels: performance
>
> we have a cassandra cluster, which has 16 nodes(m4.2xlarge) on aws. 
> The total data size is 2.5TB now. There is a very large table named inbox_musical, the
schema is like this: 
> {code}
> CREATE TABLE feeds.inbox_musical (
>     owner_id bigint,
>     activity_id bigint,
>     insert_time timestamp,
>     PRIMARY KEY (owner_id, activity_id)
> ) WITH CLUSTERING ORDER BY (activity_id DESC)
>     AND bloom_filter_fp_chance = 0.1
>     AND caching = '{"keys":"ALL", "rows_per_partition":"20"}'
>     AND comment = ''
>     AND compaction = {'class': 'org.apache.cassandra.db.compaction.LeveledCompactionStrategy'}
>     AND compression = {'sstable_compression': 'org.apache.cassandra.io.compress.LZ4Compressor'}
>     AND dclocal_read_repair_chance = 0.1
>     AND default_time_to_live = 15552000
>     AND gc_grace_seconds = 864000
>     AND max_index_interval = 2048
>     AND memtable_flush_period_in_ms = 0
>     AND min_index_interval = 128
>     AND read_repair_chance = 0.0
>     AND speculative_retry = '99.0PERCENTILE';
> {code}
> owner_id is the partition key, and activity_id is clustering key.
> 95% query can return within 10ms. but a few queries read timeout ( > 5s ).
> the slow queries is like this:
> {code:sql}
> SELECT activity_id FROM inbox_musical WHERE owner_id=5582322 ORDER BY activity_id DESC
LIMIT 100;
> {code}
> there are only 230 rows in this partition. but the query takes seconds to complete.
> the query tracing:
> {code}
>  activity                                                                           
                                            | timestamp                  | source       |
source_elapsed
> ---------------------------------------------------------------------------------------------------------------------------------+----------------------------+--------------+----------------
>                                                                                     
                         Execute CQL3 query | 2016-05-17 11:21:26.986000 | 172.31.8.188 |
             0
>                                               READ message received from /172.31.8.188
[MessagingService-Incoming-/172.31.8.188] | 2016-05-17 11:21:26.985000 | 172.31.15.14 |  
          13
>                                                          Executing single-partition query
on inbox_musical [SharedPool-Worker-4] | 2016-05-17 11:21:26.985000 | 172.31.15.14 |     
      115
>                                               READ message received from /172.31.8.188
[MessagingService-Incoming-/172.31.8.188] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |  
          13
>                                                                               Acquiring
sstable references [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |   
        137
>                                                          Executing single-partition query
on inbox_musical [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |     
      113
>                                                                                Merging
memtable tombstones [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |  
         161
>  Parsing SELECT activity_id FROM inbox_musical WHERE owner_id=5582322 ORDER BY activity_id
DESC LIMIT 100; [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |      
      66
>                                                                               Acquiring
sstable references [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |   
        136
>                                                                            Key cache
hit for sstable 18948 [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |
           199
>                                                                                     
  Preparing statement [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |
            99
>                                                                                Merging
memtable tombstones [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |  
         155
>                                                                Seeking to partition beginning
in data file [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |         
  205
>                                                                                     
 Read-repair DC_LOCAL [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |
           142
>                                                                 Bloom filter allows skipping
sstable 20159 [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |        
   179
>                                                                            Key cache
hit for sstable 18924 [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |
           459
>                                                                            reading data
from /172.31.4.135 [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |   
        160
>                                                                            Key cache
hit for sstable 20134 [SharedPool-Worker-1] | 2016-05-17 11:21:26.986000 | 172.31.4.135 |
           195
>                                                                Seeking to partition beginning
in data file [SharedPool-Worker-4] | 2016-05-17 11:21:26.986000 | 172.31.15.14 |         
  468
>                                                                            reading data
from /172.31.15.14 [SharedPool-Worker-3] | 2016-05-17 11:21:26.986000 | 172.31.8.188 |   
        212
>                                                                Seeking to partition beginning
in data file [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |         
  202
>                                                                            Key cache
hit for sstable 18547 [SharedPool-Worker-4] | 2016-05-17 11:21:26.986001 | 172.31.15.14 |
           782
>                                                  Sending READ message to /172.31.4.135
[MessagingService-Outgoing-/172.31.4.135] | 2016-05-17 11:21:26.986001 | 172.31.8.188 |  
         249
>                                                                            Key cache
hit for sstable 19782 [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |
           376
>                                                                Seeking to partition beginning
in data file [SharedPool-Worker-4] | 2016-05-17 11:21:26.986001 | 172.31.15.14 |         
  792
>                                                  Sending READ message to /172.31.15.14
[MessagingService-Outgoing-/172.31.15.14] | 2016-05-17 11:21:26.986001 | 172.31.8.188 |  
         260
>                                                                Seeking to partition beginning
in data file [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |         
  388
>                                  Skipped 0/3 non-slice-intersecting sstables, included
0 due to tombstones [SharedPool-Worker-4] | 2016-05-17 11:21:26.986001 | 172.31.15.14 |  
         963
>                                                                            Key cache
hit for sstable 16500 [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |
           477
>                                                                 Merging data from memtables
and 3 sstables [SharedPool-Worker-4] | 2016-05-17 11:21:26.986001 | 172.31.15.14 |       
    973
>                                                                Seeking to partition beginning
in data file [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |         
  484
>                                  Skipped 0/4 non-slice-intersecting sstables, included
0 due to tombstones [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |  
         573
>                                                                 Merging data from memtables
and 3 sstables [SharedPool-Worker-1] | 2016-05-17 11:21:26.986001 | 172.31.4.135 |       
    582
>                                                                        Read 101 live
and 0 tombstone cells [SharedPool-Worker-1] | 2016-05-17 11:21:31.805000 | 172.31.4.135 |
        819660
>                                                                        Enqueuing response
to /172.31.8.188 [SharedPool-Worker-1] | 2016-05-17 11:21:31.831000 | 172.31.4.135 |     
   844972
>                                      Sending REQUEST_RESPONSE message to /172.31.8.188
[MessagingService-Outgoing-/172.31.8.188] | 2016-05-17 11:21:31.868000 | 172.31.4.135 |  
      882380
>                                   REQUEST_RESPONSE message received from /172.31.4.135
[MessagingService-Incoming-/172.31.4.135] | 2016-05-17 11:21:31.962000 | 172.31.8.188 |  
      976119
>                                                                     Processing response
from /172.31.4.135 [SharedPool-Worker-2] | 2016-05-17 11:21:31.962000 | 172.31.8.188 |   
     976166
>                                                                                     
                           Request c
>                                                                                     
                       omplete | 2016-05-17 11:21:32.014093 | 172.31.8.188 |          28093
> {code}
> I used jstack to get some stacks when c* is execute query like above. and found it seems
c* take a long time do the following methods:
> {code}
> "SharedPool-Worker-5" #221 daemon prio=5 os_prio=0 tid=0x00007f177517a000 nid=0x8b6 runnable
[0x00007f1471e5b000]
>    java.lang.Thread.State: RUNNABLE
>     at org.apache.cassandra.db.RangeTombstoneList.addInternal(RangeTombstoneList.java:689)
>     at org.apache.cassandra.db.RangeTombstoneList.insertFrom(RangeTombstoneList.java:649)
>     at org.apache.cassandra.db.RangeTombstoneList.add(RangeTombstoneList.java:170)
>     at org.apache.cassandra.db.RangeTombstoneList.add(RangeTombstoneList.java:142)
>     at org.apache.cassandra.db.DeletionInfo.add(DeletionInfo.java:239)
>     at org.apache.cassandra.db.ArrayBackedSortedColumns.delete(ArrayBackedSortedColumns.java:490)
>     at org.apache.cassandra.db.ColumnFamily.addAtom(ColumnFamily.java:153)
>     at org.apache.cassandra.db.filter.QueryFilter$2.getNext(QueryFilter.java:185)
>     at org.apache.cassandra.db.filter.QueryFilter$2.hasNext(QueryFilter.java:157)
>     at org.apache.cassandra.utils.MergeIterator$Candidate.advance(MergeIterator.java:146)
>     at org.apache.cassandra.utils.MergeIterator$ManyToOne.advance(MergeIterator.java:125)
>     at org.apache.cassandra.utils.MergeIterator$ManyToOne.computeNext(MergeIterator.java:99)
>     at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)
>     at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)
>     at org.apache.cassandra.db.filter.SliceQueryFilter.collectReducedColumns(SliceQueryFilter.java:264)
>     at org.apache.cassandra.db.filter.QueryFilter.collateColumns(QueryFilter.java:109)
>     at org.apache.cassandra.db.filter.QueryFilter.collateOnDiskAtom(QueryFilter.java:82)
>     at org.apache.cassandra.db.filter.QueryFilter.collateOnDiskAtom(QueryFilter.java:69)
>     at org.apache.cassandra.db.CollationController.collectAllData(CollationController.java:317)
>     at org.apache.cassandra.db.CollationController.getTopLevelColumns(CollationController.java:61)
>     at org.apache.cassandra.db.ColumnFamilyStore.getTopLevelColumns(ColumnFamilyStore.java:2011)
>     at org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore.java:1815)
>     at org.apache.cassandra.db.Keyspace.getRow(Keyspace.java:360)
>     at org.apache.cassandra.db.SliceFromReadCommand.getRow(SliceFromReadCommand.java:85)
> {code}
> I executed these query when server was on very low load.
> from the tracing it seems that something is very slow between 'Merging data from memtables
and 3 sstables' and 'Read 101 live and 0 tombstone cells'



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message