ms-dred
@ms-dred
Вечно что то не то и что то не так...

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

Когда стояла 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 (после перезагрузки сервера спустя пол часа)
1Sr7k.png
По mongostat видно как потихоньку растет используемая память

Top (после перезагрузки сервера спустя час)
U9Cwt.png
  • Вопрос задан
  • 1848 просмотров
Пригласить эксперта
Ответы на вопрос 3
ms-dred
@ms-dred Автор вопроса
Вечно что то не то и что то не так...
И так, видимо дело было действительно в mongodb, всего скорее в ней была утечка.
Сегодня обновился до 4.0.1, врубил top и наблюдал.
Не увидел момента освобождения памяти, но mongod использовал около 45% памяти, когда я вновь в консольку глянул через час где то, то было уже 33% памяти, видать был сброс. Открыл лог mongodb, перезагрузок не было.
Еще понаблюдаю конечно, но похоже либо криво встала, либо ошибка изначально в mongodb была
mongostat тоже показывает что mongo меньше потребляет память, не на много, но меньше.
Ответ написан
MDiMaI666
@MDiMaI666
Талантливый программист
Я бы рекомендовал на postgres с sequalizejs, он по всем пунктам лучше. У меня на железе одна база падала раз в месяц, а с постгрес уже несколько экземпляров приложения спокойно держит.
Ответ написан
@KaterynaA
Здравствуйте!

А сколько у Вас коллекций?
Ответ написан
Комментировать
Ваш ответ на вопрос

Войдите, чтобы написать ответ

Войти через центр авторизации
Похожие вопросы