cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Stefania (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (CASSANDRA-13120) Trace and Histogram output misleading
Date Mon, 22 May 2017 01:00:29 GMT

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

Stefania commented on CASSANDRA-13120:
--------------------------------------

bq. Right now, what CFHistograms expose is the number of SSTables on which we do a partition
lookup.

Except it has never been documented, as far as I can see neither the [ASF docs|http://cassandra.apache.org/doc/latest/tools/nodetool/tablehistograms.html]
nor the [DS docs|http://docs.datastax.com/en/cassandra/3.0/cassandra/tools/toolsTablehisto.html]
say what the number of sstables actually is  and [people|https://www.smartcat.io/blog/2017/where-is-my-data-debugging-sstables-in-cassandra/]
tend to think this is the number of sstables it touches on each read, so it is very misleading.
Our own comment says {{/** Histogram of the number of sstable data files accessed per read
*/}}, which to me would indicate that if the BF excludes a table then it should not be counted.
We should at a minimum improve our own comments.

bq. keep the metric as it is and to add a new one mergedSSTable to track how many SSTables
have been actually merged.

Are we thinking of a new metrics histogram? I'm not opposed, as long as we document {{nodetool
\[cf|table\]histograms}} accordingly. My only concern is that adding a new histogram on each
read may have a performance impact - but I do understand if we don't want to change the existing
behavior, especially in 3.0.



> Trace and Histogram output misleading
> -------------------------------------
>
>                 Key: CASSANDRA-13120
>                 URL: https://issues.apache.org/jira/browse/CASSANDRA-13120
>             Project: Cassandra
>          Issue Type: Bug
>          Components: Core
>            Reporter: Adam Hattrell
>            Assignee: Benjamin Lerer
>            Priority: Minor
>
> If we look at the following output:
> {noformat}
> [centos@cassandra-c-3]$ nodetool getsstables -- keyspace table 60ea4399-6b9f-4419-9ccb-ff2e6742de10
> /mnt/cassandra/data/data/keyspace/table-62f30431acf411e69a4ed7dd11246f8a/mc-647146-big-Data.db
> /mnt/cassandra/data/data/keyspace/table-62f30431acf411e69a4ed7dd11246f8a/mc-647147-big-Data.db
> /mnt/cassandra/data/data/keyspace/table-62f30431acf411e69a4ed7dd11246f8a/mc-647145-big-Data.db
> /mnt/cassandra/data/data/keyspace/table-62f30431acf411e69a4ed7dd11246f8a/mc-647152-big-Data.db
> /mnt/cassandra/data/data/keyspace/table-62f30431acf411e69a4ed7dd11246f8a/mc-647157-big-Data.db
> /mnt/cassandra/data/data/keyspace/table-62f30431acf411e69a4ed7dd11246f8a/mc-648137-big-Data.db
> {noformat}
> We can see that this key value appears in just 6 sstables.  However, when we run a select
against the table and key we get:
> {noformat}
> Tracing session: a6c81330-d670-11e6-b00b-c1d403fd6e84
>  activity                                                                           
                              | timestamp                  | source         | source_elapsed
> -------------------------------------------------------------------------------------------------------------------+----------------------------+----------------+----------------
>                                                                                     
           Execute CQL3 query | 2017-01-09 13:36:40.419000 | 10.200.254.141 |            
 0
>  Parsing SELECT * FROM keyspace.table WHERE id = 60ea4399-6b9f-4419-9ccb-ff2e6742de10;
[SharedPool-Worker-2]       | 2017-01-09 13:36:40.419000 | 10.200.254.141 |            104
>                                                                          Preparing statement
[SharedPool-Worker-2] | 2017-01-09 13:36:40.419000 | 10.200.254.141 |            220
>                                         Executing single-partition query on table [SharedPool-Worker-1]
           | 2017-01-09 13:36:40.419000 | 10.200.254.141 |            450
>                                                                 Acquiring sstable references
[SharedPool-Worker-1] | 2017-01-09 13:36:40.419000 | 10.200.254.141 |            477
>                                                  Bloom filter allows skipping sstable
648146 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419000 | 10.200.254.141 |            496
>                                                  Bloom filter allows skipping sstable
648145 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419001 | 10.200.254.141 |            503
>                                                             Key cache hit for sstable
648140 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419001 | 10.200.254.141 |            513
>                                                  Bloom filter allows skipping sstable
648135 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419001 | 10.200.254.141 |            520
>                                                  Bloom filter allows skipping sstable
648130 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419001 | 10.200.254.141 |            526
>                                                  Bloom filter allows skipping sstable
648048 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419001 | 10.200.254.141 |            530
>                                                  Bloom filter allows skipping sstable
647749 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419001 | 10.200.254.141 |            535
>                                                  Bloom filter allows skipping sstable
647404 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419001 | 10.200.254.141 |            540
>                                                             Key cache hit for sstable
647145 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419001 | 10.200.254.141 |            548
>                                                             Key cache hit for sstable
647146 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419001 | 10.200.254.141 |            556
>                                                             Key cache hit for sstable
647147 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419002 | 10.200.254.141 |            564
>                                                  Bloom filter allows skipping sstable
647148 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419002 | 10.200.254.141 |            570
>                                                  Bloom filter allows skipping sstable
647149 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419002 | 10.200.254.141 |            575
>                                                  Bloom filter allows skipping sstable
647150 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419002 | 10.200.254.141 |            580
>                                                  Bloom filter allows skipping sstable
647151 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419002 | 10.200.254.141 |            585
>                                                             Key cache hit for sstable
647152 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419002 | 10.200.254.141 |            591
>                                                  Bloom filter allows skipping sstable
647153 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419002 | 10.200.254.141 |            597
>                                                  Bloom filter allows skipping sstable
647154 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419002 | 10.200.254.141 |            601
>                                                  Bloom filter allows skipping sstable
647155 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419002 | 10.200.254.141 |            606
>                                                  Bloom filter allows skipping sstable
647156 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419002 | 10.200.254.141 |            611
>                                                             Key cache hit for sstable
647157 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419002 | 10.200.254.141 |            617
>                                                  Bloom filter allows skipping sstable
647158 [SharedPool-Worker-1] | 2017-01-09 13:36:40.419003 | 10.200.254.141 |            623
>                   Skipped 0/22 non-slice-intersecting sstables, included 0 due to tombstones
[SharedPool-Worker-1] | 2017-01-09 13:36:40.419003 | 10.200.254.141 |            644
>                                                  Merging data from memtables and 22 sstables
[SharedPool-Worker-1] | 2017-01-09 13:36:40.419003 | 10.200.254.141 |            654
>                                                            Read 9 live and 0 tombstone
cells [SharedPool-Worker-1] | 2017-01-09 13:36:40.419003 | 10.200.254.141 |            732
>                                                                                     
             Request complete | 2017-01-09 13:36:40.419808 | 10.200.254.141 |            808
> {noformat}
> You'll note we claim not to have skipped any files due to bloom filters - even though
we know the data is only in 6 files.
> CFHistograms also report that we're hitting every sstables:
> {noformat}
> Percentile SSTables Write Latency Read Latency Partition Size Cell Count 
> (micros) (micros) (bytes) 
> 50% 24.00 14.24 182.79 103 1 
> 75% 24.00 17.08 315.85 149 2 
> 95% 24.00 20.50 7007.51 372 7 
> 98% 24.00 24.60 10090.81 642 12 
> 99% 24.00 29.52 12108.97 770 14 
> Min 21.00 3.31 29.52 43 0 
> Max 29.00 1358.10 62479.63 1597 35
> {noformat}
> Code for the read is here:
> https://github.com/apache/cassandra/blob/cassandra-3.0/src/java/org/apache/cassandra/db/SinglePartitionReadCommand.java#L561
> We seem to iterate over all the sstables and increment the metric as part of that iteration.
> Either the reporting is incorrect - or we should maybe check the bloom filters first
and then iterate the tombstones after?  
> In this particular case we were using TWCS which makes the problem more apparent.  TWCS
guarantees that we'll keep more sstables in an un-merged state.  With STCS we have to search
them all, but most of them should be merged together if Compaction is keeping up.  LCS the
read path is restricted which will disguise the impact.



--
This message was sent by Atlassian JIRA
(v6.3.15#6346)

---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@cassandra.apache.org
For additional commands, e-mail: commits-help@cassandra.apache.org


Mime
View raw message