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

Details

    • Icon: Bug Bug
    • Resolution: Duplicate
    • Icon: Major - P3 Major - P3
    • None
    • 3.0.3
    • Querying, WiredTiger
    • None
    • ALL

    Description

      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

      Attachments

        1. Test.log
          84.61 MB

        Activity

          People

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

            Dates

              Created:
              Updated:
              Resolved: