Re: COUNTER timeout
Thank you!
Clocks were out of sync; chronyd wasn't chrony'ding.
Going so much faster now! Cheers.
-Joe
On 9/15/2021 4:07 PM, Bowen Song wrote:
Well, the log says cross node timeout, latency a bit over 44 seconds.
Here's a few most likely causes:
1. The clocks are not in sync - please check the time on each server,
and ensure NTP client is running on all Cassandra servers
2. Long stop the world GC pauses - please check the GC logs and make
sure this isn't the case
3. Overload - please monitor the CPU usage and disk IO when timeout
happens and make sure they are not the bottleneck
On 15/09/2021 20:34, Joe Obernberger wrote:
Thank you Erick - looking through all the logs on the nodes I found this:
INFO [CompactionExecutor:17551] 2021-09-15 15:13:20,524
CompactionTask.java:245 - Compacted
(fb0cdca0-1658-11ec-9098-dd70c3a3487a) 4 sstables to
[/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96619-big,]
to level=0. 9.762MiB to 9.672MiB (~99% of original) in 3,873ms.
Read Throughput = 2.520MiB/s, Write Throughput = 2.497MiB/s, Row
Throughput = ~125,729/s. 255,171 total partitions merged to
251,458. Partition merge counts were {1:247758, 2:3687, 3:13, }
INFO [NonPeriodicTasks:1] 2021-09-15 15:13:20,524 SSTable.java:111 -
Deleting sstable:
/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96618-big
INFO [NonPeriodicTasks:1] 2021-09-15 15:13:20,525 SSTable.java:111 -
Deleting sstable:
/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96575-big
INFO [NonPeriodicTasks:1] 2021-09-15 15:13:20,526 SSTable.java:111 -
Deleting sstable:
/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96607-big
INFO [NonPeriodicTasks:1] 2021-09-15 15:13:20,532 SSTable.java:111 -
Deleting sstable:
/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96554-big
DEBUG [epollEventLoopGroup-5-85] 2021-09-15 15:13:20,642
InitialConnectionHandler.java:121 - Response to STARTUP sent,
configuring pipeline for 5/v5
DEBUG [epollEventLoopGroup-5-85] 2021-09-15 15:13:20,643
InitialConnectionHandler.java:153 - Configured pipeline:
DefaultChannelPipeline{(frameDecoder =
org.apache.cassandra.net.FrameDecoderCrc), (frameEncoder =
org.apache.cassandra.net.FrameEncoderCrc), (cqlProcessor =
org.apache.cassandra.transport.CQLMessageHandler), (exceptionHandler
=
org.apache.cassandra.transport.ExceptionHandlers$PostV5ExceptionHandler)}
INFO [ScheduledTasks:1] 2021-09-15 15:13:21,976
MessagingMetrics.java:206 - COUNTER_MUTATION_RSP messages were
dropped in last 5000 ms: 0 internal and 1 cross node. Mean internal
dropped latency: 0 ms and Mean cross-node dropped latency: 44285 ms
So - yes, nodes are dropping mutations. I did find a node where one
of the drives was pegged. Fixed that - but it's still happening.
This happened after adding a relatively large node (.44) to the cluster:
nodetool status
Datacenter: datacenter1
===
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host
ID Rack
UN 172.16.100.251 526.35 GiB 200 35.1%
660f476c-a124-4ca0-b55f-75efe56370da rack1
UN 172.16.100.252 537.14 GiB 200 34.8%
e83aa851-69b4-478f-88f6-60e657ea6539 rack1
UN 172.16.100.249 548.82 GiB 200 34.6%
49e4f571-7d1c-4e1e-aca7-5bbe076596f7 rack1
UN 172.16.100.36 561.85 GiB 200 35.0%
d9702f96-256e-45ae-8e12-69a42712be50 rack1
UN 172.16.100.39 547.86 GiB 200 34.2%
93f9cb0f-ea71-4e3d-b62a-f0ea0e888c47 rack1
UN 172.16.100.253 11.52 GiB 4 0.7%
a1a16910-9167-4174-b34b-eb859d36347e rack1
UN 172.16.100.248 560.63 GiB 200 35.0%
4bbbe57c-6219-41e5-bbac-de92a9594d53 rack1
UN 172.16.100.44 432.76 GiB 200 34.7%
b2e5366e-8386-40ec-a641-27944a5a7cfa rack1
UN 172.16.100.37 331.31 GiB 120 20.5%
08a19658-40be-4e55-8709-812b3d4ac750 rack1
UN 172.16.100.250 501.62 GiB 200 35.3%
b74b6e65-af63-486a-b07f-9e304ec30a39 rack1
At this point I'm not sure what's going on. Some repairs have failed
over the past few days.
-Joe
On 9/14/2021 7:23 PM, Erick Ramirez wrote:
The obvious conclusion is to say that the nodes can't keep up so it
would be interesting to know how often you're issuing the counter
updates. Also, how are the commit log disks performing on the nodes?
If you have monitoring in place, check the IO stats/metrics. And
finally, review the logs on the nodes to see if they are indeed
dropping mutations. Cheers!
Virus-free. www.avg.com
<#DAB4FAD8-2DD7-40BB-A1B8-4E2AA1F9FDF2>
Re: COUNTER timeout
Well, the log says cross node timeout, latency a bit over 44 seconds.
Here's a few most likely causes:
1. The clocks are not in sync - please check the time on each server,
and ensure NTP client is running on all Cassandra servers
2. Long stop the world GC pauses - please check the GC logs and make
sure this isn't the case
3. Overload - please monitor the CPU usage and disk IO when timeout
happens and make sure they are not the bottleneck
On 15/09/2021 20:34, Joe Obernberger wrote:
Thank you Erick - looking through all the logs on the nodes I found this:
INFO [CompactionExecutor:17551] 2021-09-15 15:13:20,524
CompactionTask.java:245 - Compacted
(fb0cdca0-1658-11ec-9098-dd70c3a3487a) 4 sstables to
[/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96619-big,]
to level=0. 9.762MiB to 9.672MiB (~99% of original) in 3,873ms. Read
Throughput = 2.520MiB/s, Write Throughput = 2.497MiB/s, Row Throughput
= ~125,729/s. 255,171 total partitions merged to 251,458. Partition
merge counts were {1:247758, 2:3687, 3:13, }
INFO [NonPeriodicTasks:1] 2021-09-15 15:13:20,524 SSTable.java:111 -
Deleting sstable:
/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96618-big
INFO [NonPeriodicTasks:1] 2021-09-15 15:13:20,525 SSTable.java:111 -
Deleting sstable:
/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96575-big
INFO [NonPeriodicTasks:1] 2021-09-15 15:13:20,526 SSTable.java:111 -
Deleting sstable:
/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96607-big
INFO [NonPeriodicTasks:1] 2021-09-15 15:13:20,532 SSTable.java:111 -
Deleting sstable:
/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96554-big
DEBUG [epollEventLoopGroup-5-85] 2021-09-15 15:13:20,642
InitialConnectionHandler.java:121 - Response to STARTUP sent,
configuring pipeline for 5/v5
DEBUG [epollEventLoopGroup-5-85] 2021-09-15 15:13:20,643
InitialConnectionHandler.java:153 - Configured pipeline:
DefaultChannelPipeline{(frameDecoder =
org.apache.cassandra.net.FrameDecoderCrc), (frameEncoder =
org.apache.cassandra.net.FrameEncoderCrc), (cqlProcessor =
org.apache.cassandra.transport.CQLMessageHandler), (exceptionHandler =
org.apache.cassandra.transport.ExceptionHandlers$PostV5ExceptionHandler)}
INFO [ScheduledTasks:1] 2021-09-15 15:13:21,976
MessagingMetrics.java:206 - COUNTER_MUTATION_RSP messages were dropped
in last 5000 ms: 0 internal and 1 cross node. Mean internal dropped
latency: 0 ms and Mean cross-node dropped latency: 44285 ms
So - yes, nodes are dropping mutations. I did find a node where one
of the drives was pegged. Fixed that - but it's still happening.
This happened after adding a relatively large node (.44) to the cluster:
nodetool status
Datacenter: datacenter1
===
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host
ID Rack
UN 172.16.100.251 526.35 GiB 200 35.1%
660f476c-a124-4ca0-b55f-75efe56370da rack1
UN 172.16.100.252 537.14 GiB 200 34.8%
e83aa851-69b4-478f-88f6-60e657ea6539 rack1
UN 172.16.100.249 548.82 GiB 200 34.6%
49e4f571-7d1c-4e1e-aca7-5bbe076596f7 rack1
UN 172.16.100.36 561.85 GiB 200 35.0%
d9702f96-256e-45ae-8e12-69a42712be50 rack1
UN 172.16.100.39 547.86 GiB 200 34.2%
93f9cb0f-ea71-4e3d-b62a-f0ea0e888c47 rack1
UN 172.16.100.253 11.52 GiB 4 0.7%
a1a16910-9167-4174-b34b-eb859d36347e rack1
UN 172.16.100.248 560.63 GiB 200 35.0%
4bbbe57c-6219-41e5-bbac-de92a9594d53 rack1
UN 172.16.100.44 432.76 GiB 200 34.7%
b2e5366e-8386-40ec-a641-27944a5a7cfa rack1
UN 172.16.100.37 331.31 GiB 120 20.5%
08a19658-40be-4e55-8709-812b3d4ac750 rack1
UN 172.16.100.250 501.62 GiB 200 35.3%
b74b6e65-af63-486a-b07f-9e304ec30a39 rack1
At this point I'm not sure what's going on. Some repairs have failed
over the past few days.
-Joe
On 9/14/2021 7:23 PM, Erick Ramirez wrote:
The obvious conclusion is to say that the nodes can't keep up so it
would be interesting to know how often you're issuing the counter
updates. Also, how are the commit log disks performing on the nodes?
If you have monitoring in place, check the IO stats/metrics. And
finally, review the logs on the nodes to see if they are indeed
dropping mutations. Cheers!
Virus-free. www.avg.com
<#DAB4FAD8-2DD7-40BB-A1B8-4E2AA1F9FDF2>
Re: COUNTER timeout
Thank you Erick - looking through all the logs on the nodes I found this:
INFO [CompactionExecutor:17551] 2021-09-15 15:13:20,524
CompactionTask.java:245 - Compacted
(fb0cdca0-1658-11ec-9098-dd70c3a3487a) 4 sstables to
[/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96619-big,]
to level=0. 9.762MiB to 9.672MiB (~99% of original) in 3,873ms. Read
Throughput = 2.520MiB/s, Write Throughput = 2.497MiB/s, Row Throughput =
~125,729/s. 255,171 total partitions merged to 251,458. Partition
merge counts were {1:247758, 2:3687, 3:13, }
INFO [NonPeriodicTasks:1] 2021-09-15 15:13:20,524 SSTable.java:111 -
Deleting sstable:
/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96618-big
INFO [NonPeriodicTasks:1] 2021-09-15 15:13:20,525 SSTable.java:111 -
Deleting sstable:
/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96575-big
INFO [NonPeriodicTasks:1] 2021-09-15 15:13:20,526 SSTable.java:111 -
Deleting sstable:
/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96607-big
INFO [NonPeriodicTasks:1] 2021-09-15 15:13:20,532 SSTable.java:111 -
Deleting sstable:
/data/7/cassandra/data/doc/fieldcounts-03b67080ada111ebade9fdc1d34336d3/nb-96554-big
DEBUG [epollEventLoopGroup-5-85] 2021-09-15 15:13:20,642
InitialConnectionHandler.java:121 - Response to STARTUP sent,
configuring pipeline for 5/v5
DEBUG [epollEventLoopGroup-5-85] 2021-09-15 15:13:20,643
InitialConnectionHandler.java:153 - Configured pipeline:
DefaultChannelPipeline{(frameDecoder =
org.apache.cassandra.net.FrameDecoderCrc), (frameEncoder =
org.apache.cassandra.net.FrameEncoderCrc), (cqlProcessor =
org.apache.cassandra.transport.CQLMessageHandler), (exceptionHandler =
org.apache.cassandra.transport.ExceptionHandlers$PostV5ExceptionHandler)}
INFO [ScheduledTasks:1] 2021-09-15 15:13:21,976
MessagingMetrics.java:206 - COUNTER_MUTATION_RSP messages were dropped
in last 5000 ms: 0 internal and 1 cross node. Mean internal dropped
latency: 0 ms and Mean cross-node dropped latency: 44285 ms
So - yes, nodes are dropping mutations. I did find a node where one of
the drives was pegged. Fixed that - but it's still happening. This
happened after adding a relatively large node (.44) to the cluster:
nodetool status
Datacenter: datacenter1
===
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host
ID Rack
UN 172.16.100.251 526.35 GiB 200 35.1%
660f476c-a124-4ca0-b55f-75efe56370da rack1
UN 172.16.100.252 537.14 GiB 200 34.8%
e83aa851-69b4-478f-88f6-60e657ea6539 rack1
UN 172.16.100.249 548.82 GiB 200 34.6%
49e4f571-7d1c-4e1e-aca7-5bbe076596f7 rack1
UN 172.16.100.36 561.85 GiB 200 35.0%
d9702f96-256e-45ae-8e12-69a42712be50 rack1
UN 172.16.100.39 547.86 GiB 200 34.2%
93f9cb0f-ea71-4e3d-b62a-f0ea0e888c47 rack1
UN 172.16.100.253 11.52 GiB 4 0.7%
a1a16910-9167-4174-b34b-eb859d36347e rack1
UN 172.16.100.248 560.63 GiB 200 35.0%
4bbbe57c-6219-41e5-bbac-de92a9594d53 rack1
UN 172.16.100.44 432.76 GiB 200 34.7%
b2e5366e-8386-40ec-a641-27944a5a7cfa rack1
UN 172.16.100.37 331.31 GiB 120 20.5%
08a19658-40be-4e55-8709-812b3d4ac750 rack1
UN 172.16.100.250 501.62 GiB 200 35.3%
b74b6e65-af63-486a-b07f-9e304ec30a39 rack1
At this point I'm not sure what's going on. Some repairs have failed
over the past few days.
-Joe
On 9/14/2021 7:23 PM, Erick Ramirez wrote:
The obvious conclusion is to say that the nodes can't keep up so it
would be interesting to know how often you're issuing the counter
updates. Also, how are the commit log disks performing on the nodes?
If you have monitoring in place, check the IO stats/metrics. And
finally, review the logs on the nodes to see if they are indeed
dropping mutations. Cheers!
Virus-free. www.avg.com
<#DAB4FAD8-2DD7-40BB-A1B8-4E2AA1F9FDF2>
Re: TWCS on Non TTL Data
You may try roll up the data, i.e. a table only 1 month data, old data roll up to a table keep a year data. Thanks, Jim On Wed, Sep 15, 2021 at 1:26 AM Isaeed Mohanna wrote: > My cluster column is the time series timestamp, so basically sourceId, > metric type for partition key and timestamp for the clustering key the rest > of the fields are just values outside of the primary key. Our reads request > are simply give me values for a time range of a specific sourceId,Metric > combination. So I am guess that during read the sstables that contain the > partition key will be found and out of those the ones that are out of the > range will be excluded, correct? > > In practice our queries are up to a month by default, only rarely we fetch > more when someone is exporting the data or so. > > > > In reality also we get old data, that is a source will send its > information late instead of sending it in realtime it will send all last > month\week\day data at once, in that case I guess the data will end up in > current bucket, will that affect performance? > > > > Assuming I start with a 1 week bucket, I could later change the time > window right? > > > > Thanks > > > > > > *From:* Jeff Jirsa > *Sent:* Tuesday, September 14, 2021 10:35 PM > *To:* cassandra > *Subject:* Re: TWCS on Non TTL Data > > > > Inline > > > > On Tue, Sep 14, 2021 at 11:47 AM Isaeed Mohanna wrote: > > Hi Jeff > > My data is partitioned by a sourceId and metric, a source is usually > active up to a year after which there is no additional writes for the > partition, and reads become scarce, so although this is not an explicit > time component, its time based, will that suffice? > > > > I guess it means that a single read may touch a year of sstables. Not > great, but perhaps not fatal. Hopefully your reads avoid that in practice. > We'd need the full schema to be very sure (does clustering column include > month/day? if so, there are cases where that can help exclude sstables) > > > > > > If I use a week bucket we will be able to serve last few days reads from > one file and last month from ~5 which is the most common queries, do u > think doing a months bucket a good idea? That will allow reading from one > file most of the time but the size of each SSTable will be ~5 times bigger > > > > It'll be 1-4 for most common (up to 4 for same bucket reads because STCS > in the first bucket is triggered at min_threshold=4), and 5 max, seems > reasonable. Way better than the 200 or so you're doing now. > > > > > > When changing the compaction strategy via JMX, do I need to issue the > alter table command at the end so it will be reflected in the schema or is > it taking care of automatically? (I am using cassandra 3.11.11) > > > > > > At the end, yes. > > > > Thanks a lot for your help. > > > > > > > > > > > > > > > > > > *From:* Jeff Jirsa > *Sent:* Tuesday, September 14, 2021 4:51 PM > *To:* cassandra > *Subject:* Re: TWCS on Non TTL Data > > > > > > > > On Tue, Sep 14, 2021 at 5:42 AM Isaeed Mohanna wrote: > > Hi > > I have a table that stores time series data, the data is not TTLed since > we want to retain the data for the foreseeable future, and there are no > updates or deletes. (deletes could happens rarely in case some scrambled > data reached the table, but its extremely rare). > > Usually we do constant write of incoming data to the table ~ 5 milion a > day, mostly newly generated data in the past week, but we also get old data > that got stuck somewhere but not that often. Usually our reads are for the > most recent data last month – three. But we do fetch old data as well in a > specific time period in the past. > > Lately we have been facing performance trouble with this table see > histogram below, When compaction is working on the table the performance > even drops to 10-20 seconds!! > > Percentile SSTables Write Latency Read LatencyPartition > SizeCell Count > > (micros) (micros) (bytes) > > 50% 215.00 17.08 89970.66 > 1916 149 > > 75% 446.00 24.60 223875.79 > 2759 215 > > 95% 535.00 35.43 464228.84 > 8239 642 > > 98% 642.00 51.01 668489.53 > 24601 1916 > > 99% 642.00 73.46 962624.93 > 42510 3311 > > Min 0.00 2.30 10090.81 > 43 0 > > Max 770.00 1358.102395318.86 > 5839588454826 > > > > As u can see we are scaning hundreds of sstables, turns out we are using > DTCS (min:4,max32) , the table folder contains ~33K files of ~130GB per > node (cleanup pending after increasing the cluster), And compaction takes a > very long time to complete. > > As I understood DTCS is deprecated so my questions > >1. should we switch to TWCS even though our data is
Re: COUNTER timeout
Check the logs on the Cassandra servers first. Many different things can
cause the same result, and you will have to dig in deeper to discover
the true cause.
On 14/09/2021 23:55, Joe Obernberger wrote:
I'm getting a lot of the following errors during ingest of data:
com.datastax.oss.driver.api.core.servererrors.WriteTimeoutException:
Cassandra timeout during COUNTER write query at consistency ONE (1
replica were required but only 0 acknowledged the write)
at
com.datastax.oss.driver.api.core.servererrors.WriteTimeoutException.copy(WriteTimeoutException.java:96)
at
com.datastax.oss.driver.internal.core.util.concurrent.CompletableFutures.getUninterruptibly(CompletableFutures.java:149)
at
com.datastax.oss.driver.internal.core.cql.CqlRequestSyncProcessor.process(CqlRequestSyncProcessor.java:53)
at
com.datastax.oss.driver.internal.core.cql.CqlRequestSyncProcessor.process(CqlRequestSyncProcessor.java:30)
at
com.datastax.oss.driver.internal.core.session.DefaultSession.execute(DefaultSession.java:230)
at
com.datastax.oss.driver.api.core.cql.SyncCqlSession.execute(SyncCqlSession.java:54)
The CQL being executed is:
"update doc.seq set doccount=doccount+? where id=?"
Table is:
CREATE TABLE doc.seq (
id text PRIMARY KEY,
doccount counter
) WITH additional_write_policy = '99p'
AND bloom_filter_fp_chance = 0.01
AND caching = {'keys': 'ALL', 'rows_per_partition': 'NONE'}
AND cdc = false
AND comment = ''
AND compaction = {'class':
'org.apache.cassandra.db.compaction.SizeTieredCompactionStrategy',
'max_threshold': '32', 'min_threshold': '4'}
AND compression = {'chunk_length_in_kb': '16', 'class':
'org.apache.cassandra.io.compress.LZ4Compressor'}
AND crc_check_chance = 1.0
AND default_time_to_live = 0
AND extensions = {}
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 = 'BLOCKING'
AND speculative_retry = '99p';
Total rows in the doc.seq table is 356. What could cause this timeout
error?
Thank you!
-Joe
