[SERVER-24019] Eviction failure because of hazard pointer and query throughput regression (not DML) Created: 03/May/16  Updated: 08/Feb/23  Resolved: 15/Jun/16

Status: Closed
Project: Core Server
Component/s: WiredTiger
Affects Version/s: 3.2.5
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: 아나 하리 Assignee: Michael Cahill (Inactive)
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File block_reads_writes.png     File diagnostic_data.tar.gz     PNG File eviction_blocked.png     PNG File eviction_failed.png     PNG File forcible_eviction.png     PNG File mongostat.png     Text File mongostat.txt     PNG File pages_eviceted_by.png     Text File sharding_status.txt    
Issue Links:
Duplicate
duplicates SERVER-24303 Enable tcmalloc aggressive decommit b... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

Query throughput is decreased temporarily.
And during this issue, eviction failure and hazard pointer eviction blocked counter is excessively increased.

Only query throughput is decreased, not Update and Delete Insert.

insert query update delete getmore command % dirty % used flushes vsize   res  qr|qw   ar|aw netIn netOut conn         set repl                      time
    *0  2115   1337     20     287   778|0     0.3   80.4       0 43.2G 35.5G    3|0    11|2    2m    34m  750 testreplset  PRI 2016-05-02T21:26:28+09:00
    *0  2149   1386     16     290   794|0     0.4   80.9       0 43.2G 35.5G    0|1     0|0    2m    35m  750 testreplset  PRI 2016-05-02T21:26:29+09:00
    *0  1958   1167     13     275   751|0     0.3   80.3       0 43.2G 35.5G    0|0     0|0    1m    31m  750 testreplset  PRI 2016-05-02T21:26:30+09:00
    *0  1931   1253     19     259   548|0     0.5   80.8       0 43.2G 35.5G    0|0     4|1    1m    31m  750 testreplset  PRI 2016-05-02T21:26:31+09:00
    *0  2156   1329     20     279   791|0     0.4   80.8       0 43.2G 35.5G    0|0     0|0    2m    35m  750 testreplset  PRI 2016-05-02T21:26:32+09:00
    *0  2070   1188     13     297   806|0     0.3   80.2       0 43.2G 35.5G    0|0    14|7    1m    33m  750 testreplset  PRI 2016-05-02T21:26:33+09:00
    *0  2095   1299     20     297   761|0     0.5   80.8       1 43.2G 35.5G    0|1    92|2    1m    32m  750 testreplset  PRI 2016-05-02T21:26:34+09:00
    *0  2030   1305     31     304   838|0     0.2   80.7       0 43.2G 35.5G    0|0     1|1    2m    34m  750 testreplset  PRI 2016-05-02T21:26:35+09:00
    *0  2047   1136      9     276   803|0     0.1   80.4       0 43.2G 35.5G    0|0     1|0    1m    33m  750 testreplset  PRI 2016-05-02T21:26:36+09:00
    *0  1477   1310     22     112   331|0     0.1   80.5       0 43.2G 35.5G   72|0  128|35    1m    21m  750 testreplset  PRI 2016-05-02T21:26:37+09:00
    *0  1090   1365     13      31   132|0     0.1   80.1       0 43.2G 35.5G  105|0  128|52  893k    17m  751 testreplset  PRI 2016-05-02T21:26:38+09:00
    *0   969   1205     14      22    92|0     0.1   80.2       0 43.2G 35.5G  106|0  128|44  806k    16m  753 testreplset  PRI 2016-05-02T21:26:39+09:00
    *0   981   1249     15      21    95|0     0.1   80.2       0 43.2G 35.5G  112|0  128|48  814k    16m  755 testreplset  PRI 2016-05-02T21:26:40+09:00
    *0   883   1370     23      22    95|0     0.2   80.4       0 43.2G 35.5G  118|1  128|72  819k    15m  756 testreplset  PRI 2016-05-02T21:26:41+09:00
    *0   780   1123     15      18    75|0     0.1   80.0       0 43.2G 35.5G  117|0  128|44  732k    13m  756 testreplset  PRI 2016-05-02T21:26:42+09:00
    *0   992   1288     21      19    83|0     0.1   80.1       0 43.2G 35.5G  118|0  128|46  833k    16m  758 testreplset  PRI 2016-05-02T21:26:43+09:00
    *0   810   1287     11      21    85|0     0.2   80.4       0 43.2G 35.5G  111|1  128|50  779k    13m  758 testreplset  PRI 2016-05-02T21:26:44+09:00
    *0   885   1177      9      21    93|0     0.2   80.2       0 43.2G 35.5G  116|2  128|31  780k    15m  758 testreplset  PRI 2016-05-02T21:26:45+09:00
    *0   825   1239     20      21    94|0     0.2   80.3       0 43.2G 35.5G  122|0  127|47  770k    14m  759 testreplset  PRI 2016-05-02T21:26:46+09:00
    *0   653   1259     18      19    88|0     0.2   80.2       0 43.2G 35.5G  104|1  128|35  741k    11m  759 testreplset  PRI 2016-05-02T21:26:47+09:00

I am not sure this is related with SERVER-23778.
And I have experienced this issue from patched (https://github.com/mongodb/mongo/pull/1078) mongodb.



 Comments   
Comment by 아나 하리 [ 15/Jun/16 ]

Hi Michael Cahill.

I have not seen this issue after reporting or ignored without knowing.
Anyway If this issue happen again, I will try smaller cache you suggested.

Comment by Michael Cahill (Inactive) [ 15/Jun/16 ]

We have suggested a workaround (smaller cache) until the primary fix in SERVER-24303. matt.lee, please let us know if you have a chance to test with a smaller cache.

Comment by Michael Cahill (Inactive) [ 30/May/16 ]

matt.lee, I have looked more closely at the diagnostic data you attached to this ticket.

Several unfortunate things are going on here. In particular, there is >56GB of dirty data in cache later in the workload, which means checkpoints are taking a very long time to complete. In addition, and more problematic for performance, there is very large amount of memory that has been freed by MongoDB that is not being reused or returned to the operating system (over 44GB peak). This is resulting in paging, leading to poor performance.

We are currently working on general solutions to both of these issues. In the meantime, can you please try running this workload with a smaller cache size. For example:

mongod --wiredTigerCacheGB 30

Please let us know if that improves this workload.

Comment by 아나 하리 [ 03/May/16 ]

Hi Michael Cahill, Alexander Corrod,

>> Configuration used to start mongod
Nothing special in the configuration.

replication:
   oplogSizeMB: 102400
   replSetName: testreplset3
 
storage:
    syncPeriodSecs: 60
    directoryPerDB: true
    dbPath: /data/mongodb
    journal:
        enabled: true
        commitIntervalMs: 100
 
    engine: wiredTiger
 
    wiredTiger:
        engineConfig:
            cacheSizeGB: 40
            journalCompressor: none
            directoryForIndexes: false
        collectionConfig:
            blockCompressor: snappy
        indexConfig:
            prefixCompression: false

>> Whether running in a replication group (if so, whether the issue is specific to the master or slaves)
4 shard and each shard has 3 replica in the set, This issue is happened primary node. (Querys are only requested to primary not secondary)

>> Whether running in a sharded environment
Yes sharded. I attached sharding status. "sharding_status.txt"

>> Can you describe the workload you are running when this issue happens?
Read :

testdb.testcoll.find({pid:?}).sort({guid:-1}).limit(100)


Write :

testdb.testcoll.update({ pid: ?, key: ? }, { $set: { pid: ?, key: ?, guid: ?, ...}, {upsert:true}}


There's only one collection and that collection has 5 indexes

{_id:1},
{pid:hashed},
{pid:1, key:1},
{pid:1, guid:1},
{pid:1, ..}

>> Is there any chance that we can reproduce it locally?
Unfournately, this is real service traffic. So I can't prepare test scenario which reproduce this issue.

MongoDB log file is too big. So I copied head of log file. (And also log file contains our real service data)

2016-04-25T10:53:25.971+0900 I CONTROL  [initandlisten] MongoDB starting : pid=129951 port=27017 dbpath=/data/mongodb 64-bit host=test03-mongo2
2016-04-25T10:53:25.971+0900 I CONTROL  [initandlisten] db version v3.2.5
2016-04-25T10:53:25.971+0900 I CONTROL  [initandlisten] git version: 34e65e5383f7ea1726332cb175b73077ec4a1b02
2016-04-25T10:53:25.971+0900 I CONTROL  [initandlisten] allocator: tcmalloc
2016-04-25T10:53:25.971+0900 I CONTROL  [initandlisten] modules: none
2016-04-25T10:53:25.971+0900 I CONTROL  [initandlisten] build environment:
2016-04-25T10:53:25.971+0900 I CONTROL  [initandlisten]     distarch: x86_64
2016-04-25T10:53:25.971+0900 I CONTROL  [initandlisten]     target_arch: x86_64
2016-04-25T10:53:25.971+0900 I CONTROL  [initandlisten] options: { config: "/etc/mongod.conf", net: { port: 27017 }, operationProfiling: { mode: "slowOp", slowOpThresholdMs: 100 }, processManagement: { fork: true, pidFilePath: "/data/mongodb/mongod.pid" }, replication: { oplogSizeMB: 102400, replSetName: "testreplset3" }, sharding: { clusterRole: "shardsvr" }, storage: { dbPath: "/data/mongodb", directoryPerDB: true, engine: "wiredTiger", journal: { commitIntervalMs: 100, enabled: true }, syncPeriodSecs: 60.0, wiredTiger: { collectionConfig: { blockCompressor: "snappy" }, engineConfig: { cacheSizeGB: 40, directoryForIndexes: false, journalCompressor: "none" }, indexConfig: { prefixCompression: false } } }, systemLog: { destination: "file", logAppend: false, path: "/data/mongodb/mongod.log" } }
2016-04-25T10:53:25.992+0900 W -        [initandlisten] Detected unclean shutdown - /data/mongodb/mongod.lock is not empty.
2016-04-25T10:53:25.992+0900 W STORAGE  [initandlisten] Recovering data from the last clean checkpoint.
2016-04-25T10:53:25.992+0900 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=40G,session_max=20000,eviction=(threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=none),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),

And during the issue, there's no something special in the log file except a few finding split vector message.

2016-05-02T21:20:07.307+0900 W SHARDING [conn47385] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 22871 took 166ms
2016-05-02T21:22:09.698+0900 W SHARDING [conn47385] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 31714 took 103ms
2016-05-02T21:22:33.966+0900 W SHARDING [conn47369] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 34239 took 105ms
2016-05-02T21:23:27.379+0900 W SHARDING [conn47369] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 29688 took 120ms
2016-05-02T21:27:37.989+0900 W SHARDING [conn47475] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 45094 took 4485ms
2016-05-02T21:27:38.529+0900 W SHARDING [conn47476] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 45094 took 4718ms
2016-05-02T21:28:14.707+0900 W SHARDING [conn47492] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 117 took 9617ms
2016-05-02T21:28:15.041+0900 W SHARDING [conn47496] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 117 took 4877ms
2016-05-02T21:28:19.681+0900 W SHARDING [conn47499] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 20872 took 3382ms
2016-05-02T21:28:19.879+0900 W SHARDING [conn47369] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 20872 took 8743ms
2016-05-02T21:29:26.750+0900 W SHARDING [conn47521] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 49862 took 10096ms
2016-05-02T21:29:26.858+0900 W SHARDING [conn47523] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 49863 took 3678ms
2016-05-02T21:29:28.758+0900 W SHARDING [conn47524] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 49863 took 3113ms
2016-05-02T21:29:44.800+0900 W SHARDING [conn47496] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 41594 took 8938ms
2016-05-02T21:29:44.809+0900 W SHARDING [conn47492] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 41594 took 7376ms
2016-05-02T21:29:53.196+0900 W SHARDING [conn47476] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 51153 took 11125ms
2016-05-02T21:29:53.633+0900 W SHARDING [conn47475] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 51154 took 3709ms
2016-05-02T21:29:54.270+0900 W SHARDING [conn47529] Finding the split vector for db.coll over { profile_id: "hashed" } keyCount: 125672 numSplits: 1 lookedAt: 51154 took 3811ms
...

Thanks.
Matt.

<<I changed server name and database collection name instantly, so there's something not matched among log>>

Comment by Alexander Gorrod [ 03/May/16 ]

matt.lee Could you please also upload the mongod log file and describe how you are using MongoDB including:

  • Configuration used to start mongod
  • Whether running in a replication group (if so, whether the issue is specific to the master or slaves)
  • Whether running in a sharded environment
Comment by Michael Cahill (Inactive) [ 03/May/16 ]

matt.lee, thanks for this bug report.

Can you describe the workload you are running when this issue happens? Is there any chance that we can reproduce it locally?

Generated at Thu Feb 08 04:05:09 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.