Could you decrease chunk_length_in_kb to 16 or 8 and repeat the test.
On Wed, Sep 5, 2018, 5:51 AM wxn...@zjqunshuo.com <wxn...@zjqunshuo.com>
wrote:
> How large is your row? You may meet reading wide row problem.
>
> -Simon
>
> *From:* Laxmikant Upadhyay <laxmikant....@gmail.com>
> *Date:* 2018-09-05 01:01
> *To:* user <user@cassandra.apache.org>
> *Subject:* High IO and poor read performance on 3.11.2 cassandra cluster
> 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
>
>
