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

Batch inserts through mongos with authentication much higher lock % than without in mongostat

    XMLWordPrintableJSON

Details

    • Icon: Bug Bug
    • Resolution: Cannot Reproduce
    • Icon: Major - P3 Major - P3
    • None
    • 2.2.0
    • Sharding
    • None
    • ALL

    Description

      I've set up a sharded cluster, 1 shard, replica set of 3 nodes. Then inserted 500k small documents through mongos.

      When running everything with authentication (--keyFile), the lock % in mongostat is much higher (~69%) than when running without authentication (~29%), see below outputs.

      Side node: I used a monotonically increasing shard key for this test, because it is related to the customer case, but I don't know if this is relevant.

      With authentication:

           0      0      0      0       0       1       0   464m  3.37g    61m      0 local:0.0%          0       0|0     0|0    62b     2k    13 shard0  PRI   12:25:49 
           0      0      0      0       0       3       0   464m  3.37g    61m      0 local:0.0%          0       0|0     0|0   402b     2k    13 shard0  PRI   12:25:50 
      insert  query update delete getmore command flushes mapped  vsize    res faults   locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn    set repl       time 
        4271      0      0      0    3612       5       0   544m  3.56g    38m    121 local:14.5%          0       0|0     0|1   469k     1m    13 shard0  PRI   12:25:51 
        6121      0      2      0    5867       4       0   544m  3.56g    40m    170  test:67.9%          0       0|1     3|1   704k     1m    13 shard0  PRI   12:25:52 
        6138      0      2      0    6447       3       0   544m  3.56g    43m    155  test:63.3%          0       0|0     1|0   733k     1m    13 shard0  PRI   12:25:53 
        5677      0      2      0    5313      11       0   544m  3.56g    44m    179  test:65.7%          0       0|0     0|0   648k     1m    13 shard0  PRI   12:25:54 
        5756      0      2      0    5673       1       0   544m  3.56g    45m    154  test:64.7%          0       0|0     0|0   669k     1m    13 shard0  PRI   12:25:55 
        5928      0      2      0    6005       3       0   544m  3.56g    47m    164  test:65.8%          0       0|1     1|1   697k     1m    13 shard0  PRI   12:25:56 
        5988      0      2      0    6029       1       0   544m  3.56g    48m    182  test:67.0%          0       0|0     0|0   702k     1m    13 shard0  PRI   12:25:57 
        6052      0      2      0    6697       4       0   544m  3.56g    50m    166  test:63.4%          0       3|1     4|1   738k     1m    13 shard0  PRI   12:25:58 
        6278      0      2      0    6687       1       0   544m  3.56g    51m    168  test:64.8%          0       0|0     0|1   753k     1m    13 shard0  PRI   12:25:59 
        6643      0      2      0    6620       3       0   544m  3.56g    54m    204  test:67.2%          0       0|0     1|1   776k     1m    13 shard0  PRI   12:26:00 
      insert  query update delete getmore command flushes mapped  vsize    res faults   locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn    set repl       time 
        5228      0      2      0    5828       1       0   544m  3.56g    54m    139  test:65.7%          0       0|0     1|0   640k     1m    13 shard0  PRI   12:26:01 
        5532      0      2      0    5842       3       0   544m  3.56g    57m    166  test:64.9%          0       0|0     0|0   662k     1m    13 shard0  PRI   12:26:02 
        6645      0      2      0    7726       1       0   544m  3.56g    58m    183  test:65.4%          0       0|0     0|1   828k     1m    13 shard0  PRI   12:26:03 
        5241      3      2      0    5731      12       1   544m  3.56g    59m    148  test:65.1%          0       0|0     0|1   637k     1m    13 shard0  PRI   12:26:04 
        6000      0      2      0    6290       1       0   544m  3.56g    61m    174  test:64.3%          0       0|0     0|0   715k     1m    13 shard0  PRI   12:26:05 
        6460      0      2      0    6896       5       0   544m  3.56g    63m    179  test:65.5%          0       0|0     1|0   777k     1m    13 shard0  PRI   12:26:06 
        6041      0      2      0    6544       2       0   544m  3.56g    64m    180  test:59.3%          0       0|0     0|0   730k     1m    13 shard0  PRI   12:26:07 
           0      0      2      0       0       3       0   544m  3.56g    64m      0      .:1.1%          0       0|0     0|0   402b     2k    13 shard0  PRI   12:26:08 
           0      0      0      0       0       1       0   544m  3.56g    64m      0      .:0.3%          0       0|0     0|0    62b     2k    13 shard0  PRI   12:26:09 
           0      0      0      0       0       4       0   544m  3.56g    64m      0  local:0.0%          0       0|0     0|0   498b     2k    13 shard0  PRI   12:26:10 

      Without authentication:*

      insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn    set repl       time 
           0      0      0      0       0       1       0   464m  3.38g    20m      0 local:0.0%          0       0|0     0|0    62b     2k    11 shard0  PRI   12:28:16 
           0      0      0      0       0       9       0   464m  3.38g    20m      0 local:0.0%          0       0|0     0|0   722b     5k    11 shard0  PRI   12:28:17 
           0      0      0      0       0       1       0   464m  3.38g    20m      0 local:0.0%          0       0|0     0|0    62b     2k    11 shard0  PRI   12:28:18 
         368      0      0      0     531       9       0   544m  3.56g    37m      1 local:0.8%          0       1|0     2|0    51k   106k    12 shard0  PRI   12:28:19 
        3485      0      2      0    5618       1       0   544m  3.56g    24m    101 test:29.6%          0       0|0     0|0   508k     1m    12 shard0  PRI   12:28:20 
        3563      0      2      0    5925       4       0   544m  3.56g     9m    104 local:12.7%          0       0|0     0|0   528k     1m    12 shard0  PRI   12:28:21 
        4002      0      2      0    6426       1       0   544m  3.56g    10m    116  test:29.3%          0       0|0     0|0   582k     1m    12 shard0  PRI   12:28:22 
        3888      0      2      0    6147       5       0   544m  3.56g    13m    100  test:27.7%          0       0|0     0|0   561k     1m    12 shard0  PRI   12:28:23 
        3506      0      2      0    5829       1       0   544m  3.56g    14m    103  test:29.4%          0       0|0     0|0   519k     1m    12 shard0  PRI   12:28:24 
        3684      0      2      0    6284       3       0   544m  3.56g    15m    108  test:29.1%          0       0|0     0|0   553k     1m    12 shard0  PRI   12:28:25 
      insert  query update delete getmore command flushes mapped  vsize    res faults   locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn    set repl       time 
        3912      0      2      0    6423       1       0   544m  3.56g    16m    115  test:30.0%          0       0|0     0|0   575k     1m    12 shard0  PRI   12:28:26 
        3793      0      2      0    6366      10       0   544m  3.56g    19m     95  test:27.5%          0       0|0     0|0   565k     1m    13 shard0  PRI   12:28:27 
        3820      0      2      0    6268       1       0   544m  3.56g    21m    112  test:29.0%          0       0|0     0|0   562k     1m    13 shard0  PRI   12:28:28 
        3992      0      2      0    6310       3       0   544m  3.56g    22m    116  test:29.3%          0       0|0     2|0   576k     1m    13 shard0  PRI   12:28:29 
        3760      0      2      0    6146       1       0   544m  3.56g    22m    110  test:29.9%          0       0|0     0|0   552k     1m    13 shard0  PRI   12:28:30 
        3768      2      2      0    5988       3       1   544m  3.56g    24m     97  test:29.0%          0       0|1     0|1   545k     1m    13 shard0  PRI   12:28:31 
        4110      0      2      0    6426       1       0   544m  3.56g    27m    118  test:29.2%          0       0|0     0|0   589k     1m    13 shard0  PRI   12:28:32 
        3618      0      2      0    6081       4       0   544m  3.56g    28m    106  test:29.0%          0       0|0     0|0   539k     1m    13 shard0  PRI   12:28:33 
        3549      0      2      0    6266       1       0   544m  3.56g    28m    103 local:12.3%          0       0|1     1|1   542k     1m    13 shard0  PRI   12:28:34 
        3930      0      2      0    6404       3       0   544m  3.56g    31m    114  test:29.3%          0       0|0     0|0   576k     1m    13 shard0  PRI   12:28:35 
      insert  query update delete getmore command flushes mapped  vsize    res faults   locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn    set repl       time 
        3871      0      2      0    6042       1       0   544m  3.56g    32m     99  test:29.8%          0       0|0     0|0   555k     1m    13 shard0  PRI   12:28:36 
        3801      0      2      0    6367       9       0   544m  3.56g    34m    111  test:28.2%          0       0|0     2|0   565k     1m    13 shard0  PRI   12:28:37 
        4002      0      2      0    6277       1       0   544m  3.56g    35m    117  test:30.0%          0       0|0     0|0   575k     1m    13 shard0  PRI   12:28:38 
        3666      0      2      0    6099       4       0   544m  3.56g    37m    108  test:29.6%          0       0|0     0|0   543k     1m    13 shard0  PRI   12:28:39 
        3942      0      2      0    6452       1       0   544m  3.56g    37m    101  test:28.8%          0       0|0     0|0   579k     1m    13 shard0  PRI   12:28:40 
        3969      0      2      0    6537       3       0   544m  3.56g    38m    115  test:28.8%          0       0|0     1|0   585k     1m    13 shard0  PRI   12:28:41 
        4032      0      2      0    6637       1       0   544m  3.56g    41m    117  test:28.6%          0       0|0     0|0   594k     1m    13 shard0  PRI   12:28:42 
        3810      0      2      0    6195       5       0   544m  3.56g    42m    110  test:28.9%          0       0|0     0|0   558k     1m    13 shard0  PRI   12:28:43 
        3985      0      2      0    6371       1       0   544m  3.56g    43m    115  test:29.6%          0       0|0     0|0   578k     1m    13 shard0  PRI   12:28:44 
        3873      0      2      0    6323       4       0   544m  3.56g    44m    100  test:28.4%          0       0|0     0|0   568k     1m    13 shard0  PRI   12:28:45 
      insert  query update delete getmore command flushes mapped  vsize    res faults   locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn    set repl       time 
         300      0      2      0     479       2       0   544m  3.56g    44m     21   test:2.8%          0       0|0     0|0    43k    90k    13 shard0  PRI   12:28:46 
           0      0      0      0       0       9       0   544m  3.56g    44m      0      .:0.9%          0       0|0     0|0   722b     5k    13 shard0  PRI   12:28:47 
           0      0      0      0       0       1       0   544m  3.56g    44m      0   test:0.0%          0       0|0     0|0    62b     2k    13 shard0  PRI   12:28:48 

      Attachments

        Activity

          People

            thomas.rueckstiess@mongodb.com Thomas Rueckstiess
            thomas.rueckstiess@mongodb.com Thomas Rueckstiess
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: