Node runs out of memory when doing db backup or migrations

Developer help
1

Fill out the following bug report template with as much detail as possible!

Are you sure this is a bug? If you just need help, post in the developer help category. If it’s a feature request, head to the ideas category.

Issue Summary

  • Explain roughly what’s wrong
    When trying to update Ghost from 5.49.1 to 5.65 the ghost service is restarted with the new ghost version, and tries to do migrations. There is an GC error that node ran out of memory right after it tries to do db backup. Also happens when trying to run ghost backup or ghost admin interface Labs → Export Content
  • What did you expect to happen?

Steps to Reproduce

Setup information

Ghost Version
5.49.1

Node.js Version
v18.18.0

How did you install Ghost?
ghost install

Provide details of your host & operating system
Ubuntu 22

Database type
MySQL 8

Browser & OS version
Not applicable

Relevant log / error output
Copy and paste any relevant log output. Use backticks to format this into code.

When running ghost update this are the logs:

Sep 26 14:21:11 rbv-main node[20029]: [2023-09-26 14:21:11] INFO Bootstrap client was closed.

Sep 26 14:21:11 rbv-main node[20029]: [2023-09-26 14:21:11] WARN Database state requires migration.

Sep 26 14:21:11 rbv-main node[20029]: [2023-09-26 14:21:11] INFO Creating database backup

Sep 26 14:21:17 rbv-main node[19998]: <--- Last few GCs --->

Sep 26 14:21:17 rbv-main node[19998]: [20029:0x5b02710] 6705 ms: Mark-sweep 1913.3 (2084.0) -> 1911.4 (2084.0) MB, 98.1 / 0.0 ms (average mu = 0.889, current mu = 0.619) allocation failure; scavenge might not succeed

Sep 26 14:21:17 rbv-main node[19998]: [20029:0x5b02710] 6989 ms: Mark-sweep 1927.1 (2084.0) -> 1925.4 (2115.7) MB, 257.3 / 0.0 ms (average mu = 0.661, current mu = 0.092) allocation failure; scavenge might not succeed

Sep 26 14:21:17 rbv-main node[19998]: <--- JS stacktrace --->

Sep 26 14:21:17 rbv-main node[19998]: FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory

Sep 26 14:21:17 rbv-main node[19998]: 1: 0xb87bc0 node::Abort() [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 2: 0xa96834 [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 3: 0xd687f0 v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 4: 0xd68b97 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 5: 0xf462a5 [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 6: 0xf5878d v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 7: 0xf32e8e v8::internal::HeapAllocator::AllocateRawWithLightRetrySlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 8: 0xf34257 v8::internal::HeapAllocator::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 9: 0xf147a0 v8::internal::Factory::AllocateRaw(int, v8::internal::AllocationType, v8::internal::AllocationAlignment) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 10: 0xf0c214 v8::internal::FactoryBase<v8::internal::Factory>::AllocateRawWithImmortalMap(int, v8::internal::AllocationType, v8::internal::Map, v8::internal::AllocationAlignment) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 11: 0xf0e5a8 v8::internal::FactoryBase<v8::internal::Factory>::NewRawTwoByteString(int, v8::internal::AllocationType) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 12: 0x133ff6c v8::internal::IncrementalStringBuilder::Extend() [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 13: 0x1055450 v8::internal::JsonStringifier::SerializeString(v8::internal::Handle<v8::internal::String>) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 14: 0x1056962 v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_<true>(v8::internal::Handle<v8::internal::Object>, bool, v8::internal::Handle<v8::internal::Object>) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 15: 0x105ad2f v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_<false>(v8::internal::Handle<v8::internal::Object>, bool, v8::internal::Handle<v8::internal::Object>) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 16: 0x105818a v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_<true>(v8::internal::Handle<v8::internal::Object>, bool, v8::internal::Handle<v8::internal::Object>) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 17: 0x1058b33 v8::internal::JsonStringifier::SerializeJSReceiverSlow(v8::internal::Handle<v8::internal::JSReceiver>) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 18: 0x1057bee v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_<true>(v8::internal::Handle<v8::internal::Object>, bool, v8::internal::Handle<v8::internal::Object>) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 19: 0x105ad2f v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_<false>(v8::internal::Handle<v8::internal::Object>, bool, v8::internal::Handle<v8::internal::Object>) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 20: 0x105ba7f v8::internal::JsonStringify(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 21: 0xdee7a7 v8::internal::Builtin_JsonStringify(int, unsigned long*, v8::internal::Isolate*) [/usr/bin/node]

Sep 26 14:21:17 rbv-main node[19998]: 22: 0x170a179 [/usr/bin/node]

Sep 26 14:21:18 rbv-main systemd[1]: ghost_new2-brasovultau-ro.service: Deactivated successfully.

Sep 26 14:21:18 rbv-main systemd[1]: ghost_new2-brasovultau-ro.service: Consumed 11.454s CPU time.

Sep 26 14:21:18 rbv-main systemd[1]: ghost_new2-brasovultau-ro.service: Scheduled restart job, restart counter is at 1.

Sep 26 14:21:18 rbv-main systemd[1]: Stopped Ghost systemd service for blog: new2-brasovultau-ro.

Sep 26 14:21:18 rbv-main systemd[1]: ghost_new2-brasovultau-ro.service: Consumed 11.454s CPU time.

Sep 26 14:21:18 rbv-main systemd[1]: Started Ghost systemd service for blog: new2-brasovultau-ro.

Sep 26 14:21:18 rbv-main node[20046]: Love open source? We’re hiring JavaScript Engineers to work on Ghost full-time.

Sep 26 14:21:18 rbv-main node[20046]: https://careers.ghost.org

Sep 26 14:21:18 rbv-main node[20046]: - Inspecting operating system

Sep 26 14:21:19 rbv-main node[20076]: [2023-09-26 14:21:19] INFO Ghost is running in production...

Sep 26 14:21:19 rbv-main node[20076]: [2023-09-26 14:21:19] INFO Your site is now available on https://new2.brasovultau.ro/

Sep 26 14:21:19 rbv-main node[20076]: [2023-09-26 14:21:19] INFO Ctrl+C to shut down

Sep 26 14:21:19 rbv-main node[20076]: [2023-09-26 14:21:19] INFO Ghost server started in 0.397s

Sep 26 14:21:19 rbv-main node[20076]: [2023-09-26 14:21:19] INFO Bootstrap client was closed.

Sep 26 14:21:19 rbv-main node[20076]: [2023-09-26 14:21:19] ERROR Migration lock was never released or currently a migration is running.

Sep 26 14:21:19 rbv-main node[20076]:

Sep 26 14:21:19 rbv-main node[20076]: Migration lock was never released or currently a migration is running.

Sep 26 14:21:19 rbv-main node[20076]: "If you are sure no migration is running, check your data and if your database is in a broken state, you could run `yarn knex-migrator rollback`."

Sep 26 14:21:19 rbv-main node[20076]: Error ID:

Sep 26 14:21:19 rbv-main node[20076]: 500

Sep 26 14:21:19 rbv-main node[20076]: ----------------------------------------

Sep 26 14:21:19 rbv-main node[20076]: MigrationsAreLockedError: Migration lock was never released or currently a migration is running.

Sep 26 14:21:19 rbv-main node[20076]: at /var/www/bvt/versions/5.65.0/node_modules/knex-migrator/lib/locking.js:62:23

Sep 26 14:21:19 rbv-main node[20076]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5)

Sep 26 14:21:19 rbv-main node[20076]: at async DatabaseStateManager.getState (/var/www/bvt/versions/5.65.0/core/server/data/db/DatabaseStateManager.js:40:13)

Sep 26 14:21:19 rbv-main node[20076]: at async DatabaseStateManager.makeReady (/var/www/bvt/versions/5.65.0/core/server/data/db/DatabaseStateManager.js:73:25)

Sep 26 14:21:19 rbv-main node[20076]: at async initDatabase (/var/www/bvt/versions/5.65.0/core/boot.js:69:5)

Sep 26 14:21:19 rbv-main node[20076]: at async bootGhost (/var/www/bvt/versions/5.65.0/core/boot.js:499:9)

Sep 26 14:21:19 rbv-main node[20076]:

Sep 26 14:21:19 rbv-main node[20076]: [2023-09-26 14:21:19] WARN Ghost is shutting down

Sep 26 14:21:19 rbv-main node[20076]: [2023-09-26 14:21:19] WARN Ghost has shut down

Sep 26 14:21:19 rbv-main node[20076]: [2023-09-26 14:21:19] WARN Your site is now offline

Sep 26 14:21:19 rbv-main node[20076]: [2023-09-26 14:21:19] WARN Ghost was running for a few seconds

Ghost runs db backup and remains out of memory, than the service is restarted but there is a migration lock.

When trying to export the data from admin UI or using ghost backup the enpoint returns a 520 and in the logs there can be seen the service stopped.

These are the logs just after running ghost backup or export from UI:

Sep 26 15:15:33 rbv-main systemd[1]: ghost_new2-brasovultau-ro.service: Deactivated successfully.

Sep 26 15:15:33 rbv-main systemd[1]: ghost_new2-brasovultau-ro.service: Consumed 37.941s CPU time.

Sep 26 15:15:34 rbv-main systemd[1]: ghost_new2-brasovultau-ro.service: Scheduled restart job, restart counter is at 1.

Sep 26 15:15:34 rbv-main systemd[1]: Stopped Ghost systemd service for blog: new2-brasovultau-ro.

Sep 26 15:15:34 rbv-main systemd[1]: ghost_new2-brasovultau-ro.service: Consumed 37.941s CPU time.

Sep 26 15:15:34 rbv-main systemd[1]: Started Ghost systemd service for blog: new2-brasovultau-ro.
2

Is this a droplet or small vps? You might need to upgrade it, or add some swap space - see here

3

It’s not a droplet or small VPS. It’s a Hetzner VPS with dedicated 4 CPU cores and 16GB of RAM. I have however a lot of articles, tens of thousands. I don’t think however that the number of articles should break an update.

4

Agreed, that’s NOT a small vps. :)

But maybe it’s too small for how many articles it’s trying to export?

5

I do a backup every week, and never had any problem, even if I have a fairly cheap droplet. But I spent weeks (if not months) to optimize Cloudflare edge caching and the Digital Ocean configuration following also this guide.

6

This has nothing to do with my issue. My ghost publication is not public so no traffic. The problem is when Ghost restarts after updating the version it need to do migrations, but before migrations it backs up the data. The data backup function is a JSON.stringify which writes your whole database data to a file using a basic JSON.stringify, which for large amounts of data ofcourse it will run out of memory…

7

Managed to finally update it to latest version. After installing the update, ghost will try restarting the service which will try to do migrations but before, it will run a backup functions which will fail and the database will be in locked state. To unlock the database:

select * from migrations_lock;
update migrations_lock SET locked=0 where lock_key='km01';

Then manually run the run command of ghost increasing it’s memory:

NODE_OPTIONS=--max_old_space_size=12000 /usr/bin/node --max-old-space-size=12000 /usr/bin/ghost run

This gives enough memory to overcome the backup using JSON.stringify.

If any of the devs read this, I’m just curious, who came up with the idea of backing up a whole database using JSON.stringify? :exploding_head:

1 Like
8

Thanks for documenting the solution. If you haven’t opened an issue over on GitHub, that would be a good idea. (More devs there than here.)