[SERVER-7936] Slow authentication Created: 14/Dec/12  Updated: 08/Mar/13  Resolved: 15/Jan/13

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

Type: Question Priority: Major - P3
Reporter: dongde wu Assignee: Stephen Lee
Resolution: Cannot Reproduce Votes: 0
Labels: nh-240
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

3 nodes with Replica set
Server OS: Centos 5.5 64 bit
MongoDB : 1.8.2 64 bit
PHP : 5.3.6
PHP driver : 1.2.6


Participants:

 Description   

Dear Sir ,

The account authentication became slowly after MongoDB running a period of time (about 3 months) , the problem will be get rid after switch to second node . please help me investigate the problem , thanks

Here is log :
Fri Dec 14 01:28:00 [conn13613089] query devcmd.$cmd ntoreturn:1 command:

{ authenticate: 1, user: "mportal", nonce: "ab55d0ce2583c596", key: "d8dc96d497bbdfb52c9d132b842110a4" }

reslen:53 7111ms
Fri Dec 14 01:28:00 [conn13613090] query devcmd.$cmd ntoreturn:1 command:

{ authenticate: 1, user: "mportal", nonce: "33ed05275ef0e04b", key: "6d1a8349f759a4f5c9656b502f913e14" }

reslen:53 6396ms
Fri Dec 14 01:28:00 [conn13547075] query mstore.$cmd ntoreturn:1 command:

{ authenticate: 1, user: "tmpn", nonce: "abe4b16c18f1d400", key: "aa87004f495f76f4de862ac4287f9993" }

reslen:53 6386ms
Fri Dec 14 01:28:00 [conn13613091] query devcmd.$cmd ntoreturn:1 command:

{ authenticate: 1, user: "mportal", nonce: "41106940b1c2ebc1", key: "0eb6c6f29610ef0bb729c23f4034bf43" }

reslen:53 6203ms
Fri Dec 14 01:28:00 [conn13613092] query devcmd.$cmd ntoreturn:1 command:

{ authenticate: 1, user: "mportal", nonce: "c7acf1353aaa024", key: "9ec8baca40439ed2a16aa35c5e3fb8ff" }

reslen:53 6123ms
Fri Dec 14 01:28:00 [conn13544080] query mstore.$cmd ntoreturn:1 command:

{ authenticate: 1, user: "tmpn", nonce: "3a16d4a086559bfc", key: "8c7d2e6c6c5e7e0b23f3c9b0772c8c78" }

reslen:53 5186ms
Fri Dec 14 01:28:00 [conn13583888] query mstore.$cmd ntoreturn:1 command:

{ authenticate: 1, user: "tmpn", nonce: "f92a4be746b2749c", key: "c0c25347be7a272ea34d97d2dd4f112a" }

reslen:53 9035ms
Fri Dec 14 01:28:00 [conn13606051] query mstore.$cmd ntoreturn:1 command:

{ authenticate: 1, user: "tmpn", nonce: "4135f98c6f397df4", key: "85bf798b4986fb10b3424e5d50d6c581" }

reslen:53 7500ms
Fri Dec 14 01:28:00 [conn13613093] query devcmd.$cmd ntoreturn:1 command:

{ authenticate: 1, user: "mportal", nonce: "814c80c117a046e1", key: "6905af681aceb9d49c0cf6aab1d8a70b" }

reslen:53 5571ms



 Comments   
Comment by dongde wu [ 10/Jan/13 ]

Stephen ,

Will consider to upgrading to latest release .
thanks.

Comment by Stephen Lee [ 09/Jan/13 ]

dongde, have you considered upgrading to v2.0.8 or v2.2.2 per my earlier comment? A lot has changed since v1.8, so it might be worth trying before we continue debugging this older release.

Comment by dongde wu [ 09/Jan/13 ]

Stephen ,

Thanks for reply.

I tried to login with mongo shell , the problem also happen , i suppose it may not related to PHP driver ?

Here is some log for reference after enable log level 1 :
========================================================

Wed Jan  9 00:29:25 [conn2963373] run command admin.$cmd { serverStatus: 1 }
Wed Jan  9 00:29:25 [conn2963373] query admin.$cmd ntoreturn:1 command: { serverStatus: 1 } reslen:1522 0ms
Wed Jan  9 00:29:25 [conn2954466] run command admin.$cmd { ismaster: 1 }
Wed Jan  9 00:29:25 [conn2954466] query admin.$cmd ntoreturn:1 command: { ismaster: 1 } reslen:233 0ms
Wed Jan  9 00:29:25 [conn2963725] run command devcmd.$cmd { ismaster: 1 }
Wed Jan  9 00:29:25 [conn2963725] query devcmd.$cmd ntoreturn:1 command: { ismaster: 1 } reslen:233 0ms
Wed Jan  9 00:29:25 [conn2963725] run command devcmd.$cmd { getnonce: 1 }
Wed Jan  9 00:29:25 [conn2963725] query devcmd.$cmd ntoreturn:1 command: { getnonce: 1 } reslen:81 0ms
Wed Jan  9 00:29:25 [conn2963725] run command devcmd.$cmd { authenticate: 1, user: "mportal", nonce: "1a06ed871f93c025", key: "c5d114d0acaacb10eaa2dedbc569134a" }
Wed Jan  9 00:29:25 [conn2959888]  authenticate: { authenticate: 1, user: "tmpn", nonce: "dee7291f356818d2", key: "e1a12e6c5f92adec5c0bdff71ebbecdc" }
Wed Jan  9 00:29:25 [conn2959888] query mstore.$cmd ntoreturn:1 command: { authenticate: 1, user: "tmpn", nonce: "dee7291f356818d2", key: "e1a12e6c5f92adec5c0bdff71ebbecdc" } reslen:53 2628ms
Wed Jan  9 00:29:25 [slaveTracking] update  0ms
Wed Jan  9 00:29:25 [conn2937054] query mstore.push ntoreturn:1 idhack  reslen:882 0ms
Wed Jan  9 00:29:25 [conn2953826] query mstore.push ntoreturn:1 idhack  reslen:853 0ms
Wed Jan  9 00:29:25 [conn2963723]  authenticate: { authenticate: 1, user: "mportal", nonce: "af35ba2016fe99a5", key: "255efa3e39d9af20103b5586eb8453e3" }
Wed Jan  9 00:29:25 [conn2963723] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "af35ba2016fe99a5", key: "255efa3e39d9af20103b5586eb8453e3" } reslen:53 1885ms
Wed Jan  9 00:29:25 [conn2963724]  authenticate: { authenticate: 1, user: "mportal", nonce: "5dc07fde4de90534", key: "fa53970fe6cee07ec724dc9c2fca6d41" }
Wed Jan  9 00:29:25 [conn2963724] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "5dc07fde4de90534", key: "fa53970fe6cee07ec724dc9c2fca6d41" } reslen:53 372ms
Wed Jan  9 00:29:25 [conn2904320] query mstore.push ntoreturn:1 idhack  reslen:882 0ms
Wed Jan  9 00:29:25 [conn2963721]  authenticate: { authenticate: 1, user: "mportal", nonce: "7059d975a4c43ff2", key: "391bf0bdc7a33026d019b411da1040b1" }
Wed Jan  9 00:29:25 [conn2963721] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "7059d975a4c43ff2", key: "391bf0bdc7a33026d019b411da1040b1" } reslen:53 2073ms
Wed Jan  9 00:29:25 [conn2963723] run command devcmd.$cmd { create: "DeviceStatus" }
Wed Jan  9 00:29:25 [conn2963722]  authenticate: { authenticate: 1, user: "mportal", nonce: "3aa02144330a1cac", key: "9e4890b9c8827e85af3528c75116c581" }
ed Jan  9 00:29:25 [conn2963722] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "3aa02144330a1cac", key: "9e4890b9c8827e85af3528c75116c581" } reslen:53 1886ms
Wed Jan  9 00:29:25 [conn2959888] query mstore.push ntoreturn:1 reslen:36 nreturned:0 0ms
Wed Jan  9 00:29:25 [conn2963724] run command devcmd.$cmd { create: "DeviceStatus" }
Wed Jan  9 00:29:25 [conn2963724] query devcmd.$cmd ntoreturn:1 command: { create: "DeviceStatus" } reslen:91 0ms
Wed Jan  9 00:29:25 [conn2963723] query devcmd.$cmd ntoreturn:1 command: { create: "DeviceStatus" } reslen:91 0ms
Wed Jan  9 00:29:25 [conn2963722] run command devcmd.$cmd { create: "DeviceStatus" }
Wed Jan  9 00:29:25 [conn2937054] update mstore.push  query: { _id: ObjectId('50ecb9e1c7de84678e5734b9') } nscanned:1
2 key updates  0ms
Wed Jan  9 00:29:25 [conn2937054] run command mstore.$cmd { getlasterror: 1 }
Wed Jan  9 00:29:25 [conn2937054] query mstore.$cmd ntoreturn:1 command: { getlasterror: 1 } reslen:117 0ms
Wed Jan  9 00:29:25 [conn2963721] run command devcmd.$cmd { create: "DeviceStatus" }
Wed Jan  9 00:29:25 [conn2904320] update mstore.push  query: { _id: ObjectId('50ecb9e1c7de84678e5734bb') } nscanned:1
2 key updates  0ms
Wed Jan  9 00:29:25 [conn2904320] run command mstore.$cmd { getlasterror: 1 }
Wed Jan  9 00:29:25 [conn2904320] query mstore.$cmd ntoreturn:1 command: { getlasterror: 1 } reslen:117 0ms
Wed Jan  9 00:29:25 [conn2959888] update mstore.push  query: { UniqueID: "7a0ecaf280870198658ec004dcb7b61b", PID: "MS28", Command: "CUSTDATA", FinishAt: -1 } nscanned:0 upsert  0ms
Wed Jan  9 00:29:25 [conn2963722] query devcmd.$cmd ntoreturn:1 command: { create: "DeviceStatus" } reslen:91 0ms
Wed Jan  9 00:29:25 [conn2959888] run command mstore.$cmd { getlasterror: 1 }
Wed Jan  9 00:29:25 [conn2959888] query mstore.$cmd ntoreturn:1 command: { getlasterror: 1 } reslen:139 0ms
Wed Jan  9 00:29:25 [conn2963721] query devcmd.$cmd ntoreturn:1 command: { create: "DeviceStatus" } reslen:91 0ms
Wed Jan  9 00:29:25 [conn2963725]  authenticate: { authenticate: 1, user: "mportal", nonce: "1a06ed871f93c025", key: "c5d114d0acaacb10eaa2dedbc569134a" }
Wed Jan  9 00:29:25 [conn2963725] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "1a06ed871f93c025", key: "c5d114d0acaacb10eaa2dedbc569134a" } reslen:53 38ms
Wed Jan  9 00:29:25 [conn2953826] update mstore.push  query: { _id: ObjectId('50ecb9e1c7de84678e5734b8') } nscanned:1
2 key updates  0ms
Wed Jan  9 00:29:25 [conn2953826] run command mstore.$cmd { getlasterror: 1 }
Wed Jan  9 00:29:25 [conn2953826] query mstore.$cmd ntoreturn:1 command: { getlasterror: 1 } reslen:117 0ms
Wed Jan  9 00:29:25 [conn2963723] update devcmd.DeviceStatus  query: { UniqueID: "ebdb76f37be983c81412e899d8ff30d9", PID: "MS20" } 0ms
Wed Jan  9 00:29:25 [conn2963723] run command devcmd.$cmd { getlasterror: 1 }
Wed Jan  9 00:29:25 [conn2963723] query devcmd.$cmd ntoreturn:1 command: { getlasterror: 1 } reslen:117 0ms
Wed Jan  9 00:29:26 [conn2963373] run command admin.$cmd { serverStatus: 1 }
Wed Jan  9 00:29:26 [conn2963373] query admin.$cmd ntoreturn:1 command: { serverStatus: 1 } reslen:1522 0ms
Wed Jan  9 00:29:26 [slaveTracking] update  0ms
Wed Jan  9 00:29:26 [conn2904343] run command admin.$cmd { ismaster: 1 }
Wed Jan  9 00:29:26 [conn2904343] query admin.$cmd ntoreturn:1 command: { ismaster: 1 } reslen:233 0ms
Wed Jan  9 00:29:26 [conn2904307] run command admin.$cmd { ismaster: 1 }
Wed Jan  9 00:29:26 [conn2904307] query admin.$cmd ntoreturn:1 command: { ismaster: 1 } reslen:233 0ms
Wed Jan  9 00:29:26 [conn2904307] run command mstore.$cmd { getnonce: 1 }
Wed Jan  9 00:29:26 [conn2904307] query mstore.$cmd ntoreturn:1 command: { getnonce: 1 } reslen:81 0ms
Wed Jan  9 00:29:26 [conn2904307] run command mstore.$cmd { authenticate: 1, user: "tmpn", nonce: "bdb295a584232902", key: "cfeb394f8062ac69172bc3aaa74b4dad" }
Wed Jan  9 00:29:26 [conn2904307]  authenticate: { authenticate: 1, user: "tmpn", nonce: "bdb295a584232902", key: "cfeb394f8062ac69172bc3aaa74b4dad" }
Wed Jan  9 00:29:26 [conn2904307] query mstore.$cmd ntoreturn:1 command: { authenticate: 1, user: "tmpn", nonce: "bdb295a584232902", key: "cfeb394f8062ac69172bc3aaa74b4dad" } reslen:53 0ms
Wed Jan  9 00:29:26 [conn2904307] query mstore.reg ntoreturn:1 reslen:36 nreturned:0 0ms

=========================================================================================================

Thanks.

Comment by Stephen Lee [ 07/Jan/13 ]

dongde,

Thanks for the db.serverStatus() and mongostat output. At first glance, lock contention doesn't seem like the issue slowing down your authentication requests.

Could you provide more logging, perhaps with increased verbosity?

db.adminCommand({ setParameter: 1, logLevel: 1 })

Given that you're using v1.2.6 of the PHP driver, could you repeat your testing using the latest v1.2 release, v1.2.12?

If that experiment still results in slow authentication and since v1.8.2 is also somewhat old, is it possible for you to try reproducing using the latest v2.0 release, v2.0.8, using a backup to not disturb your current setup? v2.0 should be a drop-in replacement for v1.8 but you should be aware of the release notes.

-Stephen

Comment by dongde wu [ 07/Jan/13 ]

thanks for response .

Here is db.serverStatus() output information:

MyrepSet:PRIMARY> db.serverStatus()
{
        "host" : "TMMS-DB01.SJC1:28008",
        "version" : "1.8.2",
        "process" : "mongod",
        "uptime" : 1707156,
        "uptimeEstimate" : 1696786,
        "localTime" : ISODate("2013-01-07T01:49:37.609Z"),
        "globalLock" : {
                "totalTime" : 1707156485422,
                "lockTime" : 3601963676,
                "ratio" : 0.002109920037652327,
                "currentQueue" : {
                        "total" : 0,
                        "readers" : 0,
                        "writers" : 0
                },
                "activeClients" : {
                        "total" : 1,
                        "readers" : 1,
                        "writers" : 0
                }
        },
        "mem" : {
                "bits" : 64,
                "resident" : 6350,
                "virtual" : 55732,
                "supported" : true,
                "mapped" : 26805
        },
        "connections" : {
                "current" : 138,
                "available" : 9462
        },
        "extra_info" : {
                "note" : "fields vary by platform",
                "heap_usage_bytes" : 123328368,
                "page_faults" : 444680
        },
        "indexCounters" : {
                "btree" : {
                        "accesses" : 729811,
                        "hits" : 729776,
                        "misses" : 33,
                        "resets" : 0,
                        "missRatio" : 0.000045217186367429374
                }
        },
        "backgroundFlushing" : {
                "flushes" : 28452,
                "total_ms" : 4858631,
                "average_ms" : 170.76588640517363,
                "last_ms" : 56,
                "last_finished" : ISODate("2013-01-07T01:49:21.941Z")
        },
        "cursors" : {
                "totalOpen" : 1,
                "clientCursors_size" : 1,
                "timedOut" : 2
        },
        "network" : {
                "bytesIn" : 6798853981,
                "bytesOut" : 64252870576,
                "numRequests" : 59751762
        },
        "repl" : {
                "setName" : "MyrepSet",
                "ismaster" : true,
                "secondary" : false,
                "hosts" : [
                        "TMMS-DB01.sjc1:28008",
                        "TMMS-DB02.sjc1:28008"
                ],
                "arbiters" : [
                        "TMMS-ARB01.sjc1:28008"
                ]
        },
        "opcounters" : {
                "insert" : 706266,
                "query" : 11618179,
                "update" : 8151718,
                "delete" : 587102,
                "getmore" : 6691439,
                "command" : 35394601
        },
        "asserts" : {
                "regular" : 0,
                "warning" : 0,
                "msg" : 0,
                "user" : 547,
                "rollovers" : 0
        },
        "writeBacksQueued" : false,
        "dur" : {
                "commits" : 8,
                "journaledMB" : 0.114688,
                "writeToDataFilesMB" : 0,
                "commitsInWriteLock" : 0,
                "earlyCommits" : 0,
                "timeMs" : {
                        "dt" : 3099,
                        "prepLogBuffer" : 0,
                        "writeToJournal" : 11,
                        "writeToDataFiles" : 0,
                        "remapPrivateView" : 0
                }
        },
        "ok" : 1
}
MyrepSet:PRIMARY> 

and here is mongostat information when slow authentcation happen :

insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn      set repl       time ^M
     0      0      1      0       0       4       0  26.2g  54.4g   6.2g      0        0          0       0|0     1|0   317b     3k   139 MyrepSet    M   01:40:04 ^M
     0      5      4      0       3      18       0  26.2g  54.4g   6.2g      0      0.1          0       0|0     1|0     3k     7k   139 MyrepSet    M   01:40:05 ^M
     0      5      3      0       2      12       0  26.2g  54.4g   6.2g      0        0          0       0|0     1|0     1k     6k   139 MyrepSet    M   01:40:06 ^M
     0      2      4      0       3      14       0  26.2g  54.4g   6.2g      0        0          0       0|0     1|0     2k     5k   139 MyrepSet    M   01:40:07 ^M
     0      0      0      0       0      22       0  26.2g  54.4g   6.2g      0        0          0       1|6     1|5     1k     4k   141 MyrepSet    M   01:40:08 ^M
     1     23      7      0       3      39       0  26.2g  54.4g   6.2g      0      0.3          0       0|0     1|0    11k    22k   139 MyrepSet    M   01:40:09 ^M
     0      2      4      0       2      19       0  26.2g  54.4g   6.2g      0        0          0       0|0     1|0     2k     6k   139 MyrepSet    M   01:40:10 ^M
     0      5      5      0       1      20       0  26.2g  54.4g   6.2g      0      0.1          0       0|0     1|0     4k     8k   139 MyrepSet    M   01:40:11 ^M
     0      4      1      0       1      15       0  26.2g  54.4g   6.2g      0        0          0       1|3     1|2     2k     6k   140 MyrepSet    M   01:40:12 ^M
     0      7      6      0       3      22       0  26.2g  54.4g   6.2g      0      0.1          0       2|1     1|1     4k    10k   140 MyrepSet    M   01:40:13 ^M
insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn      set repl       time ^M
     0      1      4      0       2      19       0  26.2g  54.4g   6.2g      0        0          0       1|2     1|2     2k     5k   139 MyrepSet    M   01:40:14 ^M
     0     11      3      0       1       8       0  26.2g  54.4g   6.2g      0        0          0       0|0     1|0     4k    10k   139 MyrepSet    M   01:40:15 ^M
     0      5      4      0       2      14       0  26.2g  54.4g   6.2g      0      0.1          0       0|0     1|0     3k     7k   139 MyrepSet    M   01:40:16 ^M
     0      1      0      0       0      14       0  26.2g  54.4g   6.2g      0        0          0       2|4     2|3   724b     3k   142 MyrepSet    M   01:40:17 ^M
     0      3      6      0       3      14       0  26.2g  54.4g   6.2g      0      0.1          0       0|0     1|0     3k     7k   139 MyrepSet    M   01:40:18 ^M
     0      4      2      0       1      11       0  26.2g  54.4g   6.2g      0        0          0       1|1     1|1     2k     5k   139 MyrepSet    M   01:40:19 ^M
     0      0      0      0       0      10       0  26.2g  54.4g   6.2g      0        0          0       1|4     1|3   547b     2k   139 MyrepSet    M   01:40:20 ^M
     0      7      5      0       3      16       0  26.2g  54.4g   6.2g      0      0.1          0       0|0     1|0     4k     8k   139 MyrepSet    M   01:40:21 ^M
     0      9      2      0       1      15       0  26.2g  54.4g   6.2g      0        0          0       2|1     2|1     2k     8k   140 MyrepSet    M   01:40:22 ^M
     0      4      2      0       1       8       0  26.2g  54.4g   6.2g      0      0.1          0       0|0     1|0     1k     5k   139 MyrepSet    M   01:40:23 ^M
insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn      set repl       time ^M
     0      1      1      0       0       6       0  26.2g  54.4g   6.2g      0        0          0       1|3     1|2   434b     3k   139 MyrepSet    M   01:40:24 ^M
     0      1      2      0       2      21       0  26.2g  54.4g   6.2g      0        0          0       1|3     1|3     1k     5k   141 MyrepSet    M   01:40:25 ^M
     0      4      7      0       1      25       0  26.2g  54.4g   6.2g      0      0.1          0       0|0     1|0     6k     9k   139 MyrepSet    M   01:40:26 ^M
     0      0      0      0       0      10       0  26.2g  54.4g   6.2g      0        0          0       1|3     1|2   546b     2k   139 MyrepSet    M   01:40:27 ^M
insert  query update delete getmore command flushes mapped  vsize    res faults locked % idx miss %     qr|qw   ar|aw  netIn netOut  conn      set repl       time ^M
     0      1      2      0       0      11       0  26.2g  54.4g   6.2g      0        0          0       0|2     1|1   978b     3k   140 MyrepSet    M   01:40:34 ^M
     0      5      3      0       2       7       0  26.2g  54.4g   6.2g      0      0.1          0       1|1     1|0     3k     6k   139 MyrepSet    M   01:40:35 ^M
     0      1      0      0       0       6       0  26.2g  54.4g   6.2g      0        0          0       2|2     2|1   372b     2k   139 MyrepSet    M   01:40:36 ^M
     0     18      6      0       3      23       0  26.2g  54.4g   6.2g      0      0.2          0       3|1     3|1     7k    17k   140 MyrepSet    M   01:40:37 ^M
     0      6      6      0       1      11       1  26.2g  54.4g   6.2g      0      0.1          0       2|1     2|1     3k     9k   139 MyrepSet    M   01:40:38 ^M
     0      0      2      0       0      22       0  26.2g  54.4g   6.2g      0      0.1          0       0|0     1|1     2k     5k   141 MyrepSet    M   01:40:39 ^M
     0      6      4      0       2      18       0  26.2g  54.4g   6.2g      0        0          0       2|5     2|4     3k     8k   140 MyrepSet    M   01:40:40 ^M
     0     11      7      0       2      24       0  26.2g  54.4g   6.2g      0      0.2          0       0|0     1|0     7k    14k   139 MyrepSet    M   01:40:41 ^M
     0      5      5      0       2      19       0  26.2g  54.4g   6.2g      0      0.1          0       1|1     1|1     4k     8k   139 MyrepSet    M   01:40:42 ^M
     1      5      2      0       2      13       0  26.2g  54.4g   6.2g      0      0.1          0       0|0     1|0     2k     6k   139 MyrepSet    M   01:40:43 ^M

============================================================

Mon Jan  7 01:40:03 [conn2716820] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "d37361d574c443f1", key: "4e7c9c07c50ee08f24b86fc5ef60bef2" } reslen:53 1035ms
Mon Jan  7 01:40:03 [conn2697824] query mstore.$cmd ntoreturn:1 command: { authenticate: 1, user: "tmpn", nonce: "d38c9426841fe0ad", key: "e3e38a0d0b3d1e376a5640a9f47ee998" } reslen:53 968ms
Mon Jan  7 01:40:03 [conn2708590] query mstore.$cmd ntoreturn:1 command: { authenticate: 1, user: "tmpn", nonce: "c83930ab599beaa5", key: "69588eecae88907195695828be071bbe" } reslen:53 838ms
Mon Jan  7 01:40:03 [conn2716819] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "c1ef49843f35fb02", key: "8f76a6f4ff362a22ae699014e49f2478" } reslen:53 1072ms
Mon Jan  7 01:40:08 [conn2716824] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "42349606142dc929", key: "8393b09e4c41b940f9b4d1c7ddecf72d" } reslen:53 1421ms
Mon Jan  7 01:40:08 [conn2711692] query mstore.$cmd ntoreturn:1 command: { authenticate: 1, user: "tmpn", nonce: "9e9706c0ec62af2c", key: "20c1f58021df938d56b8befa7b54dcbb" } reslen:53 1318ms
Mon Jan  7 01:40:08 [conn2711679] query mstore.$cmd ntoreturn:1 command: { authenticate: 1, user: "tmpn", nonce: "50f95e7ef99d860b", key: "ea4e9be1cfc26773fce51f96c54afced" } reslen:53 1180ms
Mon Jan  7 01:40:08 [conn2716825] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "2403ba5fd39c5cec", key: "22982d6cd298e8df4be9a548b466794b" } reslen:53 1137ms
Mon Jan  7 01:40:08 [conn2710134] query mstore.$cmd ntoreturn:1 command: { authenticate: 1, user: "tmpn", nonce: "d8e4831d7e336be5", key: "fe6b4c19da078a3afe16a6512e27108f" } reslen:53 137ms
Mon Jan  7 01:40:08 [conn2697257] query mstore.$cmd ntoreturn:1 command: { authenticate: 1, user: "tmpn", nonce: "4ab05e0002ad2900", key: "7844cf2d4376d0b03ade1b8db196c834" } reslen:53 602ms
Mon Jan  7 01:40:09 [conn2716830] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "54fdfebc4e60650", key: "2dc088186c18f003b0cffb6291a901b9" } reslen:53 302ms
Mon Jan  7 01:40:11 [conn2716832] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "fbf92763601c65f4", key: "c528a926278ef69d56115e8880574f43" } reslen:53 879ms
Mon Jan  7 01:40:11 [conn2716833] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "9431264bb5499bb2", key: "2e9619b110fce65d10169d24c68d1dcb" } reslen:53 844ms
Mon Jan  7 01:40:11 [conn2668327] query mstore.$cmd ntoreturn:1 command: { authenticate: 1, user: "tmpn", nonce: "68b802ff80e4a100", key: "1bc731ac173200509fc26de1f597eec8" } reslen:53 598ms
Mon Jan  7 01:40:12 [conn2697420] query mstore.$cmd ntoreturn:1 command: { authenticate: 1, user: "tmpn", nonce: "376ff116fb1bf4b0", key: "6389c7bf37efdbd1ec90a8343234f889" } reslen:53 560ms
Mon Jan  7 01:40:12 [conn2716834] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "5a4082600cc7e601", key: "e30e230f3ed1297902b201622be6b707" } reslen:53 287ms
Mon Jan  7 01:40:13 [conn2716837] query devcmd.$cmd ntoreturn:1 command: { authenticate: 1, user: "mportal", nonce: "275394eadd65702c", key: "68418c4849bb458c0de077e2f9e17e73" } reslen:53 729ms
Mon Jan  7 01:40:15 [conn2709429] query mstore.$cmd ntoreturn:1 command: { authenticate: 1, user: "tmpn", nonce: "9ee7c0b54b20772e", key: "5920a4137f17a13cfee7bc7358c03205" } reslen:53 857ms
Mon Jan  7 01:40:15 [conn2704912] query mstore.$cmd ntoreturn:1 command: { authenticate: 1, user: "tmpn", nonce: "61dbe116a0d1af0f", key: "c19becd778bbbe0f2d37ae4548077e86" } reslen:53 694ms

===========================================================================

Because of ACL control , i cannot setup host in MMS . i will provide all information for investigation .
thanks.

Dongde.

     0     13      7      0       2      22       0  26.2g  54.4g   6.2g      0      0.1          0       0|0     1|0     7k    15k   139 MyrepSet    M   01:40:28 ^M
     0      1      1      0       0      10       0  26.2g  54.4g   6.2g      0        0          0       1|4     1|3   608b     3k   139 MyrepSet    M   01:40:29 ^M
     0      2      0      0       0       2       0  26.2g  54.4g   6.2g      0        0          0       4|4     3|3   197b     1k   139 MyrepSet    M   01:40:30 ^M
     0      4      5      0       1      13       0  26.2g  54.4g   6.2g      0      0.1          0       0|0     1|0     3k     8k   139 MyrepSet    M   01:40:31 ^M
     0      1      0      0       0      10       0  26.2g  54.4g   6.2g      0        0          0       2|3     2|2   547b     2k   139 MyrepSet    M   01:40:32 ^M
     0      8      4      0       2       9       0  26.2g  54.4g   6.2g      0      0.2          0       1|1 

Comment by Stephen Lee [ 04/Jan/13 ]

dongde,

The most common cause for a slow read (which is essentially what an authentication request is), would probably be lock contention on the specific database. For example, if that database was seeing a large volume of write traffic at the time, then reads would be potentially queued up behind writes (which are greedy when it comes to locking). Hence the reads (in this case authentication requests) would have to wait for the writes to finish (or for one of the writes to yield) to complete.

Is the host experiencing these slow authentication calls available in MMS? If not, could you perhaps run db.serverStatus() which should output the lock time for each database? It'd be preferable to setup these hosts in MMS, so we can see lock percentages over time and correlate the database locking with your authentication requests.

-Stephen

Comment by dongde wu [ 18/Dec/12 ]

Dear Sir ,

The slow authentication problem happen again after switched to second node for 2 days .
here is my memory utilization information :
OS total RAM size : 72 GB
MyrepSet:PRIMARY> db.serverStatus().mem
{
"bits" : 64,
"resident" : 17207,
"virtual" : 51924,
"supported" : true,
"mapped" : 24758
}
MyrepSet:PRIMARY> db.serverStatus().extra_info
{
"note" : "fields vary by platform",
"heap_usage_bytes" : 28682784,
"page_faults" : 100464
}

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