[
https://issues.apache.org/jira/browse/CASSANDRA-6823?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13929983#comment-13929983
]
dan jatnieks commented on CASSANDRA-6823:
-----------------------------------------
Yes, it could be flushing or compaction maybe; anyway something that seems to
be to be maxing out the IO capabilities of this blade server with slow drives.
So probably not a C* or stress issue then; but I used the same blade servers
not long ago without problems. I ran this same scenario in Dec using C* 2.0.3
and stress was able to complete without errors - although there were frequent
periods of time where nothing was being loaded, e.g.
{noformat}
9920313,0,0,1.1,6.1,4860.3,3984
9920313,0,0,1.1,6.1,4860.3,3994
9920313,0,0,1.1,6.1,4860.3,4004
9920313,0,0,1.1,6.1,4860.3,4014
9924219,390,390,1.1,5.9,4860.3,4024
9941460,1724,1724,1.1,6.7,4860.3,4035
10000000,5854,5854,0.9,5.0,4860.3,4042
{noformat}
I wanted to re-run the same scenario again with C* 2.1 and that's when I
started getting the TimedOutException's described above.
BTW, I did try the new (C* 2.1) stress against C* 2.0 and still got the
timeouts.
Then I went back to C* 2.0, now at 2.0.6, and even then am getting timeouts,
e.g.
{noformat}
6978866,0,0,1.1,7.3,21019.4,1193
6978866,0,0,1.1,7.3,21019.4,1203
6978866,0,0,1.1,7.3,21019.4,1213
6978866,0,0,1.1,7.3,21019.4,1223
6978866,0,0,1.1,7.3,21019.4,1234
Operation [6978905] retried 100 times - error inserting key 06978905
((TimedOutException))
Operation [6978883] retried 100 times - error inserting key 06978883
((TimedOutException))
{noformat}
Maybe something's changed between 2.0.3 and 2.0.6/2.1 to improve the throughput
of C* and therefore exceeding the disk I/O? (watching with iostat confirms the
disk 90-100% a lot of the time)
Comparing the earlier 2.0.3 stress results with current 2.0.6 shows almost 1.5x
more total keys after 5 minutes with 2.0.6. I'm not aware of anything
significant has changed on the blade server to account for this.
2.0.3 (Dec '13)
{noformat}
total,interval_op_rate,interval_key_rate,latency,95th,99.9th,elapsed_time
101059,10105,10105,1.0,9.8,240.6,10
195848,9478,9478,1.1,8.1,156.3,20
303346,10749,10749,1.1,6.5,156.3,30
353340,4999,4999,1.1,5.1,156.2,40
391734,3839,3839,1.1,5.1,4165.0,50
503239,11150,11150,1.1,6.0,4164.7,60
603452,10021,10021,1.2,6.4,4164.7,70
603741,28,28,1.2,6.4,4164.7,80
631263,2752,2752,1.2,6.4,126.9,91
745765,11450,11450,1.1,6.6,3655.2,101
804784,5901,5901,1.0,6.7,3749.8,111
825932,2114,2114,1.0,6.7,3749.8,121
865002,3907,3907,1.0,7.4,3749.8,131
953287,8828,8828,1.0,7.2,175.3,141
1030450,7716,7716,1.0,7.2,175.0,151
1035041,459,459,1.0,7.6,10645.7,161
1035301,26,26,1.0,7.6,10645.7,171
1082020,4671,4671,1.1,8.6,10645.7,182
1203203,12118,12118,1.1,7.6,10645.7,192
1205520,231,231,1.1,7.6,10645.7,202
1231013,2549,2549,1.1,7.7,10645.7,212
1231013,0,0,1.1,7.7,10645.7,222
1231013,0,0,1.1,7.7,10645.7,232
1231013,0,0,1.1,7.7,10645.7,242
1231013,0,0,1.1,7.7,10645.7,252
1282460,5144,5144,1.1,6.7,49538.0,262
1346346,6388,6388,1.1,7.1,2228.0,273
1482054,13570,13570,1.1,5.4,310.0,283
1522362,4030,4030,1.1,5.5,780.0,293
1559749,3738,3738,1.1,5.8,776.4,303
{noformat}
2.0.6 (Mar '14)
{noformat}
total,interval_op_rate,interval_key_rate,latency,95th,99.9th,elapsed_time
81582,8158,8158,1.4,12.4,882.2,10
166315,8473,8473,1.2,9.0,125.6,20
286042,11972,11972,1.2,7.8,1827.1,30
370722,8468,8468,1.2,7.0,1827.5,40
434601,6387,6387,1.2,6.1,1860.1,50
501459,6685,6685,1.2,5.8,1860.1,60
584545,8308,8308,1.2,6.9,1860.1,70
692765,10822,10822,1.2,6.9,1287.8,80
805827,11306,11306,1.1,7.2,1287.8,91
880074,7424,7424,1.1,6.8,1260.0,101
965474,8540,8540,1.2,7.2,1500.5,111
1057880,9240,9240,1.2,6.6,1500.5,121
1137539,7965,7965,1.2,6.3,1472.5,131
1213965,7642,7642,1.2,6.1,1467.8,141
1288224,7425,7425,1.2,5.9,1467.8,151
1324108,3588,3588,1.2,6.0,4041.8,161
1422788,9868,9868,1.1,5.6,1467.8,171
1525673,10288,10288,1.1,5.4,1467.8,182
1592155,6648,6648,1.1,5.9,1467.9,192
1653758,6160,6160,1.2,6.1,1467.8,202
1788367,13460,13460,1.1,5.9,1467.8,212
1829188,4082,4082,1.1,5.7,159.5,222
1924749,9556,9556,1.1,4.9,159.5,232
1991759,6701,6701,1.1,5.3,202.2,242
2057482,6572,6572,1.1,5.2,202.2,252
2190652,13317,13317,1.1,5.9,202.2,263
2234147,4349,4349,1.1,6.0,4639.1,273
2312015,7786,7786,1.1,5.9,4639.1,283
2393938,8192,8192,1.1,5.5,4639.1,293
2454516,6057,6057,1.1,5.5,4639.1,303
{noformat}
And with 2.1 there is an even greater op/s rate, at least initially (due to the
warm-up?), but I just don't think the blade server disks can keep up and it
drops off pretty fast.
One note about these 2.1 results is that data and flush directories have been
put on separate disks. In fact, on this server, I'm not seeing a significant
difference in the stress results when data/flush are on the same or different
devices. But that is a different ticket (CASSANDRA-6357).
{noformat}
ops , op/s,adj op/s, key/s, mean, med, .95, .99,
.999, max, time, stderr
273625 , 27362, 27362, 27362, 1.8, 0.9, 4.7, 12.2,
106.2, 162.1, 10.0, 0.00000
548201 , 27362, 27362, 27362, 1.8, 0.9, 4.8, 13.1,
103.8, 143.7, 20.0, 0.00000
818405 , 27096, 27096, 27096, 1.8, 0.9, 4.8, 13.6,
106.1, 446.8, 30.0, 0.00000
895435 , 26484, 26484, 26484, 1.9, 0.9, 4.9, 15.3,
106.2, 145.1, 32.9, 0.00265
941568 , 4057, 27775, 4057, 12.3, 0.9, 5.2, 15.3,
9711.6, 9742.1, 44.3, 0.00662
966621 , 1257, 2610, 1257, 39.7, 1.0, 18.2, 39.5,
10341.1, 10364.6, 64.2, 0.00699
983185 , 842, 1763, 842, 59.4, 1.2, 21.7, 47.4,
10303.5, 10342.3, 83.9, 0.16210
994109 , 555, 1174, 555, 90.1, 1.5, 25.5, 164.7,
10404.2, 10426.9, 103.6, 0.21314
1001448 , 373, 795, 373, 134.0, 3.4, 30.9, 8074.0,
10471.1, 10506.1, 123.3, 0.24546
1005507 , 208, 439, 208, 240.9, 10.3, 36.4, 10494.6,
10512.9, 10530.8, 142.8, 0.26853
1008785 , 167, 359, 167, 299.5, 12.0, 37.5, 10618.0,
10644.9, 10660.6, 162.4, 0.28654
1010927 , 111, 245, 111, 452.4, 12.2, 215.0, 10742.7,
10755.9, 10767.0, 181.8, 0.30048
1012312 , 73, 160, 73, 683.5, 12.7, 8164.7, 10433.8,
10454.4, 10459.3, 200.8, 0.31185
1013323 , 53, 119, 53, 951.8, 12.0, 8264.3, 10791.4,
10801.0, 10811.2, 220.0, 0.32134
1013940 , 33, 81, 33, 1505.3, 12.7, 10976.3, 10992.4,
11004.0, 11004.0, 238.6, 0.32932
1014377 , 23, 52, 23, 2172.5, 12.3, 10752.8, 10760.6,
10768.5, 10768.5, 257.6, 0.33617
1014647 , 15, 39, 15, 3273.9, 12.6, 17638.0, 17664.1,
17688.5, 17688.5, 275.3, 0.34212
1014871 , 13, 33, 13, 3913.4, 12.6, 17502.4, 17541.7,
17553.6, 17553.6, 292.8, 0.34731
1015056 , 11, 28, 11, 4735.8, 15.3, 17506.5, 17522.5,
17548.4, 17548.4, 310.3, 0.35187
{noformat}
So maybe what I should be doing here is to throttle stress to a rate that my
disks can handle. Then I can get enough data loaded to ensure that flushes and
compactions are happening and be able to measure the effect of CASSANDRA-6357.
A side observation; I'm using 'tee' to capture output and I just noticed that
while in 2.0 the {{TimedOutException}} messages go to stdout, in 2.1 stress the
{{TimedOutException(acknowledged_by:0)}} and
{{org.apache.thrift.transport.TTransportException: java.net.SocketException:
Broken pipe}} messages are going to stderr.
So looking at the tee'd file output instead of the console, it's a bit cleaner
since the {{TimedOutException}} messages are not included.
{noformat}
1014377 , 23, 52, 23, 2172.5, 12.3, 10752.8, 10760.6,
10768.5, 10768.5, 257.6, 0.33617
1014647 , 15, 39, 15, 3273.9, 12.6, 17638.0, 17664.1,
17688.5, 17688.5, 275.3, 0.34212
1014871 , 13, 33, 13, 3913.4, 12.6, 17502.4, 17541.7,
17553.6, 17553.6, 292.8, 0.34731
1015056 , 11, 28, 11, 4735.8, 15.3, 17506.5, 17522.5,
17548.4, 17548.4, 310.3, 0.35187
1015342 , 8, 8, 8, 6227.7, 14.8, 19078.6, 19103.3,
36763.8, 36763.8, 347.1, 0.35590
java.lang.RuntimeException: Timed out waiting for a timer thread - seems one
got stuck
at org.apache.cassandra.stress.util.Timing.snapInterval(Timing.java:58)
at org.apache.cassandra.stress.util.Timing.snapInterval(Timing.java:83)
at
org.apache.cassandra.stress.StressMetrics.update(StressMetrics.java:121)
at
org.apache.cassandra.stress.StressMetrics.access$200(StressMetrics.java:35)
at
org.apache.cassandra.stress.StressMetrics$1.run(StressMetrics.java:70)
at java.lang.Thread.run(Thread.java:744)
java.io.IOException: Operation [1016301] x101 key 00000F81EE Error executing:
(TTransportException): java.net.SocketException: Broken pipe
at org.apache.cassandra.stress.Operation.error(Operation.java:233)
at
org.apache.cassandra.stress.Operation.timeWithRetry(Operation.java:212)
at
org.apache.cassandra.stress.operations.ThriftInserter.run(ThriftInserter.java:72)
at
org.apache.cassandra.stress.StressAction$Consumer.run(StressAction.java:302)
{noformat}
> 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
> Labels: stress
> 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)
