[SERVER-5080] journal rotates while dbMutex is held Created: 24/Feb/12  Updated: 16/Feb/15  Resolved: 21/Jan/15

Status: Closed
Project: Core Server
Component/s: Performance, Storage
Affects Version/s: 2.1.0
Fix Version/s: 3.0.0-rc6

Type: Bug Priority: Major - P3
Reporter: Eric Milkie Assignee: Kaloian Manassiev
Resolution: Done Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
is related to SERVER-5072 Journal rotate with paranoid journali... Closed
is related to SERVER-5076 Replication tests failing on drop_dup... Closed
is related to SERVER-4880 frequent journal warnings with Win2008 Closed
is related to SERVER-6229 not so rare verbose log message: info... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

from SERVER-4880..
log message is:

Mon Feb 06 10:47:57 [journal] info journal _rotate called insider dbMutex - ok but should be somewhat rare

dwight says:

not sure why it is being called so much inside the lock. rotating in the lock would be a little bad as the world would be stopped while we unlink a 2GB file which might take a little time. but it's a rare event.
 
the logging is happening before the if statement that checks if we are due to rotate - it's good it's before the rotate as rotates are so rare we'd never notice it otherwise.
 
so we should analyze and see what is up but severity is not high

This may have caused a couple recent unit test breaks, in particular if it happens to occur while we are in an assert.soon(), since the default is that it only waits 30 seconds and the journal rotating can take a while as Dwight mentions above.



 Comments   
Comment by Githook User [ 21/Jan/15 ]

Author:

{u'username': u'kaloianm', u'name': u'Kaloian Manassiev', u'email': u'kaloian.manassiev@mongodb.com'}

Message: SERVER-16065, SERVER-5080 Write MMAP V1 journal in a separate thread

Offloads the writing of the journal to disk to a separate thread, so that
when the journal lock is dropped we can immediately loop back and pick up
the next batch of changes.

This allows the journal write to be parallelized with concurrent workload
once the intents list has been materialized.
Branch: master
https://github.com/mongodb/mongo/commit/f346c4ad0c2d892014c79d7adbbca61031f50194

Comment by Dwight Merriman [ 06/Mar/14 ]

i think the way to go is simply move the _rotate call after the call to groupCommit. it can happen afterwards. you just have to be in _curLogFileMutex, I believe. so probably don't need to be in any dbMutex lock at all.

perhaps it is called in the durThread() main loop.

Comment by Eric Milkie [ 27/Feb/12 ]

I looked at the code. It seems like _rotate() (which does not actually rotate every time it's called but only rotates when it's time to do it) is always called each time we call WRITETOJOURNAL(). The comment for WRITETOJOURNAL() says:

        /** write (append) the buffer we have built to the journal and fsync it.
            outside of dbMutex lock as this could be slow.
            @param uncompressed - a buffer that will be written to the journal after compression
            will not return until on disk
        */

There are two places in the code where WRITETOJOURNAL() is called; in groupCommit() and in groupCommitWithLimitedLocks(). The former is called with the read lock still held, while the latter does not. Most of the times groupCommit() is called seem to be rare, but there is one case in the main journal loop that I believe is causing most of the log entries:

  if( privateMapBytes < UncommittedBytesLimit && ++n % N && (cmdLine.durOptions&CmdLine::DurAlwaysRemap)==0 ) {
      (groupCommitWithLimitedLocks)
  } else {
      (grab read lock)
      (groupCommit)
  }

The big N is 10, so every 10 times we automatically fall through and call the locking rotate check. Also, it looks like the private Map bytes comparison check fails if we are very write heavy – this is probably another trigger for the log entry.

The call to WRITETOJOURNAL() in groupCommit() has a comment:

            // todo : write to the journal outside locks, as this write can be slow.
            //        however, be careful then about remapprivateview as that cannot be done 
            //        if new writes are then pending in the private maps.

Perhaps this is the best way to avoid journal rotations with a read lock held; change the code so that no read locks are held during calls to groupCommit().

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