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

A query will take very long time in a sudden but it works well in most time.

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 3.0.3
    • Component/s: Querying, WiredTiger
    • None
    • ALL
    • None
    • 3
    • None
    • None
    • None
    • None
    • None
    • None

      There is a very strange issue when new Mongodb 3.0.3 instance running ,
      queries works well in most time , but suddenly it will cost more than 10 seconds.

      Here is the output from the db log, first the short one and then the long one:

      2015-05-18T15:24:42.879+0800 I COMMAND  [conn22550] command Radius.$cmd command: findAndModify { findandmodify: "RadiusAccount", query: { acctsessionid: "90-3C-92-C2-EA-38-9659892E" }, sort: { _id: -1 }, update: { $set: { acctsessionid: "90-3C-92-C2-EA-38-9659892E", username: "18918978008", nasipaddress: "183.192.114.254", nasportid: "0000000125", nasporttype: 19, nasport: 1, sessiontime: 2700, inputoctets: "5456078", outputoctets: "694505", ipaddress: "100.65.154.152", calledstationid: "00-19-70-FE-14-5B:i-Shanghai", callingstationid: "90:3C:92:C2:EA:38", userlocation: "mobile&0206050021000460", operator: 2, userlevel: "1", nasipv6address: "::", framedinterfaceid: "9d27:dc24:ee63:9de5", loginipv6host: "2409:88a4:8000:16:9d27:dc24:ee63:9de5", acctipv6inputoctets: "6004364279808", acctipv6outputoctets: "19546396164096", nasidentifier: "0206050021000460", lut: new Date(1431933882876) } }, new: true, upsert: true } update: { $set: { acctsessionid: "90-3C-92-C2-EA-38-9659892E", username: "18918978008", nasipaddress: "183.192.114.254", nasportid: "0000000125", nasporttype: 19, nasport: 1, sessiontime: 2700, inputoctets: "5456078", outputoctets: "694505", ipaddress: "100.65.154.152", calledstationid: "00-19-70-FE-14-5B:i-Shanghai", callingstationid: "90:3C:92:C2:EA:38", userlocation: "mobile&0206050021000460", operator: 2, userlevel: "1", nasipv6address: "::", framedinterfaceid: "9d27:dc24:ee63:9de5", loginipv6host: "2409:88a4:8000:16:9d27:dc24:ee63:9de5", acctipv6inputoctets: "6004364279808", acctipv6outputoctets: "19546396164096", nasidentifier: "0206050021000460", lut: new Date(1431933882876) } } nscanned:1 nscannedObjects:1 nMatched:1 nModified:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:865 locks:{ Global: { acquireCount: { w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } 1ms
2015-05-17T00:12:46.422+0800 I COMMAND  [conn12974] command Radius.$cmd command: findAndModify { findandmodify: "RadiusAccount", query: { acctsessionid: "090de21e9375571fece70d267c3e79a705e60cca2b751a64" }, sort: { _id: -1 }, update: { $set: { acctsessionid: "090de21e9375571fece70d267c3e79a705e60cca2b751a64", username: "18817339667", nasipaddress: "222.66.249.120", nasportid: "CPD11225", nasporttype: 19, nasport: 1, stoptime: new Date(1431792754077), sessiontime: 114, inputoctets: "57753", outputoctets: "320987", terminatecause: "Admin-Reset", stopdelay: 0, ipaddress: "101.92.170.191", calledstationid: "ishanghai", callingstationid: "D0:DF:9A:46:F2:78", userlocation: "telecom&CPD11225", operator: 1, userlevel: "1", servicetype: "Framed-User", nasidentifier: "2bb2f23ce9c21f721e9087ee9899ff76", lut: new Date(1431792754078) } }, new: true, upsert: true } keyUpdates:0 writeConflicts:0 numYields:35862 reslen:707 locks:{ Global: { acquireCount: { w: 35864 } }, Database: { acquireCount: { w: 35864 } }, Collection: { acquireCount: { w: 35863 } }, oplog: { acquireCount: { w: 1 } } } 12341ms

      Actully , both the same query , it cost only 1ms when I run them manually.

      Here is my config file :

      processManagement :
 fork : true
 pidFilePath :  /home/Radius/Rad.pid
systemLog:
 destination : file
 path : /home/Radius/Log/Rad_Log
 logAppend : true

storage:
 dbPath : /home/Radius/Data_WiredTiger
 engine : wiredTiger
 wiredTiger :
  engineConfig :
   cacheSizeGB : 20
 directoryPerDB : true

net:
 port : 40001
 maxIncomingConnections : 2000

security:
 authorization  : enabled
 keyFile : /home/Radius/Keys/RadKey

replication:
 replSetName : rad

auditLog:
 destination : file
 format : JSON
 path : /home/Radius/Log/RadiusDBAduit.json
 filter : '{ atype : {$nin : ["authenticate"]} }'

      Please give some advise on tracing the issue .

      Thanks .

      Carl Dong

        1. Test.log
          84.61 MB

            Assignee:
            ramon.fernandez@mongodb.com Ramon Fernandez Marina
            Reporter:
            carl.dong@windfindtech.com carl dong
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: