[Date Prev][Date Next] [Chronological] [Thread] [Top]
Re: (ITS#8392) Opening multiple databases from the same process

To: openldap-its@OpenLDAP.org
Subject: Re: (ITS#8392) Opening multiple databases from the same process
From: matthew@wellquite.org
Date: Sat, 26 Mar 2016 21:07:38 +0000
Auto-submitted: auto-generated (OpenLDAP-ITS)
--rwEMma7ioTxnRzrJ
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

Hi Howard,

Thanks for the quick reply.

On Sat, Mar 26, 2016 at 06:44:29PM +0000, Howard Chu wrote:
> Is this entire task read-only, nobody is modifying any of the DBs while
> these readers are iterating thru the DBs?

This entire process is read only, and indeed the transactions that
contain cursors are marked RDONLY. No other process is running that
accesses any of these databases.

> You might consider compiling LMDB with MDB_DEBUG defined, enabling debug
> output, and then watching the cursor activity. Of course, the act of writing
> debug messages will impact thread scheduling, so it may not reveal what's
> going on.

Ok, I've done all that and got debug output going. I can still provoke
the same problem easily. A log is attached.
Ultimately, both cursors should start on a key
0000000000000000000000000000000000000000, but the second cursor/db
discovers it actually starts on
0000000000000000000000000000000141d8872b.

One problem is that the debug output gives no indication of which thread
is which so it seems pretty tricky to separate out the different calls.
Do you have any hints or tricks for doing this?

Matthew

--rwEMma7ioTxnRzrJ
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment; filename=log

GoshawkDBConsistencyChecker 2016/03/26 20:58:25.362121 [./consistencychecker /tmp/data1 /tmp/data2]
GoshawkDBConsistencyChecker 2016/03/26 20:58:25.362201 ...loading from /tmp/data1
GoshawkDBConsistencyChecker 2016/03/26 20:58:25.362223 Starting disk server on /tmp/data1
mdb_env_open2:4175 opened database version 1, pagesize 4096
mdb_env_open2:4176 using meta page 0
mdb_env_open2:4177 depth: 1
mdb_env_open2:4178 entries: 5
mdb_env_open2:4179 branch pages: 0
mdb_env_open2:4180 leaf pages: 1
mdb_env_open2:4181 overflow pages: 0
mdb_env_open2:4182 root: 1192
mdb_env_open:4803 opened dbenv 0xd363c0
mdb_txn_begin:2850 begin txn 1785w 0xd37660 on mdbenv 0xd363c0, root page 1192
mdb_page_search:5426 db 1 root page 1192 has flags 0x2
mdb_page_search_root:5323 found leaf page 1192 for key [5472616e73616374696f6e52656673]
mdb_node_search:5072 searching 5 keys in leaf page 1192
mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 0
mdb_cursor_set:5980 ==> cursor placed on key [5472616e73616374696f6e52656673]
mdb_page_search:5426 db 1 root page 1192 has flags 0x2
mdb_page_search_root:5323 found leaf page 1192 for key [56617273]
mdb_node_search:5072 searching 5 keys in leaf page 1192
mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 2
mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 2
mdb_node_search:5116 found leaf index 4 [56617273], rc = 0
mdb_cursor_set:5980 ==> cursor placed on key [56617273]
mdb_page_search:5426 db 1 root page 1192 has flags 0x2
mdb_page_search_root:5323 found leaf page 1192 for key [5472616e73616374696f6e73]
mdb_node_search:5072 searching 5 keys in leaf page 1192
mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 8448
mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 0
mdb_cursor_set:5980 ==> cursor placed on key [5472616e73616374696f6e73]
mdb_txn_end:2918 empty-commit txn 1785w 0xd37660 on mdbenv 0xd363c0, root page 1192
mdb_txn_begin:2850 begin txn 1784r 0x7f36e8000a10 on mdbenv 0xd363c0, root page 1192
mdb_txn_end:2918 abort txn 1784r 0x7f36e8000a10 on mdbenv 0xd363c0, root page 1192
mdb_txn_begin:2850 begin txn 1784r 0x7f36e8000a10 on mdbenv 0xd363c0, root page 1192
mdb_get:5556 ===> get db 3 key [0000000000000000000000000000000000000000]
mdb_page_search:5426 db 1 root page 1192 has flags 0x2
mdb_page_search_root:5323 found leaf page 1192 for key [56617273]
mdb_node_search:5072 searching 5 keys in leaf page 1192
mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 2
mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 2
mdb_node_search:5116 found leaf index 4 [56617273], rc = 0
mdb_page_search:5426 db 3 root page 854 has flags 0x1
mdb_page_search:5426 db 3 root page 854 has flags 0x1
mdb_page_search_root:5271 branch page 854 has 2 keys
mdb_page_search_root:5277 found index 0 to page 868
mdb_node_search:5072 searching 2 keys in branch page 854
mdb_node_search:5119 found branch index 1 [00000000000001f500000006000000016634c9ee -> 734], rc = -1
mdb_page_search_root:5295 following index 0 for key [0000000000000000000000000000000000000000]
mdb_cursor_push:5183 pushing page 868 on db 3 cursor 0x7f36f0d5e6c0
mdb_page_search_root:5271 branch page 868 has 135 keys
mdb_page_search_root:5277 found index 0 to page 96
mdb_node_search:5072 searching 135 keys in branch page 868
mdb_node_search:5119 found branch index 67 [00000000000000c600000006000000016634c9ee -> 65], rc = -50688
mdb_node_search:5119 found branch index 33 [000000000000005a00000006000000016634c9ee -> 61], rc = -23040
mdb_node_search:5119 found branch index 16 [000000000000001900000006000000016634c9ee -> 964], rc = -6400
mdb_node_search:5119 found branch index 8 [000000000000000f00000006000000016634c9ee -> 72], rc = -3840
mdb_node_search:5119 found branch index 4 [000000000000000500000006000000016634c9ee -> 124], rc = -1280
mdb_node_search:5119 found branch index 2 [000000000000000100000004000000016634c9ee -> 1021], rc = -256
mdb_node_search:5119 found branch index 1 [000000000000000000000006000000016634c9ee -> 869], rc = -1536
mdb_page_search_root:5295 following index 0 for key [0000000000000000000000000000000000000000]
mdb_cursor_push:5183 pushing page 96 on db 3 cursor 0x7f36f0d5e6c0
mdb_page_search_root:5323 found leaf page 96 for key [0000000000000000000000000000000000000000]
mdb_node_search:5072 searching 7 keys in leaf page 96
mdb_node_search:5116 found leaf index 3 [000000000000000000000000000000019f23085d], rc = -256
mdb_node_search:5116 found leaf index 1 [0000000000000000000000000000000141d8872b], rc = -256
mdb_node_search:5116 found leaf index 0 [0000000000000000000000000000000000000000], rc = 0
mdb_cursor_set:5980 ==> cursor placed on key [0000000000000000000000000000000000000000]
mdb_get:5556 ===> get db 4 key [000000000000000100000000000000019f23085d]
mdb_page_search:5426 db 1 root page 1192 has flags 0x2
mdb_page_search_root:5323 found leaf page 1192 for key [5472616e73616374696f6e73]
mdb_node_search:5072 searching 5 keys in leaf page 1192
mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 8448
mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 0
mdb_page_search:5426 db 4 root page 592 has flags 0x1
mdb_page_search:5426 db 4 root page 592 has flags 0x1
mdb_page_search_root:5271 branch page 592 has 128 keys
mdb_page_search_root:5277 found index 0 to page 37
mdb_node_search:5072 searching 128 keys in branch page 592
mdb_node_search:5119 found branch index 64 [00000000000001fe000000000000000141d8872b -> 565], rc = -1
mdb_node_search:5119 found branch index 32 [00000000000000fe00000000000000019f23085d -> 461], rc = -64768
mdb_node_search:5119 found branch index 16 [000000000000007300000000000000016634c9ee -> 323], rc = -29184
mdb_node_search:5119 found branch index 8 [000000000000003f000000000000000141d8872b -> 20], rc = -15872
mdb_node_search:5119 found branch index 4 [000000000000001200000000000000019f23085d -> 448], rc = -4352
mdb_node_search:5119 found branch index 2 [000000000000000200000000000000019f23085d -> 141], rc = -256
mdb_node_search:5119 found branch index 1 [000000000000000100000000000000019f23085d -> 142], rc = 0
mdb_page_search_root:5295 following index 1 for key [000000000000000100000000000000019f23085d]
mdb_cursor_push:5183 pushing page 142 on db 4 cursor 0x7f36f0d5e6c0
mdb_page_search_root:5323 found leaf page 142 for key [000000000000000100000000000000019f23085d]
mdb_node_search:5072 searching 3 keys in leaf page 142
mdb_node_search:5116 found leaf index 1 [0000000000000002000000000000000141d8872b], rc = -256
mdb_node_search:5116 found leaf index 0 [000000000000000100000000000000019f23085d], rc = 0
mdb_cursor_set:5980 ==> cursor placed on key [000000000000000100000000000000019f23085d]
mdb_txn_end:2918 reset txn 1784r 0x7f36e8000a10 on mdbenv 0xd363c0, root page 1192
GoshawkDBConsistencyChecker 2016/03/26 20:58:25.364770 ...loading from /tmp/data2
GoshawkDBConsistencyChecker 2016/03/26 20:58:25.364807 Starting disk server on /tmp/data2
mdb_env_open2:4175 opened database version 1, pagesize 4096
mdb_env_open2:4176 using meta page 1
mdb_env_open2:4177 depth: 1
mdb_env_open2:4178 entries: 5
mdb_env_open2:4179 branch pages: 0
mdb_env_open2:4180 leaf pages: 1
mdb_env_open2:4181 overflow pages: 0
mdb_env_open2:4182 root: 1239
mdb_env_open:4803 opened dbenv 0x7f36e00008c0
mdb_txn_begin:2850 begin txn 1858w 0x7f36e0001b80 on mdbenv 0x7f36e00008c0, root page 1239
mdb_page_search:5426 db 1 root page 1239 has flags 0x2
mdb_page_search_root:5323 found leaf page 1239 for key [5472616e73616374696f6e73]
mdb_node_search:5072 searching 5 keys in leaf page 1239
mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 8448
mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 0
mdb_cursor_set:5980 ==> cursor placed on key [5472616e73616374696f6e73]
mdb_page_search:5426 db 1 root page 1239 has flags 0x2
mdb_page_search_root:5323 found leaf page 1239 for key [5472616e73616374696f6e52656673]
mdb_node_search:5072 searching 5 keys in leaf page 1239
mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 0
mdb_cursor_set:5980 ==> cursor placed on key [5472616e73616374696f6e52656673]
mdb_page_search:5426 db 1 root page 1239 has flags 0x2
mdb_page_search_root:5323 found leaf page 1239 for key [56617273]
mdb_node_search:5072 searching 5 keys in leaf page 1239
mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 2
mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 2
mdb_node_search:5116 found leaf index 4 [56617273], rc = 0
mdb_cursor_set:5980 ==> cursor placed on key [56617273]
mdb_txn_end:2918 empty-commit txn 1858w 0x7f36e0001b80 on mdbenv 0x7f36e00008c0, root page 1239
mdb_txn_begin:2850 begin txn 1857r 0x7f36e4000a10 on mdbenv 0x7f36e00008c0, root page 1239
mdb_txn_end:2918 abort txn 1857r 0x7f36e4000a10 on mdbenv 0x7f36e00008c0, root page 1239
mdb_txn_begin:2850 begin txn 1857r 0x7f36e4000a10 on mdbenv 0x7f36e00008c0, root page 1239
mdb_get:5556 ===> get db 4 key [0000000000000000000000000000000000000000]
mdb_page_search:5426 db 1 root page 1239 has flags 0x2
mdb_page_search_root:5323 found leaf page 1239 for key [56617273]
mdb_node_search:5072 searching 5 keys in leaf page 1239
mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 2
mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 2
mdb_node_search:5116 found leaf index 4 [56617273], rc = 0
mdb_page_search:5426 db 4 root page 633 has flags 0x1
mdb_page_search:5426 db 4 root page 633 has flags 0x1
mdb_page_search_root:5271 branch page 633 has 2 keys
mdb_page_search_root:5277 found index 0 to page 634
mdb_node_search:5072 searching 2 keys in branch page 633
mdb_node_search:5119 found branch index 1 [00000000000000f900000006000000016634c9ee -> 115], rc = -63744
mdb_page_search_root:5295 following index 0 for key [0000000000000000000000000000000000000000]
mdb_cursor_push:5183 pushing page 634 on db 4 cursor 0x7f36f055d6c0
mdb_page_search_root:5271 branch page 634 has 68 keys
mdb_page_search_root:5277 found index 0 to page 56
mdb_node_search:5072 searching 68 keys in branch page 634
mdb_node_search:5119 found branch index 34 [000000000000006100000006000000016634c9ee -> 562], rc = -24832
mdb_node_search:5119 found branch index 17 [000000000000001c00000006000000016634c9ee -> 18], rc = -7168
mdb_node_search:5119 found branch index 8 [000000000000000e00000006000000016634c9ee -> 160], rc = -3584
mdb_node_search:5119 found branch index 4 [000000000000000400000006000000016634c9ee -> 405], rc = -1024
mdb_node_search:5119 found branch index 2 [000000000000000100000004000000016634c9ee -> 489], rc = -256
mdb_node_search:5119 found branch index 1 [000000000000000000000006000000016634c9ee -> 636], rc = -1536
mdb_page_search_root:5295 following index 0 for key [0000000000000000000000000000000000000000]
mdb_cursor_push:5183 pushing page 56 on db 4 cursor 0x7f36f055d6c0
mdb_page_search_root:5323 found leaf page 56 for key [0000000000000000000000000000000000000000]
mdb_node_search:5072 searching 7 keys in leaf page 56
mdb_node_search:5116 found leaf index 3 [000000000000000000000000000000019f23085d], rc = -256
mdb_node_search:5116 found leaf index 1 [0000000000000000000000000000000141d8872b], rc = -256
mdb_node_search:5116 found leaf index 0 [0000000000000000000000000000000000000000], rc = 0
mdb_cursor_set:5980 ==> cursor placed on key [0000000000000000000000000000000000000000]
mdb_get:5556 ===> get db 2 key [000000000000000100000000000000019f23085d]
mdb_page_search:5426 db 1 root page 1239 has flags 0x2
mdb_page_search_root:5323 found leaf page 1239 for key [5472616e73616374696f6e73]
mdb_node_search:5072 searching 5 keys in leaf page 1239
mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 8448
mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 0
mdb_page_search:5426 db 2 root page 606 has flags 0x1
mdb_page_search:5426 db 2 root page 606 has flags 0x1
mdb_page_search_root:5271 branch page 606 has 128 keys
mdb_page_search_root:5277 found index 0 to page 8
mdb_node_search:5072 searching 128 keys in branch page 606
mdb_node_search:5119 found branch index 64 [0000000000000219000000000000000141d8872b -> 414], rc = -2
mdb_node_search:5119 found branch index 32 [00000000000000fe00000000000000019f23085d -> 832], rc = -64768
mdb_node_search:5119 found branch index 16 [000000000000007400000000000000016634c9ee -> 85], rc = -29440
mdb_node_search:5119 found branch index 8 [000000000000003f000000000000000141d8872b -> 108], rc = -15872
mdb_node_search:5119 found branch index 4 [000000000000001200000000000000019f23085d -> 10], rc = -4352
mdb_node_search:5119 found branch index 2 [000000000000000200000000000000019f23085d -> 19], rc = -256
mdb_node_search:5119 found branch index 1 [000000000000000100000000000000019f23085d -> 33], rc = 0
mdb_page_search_root:5295 following index 1 for key [000000000000000100000000000000019f23085d]
mdb_cursor_push:5183 pushing page 33 on db 2 cursor 0x7f36f055d6c0
mdb_page_search_root:5323 found leaf page 33 for key [000000000000000100000000000000019f23085d]
mdb_node_search:5072 searching 3 keys in leaf page 33
mdb_node_search:5116 found leaf index 1 [0000000000000002000000000000000141d8872b], rc = -256
mdb_node_search:5116 found leaf index 0 [000000000000000100000000000000019f23085d], rc = 0
mdb_cursor_set:5980 ==> cursor placed on key [000000000000000100000000000000019f23085d]
mdb_txn_end:2918 reset txn 1857r 0x7f36e4000a10 on mdbenv 0x7f36e00008c0, root page 1239
mdb_txn_renew:2750 renew txn 1857r 0x7f36e4000a10 on mdbenv 0x7f36e00008c0, root page 1239
mdb_page_search:5426 db 1 root page 1239 has flags 0x2
mdb_page_search_root:5323 found leaf page 1239 for key [56617273]
mdb_node_search:5072 searching 5 keys in leaf page 1239
mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 2
mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 2
mdb_node_search:5116 found leaf index 4 [56617273], rc = 0
mdb_page_search:5426 db 4 root page 633 has flags 0x1
mdb_page_search:5426 db 4 root page 633 has flags 0x1
mdb_page_search_root:5271 branch page 633 has 2 keys
mdb_page_search_root:5277 found index 0 to page 634
mdb_cursor_push:5183 pushing page 634 on db 4 cursor 0x7f36e4000bd0
mdb_page_search_root:5271 branch page 634 has 68 keys
mdb_page_search_root:5277 found index 0 to page 56
mdb_cursor_push:5183 pushing page 56 on db 4 cursor 0x7f36e4000bd0
mdb_page_search_root:5323 found leaf page 56 for key [null]
RM:9f23085d(/tmp/data2) VarUUId:0000000000000000000000000000000000000000 [0 0 0 0 26 0 0 0 0 0 0 0 0 0 5 0 17 0 0 0 162 0 0 0 25 0 0 0 2 0 0 0 21 0 0 0 162 0 0 0 28 0 0 0 0 0 2 0 52 0 0 0 0 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 1 159 35 8 93 0 0 0 0 5 0 0 0 14 0 0 0 17 0 0 0 13 0 0 0 1 0 0 0 162 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0 5 0 0 0 14 0 0 0 5 0 0 0 13 0 0 0 5 0 0 0 162 0 0 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
mdb_txn_renew:2750 renew txn 1784r 0x7f36e8000a10 on mdbenv 0xd363c0, root page 1192
mdb_page_search:5426 db 1 root page 1192 has flags 0x2
mdb_page_search_root:5323 found leaf page 1192 for key [5472616e73616374696f6e73]
mdb_node_search:5072 searching 5 keys in leaf page 1192
mdb_node_search:5116 found leaf index 2 [5472616e73616374696f6e52656673], rc = 8448
mdb_node_search:5116 found leaf index 3 [5472616e73616374696f6e73], rc = 0
mdb_page_search:5426 db 4 root page 592 has flags 0x1
mdb_page_search:5426 db 4 root page 592 has flags 0x1
mdb_page_search_root:5271 branch page 592 has 128 keys
mdb_page_search_root:5277 found index 0 to page 37
mdb_cursor_push:5183 pushing page 37 on db 4 cursor 0x7f36e8000bd0
mdb_page_search_root:5323 found leaf page 37 for key [null]
mdb_txn_end:2918 reset txn 1784r 0x7f36e8000a10 on mdbenv 0xd363c0, root page 1192
GoshawkDBConsistencyChecker 2016/03/26 20:58:25.367498 Shutting down iterator
GoshawkDBConsistencyChecker 2016/03/26 20:58:25.367507 Err on finding first var in RM:6634c9ee(/tmp/data1): expected to find topology var, but found VarUUId:0000000000000000000000000000000141d8872b instead! ([0 0 0 0 30 0 0 0 0 0 0 0 2 0 3 0 43 135 216 65 1 0 0 0 0 2 0 0 2 0 0 0 9 0 0 0 162 0 0 0 17 0 0 0 47 0 0 0 57 0 0 0 55 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 65 216 135 43 0 0 0 0 4 0 0 0 1 0 4 0 3 0 0 0 0 0 0 0 13 0 0 0 162 0 0 0 21 0 0 0 42 0 0 0 21 0 0 0 2 0 0 0 17 0 0 0 7 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 65 216 135 43 0 0 0 0 0 1 2 3 4 0 0 0 0 0 0 0 0 0 2 0 12 0 0 0 1 0 1 0 238 201 52 102 1 0 0 0 17 0 0 0 11 0 0 0 93 8 35 159 1 0 0 0 13 0 0 0 11 0 0 0 43 135 216 65 0 0 0 0 9 0 0 0 11 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0])

--rwEMma7ioTxnRzrJ--
Prev by Date: Re: (ITS#8392) Opening multiple databases from the same process
Next by Date: Re: (ITS#8392) Opening multiple databases from the same process
Index(es):
- Chronological
- Thread