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 > >