[SERVER-18602] A query will take very long time in a sudden but it works well in most time. Created: 21/May/15  Updated: 21/May/15  Resolved: 21/May/15

Status: Closed
Project: Core Server
Component/s: Querying, WiredTiger
Affects Version/s: 3.0.3
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: carl dong Assignee: Ramon Fernandez Marina
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-18507 A query will take very long time in a... Closed
Operating System: ALL
Participants:

 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



 Comments   
Comment by Ramon Fernandez Marina [ 21/May/15 ]

carl.dong@windfindtech.com, something was recently changed in our JIRA workflow which no longer moves tickets from "Waiting for user input" to the "Open" state when a user posts a message – apologies for the confusion. Rest assured we review these tickets often to make sure they are taken care of. I'm going to close this ticket as a duplicate of SERVER-18507, which we're still investigating.

Regards,
Ramón.

Comment by carl dong [ 21/May/15 ]

I am confused , I added comments in the original ticket but the status is still waiting on user input , seems something not right on this system , how should I update the task status ?
So I duplicated the ticket to be noticed , thanks for understanding.

Comment by carl dong [ 21/May/15 ]

I restarted the mongod service and queries works well in 2 days , but it happend today again , it only happens on this query , others are working good .
BTW, there are millions operations on RadiusAccount collection, and this issue causes lots of timeout operations, need to be solved.

Comment by carl dong [ 21/May/15 ]

Sure, I have some indexes build on the collection.
"indexSizes" : {
"id" : 48078848,
"username_1_stoptime_1" : 135180288,
"acctsessionid_1" : 397062144,
"starttime_1" : 37175296,
"stoptime_1" : 44113920,
"userlocation_1_stoptime_1" : 69537792
and Count in the collection:
PRIMARY> db.RadiusAccount.count()
4782765

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