Hi Chap,

You don't indicate which version of Cassandra and what client side driver you are using, but I have seen the same behavior with Cassandra 2.0.2 and earlier versions of the Java Driver. With Cassandra 2.0.3 and the 2.0.0rc2 driver, my read timeouts are basically nonexistent at my current load levels.

Not sure how this applies if you're still on 1.x versions of Cassandra since we moved off of that branch a few months ago. Ditto for the client driver if you're using something other than the Java Driver, or the 1.x version of same. Our problems were due to changes specific to the 2.x versions only.

Steve



On Wed, Feb 5, 2014 at 2:14 PM, Chap Lovejoy <chaplovejoy@gmail.com> wrote:
Hi,

We're seeing pretty regular rpc timeout errors on what appear to be simple queries. We're running a three node cluster under pretty light load. We're averaging 30-40 writes/sec and about 8 reads/sec according to OpsCenter. The failures don't seem to be related to any changes in load. A single query repeated from CQLSH (about once a second or so) will fail approximately one out of ten times. I do see an increase in the average read latency around the time of the failure, though it's unclear if that's from the single failed request or if others are affected. This seems to happen most on a number of similarly structured tables. One is:

CREATE TABLE psr (
  inst_id bigint,
  prosp_id bigint,
  inter_id bigint,
  avail text,
  comments text,
  email text,
  first_name text,
  last_name text,
  m_id text,
  m_num text,
  phone text,
  info blob,
  status text,
  time timestamp,
  PRIMARY KEY ((inst_id, prosp_id), inter_id)
) WITH CLUSTERING ORDER BY (inter_id DESC) AND
  bloom_filter_fp_chance=0.010000 AND
  caching='KEYS_ONLY' AND
  comment='' AND
  dclocal_read_repair_chance=0.000000 AND
  gc_grace_seconds=864000 AND
  index_interval=128 AND
  read_repair_chance=0.100000 AND
  replicate_on_write='true' AND
  populate_io_cache_on_flush='false' AND
  default_time_to_live=0 AND
  speculative_retry='99.0PERCENTILE' AND
  memtable_flush_period_in_ms=0 AND
  compaction={'class': 'SizeTieredCompactionStrategy'} AND
  compression={'sstable_compression': 'LZ4Compressor'};

I'm executing the query:
SELECT inter_id FROM "psr" WHERE inst_id = 1 AND prosp_id = 127788649174986752 AND inter_id < 30273563814527279 LIMIT 10000;

Normally this query returns 32 rows. A total of 413 match the partition key.

Here is a trace for a successful run:
                                                  | timestamp    | source        | source_elapsed
--------------------------------------------------+--------------+---------------+----------------
                               execute_cql3_query | 21:52:20,831 | 10.128.32.141 |              0
             Message received from /10.128.32.141 | 21:52:20,826 | 10.128.32.140 |             69
          Executing single-partition query on psr | 21:52:20,827 | 10.128.32.140 |            502
                     Acquiring sstable references | 21:52:20,827 | 10.128.32.140 |            517
                      Merging memtable tombstones | 21:52:20,827 | 10.128.32.140 |            576
                     Key cache hit for sstable 54 | 21:52:20,827 | 10.128.32.140 |            685
Seeking to partition indexed section in data file | 21:52:20,827 | 10.128.32.140 |            697
    Skipped 1/2 non-slice-intersecting sstables,  | 21:52:20,827 | 10.128.32.140 |            751
    included 0 due to tombstones
       Merging data from memtables and 1 sstables | 21:52:20,827 | 10.128.32.140 |            773
              Read 32 live and 0 tombstoned cells | 21:52:20,828 | 10.128.32.140 |           2055
             Enqueuing response to /10.128.32.141 | 21:52:20,829 | 10.128.32.140 |           2172
                Sending message to /10.128.32.141 | 21:52:20,829 | 10.128.32.140 |           2341
                              Parsing SELECT ...  | 21:52:20,831 | 10.128.32.141 |            105
                              Preparing statement | 21:52:20,831 | 10.128.32.141 |            200
                Sending message to /10.128.32.140 | 21:52:20,831 | 10.128.32.141 |            492
             Message received from /10.128.32.140 | 21:52:20,836 | 10.128.32.141 |           5361
          Processing response from /10.128.32.140 | 21:52:20,836 | 10.128.32.141 |           5534
                                 Request complete | 21:52:20,837 | 10.128.32.141 |           6013


And here is on unsuccessful run:

                                                   | timestamp    | source        | source_elapsed
---------------------------------------------------+--------------+---------------+---------------
                                execute_cql3_query | 21:56:19,792 | 10.128.32.141 |              0
                               Parsing SELECT ...  | 21:56:19,792 | 10.128.32.141 |             69
                               Preparing statement | 21:56:19,792 | 10.128.32.141 |            160
                 Sending message to /10.128.32.137 | 21:56:19,792 | 10.128.32.141 |            509
              Message received from /10.128.32.141 | 21:56:19,793 | 10.128.32.137 |             57
           Executing single-partition query on psr | 21:56:19,794 | 10.128.32.137 |            412
                      Acquiring sstable references | 21:56:19,794 | 10.128.32.137 |            444
                       Merging memtable tombstones | 21:56:19,794 | 10.128.32.137 |            486
                      Key cache hit for sstable 59 | 21:56:19,794 | 10.128.32.137 |            555
 Seeking to partition indexed section in data file | 21:56:19,794 | 10.128.32.137 |            569
                       Key cache hit for sstable 3 | 21:56:19,794 | 10.128.32.137 |            609
 Seeking to partition indexed section in data file | 21:56:19,794 | 10.128.32.137 |            621
              Timed out; received 0 of 1 responses | 21:56:24,792 | 10.128.32.141 |        5000766
                                  Request complete | 21:56:24,792 | 10.128.32.141 |        5000888

The output of cfstats is:

                SSTable count: 3
                Space used (live), bytes: 606268
                Space used (total), bytes: 612372
                SSTable Compression Ratio: 0.4011882905126778
                Number of keys (estimate): 768
                Memtable cell count: 156
                Memtable data size, bytes: 60451
                Memtable switch count: 34
                Local read count: 1439
                Local read latency: NaN ms
                Local write count: 618
                Local write latency: NaN ms
                Pending tasks: 0
                Bloom filter false positives: 0
                Bloom filter false ratio: 0.00000
                Bloom filter space used, bytes: 1840
                Compacted partition minimum bytes: 447
                Compacted partition maximum bytes: 20501
                Compacted partition mean bytes: 3478
                Average live cells per slice (last five minutes): 0.0
                Average tombstones per slice (last five minutes): 0.0

Is there a problem with the table structure or query that would be causing these failures? Should we expect timeouts as a regular occurrence in operation and be prepared to retry every query as needed?

I'd really appreciate any input you could offer on how to improve this. These timeouts are causing some rather troublesome errors in our application.

Thank you,
Chap



--
Steve Robenalt
Software Architect
HighWire | Stanford University 
425 Broadway St, Redwood City, CA 94063 

srobenal@stanford.edu
http://highwire.stanford.edu