[JAVA-2846] WriteConcern.JOURNALED is not working Created: 02/May/18  Updated: 27/Oct/23  Resolved: 03/May/18

Status: Closed
Project: Java Driver
Component/s: Write Operations
Affects Version/s: 3.6.3
Fix Version/s: None

Type: Task Priority: Major - P3
Reporter: 아나 하리 Assignee: Unassigned
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

OS 3.10.0-693.21.1.el7.x86_64 #1 SMP Wed Mar 7 19:03:37 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
MongoDB 3.4.12 (with Replica-set)
Java driver 3.6.3



 Description   

With mongo client, we can see disk write operation for journal sync with writeconcern({w:1,j:true}).

for(var idx=0; idx<1000000; idx++){
  db.wctest.insert({ "someKey" : "someValue" }, { writeConcern: { w: 1, j:true } });
}
 
$ iostat -dxk 1
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00    10.00    0.00 3217.00     0.00 13025.00     8.10     0.09    0.03    0.00    0.03   0.03   8.90
sda               0.00     0.00    0.00 3126.00     0.00 12596.00     8.06     0.09    0.03    0.00    0.03   0.03   8.90
sda               0.00     0.00    0.00 3154.00     0.00 12710.50     8.06     0.09    0.03    0.00    0.03   0.03   9.30
sda               0.00     0.00    0.00 3181.00     0.00 12817.50     8.06     0.08    0.03    0.00    0.03   0.03   8.10
sda               0.00     0.00    3.00 3230.00    24.00 13025.50     8.07     0.10    0.03    0.33    0.03   0.03   9.50
sda               0.00     0.00    3.00 3171.00    24.00 12777.50     8.07     0.10    0.03    0.00    0.03   0.03   9.60
 
$ mongostat
insert query update delete getmore command dirty used flushes vsize  res qrw arw net_in net_out conn         set repl                time
  2873    *0     *0     *0     674  1301|0  0.1% 2.9%       1 1.73G 340M 0|0 1|0  1.52m   1.47m    9 journaltest  PRI May  2 17:03:05.489
  2952    *0     *0     *0     683  1326|0  0.1% 2.9%       0 1.73G 341M 0|0 1|0  1.55m   1.50m    9 journaltest  PRI May  2 17:03:06.489
  2959    *0     *0     *0     680  1317|0  0.2% 2.9%       0 1.76G 342M 0|0 1|0  1.54m   1.50m    9 journaltest  PRI May  2 17:03:07.490
  2986    *0     *0     *0     686  1331|0  0.2% 2.9%       0 1.76G 343M 0|0 1|1  1.56m   1.51m    9 journaltest  PRI May  2 17:03:08.489

And journal false writeconcern also.

for(var idx=0; idx<1000000; idx++){
  db.wctest.insert({ "someKey" : "someValue" }, { writeConcern: { w: 1, j:false } });
}
 
$ iostat -dxk 1
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00     0.00    0.00   16.00     0.00  1182.00   147.75     0.00    0.12    0.00    0.12   0.12   0.20
sda               0.00     0.00    0.00    6.00     0.00   985.00   328.33     0.00    0.50    0.00    0.50   0.50   0.30
sda               0.00     5.00    0.00   17.00     0.00  1068.00   125.65     0.00    0.12    0.00    0.12   0.12   0.20
sda               0.00     0.00    0.00    6.00     0.00   977.00   325.67     0.00    0.33    0.00    0.33   0.33   0.20
sda               0.00     0.00    0.00    6.00     0.00   985.00   328.33     0.00    0.33    0.00    0.33   0.33   0.20
sda               0.00     0.00    0.00    6.00     0.00   978.50   326.17     0.00    0.33    0.00    0.33   0.33   0.20
sda               0.00     0.00    0.00    6.00     0.00   989.00   329.67     0.00    0.33    0.00    0.33   0.33   0.20
 
$ mongostat
insert query update delete getmore command dirty used flushes vsize  res qrw arw net_in net_out conn         set repl                time
  3768    *0     *0     *0     684  1310|0  0.4% 3.2%       0 1.76G 376M 0|0 1|0  1.68m   1.80m    9 journaltest  PRI May  2 17:04:48.351
  3808    *0     *0     *0     681  1316|0  0.4% 3.3%       0 1.79G 378M 0|0 1|0  1.69m   1.82m    9 journaltest  PRI May  2 17:04:49.351
  3845    *0     *0     *0     677  1299|0  0.4% 3.3%       0 1.79G 379M 0|0 2|0  1.68m   1.82m    9 journaltest  PRI May  2 17:04:50.352
  3743    *0     *0     *0     681  1321|0  0.4% 3.3%       0 1.79G 381M 0|0 1|0  1.68m   1.79m    9 journaltest  PRI May  2 17:04:51.350
  3637    *0     *0     *0     680  1303|0  0.4% 3.3%       0 1.82G 382M 0|0 1|0  1.65m   1.75m    9 journaltest  PRI May  2 17:04:52.350
  3680    *0     *0     *0     684  1314|0  0.4% 3.3%       0 1.82G 384M 0|0 1|0  1.66m   1.77m    9 journaltest  PRI May  2 17:04:53.350

But with java client driver, looks like no disk operations for journal sync even I set WriteConcern.JOURNALED writeconcern. And I have traced disk io system call with strace, but there's no sync operation. Below is simple test program I have used.

public class WriteConcernJournalTester {
  private static final Logger log = Logger.getAnonymousLogger();
  
  public static void main(String[] args) throws Exception {
    WriteConcernJournalTester tester = new WriteConcernJournalTester();
    
    boolean withJournal = Boolean.getBoolean(args[0]);
    tester.run(withJournal);
  }
  
  private void run(boolean withJournal) throws Exception{
    MongoCollection<Document> collection = getCollection("perftest", withJournal);
    log.info("Elapsed : " + insertRecords(collection, withJournal));
  }
  
  private long insertRecords(MongoCollection<Document> collection, boolean withJournal) {
    long startTime=System.currentTimeMillis();
    for(int i=0;i<1000000;i++){
      collection.insertOne(new Document("someKey", "someValue"));
    }
    
    long endTime=System.currentTimeMillis();
    collection.drop();
    return (endTime-startTime);
  }  private MongoCollection<Document> getCollection(String databaseName, boolean withJournal) throws Exception{
    MongoClient conn = new MongoClient(new MongoClientURI("mongodb://node1:27017,node2:27017/?replicaSet=journaltest"));
    if(withJournal){
      WriteConcern wc = WriteConcern.W1.withJournal(true);
      // WriteConcern wc = WriteConcern.ACKNOWLEDGED.withJournal(true);
      return conn.getDatabase("perftest").getCollection("perftest").withWriteConcern(wc);
    }else{
      WriteConcern wc = WriteConcern.W1.withJournal(false);
      // WriteConcern wc = WriteConcern.ACKNOWLEDGED.withJournal(false);
      return conn.getDatabase("perftest").getCollection("perftest").withWriteConcern(wc);
    }
  } 
}

for both "WriteConcern.W1.withJournal(true)" and "WriteConcern.ACKNOWLEDGED.withJournal(true)", looks like mongod does not sync journal log for each write operation. Disk write operations is almost same as "{w:1, f:false}" in mongo client.



 Comments   
Comment by 아나 하리 [ 03/May/18 ]

@Jeff Yemin 

 

Sorry, forget about this issue. I was wrong with below code. This code return FALSE always whatever cmd line value. (I don't know why, but am not interested in this.)

boolean withJournal = Boolean.getBoolean(args[0]);

Regards,

Comment by Jeffrey Yemin [ 02/May/18 ]

I'm not able to reproduce this.  First I proved that the driver is indeed sending the correct write concern, by registering a command listener with the MongoClient:

        CommandListener commandListener = new CommandListener() {
            @Override
            public void commandStarted(final CommandStartedEvent event) {
                System.out.println(event.getCommand());
            }
 
            @Override
            public void commandSucceeded(final CommandSucceededEvent event) {
            }
 
            @Override
            public void commandFailed(final CommandFailedEvent event) {
            }
        };
        MongoClient conn = new MongoClient(new MongoClientURI("mongodb://localhost,localhost:27018",
                MongoClientOptions.builder().addCommandListener(commandListener)));

This prints out every command sent by the driver, and the commands look like this:

{ "insert" : "perftest", "ordered" : true, "writeConcern" : { "w" : 1, "j" : true }, "$db" : "perftest",  "documents" : [{ "_id" : { "$oid" : "5ae9a2ee3e50231fc6b1e61f" }, "largeBinary" : "someValue" }], ... }

So the driver is including j : true in the write concern.

I also observed an increase in I/O activity during the test run:

              disk0       cpu    load average
    KB/t  tps  MB/s  us sy id   1m   5m   15m
   15.75  210  3.23   6  4 90  3.26 2.87 2.85
  119.08   26  3.01   8  7 85  3.26 2.87 2.85   // start run
  128.00    2  0.25   4  4 92  3.26 2.87 2.85
   48.47   17  0.80   5  4 92  3.26 2.87 2.85
   63.48  366 22.66  17  8 75  3.24 2.87 2.85
   81.93  181 14.52  12  7 81  3.24 2.87 2.85
   15.48  406  6.13  63  8 29  3.24 2.87 2.85
    6.92 1403  9.49  27  8 65  3.24 2.87 2.85
   10.02 1334 13.05  16  7 77  3.24 2.87 2.85
    7.09 1301  9.01  17  9 74  3.62 2.95 2.88
    9.25 1421 12.84  13  8 79  3.62 2.95 2.88
    6.29 1411  8.67  14 12 74  3.62 2.95 2.88
   10.46 1444 14.75  16 12 72  3.62 2.95 2.88
   45.60 1278 56.93  14 10 76  3.62 2.95 2.88
   93.33   33  3.00  10  6 84  3.49 2.94 2.87      // end run
   13.21  302  3.90   5  4 90  3.49 2.94 2.87
  130.67    6  0.76   4  3 93  3.49 2.94 2.87
  129.00    4  0.50   5  3 93  3.49 2.94 2.87

Generated at Thu Feb 08 08:58:12 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.