[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: |
|
||||||||
| 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 , $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 Regards |
| Comments |
| Comment by Tad Marshall [ 22/Apr/12 ] |
|
Duplicate of |
| 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 |
| 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 30/09/2011 21:23:58.789 - Fri Sep 30 21:23:58 [conn2] insert ds3000.logevents 639ms |
| 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, 37790300/39342713 96% |
| Comment by Matthew Todd [ 21/Sep/11 ] |
|
Hi Dwight, Regards, 21/09/2011 12:12:24.052 - 38356000/39342713 97% 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.244 - Wed Sep 21 12:13:09 [conn15] closing listening socket: 344 |
| 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? |
| 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: 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 |
| 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? 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 |
| 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 |
| 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 |
| 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 Regards |
| 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 |
| 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 |
| 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 |
| 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? |