Recently I run several times into trouble with mongodb that exhausted my system. The database is tiny, after a mongodump, all files together weight 248KB.
After some hours uptime it happens that the machine is not accessible anymore, i.e. no responses to HTTP-Request, neither to SSH. The AWS console shows not more than a CPU peak up to 80%, status is still running, status checks are 2/2 OK. Nodetime shows that memory usage and CPU load arose sharply before the outage. As I could not interact at all with the machine, the only possibility I had was to stop/start the instance.
Configuration/environment info
- Ubuntu 14/04
- MongoDB: v2.4.12 from mongodb-10gen
- smallfiles=true
- no swap configured
- AWS t2.micro (1GB RAM) -> should be enough for that amount of data, isn't it?
- NUMA: I have not found any information whether the t2.micro has NUMA or not, dmesg did not show any NUMA hints. (http://docs.mongodb.org/manual/administration/production-notes/#mongodb-and-numa-hardware)
MongoDB logs
The following logs are generated before the machine is not responsible. As you see, the mongodb was started the evening before and not touched until mongodb started to cleanup things. What looks weired for me is the increase of time and seemingly endless repetition of flushing mmaps.
Thu Apr 16 21:40:54.423 [initandlisten] connection accepted from 127.0.0.1:57803 #591 (1 connection now open)
Thu Apr 16 21:40:54.430 [initandlisten] connection accepted from 127.0.0.1:57804 #592 (2 connections now open)
Thu Apr 16 21:40:54.431 [initandlisten] connection accepted from 127.0.0.1:57805 #593 (3 connections now open)
Thu Apr 16 21:40:54.432 [initandlisten] connection accepted from 127.0.0.1:57806 #594 (4 connections now open)
Thu Apr 16 21:40:54.432 [initandlisten] connection accepted from 127.0.0.1:57807 #595 (5 connections now open)
Thu Apr 16 21:40:54.439 [initandlisten] connection accepted from 127.0.0.1:57809 #596 (6 connections now open)
Thu Apr 16 21:40:54.482 [initandlisten] connection accepted from 127.0.0.1:57810 #597 (7 connections now open)
Thu Apr 16 21:40:54.486 [initandlisten] connection accepted from 127.0.0.1:57811 #598 (8 connections now open)
Thu Apr 16 21:40:54.491 [initandlisten] connection accepted from 127.0.0.1:57812 #599 (9 connections now open)
Thu Apr 16 21:40:54.495 [initandlisten] connection accepted from 127.0.0.1:57813 #600 (10 connections now open)
Fri Apr 17 06:35:25.591 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 14ms
Fri Apr 17 06:35:30.485 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:1711221 nreturned:0 reslen:20 1955ms
Fri Apr 17 06:35:33.461 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:2426135 nreturned:0 reslen:20 1419ms
Fri Apr 17 06:36:26.380 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 13ms
Fri Apr 17 06:36:26.780 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 41ms
Fri Apr 17 06:36:27.175 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 12ms
Fri Apr 17 06:36:38.790 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:3022685 nreturned:0 reslen:20 2917ms
Fri Apr 17 06:36:41.366 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:2791677 nreturned:0 reslen:20 1708ms
Fri Apr 17 06:37:27.700 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 7ms
Fri Apr 17 06:37:28.179 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 12ms
Fri Apr 17 06:37:28.725 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 11ms
Fri Apr 17 06:37:44.266 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:1470008 nreturned:0 reslen:20 1600ms
Fri Apr 17 06:37:46.109 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:1500357 nreturned:0 reslen:20 888ms
Fri Apr 17 06:38:29.235 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 13ms
Fri Apr 17 06:38:29.868 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 9ms
Fri Apr 17 06:38:30.068 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 5ms
Fri Apr 17 06:38:50.172 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:2414304 nreturned:0 reslen:20 2288ms
Fri Apr 17 06:38:53.425 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:3355767 nreturned:0 reslen:20 2166ms
Fri Apr 17 06:39:30.664 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 12ms
Fri Apr 17 06:39:31.187 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 4ms
Fri Apr 17 06:39:32.122 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 7ms
Fri Apr 17 06:39:58.331 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:2569707 nreturned:0 reslen:20 2484ms
Fri Apr 17 06:40:01.482 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:2260314 nreturned:0 reslen:20 1635ms
Fri Apr 17 06:40:33.047 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 4ms
Fri Apr 17 06:40:33.566 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 13ms
Fri Apr 17 06:40:34.118 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 12ms
Fri Apr 17 06:41:06.837 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:2129736 nreturned:0 reslen:20 2200ms
Fri Apr 17 06:41:13.809 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:7635962 nreturned:0 reslen:20 4436ms
Fri Apr 17 06:41:34.366 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 30ms
Fri Apr 17 06:41:34.753 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 13ms
Fri Apr 17 06:41:35.621 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 11ms
Fri Apr 17 06:42:18.303 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:2653563 nreturned:0 reslen:20 2667ms
Fri Apr 17 06:42:23.794 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:4669211 nreturned:0 reslen:20 3391ms
Fri Apr 17 06:42:36.134 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 4ms
Fri Apr 17 06:42:37.043 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 12ms
Fri Apr 17 06:42:37.827 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 13ms
Fri Apr 17 06:43:26.136 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:1126718 nreturned:0 reslen:20 1136ms
Fri Apr 17 06:43:26.963 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 locks(micros) r:152107 nreturned:0 reslen:20 146ms
Fri Apr 17 06:43:38.157 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 12ms
Fri Apr 17 06:43:38.529 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 7ms
Fri Apr 17 06:43:38.565 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 13ms
Fri Apr 17 06:44:31.847 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:1946757 nreturned:0 reslen:20 2097ms
Fri Apr 17 06:44:37.872 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:5141016 nreturned:0 reslen:20 3386ms
Fri Apr 17 06:44:38.639 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 5ms
Fri Apr 17 06:44:39.030 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 49ms
Fri Apr 17 06:45:39.180 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 10ms
Fri Apr 17 06:45:39.576 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 35ms
Fri Apr 17 06:45:39.860 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 22ms
Fri Apr 17 06:45:39.888 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:1097134 nreturned:0 reslen:20 1104ms
Fri Apr 17 06:45:41.629 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 locks(micros) r:1011759 nreturned:0 reslen:20 1033ms
Fri Apr 17 06:46:40.331 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 13ms
Fri Apr 17 06:46:45.733 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:2278078 nreturned:0 reslen:20 2460ms
Fri Apr 17 06:46:50.187 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:4429550 nreturned:0 reslen:20 2636ms
Fri Apr 17 06:47:41.155 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 14ms
Fri Apr 17 06:47:42.153 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 11ms
Fri Apr 17 06:47:55.626 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:3271941 nreturned:0 reslen:20 3337ms
Fri Apr 17 06:47:59.109 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 locks(micros) r:1253524 nreturned:0 reslen:20 1288ms
Fri Apr 17 06:48:42.940 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 7ms
Fri Apr 17 06:48:43.545 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 11ms
Fri Apr 17 06:49:02.613 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:1722689 nreturned:0 reslen:20 1682ms
Fri Apr 17 06:49:04.752 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:1693137 nreturned:0 reslen:20 1222ms
Fri Apr 17 06:49:44.150 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 12ms
Fri Apr 17 06:49:44.284 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 12ms
Fri Apr 17 06:49:44.290 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 5ms
Fri Apr 17 06:50:09.822 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:2438119 nreturned:0 reslen:20 2469ms
Fri Apr 17 06:50:15.615 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:5511859 nreturned:0 reslen:20 3486ms
Fri Apr 17 06:50:45.017 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 6ms
Fri Apr 17 06:50:45.483 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 11ms
Fri Apr 17 06:51:21.221 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:2581407 nreturned:0 reslen:20 2389ms
Fri Apr 17 06:51:25.714 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:4106311 nreturned:0 reslen:20 2362ms
Fri Apr 17 06:51:45.675 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 13ms
Fri Apr 17 06:51:46.066 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 36ms
Fri Apr 17 06:51:46.504 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 24ms
Fri Apr 17 06:52:29.566 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:1637301 nreturned:0 reslen:20 1841ms
Fri Apr 17 06:52:33.587 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 locks(micros) r:2111376 nreturned:0 reslen:20 2145ms
Fri Apr 17 06:52:47.423 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 5ms
Fri Apr 17 06:52:47.994 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 13ms
Fri Apr 17 06:52:48.746 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 40ms
Fri Apr 17 06:53:38.973 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:2888527 nreturned:0 reslen:20 3022ms
Fri Apr 17 06:53:45.142 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:6342327 nreturned:0 reslen:20 3895ms
Fri Apr 17 06:53:49.222 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 12ms
Fri Apr 17 06:53:50.114 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 11ms
Fri Apr 17 06:54:50.181 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:2824385 nreturned:0 reslen:20 2857ms
Fri Apr 17 06:54:50.676 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 6ms
Fri Apr 17 06:54:50.708 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 4ms
Fri Apr 17 06:54:57.179 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 2 locks(micros) r:8006812 nreturned:0 reslen:20 5087ms
Fri Apr 17 06:55:51.217 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 11ms
Fri Apr 17 06:56:02.830 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:3039337 nreturned:0 reslen:20 3048ms
Fri Apr 17 06:56:06.446 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:3686050 nreturned:0 reslen:20 2095ms
Fri Apr 17 06:56:51.898 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 12ms
Fri Apr 17 06:56:52.414 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 5ms
Fri Apr 17 06:57:08.640 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:850728 nreturned:0 reslen:20 891ms
Fri Apr 17 06:57:10.878 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:2299969 nreturned:0 reslen:20 1425ms
Fri Apr 17 06:57:52.972 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 13ms
Fri Apr 17 06:57:53.249 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 4ms
Fri Apr 17 06:58:16.422 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:3148967 nreturned:0 reslen:20 3225ms
Fri Apr 17 06:58:22.201 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 1 locks(micros) r:5783495 nreturned:0 reslen:20 3641ms
Fri Apr 17 07:00:17.208 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 1273ms
Fri Apr 17 07:01:53.749 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 5011ms
Fri Apr 17 07:03:13.542 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 5545ms
Fri Apr 17 07:03:13.542 [DataFileSync] flushing mmaps took 11336ms for 4 files
Fri Apr 17 07:06:27.301 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 1647ms
Fri Apr 17 07:07:33.188 [DataFileSync] flushing mmaps took 25227ms for 4 files
Fri Apr 17 07:08:29.902 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 5469ms
Fri Apr 17 07:10:08.515 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 1684ms
Fri Apr 17 07:10:00.050 [DataFileSync] flushing mmaps took 13659ms for 4 files
Fri Apr 17 07:12:53.600 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 2149ms
Fri Apr 17 07:13:05.344 [DataFileSync] flushing mmaps took 28014ms for 4 files
Fri Apr 17 07:14:08.749 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:468703473 nreturned:0 reslen:20 471988ms
Fri Apr 17 07:14:54.817 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 4052ms
Fri Apr 17 07:17:34.823 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 7439ms
Fri Apr 17 07:20:37.584 [DataFileSync] flushing mmaps took 20461ms for 4 files
Fri Apr 17 07:21:46.760 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 1737ms
Fri Apr 17 07:24:08.300 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 2990ms
Fri Apr 17 07:24:08.300 [DataFileSync] flushing mmaps took 19078ms for 4 files
Fri Apr 17 07:26:16.721 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 2739ms
Fri Apr 17 07:28:47.568 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 964ms
Fri Apr 17 07:31:20.573 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 5701ms
Fri Apr 17 07:32:50.197 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 1746ms
Fri Apr 17 07:33:59.389 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 1368ms
Fri Apr 17 07:35:44.158 [DataFileSync] flushing mmaps took 14481ms for 4 files
Fri Apr 17 07:36:04.368 [TTLMonitor] query recapp.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:8 keyUpdates:0 numYields: 3 locks(micros) r:1292331060 nreturned:0 reslen:20 817257ms
Fri Apr 17 07:36:05.716 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 1154ms
Fri Apr 17 07:36:55.287 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 1049ms
Fri Apr 17 07:38:56.528 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 1845ms
Fri Apr 17 07:41:25.174 [DataFileSync] flushing mmaps took 10397ms for 4 files
Fri Apr 17 07:41:25.174 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 1512ms
Fri Apr 17 07:43:14.455 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 2001ms
Fri Apr 17 07:43:14.455 [DataFileSync] flushing mmaps took 13598ms for 4 files
Fri Apr 17 07:44:43.177 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 1923ms
Fri Apr 17 07:46:52.463 [DataFileSync] flushing mmaps took 12431ms for 4 files
Fri Apr 17 07:47:44.710 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 1794ms
Fri Apr 17 07:49:17.343 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 3740ms
Fri Apr 17 07:49:17.343 [DataFileSync] flushing mmaps took 19263ms for 4 files
Fri Apr 17 07:49:50.800 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:448435774 nreturned:0 reslen:20 446443ms
Fri Apr 17 07:52:06.774 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 1917ms
Fri Apr 17 07:54:05.273 [DataFileSync] flushing mmaps took 27754ms for 4 files
Fri Apr 17 07:55:55.902 [DataFileSync] flushing mmaps took 19278ms for 4 files
Fri Apr 17 07:55:55.902 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 1762ms
Fri Apr 17 07:58:00.151 [PeriodicTask::Runner] task: WriteBackManager::cleaner took: 2425ms
Fri Apr 17 07:59:46.385 [DataFileSync] flushing mmaps took 44356ms for 4 files
Fri Apr 17 08:00:55.381 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 2428ms
Fri Apr 17 08:04:00.837 [DataFileSync] flushing mmaps took 11460ms for 4 files
Fri Apr 17 08:05:08.558 [PeriodicTask::Runner] task: DBConnectionPool-cleaner took: 3343ms
Has anybody faced similar mongodb behaviour patterns? I disabeld TTL already and I am going to install some SWAP space and will report the system reactions. As the database is really small, I think 1GB RAM should be sufficient. All other processes (nginx, 2 small nodes) seem to run normally. Have you suggestions for other monitoring tools? I use:
* nodetime
* AWS mon-scripts for memory (http://docs.aws.amazon.com/AWSEC2/latest/UserGuide/mon-scripts.html)
Thanks for hints and idea sharing.
Best Answer
After eliminating other memory-hungry processes, the machine runs smoothly at the moment. No such log entries like described above are observed. Thanks for pointing out that MongoDB really needs an amount of memory.
Best