Uploaded image for project: 'Java Driver'
  1. Java Driver
  2. JAVA-2846

WriteConcern.JOURNALED is not working

    • Type: Icon: Task Task
    • Resolution: Works as Designed
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 3.6.3
    • Component/s: Write Operations
    • None
    • 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

      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.

            Assignee:
            Unassigned Unassigned
            Reporter:
            sunguck.lee@gmail.com 아나 하리
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: