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