[SERVER-9824] Assertion on unordered_fast_key_table_internal.h Created: 30/May/13  Updated: 11/Jul/16  Resolved: 10/Jun/13

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: 2.4.3
Fix Version/s: 2.4.5, 2.5.1

Type: Bug Priority: Minor - P4
Reporter: Justin Assignee: Tad Marshall
Resolution: Done Votes: 0
Labels: query
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Linux Debian Wheezy


Issue Links:
Duplicate
is duplicated by SERVER-9922 Mongod instance (2.4.4) crashed with ... Closed
Related
Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

Create a document with a large number of key/value pairs:

{ _id: <object>, r1: <value>, r2: <value>, r3: <value>, ... rN: <value> }

Query the document with provided fields:
db.collection.find(

{ _id: <object> }

,

{ r1: 1, r2: 1, r3: 1, ... rN: 1 }

)

Participants:

 Description   

An assertion is being issues by the server when providing a field list with a large number of fields. Reducing the number of fields returned does not cause the assertion.

I first noticed this issue when querying via the PHP driver but running an identical query in the shell produces the same result:

error:

{ "$err" : "assertion src/mongo/util/unordered_fast_key_table_internal.h:94" }

Querying with 150 fields defined triggers the assertion. Query values of less (say, 100) do not. For my document it asserts at exactly 101 field values defined.



 Comments   
Comment by auto [ 19/Jun/13 ]

Author:

{u'username': u'tadmarshall', u'name': u'Tad Marshall', u'email': u'tad@10gen.com'}

Message: SERVER-9824 Add jstest
Branch: v2.4
https://github.com/mongodb/mongo/commit/9f975ab30ef2f579ea2bbb2bebeadd7abf1d69d2

Comment by auto [ 19/Jun/13 ]

Author:

{u'username': u'tadmarshall', u'name': u'Tad Marshall', u'email': u'tad@10gen.com'}

Message: SERVER-9824 Whitespace – CRLF to newline
Branch: v2.4
https://github.com/mongodb/mongo/commit/6ab83d2992c3432f03951ca96a8d5f078a954664

Comment by auto [ 19/Jun/13 ]

Author:

{u'username': u'tadmarshall', u'name': u'Tad Marshall', u'email': u'tad@10gen.com'}

Message: SERVER-9824 Retry hash table grow operation on excessive collisions

Be defensive against excessively long hash chains in a resized table in
UnorderedFastKeyTable::_grow(). Retry growing the table up to 5 times
before declaring failure (as we do when inserting into a table). Reduce
the maximum retry count for table insertions from 10 to 5, since growing
the table by a factor of 32 (2**5) guarantees that no hash chain can be
as long as 5% (1/20, the default _maxProbeRatio) of the new table size.
Branch: v2.4
https://github.com/mongodb/mongo/commit/df2274d2a2cac0fe41de61b0a7943ff7977975f7

Comment by auto [ 10/Jun/13 ]

Author:

{u'username': u'tadmarshall', u'name': u'Tad Marshall', u'email': u'tad@10gen.com'}

Message: SERVER-9824 Add jstest
Branch: master
https://github.com/mongodb/mongo/commit/8d832958dd3387336bfedc9ed400b72f1012a61d

Comment by Tad Marshall [ 07/Jun/13 ]

Reopening for addition of jstest.

Comment by auto [ 07/Jun/13 ]

Author:

{u'username': u'tadmarshall', u'name': u'Tad Marshall', u'email': u'tad@10gen.com'}

Message: SERVER-9824 Whitespace – CRLF to newline
Branch: master
https://github.com/mongodb/mongo/commit/c2748a2bf862e026c4a919aac62a568b52abb9a2

Comment by auto [ 07/Jun/13 ]

Author:

{u'username': u'tadmarshall', u'name': u'Tad Marshall', u'email': u'tad@10gen.com'}

Message: SERVER-9824 Retry hash table grow operation on excessive collisions

Be defensive against excessively long hash chains in a resized table in
UnorderedFastKeyTable::_grow(). Retry growing the table up to 5 times
before declaring failure (as we do when inserting into a table). Reduce
the maximum retry count for table insertions from 10 to 5, since growing
the table by a factor of 32 (2**5) guarantees that no hash chain can be
as long as 5% (1/20, the default _maxProbeRatio) of the new table size.
Branch: master
https://github.com/mongodb/mongo/commit/1bad6b0bd957b0bbe98459770c10bf1af0670a99

Comment by Tad Marshall [ 01/Jun/13 ]

Hi Justin,

Thanks for the stack trace!

I was able to reproduce your issue in the current master branch. I tested a Windows debug build, which is why the server stack trace looks different from your example.

SERVER-9824.js:

// Test for SERVER-9824
 
var testDB = db.getSiblingDB('SERVER-9824');
 
var doTest = function(count) {
    print('Testing with count of ' + count);
    testDB.dropDatabase();
    var id = { data: 1 };
    var doc = { _id: id };
    var projection = { };
 
    for (var i = 1; i <= count; ++i) {
        var r = 'r' + i;
        doc[r] = i;
        projection[r] = 1;
    }
 
    testDB.collection.insert( doc );
    try {
        var found = testDB.collection.find( { _id: id }, projection ).itcount();
        return found;
    }
    catch (e) {
        doassert('Test FAILED!  Caught exception ' + tojsononeline(e));
    }
}
 
for (var j = 90; j < 150; ++j) {
    doTest(j);
}

shell output:

MongoDB shell version: 2.5.1-pre-
connecting to: test
Server has startup warnings:
Sat Jun 01 08:07:54.041 [initandlisten]
Sat Jun 01 08:07:54.041 [initandlisten] ** NOTE: This is a development version (2.5.1-pre-) of MongoDB.
Sat Jun 01 08:07:54.042 [initandlisten] **       Not recommended for production.
Sat Jun 01 08:07:54.042 [initandlisten]
> load('C:\\BAT\\SERVER-9824.js')
Testing with count of 90
Testing with count of 91
Testing with count of 92
Testing with count of 93
Testing with count of 94
Testing with count of 95
Testing with count of 96
Testing with count of 97
Testing with count of 98
Testing with count of 99
Testing with count of 100
Testing with count of 101
Testing with count of 102
Testing with count of 103
Sat Jun 01 09:31:58.143 Socket recv() errno:10054 An existing connection was forcibly closed by the remote host. 127.0.0.1:27017
Sat Jun 01 09:31:58.144 SocketException: remote: 127.0.0.1:27017 error: 9001 socket exception [RECV_ERROR] server [127.0.0.1:27017]
Sat Jun 01 09:31:58.144 DBClientCursor::init call() failed
assert: Test FAILED!  Caught exception Error: error doing query: failed
Error: Printing Stack Trace
    at printStackTrace (src/mongo/shell/utils.js:37:15)
    at doassert (src/mongo/shell/assert.js:6:5)
    at doTest (C:\BAT\SERVER-9824.js:24:9)
    at C:\BAT\SERVER-9824.js:29:5
    at (shell):1:1
Sat Jun 01 09:31:58.183 Test FAILED!  Caught exception Error: error doing query: failed at src/mongo/shell/assert.js:7
Sat Jun 01 09:31:58.184 Error: error loading js file: C:\BAT\SERVER-9824.js
Sat Jun 01 09:31:58.190 trying reconnect to 127.0.0.1:27017
Sat Jun 01 09:31:59.190 reconnect 127.0.0.1:27017 failed couldn't connect to server 127.0.0.1:27017
>

server log:

Sat Jun 01 08:07:54.039 [initandlisten] MongoDB starting : pid=8148 port=27017 dbpath=f:\cleandb 64-bit host=MissLucy
Sat Jun 01 08:07:54.041 [initandlisten] _DEBUG build (which is slower)
Sat Jun 01 08:07:54.041 [initandlisten]
Sat Jun 01 08:07:54.041 [initandlisten] ** NOTE: This is a development version (2.5.1-pre-) of MongoDB.
Sat Jun 01 08:07:54.042 [initandlisten] **       Not recommended for production.
Sat Jun 01 08:07:54.042 [initandlisten]
Sat Jun 01 08:07:54.042 [initandlisten] db version v2.5.1-pre-
Sat Jun 01 08:07:54.042 [initandlisten] git version: not-scons
Sat Jun 01 08:07:54.042 [initandlisten] build info: not-scons win mscver:160040219 built:Jun  1 2013 boostver:1049001
Sat Jun 01 08:07:54.042 [initandlisten] allocator:
Sat Jun 01 08:07:54.042 [initandlisten] options: { dbpath: "f:\cleandb" }
Sat Jun 01 08:07:54.509 [initandlisten] journal dir=f:\cleandb\journal
Sat Jun 01 08:07:54.510 [initandlisten] recover : no journal files present, no recovery needed
Sat Jun 01 08:07:54.518 [initandlisten] opening db:  local
Sat Jun 01 08:07:54.524 [initandlisten]
debug have W lock but w would suffice for command create
Sat Jun 01 08:07:54.525 [FileAllocator] allocating new datafile f:\cleandb\local.ns, filling with zeroes...
Sat Jun 01 08:07:54.525 [IndexRebuilder] thread IndexRebuilder stack usage was 8896 bytes,  which is the most so far
Sat Jun 01 08:07:54.526 [FileAllocator] creating directory f:\cleandb\_tmp
Sat Jun 01 08:07:54.605 [FileAllocator] done allocating datafile f:\cleandb\local.ns, size: 16MB,  took 0.078 secs
Sat Jun 01 08:07:54.606 [FileAllocator] allocating new datafile f:\cleandb\local.0, filling with zeroes...
Sat Jun 01 08:07:54.920 [FileAllocator] done allocating datafile f:\cleandb\local.0, size: 64MB,  took 0.312 secs
Sat Jun 01 08:07:54.920 [initandlisten] datafileheader::init initializing f:\cleandb\local.0 n:0
Sat Jun 01 08:07:54.922 [initandlisten] command local.$cmd command: { create: "startup_log", size: 10485760, capped: true } ntoreturn:1 keyUpdates:0  reslen:37 397ms
Sat Jun 01 08:07:54.922 [initandlisten] info PageFaultRetryableSection will not yield, already locked upon reaching
Sat Jun 01 08:07:54.927 [initandlisten] waiting for connections on port 27017
Sat Jun 01 08:08:01.378 [initandlisten] connection accepted from 127.0.0.1:53267 #1 (1 connection now open)
Sat Jun 01 08:08:03.878 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:03.882 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:04.262 [conn1] removeJournalFiles
Sat Jun 01 08:08:04.266 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:04.266 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:388344 reslen:62 388ms
Sat Jun 01 08:08:04.301 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:04.305 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:04.385 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.078 secs
Sat Jun 01 08:08:04.387 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:04.702 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.313 secs
Sat Jun 01 08:08:04.703 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:04.704 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:04.706 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:04.707 [conn1] build index done.  scanned 0 total records. 0.001 secs
Sat Jun 01 08:08:04.708 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:407291 404ms
Sat Jun 01 08:08:04.846 [conn1] query SERVER-9824.collection query: { _id: { data: 1.0 } } ntoreturn:0 idhack:1 keyUpdates:0 locks(micros) r:190 reslen:1210 131ms
Sat Jun 01 08:08:04.852 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:05.331 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.626 secs
Sat Jun 01 08:08:05.617 [conn1] removeJournalFiles
Sat Jun 01 08:08:05.631 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:05.632 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:779388 reslen:62 779ms
Sat Jun 01 08:08:05.651 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:05.652 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:05.731 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.078 secs
Sat Jun 01 08:08:05.732 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:06.043 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.31 secs
Sat Jun 01 08:08:06.044 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:06.045 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:06.046 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:06.047 [conn1] build index done.  scanned 0 total records. 0 secs
Sat Jun 01 08:08:06.048 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:397499 396ms
Sat Jun 01 08:08:06.445 [conn1] query SERVER-9824.collection query: { _id: { data: 1.0 } } ntoreturn:0 idhack:1 keyUpdates:0 locks(micros) r:192 reslen:1223 133ms
Sat Jun 01 08:08:06.450 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:06.667 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.621 secs
Sat Jun 01 08:08:07.162 [conn1] removeJournalFiles
Sat Jun 01 08:08:07.178 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:07.178 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:727978 reslen:62 728ms
Sat Jun 01 08:08:07.195 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:07.197 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:07.275 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.077 secs
Sat Jun 01 08:08:07.277 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:07.587 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.31 secs
Sat Jun 01 08:08:07.588 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:07.589 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:07.590 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:07.591 [conn1] build index done.  scanned 0 total records. 0 secs
Sat Jun 01 08:08:07.592 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:396721 395ms
Sat Jun 01 08:08:07.993 [conn1] query SERVER-9824.collection query: { _id: { data: 1.0 } } ntoreturn:0 idhack:1 keyUpdates:0 locks(micros) r:192 reslen:1236 139ms
Sat Jun 01 08:08:07.998 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:08.214 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.624 secs
Sat Jun 01 08:08:08.810 [conn1] removeJournalFiles
Sat Jun 01 08:08:08.826 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:08.826 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:827953 reslen:62 828ms
Sat Jun 01 08:08:08.844 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:08.845 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:08.924 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.077 secs
Sat Jun 01 08:08:08.925 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:09.239 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.313 secs
Sat Jun 01 08:08:09.240 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:09.240 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:09.242 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:09.243 [conn1] build index done.  scanned 0 total records. 0 secs
Sat Jun 01 08:08:09.244 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:399980 399ms
Sat Jun 01 08:08:09.660 [conn1] query SERVER-9824.collection query: { _id: { data: 1.0 } } ntoreturn:0 idhack:1 keyUpdates:0 locks(micros) r:194 reslen:1249 143ms
Sat Jun 01 08:08:09.664 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:09.865 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.622 secs
Sat Jun 01 08:08:10.406 [conn1] removeJournalFiles
Sat Jun 01 08:08:10.421 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:10.422 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:757393 reslen:62 757ms
Sat Jun 01 08:08:10.439 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:10.441 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:10.520 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.077 secs
Sat Jun 01 08:08:10.521 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:10.831 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.31 secs
Sat Jun 01 08:08:10.832 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:10.833 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:10.834 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:10.835 [conn1] build index done.  scanned 0 total records. 0 secs
Sat Jun 01 08:08:10.836 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:396709 395ms
Sat Jun 01 08:08:11.270 [conn1] query SERVER-9824.collection query: { _id: { data: 1.0 } } ntoreturn:0 idhack:1 keyUpdates:0 locks(micros) r:197 reslen:1262 148ms
Sat Jun 01 08:08:11.275 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:11.459 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.625 secs
Sat Jun 01 08:08:12.062 [conn1] removeJournalFiles
Sat Jun 01 08:08:12.078 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:12.078 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:803336 reslen:62 803ms
Sat Jun 01 08:08:12.096 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:12.098 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:12.176 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.077 secs
Sat Jun 01 08:08:12.177 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:12.488 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.31 secs
Sat Jun 01 08:08:12.489 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:12.489 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:12.491 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:12.492 [conn1] build index done.  scanned 0 total records. 0 secs
Sat Jun 01 08:08:12.493 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:396689 395ms
Sat Jun 01 08:08:12.960 [conn1] query SERVER-9824.collection query: { _id: { data: 1.0 } } ntoreturn:0 idhack:1 keyUpdates:0 locks(micros) r:203 reslen:1275 148ms
Sat Jun 01 08:08:12.965 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:13.110 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.62 secs
Sat Jun 01 08:08:13.729 [conn1] removeJournalFiles
Sat Jun 01 08:08:13.745 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:13.745 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:780137 reslen:62 780ms
Sat Jun 01 08:08:13.763 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:13.765 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:13.843 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.077 secs
Sat Jun 01 08:08:13.844 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:14.155 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.309 secs
Sat Jun 01 08:08:14.155 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:14.156 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:14.157 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:14.159 [conn1] build index done.  scanned 0 total records. 0 secs
Sat Jun 01 08:08:14.159 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:396140 395ms
Sat Jun 01 08:08:14.548 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:14.778 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.621 secs
Sat Jun 01 08:08:15.309 [conn1] removeJournalFiles
Sat Jun 01 08:08:15.325 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:15.325 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:776660 reslen:62 776ms
Sat Jun 01 08:08:15.343 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:15.345 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:15.423 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.077 secs
Sat Jun 01 08:08:15.424 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:15.736 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.31 secs
Sat Jun 01 08:08:15.736 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:15.737 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:15.738 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:15.739 [conn1] build index done.  scanned 0 total records. 0 secs
Sat Jun 01 08:08:15.740 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:396817 395ms
Sat Jun 01 08:08:15.981 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:16.358 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.62 secs
Sat Jun 01 08:08:16.709 [conn1] removeJournalFiles
Sat Jun 01 08:08:16.725 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:16.725 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:743653 reslen:62 743ms
Sat Jun 01 08:08:16.743 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:16.745 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:16.823 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.077 secs
Sat Jun 01 08:08:16.824 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:17.135 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.31 secs
Sat Jun 01 08:08:17.136 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:17.136 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:17.138 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:17.139 [conn1] build index done.  scanned 0 total records. 0 secs
Sat Jun 01 08:08:17.140 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:396270 395ms
Sat Jun 01 08:08:17.387 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:17.760 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.622 secs
Sat Jun 01 08:08:18.161 [conn1] removeJournalFiles
Sat Jun 01 08:08:18.177 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:18.177 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:790542 reslen:62 790ms
Sat Jun 01 08:08:18.196 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:18.197 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:18.276 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.078 secs
Sat Jun 01 08:08:18.277 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:18.588 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.31 secs
Sat Jun 01 08:08:18.589 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:18.590 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:18.591 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:18.592 [conn1] build index done.  scanned 0 total records. 0 secs
Sat Jun 01 08:08:18.593 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:397254 396ms
Sat Jun 01 08:08:18.843 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:19.210 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.62 secs
Sat Jun 01 08:08:19.596 [conn1] removeJournalFiles
Sat Jun 01 08:08:19.610 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:19.610 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:767373 reslen:62 767ms
Sat Jun 01 08:08:19.629 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:19.631 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:19.709 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.077 secs
Sat Jun 01 08:08:19.710 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:20.021 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.31 secs
Sat Jun 01 08:08:20.022 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:20.022 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:20.024 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:20.025 [conn1] build index done.  scanned 0 total records. 0 secs
Sat Jun 01 08:08:20.026 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:396611 395ms
Sat Jun 01 08:08:20.275 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:20.643 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.62 secs
Sat Jun 01 08:08:21.085 [conn1] removeJournalFiles
Sat Jun 01 08:08:21.100 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:21.101 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:825711 reslen:62 825ms
Sat Jun 01 08:08:21.120 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:21.121 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:21.199 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.077 secs
Sat Jun 01 08:08:21.200 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:21.511 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.309 secs
Sat Jun 01 08:08:21.512 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:21.512 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:21.514 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:21.515 [conn1] build index done.  scanned 0 total records. 0 secs
Sat Jun 01 08:08:21.516 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:396154 395ms
Sat Jun 01 08:08:21.782 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:22.134 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.62 secs
Sat Jun 01 08:08:22.575 [conn1] removeJournalFiles
Sat Jun 01 08:08:22.591 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:22.591 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:808827 reslen:62 808ms
Sat Jun 01 08:08:22.610 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:22.612 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:22.690 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.077 secs
Sat Jun 01 08:08:22.691 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:23.006 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.314 secs
Sat Jun 01 08:08:23.007 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:23.007 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:23.009 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:23.010 [conn1] build index done.  scanned 0 total records. 0 secs
Sat Jun 01 08:08:23.011 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:400617 399ms
Sat Jun 01 08:08:23.281 [conn1] query SERVER-9824.collection query: { _id: { data: 1.0 } } ntoreturn:0 idhack:1 keyUpdates:0 locks(micros) r:201 reslen:1369 106ms
Sat Jun 01 08:08:23.285 [conn1] dropDatabase SERVER-9824 starting
Sat Jun 01 08:08:23.628 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.62 secs
Sat Jun 01 08:08:24.042 [conn1] removeJournalFiles
Sat Jun 01 08:08:24.057 [conn1] dropDatabase SERVER-9824 finished
Sat Jun 01 08:08:24.058 [conn1] command SERVER-9824.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:772128 reslen:62 772ms
Sat Jun 01 08:08:24.077 [conn1] opening db:  SERVER-9824
Sat Jun 01 08:08:24.078 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.ns, filling with zeroes...
Sat Jun 01 08:08:24.157 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.ns, size: 16MB,  took 0.077 secs
Sat Jun 01 08:08:24.158 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.0, filling with zeroes...
Sat Jun 01 08:08:24.468 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.0, size: 64MB,  took 0.309 secs
Sat Jun 01 08:08:24.469 [conn1] datafileheader::init initializing f:\cleandb\SERVER-9824.0 n:0
Sat Jun 01 08:08:24.469 [FileAllocator] allocating new datafile f:\cleandb\SERVER-9824.1, filling with zeroes...
Sat Jun 01 08:08:24.471 [conn1] build index SERVER-9824.collection { _id: 1 }
Sat Jun 01 08:08:24.472 [conn1] build index done.  scanned 0 total records. 0 secs
Sat Jun 01 08:08:24.473 [conn1] insert SERVER-9824.collection ninserted:1 keyUpdates:0 locks(micros) w:395833 394ms
Sat Jun 01 08:08:24.642 [conn1]   Assertion failure firstEmpty >= 0 C:\Visual Studio 2010 Projects\mongodev\src\mongo/util/unordered_fast_key_table_internal.h 94
Sat Jun 01 08:08:25.092 [FileAllocator] done allocating datafile f:\cleandb\SERVER-9824.1, size: 128MB,  took 0.622 secs
Sat Jun 01 08:08:25.496 [conn1] mongod.exe  ...\src\mongo\util\stacktrace.cpp(189)                           mongo::printStackTrace+0x5a
Sat Jun 01 08:08:25.496 [conn1] mongod.exe  ...\src\mongo\util\log.cpp(456)                                  mongo::logContext+0x72
Sat Jun 01 08:08:25.497 [conn1] mongod.exe  ...\src\mongo\util\assert_util.cpp(114)                          mongo::verifyFailed+0x190
Sat Jun 01 08:08:25.497 [conn1] mongod.exe  ...\src\mongo\util\unordered_fast_key_table_internal.h(94)       mongo::UnorderedFastKeyTable<mongo::StringData,std::basic_string<char,std::char_traits<char>,std::allocator<char> >,boost::shared_ptr<mongo::Projection>,mongo::StringMapDefaultHash,mongo::StringMapDefaultEqual,mongo::StringMapDefaultConvertor,mongo::StringMapDefaultConvertorOther>::Area::transfer+0x173
Sat Jun 01 08:08:25.498 [conn1] mongod.exe  ...\src\mongo\util\unordered_fast_key_table_internal.h(174)      mongo::UnorderedFastKeyTable<mongo::StringData,std::basic_string<char,std::char_traits<char>,std::allocator<char> >,boost::shared_ptr<mongo::Projection>,mongo::StringMapDefaultHash,mongo::StringMapDefaultEqual,mongo::StringMapDefaultConvertor,mongo::StringMapDefaultConvertorOther>::_grow+0x63
Sat Jun 01 08:08:25.498 [conn1] mongod.exe  ...\src\mongo\util\unordered_fast_key_table_internal.h(152)      mongo::UnorderedFastKeyTable<mongo::StringData,std::basic_string<char,std::char_traits<char>,std::allocator<char> >,boost::shared_ptr<mongo::Projection>,mongo::StringMapDefaultHash,mongo::StringMapDefaultEqual,mongo::StringMapDefaultConvertor,mongo::StringMapDefaultConvertorOther>::get+0x20b
Sat Jun 01 08:08:25.500 [conn1] mongod.exe  ...\src\mongo\util\unordered_fast_key_table.h(112)               mongo::UnorderedFastKeyTable<mongo::StringData,std::basic_string<char,std::char_traits<char>,std::allocator<char> >,boost::shared_ptr<mongo::Projection>,mongo::StringMapDefaultHash,mongo::StringMapDefaultEqual,mongo::StringMapDefaultConvertor,mongo::StringMapDefaultConvertorOther>::operator[]+0x32
Sat Jun 01 08:08:25.503 [conn1] mongod.exe  ...\src\mongo\db\projection.cpp(129)                             mongo::Projection::add+0x24a
Sat Jun 01 08:08:25.510 [conn1] mongod.exe  ...\src\mongo\db\projection.cpp(92)                              mongo::Projection::init+0x7e9
Sat Jun 01 08:08:25.510 [conn1] mongod.exe  ...\src\mongo\db\parsed_query.cpp(196)                           mongo::ParsedQuery::initFields+0xcf
Sat Jun 01 08:08:25.511 [conn1] mongod.exe  ...\src\mongo\db\parsed_query.cpp(33)                            mongo::ParsedQuery::ParsedQuery+0x10f
Sat Jun 01 08:08:25.511 [conn1] mongod.exe  ...\src\mongo\db\ops\query.cpp(929)                              mongo::runQuery+0x8e
Sat Jun 01 08:08:25.512 [conn1] mongod.exe  ...\src\mongo\db\instance.cpp(249)                               mongo::receivedQuery+0x33d
Sat Jun 01 08:08:25.512 [conn1] mongod.exe  ...\src\mongo\db\instance.cpp(388)                               mongo::assembleResponse+0x353
Sat Jun 01 08:08:25.512 [conn1] mongod.exe  ...\src\mongo\db\db.cpp(201)                                     mongo::MyMessageHandler::process+0x133
Sat Jun 01 08:08:25.514 [conn1] mongod.exe  ...\src\mongo\util\net\message_server_port.cpp(206)              mongo::PortMessageServer::handleIncomingMsg+0x676
Sat Jun 01 08:08:25.514 [conn1] mongod.exe  ...\src\third_party\boost\boost\bind\bind.hpp(244)               boost::_bi::list1<boost::_bi::value<mongo::PortMessageServer::HandleIncomingMsgParam * __ptr64> >::operator()<void * __ptr64,void * __ptr64 (__cdecl*)(void * __ptr64),boost::_bi::list0>+0x56
Sat Jun 01 08:08:25.515 [conn1] mongod.exe  ...\src\third_party\boost\boost\bind\bind_template.hpp(21)       boost::_bi::bind_t<void * __ptr64,void * __ptr64 (__cdecl*)(void * __ptr64),boost::_bi::list1<boost::_bi::value<mongo::PortMessageServer::HandleIncomingMsgParam * __ptr64> > >::operator()+0x61
Sat Jun 01 08:08:25.515 [conn1] mongod.exe  ...\src\third_party\boost\boost\thread\detail\thread.hpp(63)     boost::detail::thread_data<boost::_bi::bind_t<void * __ptr64,void * __ptr64 (__cdecl*)(void * __ptr64),boost::_bi::list1<boost::_bi::value<mongo::PortMessageServer::HandleIncomingMsgParam * __ptr64> > > >::run+0x2f
Sat Jun 01 08:08:25.516 [conn1] mongod.exe  ...\src\third_party\boost\libs\thread\src\win32\thread.cpp(185)  boost::`anonymous namespace'::thread_start_function+0x4c

This is a bug in the UnorderedFastKeyTable class, which is the base class for the StringMap class that is used to store the field names of your projection (the second part of your find() query,

{ r1: 1, r2: 1, r3: 1, ... rN: 1 }

).

UnorderedFastKeyTable implements a hash table to find keys quickly, and when enough keys are added to the hash table to impact its performance, it creates a new hash table twice the size of the old one and transfers the contents of the old table to the new one. The performance check is that no hash chain is longer than 5% of the capacity of the table.

The bug is that the transfer code assumes that it will be able to store all of the keys in the new table subject to the same performance requirement that caused it to create a new table. This will usually be true, but is not guaranteed. If the new table produces a hash chain longer than 5% of the new table's size while transferring the contents of the old table, the assertion you saw is generated and the assertion error is returned to the client.

Tad

Comment by Justin [ 01/Jun/13 ]

Sure!

I happened to have verbose logging turned on. Hopefully this is what you're looking for:

Thu May 30 13:52:09.305 [conn2767]   Assertion failure firstEmpty >= 0 src/mongo/util/unordered_fast_key_table_internal.h 94
0xdcf361 0xd902bd 0xb33611 0xb33d29 0xb7fc01 0xb691ae 0xa7f649 0x9f44d4 0x9f57e2 0x6e747a 0xdbbb7e 0x7fb5385a2b50 0x7fb537945a7d
 /usr/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0xdcf361]
 /usr/bin/mongod(_ZN5mongo12verifyFailedEPKcS1_j+0xfd) [0xd902bd]
 /usr/bin/mongod(_ZN5mongo10Projection3addERKSsb+0x6c1) [0xb33611]
 /usr/bin/mongod(_ZN5mongo10Projection4initERKNS_7BSONObjE+0x289) [0xb33d29]
 /usr/bin/mongod(_ZN5mongo11ParsedQuery10initFieldsERKNS_7BSONObjE+0x1c1) [0xb7fc01]
 /usr/bin/mongod(_ZN5mongo11ParsedQueryC1ERNS_12QueryMessageE+0x9e) [0xb691ae]
 /usr/bin/mongod(_ZN5mongo8runQueryERNS_7MessageERNS_12QueryMessageERNS_5CurOpES1_+0x39) [0xa7f649]
 /usr/bin/mongod() [0x9f44d4]
 /usr/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x392) [0x9f57e2]
 /usr/bin/mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x9a) [0x6e747a]
 /usr/bin/mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x42e) [0xdbbb7e]
 /lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50) [0x7fb5385a2b50]
 /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7fb537945a7d]
Thu May 30 13:52:09.314 [conn2767] assertion 0 assertion src/mongo/util/unordered_fast_key_table_internal.h:94 ns:<removed> query:{ _id: "7fffe4f70000451aa782d610ce310a91" }
Thu May 30 13:52:09.314 [conn2767] query  keyUpdates:0 exception: assertion src/mongo/util/unordered_fast_key_table_internal.h:94  reslen:99 0ms

If you need any more information, let me know!

Thanks,

Justin

Comment by Tad Marshall [ 31/May/13 ]

Hi Justin,

Thanks for the report.

Is there a stack trace in the server log corresponding to this event? The assertion is coming from a C++ template, so seeing the details of what the code was doing would help pin this down.

Thanks!

Tad

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