Low Description
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.
$ 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
And in from the system log:
[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
I am seeing the same results using -mode thrift as well the default using the java-driver.