dan jatnieks created CASSANDRA-6823:
---------------------------------------
Summary: TimedOutException/dropped mutations running stress on 2.1
Key: CASSANDRA-6823
URL: https://issues.apache.org/jira/browse/CASSANDRA-6823
Project: Cassandra
Issue Type: Bug
Reporter: dan jatnieks
Priority: Minor
Attachments: stress.log, system.log
While testing CASSANDRA-6357, I am seeing TimedOutException errors running
stress on both 2.1 and trunk, and system log is showing dropped mutation
messages.
{noformat}
$ ant -Dversion=2.1.0-SNAPSHOT jar
$ ./bin/cassandra
$ ./cassandra-2.1/tools/bin/cassandra-stress write n=10000000
Created keyspaces. Sleeping 1s for propagation.
Warming up WRITE with 50000 iterations...
Connected to cluster: Test Cluster
Datatacenter: datacenter1; Host: localhost/127.0.0.1; Rack: rack1
Sleeping 2s...
Running WRITE with 50 threads for 10000000 iterations
ops , op/s,adj op/s, key/s, mean, med, .95, .99,
.999, max, time, stderr
74597 , 74590, 74590, 74590, 0.7, 0.3, 1.7, 7.8,
39.4, 156.0, 1.0, 0.00000
175807 , 100469, 111362, 100469, 0.5, 0.3, 1.0, 2.2,
16.4, 105.2, 2.0, 0.00000
278037 , 100483, 110412, 100483, 0.5, 0.4, 0.9, 2.2,
15.9, 95.4, 3.0, 0.13983
366806 , 86301, 86301, 86301, 0.6, 0.4, 0.9, 2.4,
97.6, 107.0, 4.1, 0.10002
473244 , 105209, 115906, 105209, 0.5, 0.3, 1.0, 2.2,
10.2, 99.6, 5.1, 0.08246
574363 , 99939, 112606, 99939, 0.5, 0.3, 1.0, 2.2,
8.4, 115.3, 6.1, 0.07297
665162 , 89343, 89343, 89343, 0.6, 0.3, 1.1, 2.3,
12.5, 116.4, 7.1, 0.06256
768575 , 102028, 102028, 102028, 0.5, 0.3, 1.0, 2.1,
10.7, 116.0, 8.1, 0.05703
870318 , 100383, 112278, 100383, 0.5, 0.4, 1.0, 2.1,
8.2, 109.1, 9.1, 0.04984
972584 , 100496, 111616, 100496, 0.5, 0.3, 1.0, 2.3,
10.3, 109.1, 10.1, 0.04542
1063466 , 88566, 88566, 88566, 0.6, 0.3, 1.1, 2.5,
107.3, 116.9, 11.2, 0.04152
1163218 , 98512, 107549, 98512, 0.5, 0.3, 1.2, 3.4,
17.9, 92.9, 12.2, 0.04007
1257989 , 93578, 103808, 93578, 0.5, 0.3, 1.4, 3.8,
12.6, 105.6, 13.2, 0.03687
1349628 , 90205, 99257, 90205, 0.6, 0.3, 1.2, 2.9,
20.3, 99.6, 14.2, 0.03401
1448125 , 97133, 106429, 97133, 0.5, 0.3, 1.2, 2.9,
11.9, 102.2, 15.2, 0.03170
1536662 , 87137, 95464, 87137, 0.6, 0.4, 1.1, 2.9,
83.7, 94.0, 16.2, 0.02964
1632373 , 94446, 102735, 94446, 0.5, 0.4, 1.1, 2.6,
11.7, 85.5, 17.2, 0.02818
1717028 , 83533, 83533, 83533, 0.6, 0.4, 1.1, 2.7,
87.4, 101.8, 18.3, 0.02651
1817081 , 97807, 108004, 97807, 0.5, 0.3, 1.1, 2.5,
14.5, 99.1, 19.3, 0.02712
1904103 , 85634, 94846, 85634, 0.6, 0.3, 1.2, 3.0,
92.4, 105.3, 20.3, 0.02585
2001438 , 95991, 104822, 95991, 0.5, 0.3, 1.2, 2.7,
13.5, 95.3, 21.3, 0.02482
2086571 , 89121, 99429, 89121, 0.6, 0.3, 1.2, 3.2,
30.9, 103.3, 22.3, 0.02367
2184096 , 88718, 97020, 88718, 0.6, 0.3, 1.3, 3.2,
85.6, 98.0, 23.4, 0.02262
2276823 , 91795, 91795, 91795, 0.5, 0.3, 1.3, 3.5,
81.1, 102.1, 24.4, 0.02174
2381493 , 101074, 101074, 101074, 0.5, 0.3, 1.3, 3.3,
12.9, 99.1, 25.4, 0.02123
2466415 , 83368, 92292, 83368, 0.6, 0.4, 1.2, 3.0,
14.3, 188.5, 26.4, 0.02037
2567406 , 100099, 109267, 100099, 0.5, 0.3, 1.4, 3.3,
10.9, 94.2, 27.4, 0.01989
2653040 , 84476, 91922, 84476, 0.6, 0.3, 1.4, 3.2,
77.0, 100.3, 28.5, 0.01937
TimedOutException(acknowledged_by:0)
TimedOutException(acknowledged_by:0)
TimedOutException(acknowledged_by:0)
TimedOutException(acknowledged_by:0)
TimedOutException(acknowledged_by:0)
TimedOutException(acknowledged_by:0)
TimedOutException(acknowledged_by:0)
TimedOutException(acknowledged_by:0)
...
9825371 , 84636, 91716, 84636, 0.6, 0.3, 1.4, 4.5,
23.4, 86.4, 125.7, 0.00894
9915317 , 87803, 93938, 87803, 0.6, 0.3, 1.3, 4.2,
62.4, 87.2, 126.7, 0.00888
10000000 , 93564, 101405, 93564, 0.5, 0.3, 1.4, 4.2,
16.2, 83.1, 127.6, 0.00880
Results:
real op rate : 78378
adjusted op rate : 78378
adjusted op rate stderr : 0
key rate : 78378
latency mean : 0.6
latency median : 0.3
latency 95th percentile : 1.1
latency 99th percentile : 3.2
latency 99.9th percentile : 20.0
latency max : 11141.1
Total operation time : 00:02:07
END
{noformat}
And in from the system log:
{noformat}
[jenkins@blade-2-1a ~]$ grep -i "messages dropped" /var/log/cassandra/system.log
INFO [ScheduledTasks:1] 2014-03-07 11:35:27,872 MessagingService.java:818 - 18
MUTATION messages dropped in last 5000ms
INFO [ScheduledTasks:1] 2014-03-07 11:35:53,037 MessagingService.java:818 - 18
MUTATION messages dropped in last 5000ms
INFO [ScheduledTasks:1] 2014-03-07 11:36:43,210 MessagingService.java:818 -
218 MUTATION messages dropped in last 5000ms
{noformat}
I am seeing the same results using {{\-mode thrift}} as well the default using
the java-driver.
--
This message was sent by Atlassian JIRA
(v6.2#6252)
