Here's a sample request trace (Cassandra 1.2.1), where there's a gap of
almost 60ms between one of the two local quorum nodes receiving a message
and the row cache getting hit. There's then a further almost 60ms delay
between the response enqueue and the actual send. Please see 54.234.178.159 in
the trace below. My question is what (besides GC pauses) could be causing
this? There was no load on the nodes during this request.
Thanks.
tracing on;
CONSISTENCY LOCAL_QUORUM;
select * from "Account" where key = 'AXNB7rW9q7l4dqOT4gNkcwfU767fcFtW';
Now tracing requests.
Consistency level set to LOCAL_QUORUM.
key | name
----------------------------------+--------------
AXNB7rW9q7l4dqOT4gNkcwfU767fcFtW | juicy
Tracing session: 47aaf840-7fa3-11e2-98e2-bbb3d297e375
activity | timestamp | source |
source_elapsed
------------------------------------------+--------------+----------------+----------------
execute_cql3_query | 23:30:03,354 | 107.20.35.23 |
0
Parsing statement | 23:30:03,354 | 107.20.35.23 |
40
Peparing statement | 23:30:03,354 | 107.20.35.23 |
190
Sending message to /10.87.26.112 | 23:30:03,354 | 107.20.35.23 |
435
Sending message to /10.35.85.85 | 23:30:03,354 | 107.20.35.23 |
571
Message received from /23.22.38.255 | 23:30:03,356 | 107.20.35.23 |
2754
Processing response from /23.22.38.255 | 23:30:03,356 | 107.20.35.23 |
2862
Message received from /107.20.35.23 | 23:30:03,356 | 23.22.38.255 |
44
Row cache hit | 23:30:03,356 | 23.22.38.255 |
203
Enqueuing response to /107.20.35.23 | 23:30:03,356 | 23.22.38.255 |
281
Sending message to /10.169.19.28 | 23:30:03,356 | 23.22.38.255 |
384
Message received from /107.20.35.23 | 23:30:03,356 | 54.234.178.159 |
20
Row cache hit | 23:30:03,415 | 54.234.178.159 |
59441
Enqueuing response to /107.20.35.23 | 23:30:03,415 | 54.234.178.159 |
59554
Sending message to /10.169.19.28 | 23:30:03,475 | 54.234.178.159 |
119282
Message received from /54.234.178.159 | 23:30:03,476 | 107.20.35.23 |
122085
Processing response from /54.234.178.159 | 23:30:03,476 | 107.20.35.23 |
122226
Request complete | 23:30:03,476 | 107.20.35.23 |
122399
EC2 IP mapping:
10.35.85.85 = 54.234.178.159
10.87.26.112 = 23.22.38.255
--
-ilya
