[SERVER-6985] create failed in createPrivateMap, again Created: 10/Sep/12  Updated: 08/Mar/13  Resolved: 26/Nov/12

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

Type: Bug Priority: Major - P3
Reporter: Johan Kanflo Assignee: Eric Milkie
Resolution: Incomplete Votes: 0
Labels: insert
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Server: Linux 2.6.37.6-0.20-default #1 SMP 2011-12-19 23:39:38 +0100 x86_64 x86_64 x86_64 GNU/Linux
MongoDB: build info: Linux ip-10-2-29-40 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_49


Attachments: Text File mongod.log    
Operating System: Linux
Participants:

 Description   

Mon Sep 10 09:10:21 [conn6338] insert kpsommar3.microlog keyUpdates:0 exception: file /var/lib/mongodb/kpsommar3.1 open/create failed in createPrivateMap (look in log for more information) code:13636 locks(micros) w:9235 9ms
Mon Sep 10 09:10:21 [conn6313] ERROR: mmap private failed with out of memory. (64 bit build)
Mon Sep 10 09:10:21 [conn6313] Assertion: 13636:file /var/lib/mongodb/kpsommar3.1 open/create failed in createPrivateMap (look in log for more information)
0

I ran into this error while running 2.0.4 and upgraded to 2.2.0 and the problem went away. After two/three days after upgrading the problem came back but disappeared after a mongod restart. Could this be related to a memory leak?

I'll try to fix a simple test case but essentially I have five monitoring scripts sending log data to a PHP script via a REST interface.

Some more system info:

> db.stats();
{
"db" : "kpsommar3",
"collections" : 6,
"objects" : 72223,
"avgObjSize" : 211.56794926823866,
"dataSize" : 15280072,
"storageSize" : 18935808,
"numExtents" : 12,
"indexes" : 7,
"indexSize" : 20889680,
"fileSize" : 469762048,
"nsSizeMB" : 16,
"ok" : 1
}
>

% ulimit -v -H
unlimited

I'd love to help debugging this one to get rid of it once and for all.

Johan



 Comments   
Comment by Eric Milkie [ 26/Nov/12 ]

Resolving as Incomplete; we can reopen later.

Comment by Eric Milkie [ 05/Nov/12 ]

Hi Johan,
Just checking in, did you try a test program with mmap?

Comment by Bráulio Bhavamitra [ 30/Sep/12 ]

It seems I've reached the 2gb limit

➜ mongodb pwd
/var/lib/mongodb
➜ mongodb du -h
769M ./journal
2,3G .

Comment by Eric Milkie [ 30/Sep/12 ]

Hi Bráulio. It's not clear to me that it's the same problem; can you post the log entry that shows what the error actually was? In Johan's situation, it was "mmap private failed with out of memory. (64 bit build)".

Comment by Bráulio Bhavamitra [ 30/Sep/12 ]

Same problem here. Setting sysctl vm.overcommit_memory=2 and restating the server doesn't help.
Using mongo 2.0.6.

➜ IMD git:(master) ✗ rails c
/home/bhavamitra/.rvm/gems/ree-1.8.7-2012.02@mongo/gems/mongo-1.7.0/lib/mongo/collection.rb:986:in `generate_indexes': Failed to creat
e index {:key=>#<BSON::OrderedHash:0x51f4456

{"cgc"=>1}

>, :ns=>"imd-development.owners", :name=>"cgc_1"} with the following error: 13636: file /var/lib/mongodb/imd-development.6 open/create failed in createPrivateMap (look in log for more information) (Mongo::OperationFailure)

Comment by Johan Kanflo [ 20/Sep/12 ]

I'll give it a try. The kpsommar2 directory was empty, unsure how that ended up there. Removing it didn't solve the problem

Comment by Eric Milkie [ 20/Sep/12 ]

If you could try a sample program that simply mmaps all the database files in your data directory, that could be very illuminating. Note that with journaling turned on, mongod mmaps all the files twice, so I would try that in your test program as well.
What's in the kpsommar2 subdirectory?

Comment by Johan Kanflo [ 20/Sep/12 ]

I have verified that cgroups is not configured on the server.

Comment by Johan Kanflo [ 20/Sep/12 ]

You learn something new every day, I did not know about the concept of cgroups. I would say it is off though. There is no /etc/cgconfig.conf, no /etc/init.d/cg* and /sys/fs/cgroup exists but is empty. I will try a sample program that mmaps the mongodb files to see if the problem is related to my system or to mongod. Will probably have to roll my own mongod too with some extra debug prints.

Comment by Eric Milkie [ 19/Sep/12 ]

It runs out of memory awfully quickly. Are you running with control groups?
(Do you have an /etc/cgconfig.conf file?) That's the only way I can think of that your process's memory is restricted. With vm.overcommit_memory=0, it ought to be able to map all your database files easily.

Comment by Johan Kanflo [ 19/Sep/12 ]

Here's the output, sorry about the delay. I restarted mongod and opened kpsommar, did a db.microlog.find() and then the same operation on kpsommar2, that failed. The database files are quite big, but that should be ok since vm.overcommit_memory = 0 (right?)

-rw-------  1 mongodb mongodb  64M Jul 31 23:50 test.0
-rw-------  1 mongodb mongodb 128M Jul 31 23:50 test.1
-rw-------  1 mongodb mongodb  16M Jul 31 23:50 test.ns
drwxr-xr-x  2 mongodb mongodb 4.0K Sep 19 07:45 journal
-rw-------  1 mongodb mongodb  64M Aug 20 10:02 kpsommar.0
-rw-------  1 mongodb mongodb 128M Aug 20 09:56 kpsommar.1
drwxr-xr-x  2 mongodb mongodb 4.0K Sep  6 12:26 kpsommar2
-rw-------  1 mongodb mongodb 256M Aug 20 10:00 kpsommar.2
-rw-------  1 mongodb mongodb  64M Sep  6 12:27 kpsommar2.0
-rw-------  1 mongodb mongodb 128M Sep  6 12:27 kpsommar2.1
-rw-------  1 mongodb mongodb 256M Sep  6 12:27 kpsommar2.2
-rw-------  1 mongodb mongodb 512M Sep  6 12:27 kpsommar2.3
-rw-------  1 mongodb mongodb  16M Sep  6 12:27 kpsommar2.ns
-rw-------  1 mongodb mongodb 512M Aug  6 09:41 kpsommar.3
-rw-------  1 mongodb mongodb  64M Sep 19 06:56 kpsommar3.0
-rw-------  1 mongodb mongodb 128M Sep 19 07:44 kpsommar3.1
-rw-------  1 mongodb mongodb 256M Sep 19 07:44 kpsommar3.2
-rw-------  1 mongodb mongodb 512M Sep 18 04:21 kpsommar3.3
-rw-------  1 mongodb mongodb  16M Sep 19 07:44 kpsommar3.ns
-rw-------  1 mongodb mongodb  64M Sep 11 10:15 kpsommar4.0
-rw-------  1 mongodb mongodb 128M Sep 11 10:05 kpsommar4.1
-rw-------  1 mongodb mongodb  16M Sep 11 10:15 kpsommar4.ns
-rw-------  1 mongodb mongodb  16M Aug 20 10:02 kpsommar.ns
-rwxr-xr-x  1 mongodb mongodb    6 Sep 19 07:45 mongod.lock

Comment by Johan Kanflo [ 19/Sep/12 ]

Fresh restart to mmap failure, log is attached at the top.

Comment by Eric Milkie [ 14/Sep/12 ]

Interesting, less than a minute for it to fail. Can you attach the entire log from start to end?

Comment by Johan Kanflo [ 14/Sep/12 ]

Running without quiet and with verbose:

Fri Sep 14 17:17:12 [initandlisten] MongoDB starting : pid=21285 port=27017 dbpath=/var/lib/mongodb 64-bit host=REDACTED
Fri Sep 14 17:17:12 [initandlisten] db version v2.2.0, pdfile version 4.5
Fri Sep 14 17:17:12 [initandlisten] git version: f5e83eae9cfbec7fb7a071321928f00d1b0c5207
Fri Sep 14 17:17:12 [initandlisten] build info: Linux ip-10-2-29-40 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_49
Fri Sep 14 17:17:12 [initandlisten] options: { auth: "true", bind_ip: "127.0.0.1", config: "/etc/mongodb.conf", dbpath: "/var/lib/mongodb", fork: "true", logappend: "true", logpath: "/var/log/mongodb/mongodb.log", nohttpinterface: "true", verbose: true }

and then db.microlog.find() fails:

Fri Sep 14 17:17:54 [conn9] opening db:  kpsommar
Fri Sep 14 17:17:54 [conn9] ERROR: mmap private failed with out of memory. (64 bit build)
Fri Sep 14 17:17:54 [conn9] Assertion: 13636:file /var/lib/mongodb/kpsommar.3 open/create failed in createPrivateMap (look in log for more information)
0xade6e1 0x8036eb 0x80386c 0xbe2ec3 0xbe3e60 0x738be3 0x88be35 0x88c44f 0x88c65a 0x88cf41 0xaf335b 0xaf3623 0xaf3d3f 0x6b3be7 0xb5ba7d 0xb5d052 0x56fa52 0x5dbf11 0x7f7de67baa3f 0x7f7de5b9b71d 
 /usr/sbin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0xade6e1]
 /usr/sbin/mongod(_ZN5mongo11msgassertedEiPKc+0x9b) [0x8036eb]
 /usr/sbin/mongod() [0x80386c]
 /usr/sbin/mongod(_ZN5mongo8MongoMMF13finishOpeningEv+0x1e3) [0xbe2ec3]
 /usr/sbin/mongod(_ZN5mongo8MongoMMF4openESsb+0x70) [0xbe3e60]
 /usr/sbin/mongod(_ZN5mongo13MongoDataFile12openExistingEPKc+0x93) [0x738be3]
 /usr/sbin/mongod(_ZN5mongo8Database16openExistingFileEi+0x595) [0x88be35]
 /usr/sbin/mongod(_ZN5mongo8Database12openAllFilesEv+0x1f) [0x88c44f]
 /usr/sbin/mongod(_ZN5mongo8DatabaseC1EPKcRbRKSs+0x1da) [0x88c65a]
 /usr/sbin/mongod(_ZN5mongo14DatabaseHolder11getOrCreateERKSsS2_Rb+0x441) [0x88cf41]
 /usr/sbin/mongod(_ZN5mongo6Client7Context11_finishInitEb+0x6b) [0xaf335b]
 /usr/sbin/mongod(_ZN5mongo6Client7ContextC1ERKSsSsbb+0x93) [0xaf3623]
 /usr/sbin/mongod(_ZN5mongo6Client11ReadContextC1ERKSsSsb+0x24f) [0xaf3d3f]
 /usr/sbin/mongod(_ZN5mongo8runQueryERNS_7MessageERNS_12QueryMessageERNS_5CurOpES1_+0x1567) [0x6b3be7]
 /usr/sbin/mongod() [0xb5ba7d]
 /usr/sbin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x3a2) [0xb5d052]
 /usr/sbin/mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x82) [0x56fa52]
 /usr/sbin/mongod(_ZN5mongo3pms9threadRunEPNS_13MessagingPortE+0x411) [0x5dbf11]
 /lib64/libpthread.so.0(+0x6a3f) [0x7f7de67baa3f]
 /lib64/libc.so.6(clone+0x6d) [0x7f7de5b9b71d]
Fri Sep 14 17:17:54 [conn9] warning database /var/lib/mongodb kpsommar could not be opened
Fri Sep 14 17:17:54 [conn9] DBException 13636: file /var/lib/mongodb/kpsommar.3 open/create failed in createPrivateMap (look in log for more information)
Fri Sep 14 17:17:54 [conn9] assertion 13636 file /var/lib/mongodb/kpsommar.3 open/create failed in createPrivateMap (look in log for more information) ns:kpsommar.microlog query:{}
Fri Sep 14 17:17:54 [conn9] problem detected during query over kpsommar.microlog : { $err: "file /var/lib/mongodb/kpsommar.3 open/create failed in createPrivateMap (look in log for more information)", code: 13636 }
Fri Sep 14 17:17:54 [conn9] query kpsommar.microlog ntoreturn:0 keyUpdates:0 exception: file /var/lib/mongodb/kpsommar.3 open/create failed in createPrivateMap (look in log for more information) code:13636 locks(micros) W:15910 r:2 reslen:152 0ms
Fri Sep 14 17:17:54 [conn9] run command admin.$cmd { replSetGetStatus: 1.0, forShell: 1.0 }
Fri Sep 14 17:17:54 [conn9] command admin.$cmd command: { replSetGetStatus: 1.0, forShell: 1.0 } ntoreturn:1 keyUpdates:0  reslen:76 0ms
Fri Sep 14 17:17:58 [conn9] run command admin.$cmd { replSetGetStatus: 1.0, forShell: 1.0 }
Fri Sep 14 17:17:58 [conn9] command admin.$cmd command: { replSetGetStatus: 1.0, forShell: 1.0 } ntoreturn:1 keyUpdates:0  reslen:76 0ms
Fri Sep 14 17:18:03 [conn9] end connection 127.0.0.1:51108 (8 connections now open)

Comment by Eric Milkie [ 14/Sep/12 ]

I see you're starting mongod with --quiet. It would be helpful if you could run the server with at least -v to see if anything else comes out – if you have the space for the logs. Your limits and free memory look fine to me.

Comment by Johan Kanflo [ 14/Sep/12 ]

Nope, no lowering of mapped file limit.

% free -m
             total       used       free     shared    buffers     cached
Mem:          2007       1813        193          0        113       1007
-/+ buffers/cache:        693       1314
Swap:         1026        144        882

and

% cat /proc/24535/limits
Limit                     Soft Limit           Hard Limit           Units     
Max cpu time              unlimited            unlimited            seconds   
Max file size             unlimited            unlimited            bytes     
Max data size             unlimited            unlimited            bytes     
Max stack size            8388608              unlimited            bytes     
Max core file size        0                    unlimited            bytes     
Max resident set          1789194240           unlimited            bytes     
Max processes             16002                16002                processes 
Max open files            1024                 8192                 files     
Max locked memory         65536                262144               bytes     
Max address space         2545418240           unlimited            bytes     
Max file locks            unlimited            unlimited            locks     
Max pending signals       16002                16002                signals   
Max msgqueue size         819200               819200               bytes     
Max nice priority         0                    0                    
Max realtime priority     0                    0                    
Max realtime timeout      unlimited            unlimited            us  

Once again, I cannot run db.microlog.find() on one of my databases and a mongod restart fixes the problem temporarily. Quite handy for ironing this one out I'd say.

Comment by Eric Milkie [ 13/Sep/12 ]

Yes, 0 for overcommit_memory should be working for you. At this point I'm somewhat at a loss as to why mmap() would return ENOMEM for you in 64-bit mode. You don't seem to have very many files mapped. Did you happen to lower your limit for number of mapped files? It defaults to 1024.
Also, what does "free -m" say when you experience the issue? Can you also show what /proc/####/limits says?

Comment by Johan Kanflo [ 11/Sep/12 ]

Currently the problem will reproduce itself after a few hours. I have a previous version of my database that can only be read after a mongod restart:

Mongod has been running for a few hours, db.microlog.find() fails with

Tue Sep 11 08:54:59 [conn1038] warning database /var/lib/mongodb kpsommar could not be opened
Tue Sep 11 08:54:59 [conn1038] DBException 13636: file /var/lib/mongodb/kpsommar.3 open/create failed in createPrivateMap (look in log for more information)
Tue Sep 11 08:54:59 [conn1038] assertion 13636 file /var/lib/mongodb/kpsommar.3 open/create failed in createPrivateMap (look in log for more information) ns:kpsommar.system.namespaces query:{}
Tue Sep 11 08:54:59 [conn1038] problem detected during query over kpsommar.system.namespaces : { $err: "file /var/lib/mongodb/kpsommar.3 open/create failed in createPrivateMap (look in log for more information)", code: 13636 }
Tue Sep 11 08:55:04 [conn1038] ERROR: mmap private failed with out of memory. (64 bit build)
Tue Sep 11 08:55:04 [conn1038] Assertion: 13636:file /var/lib/mongodb/kpsommar.3 open/create failed in createPrivateMap (look in log for more information)

Some process stats:

% ps axu | grep mongo
mongodb   7522  0.1  2.1 616104 43416 ?        Sl   Sep10   2:00 /usr/sbin/mongod --quiet -f /etc/mongodb.conf
% cat /proc/7522/status
Name:   mongod
State:  S (sleeping)
Tgid:   7522
Pid:    7522
PPid:   1
TracerPid:      0
Uid:    304     304     304     304
Gid:    305     305     305     305
FDSize: 64
Groups: 305
VmPeak:  2090664 kB
VmSize:   616104 kB
VmLck:         0 kB
VmHWM:     94828 kB
VmRSS:     43416 kB
VmData:   164348 kB
VmStk:       136 kB
VmExe:     10060 kB
VmLib:      3036 kB
VmPTE:       428 kB
VmSwap:        0 kB
Threads:        19
SigQ:   0/16002
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000004002
SigIgn: 0000000000001000
SigCgt: 0000000180000eed
CapInh: 0000000000000000
CapPrm: 0000000000000000
CapEff: 0000000000000000
CapBnd: ffffffffffffffff
Cpus_allowed:   ff
Cpus_allowed_list:      0-7
Mems_allowed:   00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000001
Mems_allowed_list:      0
voluntary_ctxt_switches:        6304638
nonvoluntary_ctxt_switches:     317

MongoDB restart, db.microlog.find() succeeds

% ps axu | grep mongo
mongodb  23067  0.6  2.2 2122212 45920 ?       Sl   09:10   0:00 /usr/sbin/mongod --quiet -f /etc/mongodb.conf
% cat /proc/23067/status
Name:   mongod
State:  S (sleeping)
Tgid:   23067
Pid:    23067
PPid:   1
TracerPid:      0
Uid:    304     304     304     304
Gid:    305     305     305     305
FDSize: 64
Groups: 305
VmPeak:  2122212 kB
VmSize:  2122212 kB
VmLck:         0 kB
VmHWM:     94824 kB
VmRSS:     45920 kB
VmData:    97592 kB
VmStk:       136 kB
VmExe:     10060 kB
VmLib:      3036 kB
VmPTE:       204 kB
VmSwap:        0 kB
Threads:        9
SigQ:   0/16002
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000004002
SigIgn: 0000000000001000
SigCgt: 0000000180000eed
CapInh: 0000000000000000
CapPrm: 0000000000000000
CapEff: 0000000000000000
CapBnd: ffffffffffffffff
Cpus_allowed:   ff
Cpus_allowed_list:      0-7
Mems_allowed:   00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000001
Mems_allowed_list:      0
voluntary_ctxt_switches:        3330
nonvoluntary_ctxt_switches:     1

The figure that stands out when db.microlog.find() fails is VmSize:616104 kB that has shrunk after the mongod launch. Does that provide any hints?

Comment by Johan Kanflo [ 11/Sep/12 ]

% sysctl vm.overcommit_memory
vm.overcommit_memory = 0

I did some reading up on this setting and as far as I understand 0 is the value that should be used, right?

Comment by Eric Milkie [ 10/Sep/12 ]

What does "sysctl vm.overcommit_memory" say?
e.g.

~: sysctl vm.overcommit_memory
vm.overcommit_memory = 2
~:

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