[SERVER-18888] WiredTiger instances become unresponsive due to ~120 Connections Created: 09/Jun/15  Updated: 07/Apr/23  Resolved: 05/Aug/15

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

Type: Bug Priority: Major - P3
Reporter: Roger Dawson Assignee: Ramon Fernandez Marina
Resolution: Done Votes: 0
Labels: RF
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Windows Server 2012 R2, 7GB RAM


Attachments: File currentop.json     Text File mongo-wiredtigerunresponsive.log    
Issue Links:
Related
Operating System: Windows
Participants:

 Description   

We have a 5 node replica set, running 2 MMAP, 2 WiredTiger and 1 arbiter instance. Upon making WiredTiger a primary our web-server become unresponsive. Further investigation revealed the number of connections had gone from ~25 to 120.

The problem appears to manifest itself when our system is on catch up and thus more heavily loaded that usual. The load is not exceptional though, with only a single threaded service performing multiple reads and writes to MongoDB, and a web-server connecting to MongoDB and performing reads for the most part with only a handful of users.

The MMAP instances do not appear to exhibit this problem.



 Comments   
Comment by Ramon Fernandez Marina [ 05/Aug/15 ]

Thanks for the additional details rogerdawson7, and sorry you run into all this trouble. I'm glad to hear that your new setup with Linux and MMAPv1 is stable and performance is meeting your needs.

I understand you may not be able to spend more time on testing WiredTiger at the moment, so I'm going to close this ticket for now. Please note that we're actively working to fix some open issues related to WiredTiger memory consumption in 3.0.5, so whenever you resume your testing I'd recommend you use version 3.0.6 or newer – and I think it will be better to open new tickets as necessary.

Thanks,
Ramón.

Comment by Roger Dawson [ 04/Aug/15 ]

Hi Ramon,

as this problem, and others such as large background flush times in Windows on MMAP machines, were affecting our production system we had to resolve the issue quickly so we switched our database over to a 3 member Linux replica set all running MMAP. We will definitely give Wired Tiger another go on our production system, although I'm not sure how soon this will be as we lost a few man weeks trying to make our system stable which has caused other timescales to slip. Our test system is Wired Tiger still, albeit standalone, but it did occasionally exhibit the issue so I'll upgrade it to 3.0.5 and see how it performs.

Overall we had a few issues, recently, some down to our usage which we have improved and others seemingly related to Azure VM's (high disk latency), write concurrency on Windows and/or WiredTiger issues which when combined didn't make for a very stable system. Since switching to the Linux MMAP replica set performance is greatly improved as is stability. Regarding this ticket, I'll leave it up to you whether you wish to mark as closed or leave until we can give WiredTiger another try, but this will be weeks away.

Many Thanks,

Roger

Comment by Ramon Fernandez Marina [ 03/Aug/15 ]

Hi rogerdawson7. I was looking at this ticket again, and our suspicion is that the number of connections is a symptom of the problem, not the cause. We've been working on a number of WiredTiger concurrency issues which could account for this behavior (120 is the number of WT threads we allow), and there's also SERVER-12401 (background flush improvements on Windows). While the latter hasn't been addressed yet, MongoDB 3.0.4 and 3.0.5 do have a number of WiredTiger improvements – specially on oplog-handling issues, which should help with replication problems like the ones you described. Have you had a chance to try 3.0.5?

Also you do mention MMS, but I couldn't find a deployment that matches your description. I'll be happy to take a closer look at the MMS data if this is still an issue for you (feel free to email me the link directly if you don't want it displayed in this ticket). Is there any more data you can share with us about the state of your system that can help us move this ticket forward?

Thanks,
Ramón.

Comment by Roger Dawson [ 22/Jun/15 ]

Hello Sam,

the Wired Tiger secondary has locked up again. I tried to export some data and noticed it was unresponsive. After looking at MMS I can see the number of connections has been progressively ramping up. Presumably my export was unresponsive as we have secondary preferred and its unfortunately picked the wired tiger node to read off. Going by our websites session information there are only 3 users on the website at the moment so it's not heavily loaded. I've attached the current operation as per you suggested last week.

Many Thanks,

Roger

Comment by Roger Dawson [ 17/Jun/15 ]

Hi Sam,

the down replica set member is only recent, and this was not the case when this problem began occurring. It's even happened on our standalone test server.

The problem generally occurs (but not always) when the system is under a heavier than usual load i.e. on startup when processing queued messages and performing a lot of reads. Surely even if MongoDB was being saturated with requests it should still handle this scenario gracefully either through throttling or just naturally. At the end of the day we have a single processing thread, performing non-async calls on MongoDB, and even that thread is self-limiting due to other, non-MongoDB, blocking calls that can take 10's of milliseconds. The website makes very little demand on the server as there are very few users and historical data is only occasionally viewed. Our intention in the near future is to perform asynchronous operations in multiple threads but we're not sure we can use MongoDB for this if it is beginning to lock-up with only a single thread. Slow we can accept, but locked up for 30 minutes we cannot. Furthermore, the most recent lock-up was when it was running as a secondary and not on catch-up.

Many Thanks,

Roger

Comment by Sam Kleinman (Inactive) [ 17/Jun/15 ]

I think there are a few issues that are responsible for the performance issues you're seeing.

  1. The "down" replica set member is probably responsible for some of overhead as members are waiting for heartbeats and status calls that will never return and must hit timeouts. For example, it looks like determining the state of the replica set represents the bulk of the time during the serverStatus operation. If you've removed a member from your replica set for a long-period of time, it might make more sense to remove it from the configuration, and add it back later when it becomes available.
  2. The slow queries and write operations are likely attributable to the use of indexes by your application and the avalible throughput of your underlying storage system. In particular, using a more responsive storage system will allow you to reduce the background flush times.

We do not think that there is an underlying bug with MongoDB described here. While the performance issue you're experiencing seem quite frustrating, the SERVER project is for tracking bugs and feature requests and you may able to find more appropriate support by addressing one of our support channels. For MongoDB-related support discussion please post on the mongodb-users group or Stack Overflow with the mongodb tag.

Regards,
sam

Comment by Roger Dawson [ 15/Jun/15 ]

Hello Ramon, Eliot,

we're still having problems with our WiredTiger member. Today it was running as a secondary and has a single member replicating off it and it just stopped functioning for an hour or so. I've attached a stripped down version of the log file with information around when the unresponsiveness occurred. The 'Failed to connect to 10.0.1.71' messages are referring to one of our members that is down currently. There seem to be quite a few connection errors followed by server status messages stating times in the 10's of minutes which I guess is not a good sign.

We're still trying to improve performance on this system via improving queries and starting new collections for our raw data but the background flush is still high, even when there is very little activity. This is a separate issue though that we are still investigating.

Possibly unrelated but we do seem to be getting a lot of listCollection commands on our primary, probably every 7 seconds on average, and they are indicating times of 600-1100ms. We're not sure what is generating these commands, it should certainly not be anything in our code, we are wondering if it is MMS but we don't understand why it would be doing this so frequently. I've shown a log of one below:

2015-06-15T15:23:49.502+0000 I COMMAND [conn54001] command OurCustomerDBV3.$cmd command: listCollections { $query:

{ listCollections: 1 }

} keyUpdates:0 writeConflicts:0 numYields:0 reslen:70221 locks:{ Global: { acquireCount:

{ r: 1 }

}, MMAPV1Journal: { acquireCount:

{ r: 1 }

}, Database: { acquireCount:

{ R: 1 }

} } 1068ms

Thanks

Comment by Roger Dawson [ 15/Jun/15 ]

Log following WiredTiger member becoming unresponsive

Comment by Roger Dawson [ 12/Jun/15 ]

Hi Ramon, Eliot,

since the last time this occurred we made improvements to some of our queries so the startup loading of our system is not as bad (10 fold improvement as we weren't using the indexed fields correctly when querying). Last time we restarted the system the unresponsiveness didn't occur so we haven't got any meaningful log information to give you at the moment.

However, we have noticed some other aspects that might not be helping i.e. MMAP is showing average background flush times in the region of 20 seconds which we understand to be undesirable. Looking at this historically the value used to be a few seconds at most a year ago but MMS is showing what looks to be an exponential rise over the past 2 or 3 months to where we are now. Further investigation has shown we probably have 100+ collections in the region of 1GB in size with index sizes of roughly a quarter of the overall size that are each updated with busts of records every few minutes. We are starting to think the index writes could be part of the problem (one is on _id and another is a compound index on an int and a time field). In particular we think the compound index might be problematic because the time is not the first parameter so it won't be stored in time ascending order. Our proposed solution to all this will be to start new collections for our log data to decrease the load caused by updating the indexes. Long-term our method of storing data will be different, perhaps by splitting collections based on time ranges or some other mechanism (undecided).

Overall, I'm not sure where this leaves us - we'd like to use WiredTiger because it seems to give us much better performance but we can't afford the possibility of the unresponsiveness at the moment and the other issue we seem to have (see https://jira.mongodb.org/browse/SERVER-18887). However, our existing architecture might not have been helping so we are trying to make it more favourable to the way MongoDB operates.

I haven't tried your suggestions yet (db.adminCommand) as the problem hasn't manifested itself since.

Do you think our conclusions as to what might be causing this problem are correct? Have you any other recommendations other than those above based on this new information?

Many Thanks,

Roger

Comment by Ramon Fernandez Marina [ 10/Jun/15 ]

rogerdawson7, do you happen to have logs for the unresponsive primary when you observed this issue? If you do, could you please compress them and upload them to the ticket? Perhaps there some information that can help us understand what happened.

Thanks,
Ramón.

Comment by Roger Dawson [ 10/Jun/15 ]

Hi Eliot,

the problem has occurred on a 4 core wiredTiger server with 7GB RAM and a 2 core mmapv1 machine with 3.5GB, all running in Azure VMs.

Reproducing it is tricky as this is on our production server and it's only when under heavier than usual loading. It's done it a couple of times today, once after it had finished catching up a server that was 24 hours behind and again when our service restarted (which results in a lot of reads). Our web-site/server again seemed to be the culprit with regards to where all the TCP connections were going although it wasn't really be used much at the time. I'll see what we can do to try and repeat the problem (it might take 48 hours to get you the results as I have to notify customers of potential down-time/reduced service). During the problem with the connections the number of queues also appeared to spike, albeit shorter duration, and the op counter dropped to nothing. I will also try performing the settings you mention, assuming I can get a connection using the mongo shell. Ditto the db.currentOp.

Thanks for looking into this,

Roger

Comment by Eliot Horowitz (Inactive) [ 10/Jun/15 ]

How many cores do you have?
Are you easily able to reproduce this?

If so, is it possible get a db.currentOp() snapshot when this happens?

Also, you could try this when it happens to see if it resolves which would help narrow down the issue:

db.adminCommand( { setParameter: 1, wiredTigerConcurrentWriteTransactions: 256 } )
db.adminCommand( { setParameter: 1, wiredTigerConcurrentReadTransactions: 256 } )

If you have < 16 cores, could also try

db.adminCommand( { setParameter: 1, wiredTigerConcurrentWriteTransactions: 11 } )
db.adminCommand( { setParameter: 1, wiredTigerConcurrentReadTransactions: 11 } )

Comment by Roger Dawson [ 09/Jun/15 ]

Sorry, clicked Create too early when generating the issue. The version affected appear to be 3.0.3 for sure. I looked at the open connections on the MongoDB WiredTiger primary that exhibited the problem and it had numerous connections to the webserver (~70), and about 5-10 to each replica set node. Shutting down the webserver did not release the TCP/IP connections, at least not on every occasion. I did also observe similar problems with our test system which runs a single standalone instance of MongoDB running WiredTiger.

This problem is a showstopper for us as it is preventing us from switching to WiredTiger which appears to offer significantly better performance than MMAP for us. We are starting to experience long startup times with MMAP (as we perform a lots of reads on historical data) as our database size is growing (~280GB).

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