[SERVER-7480] Batch inserts through mongos with authentication much higher lock % than without in mongostat Created: 26/Oct/12  Updated: 05/May/14  Resolved: 15/Mar/14

Status: Closed
Project: Core Server
Component/s: Sharding
Affects Version/s: 2.2.0
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Thomas Rueckstiess Assignee: Thomas Rueckstiess
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 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 



 Comments   
Comment by Thomas Rueckstiess [ 15/Mar/14 ]

Can't reproduce this with 2.6, but I also don't get to these insert rates with 2.6 anymore. Closing.

Comment by Spencer Brody (Inactive) [ 13/Mar/14 ]

Thomas, can you confirm whether this is still a problem in 2.6?

Generated at Thu Feb 08 03:14:40 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.