[SERVER-18018] Mongo DB 3.0 Full Text Search Memory Leak due to open cursors Created: 13/Apr/15  Updated: 05/Jun/15  Resolved: 05/Jun/15

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

Type: Bug Priority: Major - P3
Reporter: zhongxi yuan Assignee: Ramon Fernandez Marina
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

PS D:\mongodb\bin> mongo.exe --eval "printjson(db.serverBuildInfo())"
MongoDB shell version: 3.0.2
connecting to: test
{
        "version" : "3.0.2",
        "gitVersion" : "6201872043ecbbc0a4cc169b5482dcf385fc464f",
        "targetMinOS" : "Windows 7/Windows Server 2008 R2",
        "OpenSSLVersion" : "OpenSSL 1.0.1m-fips 19 Mar 2015",
        "sysInfo" : "windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack
1') BOOST_LIB_VERSION=1_49",
        "loaderFlags" : "/nologo /DEBUG /INCREMENTAL:NO /LARGEADDRESSAWARE /OPT:REF",
        "compilerFlags" : "/TP /nologo /EHsc /W3 /wd4355 /wd4800 /wd4267 /wd4244 /wd4290 /wd4068 /wd4351 /we4099 /Z7 /er
rorReport:none /MD /O2 /Oy- /Gw /Gy /Zc:inline",
        "allocator" : "system",
        "versionArray" : [
                3,
                0,
                2,
                0
        ],
        "javascriptEngine" : "V8",
        "bits" : 64,
        "debug" : false,
        "maxBsonObjectSize" : 16777216,
        "ok" : 1
}


Operating System: Windows
Participants:

 Description   

Hi All,
Recently I update my DB from2.6 to 3.0. I find when I execute command
db.DeviceDataCurr.find({$text:{$search:"hostname"}},{_id:1}).limit(10)
via mongo.exe, the Server memory will increase, The server died after I looped run this command.
I tried many times and found that both mmapv1 and wiredtiger have this promblem.
I also tried v2.6, It works fine.

Hope your response.

there are some db log

2015-04-11T20:59:41.271-0400 I QUERY    [conn12] query NGDomain111.DeviceDataCurr query: { $text: { $search: "hostname" } } planSummary: TEXT {} cursorid:30552791919 ntoreturn:10 ntoskip:0 nscanned:58912 nscannedObjects:58912 keyUpdates:0 writeConflicts:0 numYields:461 nreturned:10 reslen:550 locks:{ Global: { acquireCount: { r: 462 } }, MMAPV1Journal: { acquireCount: { r: 462 } }, Database: { acquireCount: { r: 462 } }, Collection: { acquireCount: { R: 462 } } } 1744ms
2015-04-11T20:59:42.061-0400 I STORAGE  [DataFileSync] flushing mmaps took 14790ms  for 14 files
2015-04-11T20:59:42.651-0400 I QUERY    [conn12] query NGDomain111.DeviceDataCurr query: { $text: { $search: "hostname" } } planSummary: TEXT {} cursorid:31386534272 ntoreturn:10 ntoskip:0 nscanned:58912 nscannedObjects:58912 keyUpdates:0 writeConflicts:0 numYields:461 nreturned:10 reslen:550 locks:{ Global: { acquireCount: { r: 462 } }, MMAPV1Journal: { acquireCount: { r: 462 } }, Database: { acquireCount: { r: 462 } }, Collection: { acquireCount: { R: 462 } } } 1375ms
2015-04-11T20:59:44.443-0400 I QUERY    [conn12] query NGDomain111.DeviceDataCurr query: { $text: { $search: "hostname" } } planSummary: TEXT {} cursorid:31826192619 ntoreturn:10 ntoskip:0 nscanned:58912 nscannedObjects:58912 keyUpdates:0 writeConflicts:0 numYields:462 nreturned:10 reslen:550 locks:{ Global: { acquireCount: { r: 463 } }, MMAPV1Journal: { acquireCount: { r: 463 } }, Database: { acquireCount: { r: 463 } }, Collection: { acquireCount: { R: 463 } } } 1786ms
2015-04-11T20:59:45.915-0400 I QUERY    [conn12] query NGDomain111.DeviceDataCurr query: { $text: { $search: "hostname" } } planSummary: TEXT {} cursorid:31081467184 ntoreturn:10 ntoskip:0 nscanned:58912 nscannedObjects:58912 keyUpdates:0 writeConflicts:0 numYields:462 nreturned:10 reslen:550 locks:{ Global: { acquireCount: { r: 463 } }, MMAPV1Journal: { acquireCount: { r: 463 } }, Database: { acquireCount: { r: 463 } }, Collection: { acquireCount: { R: 463 } } } 1468ms
2015-04-11T21:00:21.665-0400 I COMMAND  [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 421ms
2015-04-11T21:00:27.988-0400 I COMMAND  [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 375ms
2015-04-11T21:01:31.943-0400 I COMMAND  [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 528ms
2015-04-11T21:01:32.589-0400 I COMMAND  [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 244ms
2015-04-11T21:02:30.713-0400 I QUERY    [conn12] query NGDomain111.DeviceDataCurr query: { $text: { $search: "hostname" } } planSummary: TEXT {} cursorid:31859778607 ntoreturn:10 ntoskip:0 nscanned:58912 nscannedObjects:58912 keyUpdates:0 writeConflicts:0 numYields:483 nreturned:10 reslen:550 locks:{ Global: { acquireCount: { r: 484 } }, MMAPV1Journal: { acquireCount: { r: 484 } }, Database: { acquireCount: { r: 484 } }, Collection: { acquireCount: { R: 484 } } } 164738ms
2015-04-11T21:02:31.388-0400 I NETWORK  [conn12] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [127.0.0.1:50994] 



 Comments   
Comment by Ramon Fernandez Marina [ 05/Jun/15 ]

Thanks for testing and for the additional information zhongxi.yuan. I'm going to resolve this ticket as "works as designed", meaning that it's expected to have higher memory consumption when one opens many cursors that are never closed, as each open cursor consumes memory.

Regards,
Ramón.

Comment by zhongxi yuan [ 05/Jun/15 ]

Hi, Ramon

I tested it in my computer, the reason is cursorTimeoutMillis,
Before I running the command db.runCommand(

{setParameter:1, cursorTimeoutMillis: 5000}

), The memory increaced very quickly, after running the command , it did not increase,

Thanks

yuanzhongxi@gmail.com

From: Ramon Fernandez (JIRA)
Date: 2015-06-03 17:46
To: yuanzhongxi
Subject: [MongoDB-JIRA] (SERVER-18018) Mongo DB 3.0 Full Text Search Memory Leak

[ https://jira.mongodb.org/browse/SERVER-18018?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=931065#comment-931065 ]

Ramon Fernandez commented on SERVER-18018:
------------------------------------------

zhongxi.yuan, I'm unable to reproduce the behavior you describe in the shell with 3.0.3. I have two shells running the $text query you posted on a loop, but the amount of memory used by the server doesn't change.

If you suspect the memory consumption on your repro case is related to idle cursos, can you please run

use admin
db.runCommand({setParameter:1, cursorTimeoutMillis: 5000})

as described in SERVER-8188 and then try your reproducer again?

Also, how are you measuring memory consumption? What does

db.serverStatus().extra_info.heap_usage_bytes

report?

Thanks,
Ramón.

----------------------
This message was sent from MongoDB's issue tracking system. To respond to this ticket, please login to https://jira.mongodb.org using your JIRA or MMS credentials.

Comment by Ramon Fernandez Marina [ 03/Jun/15 ]

zhongxi.yuan, I'm unable to reproduce the behavior you describe in the shell with 3.0.3. I have two shells running the $text query you posted on a loop, but the amount of memory used by the server doesn't change.

If you suspect the memory consumption on your repro case is related to idle cursos, can you please run

use admin
db.runCommand({setParameter:1, cursorTimeoutMillis: 5000})

as described in SERVER-8188 and then try your reproducer again?

Also, how are you measuring memory consumption? What does

db.serverStatus().extra_info.heap_usage_bytes

report?

Thanks,
Ramón.

Comment by Ramon Fernandez Marina [ 16/Apr/15 ]

Thanks for the additional information zhongxi.yuan. We're looking into this issue now and will let you know what we find.

Comment by zhongxi yuan [ 13/Apr/15 ]

I also test general find command db.DeviceDataCurr.find().limit(10)
It works fine in both 2.6 and 3.0

Comment by zhongxi yuan [ 13/Apr/15 ]

Hi,
It work fine in PyMongo with Single-Thread. I also test it in C# Driver 1.10 with Multi-Thread, It leaked too. (may be the server do not kill cursors ).
By The way, When I do this search the CPU in Server is always 25%, In 2.6 it always 3%. The performance in 2.6 it much better then 3.0.

this is the process running info
Name PID Status User name CPU Memory (private working set) Commit size Command line
mongod.exe 4984 Running SYSTEM 25 125,312 K 252,464 K d:\mongodb\bin\mongod.exe --config d:\mongodb\standalone\config.conf --service

this is the server log
2015-04-13T15:53:11.202-0400 I QUERY [conn444] query NGDomain111.DeviceDataCurr query: { $text:

{ $search: "hostname" }

} planSummary: TEXT {} cursorid:87114654502 ntoreturn:10 ntoskip:0 nscanned:58912 nscannedObjects:58912 keyUpdates:0 writeConflicts:0 numYields:463 nreturned:10 reslen:530 locks:{ Global: { acquireCount:

{ r: 464 }

}, MMAPV1Journal: { acquireCount:

{ r: 464 }

}, Database: { acquireCount:

{ r: 464 }

}, Collection: { acquireCount:

{ R: 464 }

} } 2934ms
2015-04-13T15:53:11.273-0400 I QUERY [conn444] killcursors keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount:

{ r: 1 }

}, MMAPV1Journal: { acquireCount:

{ r: 1 }

}, Database: { acquireCount:

{ r: 1 }

}, Collection: { acquireCount:

{ R: 1 }

} } 59ms

Comment by J Rassi [ 13/Apr/15 ]

Hi,

I'll need some additional information to determine whether or not this issue is a duplicate of SERVER-17792, or some other issue with the mongo shell.

Do you have Python installed on this machine? If so, would you be willing to install the PyMongo driver (visit this link and select the green "Downloads" button) and see if running the following Python script also reproduces this issue? Please replace DATABASE_NAME with a quoted string containing the name of the database that has this issue.

import pymongo
c = pymongo.MongoClient()
while True:
    print(len(list(c[DATABASE_NAME]["DeviceDataCurr"].find({"$text":{"$search":"hostname"}},{"_id":1}).limit(10))))

Thanks.
~ Jason Rassi

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