MongoDB Log Analysis – Understanding COMMAND [PeriodicTaskRunner] UnusedLockCleaner

lockinglogmongodbmongodb-3.2scheduled-tasks

With mloginfo I found a strange log entry. Didn't find anything about it in MongoDB docs and other related sites.

$ mloginfo mongodb.log  --distinct
     source: mongodb.log
       host: example
      start: 2016 Aug 25 14:57:57.630
        end: 2016 Aug 26 08:02:05.751
date format: iso8601-local
     length: 572308
     binary: mongod
    version: 3.2.8
    storage: wiredTiger

DISTINCT

   28069    connection accepted from ... # ... ( ... now open)
   27587    end connection ... ( ... now open)
      15    exception: ... on:
      10    serverStatus was very slow:
       4    task: ... took: ... ms
       3    killcursors: found ... of
       3    SocketException handling request, closing client connection:
       1    git version:
       1    waiting for connections on port

what is that exactly? What is a PeriodicTaskRunner and what does UnusedLockCleaner do? Any actions required from DBA?

2016-08-25T21:03:38.449+0200 I COMMAND  [PeriodicTaskRunner] task: UnusedLockCleaner took: 105ms
2016-08-26T00:21:40.285+0200 I COMMAND  [PeriodicTaskRunner] task: UnusedLockCleaner took: 184ms
2016-08-26T01:25:40.940+0200 I COMMAND  [PeriodicTaskRunner] task: UnusedLockCleaner took: 273ms
2016-08-26T01:55:41.357+0200 I COMMAND  [PeriodicTaskRunner] task: UnusedLockCleaner took: 234ms

Best Answer

The nice part about MongoDB is that it is open source, so your answer is in the code, starting with comments about UnusedLockCleaner:

Periodically purges unused lock buckets. The first time the lock is used again after cleanup it needs to be allocated, and similarly, every first use by a client for an intent mode may need to create a partitioned lock head. Cleanup is done roughtly once a minute.

Then taking a look at the lock_manager code we get more info about the cleanup function:

Iterates through all buckets and deletes all locks, which have no requests on them. This call is kind of expensive and should only be used for reducing the memory footprint of the lock manager.

Basically it looks like some background maintenance being done by the database to clear out unused locks and keep the memory usage of the lock manager under control. Nothing to be concerned about, since if the database is busy and the locks are in use they won't be cleaned up. If you are seeing (reproducible) issues with it, then it would be best to open a ticket to debug with the developers, since this would not be intended.

Related Question