Info

We just had a mongod crash after seeing this logged. We use sharding and replication. 2017-07-31T04:29:57.670+0000 E STORAGE [conn38291] WiredTiger (12) [1501475397:670620][1176:0x7fcb5f447700], WT_CONNECTION.open_session: only configured to support 20020 sessions (including 20 additional internal sessions): Cannot allocate memory 2017-07-31T04:29:57.670+0000 E STORAGE [conn31681] WiredTiger (12) [1501475397:670839][1176:0x7fccd90cc700], WT_CONNECTION.open_session: only configured to support 20020 sessions (including 20 additional internal sessions): Cannot allocate memory 2017-07-31T04:29:57.670+0000 E STORAGE [conn34966] WiredTiger (12) [1501475397:670984][1176:0x7fcc21259700], WT_CONNECTION.open_session: only configured to support 20020 sessions (including 20 additional internal sessions): Cannot allocate memory 2017-07-31T04:29:57.682+0000 E STORAGE [conn35450] WiredTiger (12) [1501475397:682359][1176:0x7fcef4660700], WT_CONNECTION.open_session: only configured to support 20020 sessions (including 20 additional internal sessions): Cannot allocate memory 2017-07-31T04:29:57.695+0000 E STORAGE [WTJournalFlusher] WiredTiger (12) [1501475397:695320][1176:0x7fd1676a8700], WT_CONNECTION.open_session: only configured to support 20020 sessions (including 20 additional internal sessions): Cannot allocate memory 2017-07-31T04:29:57.715+0000 E STORAGE [conn20441] WiredTiger (12) [1501475397:715160][1176:0x7fcf63c4f700], WT_CONNECTION.open_session: only configured to support 20020 sessions (including 20 additional internal sessions): Cannot allocate memory 2017-07-31T04:29:57.737+0000 E STORAGE [conn11932] WiredTiger (12) [1501475397:737176][1176:0x7fd12372e700], WT_CONNECTION.open_session: only configured to support 20020 sessions (including 20 additional internal sessions): Cannot allocate memory 2017-07-31T04:29:57.787+0000 I - [conn38291] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: 12: Cannot allocate memory at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 54 2017-07-31T04:29:57.787+0000 I - [conn11932] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: 12: Cannot allocate memory at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 54 2017-07-31T04:29:57.787+0000 I - [conn31681] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: 12: Cannot allocate memory at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 54 2017-07-31T04:29:57.788+0000 I - [conn34966] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: 12: Cannot allocate memory at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 54 2017-07-31T04:29:57.787+0000 I - [conn20441] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: 12: Cannot allocate memory at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 54 2017-07-31T04:29:57.788+0000 I - [WTJournalFlusher] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: 12: Cannot allocate memory at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 54 2017-07-31T04:29:57.788+0000 I - [conn35450] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: 12: Cannot allocate memory at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 54 2017-07-31T04:29:57.821+0000 E STORAGE [conn31327] WiredTiger (12) [1501475397:821140][1176:0x7fcceda14700], WT_CONNECTION.open_session: only configured to support 20020 sessions (including 20 additional internal sessions): Cannot allocate memory 2017-07-31T04:29:57.821+0000 I - [conn31327] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: 12: Cannot allocate memory at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 54 2017-07-31T04:29:57.827+0000 E STORAGE [conn33938] WiredTiger (12) [1501475397:827764][1176:0x7fcc58fd3700], WT_CONNECTION.open_session: only configured to support 20020 sessions (including 20 additional internal sessions): Cannot allocate memory 2017-07-31T04:29:57.827+0000 I - [conn33938] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: 12: Cannot allocate memory at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 54 2017-07-31T04:29:57.835+0000 E STORAGE [conn37020] WiredTiger (12) [1501475397:835110][1176:0x7fcbaa7f6700], WT_CONNECTION.open_session: only configured to support 20020 sessions (including 20 additional internal sessions): Cannot allocate memory 2017-07-31T04:29:57.835+0000 I - [conn37020] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: 12: Cannot allocate memory at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 54 2017-07-31T04:29:57.864+0000 E STORAGE [conn11921] WiredTiger (12) [1501475397:864452][1176:0x7fd124239700], WT_CONNECTION.open_session: only configured to support 20020 sessions (including 20 additional internal sessions): Cannot allocate memory 2017-07-31T04:29:57.864+0000 I - [conn11921] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: 12: Cannot allocate memory at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 54 2017-07-31T04:29:57.901+0000 E STORAGE [conn36886] WiredTiger (12) [1501475397:901889][1176:0x7fcbb2b79700], WT_CONNECTION.open_session: only configured to support 20020 sessions (including 20 additional internal sessions): Cannot allocate memory 2017-07-31T04:29:57.901+0000 I - [conn36886] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: 12: Cannot allocate memory at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 54 2017-07-31T04:29:57.926+0000 E STORAGE [conn37963] WiredTiger (12) [1501475397:926271][1176:0x7fcb72779700], WT_CONNECTION.open_session: only configured to support 20020 sessions (including 20 additional internal sessions): Cannot allocate memory 2017-07-31T04:29:57.926+0000 I - [conn37963] Invariant failure: conn->open_session(conn, NULL, "isolation=snapshot", &_session) resulted in status UnknownError: 12: Cannot allocate memory at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 54 2017-07-31T04:29:57.971+0000 I CONTROL [WTJournalFlusher] 0x1556b32 0x14ee2a4 0x14d4d53 0x126e8fb 0x126f665 0x126fd46 0x125aba3 0x14d7b77 0x1d00200 0x7fd16ca846ba 0x7fd16c7ba3dd ----- BEGIN BACKTRACE ----- {"backtrace":[{"b":"400000","o":"1156B32","s":"_ZN5mongo15printStackTraceERSo"},{"b":"400000","o":"10EE2A4","s":"_ZN5mongo10logContextEPKc"},{"b":"400000","o":"10D4D53","s":"_ZN5mongo17invariantOKFailedEPKcRKNS_6StatusES1_j"},{"b":"400000","o":"E6E8FB","s":"_ZN5mongo17WiredTigerSessionC1EP15__wt_connectionmm"},{"b":"400000","o":"E6F665","s":"_ZN5mongo22WiredTigerSessionCache10getSessionEv"},{"b":"400000","o":"E6FD46","s":"_ZN5mongo22WiredTigerSessionCache16waitUntilDurableEb"},{"b":"400000","o":"E5ABA3","s":"_ZN5mongo18WiredTigerKVEngine24WiredTigerJournalFlusher3runEv"},{"b":"400000","o":"10D7B77","s":"_ZN5mongo13BackgroundJob7jobBodyEv"},{"b":"400000","o":"1900200"},{"b":"7FD16CA7D000","o":"76BA"},{"b":"7FD16C6B3000","o":"1073DD","s":"clone"}],"processInfo":{ "mongodbVersion" : "3.2.16", "gitVersion" : "056bf45128114e44c5358c7a8776fb582363e094", "compiledModules" : [], "uname" : { "sysname" : "Linux", "release" : "4.4.0-87-generic", "version" : "#110-Ubuntu SMP Tue Jul 18 12:55:35 UTC 2017", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000", "buildId" : "B4C77D1B42936B23E28A2739927CB25274DB2D96" }, { "b" : "7FFC92910000", "elfType" : 3, "buildId" : "D4057BD712DABB1A8B5F4666C1CA1CD47E70FBA1" }, { "b" : "7FD16DA09000", "path" : "/lib/x86_64-linux-gnu/libssl.so.1.0.0", "elfType" : 3, "buildId" : "675F454AD6FD0B6CA2E41127C7B98079DA37F7B6" }, { "b" : "7FD16D5C5000", "path" : "/lib/x86_64-linux-gnu/libcrypto.so.1.0.0", "elfType" : 3, "buildId" : "2DA08A7E5BF610030DD33B70DB951399626B7496" }, { "b" : "7FD16D3BD000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3, "buildId" : "F951C1E0765FCAE48F82CAFE35D1ADD36D6C9AF9" }, { "b" : "7FD16D1B9000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3, "buildId" : "0FC788F0861846257B5F1773FBD438E95DFC1032" }, { "b" : "7FD16CEB0000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3, "buildId" : "FF7A33D389E756CA381A8189291A968EA5E1F4F8" }, { "b" : "7FD16CC9A000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3, "buildId" : "68220AE2C65D65C1B6AAA12FA6765A6EC2F5F434" }, { "b" : "7FD16CA7D000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3, "buildId" : "27F189EF8DB8C3734C6A678E6EF3CB0B206D58B2" }, { "b" : "7FD16C6B3000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3, "buildId" : "088A6E00A1814622219F346B41E775B8DD46C518" }, { "b" : "7FD16DC72000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "9157F205547F0EB588E2AB1F2F120B74253A43EA" } ] }} mongod(_ZN5mongo15printStackTraceERSo+0x32) [0x1556b32] mongod(_ZN5mongo10logContextEPKc+0x174) [0x14ee2a4] mongod(_ZN5mongo17invariantOKFailedEPKcRKNS_6StatusES1_j+0xF3) [0x14d4d53] mongod(_ZN5mongo17WiredTigerSessionC1EP15__wt_connectionmm+0x9B) [0x126e8fb] mongod(_ZN5mongo22WiredTigerSessionCache10getSessionEv+0xD5) [0x126f665] mongod(_ZN5mongo22WiredTigerSessionCache16waitUntilDurableEb+0x2F6) [0x126fd46] mongod(_ZN5mongo18WiredTigerKVEngine24WiredTigerJournalFlusher3runEv+0xB3) [0x125aba3] mongod(_ZN5mongo13BackgroundJob7jobBodyEv+0x1B7) [0x14d7b77] mongod(+0x1900200) [0x1d00200] libpthread.so.0(+0x76BA) [0x7fd16ca846ba] libc.so.6(clone+0x6D) [0x7fd16c7ba3dd] ----- END BACKTRACE ----- 2017-07-31T04:29:57.975+0000 I - [WTJournalFlusher] ***aborting after invariant() failure

Top User Comments

dmitry.agranat commented on Tue, 8 Aug 2017 07:44:20 +0000: Thanks for reporting this behavior tch@virtall.com We are aware that the system was overloaded at the time of crash. Still, in our opinion, it shouldn't cause mongod crash (especially that there was no OOM-killer). We are working on improving this in SERVER-30462. Please feel free to vote and watch SERVER-30462 for updates. Kind Regards, Dima tch@virtall.com commented on Mon, 7 Aug 2017 02:47:23 +0000: Thanks for your analysis. To clarify: "at 04:33 the server was stopped". It wasn't stopped by system administrator. It crashed, as initial log shows. We are aware that the system was overloaded at the time of crash. Still, in our opinion, it shouldn't cause mongod crash (especially that there was no OOM-killer). dmitry.agranat commented on Sun, 6 Aug 2017 12:11:20 +0000: Thank you for the clarification tch@virtall.com. Here is the analysis of the event: Summary: Due to a shift in the workload to a different part of the dataset that is not in FS cache, most of the reads are done directly from the disk and disk becomes the bottleneck. This slows down the server as most of the CPU resources are just waiting for I/O. When the server slows down, but the rate of incoming work to the application does not, the application open more connections to queue the requests. At this point, mongod itself is starting to use more memory. This, in turn, is due to the increase in connections, via cursors, stack, etc. This forces the o/s to reduce FS cache, which further exacerbates the FS cache miss issue. For about an hour, between B and the reported crash at 04:29, the WiredTiger open sessions number grows until we reached it’s maximum defined of 20000. Too many open cursors results in too many open sessions and the system fasserts. Please note that the reported error message is misleading: Cannot allocate memory as we still have available memory. This should be Cannot allocate resource to better reflect this event. I’ve filed SERVER-30493 to address this. 3 minutes later, at 04:33 the server was stopped and changed to i2.4xlarge Instance which has doubled the CPU and RAM. Overall event analysis: There is a significant increase in wt cache application threads page read from disk to cache time metric - indicating that the reads were slower following the incident, either because the disk slowed down, or because the pages requested were slower to be read, or because there are more read requests and/or more bytes being read. This contributes to the overall slow down, and the total time waiting here is quite high (all 128 read threads are waiting). As the event progresses, there is a gradual decrease in the wt block-manager bytes read metric. This metric stands for the FS reads and stays rather stable until the event. There is an increase in the tcmalloc derived allocated minus wt cache metric. This is the amount of memory in the heap that is allocated and in use by the application. The allocated minus cache metric is allocated bytes not accounted for by the WiredTiger cache. Even though the increase by the ~7GB is significantly less than the WiredTiger cache (35GB), this still indicates that the memory growth is outside of the WiredTiger cache. The open cursors metric curves strongly suggests cursors are responsible for the increase in the tcmalloc derived allocated minus wt cache. At B, we can see that most of the processes (~126) are blocked under system processes running metric and the kernel CPU is spiking above 60%. The kernel time increase is most probably due to the new threads being created as connections increase. There is some increase in all the IO related metrics between A and B and a significant increase after B: CPU IO wait, disk Utilization, disk xvdc bytes read and xvdc read requests issued. The queue length is ~proportional to IO wait, which means that the CPU resources are just waiting for I/O access which usually indicates that the IO subsystem just being too slow/busy to handle the incoming requests. Evidence of a shift in the workload: By inspecting the IO related metrics, we can see that at A, there is a change in the behavior between wt block-manager bytes read and the disk xvdc bytes read. Before the event, the wt block-manager bytes read metric is ~500 MB/s, yet, the disk xvdc bytes read metric is only ~10 MB/s. When the incident starts at A (and as it progresses) this ratio changes. This strongly indicates that the workload must have shifted to a different part of the dataset that is not in FS cache and from this point, we are reading mainly from disk. To prevent this from happening again in the future, I recommend keeping your dataset in the cache. Thanks, Dima tch@virtall.com commented on Thu, 3 Aug 2017 07:03:05 +0000: We were overloaded when mongod crashed (as you can only see from "only configured to support 20020 sessions" - mongod was slow, and new connections were being made, while the old ones were not yet served). Just not sure if it was a result of mongo malfunctioning, or something else - we never had a similar issue before. So after we've realised it crashed, we've stopped the instance, then started as a bigger one. Ins syslog, there isn't really anything interesting - DHCP renewals and such. There aren't any OOM, crashes, nothing unexpected. dmitry.agranat commented on Thu, 3 Aug 2017 06:45:17 +0000: Thanks for uploading the $dbpath/diagnostic.data directory tch@virtall.com. I am still looking at the provided data to understand exactly what happened, but in the meantime, can you clarify one thing? At the time of the incident, at 2017-07-31T04:29:57, the server had 8 CPU and 60GB RAM (if it's AWS Instance than it's i2.2xlarge). 3 minutes later, at 2017-07-31T04:33:00 I can see that the server had 16 CPU and 122GB RAM (if it's AWS Instance than it's i2.4xlarge). Could you clarify if you have manually changed the Instance type and if yes, was it intentional? Also, if you could attach the syslog from this server that contains the crash that could be helpful. tch@virtall.com commented on Mon, 31 Jul 2017 22:48:30 +0000: The log contains some info which is not public (we had slow log enabled). $dbpath/diagnostic.data: https://www.virtall.com/tmp/diagnostic.data.tar.gz bruce.lucas@10gen.com commented on Mon, 31 Jul 2017 15:45:30 +0000: Hi Tomasz, Can you please archive and attach the $dbpath/diagnostic.data directory? Also, if you could attach the complete mongod log file that contains the crash that could be helpful. Thanks, Bruce

Steps to Reproduce