[SERVER-20008] Stress test deadlock in WiredTiger Created: 18/Aug/15  Updated: 13/Oct/15  Resolved: 10/Sep/15

Status: Closed
Project: Core Server
Component/s: WiredTiger
Affects Version/s: None
Fix Version/s: 3.0.7, 3.1.8

Type: Bug Priority: Major - P3
Reporter: Eitan Klein Assignee: Michael Cahill (Inactive)
Resolution: Done Votes: 0
Labels: 32qa
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: HTML File 317.html     PNG File Opspersec-duringstress.png     Text File deadlockduringstress.txt     Text File rs3primary.txt     PNG File timeseries-20008.png    
Issue Links:
Depends
is depended on by WT-1973 MongoDB changes for WiredTiger 2.7.0 Closed
Related
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Completed:
Steps To Reproduce:

Insert only workload (hammer.mongo)
--replSet EitanRs3a --dbpath f:\data\db1 --logpath h:\data\rs3primary.txt --storageEngine wiredTiger --port 5002

Participants:

 Description   
Issue Status as of Sep 10, 2015

ISSUE SUMMARY
MongoDB running with the WiredTiger storage engine, under high load with append-only workloads and no reads, may fail to find pages to evict from cache and hang.

USER IMPACT
mongod keeps running but becomes unresponsive.

WORKAROUNDS
Once the process becomes stuck, mongod must be restarted.

AFFECTED VERSIONS
MongoDB 3.0.0 through 3.0.6

FIX VERSION
The fix is included in the 3.0.7 production release.

Configuration:

3 members replica set
db version v3.1.7-pre-
git version: 4cf56d86a386039839dc10bb761bd28c829be426

Two problems:

1) Primary node is up and running but not able to perform any CRUD operations (mongostat and other db. . insert({}) hang), however failover didn't occur.

2) WiredTiger execute endless loop in !__wt_tree_walk and holding CRUD operations w/o timeout/watchdog for robustness (See debugger output for the lock owner)

0:460> !cs -l
-----------------------------------------
DebugInfo          = 0x000000de00a25740
Critical section   = 0x000000de7fc780c0 (+0xDE7FC780C0)
LOCKED
LockCount          = 0x0
WaiterWoken        = No
OwningThread       = 0x000000000000097c
RecursionCount     = 0x1
LockSemaphore      = 0xD8C
SpinCount          = 0x0000000000000fa0
 
  2  Id: 11d4.97c Suspend: 1 Teb: 00007ff7`4fe68000 Unfrozen
Child-SP          RetAddr           Call Site
000000de`01dafc30 00007ff7`51567749 mongod!__wt_tree_walk+0x1a8 [c:\data\mci\src\src\third_party\wiredtiger\src\btree\bt_walk.c @ 243]
000000de`01dafcc0 00007ff7`515672e7 mongod!__evict_walk_file+0x329 [c:\data\mci\src\src\third_party\wiredtiger\src\evict\evict_lru.c @ 1154]
000000de`01dafd60 00007ff7`51566764 mongod!__evict_walk+0x2b7 [c:\data\mci\src\src\third_party\wiredtiger\src\evict\evict_lru.c @ 1032]
000000de`01dafdf0 00007ff7`51566d5b mongod!__evict_lru_walk+0x24 [c:\data\mci\src\src\third_party\wiredtiger\src\evict\evict_lru.c @ 789]
000000de`01dafe20 00007ff7`51566f58 mongod!__evict_pass+0x25b [c:\data\mci\src\src\third_party\wiredtiger\src\evict\evict_lru.c @ 502]
000000de`01dafe80 00007ffb`5e534f7f mongod!__evict_server+0x38 [c:\data\mci\src\src\third_party\wiredtiger\src\evict\evict_lru.c @ 169]
000000de`01dafeb0 00007ffb`5e535126 MSVCR120!beginthreadex+0x107
000000de`01dafee0 00007ffb`6d3f15dd MSVCR120!endthreadex+0x192
000000de`01daff10 00007ffb`6d7343d1 KERNEL32!BaseThreadInitThunk+0xd
000000de`01daff40 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

RS.Status

EitanRs3a:PRIMARY> rs.status()
{
        "set" : "EitanRs3a",
        "date" : ISODate("2015-08-18T14:45:29.611Z"),
        "myState" : 1,
        "term" : NumberLong(0),
        "heartbeatIntervalMillis" : NumberLong(2000),
        "members" : [
                {
                        "_id" : 0,
                        "name" : "eitan5:5002",
                        "health" : 1,
                        "state" : 1,
                        "stateStr" : "PRIMARY",
                        "uptime" : 66715,
                        "optime" : Timestamp(1439894846, 12455),
                        "optimeDate" : ISODate("2015-08-18T10:47:26Z"),
                        "electionTime" : Timestamp(1439842421, 2),
                        "electionDate" : ISODate("2015-08-17T20:13:41Z"),
                        "configVersion" : 3,
                        "self" : true
                },
                {
                        "_id" : 1,
                        "name" : "Eitan1:5002",
                        "health" : 1,
                        "state" : 1,
                        "stateStr" : "PRIMARY",
                        "uptime" : 66704,
                        "optime" : Timestamp(1439894723, 4673),
                        "optimeDate" : ISODate("2015-08-18T10:45:23Z"),
                        "lastHeartbeat" : ISODate("2015-08-18T14:45:29.030Z"),
                        "lastHeartbeatRecv" : ISODate("2015-08-18T14:45:28.841Z"),
                        "pingMs" : 2,
                        "electionTime" : Timestamp(1439906145, 1),
                        "electionDate" : ISODate("2015-08-18T13:55:45Z"),
                        "configVersion" : 3
                },
                {
                        "_id" : 2,
                        "name" : "Eitan6:5002",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 66663,
                        "optime" : Timestamp(1439893521, 7147),
                        "optimeDate" : ISODate("2015-08-18T10:25:21Z"),
                        "lastHeartbeat" : ISODate("2015-08-18T14:45:29.041Z"),
                        "lastHeartbeatRecv" : ISODate("2015-08-18T14:45:28.844Z"),
                        "pingMs" : 1,
                        "syncingTo" : "eitan5:5002",
                        "configVersion" : 3
                }
        ],
        "ok" : 1
}



 Comments   
Comment by Githook User [ 26/Aug/15 ]

Author:

{u'username': u'michaelcahill', u'name': u'Michael Cahill', u'email': u'michael.cahill@mongodb.com'}

Message: SERVER-20008 Acquire the handle list lock when clearing walks to avoid a race with sweep.

(cherry picked from commit 33f5597916964a6b4956bccac15644b0d61bbb36)
Branch: mongodb-3.0
https://github.com/wiredtiger/wiredtiger/commit/0d76fcd0976a55385d68ae5d5d389147f641976b

Comment by Githook User [ 26/Aug/15 ]

Author:

{u'username': u'michaelcahill', u'name': u'Michael Cahill', u'email': u'michael.cahill@mongodb.com'}

Message: SERVER-20008 Acquire the handle list lock when clearing walks to avoid a race with sweep.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/33f5597916964a6b4956bccac15644b0d61bbb36

Comment by Githook User [ 25/Aug/15 ]

Author:

{u'username': u'agorrod', u'name': u'Alex Gorrod', u'email': u'alexander.gorrod@mongodb.com'}

Message: SERVER-20008 Don't reset eviction walks when hitting a busy page.

Merge pull request #2148 from wiredtiger/SERVER-20008

(cherry picked from commit 38dad395053b3eca1998c6c1402adc74fc4cba61)
Branch: mongodb-3.0
https://github.com/wiredtiger/wiredtiger/commit/52feb5b11555f1b9535063388db45d540cf168ea

Comment by Githook User [ 25/Aug/15 ]

Author:

{u'username': u'agorrod', u'name': u'Alex Gorrod', u'email': u'alexander.gorrod@mongodb.com'}

Message: SERVER-20008 Don't reset eviction walks when hitting a busy page.

Merge pull request #2148 from wiredtiger/SERVER-20008

(cherry picked from commit 38dad395053b3eca1998c6c1402adc74fc4cba61)
Branch: mongodb-3.0
https://github.com/wiredtiger/wiredtiger/commit/52feb5b11555f1b9535063388db45d540cf168ea

Comment by Githook User [ 25/Aug/15 ]

Author:

{u'username': u'agorrod', u'name': u'Alex Gorrod', u'email': u'alexander.gorrod@mongodb.com'}

Message: Merge pull request #2148 from wiredtiger/SERVER-20008

SERVER-20008 Don't reset eviction walks when hitting a busy page.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/38dad395053b3eca1998c6c1402adc74fc4cba61

Comment by Githook User [ 25/Aug/15 ]

Author:

{u'username': u'agorrod', u'name': u'Alex Gorrod', u'email': u'alexander.gorrod@mongodb.com'}

Message: Merge pull request #2148 from wiredtiger/SERVER-20008

SERVER-20008 Don't reset eviction walks when hitting a busy page.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/38dad395053b3eca1998c6c1402adc74fc4cba61

Comment by Githook User [ 25/Aug/15 ]

Author:

{u'username': u'michaelcahill', u'name': u'Michael Cahill', u'email': u'michael.cahill@mongodb.com'}

Message: SERVER-20008 Don't fail if stepping past the last page in a file.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/0719dbad7dcc0cd21edba1e4f783eee82fe18909

Comment by Githook User [ 25/Aug/15 ]

Author:

{u'username': u'michaelcahill', u'name': u'Michael Cahill', u'email': u'michael.cahill@mongodb.com'}

Message: SERVER-20008 Don't reset eviction walks when hitting a busy page.

Also, when clearing eviction walk points before the eviction server goes to sleep, clear all walks, not just ones that sessions are waiting to be have cleared.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/e796ca9280b7b763dc3ec48af8d8a5dc0c7a4c33

Comment by Eitan Klein [ 25/Aug/15 ]

michael.cahill
I observed this twice, not likely to reproduce per our request, Is it a regression? Any idea , Why it has been seen before?

Comment by Michael Cahill (Inactive) [ 25/Aug/15 ]

I spent more time stepping through the eviction thread – it appears to be stuck considering a very small set of candidate pages, none of which can actually be evicted. I'm still looking today but I have some ideas about where to look...

eitan.klein, how reproducible is this? If I had a patch build to test, would it be easy to tell whether the problem is fixed?

Comment by Michael Cahill (Inactive) [ 24/Aug/15 ]

eitan.klein, I have spent some time stepping through the process in a debugger. It hasn't hung, as far as I can tell: there is a checkpoint in progress that seems to be taking a long time. How long was the process in this state before you attached the debugger?

Comment by Michael Cahill (Inactive) [ 24/Aug/15 ]

eitan.klein, thanks for the timeseries HTML, I have taken a look and there is something interesting going on. In future, if you could just attach the server status log file, that would be great: there are many command-line options to bruce.lucas@10gen.com's timeseries tool (including restricting the range for graphing) that can help a lot in seeing the detail.

Here is some analysis of the timeseries data:

As you can see from the marked timestamps, every 90 minutes something is causing a spike in activity. The hang occurred during one such spike. At these times, a checkpoint takes much longer than usual (up to 20 seconds instead of ~5). One possible explanation would be some periodic activity on the machine (e.g., backups). Do you know of anything that happens every 90 minutes?

In terms of the hang itself, something has gone wrong with eviction. The eviction thread is not finding pages to add to the eviction queue, and consequently application operations are blocked because there is no free space in the cache. I have attached to the debugger, I'll see if I can see what is going wrong.

Comment by Michael Cahill (Inactive) [ 19/Aug/15 ]

eitan.klein, it is normal for the eviction thread to spend a lot of time walking files looking for pages to evict, so that stack doesn't help find the source of the problem.

Can you please gather server status in the usual way while the test is running:

mongo --eval "while(true) {print(JSON.stringify(db.serverStatus({tcmalloc:1}))); sleep(10000)}" > ss.log

That is the best starting point for analysing what is going on.

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