We have 3 node cassandra cluster (3.11.2) in single dc.

We have written 450 million records on the table with LCS. The write
latency is fine.  After write we perform read and update operations.

When we run read+update operations on newly inserted 1 million records (on
top of 450 m records) then the read latency and io usage is under control.
However when we perform read+update on old 1 million records which are part
of 450 million records we observe high read latency (The performance goes
down by 4 times in comparison 1st case ).  We have not observed major gc
pauses.

*system information:*
*cpu core :*  24
*disc type : *ssd . we are using raid with deadline schedular
*disk space:*
df -h :
Filesystem                      Size  Used Avail Use% Mounted on
/dev/sdb1                        1.9T  393G  1.5T  22% /var/lib/cassandra
*memory:*
free -g
              total        used        free      shared  buff/cache
 available
Mem:             62          30           0           0          32
  31
Swap:             8           0           8

==========================================

*schema*

desc table ks.xyz;

CREATE TABLE ks.xyz (
    key text,
    column1 text,
    value text,
    PRIMARY KEY (key, column1)
) WITH COMPACT STORAGE
    AND CLUSTERING ORDER BY (column1 ASC)
    AND bloom_filter_fp_chance = 0.1
    AND caching = {'keys': 'ALL', 'rows_per_partition': 'NONE'}
    AND comment = ''
    AND compaction = {'class':
'org.apache.cassandra.db.compaction.LeveledCompactionStrategy'}
    AND compression = {'chunk_length_in_kb': '64', 'class':
'org.apache.cassandra.io.compress.LZ4Compressor'}
    AND crc_check_chance = 1.0
    AND dclocal_read_repair_chance = 0.0
    AND default_time_to_live = 0
    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 = '99PERCENTILE';
==============================================================================
Below is some system stats snippet when read operations was running:

*iotop -o * : Observation : the disk read goes up to 5.5 G/s

Total DISK READ :       *3.86 G/s* | Total DISK WRITE :    1252.88 K/s
Actual DISK READ:      * 3.92 G/s* | Actual DISK WRITE:       0.00 B/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND
10715 be/4 cassandr  375.89 M/s   99.79 K/s  0.00 % 29.15 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/
10714 be/4 cassandr  358.56 M/s  107.18 K/s  0.00 % 27.06 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/
10712 be/4 cassandr  351.86 M/s  147.83 K/s  0.00 % 25.02 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/
10718 be/4 cassandr  359.82 M/s  110.87 K/s  0.00 % 24.49 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/
10711 be/4 cassandr  333.03 M/s  125.66 K/s  0.00 % 23.37 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/
10716 be/4 cassandr  330.80 M/s  103.48 K/s  0.00 % 23.02 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/
10717 be/4 cassandr  319.49 M/s  118.27 K/s  0.00 % 22.11 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/
10713 be/4 cassandr  300.62 M/s  118.27 K/s  0.00 % 21.65 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/
10719 be/4 cassandr  294.98 M/s   81.31 K/s  0.00 % 21.60 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/
10720 be/4 cassandr  289.00 M/s   73.92 K/s  0.00 % 21.45 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/
10742 be/4 cassandr  240.98 M/s   81.31 K/s  0.00 % 17.68 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/
10743 be/4 cassandr  224.43 M/s   36.96 K/s  0.00 % 17.57 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/
10744 be/4 cassandr  113.29 M/s   14.78 K/s  0.00 % 10.22 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/
10745 be/4 cassandr   61.63 M/s   33.26 K/s  0.00 %  4.20 % java
-Dorg.xerial.snappy.tempdir=/var/tmp
-Dja~etrics-core-3.1.0.jar:/usr/share/cassandra/lib/

==================================================================================================
*iostats -x 5*

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
                     2.35    0.00    7.09       *11.26 *   0.00   79.30

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz
avgqu-sz   await r_await w_await  svctm  %util
sdb             205.60     0.00 5304.60    3.00 3707651.20  2450.40
1398.03    11.37    2.14    2.14    0.67   0.18  93.60


avg-cpu:  %user   %nice %system %iowait  %steal   %idle
                       2.99    0.00    7.49       *10.95*    0.00   78.56

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz
avgqu-sz   await r_await w_await  svctm  %util
sdb             228.00     0.00 5639.40    4.80 3947922.40  1348.00
1399.41    12.65    2.24    2.25    0.46   0.17  94.00

==================================================================================================
*nodetool info*
ID                     : ddab003d-41d1-413e-ace2-87ccd34229d5
Gossip active          : true
Thrift active          : false
Native Transport active: true
Load                   : 391.58 GiB
Generation No          : 1536065356
Uptime (seconds)       : 4714
Heap Memory (MB)       : 5172.52 / 13312.00
Off Heap Memory (MB)   : 2288.28
Data Center            : DC1
Rack                   : RAC1
Exceptions             : 0
Key Cache              : entries 1604008, size 167.04 MiB, capacity 256
MiB, 3615 hits, 1801574 requests, 0.002 recent hit rate, 14400 save period
in seconds
Row Cache              : entries 0, size 0 bytes, capacity 0 bytes, 0 hits,
0 requests, NaN recent hit rate, 0 save period in seconds
Counter Cache          : entries 0, size 0 bytes, capacity 50 MiB, 0 hits,
0 requests, NaN recent hit rate, 7200 save period in seconds
Chunk Cache            : entries 7680, size 480 MiB, capacity 480 MiB,
1399440 misses, 2338352 requests, 0.402 recent hit rate, 2760.976
microseconds miss latency
Percent Repaired       : 1.6357850897532832E-8%
Token                  : (invoke with -T/--tokens to see all 256 tokens)

=============================================================================

*nodetool tablehistograms ks xyz  :  *Observation : not a wide row
ks/xyz histograms
Percentile  SSTables     Write Latency      Read Latency    Partition Size
      Cell Count
                              (micros)          (micros)           (bytes)
50%             1.00             17.08           5839.59              1109
              17
75%             1.00             20.50           *7007.51 *
1331                24
95%             2.00             29.52          *12108.97 *
1331                24
98%             2.00             35.43          14530.76              1331
              24
99%             2.00             42.51          17436.92              1331
              24
Min             1.00              5.72            105.78               150
               2
Max             2.00            315.85         464228.84              1916
              35

*nodetool tablehistograms ks xyz*
ks/xyz histograms
Percentile  SSTables     Write Latency      Read Latency    Partition Size
      Cell Count
                              (micros)          (micros)           (bytes)
50%             1.00             17.08           5839.59              1109
              17
75%             1.00             20.50           7007.51              1331
              24
95%             2.00             29.52          12108.97              1331
              24
98%             2.00             35.43          14530.76              1331
              24
99%             2.00             42.51          17436.92              1331
              24
Min             1.00              4.77            105.78               150
               2
Max             2.00            315.85         464228.84              1916
              35



======================================================================

*nodetool tpstats*

Pool Name                         Active   Pending      Completed
 Blocked  All time blocked
ReadStage                              3         1        1603986
 0                 0
MiscStage                              0         0              0
 0                 0
CompactionExecutor                     0         0           6670
 0                 0
MutationStage                          0         0        5044371
 0                 0
MemtableReclaimMemory                  0         0             57
 0                 0
PendingRangeCalculator                 0         0              3
 0                 0
GossipStage                            0         0          14299
 0                 0
SecondaryIndexManagement               0         0              0
 0                 0
HintsDispatcher                        0         0              0
 0                 0
RequestResponseStage                   0         1        3867575
 0                 0
Native-Transport-Requests              3         0        2319802
 0                 0
ReadRepairStage                        0         0          13281
 0                 0
CounterMutationStage                   0         0              0
 0                 0
MigrationStage                         0         0              2
 0                 0
MemtablePostFlush                      0         0             65
 0                 0
PerDiskMemtableFlushWriter_0           0         0             57
 0                 0
ValidationExecutor                     0         0              0
 0                 0
Sampler                                0         0              0
 0                 0
MemtableFlushWriter                    0         0             57
 0                 0
InternalResponseStage                  0         0              0
 0                 0
ViewMutationStage                      0         0              0
 0                 0
AntiEntropyStage                       0         0              0
 0                 0
CacheCleanupExecutor                   0         0              0
 0                 0

Message type           Dropped
READ                         0
RANGE_SLICE                  0
_TRACE                       0
HINT                         0
MUTATION                     0
COUNTER_MUTATION             0
BATCH_STORE                  0
BATCH_REMOVE                 0
REQUEST_RESPONSE             0
PAGED_RANGE                  0
READ_REPAIR                  0

=====================================================================

*notetool compactionstats*
pending tasks: 0

==============================================================================
*debug.log Snippent*


WARN  [PERIODIC-COMMIT-LOG-SYNCER] 2018-09-04 19:39:51,057
NoSpamLogger.java:94 - Out of 29 commit log syncs over the past 263.94s
with average duration of 15.17ms, 2 have exceeded the configured commit
interval by an average of 20.32ms
DEBUG [COMMIT-LOG-ALLOCATOR] 2018-09-04 19:39:53,015
AbstractCommitLogSegmentManager.java:109 - No segments in reserve; creating
a fresh one
DEBUG [SlabPoolCleaner] 2018-09-04 19:39:59,659 ColumnFamilyStore.java:1308
- Flushing largest CFS(Keyspace='system', ColumnFamily='batches') to free
up room. Used total: 0.33/0.00, live: 0.33/0.00, flushing: 0.00/0.00, this:
0.13/0.00
DEBUG [SlabPoolCleaner] 2018-09-04 19:39:59,659 ColumnFamilyStore.java:918
- Enqueuing flush of batches: 128.567MiB (13%) on-heap, 0.000KiB (0%)
off-heap
DEBUG [PerDiskMemtableFlushWriter_0:12] 2018-09-04 19:39:59,685
Memtable.java:456 - Writing Memtable-batches@1450035834(78.630MiB
serialized bytes, 125418 ops, 13%/0% of on/off-heap limit), flushed range =
(null, null]
DEBUG [PerDiskMemtableFlushWriter_0:12] 2018-09-04 19:39:59,695
Memtable.java:485 - Completed flushing
/var/lib/cassandra/data/system/batches-919a4bc57a333573b03e13fc3f68b465/mc-16-big-Data.db
(0.000KiB) for commitlog position
CommitLogPosition(segmentId=1536065319618, position=7958044)
DEBUG [MemtableFlushWriter:12] 2018-09-04 19:39:59,695
ColumnFamilyStore.java:1216 - Flushed to [] (0 sstables, 0.000KiB), biggest
0.000KiB, smallest 8589934592.000GiB
DEBUG [ScheduledTasks:1] 2018-09-04 19:40:15,710 MonitoringTask.java:173 -
2 operations were slow in the last 4999 msecs:
<SELECT * FROM ks1.abc WHERE key = 12345 LIMIT 5000>, time 575 msec - slow
timeout 500 msec/cross-node
<SELECT * FROM ks.xyz WHERE key = key1 LIMIT 5000>, time 645 msec - slow
timeout 500 msec/cross-node
DEBUG [COMMIT-LOG-ALLOCATOR] 2018-09-04 19:40:20,475
AbstractCommitLogSegmentManager.java:109 - No segments in reserve; creating
a fresh one
DEBUG [COMMIT-LOG-ALLOCATOR] 2018-09-04 19:40:46,675
AbstractCommitLogSegmentManager.java:109 - No segments in reserve; creating
a fresh one
DEBUG [SlabPoolCleaner] 2018-09-04 19:41:04,976 ColumnFamilyStore.java:1308
- Flushing largest CFS(Keyspace='ks', ColumnFamily='xyz') to free up room.
Used total: 0.33/0.00, live: 0.33/0.00, flushing: 0.00/0.00, this: 0.12/0.00
DEBUG [SlabPoolCleaner] 2018-09-04 19:41:04,977 ColumnFamilyStore.java:918
- Enqueuing flush of xyz: 121.374MiB (12%) on-heap, 0.000KiB (0%) off-heap

*Observation :*  frequent "operations were slow in the last " (for select
queries) and "WARN: commit log syncs over the past"
===================================================

*notetool tablestats -H  ks.xyz <http://ks.xyz>;*
Total number of tables: 89
----------------
Keyspace : ks
        Read Count: 1439722
        Read Latency: 1.8982509581710914 ms
        Write Count: 4222811
        Write Latency: 0.016324778684151386 ms
        Pending Flushes: 0
                Table: xyz
                SSTable count: 1036
                SSTables in each level: [1, 10, 116/100, 909, 0, 0, 0, 0, 0]
                Space used (live): 187.09 GiB
                Space used (total): 187.09 GiB
                Space used by snapshots (total): 0 bytes
                Off heap memory used (total): 783.93 MiB
                SSTable Compression Ratio: 0.3238726404414842
                Number of partitions (estimate): 447095605
                Memtable cell count: 306194
                Memtable data size: 20.59 MiB
                Memtable off heap memory used: 0 bytes
                Memtable switch count: 7
                Local read count: 1440322
                Local read latency: 6.785 ms
                Local write count: 1408204
                Local write latency: 0.021 ms
                Pending flushes: 0
                Percent repaired: 0.0
                Bloom filter false positives: 19
                Bloom filter false ratio: 0.00003
                Bloom filter space used: 418.2 MiB
                Bloom filter off heap memory used: 418.19 MiB
                Index summary off heap memory used: 307.75 MiB
                Compression metadata off heap memory used: 57.99 MiB
                Compacted partition minimum bytes: 150
                Compacted partition maximum bytes: 1916
                Compacted partition mean bytes: 1003
                Average live cells per slice (last five minutes): 20.0
                Maximum live cells per slice (last five minutes): 20
                Average tombstones per slice (last five minutes): 1.0
                Maximum tombstones per slice (last five minutes): 1
                Dropped Mutations: 0 bytes

-- 

regards,
Laxmikant Upadhyay

Reply via email to