Как побороть, MongoDB 4.0 жрет всю память и падает, что можно придумать?

Question

[Станислав]

Когда стояла mongodb 3.6 и node.js 9.x все было замечательно, все работало 3-6 месяцев и никаких неполадок небыло. Недавно решил обновить все и начались проблемы: Сайт размещен на ВПС debian 9, 4GB ОЗУ, 2 ядра. После обновления спустя сутки сайт уходит в даун, выяснилось что упал mongod, потому что всю память сожрал. После увеличил ОЗУ до 8GB, все успешно работало 2 дня, потом опять тоже самое, приходится перезагружать сервер.

Node.js - v10.7.0 MongoDB - 4.0.0

Mongod.conf

storage:
  dbPath: /var/lib/mongodb
  journal:
    enabled: true
#  engine:
#  mmapv1:
  wiredTiger:
    engineConfig:
       cacheSizeGB: 6

cacheSizeGB добавлял после и не помогло

Syslog

Jul 28 08:56:54 SiteName dhclient[674]: DHCPREQUEST of xx.xx.xxx.186 on eth0 to xxx.xx.1.1 port 67
Jul 28 08:56:54 SiteName dhclient[674]: DHCPACK of xx.xx.xxx.186 from 172.31.1.1
Jul 28 08:56:54 SiteName dhclient[674]: bound to xx.xx.xxx.186 -- renewal in 36837 seconds.
Jul 28 09:00:01 SiteName CRON[16647]: (root) CMD (/usr/bin/node /var/www/SiteName.ru/bin/cron/synonyms.js >/dev/null 2>&1)
Jul 28 09:00:05 SiteName kernel: [331671.923612] node invoked oom-killer: gfp_mask=0x24280ca(GFP_HIGHUSER_MOVABLE|__GFP_ZERO), nodemask=0, order=0, oom_score_adj=0
Jul 28 09:00:05 SiteName kernel: [331671.926532] node cpuset=/ mems_allowed=0
Jul 28 09:00:05 SiteName kernel: [331671.927797] CPU: 1 PID: 16649 Comm: node Not tainted 4.9.0-7-amd64 #1 Debian 4.9.110-1
Jul 28 09:00:05 SiteName kernel: [331671.930045] Hardware name: Hetzner vServer, BIOS 20171111 11/11/2017
Jul 28 09:00:05 SiteName kernel: [331671.931869]  0000000000000000 ffffffff97530644 ffffa70f811ffcf0 ffff8c66a600a800
Jul 28 09:00:05 SiteName kernel: [331671.933872]  ffffffff97403b30 0000000000000000 0000000000000000 0000000c9754f4c9
Jul 28 09:00:05 SiteName kernel: [331671.936081]  ffff8c66a8f5c0c0 ffffffff973892d7 ffffffffc02d86a5 00000000ffffffff
Jul 28 09:00:05 SiteName kernel: [331671.938199] Call Trace:
Jul 28 09:00:05 SiteName kernel: [331671.939114]  [<ffffffff97530644>] ? dump_stack+0x5c/0x78
Jul 28 09:00:05 SiteName kernel: [331671.964188]  free:25595 free_pcp:30 free_cma:0
Jul 28 09:00:05 SiteName kernel: [331671.972611] Node 0 active_anon:7716024kB inactive_anon:82108kB active_file:92kB inactive_file:160kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:4868kB dirty:92kB writeback:4kB shmem:82720kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB pages_scanned:0 all_unreclaimable? no
Jul 28 09:00:05 SiteName kernel: [331672.019758] Node 0 DMA32: 216*4kB (UME) 192*8kB (UME) 169*16kB (UME) 187*32kB (UME) 73*64kB (UME) 34*128kB (UME) 17*256kB (UE) 10*512kB (UME) 1*1024kB (E) 3*2048kB (UE) 2*4096kB (M) = 44944kB
Jul 28 09:00:05 SiteName kernel: [331672.027118] Node 0 Normal: 873*4kB (UME) 618*8kB (UE) 367*16kB (UME) 260*32kB (UME) 140*64kB (UME) 46*128kB (UME) 14*256kB (UME) 1*512kB (E) 0*1024kB 0*2048kB 0*4096kB = 41572kB
Jul 28 09:00:05 SiteName kernel: [331672.033850] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Jul 28 09:00:05 SiteName kernel: [331672.037183] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Jul 28 09:00:05 SiteName kernel: [331672.040524] 20785 total pagecache pages
Jul 28 09:00:05 SiteName kernel: [331672.042589] 0 pages in swap cache
Jul 28 09:00:05 SiteName kernel: [331672.044689] Swap cache stats: add 0, delete 0, find 0/0
Jul 28 09:00:05 SiteName kernel: [331672.047591] Free swap  = 0kB
Jul 28 09:00:05 SiteName kernel: [331672.049456] Total swap = 0kB
Jul 28 09:00:05 SiteName kernel: [331672.051438] 2047866 pages RAM
Jul 28 09:00:05 SiteName kernel: [331672.053354] 0 pages HighMem/MovableOnly
Jul 28 09:00:05 SiteName kernel: [331672.055177] 51623 pages reserved
Jul 28 09:00:05 SiteName kernel: [331672.056987] 0 pages hwpoisoned
Jul 28 09:00:05 SiteName kernel: [331672.059058] [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
v2.10.4: Go
Jul 28 09:00:05 SiteName kernel: [331672.125398] [ 7026]   111  7026  2046636  1763814    3577      10        0             0 mongod
Jul 28 09:00:05 SiteName kernel: [331672.128446] [ 9043]     0  9043   326382    24448     380     166        0             0 node /var/www/f
Jul 28 09:00:05 SiteName kernel: [331672.165206] [16646]     0 16646   243203    21939     141      77        0             0 node
Jul 28 09:00:05 SiteName kernel: [331672.184308] Out of memory: Kill process 7026 (mongod) score 885 or sacrifice child
Jul 28 09:00:05 SiteName kernel: [331672.187084] Killed process 7026 (mongod) total-vm:8186544kB, anon-rss:7055256kB, file-rss:0kB, shmem-rss:0kB
Jul 28 09:00:06 SiteName systemd[1]: mongod.service: Main process exited, code=killed, status=9/KILL
Jul 28 09:00:06 SiteName systemd[1]: mongod.service: Unit entered failed state.
Jul 28 09:00:06 SiteName systemd[1]: mongod.service: Failed with result 'signal'.

Mongod.log

До этого  лог обычных запросов и ничего более

2018-07-28T09:49:08.113+0300 I CONTROL  [main] ***** SERVER RESTARTED *****
2018-07-28T09:49:08.323+0300 I CONTROL  [initandlisten] MongoDB starting : pid=826 port=27017 dbpath=/var/lib/mongodb 64-bit host=SiteName
2018-07-28T09:49:08.323+0300 I CONTROL  [initandlisten] db version v4.0.0
2018-07-28T09:49:08.323+0300 I CONTROL  [initandlisten] git version: 3b07af3d4f471ae89e8186d33bbb1d5259597d51
2018-07-28T09:49:08.323+0300 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.1.0f  25 May 2017
2018-07-28T09:49:08.323+0300 I CONTROL  [initandlisten] allocator: tcmalloc
2018-07-28T09:49:08.323+0300 I CONTROL  [initandlisten] modules: none
2018-07-28T09:49:08.323+0300 I CONTROL  [initandlisten] build environment:
2018-07-28T09:49:08.323+0300 I CONTROL  [initandlisten]     distmod: debian92
2018-07-28T09:49:08.323+0300 I CONTROL  [initandlisten]     distarch: x86_64
2018-07-28T09:49:08.323+0300 I CONTROL  [initandlisten]     target_arch: x86_64
2018-07-28T09:49:08.323+0300 I CONTROL  [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "127.0.0.1", port: 27017 }, processManagement: { timeZoneInfo: "/usr/share/zoneinfo" }, storage: { dbPath: "/var/lib/mongodb", journal: { enabled: true }, wiredTiger: { engineConfig: { cacheSizeGB: 6.0 } } }, systemLog: { destination: "file", logAppend: true, path: "/var/log/mongodb/mongod.log" } }
2018-07-28T09:49:08.323+0300 W STORAGE  [initandlisten] Detected unclean shutdown - /var/lib/mongodb/mongod.lock is not empty.
2018-07-28T09:49:08.324+0300 I STORAGE  [initandlisten] Detected data files in /var/lib/mongodb created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2018-07-28T09:49:08.324+0300 W STORAGE  [initandlisten] Recovering data from the last clean checkpoint.
2018-07-28T09:49:08.324+0300 I STORAGE  [initandlisten] 
2018-07-28T09:49:08.324+0300 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
2018-07-28T09:49:08.324+0300 I STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem
2018-07-28T09:49:08.324+0300 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=6144M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),
2018-07-28T09:49:10.581+0300 I STORAGE  [initandlisten] WiredTiger message [1532760550:581633][826:0x7f99c56a99c0], txn-recover: Main recovery loop: starting at 794/47914112
2018-07-28T09:49:10.581+0300 I STORAGE  [initandlisten] WiredTiger message [1532760550:581954][826:0x7f99c56a99c0], txn-recover: Recovering log 794 through 795
2018-07-28T09:49:10.884+0300 I STORAGE  [initandlisten] WiredTiger message [1532760550:884388][826:0x7f99c56a99c0], file:sizeStorer.wt, txn-recover: Recovering log 795 through 795
2018-07-28T09:49:11.015+0300 I STORAGE  [initandlisten] WiredTiger message [1532760551:15756][826:0x7f99c56a99c0], file:sizeStorer.wt, txn-recover: Set global recovery timestamp: 0
2018-07-28T09:49:11.127+0300 I RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)
2018-07-28T09:49:11.295+0300 I CONTROL  [initandlisten] 
2018-07-28T09:49:11.295+0300 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
2018-07-28T09:49:11.295+0300 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
2018-07-28T09:49:11.295+0300 I CONTROL  [initandlisten] 
2018-07-28T09:49:11.508+0300 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/var/lib/mongodb/diagnostic.data'
2018-07-28T09:49:11.514+0300 I NETWORK  [initandlisten] waiting for connections on port 27017
2018-07-28T09:49:11.905+0300 I CONTROL  [free_mon] Free Monitoring is Enabled. Frequency: 60 seconds
2018-07-28T09:49:12.015+0300 I FTDC     [ftdc] Unclean full-time diagnostic data capture shutdown detected, found interim file, some metrics may have been lost. OK
2018-07-28T09:49:12.573+0300 I NETWORK  [listener] connection accepted from 127.0.0.1:52684 #1 (1 connection now open)
2018-07-28T09:49:12.580+0300 I NETWORK  [conn1] received client metadata from 127.0.0.1:52684 conn1: { driver: { name: "nodejs", version: "3.1.1" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "4.9.0-7-amd64" }, platform: "Node.js v10.7.0, LE, mongodb-core: 3.1.0" }
2018-07-28T09:49:12.601+0300 I NETWORK  [listener] connection accepted from 127.0.0.1:52688 #2 (2 connections now open)

Mongostat (после перезагрузки сервера спустя пол часа)

По mongostat видно как потихоньку растет используемая память

Top (после перезагрузки сервера спустя час)

Comments

[lega]

Склько индексы весят?

[Станислав]

lega,

{
	"db" : "coll",
	"collections" : 11,
	"views" : 0,
	"objects" : 2013462,
	"avgObjSize" : 1320.375909254806,
	"dataSize" : 2658526719,
	"storageSize" : 1044905984,
	"numExtents" : 0,
	"indexes" : 53,
	"indexSize" : 789168128,
	"fsUsedSize" : 10345451520,
	"fsTotalSize" : 40263905280,
	"ok" : 1
}

[Станислав]

Сейчас приходится каждую ночь по крону перезагружать mongod

[Philipp]

А индексы у вас foreground или background?

По внешнему виду где-то внутри MongoDB memleak. У меня был на практике подобный косяк. Пришлось ждать новую версию монги.

[Станислав]

Philipp, foreground или background, я не в курсе, как проверить?
Возможно, но думаю дело не в монге, если только как то криво обновилась. На другом проекте все норм, но он слабенький и быть может поэтому все норм

[Станислав]

Индексы по весу сократил

{
	"db" : "coll",
	"collections" : 11,
	"views" : 0,
	"objects" : 2564657,
	"avgObjSize" : 1183.5082352142997,
	"dataSize" : 3035292680,
	"storageSize" : 1206362112,
	"numExtents" : 0,
	"indexes" : 48,
	"indexSize" : 172339200,
	"fsUsedSize" : 9729626112,
	"fsTotalSize" : 40263905280,
	"ok" : 1
}

Разницы не заметил, все тоже самое

[Philipp]

Либо это проделки oom-killer.
Посмотрите вот тут
https://serverfault.com/questions/457130/why-oom-k...

[Станислав]

Philipp, в общем как я понял, надо создавать новое облако, устанавливать все и переносить сайт, или ждать новой монги. Там и будет ясно что с этим делать, а сейчас у меня по крону каждые 7 часов ребут mongod, пока помогает, хорошо хоть SSD и ребут проходит очень быстро

[Philipp]

Станислав, если не хотите делать копии и т.д. можно создать ReplicaSet и подключить другой инстанс как реплику. Вообще с ReplicaSet можно сделать ребуты без простоя, просто приложение надо будет настроить на использование реплики.

Насчет второго инстанса я не уверен, если есть ошибка внутри самой MongoDB, то косяк будет проявляться и на втором инстансе. Но в таком случае сервера можно будет рестартить попеременно если использовать репликацию.

Попробуйте зарепортить свой краш в монговской джире https://jira.mongodb.org/projects/SERVER/issues/SE...

[Станислав]

Philipp, в общем продолжаю наблюдать, обновил mongoose, вышло обновление, к кофиге mongodb как и писал стоит ограничение вес кеша.
Ребучу mongod каждые 7 часов.
Наблюдаю картинку в mongostat, ребут mongod, растет поле used, на 80% стопорится и так и продолжается 79.9-80%, выше не взлетает.
vsize 5.35GB а res 4.34GB
Открываю top (mongostat при это 80%), %MEM показывает что mongod жрет 57,1% Может вылечилось?

Answer 1

[Станислав]

И так, видимо дело было действительно в mongodb, всего скорее в ней была утечка.
Сегодня обновился до 4.0.1, врубил top и наблюдал.
Не увидел момента освобождения памяти, но mongod использовал около 45% памяти, когда я вновь в консольку глянул через час где то, то было уже 33% памяти, видать был сброс. Открыл лог mongodb, перезагрузок не было.
Еще понаблюдаю конечно, но похоже либо криво встала, либо ошибка изначально в mongodb была
mongostat тоже показывает что mongo меньше потребляет память, не на много, но меньше.

Comments

[lega]

Да, скорее всего в монге, 4.0 - большой необкатаный релиз, сейчас оперативно закрывают критические баги.

[Станислав]

lega, все норм, как и ожидалось, держится на 57% +-1-2%. По сути так и должно быть!

Answer 2

[Дмитрий Макаров]

Я бы рекомендовал на postgres с sequalizejs, он по всем пунктам лучше. У меня на железе одна база падала раз в месяц, а с постгрес уже несколько экземпляров приложения спокойно держит.

Comments

[Anubis]

Ещё TypeORM отличный, если Sequelize не по вкусу

Answer 3

[KaterynaA]

Здравствуйте!

А сколько у Вас коллекций?