title: mongo upsert performance (C++)
body: <p>I am writing a C++ client that processes a file with 1M rows and inserts them in mongodb. The data is inserted in 6 different tables that follow different accumulation criteria. I accumulate the data of 5000 rows (configurable) in a C++ map and then insert (upsert) into mongodb, rinse and repeat until the end of file.</p>
  
  <p>The code for one of the upserts is:</p>
  
  <pre><code>void Upsert(mongo::DBClientConnection &amp; cmon)
      {
          map&lt;KEY, VALUE&gt;::const_iterator it;
          cmon.ensureIndex("test.WebNavigationUri", BSON("ClientId" &lt;&lt; 1 &lt;&lt; "Uri" &lt;&lt; 1 &lt;&lt; "Date" &lt;&lt; 1), true);
  
          for (it=detail.begin(); it!=detail.end(); ++it)
          {
              cmon.update("test.WebNavigationUri",
                  BSON("ClientId" &lt;&lt; it-&gt;first.clientid &lt;&lt; "Uri" &lt;&lt; it-&gt;first.uri &lt;&lt; "Date" &lt;&lt; it-&gt;second.dHora),
                  BSON("$inc" &lt;&lt; BSON("Time" &lt;&lt; it-&gt;second.time)),
                  true);
          }
      }
  </code></pre>
  
  <p>The other upsert are identical except for the info stored.
  My problem is that if I only use 2 tables, the times are reasonably fast (4-8 times faster than MySql), but if I use all 6 the performance degrades.</p>
  
  <p>With 2 tables:</p>
  
  <p>WebAccumulationCategory: 6877ms <strong>261749</strong> items; <strong>1465ms</strong> (1465 + 0 + 0 + 0).</p>
  
  <p>WebAccumulationClientId: 5005ms 0 items; 0ms (0 + 0 + 0 + 0). </p>
  
  <p>WebAccumulationPolicy: 5115ms 0 items; 0ms (0 + 0 + 0 + 0).</p>
  
  <p>WebAccumulationVirusName: 0ms 0 items; 0ms (0 + 0 + 0 + 0).</p>
  
  <p>WebNavigationCategory: 5442ms 0 items; 0ms (0 + 0 + 0 + 0).</p>
  
  <p>WebNavigationUri: 9493ms <strong>414610</strong> items; <strong>3666ms</strong> (3666 + 0 + 0 + 0).</p>
  
  <p>With 6 tables (same file, tables dropped):</p>
  
  <p>WebAccumulationCategory: 6605ms <strong>261749</strong> items; <strong>1421ms</strong> (1421 + 0 + 0 + 0)</p>
  
  <p>WebAccumulationClientId: 5367ms 172873 items; 1753ms (1753 + 0 + 0 + 0)</p>
  
  <p>WebAccumulationPolicy: 6187ms 174941 items; 2086ms (2086 + 0 + 0 + 0)</p>
  
  <p>WebAccumulationVirusName: 12ms 52 items; 0ms (0 + 0 + 0 + 0)</p>
  
  <p>WebNavigationCategory: 18745ms 258072 items; 14510ms (14510 + 0 + 0 + 0)</p>
  
  <p>WebNavigationUri: 33046ms <strong>414610</strong> items; <strong>27317ms</strong> (27317 + 0 + 0 + 0)</p>
  
  <p>Times are measured in the program with </p>
  
  <pre><code>boost::posix_time::microsec_clock::local_time();
  </code></pre>
  
  <p>I use mongodb 2.4.9 in an Oracle Server 6.5 machine. The program uses the C++ driver and runs in the same machine.</p>
  
  <p>As you can see WebNavigationUri goes from 3666ms to 27317ms when I upsert in the other 4 tables, but the time for WebAccumulationCategory remains the same. It would seem there is some sort of interaction between the tables and/or the order in which I make the upserts.
  Any ideas why is this loss of performance is happening? What can I look for / monitor in the database?</p>
  
  <p>mongostat says:</p>
  
  <pre><code>insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time  
      *0     *0     *0     *0       0     1|0       0   544m  1.42g   247m      0  test:0.0%          0       0|0     0|0    62b     3k     6   12:09:59  
       3     *0   2696     *0       0     1|0       0   544m  1.42g   254m      4 test:23.5%          0       0|0     0|0   583k     3k     6   12:10:00  
       3     *0  10635     *0       0     2|0       0   544m  1.42g   248m      3 test:80.3%          0       0|0     0|1     2m     3k     6   12:10:01  
      *0     *0  13151     *0       0     1|0       0   544m  1.42g   252m      0 test:80.9%          0       0|0     0|1     2m     3k     6   12:10:02  
      *0     *0  13089     *0       0     1|0       0   544m  1.42g   253m      0 test:81.7%          0       0|0     0|1     2m     3k     6   12:10:03  
      *0     *0  13567     *0       0     1|0       0   544m  1.42g   250m      0 test:81.5%          0       0|0     0|1     2m     3k     6   12:10:04  
      *0     *0  13636     *0       0     1|0       0   544m  1.42g   248m      0 test:81.2%          0       0|0     0|1     2m     3k     6   12:10:05  
      *0     *0  13417     *0       0     2|0       0   544m  1.42g   255m      0 test:78.9%          0       0|0     0|1     2m     3k     6   12:10:06  
      *0     *0  13759     *0       0     1|0       0   544m  1.42g   256m      0 test:81.0%          0       0|0     0|1     2m     3k     6   12:10:07  
      *0     *0  13556     *0       0     1|0       0   544m  1.42g   257m      0 test:80.9%          0       0|0     0|1     2m     3k     6   12:10:08  
  insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time  
      *0     *0  13821     *0       0     1|0       0   544m  1.42g   257m      0 test:81.0%          0       0|0     0|1     2m     3k     6   12:10:09  
      *0     *0  13932     *0       0     1|0       0   544m  1.42g   258m      0 test:81.0%          0       0|0     0|1     2m     3k     6   12:10:10  
      *0     *0  13460     *0       0     2|0       0   544m  1.42g   258m      0 test:81.0%          0       0|0     0|1     2m     3k     6   12:10:11  
      *0     *0  13823     *0       0     1|0       0   544m  1.42g   256m      0 test:80.8%          0       0|0     0|1     2m     3k     6   12:10:12  
      *0     *0  13811     *0       0     1|0       0   544m  1.42g   253m      0 test:80.3%          0       0|0     0|1     2m     3k     6   12:10:13  
      *0     *0  13794     *0       0     1|0       0   544m  1.42g   251m      0 test:81.2%          0       0|0     0|1     2m     3k     6   12:10:14  
      *0     *0  13605     *0       0     1|0       0   544m  1.42g   247m      0 test:79.6%          0       0|1     0|1     2m     3k     6   12:10:15  
      *0     *0  13403     *0       0     2|0       0   544m  1.42g   261m      0 test:79.0%          0       0|0     0|1     2m     3k     6   12:10:16  
      *0     *0  13781     *0       0     1|0       0   544m  1.42g   261m      0 test:81.2%          0       0|0     0|0     2m     3k     6   12:10:17  
      *0     *0  13824     *0       0     1|0       0   544m  1.42g   262m      0 test:80.6%          0       0|0     0|1     2m     3k     6   12:10:18  
  insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time  
      *0     *0  13954     *0       0     1|0       0   544m  1.42g   262m      0 test:81.0%          0       0|0     0|1     2m     3k     6   12:10:19  
      *0     *0  13873     *0       0     2|0       0   544m  1.42g   262m      0 test:81.3%          0       0|0     0|1     2m     3k     6   12:10:20  
      *0     *0  13416     *0       0     2|0       0   544m  1.42g   261m      0 test:79.4%          0       0|0     0|1     2m     3k     6   12:10:21  
      *0     *0  13840     *0       0     1|0       0   544m  1.42g   261m      0 test:81.2%          0       0|0     0|1     2m     3k     6   12:10:22  
      *0      1  13657     *0       0    13|0       0   544m  1.42g   259m      0 test:80.4%          0       0|0     0|1     2m    11k     6   12:10:23  
      *0     *0  12566     *0       0     1|0       0   544m  1.42g   259m      0 test:75.5%          0       0|0     0|1     2m     3k     6   12:10:24  
      *0     *0  13777     *0       0     1|0       0   544m  1.42g   251m      0 test:80.4%          0       0|0     0|1     2m     3k     6   12:10:25  
      *0     *0  13148     *0       0     2|0       0   544m  1.42g   265m      0 test:77.6%          0       0|0     0|1     2m     3k     6   12:10:26  
      *0     *0  13691     *0       0     1|0       0   544m  1.42g   265m      0 test:80.7%          0       0|0     0|1     2m     3k     6   12:10:27  
      *0     *0  13633     *0       0     1|0       0   544m  1.42g   265m      0 test:80.2%          0       0|0     0|0     2m     3k     6   12:10:28  
  insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time  
      *0     *0  13538     *0       0     1|0       0   544m  1.42g   265m      0 test:80.7%          0       0|0     0|1     2m     3k     6   12:10:29  
      *0     *0  13773     *0       0     1|0       0   544m  1.42g   265m      0 test:80.4%          0       0|0     0|1     2m     3k     6   12:10:30  
      *0     *0   9118     *0       0     2|0       0   544m  1.42g   263m      0 test:52.9%          0       0|0     0|1     1m     3k     6   12:10:31  
      *0     *0  11894     *0       0     1|0       0   544m  1.42g   268m      0 test:68.6%          0       0|0     0|1     2m     3k     6   12:10:32  
      *0     *0  13742     *0       0     1|0       0   544m  1.42g   266m      0 test:80.6%          0       0|0     0|1     2m     3k     6   12:10:33  
      *0     *0  13583     *0       0     1|0       0   544m  1.42g   266m      0 test:80.8%          0       0|0     0|1     2m     3k     6   12:10:34  
      *0     *0  13769     *0       0     1|0       0   544m  1.42g   266m      0 test:81.4%          0       0|0     0|1     2m     3k     6   12:10:35  
      *0     *0  13921     *0       0     2|0       0   544m  1.42g   268m      0 test:81.1%          0       0|0     0|1     2m     3k     6   12:10:36  
      *0     *0  13414     *0       0     1|0       0   544m  1.42g   265m      0 test:78.4%          0       0|0     0|1     2m     3k     6   12:10:37  
      *0     *0  13489     *0       0     1|0       0   544m  1.42g   263m      0 test:80.7%          0       0|0     0|1     2m     3k     6   12:10:38  
  insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time  
      *0     *0  13847     *0       0     1|0       0   544m  1.42g   262m      0 test:81.3%          0       0|0     0|1     2m     3k     6   12:10:39  
      *0      3  13776     *0       0     1|0       0   544m  1.42g   266m      0 test:80.6%          0       0|0     0|1     2m     3k     6   12:10:40  
      *0     *0  14000     *0       0     2|0       0   544m  1.42g   251m      0 test:81.1%          0       0|0     0|1     2m     3k     6   12:10:41  
      *0     *0  13416     *0       0     1|0       0   544m  1.42g   270m      0 test:77.8%          0       0|0     0|1     2m     3k     6   12:10:42  
      *0     *0  13583     *0       0     1|0       0   544m  1.42g   270m      0 test:80.8%          0       0|0     0|1     2m     3k     6   12:10:43  
      *0     *0  13854     *0       0     1|0       0   544m  1.42g   272m      0 test:80.9%          0       0|0     0|1     2m     3k     6   12:10:44  
      *0     *0  13742     *0       0     1|0       0   544m  1.42g   270m      0 test:80.6%          0       0|0     0|1     2m     3k     6   12:10:45  
      *0     *0  13708     *0       0     2|0       0   544m  1.42g   269m      0 test:80.7%          0       0|0     0|1     2m     3k     6   12:10:46  
      *0     *0  13675     *0       0     1|0       0   544m  1.42g   269m      0 test:80.8%          0       0|0     0|1     2m     3k     6   12:10:47  
      *0     *0  11748     *0       0     1|0       0   544m  1.42g   271m      0 test:68.9%          0       0|0     0|1     2m     3k     6   12:10:48  
  insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time  
      *0     *0   9845     *0       0     1|0       1   544m  1.42g   274m      0 test:56.4%          0       0|0     0|1     1m     3k     6   12:10:49  
      *0     *0  13623     *0       0     2|0       0   544m  1.42g   271m      0 test:81.0%          0       0|0     0|1     2m     3k     6   12:10:50  
      *0     *0  13530     *0       0     2|0       0   544m  1.42g   271m      0 test:80.4%          0       0|0     0|1     2m     3k     6   12:10:51  
      *0     *0  14127     *0       0     1|0       0   544m  1.42g   274m      0 test:81.2%          0       0|0     0|1     2m     3k     6   12:10:52  
      *0     *0  13734     *0       0     1|0       0   544m  1.42g   270m      0 test:80.8%          0       0|0     0|1     2m     3k     6   12:10:53  
      *0     *0  13305     *0       0     1|0       0   544m  1.42g   268m      0 test:81.3%          0       0|0     0|1     2m     3k     6   12:10:54  
      *0     *0  13575     *0       0     1|0       0   544m  1.42g   269m      0 test:80.9%          0       0|0     0|1     2m     3k     6   12:10:55  
      *0     *0  13735     *0       0     2|0       0   544m  1.42g   272m      0 test:80.2%          0       0|0     0|1     2m     3k     6   12:10:56  
      *0     *0  13809     *0       0     1|0       0   544m  1.42g   257m      0 test:80.5%          0       0|0     0|1     2m     3k     6   12:10:57  
      *0     *0  13896     *0       0     1|0       0   544m  1.42g   252m      0 test:81.3%          0       0|0     0|1     2m     3k     6   12:10:58  
  insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time  
      *0     *0  13207     *0       0     1|0       0   544m  1.42g   274m      0 test:78.0%          0       0|0     0|0     2m     3k     6   12:10:59  
      *0     *0  14075     *0       0     1|0       0   544m  1.42g   276m      0 test:81.1%          0       0|0     0|1     2m     3k     6   12:11:00  
      *0     *0  11833     *0       0     2|0       0   544m  1.42g   273m      0 test:70.9%          0       0|0     0|1     2m     3k     6   12:11:01  
      *0     *0  13540     *0       0     1|0       0   544m  1.42g   271m      0 test:81.0%          0       0|0     0|1     2m     3k     6   12:11:02  
      *0     *0  13762     *0       0     1|0       0   544m  1.42g   272m      0 test:80.8%          0       0|0     0|1     2m     3k     6   12:11:03  
      *0     *0  13535     *0       0     1|0       0   544m  1.42g   275m      0 test:79.3%          0       0|0     0|1     2m     3k     6   12:11:04  
      *0     *0  13584     *0       0     1|0       0   544m  1.42g   265m      0 test:80.1%          0       0|0     0|1     2m     3k     6   12:11:05  
      *0     *0   9272     *0       0     2|0       0   544m  1.42g   275m      0 test:54.3%          0       0|0     0|1     1m     3k     6   12:11:06  
      *0     *0   8524     *0       0     1|0       0   544m  1.42g   271m      0 test:52.8%          0       0|0     0|1     1m     3k     6   12:11:07  
      *0     *0  13772     *0       0     1|0       0   544m  1.42g   272m      0 test:81.6%          0       0|0     0|1     2m     3k     6   12:11:08  
  insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time  
      *0     *0  11479     *0       0     1|0       0   544m  1.42g   271m      0 test:65.8%          0       1|0     0|1     2m     3k     6   12:11:09  
      *0     *0  13835     *0       0     1|0       0   544m  1.42g   252m      0 test:80.8%          0       0|0     0|1     2m     3k     6   12:11:10  
      *0     *0  13597     *0       0     2|0       0   544m  1.42g   276m      0 test:80.2%          0       0|0     0|1     2m     3k     6   12:11:11  
      *0     *0  13704     *0       0     1|0       0   544m  1.42g   275m      0 test:80.9%          0       0|0     0|1     2m     3k     6   12:11:12  
      *0     *0  14127     *0       0     1|0       0   544m  1.42g   279m      0 test:81.2%          0       0|0     0|1     2m     3k     6   12:11:13  
      *0     *0  13144     *0       0     1|0       0   544m  1.42g   275m      0 test:78.1%          0       0|0     0|1     2m     3k     6   12:11:14  
      *0     *0  13680     *0       0     1|0       0   544m  1.42g   273m      0 test:80.9%          0       0|0     0|1     2m     3k     6   12:11:15  
      *0     *0  13491     *0       0     2|0       0   544m  1.42g   273m      0 test:78.9%          0       0|0     0|0     2m     3k     6   12:11:16  
      *0     *0     *0     *0       0     1|0       0   544m  1.42g   265m      0     .:0.1%          0       0|0     0|0    62b     3k     5   12:11:17  
      *0      1     *0     *0       0    13|0       0   544m  1.42g   258m      0 config:0.1%          0       0|0     0|0   892b    11k     5   12:11:18 
  </code></pre>
  
  <p>Blocking is at 80% but I guess it's normal given that I am upserting 13K records per second.</p>