New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Crashes with "invalid memory operation" when inserting into mongo collection #1707

Closed
tetianakh opened this Issue Mar 8, 2017 · 8 comments

Comments

Projects
None yet
3 participants
@tetianakh

tetianakh commented Mar 8, 2017

Hello,

I'm getting this error in my applicaton:

object.Exception@../../../../../home/dbio/.dub/packages/vibe-d-0.7.30/vibe-d/source/vibe/core/drivers/libevent2_tcp.d(435): Operating on closed TCPConnection.
----------------
/usr/include/dmd/phobos/std/exception.d:405 pure @safe void std.exception.bailOut!(Exception).bailOut(immutable(char)[], ulong, const(char[])) [0x76a1fb]
/usr/include/dmd/phobos/std/exception.d:363 pure @safe bool std.exception.enforce!(Exception, bool).enforce(bool, lazy const(char)[], immutable(char)[], ulong) [0x76a17e]
../../../../../home/dbio/.dub/packages/vibe-d-0.7.30/vibe-d/source/vibe/core/drivers/libevent2_tcp.d:435 void vibe.core.drivers.libevent2_tcp.Libevent2TCPConnection.checkConnected(bool) [0x8668c5]
../../../../../home/dbio/.dub/packages/vibe-d-0.7.30/vibe-d/source/vibe/core/drivers/libevent2_tcp.d:433 void vibe.core.drivers.libevent2_tcp.Libevent2TCPConnection.flush() [0x8663a9]
../../../../../home/dbio/.dub/packages/vibe-d-0.7.30/vibe-d/source/vibe/core/drivers/libevent2_tcp.d:403 void vibe.core.drivers.libevent2_tcp.Libevent2TCPConnection.finalize() [0x86643e]
../../../../../home/dbio/.dub/packages/vibe-d-0.7.30/vibe-d/source/vibe/db/mongo/connection.d:186 void vibe.db.mongo.connection.MongoConnection.disconnect() [0x84094c]
../../../../../home/dbio/.dub/packages/vibe-d-0.7.30/vibe-d/source/vibe/db/mongo/connection.d:208 void vibe.db.mongo.connection.MongoConnection.insert(immutable(char)[], vibe.db.mongo.flags.InsertFlags, vibe.data.bson.Bson[]) [0x840cf8]
../../../../../home/dbio/.dub/packages/vibe-d-0.7.30/vibe-d/source/vibe/db/mongo/collection.d:106 void vibe.db.mongo.collection.MongoCollection.insert!(sequence.Sequence[]).insert(sequence.Sequence[], vibe.db.mongo.flags.InsertFlags) [0x801ad9]
../common/source/dbQuery.d:138 void dbQuery.SequenceCollection.insert(sequence.Sequence[]) [0x7d72d8]
../common/source/dataStorage.d:94 void dataStorage.DataStorage.saveSequences(sequence.Sequence[immutable(char)[]]) [0x7d57df]
source/processing.d:291 void pipeline.processing.Processing.writeOutputFiles(sequence.Sequence[immutable(char)[]]) [0x7b825e]
source/app.d:69 _Dmain [0x7beabf]
??:? _D2rt6dmain211_d_run_mainUiPPaPUAAaZiZ6runAllMFZ9__lambda1MFZv [0x9080c2]
??:? void rt.dmain2._d_run_main(int, char**, extern (C) int function(char[][])*).tryExec(scope void delegate()) [0x90800c]
??:? void rt.dmain2._d_run_main(int, char**, extern (C) int function(char[][])*).runAll() [0x90807e]
??:? void rt.dmain2._d_run_main(int, char**, extern (C) int function(char[][])*).tryExec(scope void delegate()) [0x90800c]
??:? _d_run_main [0x907f7d]
??:? main [0x7bed9b]
??:? __libc_start_main [0x32aab7ec]
object.Error@(0): A fatal log message was logged
----------------
??:? _D3std12experimental6logger4core6Logger6__ctorMFNfE3std12experimental6logger4core8LogLevelZ12__dgliteral2MFNaNbNfZv [0x96fcb0]
/usr/include/dmd/phobos/std/experimental/logger/core.d:1103 void std.experimental.logger.core.Logger.memLogFunctions!(192).logImplf!(72, "source/app.d", "app.main", "int app.main(string[] args)", "app", Exception).logImplf(lazy immutable(char)[], lazy Exception) [0x7a96d8]
source/app.d:72 _Dmain [0x7beb3c]
??:? _D2rt6dmain211_d_run_mainUiPPaPUAAaZiZ6runAllMFZ9__lambda1MFZv [0x9080c2]
??:? void rt.dmain2._d_run_main(int, char**, extern (C) int function(char[][])*).tryExec(scope void delegate()) [0x90800c]
??:? void rt.dmain2._d_run_main(int, char**, extern (C) int function(char[][])*).runAll() [0x90807e]
??:? void rt.dmain2._d_run_main(int, char**, extern (C) int function(char[][])*).tryExec(scope void delegate()) [0x90800c]
??:? _d_run_main [0x907f7d]
??:? main [0x7bed9b]
??:? __libc_start_main [0x32aab7ec]
core.exception.InvalidMemoryOperationError@src/core/exception.d(693): Invalid memory operation
----------------

This happens when saving arrays about 1000 structs long into a mongo using MongoCollection.insert.
No problems with shorter arrays (~100 structs).

Minimal example to reproduce this issue:

import vibe.db.mongo.mongo: MongoCollection;
import vibe.db.mongo.mongo: connectMongoDB;



void main() {
    auto db = connectMongoDB("127.0.0.1").getDatabase("test");
    auto collection = MongoCollection(db, "test");

    Sequence[] sequences;
    for (int i = 0; i < 1000000; i++) {
        sequences ~= Sequence();
    }
    collection.insert(sequences);
}

struct Sequence {
    string dna = "Lorem ipsum dolor sit amet, consectetur adipisicing elit, sed do eiusmod tempor incididunt ut labore et dolore magna aliqua. Ut enim ad minim veniam, quis nostrud exercitation ullamco laboris nisi ut aliquip ex ea commodo consequat. Duis aute irure dolor in reprehenderit in voluptate velit esse cillum dolore eu fugiat nulla pariatur. Excepteur sint occaecat cupidatat non proident, sunt in culpa qui officia deserunt mollit anim id est laborum.";
}

The larger struct, the shorter array you need to cause a crash.

Any ideas what this might be caused by, and how to fix it?

@TETYYS

This comment has been minimized.

Show comment
Hide comment
@TETYYS

TETYYS Mar 8, 2017

Do you have 447MB memory available?

TETYYS commented Mar 8, 2017

Do you have 447MB memory available?

@tetianakh

This comment has been minimized.

Show comment
Hide comment
@tetianakh

tetianakh Mar 8, 2017

@TETYYS yes, I have about 870 Mb of RAM free at the moment of crash (according to top).

tetianakh commented Mar 8, 2017

@TETYYS yes, I have about 870 Mb of RAM free at the moment of crash (according to top).

@s-ludwig

This comment has been minimized.

Show comment
Hide comment
@s-ludwig

s-ludwig Mar 8, 2017

Member

Unfortunately it's hard to tell the root cause for the invalid memory operation error without a call stack, but the original trigger seems to be that the MongoDB server closes the connection. The reason appears to be that you are running into a hard limit there: https://docs.mongodb.com/manual/reference/limits/#Write-Command-Operation-Limit-Size

I'll try to reproduce the invalid memory operation error later when I get some time.

Member

s-ludwig commented Mar 8, 2017

Unfortunately it's hard to tell the root cause for the invalid memory operation error without a call stack, but the original trigger seems to be that the MongoDB server closes the connection. The reason appears to be that you are running into a hard limit there: https://docs.mongodb.com/manual/reference/limits/#Write-Command-Operation-Limit-Size

I'll try to reproduce the invalid memory operation error later when I get some time.

@tetianakh

This comment has been minimized.

Show comment
Hide comment
@tetianakh

tetianakh Mar 8, 2017

The 1000 operations limit is on the server side, and it is normally hidden from the app by a driver. See this SO discussion for details http://stackoverflow.com/questions/24237887/what-is-mongodb-batch-operation-max-size

tetianakh commented Mar 8, 2017

The 1000 operations limit is on the server side, and it is normally hidden from the app by a driver. See this SO discussion for details http://stackoverflow.com/questions/24237887/what-is-mongodb-batch-operation-max-size

@s-ludwig

This comment has been minimized.

Show comment
Hide comment
@s-ludwig

s-ludwig Mar 8, 2017

Member

Exactly, the client driver in vibe.d currently doesn't do any effort to hide this fact, although this would certainly be a feature worth adding.

Member

s-ludwig commented Mar 8, 2017

Exactly, the client driver in vibe.d currently doesn't do any effort to hide this fact, although this would certainly be a feature worth adding.

@tetianakh

This comment has been minimized.

Show comment
Hide comment
@tetianakh

tetianakh Mar 23, 2017

@s-ludwig sorry for replying so late. While splitting the array into 1000-element chunks does help, I don't think this is the cause of the crash. The minimal example above executes successfully with 100000 elements, but crashes with 1 million elements. So how come an array of 100k elements can be inserted regardless of the 1000-operation limit?

tetianakh commented Mar 23, 2017

@s-ludwig sorry for replying so late. While splitting the array into 1000-element chunks does help, I don't think this is the cause of the crash. The minimal example above executes successfully with 100000 elements, but crashes with 1 million elements. So how come an array of 100k elements can be inserted regardless of the 1000-operation limit?

@s-ludwig s-ludwig closed this in 1e8b08a Mar 23, 2017

@s-ludwig

This comment has been minimized.

Show comment
Hide comment
@s-ludwig

s-ludwig Mar 23, 2017

Member

Good question. Did you verify that all 100k elements are actually in the database after the operation?

I just used the code above to reproduce this locally and these are the current findings:

  • The InvalidMemoryOperationError is a consequence of the process getting terminated because the exception thrown by insert isn't caught. There is a StreamOutputRange struct instance stored in a class object and tries to write to the already closed connection. This in turn tries to allocate an exception, which causes the error (no GC operations allowed during shutdown) -- this is now fixed on master

  • The original error is Connection error while writing to TCPConnection and happens while the insert request is still transferred to the MongoDB server. It appears to be a limit to the maximum request size, according to the MongoDB log:
    2017-03-23T10:44:52.988+0100 [conn1] recv(): message len 461000030 is invalid. Min 16 Max: 48000000
    2017-03-23T10:44:52.988+0100 [conn1] end connection 127.0.0.1:42437 (0 connections now open)

Member

s-ludwig commented Mar 23, 2017

Good question. Did you verify that all 100k elements are actually in the database after the operation?

I just used the code above to reproduce this locally and these are the current findings:

  • The InvalidMemoryOperationError is a consequence of the process getting terminated because the exception thrown by insert isn't caught. There is a StreamOutputRange struct instance stored in a class object and tries to write to the already closed connection. This in turn tries to allocate an exception, which causes the error (no GC operations allowed during shutdown) -- this is now fixed on master

  • The original error is Connection error while writing to TCPConnection and happens while the insert request is still transferred to the MongoDB server. It appears to be a limit to the maximum request size, according to the MongoDB log:
    2017-03-23T10:44:52.988+0100 [conn1] recv(): message len 461000030 is invalid. Min 16 Max: 48000000
    2017-03-23T10:44:52.988+0100 [conn1] end connection 127.0.0.1:42437 (0 connections now open)

@s-ludwig

This comment has been minimized.

Show comment
Hide comment
@s-ludwig

s-ludwig Mar 23, 2017

Member

The size limit appears to be fixed, so to some degree this could also be abstracted away by the client driver, together with the 1000 operations limit. I've opened #1719 for this topic.

Member

s-ludwig commented Mar 23, 2017

The size limit appears to be fixed, so to some degree this could also be abstracted away by the client driver, together with the 1000 operations limit. I've opened #1719 for this topic.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment