[SERVER-3660] "VirtualProtect failed" when inserting (Windows) Created: 22/Aug/11  Updated: 15/Aug/12  Resolved: 22/Apr/12

Status: Closed
Project: Core Server
Component/s: Storage
Affects Version/s: 1.8.1
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Nik Mason Assignee: Tad Marshall
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Windows XP


Issue Links:
Duplicate
duplicates SERVER-5663 Private pages accumulate in Windows R... Closed
Operating System: Windows
Participants:

 Description   

Hi,

As a bit of background, we are using Mongo in journalling mode on a single server. The collection is capped and limited to 20Gb on a machine with a 75Gb hard disk. We recently updated our indexes which are now very large, the indexes for a full database take up roughly 27Gb. Every now and then (this has so far happened twice in a week), assertions fail on the indexes. This all seems to happen after the log line:

VirtualProtect failed 10441050000000 4000000 errno:1455 The paging file is too small for this operation to complete.

As I am aware, Windows will use all available hard disk space for a paging file if required. What is the limit that I am hitting?

Below is the log:

Thu Aug 18 17:06:51 [conn153] query ds3000.logevents ntoreturn:5000 reslen:36 nscanned:4591684 ntoskip:1326{ $orderby:

{ GenerationTime: -1, _id: -1 }

, $query: { $or: [ { GenerationTime:

{ $gte: new Date(1313682837364), $lte: new Date(1313683437364) }

, SourceType:

{ $in: [ "VSS" ] }

, Component:

{ $in: [ "ProsodyAdaptor.VmpRXWrapper", "MediaController.MediaControllerCore", "MediaController.RadioEndpoint", "ProsodyAdaptor.SipCall" ] }

}, { GenerationTime:

{ $gte: new Date(1313682837364), $lte: new Date(1313683437364) }

, SourceType:

{ $in: [ "VSS" ] }

} ] } } nreturned:0 28687ms
Thu Aug 18 17:07:29 [conn153] query ds3000.logevents ntoreturn:5000 reslen:175614 nscanned:4593141 { $orderby:

{ GenerationTime: -1, _id: -1 }

, $query: { $or: [ { GenerationTime:

{ $gte: new Date(1313682837364), $lte: new Date(1313683437364) }

, SourceType:

{ $in: [ "VSS" ] }

, Component:

{ $in: [ "ProsodyAdaptor.VmpRXWrapper", "MediaController.MediaControllerCore", "MediaController.RadioEndpoint", "ProsodyAdaptor.SipCall" ] }

}, { GenerationTime:

{ $gte: new Date(1313682837364), $lte: new Date(1313683437364) }

, SourceType:

{ $in: [ "VSS" ] }

} ] } } nreturned:1326 22291ms
Thu Aug 18 17:07:49 [conn134] insert ds3000.logevents 280ms
Thu Aug 18 17:07:49 [dur] lsn set 70507016
Thu Aug 18 17:08:49 [dur] lsn set 70545486
Thu Aug 18 17:09:49 [dur] lsn set 70583956
Thu Aug 18 17:10:49 [dur] lsn set 70622426
Thu Aug 18 17:11:49 [dur] lsn set 70660866
Thu Aug 18 17:12:44 [conn124] VirtualProtect failed 10441050000000 4000000 errno:1455 The paging file is too small for this operation to complete.
Thu Aug 18 17:12:44 [conn124] ds3000.logevents Assertion failure false db\mongommf.cpp 72
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ERROR k(keypos+1).prevChildBucket != lchild
Thu Aug 18 17:12:44 [conn124] thisLoc: 6:6260a800 ds3000.logevents.$HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] keyPos: 53 n:61
Thu Aug 18 17:12:44 [conn124] k(keypos+1).pcb: 6:6260e820 lchild: 6:626047d0
Thu Aug 18 17:12:44 [conn124] recordLoc: 2:55c5b10 rchild: 6:62610830
Thu Aug 18 17:12:44 [conn124] key: { : "10.253.138.200", : new Date(1313683955734), : ObjectId('4e4d39fb82005a04dc082f04') }
Thu Aug 18 17:12:44 [conn124] DUMP btreebucket n:61 parent:1fce48f0
0 { : "10.253.138.200", : new Date(1313683950453), : ObjectId('4e4d39f182005a04dc081193') } left:6252e120 RecLoc:2:511b1ac
1 { : "10.253.138.200", : new Date(1313683950531), : ObjectId('4e4d39f282005a04dc081293') } left:62530130 RecLoc:2:5129ae0
2 { : "10.253.138.200", : new Date(1313683950609), : ObjectId('4e4d39f282005a04dc081347') } left:6253a180 RecLoc:2:514bbd0
3 { : "10.253.138.200", : new Date(1313683950687), : ObjectId('4e4d39f282005a04dc0813da') } left:6253c190 RecLoc:2:5158ba8
4 { : "10.253.138.200", : new Date(1313683950781), : ObjectId('4e4d39f282005a04dc081460') } left:6253e1a0 RecLoc:2:516a000
5 { : "10.253.138.200", : new Date(1313683950859), : ObjectId('4e4d39f282005a04dc0814fc') } left:625441d0 RecLoc:2:5188a14
6 { : "10.253.138.200", : new Date(1313683950937), : ObjectId('4e4d39f382005a04dc081574') } left:625461e0 RecLoc:2:51975e8
7 { : "10.253.138.200", : new Date(1313683951015), : ObjectId('4e4d39f382005a04dc0815d7') } left:6254c210 RecLoc:2:51ae90c
8 { : "10.253.138.200", : new Date(1313683951109), : ObjectId('4e4d39f382005a04dc081625') } left:6254e220 RecLoc:2:51c7604
9 { : "10.253.138.200", : new Date(1313683951171), : ObjectId('4e4d39f382005a04dc08169d') } left:62552240 RecLoc:2:51d62fc
10 { : "10.253.138.200", : new Date(1313683951265), : ObjectId('4e4d39f382005a04dc0816f8') } left:62554250 RecLoc:2:51e2dc8
11 { : "10.253.138.200", : new Date(1313683951343), : ObjectId('4e4d39f382005a04dc081758') } left:62556260 RecLoc:2:51f464c
12 { : "10.253.138.200", : new Date(1313683951406), : ObjectId('4e4d39f382005a04dc0817d6') } left:6255c290 RecLoc:2:520a978
13 { : "10.253.138.200", : new Date(1313683951484), : ObjectId('4e4d39f482005a04dc081826') } left:6255e2a0 RecLoc:2:521fd60
14 { : "10.253.138.200", : new Date(1313683951562), : ObjectId('4e4d39f482005a04dc08189c') } left:625622c0 RecLoc:2:522de8c
15 { : "10.253.138.200", : new Date(1313683951640), : ObjectId('4e4d39f482005a04dc08192b') } left:625682f0 RecLoc:2:5244ffc
16 { : "10.253.138.200", : new Date(1313683951734), : ObjectId('4e4d39ef82005a04dc080bc5') } left:6256a300 RecLoc:2:502228c
17 { : "10.253.138.200", : new Date(1313683951796), : ObjectId('4e4d39f082005a04dc080d8f') } left:62501fc0 RecLoc:2:506ae0c
18 { : "10.253.138.200", : new Date(1313683951859), : ObjectId('4e4d39f082005a04dc080e66') } left:62507ff0 RecLoc:2:5096b9c
19 { : "10.253.138.200", : new Date(1313683951875), : ObjectId('4e4d39f082005a04dc080f15') } left:6250e020 RecLoc:2:509c978
20 { : "10.253.138.200", : new Date(1313683951953), : ObjectId('4e4d39f182005a04dc080fdb') } left:62516060 RecLoc:2:50b9e2c
21 { : "10.253.138.200", : new Date(1313683952000), : ObjectId('4e4d39f182005a04dc0810a0') } left:62518070 RecLoc:2:50f95dc
22 { : "10.253.138.200", : new Date(1313683952015), : ObjectId('4e4d39f182005a04dc081153') } left:625240d0 RecLoc:2:50fefdc
23 { : "10.253.138.200", : new Date(1313683952046), : ObjectId('4e4d39f182005a04dc0811e4') } left:6252a100 RecLoc:2:510ed74
24 { : "10.253.138.200", : new Date(1313683952046), : ObjectId('4e4d39f182005a04dc081250') } left:6252c110 RecLoc:2:5114774
25 { : "10.253.138.200", : new Date(1313683952062), : ObjectId('4e4d39f282005a04dc081336') } left:62536160 RecLoc:2:513c930
26 { : "10.253.138.200", : new Date(1313683952078), : ObjectId('4e4d39f282005a04dc08141d') } left:62538170 RecLoc:2:5171d7c
27 { : "10.253.138.200", : new Date(1313683952093), : ObjectId('4e4d39f582005a04dc081b18') } left:625401b0 RecLoc:2:5294374
28 { : "10.253.138.200", : new Date(1313683952171), : ObjectId('4e4d39f582005a04dc081b5c') } left:62576360 RecLoc:2:52a0d00
29 { : "10.253.138.200", : new Date(1313683952250), : ObjectId('4e4d39f582005a04dc081c01') } left:62578370 RecLoc:2:52bab10
30 { : "10.253.138.200", : new Date(1313683952343), : ObjectId('4e4d39f582005a04dc081c4d') } left:6257c390 RecLoc:2:52c8570
31 { : "10.253.138.200", : new Date(1313683952437), : ObjectId('4e4d39f582005a04dc081ce6') } left:6257e3a0 RecLoc:2:52def9c
32 { : "10.253.138.200", : new Date(1313683952515), : ObjectId('4e4d39f582005a04dc081d86') } left:625843d0 RecLoc:2:52f9714
33 { : "10.253.138.200", : new Date(1313683952593), : ObjectId('4e4d39f582005a04dc081de4') } left:6258a400 RecLoc:2:53058bc
34 { : "10.253.138.200", : new Date(1313683952671), : ObjectId('4e4d39f682005a04dc081e62') } left:6258c410 RecLoc:2:53202f4
35 { : "10.253.138.200", : new Date(1313683952765), : ObjectId('4e4d39f682005a04dc081e9e') } left:62590430 RecLoc:2:532cc54
36 { : "10.253.138.200", : new Date(1313683952890), : ObjectId('4e4d39f682005a04dc081f9a') } left:62592440 RecLoc:2:535a748
37 { : "10.253.138.200", : new Date(1313683953046), : ObjectId('4e4d39f682005a04dc0820a0') } left:6259e4a0 RecLoc:2:537e350
38 { : "10.253.138.200", : new Date(1313683953187), : ObjectId('4e4d39f782005a04dc082140') } left:625a24c0 RecLoc:2:53a0af4
39 { : "10.253.138.200", : new Date(1313683953328), : ObjectId('4e4d39f782005a04dc082261') } left:625a84f0 RecLoc:2:53c5230
40 { : "10.253.138.200", : new Date(1313683953468), : ObjectId('4e4d39f782005a04dc082331') } left:625ae520 RecLoc:2:53e8c28
41 { : "10.253.138.200", : new Date(1313683953609), : ObjectId('4e4d39f882005a04dc08245d') } left:625b2540 RecLoc:2:5416390
42 { : "10.253.138.200", : new Date(1313683953781), : ObjectId('4e4d39f882005a04dc082538') } left:625bc590 RecLoc:2:543762c
43 { : "10.253.138.200", : new Date(1313683954125), : ObjectId('4e4d39f882005a04dc08260e') } left:625c25c0 RecLoc:2:545afbc
44 { : "10.253.138.200", : new Date(1313683954296), : ObjectId('4e4d39f882005a04dc0826e0') } left:625c85f0 RecLoc:2:547fcb0
45 { : "10.253.138.200", : new Date(1313683954468), : ObjectId('4e4d39f982005a04dc0827b8') } left:625cc610 RecLoc:2:54a244c
46 { : "10.253.138.200", : new Date(1313683954640), : ObjectId('4e4d39f982005a04dc08295e') } left:625d6660 RecLoc:2:54d8314
47 { : "10.253.138.200", : new Date(1313683954812), : ObjectId('4e4d39f982005a04dc082a7a') } left:625e06b0 RecLoc:2:550564c
48 { : "10.253.138.200", : new Date(1313683954984), : ObjectId('4e4d39fa82005a04dc082b55') } left:625ee720 RecLoc:2:5529470
49 { : "10.253.138.200", : new Date(1313683955156), : ObjectId('4e4d39fa82005a04dc082c80') } left:625f4750 RecLoc:2:5559010
50 { : "10.253.138.200", : new Date(1313683955328), : ObjectId('4e4d39fa82005a04dc082d51') } left:625fa780 RecLoc:2:5579494
51 { : "10.253.138.200", : new Date(1313683955515), : ObjectId('4e4d39fb82005a04dc082e1f') } left:625fe7a0 RecLoc:2:559d5c0
52 { : "10.253.138.200", : new Date(1313683955703), : ObjectId('4e4d39fb82005a04dc082ef6') } left:626047d0 RecLoc:2:55c2f0c
53 { : "10.253.138.200", : new Date(1313683955734), : ObjectId('4e4d39fb82005a04dc082f04') } left:626047d0 RecLoc:2:55c5b10
54 { : "10.253.138.200", : new Date(1313683955890), : ObjectId('4e4d39f382005a04dc0817b8') } left:6260e820 RecLoc:2:51f6f9c
55 { : "10.253.138.200", : new Date(1313683961000), : ObjectId('4e4d39f982005a04dc08285f') } left:62598470 RecLoc:2:54bf2d4
56 { : "10.253.138.200", : new Date(1313683961015), : ObjectId('4e4d39f982005a04dc082908') } left:625de6a0 RecLoc:2:54c5364
57 { : "10.253.138.200", : new Date(1313683961031), : ObjectId('4e4d39f982005a04dc08298b') } left:625e26c0 RecLoc:2:54e16b0
58 { : "10.253.138.201", : new Date(1313573832000), : ObjectId('4e4b8bc882005a0b08000879') } left:625e46d0 RecLoc:1:fe290
59 { : "10.253.138.201", : new Date(1313573849375), : ObjectId('4e4b8bd982005a0b08000aee') } left:54713900 RecLoc:1:144ae4
60 { : "10.253.138.201", : new Date(1313575061000), : ObjectId('4e4b909482005a0b0800a354') } left:118d6a0 RecLoc:1:131b63c right:118f6b0
Thu Aug 18 17:12:44 [conn124] ds3000.logevents Assertion failure false db\btree.cpp 1228
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Thu Aug 18 17:12:44 [conn124] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
.....This line repeats forever....

Regards
Nik



 Comments   
Comment by Tad Marshall [ 22/Apr/12 ]

Duplicate of SERVER-5663, though you still need a large enough page file to handle the writable portions of the private view while journaling.

Comment by Tad Marshall [ 22/Apr/12 ]

The original VirtualProtect failures in 1.8.1 were because of a too-small page file. Later failures in 2.0.0 were because of SERVER-5663, in which even a larger page file will be used up.

Comment by Nik Mason [ 06/Oct/11 ]

Hi,

We've had another paging file exception, logs are below. The page file was set to 16Gb. The database data was 13Gb and the indexes were 7Gb. The Commit Size of mongod.exe reported by taskmgr was 16Gb. Is there a size I can set the page file to to guarantee it cannot run of of memory? Data + indexes size = page file size?

Regards
Nik

30/09/2011 21:23:58.789 - Fri Sep 30 21:23:58 [conn2] insert ds3000.logevents 639ms
30/09/2011 21:24:00.754 - Fri Sep 30 21:24:00 [conn2] insert ds3000.logevents 1247ms
30/09/2011 21:24:07.540 - Fri Sep 30 21:24:07 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 31ms
30/09/2011 21:24:07.711 - Fri Sep 30 21:24:07 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 155ms
30/09/2011 21:24:33.747 - Fri Sep 30 21:24:33 [conn2] insert ds3000.logevents 32025ms
30/09/2011 21:24:48.613 - Fri Sep 30 21:24:48 [conn2] VirtualProtect failed (mcw) /data/db/ds3000.8 5568b0000000 4000000 errno:1455 The paging file is too small for this operation to complete.
30/09/2011 21:24:48.737 - Fri Sep 30 21:24:48 [conn2] ds3000.logevents Assertion failure false db\mongommf.cpp 72
30/09/2011 21:24:51.452 - Fri Sep 30 21:24:51 [conn2] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_LogLevel_GenerationTimeid _id: ObjectId('4e8625837494fc0100e04a1c')
30/09/2011 21:24:51.608 - Fri Sep 30 21:24:51 [conn2] ERROR k(keypos+1).prevChildBucket != lchild
30/09/2011 21:24:51.639 - Fri Sep 30 21:24:51 [conn2] thisLoc: b:4e10b000 ds3000.logevents.$LogLevel_GenerationTimeid
30/09/2011 21:24:51.639 - Fri Sep 30 21:24:51 [conn2] keyPos: 50 n:88
30/09/2011 21:24:51.639 - Fri Sep 30 21:24:51 [conn2] k(keypos+1).pcb: b:4e10d000 lchild: b:4e101000
30/09/2011 21:24:51.639 - Fri Sep 30 21:24:51 [conn2] recordLoc: 7:13f65b40 rchild: b:4e115000
30/09/2011 21:24:51.639 - Fri Sep 30 21:24:51 [conn2] key: { : 3, : new Date(1317414274916), : ObjectId('4e8625837494fc0100e04b38') }
30/09/2011 21:24:52.169 - Fri Sep 30 21:24:52 [conn2] BUCKET n:88 parent:fffffffe
30/09/2011 21:24:52.169 - 4dfa1000
30/09/2011 21:24:52.169 - 0 { : 3, : new Date(131741422596 Loc:7:132e25c0
30/09/2011 21:24:52.169 - 4dfa9000
30/09/2011 21:24:52.169 - 1 { : 3, : new Date(131741422718 Loc:7:13322400
30/09/2011 21:24:52.169 - 4dfaf000
30/09/2011 21:24:52.169 - 2 { : 3, : new Date(131741422723 Loc:7:13362240
30/09/2011 21:24:52.169 - 4dfb7000
30/09/2011 21:24:52.169 - 3 { : 3, : new Date(131741422729 Loc:7:133a2080
30/09/2011 21:24:52.169 - 4dfbd000
30/09/2011 21:24:52.169 - 4 { : 3, : new Date(131741422733 Loc:7:133e1ec0
30/09/2011 21:24:52.169 - 4dfc5000
30/09/2011 21:24:52.169 - 5 { : 3, : new Date(131741422738 Loc:7:13421d00
30/09/2011 21:24:52.169 - 4dfcb000
30/09/2011 21:24:52.169 - 6 { : 3, : new Date(131741422741 Loc:7:13461b40
30/09/2011 21:24:52.169 - 4dfd3000
30/09/2011 21:24:52.169 - 7 { : 3, : new Date(131741422897 Loc:7:134a1980
30/09/2011 21:24:52.169 - 4dfdb000
30/09/2011 21:24:52.169 - 8 { : 3, : new Date(131741422905 Loc:7:134e17c0
30/09/2011 21:24:52.169 - 4dfe1000
30/09/2011 21:24:52.169 - 9 { : 3, : new Date(131741422911 Loc:7:13521600
30/09/2011 21:24:52.169 - 4dfe9000
30/09/2011 21:24:52.169 - a { : 3, : new Date(131741422917 Loc:7:13561440
30/09/2011 21:24:52.169 - 4dfef000
30/09/2011 21:24:52.247 - b { : 3, : new Date(131741422922 Loc:7:135a1280
30/09/2011 21:24:52.247 - 4dff7000
30/09/2011 21:24:52.247 - c { : 3, : new Date(131741423058 Loc:7:135e10c0
30/09/2011 21:24:52.247 - 4dffd000
30/09/2011 21:24:52.247 - d { : 3, : new Date(131741423064 Loc:7:13620f00
30/09/2011 21:24:52.247 - 4e005000
30/09/2011 21:24:52.325 - e { : 3, : new Date(131741423072 Loc:7:13660d40
30/09/2011 21:24:52.325 - 4e00b000
30/09/2011 21:24:52.481 - f { : 3, : new Date(131741423077 Loc:7:136a0b80
30/09/2011 21:24:52.481 - 4e013000
30/09/2011 21:24:52.481 - 10 { : 3, : new Date(131741423083 Loc:7:136e09c0
30/09/2011 21:24:52.481 - 4e01b000
30/09/2011 21:24:52.481 - 11 { : 3, : new Date(131741423091 Loc:7:13720800
30/09/2011 21:24:52.481 - 4e021000
30/09/2011 21:24:52.481 - 12 { : 3, : new Date(131741423284 Loc:7:13760640
30/09/2011 21:24:52.481 - 4e029000
30/09/2011 21:24:52.481 - 13 { : 3, : new Date(131741423290 Loc:7:137a0480
30/09/2011 21:24:52.481 - 4e02f000
30/09/2011 21:24:52.481 - 14 { : 3, : new Date(131741423295 Loc:7:137e02c0
30/09/2011 21:24:52.481 - 4e037000
30/09/2011 21:24:52.481 - 15 { : 3, : new Date(131741423304 Loc:7:13820100
30/09/2011 21:24:52.481 - 4e03d000
30/09/2011 21:24:52.528 - 16 { : 3, : new Date(131741423311 Loc:7:1385ff40
30/09/2011 21:24:52.528 - 4e045000
30/09/2011 21:24:52.528 - 17 { : 3, : new Date(131741423318 Loc:7:1389fd80
30/09/2011 21:24:52.528 - 4e04b000
30/09/2011 21:24:52.528 - 18 { : 3, : new Date(131741423454 Loc:7:138dfbc0
30/09/2011 21:24:52.528 - 4e053000
30/09/2011 21:24:52.528 - 19 { : 3, : new Date(131741423459 Loc:7:1391fa00
30/09/2011 21:24:52.528 - 4e05b000
30/09/2011 21:24:52.528 - 1a { : 3, : new Date(131741423465 Loc:7:1395f840
30/09/2011 21:24:52.528 - 4e061000
30/09/2011 21:24:52.528 - 1b { : 3, : new Date(131741423471 Loc:7:1399f680
30/09/2011 21:24:52.528 - 4e069000
30/09/2011 21:24:52.528 - 1c { : 3, : new Date(131741423476 Loc:7:139df4c0
30/09/2011 21:24:52.528 - 4e06f000
30/09/2011 21:24:52.528 - 1d { : 3, : new Date(131741423479 Loc:7:13a1f300
30/09/2011 21:24:52.528 - 4e077000
30/09/2011 21:24:52.528 - 1e { : 3, : new Date(131741423736 Loc:7:13a5f140
30/09/2011 21:24:52.528 - 4e07d000
30/09/2011 21:24:52.528 - 1f { : 3, : new Date(131741423741 Loc:7:13a9ef80
30/09/2011 21:24:52.528 - 4e085000
30/09/2011 21:24:52.684 - 20 { : 3, : new Date(131741423749 Loc:7:13adedc0
30/09/2011 21:24:52.684 - 4e08d000
30/09/2011 21:24:52.684 - 21 { : 3, : new Date(131741423755 Loc:7:13b1ec00
30/09/2011 21:24:52.684 - 4e093000
30/09/2011 21:24:52.684 - 22 { : 3, : new Date(131741423760 Loc:7:13b5ea40
30/09/2011 21:24:52.684 - 4e09b000
30/09/2011 21:24:52.684 - 23 { : 3, : new Date(131741423878 Loc:7:13b9e880
30/09/2011 21:24:52.684 - 4e0a1000
30/09/2011 21:24:52.684 - 24 { : 3, : new Date(131741423885 Loc:7:13bde6c0
30/09/2011 21:24:52.684 - 4e0a9000
30/09/2011 21:24:52.684 - 25 { : 3, : new Date(131741423891 Loc:7:13c1e500
30/09/2011 21:24:52.684 - 4e0af000
30/09/2011 21:24:52.684 - 26 { : 3, : new Date(131741423896 Loc:7:13c5e340
30/09/2011 21:24:52.684 - 4e0b7000
30/09/2011 21:24:52.684 - 27 { : 3, : new Date(131741423900 Loc:7:13c9e180
30/09/2011 21:24:52.746 - 4e0bd000
30/09/2011 21:24:52.746 - 28 { : 3, : new Date(131741423905 Loc:7:13cddfc0
30/09/2011 21:24:52.746 - 4e0c5000
30/09/2011 21:24:52.746 - 29 { : 3, : new Date(131741424086 Loc:7:13d1de00
30/09/2011 21:24:52.746 - 4e0cd000
30/09/2011 21:24:52.746 - 2a { : 3, : new Date(131741424092 Loc:7:13d5dc40
30/09/2011 21:24:52.746 - 4e0d3000
30/09/2011 21:24:52.746 - 2b { : 3, : new Date(131741424098 Loc:7:13d9da80
30/09/2011 21:24:52.746 - 4e0dd000
30/09/2011 21:24:52.746 - 2c { : 3, : new Date(131741424105 Loc:7:13ddd8c0
30/09/2011 21:24:52.746 - 4e0e5000
30/09/2011 21:24:52.824 - 2d { : 3, : new Date(131741424111 Loc:7:13e1d700
30/09/2011 21:24:52.824 - 4e0ed000
30/09/2011 21:24:52.824 - 2e { : 3, : new Date(131741424117 Loc:7:13e5d540
30/09/2011 21:24:52.824 - 4e0f3000
30/09/2011 21:24:52.824 - 2f { : 3, : new Date(131741427476 Loc:7:13e9d380
30/09/2011 21:24:52.824 - 4e0fb000
30/09/2011 21:24:52.824 - 30 { : 3, : new Date(131741427480 Loc:7:13edd1c0
30/09/2011 21:24:52.824 - 4e101000
30/09/2011 21:24:52.824 - 31 { : 3, : new Date(131741427487 Loc:7:13f1d000
30/09/2011 21:24:52.902 - 4e101000
30/09/2011 21:24:52.902 - 32 { : 3, : new Date(131741427491 Loc:7:13f65b40
30/09/2011 21:24:52.902 - 4e10d000
30/09/2011 21:24:52.902 - 33 { : 4, : new Date(131738909232 Loc:1:8a427f0
30/09/2011 21:24:52.902 - 4181b000
30/09/2011 21:24:52.902 - 34 { : 5, : new Date(131738052599 Loc:1:64bae8
30/09/2011 21:24:52.902 - 3aa77000
30/09/2011 21:24:52.902 - 35 { : 5, : new Date(131738093627 Loc:1:cf1fe0
30/09/2011 21:24:52.902 - 3ab89000
30/09/2011 21:24:52.902 - 36 { : 5, : new Date(131738136792 Loc:1:1333f34
30/09/2011 21:24:52.902 - 3c11d000
30/09/2011 21:24:52.902 - 37 { : 5, : new Date(131738201338 Loc:1:1db8c04
30/09/2011 21:24:52.902 - 3c1f3000
30/09/2011 21:24:52.902 - 38 { : 5, : new Date(131738238637 Loc:1:2468754
30/09/2011 21:24:52.996 - 3c331000
30/09/2011 21:24:52.996 - 39 { : 5, : new Date(131738294013 Loc:1:2cede0c
30/09/2011 21:24:52.996 - 3c485000
30/09/2011 21:24:52.996 - 3a { : 5, : new Date(131738336768 Loc:1:31a94e0
30/09/2011 21:24:52.996 - 3c5bd000
30/09/2011 21:24:52.996 - 3b { : 5, : new Date(131738378736 Loc:1:38e8440
30/09/2011 21:24:52.996 - 3c6bf000
30/09/2011 21:24:52.996 - 3c { : 5, : new Date(131738422307 Loc:1:3f6cd58
30/09/2011 21:24:52.996 - 3c815000
30/09/2011 21:24:53.183 - 3d { : 5, : new Date(131738435759 Loc:1:45df000
30/09/2011 21:24:53.183 - 3e779000
30/09/2011 21:24:53.183 - 3e { : 5, : new Date(131738513765 Loc:1:4c08ecc
30/09/2011 21:24:53.183 - 3e883000
30/09/2011 21:24:53.183 - 3f { : 5, : new Date(131738570784 Loc:1:5920e30
30/09/2011 21:24:53.183 - 3e9df000
30/09/2011 21:24:53.183 - 40 { : 5, : new Date(131738571983 Loc:1:5f7a03c
30/09/2011 21:24:53.183 - 3eadf000
30/09/2011 21:24:53.183 - 41 { : 5, : new Date(131738574002 Loc:1:65d0184
30/09/2011 21:24:53.183 - 3ebe7000
30/09/2011 21:24:53.183 - 42 { : 5, : new Date(131738706212 Loc:1:6c54a60
30/09/2011 21:24:53.324 - 3ecf7000
30/09/2011 21:24:53.324 - 43 { : 5, : new Date(131738707009 Loc:1:735ba24
30/09/2011 21:24:53.324 - 3eee5000
30/09/2011 21:24:53.324 - 44 { : 5, : new Date(131738711396 Loc:1:785f2d0
30/09/2011 21:24:53.324 - 3f00b000
30/09/2011 21:24:53.324 - 45 { : 5, : new Date(131738828585 Loc:1:7f6c018
30/09/2011 21:24:53.324 - 3f0f3000
30/09/2011 21:24:53.324 - 46 { : 5, : new Date(131738910733 Loc:1:8a43d10
30/09/2011 21:24:53.324 - 4179b000
30/09/2011 21:24:53.324 - 47 { : 5, : new Date(131738944141 Loc:1:90f0298
30/09/2011 21:24:53.324 - 4ec81000
30/09/2011 21:24:53.324 - 48 { : 5, : new Date(131738999645 Loc:1:25ed0d90
30/09/2011 21:24:53.324 - 54fcd000
30/09/2011 21:24:53.324 - 49 { : 5, : new Date(131739063800 Loc:1:4c28a5d0
30/09/2011 21:24:53.324 - 5d97b000
30/09/2011 21:24:53.324 - 4a { : 5, : new Date(131739067779 Loc:1:4cc5ce74
30/09/2011 21:24:53.324 - 65985000
30/09/2011 21:24:53.324 - 4b { : 5, : new Date(131739148927 Loc:1:68cbc63c
30/09/2011 21:24:53.324 - 70bb7000
30/09/2011 21:24:53.324 - 4c { : 5, : new Date(131739205948 Loc:1:763c91e4
30/09/2011 21:24:53.324 - 7c845000
30/09/2011 21:24:53.620 - 4d { : 6, : new Date(131738043818 Loc:1:42d7f0
30/09/2011 21:24:53.620 - 3a983000
30/09/2011 21:24:53.620 - 4e { : 6, : new Date(131738124837 Loc:1:1038794
30/09/2011 21:24:53.620 - 3ab4f000
30/09/2011 21:24:53.620 - 4f { : 6, : new Date(131738201410 Loc:1:1bb42fc
30/09/2011 21:24:53.620 - 3c169000
30/09/2011 21:24:53.620 - 50 { : 6, : new Date(131738277923 Loc:1:27328d0
30/09/2011 21:24:53.620 - 3c347000
30/09/2011 21:24:53.620 - 51 { : 6, : new Date(131738354434 Loc:1:333fc98
30/09/2011 21:24:53.620 - 3c543000
30/09/2011 21:24:53.620 - 52 { : 6, : new Date(131738435450 Loc:1:3f5e298
30/09/2011 21:24:53.620 - 3c729000
30/09/2011 21:24:53.620 - 53 { : 6, : new Date(131738511957 Loc:1:4a931fc
30/09/2011 21:24:53.620 - 3e789000
30/09/2011 21:24:53.620 - 54 { : 6, : new Date(131738588485 Loc:1:554dc4c
30/09/2011 21:24:53.620 - 3e955000
30/09/2011 21:24:53.620 - 55 { : 6, : new Date(131738665001 Loc:1:6023e7c
30/09/2011 21:24:53.620 - 3eb13000
30/09/2011 21:24:53.620 - 56 { : 6, : new Date(131738741515 Loc:1:6aebce8
30/09/2011 21:24:53.620 - 3ecf1000
30/09/2011 21:24:53.620 - 57 { : 6, : new Date(131738822592 Loc:1:7777fac
30/09/2011 21:24:53.620 - 3eedb000
30/09/2011 21:24:53.620 - Fri Sep 30 21:24:52 [conn2] ds3000.logevents Assertion failure false db\btree.cpp 1335
30/09/2011 21:24:53.620 - Fri Sep 30 21:24:52 [conn2] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_LogLevel_GenerationTimeid _id: ObjectId('4e8625837494fc0100e04b80')
30/09/2011 21:24:53.620 - Fri Sep 30 21:24:52 [conn2] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_LogLevel_GenerationTimeid _id: ObjectId('4e8625837494fc0100e04b84')
30/09/2011 21:24:53.620 - Fri Sep 30 21:24:52 [conn2] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_LogLevel_GenerationTimeid _id: ObjectId('4e8625837494fc0100e04b88')
30/09/2011 21:24:53.620 - Fri Sep 30 21:24:52 [conn2] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_LogLevel_GenerationTimeid _id: ObjectId('4e8625837494fc0100e04b8c')
30/09/2011 21:24:53.620 - Fri Sep 30 21:24:52 [conn2] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_LogLevel_GenerationTimeid _id: ObjectId('4e8625837494fc0100e04b90')
30/09/2011 21:24:53.620 - Fri Sep 30 21:24:52 [conn2] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_LogLevel_GenerationTimeid _id: ObjectId('4e8625837494fc0100e04b94')
30/09/2011 21:24:53.620 - Fri Sep 30 21:24:53 [conn2] ds3000.logevents caug

Comment by Dwight Merriman [ 21/Sep/11 ]

i think the automatic setting may make it too small. can you manually make larger and LMK how it goes?

we can improve handling of this on our side too but that is the way to go - in fact may always be necessary but we can probably report at startup so there are no errors later for example.

Comment by Matthew Todd [ 21/Sep/11 ]

Hi,
Here are some further errors that were seen after restarting Mongo and recreating the indexes. I'm not sure what the impact of these assertions is.

37790300/39342713 96%
38288500/39342713 97%
38820100/39342713 98%
Wed Sep 21 14:40:18 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took:
46ms
Wed Sep 21 14:40:19 [PeriodicTask::Runner] task: WriteBackManager::cleaner took:
62ms
39013400/39342713 99%
Wed Sep 21 14:40:38 [conn2] done building bottom layer, going to commit
Wed Sep 21 14:41:19 [PeriodicTask::Runner] task: WriteBackManager::cleaner took:
15ms
Wed Sep 21 14:43:19 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took:
77ms
Wed Sep 21 14:43:22 [PeriodicTask::Runner] task: WriteBackManager::cleaner took:
77ms
Wed Sep 21 15:00:30 [conn2] old journal file will be removed: /data/db/journal/j
._0
Wed Sep 21 15:00:31 [conn2] old journal file will be removed: /data/db/journal/j
._1
Wed Sep 21 15:00:31 [conn2] DR101 latency warning on journal file open 249ms
Wed Sep 21 15:07:16 [conn2] build index done 39342713 records 3483.58 secs
Wed Sep 21 15:07:16 [conn2] insert ds3000.system.indexes 3485281ms
Wed Sep 21 15:07:17 [conn30] insert ds3000.system.indexes 171ms
Wed Sep 21 15:07:17 [conn1] command ds3000.$cmd command: { count: "logevents", q
uery: {}, fields: {} } ntoreturn:1 reslen:48 436ms
Wed Sep 21 15:07:20 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:21 [conn30] end connection 10.253.138.30:54089
Wed Sep 21 15:07:21 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65182005a0674
0000a4')
Wed Sep 21 15:07:22 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:22 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65182005a0674
0000a5')
Wed Sep 21 15:07:22 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:22 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65182005a0674
0000a6')
Wed Sep 21 15:07:22 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:22 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65182005a0674
0000a7')
Wed Sep 21 15:07:22 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:22 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65182005a0674
0000a8')
Wed Sep 21 15:07:22 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:22 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65182005a0674
0000a9')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65182005a0674
0000aa')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65182005a0674
0000ab')
Wed Sep 21 15:07:23 [conn2] insert ds3000.logevents 5678ms
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65282005a0674
0000ec')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65382005a0674
0000f2')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001b0')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001b1')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001b2')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001b3')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001b4')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001b5')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001b6')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001b7')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001b8')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001b9')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001ba')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001bb')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001bc')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001bd')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001be')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001bf')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001c0')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001c1')
Wed Sep 21 15:07:23 [conn2] ds3000.logevents Assertion failure _a != -1 e:\buil
dslaves\mongo\windows_64bit_v2.0\mongo\db\pdfile.h 474
Wed Sep 21 15:07:23 [conn2] ds3000.logevents caught assertion _indexRecord ds3
000.logevents.$SourceType_GenerationTimeid _id: ObjectId('4e79d65982005a0674
0001c2')
Wed Sep 21 15:07:23 [conn2] insert ds3000.logevents 233ms

Comment by Matthew Todd [ 21/Sep/11 ]

Hi Dwight,
I work with Nik, and have been looking at this issue whilst he is away this week. Since originally reporting this issue, we have upgraded our mongo server to version 2.0.0 running on Windows Server 2008. In my tests, I have found that with server 2008 set to manage the page file automatically (which will give a maximum page file size of 4GB) we still get VirtualProtect errors. The error messages do seem to be improved on Mongo 2.0.0 though. I have included some additional logs below that show the VirtualProtect error. Are there any recommendations you can give us on page file sizing so we can avoid this issue?

Regards,
Matt

21/09/2011 12:12:24.052 - 38356000/39342713 97%
21/09/2011 12:12:34.005 - 38858500/39342713 98%
21/09/2011 12:12:44.301 - Wed Sep 21 12:12:44 [conn7] done building bottom layer, going to commit
21/09/2011 12:13:00.680 - Wed Sep 21 12:13:00 [conn7] VirtualProtect failed (mcw) /data/db/ds3000.10 673a84000000 4000000 errno:1455 The paging file is too small for this operation to complete.
21/09/2011 12:13:00.695 - Wed Sep 21 12:13:00 [conn7] ds3000.system.indexes Assertion failure false db\mongommf.cpp 72
21/09/2011 12:13:07.778 - Wed Sep 21 12:13:07 [conn7] VirtualProtect failed (mcw) /data/db/ds3000.11 733b74000000 4000000 errno:1455 The paging file is too small for this operation to complete.
21/09/2011 12:13:07.778 - Wed Sep 21 12:13:07 [conn7] ds3000.system.indexes Assertion failure false db\mongommf.cpp 72
21/09/2011 12:13:07.902 - Wed Sep 21 12:13:07 [conn7] insert ds3000.system.indexes exception: assertion db\mongommf.cpp:72 3155852ms
21/09/2011 12:13:08.121 - Wed Sep 21 12:13:08 [conn15] insert ds3000.system.indexes 109ms
21/09/2011 12:13:08.292 - Wed Sep 21 12:13:08 [conn15] build index ds3000.logevents

{ SourceType: 1, GenerationTime: 1, _id: 1 }

21/09/2011 12:13:08.729 - Wed Sep 21 12:13:08 [conn19] end connection 10.253.138.30:53861
21/09/2011 12:13:09.041 - Wed Sep 21 12:13:09 [conn15] ERROR: Uncaught std::exception: bad allocation, terminating
21/09/2011 12:13:09.244 - Wed Sep 21 12:13:09 dbexit:
21/09/2011 12:13:09.244 - Wed Sep 21 12:13:09 [conn15] shutdown: going to close listening sockets...
21/09/2011 12:13:09.244 - Wed Sep 21 12:13:09 [conn15] closing listening socket: 328
21/09/2011 12:13:09.244 - Wed Sep 21 12:13:09 [conn7] build index ds3000.logevents

{ LogLevel: 1, GenerationTime: 1, _id: 1 }

21/09/2011 12:13:09.244 - Wed Sep 21 12:13:09 [conn15] closing listening socket: 344
21/09/2011 12:13:09.244 - Wed Sep 21 12:13:09 [conn15] shutdown: going to flush diaglog...
21/09/2011 12:13:09.244 - Wed Sep 21 12:13:09 [conn15] shutdown: going to close sockets...
21/09/2011 12:13:09.572 - Wed Sep 21 12:13:09 [conn15] shutdown: waiting for fs preallocator...
21/09/2011 12:13:09.572 - Wed Sep 21 12:13:09 [conn15] shutdown: lock for final commit...
21/09/2011 12:13:19.072 - 14800/39342713 0%
21/09/2011 12:13:27.370 - Wed Sep 21 12:13:27 [conn2] got request after shutdown()
21/09/2011 12:13:29.040 - 29500/39342713 0%
21/09/2011 12:13:29.586 - Wed Sep 21 12:13:29 [conn15] shutdown: waiting for write lock...
21/09/2011 12:13:38.274 - Wed Sep 21 12:13:38 [conn7] Assertion: 10000:out of memory BufBuilder
21/09/2011 12:13:38.384 - Wed Sep 21 12:13:38 [conn7] insert ds3000.system.indexes exception: out of memory BufBuilder code:10000 29326ms
21/09/2011 12:13:38.415 - Wed Sep 21 12:13:38 [conn15] shutdown: final commit...
21/09/2011 12:14:16.836 - Wed Sep 21 12:14:16 [initandlisten] now exiting
21/09/2011 12:14:16.836 - Wed Sep 21 12:14:16 dbexit: ; exiting immediately

Comment by Dwight Merriman [ 16/Sep/11 ]

i think it's likely the virtualprotect error was causing that.

Comment by Nik Mason [ 16/Sep/11 ]

No its just a single integer. The collection was 72Gb.

Comment by Dwight Merriman [ 15/Sep/11 ]

is that field an array?
how big is the collection? (run db.mycollection.stats())

Comment by Nik Mason [ 15/Sep/11 ]

Hi Dwight,

Have set the page file to 4Gb, will see how it goes.

I noticed that one of my indexes is particularly large and may be contributing to a disk space problem.

I have 3 compound indexes, each containing 3 indexes:
__HostIP_GenerationTime_Id : 12Gb
__SourceType_GenerationTime_Id : 6Gb
__LogType_GenerationTime_Id : 128Gb

All fields are in all my documents. HostIP and SourceType are strings. LogType is an integer and only has values between 0 and 7.

I dropped the offending __LogType_GenerationTime_Id large index and rebuilt it. It is now 6Gb in size. Any ideas what may have cause this huge index? I am only inserting documents, not deleting or updating.

Regards
Nik

Comment by Dwight Merriman [ 07/Sep/11 ]

can you try making the page file much larger and let us know how it goes. for example try 4GB?
making a jira for "externally altered" case - SERVER-3777. to really fix we will need a log snippet so if you get it again please post it there.

note to committers : if page file needs to be larger, we should give a clearer error message and/or do a basic check for room at server startup.

Comment by Nik Mason [ 07/Sep/11 ]

Hi Dwight,

When running the pagefile utility it returned 2,801,127,424.

Also on another rig where we've had problems we saw the following error in the logs (I'm afraid the logs were log when mongod was restarted):

"The volume for a file has been externally altered so that the opened file is no longer valid"

Ever seen this error before? Can this be caused by low disk space?

Regards
Nik

Comment by Dwight Merriman [ 02/Sep/11 ]

I think the "automatically set" may simply make the pagefile size a certain size relative to physical ram, rather than adaptive. Can you run this:

dir /AH \pagefile.sys

and post the result?

you can also check it in system activity or perfmon, the "PagingFile.% Usage" and % Usage Peek stats.

Windows XP right? I don't think we've done a lot of QA on XP.

also, on the second run it looks like those assertions happened only 3 seconds after the server was up. that suggests to me that the index may be corrupt. i would suggest repairing or at least regen'ing that index or dropping it.

Tue Aug 30 15:07:41 [initandlisten] MongoDB starting : pid=852 port=27017 dbpath=C:\Data 64-bit
...
Tue Aug 30 15:07:42 [initandlisten] connection accepted from 10.253.138.30:54440 #3
Tue Aug 30 15:07:42 [initandlisten] connection accepted from 10.253.138.30:54441 #4
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid

Comment by Nik Mason [ 01/Sep/11 ]

There was no VirtualProtect error in the logs. The portion of logs above is from the the start.

The tester dropped the whole databasae due to time constraints. Next time it happens I'll see what happens if we recreate the indexes.

Regards
Nik

Comment by Scott Hernandez (Inactive) [ 31/Aug/11 ]

Can you post the part of the log with the "VirtualProtect" error for 1.8.3? Is that the portion you were talking about being lost?

If you recreate the index does this happen?

Comment by Nik Mason [ 31/Aug/11 ]

I think the indexes were generating so many assertions that the cause of the assertion has gone off the top of the logs? Here is the start of my log file. Looks like the indexes are already corrupt at this point

Tue Aug 30 15:07:41 [initandlisten] MongoDB starting : pid=852 port=27017 dbpath=C:\Data 64-bit
Tue Aug 30 15:07:41 [initandlisten] db version v1.8.3, pdfile version 4.5
Tue Aug 30 15:07:41 [initandlisten] git version: c206d77e94bc3b65c76681df5a6b605f68a2de05
Tue Aug 30 15:07:41 [initandlisten] build sys info: windows (6, 1, 7601, 2, 'Service Pack 1') BOOST_LIB_VERSION=1_42
Tue Aug 30 15:07:41 [initandlisten] journal dir=C:/Data/journal
Tue Aug 30 15:07:41 [initandlisten] recover : no journal files present, no recovery needed
Tue Aug 30 15:07:41 [initandlisten] waiting for connections on port 27017
Tue Aug 30 15:07:41 [websvr] web admin interface listening on port 28017
Tue Aug 30 15:07:42 [initandlisten] connection accepted from 10.253.138.30:54438 #1
Tue Aug 30 15:07:42 [initandlisten] connection accepted from 10.253.138.30:54439 #2
Tue Aug 30 15:07:42 [initandlisten] connection accepted from 10.253.138.30:54440 #3
Tue Aug 30 15:07:42 [initandlisten] connection accepted from 10.253.138.30:54441 #4
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
Tue Aug 30 15:07:45 [conn1] ds3000.logevents caught assertion indexRecord ds3000.logevents.$_HostIp_GenerationTimeid
etc. etc.

Regards
Nik

Comment by Scott Hernandez (Inactive) [ 30/Aug/11 ]

Can you attach the new error?

Comment by Nik Mason [ 30/Aug/11 ]

Hi Scott,

We've just had the same issue on 1.8.3 too. It was running fine for almost a week before the index assertion problem struck again. The swap file is 1745Mb.

Regard
Nik

Comment by Nik Mason [ 24/Aug/11 ]

Sure, I'll report back. Do you know what issue number was fixed in 1.8.3 to fix this issue?

Regards
Nik

Comment by Scott Hernandez (Inactive) [ 22/Aug/11 ]

It will, but at any given moment it will also report how much space is allocated to the swap file. Please let us know how 1.8.3 goes.

Comment by Nik Mason [ 22/Aug/11 ]

Hi Scott,

I'm using Windows. In the Virtual Memory control panel, the checkbox 'Automatically manage paging file size for all drives' is ticked so I'm assuming the page file will be of a dynamic size?

I will install 1.8.3 and give it a whirl

Regards
Nik

Comment by Scott Hernandez (Inactive) [ 22/Aug/11 ]

This has been seen with 1.8.0/1; please upgrade to 1.8.3.

How large is your page file?

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