[SERVER-28263] 2 times WT rollback_transaction than WT commit_transaction in logs on a single thread YCSB workload Created: 09/Mar/17  Updated: 18/Apr/17  Resolved: 09/Mar/17

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 3.2.11, 3.4.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Avinash Vyas Assignee: Eric Milkie
Resolution: Done Votes: 0
Labels: Rollback, WiredTiger
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Centos 7, MongoDB binaries downloaded from website


Attachments: File problemlog.tar.gz    
Participants:

 Description   

We are currently trying to evaluate MongoDB (with wiredTiger) for a project. We using YCSB (yahoo's cloud benchmark tool) as one of the tools for evaluating the performance and scalability. In one of our experiments (with global logging level of 0, and 5 for query, write and storage) we see in the logs that there are approximately 2 times transaction rollbacks than transaction commits. I have attached the log file from one such test session. Our test in ycsb inserts 1 record and then we use workload a (50% reads, 50% writes) that reads and updates the same record 100K times. We have tested this with two versions of MongoDB (3.4.2 and 3.2.11) on baremetal machine with 120GB of RAM and underlying SSDs (in raid 10) and are able to reproduce it.
We use the following parameters in YCSB
Loading
----------
bin/ycsb load mongodb -s -threads 1 -P workloads/workloada -P workloadproperty.dat -p "mongodb.url=mongodb://<mongoserver>:27017/ycsb?w=1"

Running
-----------
bin/ycsb run mongodb -s -threads 1 -P workloads/workloada -P workloadproperty.dat -p "mongodb.url=mongodb://<mongoserver>:27017/ycsb?w=1"
where workloadproperty.dat contains these two lines
recordcount=1
operationcount=100000



 Comments   
Comment by Avinash Vyas [ 09/Mar/17 ]

I can definitely post it on user forums, but just an FYI to your comment, there were no writeConflict as per serverStatus() which is what makes it more interesting. Thanks a lot for your help.

Comment by Eric Milkie [ 09/Mar/17 ]

I would expect that some of the rollbacks are due to reads and some are due to write conflicts. To determine which are which, you could look at the "metrics" section of serverStatus output, which has a "writeConflicts" counter. The write conflicts should already be logged at log level 1 in the WRITE component, so you should already be seeing those.

Please note that SERVER project is for reporting bugs or feature suggestions for the MongoDB server. For MongoDB-related support discussion please post on the mongodb-user group or Stack Overflow with the mongodb tag. A question like this involving more discussion would be best posted on the mongodb-users group.

Comment by Avinash Vyas [ 09/Mar/17 ]

Thanks for the reply. For us, I think a reasonable expectation is to see a rollback when there is a conflict, something that is explained here http://source.wiredtiger.com/2.4.1/transactions.html. This is an interesting revelation that MongoDB aborts all read transactions. Even under the light of this revelation, for 100K request workload we would assume 50k rollbacks and 50k commits but what we see here is
$ grep "begin_transaction" test1.log | wc -l
150198
$ grep "rollback_transaction" test1.log | wc -l
100080
$ grep "commit_transaction" test1.log | wc -l
50118
So should we assume that all these rollbacks are due to reads ? How can we identify a rollback caused due to a concurrent conflicting updates ?
Will there be a difference in the log message when a transaction is rolled back for a read vs when it rolled back due to a conflict ?
Thanks in advance.

Comment by Eric Milkie [ 09/Mar/17 ]

Can you describe what your expected behavior would be? Keep in mind that MongoDB aborts all read transactions in WiredTiger, rather than commit an empty transaction.

Generated at Thu Feb 08 04:17:37 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.