Mixed read/update proportions produce swinging latencies

[ghost]

When invoking ycsb run with either readproportion=1.0 or updateproportion=1.0, I get somewhat consistent average latencies. But when invoking run with mixed readproportion=0.50 and updateproportion=0.50, I get results with latencies swinging all to one side either READ or UPDATE. All using 1 thread.

Is there an explanation for this?
This behavior indicates a bug in YCSB. I haven't had time to diagnose it. Hope someone will.

% ycsb run workload.r00.w100
java -cp ycsb-memdb:/work/memdelay/ycsb/memdb-binding/conf:/work/memdelay/ycsb/conf:/work/memdelay/ycsb/lib/HdrHistogram-2.1.4.jar:/work/memdelay/ycsb/lib/core-0.12.0.jar:/work/memdelay/ycsb/lib/htrace-core4-4.1.0-incubating.jar:/work/memdelay/ycsb/lib/jackson-core-asl-1.9.4.jar:/work/memdelay/ycsb/lib/jackson-mapper-asl-1.9.4.jar com.yahoo.ycsb.Client -db MemDBClient -threads 1 -P workload.r0w100 -t
...
readproportion=0.00
updateproportion=1.0
...
[UPDATE], Operations, 100000.0
[UPDATE], AverageLatency(us), 47.87603
[UPDATE], MinLatency(us), 0.0
[UPDATE], MaxLatency(us), 4694015.0
[UPDATE], 95thPercentileLatency(us), 2.0
[UPDATE], 99thPercentileLatency(us), 12.0
[UPDATE], Return=OK, 100000

% ycsb run workload.r100.w00
java -cp ycsb-memdb:/work/memdelay/ycsb/memdb-binding/conf:/work/memdelay/ycsb/conf:/work/memdelay/ycsb/lib/HdrHistogram-2.1.4.jar:/work/memdelay/ycsb/lib/core-0.12.0.jar:/work/memdelay/ycsb/lib/htrace-core4-4.1.0-incubating.jar:/work/memdelay/ycsb/lib/jackson-core-asl-1.9.4.jar:/work/memdelay/ycsb/lib/jackson-mapper-asl-1.9.4.jar com.yahoo.ycsb.Client -db MemDBClient -threads 1 -P workload.r100w00 -t
...
readproportion=1.0
updateproportion=0.00
...
[READ], Operations, 100000.0
[READ], AverageLatency(us), 44.34925
[READ], MinLatency(us), 0.0
[READ], MaxLatency(us), 4419583.0
[READ], 95thPercentileLatency(us), 1.0
[READ], 99thPercentileLatency(us), 4.0
[READ], Return=OK, 100000

% ycsb run workload.r50.w50 #RESULTS SHOW LATENCIES SWING TO READ
java -cp ycsb-memdb:/work/memdelay/ycsb/memdb-binding/conf:/work/memdelay/ycsb/conf:/work/memdelay/ycsb/lib/HdrHistogram-2.1.4.jar:/work/memdelay/ycsb/lib/core-0.12.0.jar:/work/memdelay/ycsb/lib/htrace-core4-4.1.0-incubating.jar:/work/memdelay/ycsb/lib/jackson-core-asl-1.9.4.jar:/work/memdelay/ycsb/lib/jackson-mapper-asl-1.9.4.jar com.yahoo.ycsb.Client -db MemDBClient -threads 1 -P workload.r100w00 -t
...
readproportion=0.50
updateproportion=0.50
...
[READ], Operations, 50152.0
[READ], AverageLatency(us), 95.49270218535652
[READ], MinLatency(us), 0.0
[READ], MaxLatency(us), 4780031.0
[READ], 95thPercentileLatency(us), 1.0
[READ], 99thPercentileLatency(us), 2.0
[READ], Return=OK, 50152
[UPDATE], Operations, 49848.0
[UPDATE], AverageLatency(us), 1.7589471994864387
[UPDATE], MinLatency(us), 0.0
[UPDATE], MaxLatency(us), 492.0
[UPDATE], 95thPercentileLatency(us), 3.0
[UPDATE], 99thPercentileLatency(us), 11.0
[UPDATE], Return=OK, 49848

% ycsb run workload.r50.w50 #RESULTS SHOW LATENCIES SWING TO UPDATE
java -cp ycsb-memdb:/work/memdelay/ycsb/memdb-binding/conf:/work/memdelay/ycsb/conf:/work/memdelay/ycsb/lib/HdrHistogram-2.1.4.jar:/work/memdelay/ycsb/lib/core-0.12.0.jar:/work/memdelay/ycsb/lib/htrace-core4-4.1.0-incubating.jar:/work/memdelay/ycsb/lib/jackson-core-asl-1.9.4.jar:/work/memdelay/ycsb/lib/jackson-mapper-asl-1.9.4.jar com.yahoo.ycsb.Client -db MemDBClient -threads 1 -P workload.r100w00 -t
...
readproportion=0.50
updateproportion=0.50
...
[READ], Operations, 50019.0
[READ], AverageLatency(us), 0.16817609308462783
[READ], MinLatency(us), 0.0
[READ], MaxLatency(us), 58.0
[READ], 95thPercentileLatency(us), 1.0
[READ], 99thPercentileLatency(us), 3.0
[READ], Return=OK, 50019
[UPDATE], Operations, 49981.0
[UPDATE], AverageLatency(us), 93.02158820351734
[UPDATE], MinLatency(us), 0.0
[UPDATE], MaxLatency(us), 4579327.0
[UPDATE], 95thPercentileLatency(us), 3.0
[UPDATE], 99thPercentileLatency(us), 14.0
[UPDATE], Return=OK, 49981

[vlsi]

@dhongMicron , you are likely to be running onto Coordinated Omission issue (see #214 )

TL;DR: always check what your maximum latencies are and dig deeper in case max latency exceeds average by a high margin.

MaxLatency(us), 4579327.0 seems like a 4.57 sec GC pause. Would you list full outputs, including TOTAL_GC sections?

Suppose it takes 1.8 us to perform an update on average.
You perform 50000 operations, so it takes 1.8*50000=90000 us = 90ms for ALL 50000 updates.

Consider a single update is interrupted with a GC pause of 4.5 seconds. Then "total time" for update operations become 4.5sec + 90ms = 4.59 sec. 4.59sec/50'000 ops == 91.8 us on average.

[busbey]

YCSB 0.12.0 (which I think the posted snippets indicate) should already default to accounting for coordinated omission.

Looks to me like either the MemDBClient (which I don't think is a part of YCSB atm) or the backing datastore has unstable latency under a mixed workload.

I'm not sure how that doesn't throw everything else off, unless the long tail happens at the very end maybe, e.g. defualting to batching things client side and happening to hit the flush?