very slow startup

[bigbao9494]

Trilium Version

0.51.2

What operating system are you using?

Windows

What is your setup?

Local (no sync)

Operating System Version

windows 11

Description

very slow startup My database is about 10G bytes, sometimes it takes 10 minutes to start, sometimes 3 minutes, and sometimes it even freezes. The following are the 2 startup logs: first: 10:31:40.039 DB size: 10105278 KB 10:31:40.767 Becca (note cache) load took 55ms 10:31:40.870 App HTTP server starting up at port 37840 10:31:40.870 { "appVersion": "0.51.2", "dbVersion": 194, "syncVersion": 25, "buildDate": "2022-05-01T23:18:35+02:00", "buildRevision": "b3763eed610fa3f2aabbcbdbd21efca704a5dd08", "dataDirectory": "D:\I\TriliumDatabase", "clipperProtocolVersion": "1.0", "utcDateTime": "2022-05-31T02:31:40.038Z" } 10:31:40.871 CPU model: Intel(R) Core(TM) i7-10700F CPU @ 2.90GHz, logical cores: 16 freq: 2904 Mhz 10:31:40.887 Registered global shortcut Ctrl+Alt+P for action createNoteIntoInbox 10:31:40.898 Listening on port 37840 10:31:42.173 Generated CSRF token gHaUNi3u-1xZSRHnV2RdCQVxnsgo9srW-XUo with secret _csrf=LP_6c3AhEtonFamrUVd1DhGT; Path=/ 10:31:43.695 200 GET /api/options with 5546 bytes took 1ms 10:31:43.696 200 GET /api/tree with 25732 bytes took 1ms 10:31:43.698 200 GET /api/keyboard-actions with 10639 bytes took 0ms 10:31:43.699 200 GET /api/keyboard-shortcuts-for-notes with 2 bytes took 0ms 10:31:43.700 200 GET /api/script/widgets with 2717 bytes took 1ms 10:31:43.704 200 POST /api/tree/load with 4161 bytes took 0ms 10:31:43.765 200 POST /api/tree/load with 1712 bytes took 1ms 10:31:43.767 200 GET /api/search/%23bookmarked%20or%20%23bookmarkFolder with 31 bytes took 1ms 10:31:43.804 200 POST /api/tree/load with 7000 bytes took 1ms 10:31:44.077 200 GET /api/notes/QxoAos6WBWvk with 429 bytes took 0ms 10:31:44.078 200 GET /api/notes/QxoAos6WBWvk/backlink-count with 11 bytes took 0ms 10:31:44.447 200 GET /api/notes/kYCwEJtcPrnf with 434 bytes took 1ms 10:31:44.452 200 POST /api/tree/load with 19078 bytes took 2ms 10:31:44.455 200 GET /api/notes/gXXEca5odu7W with 428 bytes took 0ms 10:31:44.461 200 POST /api/tree/load with 13494 bytes took 1ms 10:31:44.464 200 GET /api/notes/Osw7Vz6ZpBKP with 427 bytes took 0ms 10:31:44.465 200 POST /api/tree/load with 9554 bytes took 0ms 10:31:44.467 200 GET /api/notes/j4KhYvUnKADL with 430 bytes took 0ms 10:31:44.468 200 POST /api/tree/load with 16808 bytes took 0ms 10:31:44.470 200 GET /api/notes/fGrZdWkuAcX3 with 428 bytes took 0ms 10:31:44.480 200 POST /api/tree/load with 12653 bytes took 0ms 10:31:44.483 200 GET /api/notes/yF3NVoJehAJq with 432 bytes took 1ms 10:31:44.483 200 POST /api/tree/load with 6153 bytes took 0ms 10:31:44.486 200 GET /api/notes/lGkkyyLUE3iB with 427 bytes took 1ms 10:31:44.495 200 POST /api/tree/load with 8893 bytes took 0ms 10:31:44.498 200 GET /api/notes/TmlIvwhaIHd5 with 427 bytes took 0ms 10:31:44.499 200 POST /api/tree/load with 8356 bytes took 0ms 10:31:44.502 200 GET /api/notes/6yYw86h1oWQp with 430 bytes took 1ms 10:31:44.503 200 POST /api/tree/load with 6615 bytes took 1ms 10:31:44.516 200 GET /api/notes/WpCdhakxaFuG with 439 bytes took 0ms 10:31:44.517 200 POST /api/tree/load with 7522 bytes took 0ms 10:31:44.520 200 GET /api/notes/d9OuVcYX2ZB7 with 448 bytes took 0ms 10:31:44.527 200 POST /api/tree/load with 11651 bytes took 0ms 10:31:44.530 200 GET /api/notes/5wGCtEGxRylL with 442 bytes took 0ms 10:31:44.531 200 POST /api/tree/load with 8965 bytes took 0ms 10:31:45.161 Slow query took 391ms: SELECT COUNT(1) FROM notes 10:31:45.369 Slow query took 207ms: SELECT COUNT(1) FROM branches 10:31:45.448 Slow query took 79ms: SELECT COUNT(1) FROM attributes 10:31:45.449 Table counts: notes: 14600, note_revisions: 13, branches: 14724, attributes: 9389, etapi_tokens: 0 10:31:45.472 Slow query took 23ms: SELECT noteId as entityId FROM notes LEFT JOIN entity_changes ON entity_changes.entityName = 'notes' AND entity_changes.entityId = noteId WHERE entity_changes.id IS NULL 10:31:45.528 Slow query took 56ms: SELECT id, entityId FROM entity_changes LEFT JOIN notes ON entityId = noteId WHERE entity_changes.isErased = 0 AND entity_changes.entityName = 'notes' AND noteId IS NULL 10:31:45.582 Slow query took 54ms: SELECT id, entityId FROM entity_changes JOIN notes ON entityId = noteId WHERE entity_changes.isErased = 1 AND entity_changes.entityName = 'notes' 10:31:45.659 Slow query took 65ms: SELECT id, entityId FROM entity_changes LEFT JOIN note_contents ON entityId = noteId WHERE entity_changes.isErased = 0 AND entity_changes.entityName = 'note_contents' AND noteId IS NULL 10:31:45.728 Slow query took 69ms: SELECT id, entityId FROM entity_changes JOIN note_contents ON entityId = noteId WHERE entity_changes.isErased = 1 AND entity_changes.entityName = 'note_contents' 10:31:45.794 Slow query took 54ms: SELECT id, entityId FROM entity_changes LEFT JOIN branches ON entityId = branchId WHERE entity_changes.isErased = 0 AND entity_changes.entityName = 'branches' AND branchId IS NULL 10:31:45.850 Slow query took 55ms: SELECT id, entityId FROM entity_changes JOIN branches ON entityId = branchId WHERE entity_changes.isErased = 1 AND entity_changes.entityName = 'branches' 10:31:45.877 Slow query took 20ms: SELECT id, entityId FROM entity_changes LEFT JOIN attributes ON entityId = attributeId WHERE entity_changes.isErased = 0 AND entity_changes.entityName = 'attributes' AND attributeId IS NULL 10:33:31.614 Slow query took 105682ms: SELECT notes.noteId, notes.type, notes.mime FROM notes JOIN note_contents USING (noteId) WHERE isDeleted = 0 AND isProtected = 0 AND content IS NULL 10:33:31.640 Slow query took 26ms: SELECT note_revisions.noteRevisionId FROM note_revisions LEFT JOIN note_revision_contents USING (noteRevisionId) WHERE note_revision_contents.noteRevisionId IS NULL AND note_revisions.isProtected = 0 10:33:31.674 Slow query took 32ms: SELECT attributeId FROM attributes WHERE isDeleted = 0 AND type = 'relation' AND value = '' 10:33:31.832 Slow query took 157ms: SELECT attributeId, type FROM attributes WHERE isDeleted = 0 AND type != 'label' AND type != 'relation' 10:33:32.506 Slow query took 674ms: SELECT attributeId, attributes.noteId FROM attributes JOIN notes ON attributes.noteId = notes.noteId WHERE attributes.isDeleted = 0 AND notes.isDeleted = 1 10:33:32.535 Slow query took 28ms: SELECT DISTINCT name FROM attributes 10:33:32.561 Slow query took 25ms: SELECT value FROM options WHERE name = 'lastSyncedPush' 10:33:32.600 Slow query took 25ms: UPDATE branches SET isExpanded = 1 WHERE branchId = 'root' 10:33:33.204 Slow query took 603ms: SELECT noteId, parentNoteId FROM branches WHERE isDeleted = 0 10:33:33.217 All consistency checks passed with no errors detected (took 108447ms) 10:33:33.222 200 GET /api/script/startup with 2231 bytes took 1ms 10:33:33.302 200 POST /api/tree/load with 4599 bytes took 0ms 10:33:33.305 200 POST /api/tree/load with 5857 bytes took 1ms 10:41:39.194 200 GET /api/tree?subTreeNoteId=5wGCtEGxRylL with 8965 bytes took 0ms 10:41:39.436 Slow query took 22ms: UPDATE branches SET isExpanded = ? WHERE branchId = ? 10:41:39.436 Slow 204 PUT /api/branches/AQlTGnihFtsA/expanded/1 with 0 bytes took 22ms 10:51:41.031 204 PUT /api/branches/AQlTGnihFtsA/expanded/0 with 0 bytes took 0ms 10:54:32.514 304 GET /api/clipper/handshake with 45 bytes took 1ms 10:55:31.528 304 GET /api/clipper/handshake with 45 bytes took 1ms 10:56:31.529 304 GET /api/clipper/handshake with 45 bytes took 1ms 10:57:31.536 304 GET /api/clipper/handshake with 45 bytes took 2ms 10:58:31.528 304 GET /api/clipper/handshake with 45 bytes took 0ms 10:59:31.531 304 GET /api/clipper/handshake with 45 bytes took 0ms 11:00:31.529 304 GET /api/clipper/handshake with 45 bytes took 1ms 11:01:31.531 304 GET /api/clipper/handshake with 45 bytes took 0ms 11:02:31.529 304 GET /api/clipper/handshake with 45 bytes took 1ms 11:03:31.535 304 GET /api/clipper/handshake with 45 bytes took 1ms 11:04:31.539 304 GET /api/clipper/handshake with 45 bytes took 2ms 11:05:31.528 304 GET /api/clipper/handshake with 45 bytes took 1ms 11:06:31.535 304 GET /api/clipper/handshake with 45 bytes took 2ms 11:07:31.531 304 GET /api/clipper/handshake with 45 bytes took 1ms 11:08:31.542 304 GET /api/clipper/handshake with 45 bytes took 0ms 11:09:31.536 304 GET /api/clipper/handshake with 45 bytes took 1ms 11:10:31.528 304 GET /api/clipper/handshake with 45 bytes took 0ms 11:11:31.526 304 GET /api/clipper/handshake with 45 bytes took 0ms 11:12:31.528 304 GET /api/clipper/handshake with 45 bytes took 0ms 11:13:31.530 304 GET /api/clipper/handshake with 45 bytes took 1ms 11:14:31.536 304 GET /api/clipper/handshake with 45 bytes took 3ms 11:15:31.529 304 GET /api/clipper/handshake with 45 bytes took 1ms

second: 11:16:46.223 DB size: 10105278 KB 11:16:46.907 Becca (note cache) load took 57ms 11:16:47.019 App HTTP server starting up at port 37840 11:16:47.019 { "appVersion": "0.51.2", "dbVersion": 194, "syncVersion": 25, "buildDate": "2022-05-01T23:18:35+02:00", "buildRevision": "b3763eed610fa3f2aabbcbdbd21efca704a5dd08", "dataDirectory": "D:\I\TriliumDatabase", "clipperProtocolVersion": "1.0", "utcDateTime": "2022-05-31T03:16:46.222Z" } 11:16:47.019 CPU model: Intel(R) Core(TM) i7-10700F CPU @ 2.90GHz, logical cores: 16 freq: 2904 Mhz 11:16:47.044 Registered global shortcut Ctrl+Alt+P for action createNoteIntoInbox 11:16:47.056 Listening on port 37840 11:16:48.348 Generated CSRF token r5j7b5KD-vXyjQCpGNNKorOvo1PxC7o5HNKw with secret _csrf=B094gleZoge3s6AQfQKA5xgq; Path=/ 11:16:49.868 200 GET /api/options with 5546 bytes took 0ms 11:16:49.870 200 GET /api/tree with 25732 bytes took 1ms 11:16:49.872 200 GET /api/keyboard-actions with 10639 bytes took 1ms 11:16:49.872 200 GET /api/keyboard-shortcuts-for-notes with 2 bytes took 0ms 11:16:49.883 Slow 200 GET /api/script/widgets with 2717 bytes took 11ms 11:16:49.884 200 POST /api/tree/load with 4161 bytes took 0ms 11:16:49.934 200 POST /api/tree/load with 1712 bytes took 1ms 11:16:49.936 200 GET /api/search/%23bookmarked%20or%20%23bookmarkFolder with 31 bytes took 1ms 11:16:49.959 200 POST /api/tree/load with 7000 bytes took 0ms 11:16:50.235 Slow 200 GET /api/notes/QxoAos6WBWvk with 429 bytes took 17ms 11:16:50.236 200 GET /api/notes/QxoAos6WBWvk/backlink-count with 11 bytes took 1ms 11:16:50.595 200 GET /api/notes/kYCwEJtcPrnf with 434 bytes took 1ms 11:16:50.596 200 POST /api/tree/load with 19078 bytes took 0ms 11:16:50.600 200 GET /api/notes/gXXEca5odu7W with 428 bytes took 1ms 11:16:50.601 200 POST /api/tree/load with 13494 bytes took 0ms 11:16:50.604 200 GET /api/notes/Osw7Vz6ZpBKP with 427 bytes took 0ms 11:16:50.605 200 POST /api/tree/load with 9554 bytes took 0ms 11:16:50.607 200 GET /api/notes/j4KhYvUnKADL with 430 bytes took 0ms 11:16:50.608 200 POST /api/tree/load with 16808 bytes took 1ms 11:16:50.611 200 GET /api/notes/fGrZdWkuAcX3 with 428 bytes took 1ms 11:16:50.623 200 POST /api/tree/load with 12653 bytes took 1ms 11:16:50.626 200 GET /api/notes/yF3NVoJehAJq with 432 bytes took 1ms 11:16:50.630 200 POST /api/tree/load with 6153 bytes took 0ms 11:16:50.644 Slow 200 GET /api/notes/lGkkyyLUE3iB with 427 bytes took 12ms 11:16:50.650 200 POST /api/tree/load with 8893 bytes took 1ms 11:16:50.653 200 GET /api/notes/TmlIvwhaIHd5 with 427 bytes took 1ms 11:16:50.654 200 POST /api/tree/load with 8356 bytes took 1ms 11:16:50.656 200 GET /api/notes/6yYw86h1oWQp with 430 bytes took 0ms 11:16:50.657 200 POST /api/tree/load with 6615 bytes took 0ms 11:16:50.660 200 GET /api/notes/WpCdhakxaFuG with 439 bytes took 0ms 11:16:50.673 200 POST /api/tree/load with 7522 bytes took 0ms 11:16:50.676 200 GET /api/notes/d9OuVcYX2ZB7 with 448 bytes took 0ms 11:16:50.680 200 POST /api/tree/load with 11651 bytes took 1ms 11:16:50.683 200 GET /api/notes/5wGCtEGxRylL with 442 bytes took 0ms 11:16:50.684 200 POST /api/tree/load with 8965 bytes took 0ms 11:16:51.451 Slow query took 541ms: SELECT COUNT(1) FROM notes 11:16:51.790 Slow query took 338ms: SELECT COUNT(1) FROM branches 11:16:51.990 Slow query took 200ms: SELECT COUNT(1) FROM attributes 11:16:51.990 Table counts: notes: 14600, note_revisions: 13, branches: 14724, attributes: 9389, etapi_tokens: 0 11:16:54.498 Slow query took 2508ms: SELECT noteId as entityId FROM notes LEFT JOIN entity_changes ON entity_changes.entityName = 'notes' AND entity_changes.entityId = noteId WHERE entity_changes.id IS NULL 11:17:01.740 Slow query took 7242ms: SELECT id, entityId FROM entity_changes LEFT JOIN notes ON entityId = noteId WHERE entity_changes.isErased = 0 AND entity_changes.entityName = 'notes' AND noteId IS NULL 11:17:01.794 Slow query took 54ms: SELECT id, entityId FROM entity_changes JOIN notes ON entityId = noteId WHERE entity_changes.isErased = 1 AND entity_changes.entityName = 'notes' 11:17:05.389 Slow query took 3595ms: SELECT noteId as entityId FROM note_contents LEFT JOIN entity_changes ON entity_changes.entityName = 'note_contents' AND entity_changes.entityId = noteId WHERE entity_changes.id IS NULL 11:17:17.657 Slow query took 12268ms: SELECT id, entityId FROM entity_changes LEFT JOIN note_contents ON entityId = noteId WHERE entity_changes.isErased = 0 AND entity_changes.entityName = 'note_contents' AND noteId IS NULL 11:17:17.725 Slow query took 68ms: SELECT id, entityId FROM entity_changes JOIN note_contents ON entityId = noteId WHERE entity_changes.isErased = 1 AND entity_changes.entityName = 'note_contents' 11:17:20.824 Slow query took 3089ms: SELECT branchId as entityId FROM branches LEFT JOIN entity_changes ON entity_changes.entityName = 'branches' AND entity_changes.entityId = branchId WHERE entity_changes.id IS NULL 11:17:25.259 Slow query took 4435ms: SELECT id, entityId FROM entity_changes LEFT JOIN branches ON entityId = branchId WHERE entity_changes.isErased = 0 AND entity_changes.entityName = 'branches' AND branchId IS NULL 11:17:25.315 Slow query took 56ms: SELECT id, entityId FROM entity_changes JOIN branches ON entityId = branchId WHERE entity_changes.isErased = 1 AND entity_changes.entityName = 'branches' 11:17:25.782 Slow query took 467ms: SELECT attributeId as entityId FROM attributes LEFT JOIN entity_changes ON entity_changes.entityName = 'attributes' AND entity_changes.entityId = attributeId WHERE entity_changes.id IS NULL 11:17:26.827 Slow query took 1045ms: SELECT id, entityId FROM entity_changes LEFT JOIN attributes ON entityId = attributeId WHERE entity_changes.isErased = 0 AND entity_changes.entityName = 'attributes' AND attributeId IS NULL 11:17:27.532 Slow query took 660ms: SELECT DISTINCT notes.noteId FROM notes LEFT JOIN branches ON notes.noteId = branches.noteId AND branches.isDeleted = 0 WHERE notes.isDeleted = 0 AND branches.branchId IS NULL 11:19:30.894 Slow query took 123328ms: SELECT notes.noteId, notes.type, notes.mime FROM notes JOIN note_contents USING (noteId) WHERE isDeleted = 0 AND isProtected = 0 AND content IS NULL 11:19:30.936 Slow query took 26ms: SELECT attributeId FROM attributes WHERE isDeleted = 0 AND type = 'relation' AND value = '' 11:19:31.174 Slow query took 238ms: SELECT attributeId, type FROM attributes WHERE isDeleted = 0 AND type != 'label' AND type != 'relation' 11:19:31.931 Slow query took 757ms: SELECT attributeId, attributes.noteId FROM attributes JOIN notes ON attributes.noteId = notes.noteId WHERE attributes.isDeleted = 0 AND notes.isDeleted = 1 11:19:31.953 Slow query took 21ms: SELECT DISTINCT name FROM attributes 11:19:31.978 Slow query took 23ms: SELECT value FROM options WHERE name = 'lastSyncedPush' 11:19:32.076 Slow query took 83ms: UPDATE branches SET isExpanded = 1 WHERE branchId = 'root' 11:19:32.571 Slow query took 494ms: SELECT noteId, parentNoteId FROM branches WHERE isDeleted = 0 11:19:32.593 All consistency checks passed with no errors detected (took 161683ms) 11:19:32.605 200 GET /api/script/startup with 2231 bytes took 8ms 11:19:32.704 304 GET /api/clipper/handshake with 45 bytes took 1ms 11:19:32.705 200 GET /api/clipper/handshake with 45 bytes took 0ms 11:19:32.706 200 POST /api/tree/load with 4599 bytes took 0ms 11:19:32.708 304 GET /api/clipper/handshake with 45 bytes took 1ms 11:19:32.710 200 POST /api/tree/load with 5857 bytes took 1ms

[sigaloid]

A 10GB database is very, very heavy and that is almost certainly the source of your problems. Individual large files (>~300MB) are not really meant to be stored in Trilium's database. Nonetheless, if you start trilium in a command prompt you can see the startup process and exactly what is taking so long; it's probable you'll find the database being loaded into memory is the bottleneck.

[zadam]

Hi, as @sigaloid mentioned, Trilium is not really intended to store huge files. However, this does not actually explain such long startup times, the note contents are not loaded into memory on the startup, only the metadata and the 14 000 is a normal number of notes. It looks like a bulk of the time is spent in the consistency checks (which contains some heavy queries), backup is another prime suspect (since it will copy the whole database file).

I'll try to build a big database and see if I can reproduce the long startup times.

[zadam]

@bigbao9494 could you try this build to see if it help? https://github.com/zadam/trilium/releases/download/v0.52.0-beta/trilium-windows-x64-0.52.0-beta-DB-fix.zip

Also, you might want to disable the auto-backup which can slow down startup considerably with big databases:

[bigbao9494]

Thank you very much for your reply. My database mainly stores PDF files and .RAR compressed packages. There are very few files larger than 300M. I have turned off the database backup function of . In addition, I also found a problem today, it will freeze every once in a while, I can see through the Windows task manager that it is reading the disk, I don't know the reason, but I can be sure that I have not modified any data in it, it is simple Just open it up. I'll post this log later.

[bigbao9494]

@zadam https://github.com/zadam/trilium/releases/download/v0.52.0-beta/trilium-windows-x64-0.52.0-beta-DB-fix.zip I tested this version and so far it works perfectly and the problem just above is gone. thank you very much.