[SERVER-16626] wiredtiger group commit too slow for single-threaded workloads Created: 22/Dec/14  Updated: 24/Jan/15  Resolved: 22/Dec/14

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 2.8.0-rc3
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Mark Callaghan Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

Run iibench – https://github.com/tmcallaghan/iibench-mysql
Change run.simple.bash from it with:
export MAX_ROWS=100000000
export NUM_DOCUMENTS_PER_INSERT=1
export WRITE_CONCERN=FSYNC_SAFE

Start mongod by: mongod --config /data/mysql/mongo.28/mongo.conf --storageEngine wiredTiger

Using this mongo.conf. Repeating the test with journal compression enabled makes no difference.
processManagement:
fork: true
systemLog:
destination: file
path: /data/mysql/mongo.28/log
logAppend: true
storage:
dbPath: /data/mysql/mongo.28/data
journal:
enabled: true
mmapv1:
syncPeriodSecs: 60
journal:
commitIntervalMs: 100
storage.wiredTiger.collectionConfig.blockCompressor: none
storage.wiredTiger.engineConfig.journalCompressor: none

Participants:

 Description   

I ran iibench (https://github.com/tmcallaghan/iibench-mysql) changed to insert 1 document per write and fsync enabled. My storage is fast (PCIe flash). With 10 threads I get more than 10,000 docs inserted per second. When I change to 1 thread I get ~20 docs inserted per second (or 1 per 50 milliseconds).

So then I start to look at WiredTiger source for a 50 millisecond sleep and find this in db/storage/wiredtiger/wiredtiger_recovery_unit.cpp

            // return true if happened
            bool awaitCommit() {
                boost::mutex::scoped_lock lk( mutex );
                long long start = lastSyncTime;
                numWaitingForSync.fetchAndAdd(1);
                condvar.timed_wait(lk,boost::posix_time::milliseconds(50));
                numWaitingForSync.fetchAndAdd(-1);
                return lastSyncTime > start;
            }

A typical thread stack during the single threaded test is:
pthread_cond_timedwait@@GLIBC_2.3.2,timed_wait<boost::unique_lock<boost::mutex>,timed_wait<boost::unique_lock<boost::mutex>,,awaitCommit,mongo::WiredTigerRecoveryUnit::awaitCommit,mongo::waitForWriteConcern,mongo::CmdGetLastError::run,mongo::_execCommand,mongo::Command::execCommand,mongo::_runCommands,runCommands,mongo::runQuery,receivedQuery,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg



 Comments   
Comment by Eliot Horowitz (Inactive) [ 22/Dec/14 ]

Older drivers use the old method of doing writes - fire and forget write followed by a getLastError.
In that case, when doing j:true, the getLastError is waiting for some other thread to do do the fsync, or the group commit on its own.
With newer write commands which have the j:true embedded, we simply mark the transaction as needing an fsync before returning.
Agree the behavior with old writes is not ideal, but most apps have been upgraded to newer drivers.

Comment by Mark Callaghan [ 22/Dec/14 ]

This does not reproduce with mongo-java-driver-2.12.4.jar

Comment by Mark Callaghan [ 22/Dec/14 ]

The test was doing single-doc writes. Regardless, I don't get why a 50-millisecond wait for group commit should be dependent on the version of the Java client that I use. I feel like I wasted time on this and I have better ways to waste time.

Comment by Ramon Fernandez Marina [ 22/Dec/14 ]

Support for bulk write commands were included in the 2.12.0 Java driver. The latest release candidate appears to be 2.13.0-rc0.

Comment by Mark Callaghan [ 22/Dec/14 ]

mongo-java-driver-2.11.4.jar

Why is server-side group commit code path driver dependent?

Comment by Eliot Horowitz (Inactive) [ 22/Dec/14 ]

What driver are you using?
Newer drivers that do write commands shouldn't have that path at all.
(look for goingToAwaitCommit())
If you are using commands and still seeing this then is likely a bug.

Comment by Mark Callaghan [ 22/Dec/14 ]

Also used this to get 1 or 10 threads with iibench
export NUM_LOADER_THREADS = <insert 1 or 10 here>

Comment by Mark Callaghan [ 22/Dec/14 ]

Thread stacks from PMP (poormansprofiler.org) for all threads when it was slow:

1 sigwait,mongo::(anonymous,boost::(anonymous,start_thread,clone
1 select,mongo::Listener::initAndListen,_initAndListen,mongo::initAndListen,mongoDbMain,main
1 recv,mongo::Socket::_recv,mongo::Socket::unsafe_recv,mongo::Socket::recv,mongo::MessagingPort::recv,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone
1 pthread_cond_wait@@GLIBC_2.3.2,wait<boost::unique_lock<boost::timed_mutex>,mongo::DeadlineMonitor<mongo::V8Scope>::deadlineMonitorThread,boost::(anonymous,start_thread,clone
1 pthread_cond_timedwait@@GLIBC_2.3.2,_wt_cond_wait,_sweep_server,start_thread,clone
1 pthread_cond_timedwait@@GLIBC_2.3.2,_wt_cond_wait,_log_server,start_thread,clone
1 pthread_cond_timedwait@@GLIBC_2.3.2,_wt_cond_wait,_evict_server,start_thread,clone
1 pthread_cond_timedwait@@GLIBC_2.3.2,_wt_cond_wait,_ckpt_server,start_thread,clone
1 pthread_cond_timedwait@@GLIBC_2.3.2,timed_wait<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,mongo::RangeDeleter::doWork,boost::(anonymous,start_thread,clone
1 pthread_cond_timedwait@@GLIBC_2.3.2,timed_wait<boost::unique_lock<boost::mutex>,timed_wait<boost::unique_lock<boost::mutex>,,awaitCommit,mongo::WiredTigerRecoveryUnit::awaitCommit,mongo::waitForWriteConcern,mongo::CmdGetLastError::run,mongo::_execCommand,mongo::Command::execCommand,mongo::_runCommands,runCommands,mongo::runQuery,receivedQuery,mongo::assembleResponse,mongo::MyMessageHandler::process,mongo::PortMessageServer::handleIncomingMsg,start_thread,clone
1 pthread_cond_timedwait@@GLIBC_2.3.2,boost::condition_variable_any::timed_wait<boost::unique_lock<boost::timed_mutex>,timed_wait<boost::unique_lock<boost::timed_mutex>,,timed_wait<boost::unique_lock<boost::timed_mutex>,,mongo::(anonymous,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
1 nanosleep,mongo::sleepsecs,mongo::TTLMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone
1 nanosleep,mongo::sleepsecs,mongo::ClientCursorMonitor::run,mongo::BackgroundJob::jobBody,boost::(anonymous,start_thread,clone

Generated at Thu Feb 08 03:41:43 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.