[SERVER-15722] D:/Mongo/Data/Default.0 failed with error errno:487 Attempt to access invalid address. (file size is 67108864) in MemoryMappedFile::remapPrivateView Created: 19/Oct/14  Updated: 24/Jan/15  Resolved: 23/Jan/15

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

Type: Bug Priority: Major - P3
Reporter: Paul Knopf Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Windows 7, 32bit, 4gb of ram.


Attachments: Zip Archive mongo-logs.zip     Text File mongo.log     Zip Archive mongo.log.zip    
Operating System: Windows
Participants:

 Description   

I installed mongodb as a service, and the service unexpectedly quit. I am using journaling.

I have attached a log containing the error.



 Comments   
Comment by Paul Knopf [ 20/Oct/14 ]

This is from a machine that still has journaling enabled. The service has been restarted and is responding ok now.

/* 0 */
{
    "host" : "DRSHD-6:1919",
    "version" : "2.6.3",
    "process" : "C:\\MongoDB\\mongod.exe",
    "pid" : NumberLong(376),
    "uptime" : 83245,
    "uptimeMillis" : NumberLong(83245343),
    "uptimeEstimate" : 75806,
    "localTime" : ISODate("2014-10-20T13:48:20.920Z"),
    "asserts" : {
        "regular" : 0,
        "warning" : 0,
        "msg" : 0,
        "user" : 1,
        "rollovers" : 0
    },
    "backgroundFlushing" : {
        "flushes" : 1388,
        "total_ms" : 19080,
        "average_ms" : 13.7463976945245,
        "last_ms" : 22,
        "last_finished" : ISODate("2014-10-20T13:47:44.050Z")
    },
    "connections" : {
        "current" : 4,
        "available" : 999996,
        "totalCreated" : NumberLong(7771)
    },
    "cursors" : {
        "note" : "deprecated, use server status metrics",
        "clientCursors_size" : 0,
        "totalOpen" : 0,
        "pinned" : 0,
        "totalNoTimeout" : 0,
        "timedOut" : 0
    },
    "dur" : {
        "commits" : 30,
        "journaledMB" : 0,
        "writeToDataFilesMB" : 0,
        "compression" : 0,
        "commitsInWriteLock" : 0,
        "earlyCommits" : 0,
        "timeMs" : {
            "dt" : 3076,
            "prepLogBuffer" : 0,
            "writeToJournal" : 0,
            "writeToDataFiles" : 0,
            "remapPrivateView" : 0
        }
    },
    "extra_info" : {
        "note" : "fields vary by platform",
        "page_faults" : 71540,
        "usagePageFileMB" : 83,
        "totalPageFileMB" : 6122,
        "availPageFileMB" : 4934,
        "ramMB" : 3062
    },
    "globalLock" : {
        "totalTime" : NumberLong(83245343000),
        "lockTime" : NumberLong(5818989),
        "currentQueue" : {
            "total" : 0,
            "readers" : 0,
            "writers" : 0
        },
        "activeClients" : {
            "total" : 0,
            "readers" : 0,
            "writers" : 0
        }
    },
    "indexCounters" : {
        "accesses" : 189,
        "hits" : 189,
        "misses" : 0,
        "resets" : 0,
        "missRatio" : 0
    },
    "locks" : {
        "." : {
            "timeLockedMicros" : {
                "R" : NumberLong(1406039),
                "W" : NumberLong(5818989)
            },
            "timeAcquiringMicros" : {
                "R" : NumberLong(760304),
                "W" : NumberLong(155541)
            }
        },
        "admin" : {
            "timeLockedMicros" : {
                "r" : NumberLong(15780),
                "w" : NumberLong(0)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong(222),
                "w" : NumberLong(0)
            }
        },
        "local" : {
            "timeLockedMicros" : {
                "r" : NumberLong(268460),
                "w" : NumberLong(23)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong(26829),
                "w" : NumberLong(0)
            }
        },
        "Default" : {
            "timeLockedMicros" : {
                "r" : NumberLong(2055068),
                "w" : NumberLong(3744)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong(147414),
                "w" : NumberLong(1247)
            }
        }
    },
    "network" : {
        "bytesIn" : 1374970,
        "bytesOut" : 12277177,
        "numRequests" : 23679
    },
    "opcounters" : {
        "insert" : 9,
        "query" : 4436,
        "update" : 21,
        "delete" : 1,
        "getmore" : 2,
        "command" : 23377
    },
    "opcountersRepl" : {
        "insert" : 0,
        "query" : 0,
        "update" : 0,
        "delete" : 0,
        "getmore" : 0,
        "command" : 0
    },
    "recordStats" : {
        "accessesNotInMemory" : 6,
        "pageFaultExceptionsThrown" : 1,
        "Default" : {
            "accessesNotInMemory" : 6,
            "pageFaultExceptionsThrown" : 1
        },
        "admin" : {
            "accessesNotInMemory" : 0,
            "pageFaultExceptionsThrown" : 0
        },
        "local" : {
            "accessesNotInMemory" : 0,
            "pageFaultExceptionsThrown" : 0
        }
    },
    "writeBacksQueued" : false,
    "mem" : {
        "bits" : 32,
        "resident" : 39,
        "virtual" : 440,
        "supported" : true,
        "mapped" : 160,
        "mappedWithJournal" : 320
    },
    "metrics" : {
        "cursor" : {
            "timedOut" : NumberLong(0),
            "open" : {
                "noTimeout" : NumberLong(0),
                "pinned" : NumberLong(0),
                "total" : NumberLong(0)
            }
        },
        "document" : {
            "deleted" : NumberLong(81),
            "inserted" : NumberLong(9),
            "returned" : NumberLong(6946),
            "updated" : NumberLong(17)
        },
        "getLastError" : {
            "wtime" : {
                "num" : 0,
                "totalMillis" : 0
            },
            "wtimeouts" : NumberLong(0)
        },
        "operation" : {
            "fastmod" : NumberLong(7),
            "idhack" : NumberLong(0),
            "scanAndOrder" : NumberLong(0)
        },
        "queryExecutor" : {
            "scanned" : NumberLong(17),
            "scannedObjects" : NumberLong(17)
        },
        "record" : {
            "moves" : NumberLong(0)
        },
        "repl" : {
            "apply" : {
                "batches" : {
                    "num" : 0,
                    "totalMillis" : 0
                },
                "ops" : NumberLong(0)
            },
            "buffer" : {
                "count" : NumberLong(0),
                "maxSizeBytes" : 268435456,
                "sizeBytes" : NumberLong(0)
            },
            "network" : {
                "bytes" : NumberLong(0),
                "getmores" : {
                    "num" : 0,
                    "totalMillis" : 0
                },
                "ops" : NumberLong(0),
                "readersCreated" : NumberLong(0)
            },
            "preload" : {
                "docs" : {
                    "num" : 0,
                    "totalMillis" : 0
                },
                "indexes" : {
                    "num" : 0,
                    "totalMillis" : 0
                }
            }
        },
        "storage" : {
            "freelist" : {
                "search" : {
                    "bucketExhausted" : NumberLong(0),
                    "requests" : NumberLong(8),
                    "scanned" : NumberLong(16)
                }
            }
        },
        "ttl" : {
            "deletedDocuments" : NumberLong(0),
            "passes" : NumberLong(1388)
        }
    },
    "ok" : 1
}

Comment by Paul Knopf [ 20/Oct/14 ]

Here is a machine where I disabled journaling, and the service is still responding fine.

/* 0 */
{
    "host" : "DRSHD-1080p:1919",
    "version" : "2.6.3",
    "process" : "C:\\MongoDB\\mongod.exe",
    "pid" : NumberLong(3884),
    "uptime" : 5357,
    "uptimeMillis" : NumberLong(5356769),
    "uptimeEstimate" : 4752,
    "localTime" : ISODate("2014-10-20T13:46:22.556Z"),
    "asserts" : {
        "regular" : 0,
        "warning" : 0,
        "msg" : 0,
        "user" : 0,
        "rollovers" : 0
    },
    "backgroundFlushing" : {
        "flushes" : 89,
        "total_ms" : 1871,
        "average_ms" : 21.02247191011236,
        "last_ms" : 3,
        "last_finished" : ISODate("2014-10-20T13:46:05.976Z")
    },
    "connections" : {
        "current" : 6,
        "available" : 999994,
        "totalCreated" : NumberLong(338)
    },
    "cursors" : {
        "note" : "deprecated, use server status metrics",
        "clientCursors_size" : 0,
        "totalOpen" : 0,
        "pinned" : 0,
        "totalNoTimeout" : 0,
        "timedOut" : 0
    },
    "extra_info" : {
        "note" : "fields vary by platform",
        "page_faults" : 19183,
        "usagePageFileMB" : 34,
        "totalPageFileMB" : 6122,
        "availPageFileMB" : 4756,
        "ramMB" : 3062
    },
    "globalLock" : {
        "totalTime" : NumberLong(5356769000),
        "lockTime" : NumberLong(58913),
        "currentQueue" : {
            "total" : 0,
            "readers" : 0,
            "writers" : 0
        },
        "activeClients" : {
            "total" : 0,
            "readers" : 0,
            "writers" : 0
        }
    },
    "indexCounters" : {
        "accesses" : 1760,
        "hits" : 1760,
        "misses" : 0,
        "resets" : 0,
        "missRatio" : 0
    },
    "locks" : {
        "." : {
            "timeLockedMicros" : {
                "R" : NumberLong(9),
                "W" : NumberLong(58913)
            },
            "timeAcquiringMicros" : {
                "R" : NumberLong(0),
                "W" : NumberLong(10)
            }
        },
        "admin" : {
            "timeLockedMicros" : {
                "r" : NumberLong(1081),
                "w" : NumberLong(0)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong(32),
                "w" : NumberLong(0)
            }
        },
        "local" : {
            "timeLockedMicros" : {
                "r" : NumberLong(137507),
                "w" : NumberLong(23)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong(6343),
                "w" : NumberLong(0)
            }
        },
        "Default" : {
            "timeLockedMicros" : {
                "r" : NumberLong(627413),
                "w" : NumberLong(13038)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong(12951),
                "w" : NumberLong(1180)
            }
        }
    },
    "network" : {
        "bytesIn" : 138427,
        "bytesOut" : 1645095,
        "numRequests" : 1930
    },
    "opcounters" : {
        "insert" : 36,
        "query" : 949,
        "update" : 58,
        "delete" : 1,
        "getmore" : 13,
        "command" : 1144
    },
    "opcountersRepl" : {
        "insert" : 0,
        "query" : 0,
        "update" : 0,
        "delete" : 0,
        "getmore" : 0,
        "command" : 0
    },
    "recordStats" : {
        "accessesNotInMemory" : 5,
        "pageFaultExceptionsThrown" : 0,
        "Default" : {
            "accessesNotInMemory" : 5,
            "pageFaultExceptionsThrown" : 0
        },
        "admin" : {
            "accessesNotInMemory" : 0,
            "pageFaultExceptionsThrown" : 0
        },
        "local" : {
            "accessesNotInMemory" : 0,
            "pageFaultExceptionsThrown" : 0
        }
    },
    "writeBacksQueued" : false,
    "mem" : {
        "bits" : 32,
        "resident" : 66,
        "virtual" : 244,
        "supported" : true,
        "mapped" : 160
    },
    "metrics" : {
        "cursor" : {
            "timedOut" : NumberLong(0),
            "open" : {
                "noTimeout" : NumberLong(0),
                "pinned" : NumberLong(0),
                "total" : NumberLong(0)
            }
        },
        "document" : {
            "deleted" : NumberLong(409),
            "inserted" : NumberLong(36),
            "returned" : NumberLong(8724),
            "updated" : NumberLong(56)
        },
        "getLastError" : {
            "wtime" : {
                "num" : 0,
                "totalMillis" : 0
            },
            "wtimeouts" : NumberLong(0)
        },
        "operation" : {
            "fastmod" : NumberLong(32),
            "idhack" : NumberLong(0),
            "scanAndOrder" : NumberLong(0)
        },
        "queryExecutor" : {
            "scanned" : NumberLong(56),
            "scannedObjects" : NumberLong(56)
        },
        "record" : {
            "moves" : NumberLong(17)
        },
        "repl" : {
            "apply" : {
                "batches" : {
                    "num" : 0,
                    "totalMillis" : 0
                },
                "ops" : NumberLong(0)
            },
            "buffer" : {
                "count" : NumberLong(0),
                "maxSizeBytes" : 268435456,
                "sizeBytes" : NumberLong(0)
            },
            "network" : {
                "bytes" : NumberLong(0),
                "getmores" : {
                    "num" : 0,
                    "totalMillis" : 0
                },
                "ops" : NumberLong(0),
                "readersCreated" : NumberLong(0)
            },
            "preload" : {
                "docs" : {
                    "num" : 0,
                    "totalMillis" : 0
                },
                "indexes" : {
                    "num" : 0,
                    "totalMillis" : 0
                }
            }
        },
        "storage" : {
            "freelist" : {
                "search" : {
                    "bucketExhausted" : NumberLong(0),
                    "requests" : NumberLong(52),
                    "scanned" : NumberLong(70)
                }
            }
        },
        "ttl" : {
            "deletedDocuments" : NumberLong(0),
            "passes" : NumberLong(89)
        }
    },
    "ok" : 1
}

Comment by Asya Kamsky [ 20/Oct/14 ]

It seems that mongod needs to memory map more than 2Gb of data files as that's when we see this message.

Could you attach the output from the mongo shell command db.serverStatus() from one of the servers that crashed please?

Asya

Comment by Paul Knopf [ 20/Oct/14 ]

These devices will never have 2gb of data, so that isn't an issue for me.

Comment by Asya Kamsky [ 20/Oct/14 ]

Paul,

I believe this is happening due to your use of Windows32.

As noted on the MongoDB downloads page, 32-bit builds are limited to around 2GB of data. In general you should use the 64 bit builds. The 32 bit binaries are ok for replica set arbiters and mongos' but not for production mongod's.

Asya

Comment by Paul Knopf [ 20/Oct/14 ]

I attached logs from another machine. It happened again.

Comment by Paul Knopf [ 19/Oct/14 ]

Correct, it starts up find and my software works as normal.

Comment by Asya Kamsky [ 19/Oct/14 ]

Do I understand correctly that the error has not come back up - i.e. you restarted this mongod instance and it came up with no issues and is running fine now?

I'm wondering if it's a transient disk level error or if possibly mongod hasn't attempted to access the same file/part of file that caused this problem.

Comment by Paul Knopf [ 19/Oct/14 ]

I have attached the logs from the system. It was running a test to test my software (which uses MongoDB). It wasn't exactly stress testing it, so MongoDB shouldn't have been under pressure. Just constant usage.

The "D" drive is a partition on the same hard drive as the operating system. The mongod.exe is located on the C partition and is installed as a windows server.

This is a physical system.

We have about 15 machines (same hardware, os image, configuration, etc) running the same test, and this machine has been the only one that had this error. It has not happened again yet.

Comment by Paul Knopf [ 19/Oct/14 ]

Attached all the logs on the system

Comment by Asya Kamsky [ 19/Oct/14 ]

theonlylawislove can you clarify a few things please?

Is the crash in the log the first crash? It looks like it had been running for a day and a half without issues - was that when you installed/started MongoDB for the first time if not, did it shut down normally before Oct 17th 14:22:00 GMT? Do you have the previous log by any chance?

What sort of storage is "D:\Mongo\Data\" on? Is this a local disk, a mapped drive or something else?

Is this a physical Windows 7 32-bit machine or is it a VM?

Asya

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