Login/Register
MongoDB ACKNOWLEDGED write concern faster than UNACKNOWLEDGED?
Asked Answered
javamongodbbulkinsertdatabase-performance
D

0

6

I've got a very simple test program that performs faster with ACKNOWLEDGED bulk inserts than with UNACKNOWLEDGED. And it's not just a little faster - I'm seeing a factor of nearly 100!

My understanding of the difference between these two write concerns is solely that with ACKNOWLEDGED the client waits for confirmation from the server that the operation has been executed (but not necessarily made durable), while with UNACKNOWLEDGED the client only knows that the request made it out onto the wire. So it would seem preposterous that the former could actually perform at a higher speed, yet that's what I'm seeing.

I'm using the Java driver (v2.12.0) with Oracle's Java JDK v1.7.0_71, and mongo version 3.0.0 on 64-bit Windows 7. I'm running mongod, completely out-of-the-box (fresh install), no sharding or anything. And before each test I ensure that the collection is empty and has no non-default indexes.

I would appreciate any insight into why I'm consistently seeing the opposite of what I'd expect.

Thanks.

Here's my code:

package test;

import com.mongodb.BasicDBObject;
import com.mongodb.BulkWriteOperation;
import com.mongodb.BulkWriteResult;
import com.mongodb.DBCollection;
import com.mongodb.DBObject;
import com.mongodb.MongoClient;
import com.mongodb.ServerAddress;
import com.mongodb.WriteConcern;

import java.util.Arrays;

public class Test {

  private static final int BATCHES = 100;
  private static final int BATCH_SIZE = 1000;
  private static final int COUNT = BATCHES * BATCH_SIZE;

  public static void main(String[] argv) throws Exception {
    DBCollection coll = new MongoClient(new ServerAddress()).getDB("test").getCollection("test");
    for (String wcName : Arrays.asList("UNACKNOWLEDGED", "ACKNOWLEDGED")) {
      WriteConcern wc = (WriteConcern) WriteConcern.class.getField(wcName).get(null);
      coll.dropIndexes();
      coll.remove(new BasicDBObject());
      long start = System.currentTimeMillis();
      BulkWriteOperation bulkOp = coll.initializeUnorderedBulkOperation();
      for (int i = 1; i < COUNT; i++) {
        DBObject doc = new BasicDBObject().append("int", i).append("string", Integer.toString(i));
        bulkOp.insert(doc);
        if (i % BATCH_SIZE == 0) {
          BulkWriteResult results = bulkOp.execute(wc);
          if (wc == WriteConcern.ACKNOWLEDGED && results.getInsertedCount() != 1000) {
            throw new RuntimeException("Bogus insert count: " + results.getInsertedCount());
          }
          bulkOp = coll.initializeUnorderedBulkOperation();
        }
      }
      long time = System.currentTimeMillis() - start;
      double rate = COUNT / (time / 1000.0);
      System.out.printf("%s[w=%s,j=%s]: Inserted %d documents in %s @ %f/sec\n",
          wcName, wc.getW(), wc.getJ(), COUNT, duration(time), rate);
    }
  }

  private static String duration(long msec) {
    return String.format("%d:%02d:%02d.%03d",
        msec / (60 * 60 * 1000),
        (msec % (60 * 60 * 1000)) / (60 * 1000),
        (msec % (60 * 1000)) / 1000,
        msec % 1000);
  }
}

And here's typical output:

UNACKNOWLEDGED[w=0,j=false]: Inserted 100000 documents in 0:01:27.025 @ 1149.095088/sec
ACKNOWLEDGED[w=1,j=false]: Inserted 100000 documents in 0:00:00.927 @ 107874.865156/sec

EDIT

Ran more extensive tests, per request from Markus W. Mahlberg. For these tests, I ran the code with four write concerns: UNACKNOWLEDGED, ACKNOWLEDGED, JOURNALED, and FSYNCED. (I would expect this order to show decreasing speed.) I ran 112 repetitions, each of which performed 100 batches of 1000 inserts under each of the four write concerns, each time into an empty collection with no indexes. Code was identical to original post but with two additional write concerns, and with output to CSV format for easy analysis.

Results summary:

  • UNACKNOWLEDGED: 1147.105004 docs/sec avg, std dev 27.88577035
  • ACKNOWLEDGED: 77539.27653 docs/sec avg, std dev 1567.520303
  • JOURNALED: 29574.45243 docs/sec avg, std dev 123.9927554
  • FSYNCED: 29567.02467 docs/sec avg, std dev 147.6150994

The huge inverted performance difference between UNACKNOWLEDGED and ACKNOWLEDGED is what's got me baffled.

Here's the raw data if anyone cares for it ("time" is elapsed msec for 100*1000 insertions; "rate" is docs/second):

"UNACK time","UNACK rate","ACK time","ACK rate","JRNL time","JRNL rate","FSYNC time","FSYNC rate"
92815,1077.4120562409094,1348,74183.9762611276,3380,29585.798816568047,3378,29603.31557134399
90209,1108.5368422219512,1303,76745.97083653108,3377,29612.081729345577,3375,29629.62962962963
91089,1097.8273995762386,1319,75815.01137225171,3382,29568.30277942046,3413,29299.73630237328
90159,1109.1516099335618,1320,75757.57575757576,3375,29629.62962962963,3377,29612.081729345577
89922,1112.0749093658949,1315,76045.62737642587,3380,29585.798816568047,3376,29620.853080568722
89997,1111.1481493827573,1306,76569.67840735069,3381,29577.048210588586,3379,29594.55460195324
90141,1109.373093264996,1319,75815.01137225171,3386,29533.372711163614,3378,29603.31557134399
89771,1113.9454835080371,1325,75471.69811320755,3387,29524.65308532625,3521,28401.022436807725
89716,1114.6283828971423,1325,75471.69811320755,3379,29594.55460195324,3379,29594.55460195324
90205,1108.5859985588381,1323,75585.78987150417,3377,29612.081729345577,3376,29620.853080568722
90092,1109.976468498868,1328,75301.2048192771,3382,29568.30277942046,3379,29594.55460195324
89822,1113.3129968159249,1322,75642.965204236,3385,29542.097488921714,3383,29559.562518474726
89821,1113.3253916122064,1310,76335.87786259541,3380,29585.798816568047,3383,29559.562518474726
89945,1111.7905386625162,1318,75872.53414264036,3379,29594.55460195324,3379,29594.55460195324
89917,1112.1367483345753,1352,73964.49704142011,3381,29577.048210588586,3377,29612.081729345577
90358,1106.7088691648773,1303,76745.97083653108,3377,29612.081729345577,3380,29585.798816568047
90187,1108.8072560346836,1348,74183.9762611276,3387,29524.65308532625,3395,29455.081001472754
90634,1103.3387029150208,1322,75642.965204236,3384,29550.827423167848,3381,29577.048210588586
90148,1109.2869503483162,1331,75131.48009015778,3389,29507.22927117144,3381,29577.048210588586
89767,1113.9951207013714,1321,75700.22710068131,3380,29585.798816568047,3382,29568.30277942046
89910,1112.2233344455567,1321,75700.22710068131,3381,29577.048210588586,3385,29542.097488921714
89852,1112.9412812180028,1316,75987.84194528875,3381,29577.048210588586,3401,29403.116730373422
89537,1116.8567184515898,1319,75815.01137225171,3380,29585.798816568047,3380,29585.798816568047
89763,1114.0447623185498,1331,75131.48009015778,3380,29585.798816568047,3382,29568.30277942046
90070,1110.2475852115022,1325,75471.69811320755,3383,29559.562518474726,3378,29603.31557134399
89771,1113.9454835080371,1302,76804.91551459293,3389,29507.22927117144,3378,29603.31557134399
90518,1104.7526458825869,1325,75471.69811320755,3383,29559.562518474726,3380,29585.798816568047
90314,1107.2480457071995,1322,75642.965204236,3380,29585.798816568047,3384,29550.827423167848
89874,1112.6688474976079,1329,75244.54477050414,3386,29533.372711163614,3379,29594.55460195324
89954,1111.6793027547415,1318,75872.53414264036,3381,29577.048210588586,3381,29577.048210588586
89903,1112.3099340400208,1325,75471.69811320755,3379,29594.55460195324,3388,29515.9386068477
89842,1113.0651588343983,1314,76103.500761035,3382,29568.30277942046,3377,29612.081729345577
89746,1114.2557885588217,1325,75471.69811320755,3378,29603.31557134399,3385,29542.097488921714
93249,1072.3975592231552,1327,75357.95026375283,3381,29577.048210588586,3377,29612.081729345577
93638,1067.9425019756936,1331,75131.48009015778,3377,29612.081729345577,3392,29481.132075471698
87775,1139.2765593847905,1340,74626.86567164179,3379,29594.55460195324,3378,29603.31557134399
86495,1156.136192843517,1271,78678.20613690009,3375,29629.62962962963,3376,29620.853080568722
85584,1168.442699570013,1276,78369.90595611285,3432,29137.529137529138,3376,29620.853080568722
86648,1154.094728095282,1278,78247.2613458529,3382,29568.30277942046,3411,29316.91586045148
85745,1166.2487608606916,1274,78492.93563579278,3380,29585.798816568047,3363,29735.355337496283
85813,1165.3246011676551,1279,78186.08287724786,3375,29629.62962962963,3376,29620.853080568722
85831,1165.0802157728558,1288,77639.75155279503,3376,29620.853080568722,3377,29612.081729345577
85807,1165.4060857505797,1259,79428.11755361399,3466,28851.702250432772,3375,29629.62962962963
85964,1163.2776511097668,1258,79491.2559618442,3378,29603.31557134399,3378,29603.31557134399
85854,1164.7680946723508,1257,79554.49482895785,3382,29568.30277942046,3375,29629.62962962963
85787,1165.6777833471272,1257,79554.49482895785,3377,29612.081729345577,3377,29612.081729345577
85537,1169.084723569917,1272,78616.35220125786,3377,29612.081729345577,3377,29612.081729345577
85408,1170.8505058074186,1271,78678.20613690009,3375,29629.62962962963,3425,29197.080291970804
85577,1168.5382754712132,1261,79302.14115781126,3378,29603.31557134399,3375,29629.62962962963
85663,1167.365140142185,1261,79302.14115781126,3377,29612.081729345577,3378,29603.31557134399
85812,1165.3381811401669,1273,78554.59544383347,3377,29612.081729345577,3378,29603.31557134399
85783,1165.7321380693145,1273,78554.59544383347,3377,29612.081729345577,3376,29620.853080568722
85682,1167.106276697556,1280,78125.0,3381,29577.048210588586,3376,29620.853080568722
85753,1166.1399601180133,1260,79365.07936507936,3379,29594.55460195324,3377,29612.081729345577
85573,1168.5928972923703,1332,75075.07507507507,3377,29612.081729345577,3377,29612.081729345577
86206,1160.0120641254668,1263,79176.56373713381,3376,29620.853080568722,3383,29559.562518474726
85593,1168.31983923919,1264,79113.92405063291,3380,29585.798816568047,3378,29603.31557134399
85903,1164.1036983574495,1261,79302.14115781126,3378,29603.31557134399,3377,29612.081729345577
85516,1169.3718134618082,1277,78308.53563038372,3375,29629.62962962963,3376,29620.853080568722
85553,1168.8660830128692,1291,77459.3338497289,3490,28653.295128939826,3377,29612.081729345577
85550,1168.907071887785,1293,77339.52049497294,3379,29594.55460195324,3379,29594.55460195324
85610,1168.0878402055835,1298,77041.60246533128,3384,29550.827423167848,3378,29603.31557134399
85522,1169.2897733916418,1267,78926.59826361484,3379,29594.55460195324,3379,29594.55460195324
85595,1168.2925404521293,1276,78369.90595611285,3379,29594.55460195324,3376,29620.853080568722
85451,1170.2613193526115,1286,77760.49766718507,3376,29620.853080568722,3391,29489.82601002654
85792,1165.609847071988,1252,79872.20447284346,3382,29568.30277942046,3376,29620.853080568722
86501,1156.0559993526085,1255,79681.2749003984,3379,29594.55460195324,3379,29594.55460195324
85718,1166.616113301757,1269,78802.20646178094,3382,29568.30277942046,3376,29620.853080568722
85605,1168.156065650371,1265,79051.38339920949,3378,29603.31557134399,3380,29585.798816568047
85398,1170.9876109510762,1274,78492.93563579278,3377,29612.081729345577,3395,29455.081001472754
86370,1157.809424568716,1273,78554.59544383347,3376,29620.853080568722,3376,29620.853080568722
85905,1164.0765962400326,1280,78125.0,3379,29594.55460195324,3379,29594.55460195324
86020,1162.5203441060219,1285,77821.01167315176,3375,29629.62962962963,3376,29620.853080568722
85726,1166.5072440099852,1272,78616.35220125786,3380,29585.798816568047,3380,29585.798816568047
85628,1167.8422945765403,1270,78740.15748031496,3379,29594.55460195324,3376,29620.853080568722
85989,1162.93944574306,1258,79491.2559618442,3376,29620.853080568722,3378,29603.31557134399
85981,1163.047650062223,1276,78369.90595611285,3376,29620.853080568722,3376,29620.853080568722
86558,1155.2947156819703,1269,78802.20646178094,3385,29542.097488921714,3378,29603.31557134399
85745,1166.2487608606916,1293,77339.52049497294,3378,29603.31557134399,3375,29629.62962962963
85544,1168.9890582624148,1266,78988.94154818325,3376,29620.853080568722,3377,29612.081729345577
85536,1169.0983913206135,1268,78864.35331230283,3380,29585.798816568047,3380,29585.798816568047
85477,1169.9053546568082,1278,78247.2613458529,3388,29515.9386068477,3377,29612.081729345577
85434,1170.4941826439124,1253,79808.45969672786,3378,29603.31557134399,3375,29629.62962962963
85609,1168.1014846569872,1276,78369.90595611285,3364,29726.516052318668,3376,29620.853080568722
85740,1166.316771635176,1258,79491.2559618442,3377,29612.081729345577,3377,29612.081729345577
85640,1167.6786548341897,1266,78988.94154818325,3378,29603.31557134399,3377,29612.081729345577
85648,1167.569587147394,1281,78064.012490242,3378,29603.31557134399,3376,29620.853080568722
85697,1166.9019919017,1287,77700.0777000777,3377,29612.081729345577,3378,29603.31557134399
85696,1166.9156086631815,1256,79617.83439490446,3379,29594.55460195324,3376,29620.853080568722
85782,1165.7457275419085,1258,79491.2559618442,3379,29594.55460195324,3379,29594.55460195324
85837,1164.9987767512844,1264,79113.92405063291,3379,29594.55460195324,3376,29620.853080568722
85632,1167.7877428998504,1278,78247.2613458529,3380,29585.798816568047,3459,28910.089621277824
85517,1169.3581393173288,1256,79617.83439490446,3379,29594.55460195324,3380,29585.798816568047
85990,1162.925921618793,1302,76804.91551459293,3380,29585.798816568047,3377,29612.081729345577
86690,1153.535586572846,1281,78064.012490242,3375,29629.62962962963,3381,29577.048210588586
86045,1162.1825788831425,1274,78492.93563579278,3380,29585.798816568047,3383,29559.562518474726
86146,1160.820003250296,1274,78492.93563579278,3382,29568.30277942046,3418,29256.87536571094
86027,1162.4257500552153,1280,78125.0,3382,29568.30277942046,3381,29577.048210588586
85992,1162.8988743138896,1281,78064.012490242,3376,29620.853080568722,3380,29585.798816568047
85857,1164.727395553071,1288,77639.75155279503,3382,29568.30277942046,3376,29620.853080568722
85853,1164.7816616775185,1284,77881.6199376947,3375,29629.62962962963,3374,29638.41138114997
86069,1161.8585088707896,1295,77220.07722007722,3378,29603.31557134399,3378,29603.31557134399
85842,1164.930919596468,1296,77160.49382716049,3378,29603.31557134399,3376,29620.853080568722
86195,1160.160102094089,1301,76863.95080707148,3376,29620.853080568722,3379,29594.55460195324
85523,1169.2761011657683,1305,76628.35249042146,3376,29620.853080568722,3378,29603.31557134399
85752,1166.1535591006625,1275,78431.37254901961,3374,29638.41138114997,3377,29612.081729345577
85441,1170.3982865369085,1286,77760.49766718507,3377,29612.081729345577,3380,29585.798816568047
85566,1168.6884977678048,1265,79051.38339920949,3377,29612.081729345577,3380,29585.798816568047
85523,1169.2761011657683,1267,78926.59826361484,3377,29612.081729345577,3376,29620.853080568722
86152,1160.7391586962578,1285,77821.01167315176,3374,29638.41138114997,3378,29603.31557134399
85684,1167.0790345922226,1272,78616.35220125786,3378,29603.31557134399,3384,29550.827423167848
86252,1159.3934053703103,1271,78678.20613690009,3376,29620.853080568722,3377,29612.081729345577
Danie answered 14/3, 2015 at 2:14 Comment(10)
Well, how often did you run this test? Furthermore, iirc, the actual connection is made when the first operation is executed, which introduces some overhead. So after initializing the client, you should do a read operation to make sure the connection is established. After you changed the code accordingly, you should run this test often (1000+ times) to make sure that data syncs to journal and disk don't distort your results. – Tingley
Thanks. I ran the test several times - probably around 10. Each time I got results like the ones I showed - nearly two orders of magnitude slower for the approach that should have been faster. As for "warm-up" issues, the insert operations are not the first operations performed on the connection in my code. I drop indexes and remove all existing docs before issuing any inserts, and those are not part of the timing. I have a hard time believing the other factors you mention could cause such a huge effect. The two write concerns I'm testing are supposedly identical wrt journaling and data syncs. – Danie
Let me clarify my comment that the two write concerns are identical wrt journaling and data syncs. What I mean is that the work performed by the server is identical in both cases; the only difference is whether the client waits for results. – Danie
Another twist: I tried the same test with individual inserts rather than bulk operations. In that case, acknowledged writes were slower, generally by about half. And perhaps interestingly, the speed for unacknowledged single inserts was only slightly lower than the speed for unacknowledged bulk inserts. Perhaps there's something wrong with bulk operations in unacknowledged write concern? – Danie
I will test your code here and see if I get the same results. However, your sample size still is very small. Can you run it a couple of hundred times? – Tingley
I've updated the question with summary results and raw data from 112 repetitions using four write concerns. The dramatic speed inversion between UNACKNOWLEDGED and ACKNOWLEDGED write concerns was extremely consistent. – Danie
@markus: Just wondering whether you were able to try this, and whether you saw different results. Thanks. – Danie
Do you have any news regarding your problem? We have encountered the same issue. I did similar benchmarks in C. ackknowledged: total write time for 100 bulk writes with 1000 documents each was 10 seconds. unackknowledged: total write time for 100 bulk writes with 1000 documents each was 33 seconds. – Pederson
@sicker: Sadly, no. I was experimenting at the time, but wasn't really expecting to use unacknowledged writes in my application. I eventually moved on. It might be worth reporting to MongoDB at this point, now that there are at least two of us! :) – Danie
We are seeing a very similar issue. We insert 150 documents per operation. With Bulk ACKNOWLEDGED this takes 53ms for the 150 documents, with 150 x insertOne with ACKNOWLEDGED it takes 213ms. This seems to make sense, but with UNACKNOWLEDGED both bulk and many insertOne calls the time is virtually the same at 117ms. I think there may be some issue in the bulk UNACKNOWLEDGED code which is falling back to performing many insert operations. FYI : We use mongodb-driver 3.2.2 and I have ran our test over and over. – Addlebrained

© 2022 - 2024 — McMap. All rights reserved.