-
Type:
Bug
-
Resolution: Works as Designed
-
Priority:
Major - P3
-
None
-
Affects Version/s: None
-
Component/s: None
-
Labels:None
-
Environment:Ubuntu 16.04
Reproduce
Apply the patch on top of mongodb/3138119968a4d5bb7602bc766762d571ae5cd248
Start mongod as a single member replica set node:
rm -rf /data/db/* && ./mongod --replSet rs0 --journalCommitInterval 500 --logpath open_mdb_cursors.log
When mongod is running, run mongo restart.js. Note there is a sleep to wait for the replica set to initiate. Consider increasing it based on your system.
Observations
When receiving the restartStorageEngine command (named from previous designs, pardon the lack of renaming), the WiredTigerRecordStore objects are reconstructed. This constructor calls an alter table to turn adjust the table logging. While these calls aren't necessary (the setting is in the desired state from startup), it would be work to avoid doing so. When reconstructing the WiredTigerRecordStore objects, the alter table returns an EBUSY. Tracking application level calls to sessions/cursors (see mongo/db/storage/wiredtiger/wt_debug.h and mongo/track_cursors.py) shows the only open transaction is on the thread performing the recovery (i.e: recreating the record store) and the side-session setTableLogging creates.
track_cursors.py
track_cursors.py takes mongodb log output (when run with debugging enabled as defined in wt_debug.h on stdin and keeps track of all "non-trivial" calls to sessions and cursors (trivial uses, for example, include WiredTigerUtil::exportTableToBSON that provably opens and closes a cursor in the lifetime of the method).
The cursor map is a map of cursors identified by their address to a tuple of ('Last action', "Last owning session", "last used uri"). The session map is keyed on sessions identified by their address and the value being the last open/close/reset/begin_transaction/commit/rollback method called on that session.
dgottlieb@chimichurri ~/xgen/mongo2[ebusy_on_set_table]$ cat open_mdb_cursors.log | python track_cursors.py
Cursor Map
==========
{'7faa2c53d3a0': ('Reset',
'7faa2e77d020',
'table:index-7-2679884507298173854'),
'7faa2cc2e3a0': ('Reset',
'7faa2e77dc20',
'table:index-18-2679884507298173854'),
'7faa2cc2ee20': ('Closed via session reset.',
'7faa2e77d020',
'table:index-12-2679884507298173854'),
'7faa2cc2f8a0': ('Reset',
'7faa2e77d020',
'table:collection-6-2679884507298173854'),
'7faa2cd3daa0': ('Closed via session reset.',
'7faa2e77d020',
'table:collection-0-2679884507298173854'),
'7faa2cd3e1a0': ('Closed via session reset.',
'7faa2e77d020',
'table:index-5-2679884507298173854'),
'7faa2cd3e8a0': ('Closed via session reset.',
'7faa2e77d020',
'table:index-10-2679884507298173854'),
'7faa2d01c3a0': ('Closed', '7faa2e77e020', 'table:_mdb_catalog'),
'7faa2d01ce20': ('Closed via session reset.',
'7faa2e77d020',
'table:collection-11-2679884507298173854'),
'7faa2d024020': ('Reset', '7faa2e77dc20', 'table:_mdb_catalog'),
'7faa2d038020': ('Reset', '7faa2e77d020', 'metadata:create'),
'7faa2d038aa0': ('Reset', '7faa2e77e020', 'metadata:create'),
'7faa2d03c020': ('Closed via session reset.',
'7faa2e77d020',
'table:collection-4-2679884507298173854'),
'7faa2d03c3a0': ('Closed via session reset.',
'7faa2e77d020',
'table:collection-2-2679884507298173854'),
'7faa2d03c720': ('Closed via session reset.',
'7faa2e77d020',
'table:index-1-2679884507298173854'),
'7faa2d03caa0': ('Closed via session reset.',
'7faa2e77dc20',
'table:collection-4-2679884507298173854'),
'7faa2d03d8a0': ('Closed via session reset.',
'7faa2e77d020',
'table:index-3-2679884507298173854'),
'7faa2d03dc20': ('Closed', '7faa2e77d020', 'table:_mdb_catalog'),
'7faa2d21cfe0': ('Reset', '7faa2e77dc20', 'metadata:create'),
'7faa2d2401a0': ('Closed via session reset.',
'7faa2e77d020',
'table:collection-9-2679884507298173854'),
'7faa2d30f3a0': ('Closed via session reset.',
'7faa2e77d020',
'table:collection-9-2679884507298173854'),
'7faa2d30f720': ('Reset', '7faa2e77d820', 'table:_mdb_catalog'),
'7faa2d3108a0': ('Reset',
'7faa2e77d020',
'table:collection-8-2679884507298173854'),
'7faa2d310c20': ('Closed via session reset.',
'7faa2e77d020',
'table:collection-8-2679884507298173854'),
'7faa2d53e1a0': ('Reset',
'7faa2e77dc20',
'table:collection-8-2679884507298173854'),
'7faa2db04020': ('Closed via session reset.',
'7faa2e77dc20',
'table:collection-15-2679884507298173854'),
'7faa2db04e20': ('Reset',
'7faa2e77dc20',
'table:collection-17-2679884507298173854'),
'7faa2db35aa0': ('Closed via session reset.',
'7faa2e77e020',
'table:collection-13-2679884507298173854'),
'7faa2db36520': ('Closed via session reset.',
'7faa2e77e020',
'table:index-14-2679884507298173854'),
'7faa2dc35720': ('Closed via session reset.',
'7faa2e77e020',
'table:collection-13-2679884507298173854'),
'7faa2dd3ce20': ('Reset', '7faa2e77d420', 'table:sizeStorer'),
'7faa30c9fe20': ('Reset',
'7faa2e77d020',
'table:collection-4-2679884507298173854'),
'7faa30cf2c20': ('Closed via session reset.',
'7faa2e77d020',
'table:collection-2-2679884507298173854')}
Session Map
==========
{'7faa2e77d020': 'In Transaction',
'7faa2e77d420': 'Reset',
'7faa2e77d820': 'Rolledback Transaction',
'7faa2e77dc20': 'Re-using',
'7faa2e77e020': 'Reset',
'7faa2e77e420': 'Reset',
'7faa2e77e820': 'Opened'}
- is related to
-
WT-3529 Add undocumented debug API
-
- Closed
-