Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-5375

poor mongos insert/update performance when many duplicate shard keys are present due to Chunk::splitIfShould() (OS X specific?)

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Gone away
    • Affects Version/s: 2.0.4, 2.4.6
    • Fix Version/s: None
    • Component/s: Sharding
    • Labels:
      None
    • Environment:
      Debug build
      OS X 10.7.3 4x2.8GHz i5 iMac, 12GB RAM, 1TB HD
      Ubuntu Linux 3.0.0-16 4xVirtualized cores, 2GB RAM, 256GB HD
    • Operating System:
      ALL

      Description

      Simple shard test setup:

      mongos> db.runCommand( { enablesharding : "shardtest" } );
      mongos> db.runCommand( { shardcollection : "shardtest.txtcol", key : {txtkey:1} });
      ...
      mongos> use shardtest
      switched to db shardtest
      mongos> show collections
      shardcol
      system.indexes
      txtcol
      mongos> for (i=0;i<100000;i++) { db.txtcol.insert({txtkey:'asdfasdffdsafdsa', asdf:'asdkghkuwehgkawuhegawegwkrughekurghkauerhgkuhaekruhgkuehrgkuhreg'}); }

      Inserts 2 documents every two seconds. Verified via count() and mongostat:

      insert  query update delete getmore command flushes mapped  vsize    res locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn set repl       time 
           0      0      0      0       0       5       0   672m  3.76g    19m        0          0       0|0     5|0   558b     2k    23 sh1    M   01:06:46 
           2      0      0      0       4       3       0   672m  3.76g    19m        0          0       0|0     5|0   849b     3k    23 sh1    M   01:06:47 
           0      0      0      0       0       5       0   672m  3.76g    19m        0          0       0|0     5|0   558b     2k    23 sh1    M   01:06:48 
           2      0      0      0       4       3       1   672m  3.76g    19m        0          0       0|0     5|0   849b     3k    23 sh1    M   01:06:49 
           0      0      0      0       0       5       0   672m  3.76g    20m        0          0       0|0     5|0   558b     2k    23 sh1    M   01:06:50 
           2      0      0      0       5       3       0   672m  3.76g    20m        0          0       0|0     5|0   896b     3k    23 sh1    M   01:06:51 

      When the insert function was changed to use unique keys:

      mongos> for (i=0;i<100000;i++) { db.txtcol.insert({txtkey:'asdfasdffdsafdsa'+i, asdf:'asdkghkuwehgkawuhegawegwkrughekurghkauerhgkuhaekruhgkuehrgkuhreg'}); }

      mongos slowly ramped up to roughly 2k inserts/second:

      insert  query update delete getmore command flushes mapped  vsize    res locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn set repl       time 
           0      0      0      0       0       1       0   672m  3.76g    23m        0          0       0|0     5|0    62b     1k    23 sh1    M   01:10:21 
           2      0      0      0       4      21       0   672m  3.76g    23m        0          0       0|0     5|0     2k    11k    23 sh1    M   01:10:22 
           0      0      0      0       0      17       0   672m  3.76g    23m        0          0       0|0     5|0     1k    12k    23 sh1    M   01:10:23 
           2      0      0      0       6      11       0   672m  3.76g    23m        0          0       0|0     5|0     1k     4k    23 sh1    M   01:10:24 
           0      0      0      0       0       1       0   672m  3.76g    23m        0          0       0|0     5|0    62b     1k    23 sh1    M   01:10:25 
           2      0      0      0       4       7       0   672m  3.76g    23m        0          0       0|0     5|0     1k     3k    23 sh1    M   01:10:26 
           0      0      0      0       0       1       0   672m  3.76g    23m        0          0       0|0     5|0    62b     1k    23 sh1    M   01:10:27 
           2      0      0      0       7       7       0   672m  3.76g    23m        0          0       0|0     5|0     1k     4k    23 sh1    M   01:10:28 
           0      0      0      0       0       1       0   672m  3.76g    23m        0          0       0|0     5|0    62b     1k    23 sh1    M   01:10:29 
           3      0      0      0       8      11       0   672m  3.76g    23m        0          0       0|0     6|0     2k     5k    24 sh1    M   01:10:30 
      insert  query update delete getmore command flushes mapped  vsize    res locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn set repl       time 
           0      0      0      0       0       1       0   672m  3.76g    23m        0          0       0|0     6|0    62b     1k    24 sh1    M   01:10:31 
           4      0      0      0      10      39       0   672m  3.76g    14m      1.6          0       0|0     6|0     4k    23k    24 sh1    M   01:10:32 
           0      0      0      0       0       1       0   672m  3.76g    19m        0          0       0|0     6|0   128b     2k    24 sh1    M   01:10:33 
           4      0      0      0      10      13       0   672m  3.76g    12m      1.6          0       0|0     6|0     2k     6k    25 sh1    M   01:10:34 
           0      0      0      0       0       1       0   672m  3.76g    19m        0          0       0|0     6|0    62b     1k    25 sh1    M   01:10:35 
           2      0      0      0       5       7       0   672m  3.76g    23m        0          0       0|0     6|0     1k     4k    25 sh1    M   01:10:36 
           1      3      0      0       4      11       0   672m  3.77g    23m        0          0       0|0     6|0     1k     6k    26 sh1    M   01:10:37 
           0      0      0      0       0       5       0   672m  3.77g    23m        0          0       0|0     6|0   558b     2k    26 sh1    M   01:10:38 
         750      1      0      0    1000       7       0   672m  3.77g    24m      9.6          0       0|0     6|0   170k   614k    26 sh1    M   01:10:39 
           0      0      0      0       0       5       0   672m  3.77g    24m        0          0       0|0     6|0   558b     2k    26 sh1    M   01:10:40 
      insert  query update delete getmore command flushes mapped  vsize    res locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn set repl       time 
         733      0      0      0    1158       3       0   672m  3.77g    25m     12.6          0       0|0     6|0   176k   614k    26 sh1    M   01:10:41 
         142      0      0      0      67      35       0   672m  3.77g    18m      3.3          0       0|0     5|0    28k   132k    26 sh1    M   01:10:42 
           0      0      0      0       0       1       0   672m  3.77g    23m        0          0       0|0     5|0    62b     1k    26 sh1    M   01:10:43 
         728      0      0      0     917      11       0   672m  3.77g    25m     12.9          0       0|0     5|0   165k   605k    26 sh1    M   01:10:44 
           0      0      0      0       0       1       0   672m  3.77g    25m        0          0       0|0     5|0    62b     1k    26 sh1    M   01:10:45 
         726      0      0      0     932       7       0   672m  3.77g    15m     12.4          0       0|0     5|0   165k   605k    26 sh1    M   01:10:46 
           0      0      0      0       0       7       0   672m  3.77g    21m        0          0       0|0     5|0   434b     5k    26 sh1    M   01:10:47 
           1      2      0      0       4      12       0   672m  3.77g    26m        0          0       0|0     5|0     2k     8k    26 sh1    M   01:10:48 
           0      0      0      0       0       1       1   672m  3.77g    26m        0          0       0|0     5|0    62b     1k    26 sh1    M   01:10:49 
         189      0      0      0     151       5       0   672m  3.77g    26m      2.4          0       0|0     0|1    39k   142k    26 sh1    M   01:10:50 
      insert  query update delete getmore command flushes mapped  vsize    res locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn set repl       time 
        2087      0      0      0    2088       1       0   672m  3.77g    16m     37.4          0       2|0     2|1   446k     1m    26 sh1    M   01:10:51 
        1915      0      0      0    2254      35       0   672m  3.77g    16m     34.2          0       0|0     1|0   427k     1m    26 sh1    M   01:10:52 
        1959      0      0      0    2409       1       0   672m  3.77g    18m     34.5          0       0|0     0|0   440k     1m    26 sh1    M   01:10:53 
        2002      0      0      0    2288      11       0   672m  3.77g    19m     33.4          0       0|1     0|1   443k     1m    26 sh1    M   01:10:54 
        2053      0      0      0    2029       1       0   672m  3.77g    19m     33.2          0       1|0     2|0   440k     1m    26 sh1    M   01:10:55 
        1992      0      0      0    2057       5       0   672m  3.77g    20m     36.3          0       0|0     1|0   431k     1m    26 sh1    M   01:10:56 
        1987      0      0      0    2536       7       0   672m  3.77g    22m     30.9          0       0|0     0|0   453k     1m    26 sh1    M   01:10:57 
        1873      0      0      0    2478       5       0   672m  3.77g    23m     32.8          0       0|0     0|0   431k     1m    26 sh1    M   01:10:58 
        2003      0      0      0    2299       1       0   672m  3.77g    23m     32.7          0       0|1     1|1   444k     1m    26 sh1    M   01:10:59 
        2124      0      0      0    1852       5       0   672m  3.77g    24m     34.6          0       3|0     3|0   444k     1m    26 sh1    M   01:11:00 
      insert  query update delete getmore command flushes mapped  vsize    res locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn set repl       time 
        1931      0      0      0    2303       1       0   672m  3.77g    25m     30.8          0       4|0     4|1   432k     1m    26 sh1    M   01:11:01 

      The following log entry appeared every 500ms-2s in the mongos logs:

      Fri Mar 23 01:08:11 [conn1] Request::process ns: shardtest.txtcol msg id:187 attempt: 0
      Fri Mar 23 01:08:11 [conn1] write: shardtest.txtcol
      Fri Mar 23 01:08:11 [conn1]   server:sh1:sh1/localhost:27017,localhost:27018,localhost:27019,localhost:27020,localhost:27021 { _id: ObjectId('4f6c2eb0e4466c463950f631'), txtkey: "asdfasdffdsafdsa", asdf: "asdkghkuwehgkawuhegawegwkrughekurghkauerhgkuhaekruhgkuehrgkuhreg" }
      Fri Mar 23 01:08:11 [conn1] about to initiate autosplit: ns:shardtest.txtcol at: sh1:sh1/localhost:27017,localhost:27018,localhost:27019,localhost:27020,localhost:27021 lastmod: 1|0 min: { txtkey: MinKey } max: { txtkey: MaxKey } dataWritten: 252 splitThreshold: 921

      dataWritten is the same in all output.

      The following appears in the mongod logs:

      Fri Mar 23 01:05:41 [conn25] warning: chunk is larger than 1024 bytes because of key { txtkey: "asdfasdffdsafdsa" }
      Fri Mar 23 01:05:41 [conn25] warning: Finding the split vector for shardtest.txtcol over { txtkey: 1.0 } keyCount: 4 numSplits: 0 lookedAt: 299107 took 2035ms
      Fri Mar 23 01:05:41 [conn25] command admin.$cmd command: { splitVector: "shardtest.txtcol", keyPattern: { txtkey: 1.0 }, min: { txtkey: MinKey }, max: { txtkey: MaxKey }, maxChunkSizeBytes: 1024, maxSplitPoints: 2, maxChunkObjects: 250000 } ntoreturn:1 reslen:53 2035ms

      Going back to the original test script with identical keys (and an empty collection), if the calls to splitIfShould() in strategy_shard.cpp L164 and L330 are commented out, mongos inserts documents with identical keys at over 2k/second:

      insert  query update delete getmore command flushes mapped  vsize    res locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn set repl       time 
        2081      0      0      0    2495       5       0   672m  3.76g    10m     36.5          0       0|1     1|1   456k     1m    17 sh1    M   00:56:50 
        1939      0      0      0    2844      31       0   672m  3.76g    11m     29.6          0       0|0     1|0   451k     1m    17 sh1    M   00:56:51 
        2189      0      0      0    2328       5       0   672m  3.76g    12m     34.3          0       0|0     0|0   466k     1m    17 sh1    M   00:56:52 
        2155      0      0      0    2234       1       0   672m  3.76g    12m       35          0       1|0     1|0   456k     1m    17 sh1    M   00:56:53 
        2016      0      0      0    2363       5       0   672m  3.76g    13m     31.7          0       4|0     4|1   440k     1m    17 sh1    M   00:56:54 
        2105      0      0      0    2203       1       0   672m  3.76g    14m     36.2          0       0|0     0|0   446k     1m    17 sh1    M   00:56:55 
        2139      0      0      0    2416       5       0   672m  3.76g    16m     33.8          0       1|0     2|1   462k     1m    17 sh1    M   00:56:56 
        1782      0      0      0    1737       1       0   672m  3.76g    16m     27.9          0       0|0     4|0   372k     1m    18 sh1    M   00:56:57 

      The same test was performed on a virtualized linux machine on the same host, and was consistently seeing 4-5k inserts/sec with the identical shard key test. More profiling can be done to track down the root cause of slowness. I was unable to find a reason for the different behavior on Linux.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              backlog-server-sharding Backlog - Sharding Team
              Reporter:
              benjamin.becker Ben Becker
              Participants:
              Votes:
              1 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: