YCSB core workloada always doing extra operations that were not requested

[ashwinivsh]

Hi YCSB Experts,

We are observing some unexpected behavior with our YCSB tests and wanted your feedback on what might be going on.

Following is our command and we expect it to run 2 operations "95% scan" and "05% insert":

./bin/ycsb run mongodb -s -P workloads/workloada -jvm-args="-Xms8g -Xmx16g" -threads 16 -p recordcount=250000000 -p operationcount=100000 -p scanproportion=0.95 -p insertproportion=0.05 -p mongodb.url=mongodb+srv://sarika:ClusterSarika123@vinayakgcpm50scantest.n61jk.mongodb.net/vinayak_250Mdocs_flen25_fcount10_M50_16Th_db?replicaSet=atlas-ln1o5e-shard-0 -p exportfile=gcp_95scan_05insert_250Mdocs_25fl_10fc_100Kops_16threads.txt

But as shown in the below output, this command actually did 4 operations "scan", "read", "insert" and "update", instead of the desired 2 operations:

[OVERALL], RunTime(ms), 1319884 [OVERALL], Throughput(ops/sec), 75.764233826609 [TOTAL_GCS_PS_Scavenge], Count, 65 [TOTAL_GC_TIME_PS_Scavenge], Time(ms), 383 [TOTAL_GCTIME%_PS_Scavenge], Time(%), 0.02901770155559125 [TOTAL_GCS_PS_MarkSweep], Count, 0 [TOTAL_GC_TIME_PS_MarkSweep], Time(ms), 0 [TOTAL_GCTIME%_PS_MarkSweep], Time(%), 0.0 [TOTAL_GCs], Count, 65 [TOTAL_GC_TIME], Time(ms), 383 [TOTAL_GCTIME%], Time(%), 0.02901770155559125 [READ], Operations, 24962 [READ], AverageLatency(us), 2717.22249819726 [READ], MinLatency(us), 578 [READ], MaxLatency(us), 1060863 [READ], 95thPercentileLatency(us), 4023 [READ], 99thPercentileLatency(us), 4823 [READ], Return=OK, 24962 [CLEANUP], Operations, 16 [CLEANUP], AverageLatency(us), 1516.625 [CLEANUP], MinLatency(us), 2 [CLEANUP], MaxLatency(us), 24207 [CLEANUP], 95thPercentileLatency(us), 16 [CLEANUP], 99thPercentileLatency(us), 24207 [UPDATE], Operations, 25261 [UPDATE], AverageLatency(us), 6026.520486124857 [UPDATE], MinLatency(us), 2392 [UPDATE], MaxLatency(us), 1068031 [UPDATE], 95thPercentileLatency(us), 8059 [UPDATE], 99thPercentileLatency(us), 9199 [UPDATE], Return=OK, 25261 [INSERT], Operations, 2434 [INSERT], AverageLatency(us), 6135.633525061627 [INSERT], MinLatency(us), 2774 [INSERT], MaxLatency(us), 1115135 [INSERT], 95thPercentileLatency(us), 7447 [INSERT], 99thPercentileLatency(us), 9135 [INSERT], Return=OK, 2434 [SCAN], Operations, 47343 [SCAN], AverageLatency(us), 431551.9720761253 [SCAN], MinLatency(us), 690 [SCAN], MaxLatency(us), 3708927 [SCAN], 95thPercentileLatency(us), 985087 [SCAN], 99thPercentileLatency(us), 1059839 [SCAN], Return=OK, 47343

Also notice that the READ+UPDATE constitutes about 50% of total 100K operations and SCAN+INSERT constitutes the remaining 50%. The SCAN:INSERT proportion appears to be maintained as 95% : 05% but that's 95% and 5% of 50K operations and not 100K.

Any idea why the total 100K operations might be getting split into these specific percentages?

Any idea why these extra undesired operations might be run and if there's a way to fix i.e. to get it to run only the desired set of operations in the desired proportion?

Thanks, Ashwini

[twblamer]

I assume YCSB is loading the readproportion/updateproportion properties from the workloada file.

Try using workloade instead of workloada.

[ashwinivsh]

I assume YCSB is loading the readproportion/updateproportion properties from the workloada file.

Try using workloade instead of workloada.

But, from the YCSB documentation I had read that we can override the workload properties by specifically giving those values on the command-line. Doesn't it mean I could use workloada and on command line I can override those values? e.g. refer the following command that I tried:

./bin/ycsb run mongodb -s -P workloads/workloada -jvm-args="-Xms8g -Xmx16g" -threads 1 -p recordcount=10000 -p operationcount=1000 -p readproportion=0.5 -p readmodifywriteproportion=0.5 -p updateproportion=0 -p scanproportion=0 -p insertproportion=0 -p mongodb.url=mongodb+srv://sarika:ClusterSarika123@vinayakgcpm50scantest.n61jk.mongodb.net/vinayak_960Kdocs_flen5000_fcount10_M50_16Th_db?replicaSet=atlas-ln1o5e-shard-0 -p exportfile=temp_gcp_50read_50readmodifywrite_960Kdocs_5000fl_10fc_960Kops_16threads.txt

But the output of this also shows total of 3 operations READ, UPDATE and READ-MODIFY-WRITE and apparently it did 507+507+1000 = 2014 total operations. Why would that be, any idea? Please refer below output. When we had set updateproportion=0 in the CLI argument, we expected that there won't be any UPDATE reported in the output, but somehow UPDATE is being reported. Does it mean the override mechanism isn't working correctly?

[OVERALL], RunTime(ms), 3952 [OVERALL], Throughput(ops/sec), 253.03643724696357 [TOTAL_GCS_PS_Scavenge], Count, 0 [TOTAL_GC_TIME_PS_Scavenge], Time(ms), 0 [TOTAL_GCTIME%_PS_Scavenge], Time(%), 0.0 [TOTAL_GCS_PS_MarkSweep], Count, 0 [TOTAL_GC_TIME_PS_MarkSweep], Time(ms), 0 [TOTAL_GCTIME%_PS_MarkSweep], Time(%), 0.0 [TOTAL_GCs], Count, 0 [TOTAL_GC_TIME], Time(ms), 0 [TOTAL_GCTIME%], Time(%), 0.0 [READ], Operations, 1000 [READ], AverageLatency(us), 1835.967 [READ], MinLatency(us), 671 [READ], MaxLatency(us), 572415 [READ], 95thPercentileLatency(us), 2311 [READ], 99thPercentileLatency(us), 3949 [READ], Return=OK, 1000 [READ-MODIFY-WRITE], Operations, 507 [READ-MODIFY-WRITE], AverageLatency(us), 5809.197238658777 [READ-MODIFY-WRITE], MinLatency(us), 3394 [READ-MODIFY-WRITE], MaxLatency(us), 604671 [READ-MODIFY-WRITE], 95thPercentileLatency(us), 6939 [READ-MODIFY-WRITE], 99thPercentileLatency(us), 8471 [CLEANUP], Operations, 1 [CLEANUP], AverageLatency(us), 5566.0 [CLEANUP], MinLatency(us), 5564 [CLEANUP], MaxLatency(us), 5567 [CLEANUP], 95thPercentileLatency(us), 5567 [CLEANUP], 99thPercentileLatency(us), 5567 [UPDATE], Operations, 507 [UPDATE], AverageLatency(us), 3363.652859960552 [UPDATE], MinLatency(us), 2600 [UPDATE], MaxLatency(us), 18975 [UPDATE], 95thPercentileLatency(us), 4375 [UPDATE], 99thPercentileLatency(us), 6091 [UPDATE], Return=OK, 507

Thanks, Ashwini