Details
Critical - P2 Description
Description:
Found out that a special sequence of event may reduce server throughput by 90% for around 10min. So far, the trigger seems drop a collection while there is concurrent oplog tailing going on.
Test setup
- single node replica set with wiredTiger
- use a special written tool to tail oplog with 32 or 64 thread (run from a separate server)
- use bench run run simple insert into multi collection, step of the test
- drop all collection
- use benchRun do simple insert
- check throughput with mongostat
Observation:
The throughput will drop from 70k to 600, and this will last for up to 10min (after stop tailing oplog)
MongoDB shell version: 3.0.0-rc8
|
connecting to: test
|
{ "name" : "wiredTiger" }
|
0: 79966.63852879952 <-- every test last 10 second
|
1: 73956.35971517103
|
2: 70263.89507592177
|
3: 76272.46177347556
|
4: 76179.7331941972
|
5: 76071.29258252526
|
6: 76504.322290524
|
7: 77133.12436735495
|
8: 76096.40869079733
|
9: 600.3870288152949 <--- the drop
|
10: 585.1938886069264 <-- stop tailing oplog
|
11: 587.1715686099094
|
|
|
.....
|
|
|
67: 569.518186223205
|
68: 550.9203010903097
|
69: 401.6865724762767
|
70: 74848.28307466969 <--- recover, drop last for 600sec
|
71: 76152.44327463405
|
- this also happen with smaller thread number, much easier to repro with higher thread count (tailing oplog)
- could not reproduce this with mmapv1
- tested with RC8
perf topN
- 12.37% mongod mongod [.] __rec_row_leaf_insert
|
- __rec_row_leaf_insert
|
- __rec_row_leaf
|
- __wt_reconcile
|
- 99.30% __wt_cache_op
|
- 98.54% __wt_checkpoint
|
- 98.58% __wt_txn_checkpoint
|
__session_checkpoint
|
__ckpt_server
|
start_thread
|
+ 1.42% __checkpoint_apply
|
+ 1.46% __wt_txn_checkpoint
|
+ 0.70% __evict_review
|
- 10.84% mongod mongod [.] __config_getraw.isra.
|
- __config_getraw.isra.0
|
- 54.82% __wt_config_getones
|
- 63.83% __wt_schema_open_table
|
__wt_schema_get_table
|
__wt_schema_drop
|
__session_drop
|
mongo::WiredTigerKVEngine::dropAllQueued()
|
mongo::WiredTigerSessionCache::releaseSession(mongo::WiredTigerSession*)
|
mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit()
|
+ mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit()
|
- 27.61% __wt_schema_open_colgroups
|
__wt_schema_open_table
|
__wt_schema_get_table
|
__wt_schema_drop
|
__session_drop
|
mongo::WiredTigerKVEngine::dropAllQueued()
|
mongo::WiredTigerSessionCache::releaseSession(mongo::WiredTigerSession*)
|
mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit()
|
+ mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit()
|
+ 8.47% __wt_config_gets_def
|
- 44.87% __wt_config_get
|
- 98.94% __wt_config_gets
|
- 71.56% __wt_cursor_init
|
__wt_curfile_create
|
__wt_metadata_cursor
|
__wt_metadata_update
|
__wt_meta_track_off
|
__wt_schema_drop
|
__session_drop
|
mongo::WiredTigerKVEngine::dropAllQueued()
|
mongo::WiredTigerSessionCache::releaseSession(mongo::WiredTigerSession*)
|
mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit()
|
+ mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit()
|
- 15.69% __wt_curfile_create
|
__wt_metadata_cursor
|
__wt_metadata_update
|
__wt_meta_track_off
|
__wt_schema_drop
|
__session_drop
|
mongo::WiredTigerKVEngine::dropAllQueued()
|
mongo::WiredTigerSessionCache::releaseSession(mongo::WiredTigerSession*)
|
mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit()
|
+ mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit()
|
+ 12.62% __wt_schema_drop
|
+ 1.06% __wt_config_collapse
|
|
Setup
- rc8
"version" : "3.0.0-rc8","gitVersion" : "9d0714cdcffadb203ff68730acedbc40875403da", - parameters
"--dbpath=/data/ssd-sdc/dbs-wt","--logpath=/data/ssd-sdc/logs/mongod.log","--fork","--replSet","r","--storageEngine=wiredTiger"
