search

signalapp / Signal-Desktop

A private messenger for Windows, macOS, and Linux.
https://signal.org/download
GNU Affero General Public License v3.0
14.64k stars 2.67k forks source link

Laggy UI with large (100-200 MB) message database #3713

Closed lnicola closed 2 years ago

lnicola commented 5 years ago

Bug Description

On my laptop Signal pretty much hangs (keeps drawing, but I often can't type) when a contact is typing. This might be related to the typing indicator, but I think it's been doing this since around Signal 1.25.

Platform Info

Signal Version: 1.27.4

Operating System: Arch Linux, Gnome Wayland

Hardware: i7-6700HQ, iGPU. No hangs in web browsers.

scottnonnenberg-signal commented 5 years ago

Try starting the app with --disable-gpu, see if that changes things. It could be that your graphics hardware/drivers are having trouble with the typing indicator animation.

lnicola commented 5 years ago

It's the main process that's using CPU, not the renderer:

  50.10%  .org.chromium.Chromium.CzZ9iN  [.] AES_decrypt
  23.41%  .org.chromium.Chromium.CzZ9iN  [.] sha1_block_data_order
   3.20%  .org.chromium.Chromium.CzZ9iN  [.] CRYPTO_cbc128_decrypt

A repro for me is to hold down a key during sync.

I'll try --disable-gpu next time I receive more messages.

lnicola commented 5 years ago

At the first sight, --disable-gpu doesn't seem to help.

Are these 200 ms - 2s times okay?

INFO  2019-10-29T17:43:42.433Z SQL channel job 4142 (saveMessage) succeeded in 243ms
INFO  2019-10-29T17:43:42.435Z SQL channel job 4143 (getMessageById) succeeded in 35ms
INFO  2019-10-29T17:43:42.454Z SQL channel job 4145 (getItemById) succeeded in 20ms
INFO  2019-10-29T17:43:42.454Z SQL channel job 4148 (getItemById) succeeded in 20ms
INFO  2019-10-29T17:43:42.455Z SQL channel job 4146 (getItemById) succeeded in 20ms
INFO  2019-10-29T17:43:42.455Z SQL channel job 4147 (getItemById) succeeded in 21ms
INFO  2019-10-29T17:43:42.656Z Worker job 549 (arrayBufferToStringBase64) succeeded in 0ms
INFO  2019-10-29T17:43:44.366Z SQL channel job 4149 (getUnreadByConversation) succeeded in 1869ms
INFO  2019-10-29T17:43:44.367Z SQL channel job 4150 (getConversationById) succeeded in 1850ms
INFO  2019-10-29T17:43:44.367Z SQL channel job 4154 (getNextExpiringMessage) succeeded in 1432ms
INFO  2019-10-29T17:43:44.367Z SQL channel job 4151 (createOrUpdateSession) succeeded in 1910ms
INFO  2019-10-29T17:43:44.368Z SQL channel job 4152 (createOrUpdateSession) succeeded in 1910ms
INFO  2019-10-29T17:43:44.368Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]374
INFO  2019-10-29T17:43:44.368Z SQL channel job 4153 (saveUnprocessed) succeeded in 1712ms
INFO  2019-10-29T17:43:44.369Z queueing envelope 5f68c108-c88f-47b2-9539-4b4606573581
INFO  2019-10-29T17:43:44.369Z received unidentified sender message
INFO  2019-10-29T17:43:44.369Z SQL channel job 4155 (getNextTapToViewMessageToAgeOut) succeeded in 1434ms
INFO  2019-10-29T17:43:44.391Z SQL channel job 4157 (updateConversation) succeeded in 86ms
INFO  2019-10-29T17:43:44.391Z SQL channel job 4156 (getConversationById) succeeded in 87ms
INFO  2019-10-29T17:43:44.392Z SQL channel job 4158 (getItemById) succeeded in 23ms
INFO  2019-10-29T17:43:44.395Z New remote ephemeral key
INFO  2019-10-29T17:43:44.416Z SQL channel job 4159 (updateConversation) succeeded in 24ms
INFO  2019-10-29T17:43:44.416Z SQL channel job 4160 (getItemById) succeeded in 19ms
INFO  2019-10-29T17:43:44.417Z Deleting chain closed at 1572333451090
INFO  2019-10-29T17:43:44.439Z SQL channel job 4161 (createOrUpdateSession) succeeded in 21ms
INFO  2019-10-29T17:43:44.439Z delivery receipt from +[REDACTED]350.1 1572371021874
INFO  2019-10-29T17:43:44.440Z Worker job 550 (arrayBufferToStringBase64) succeeded in 0ms
INFO  2019-10-29T17:43:44.463Z SQL channel job 4163 (removeUnprocessed) succeeded in 24ms
INFO  2019-10-29T17:43:44.463Z SQL channel job 4164 (getMessagesBySentAt) succeeded in 24ms
INFO  2019-10-29T17:43:44.465Z SQL channel job 4165 (updateUnprocessedWithData) succeeded in 25ms
INFO  2019-10-29T17:43:44.545Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]374 200 Success
INFO  2019-10-29T17:43:44.680Z SQL channel job 4166 (saveMessage) succeeded in 214ms
INFO  2019-10-29T17:43:44.901Z SQL channel job 4167 (saveMessage) succeeded in 355ms
INFO  2019-10-29T17:43:44.901Z SQL channel job 4169 (getNextTapToViewMessageToAgeOut) succeeded in 221ms
INFO  2019-10-29T17:43:44.901Z SQL channel job 4168 (getNextExpiringMessage) succeeded in 222ms
INFO  2019-10-29T17:43:44.902Z SQL channel job 4170 (getOlderMessagesByConversation) succeeded in 221ms
INFO  2019-10-29T17:43:44.941Z SQL channel job 4172 (updateConversation) succeeded in 19ms
scottnonnenberg-signal commented 5 years ago 
...succeeded in 1910ms
...succeeded in 1910ms
...succeeded in 1712ms
...succeeded in 1434ms

You're definitely experiencing some long delays in database operations, which use IPC to go from renderer process to main process. Based on your that trace output, it looks like most of the time is in encryption primitives - probably the encryption SQLCipher is doing on the way to/from disk.

Maybe you could talk about your disk stats? Is it an SSD? We've noticed that slow hard disks can really affect Signal Desktop performance.

lnicola commented 5 years ago

It's an SSD, recently trimmed, but low-end. Not sure if it's the disk or CPU, although my CPU isn't so bad I suppose.

Small rant: I don't get the point of this SQLCipher thing. The attachments are saved unencrypted (and deleting conversations doesn't seem to delete them), so I assume Signal doesn't protect me against local compromise. Why are the messages encrypted at rest, then?

lnicola commented 5 years ago

My database (sql/db.sqlite) is 192 MB, not sure if that's a lot or not. I can try to remove it and see if it helps.

scottnonnenberg-signal commented 5 years ago

Hm. One other thing to consider is how you are building Signal Desktop. We only ship .deb files.

Can you talk more about what you mean by 'and deleting conversations doesn't seem to delete them?'

lnicola commented 5 years ago

I'm using the official binaries. The AUR package extracts the .deb and installs the resulting files.

Can you talk more about what you mean by 'and deleting conversations doesn't seem to delete them?

I would test again, but after seeing how large my ~/.config/Signal/attachments.noindex was I tried to delete my conversations, and the files were still there. So was my 192 MB db.sqlite, and search was still returning old messages.

I can file a different issue if that's unexpected after checking that it's still happening. I only mentioned it because I don't see the point of SQLCipher. Some people might need encrypted messages at rest (I don't know where the key is saved), but I'm pretty sure that the attachments are more sensitive for a lot of users.

scottnonnenberg-signal commented 5 years ago

What do you mean exactly by "I tried to delete my conversations?"

lnicola commented 5 years ago

I just tried it:

  1. have one conversation show up in Signal
  2. menu / delete messages
  3. the conversation is now gone from the sidebar
  4. type something in the search bar -- some old messages show up
  5. write something on the phone to bring back that contact (I'm not sure how to start a chat from the desktop client)
  6. messages from yesterday show up in the history
  7. the attachments directory still contains old files; there aren't any from today, but I don't know how it behaves in general
scottnonnenberg-signal commented 5 years ago

Please provide a debug log - I went through some 'delete conversation' scenarios and the messages are really gone, and the messages no longer show up in search.

lnicola commented 5 years ago 

INFO  2019-10-31T15:44:54.689Z Initializing BrowserWindow config: {"show":true,"width":834,"height":550,"minWidth":640,"minHeight":550,"autoHideMenuBar":true,"backgroundColor":"#2090EA","vibrancy":"appearance-based","webPreferences":{"nodeIntegration":false,"nodeIntegrationInWorker":false,"contextIsolation":false,"preload":"[REDACTED]/app.asar/preload.js","nativeWindowOpen":true},"icon":"[REDACTED]/app.asar/images/icon_256.png","maximized":false,"x":1982,"y":255}
INFO  2019-10-31T15:44:55.240Z Updating BrowserWindow config: {"maximized":false,"autoHideMenuBar":true,"width":834,"height":550,"x":1982,"y":283}
INFO  2019-10-31T15:44:55.240Z config/set: Saving ephemeral config to disk
INFO  2019-10-31T15:44:55.303Z Detected Linux. Setting up spell check with locale en_GB and dictionary location /usr/share/hunspell
INFO  2019-10-31T15:44:55.423Z pre-main prep time: 1 ms
INFO  2019-10-31T15:44:55.450Z Build expires:  2020-01-08T18:57:26.000Z
INFO  2019-10-31T15:44:55.458Z Preloading emoji images
INFO  2019-10-31T15:44:55.462Z background page reloaded
INFO  2019-10-31T15:44:55.462Z environment: production
INFO  2019-10-31T15:44:55.620Z SQL channel job 1 (getItemById) succeeded in 158ms
INFO  2019-10-31T15:44:55.620Z Storage fetch
INFO  2019-10-31T15:44:55.660Z SQL channel job 2 (getAllItems) succeeded in 39ms
INFO  2019-10-31T15:44:55.669Z Starting background data migration. Target version: 10
INFO  2019-10-31T15:44:55.669Z ConversationController: starting initial fetch
INFO  2019-10-31T15:44:55.681Z SQL channel job 6 (getAllStickers) succeeded in 11ms
INFO  2019-10-31T15:44:55.681Z SQL channel job 7 (getRecentStickers) succeeded in 11ms
INFO  2019-10-31T15:44:55.681Z SQL channel job 8 (getRecentEmojis) succeeded in 11ms
INFO  2019-10-31T15:44:55.681Z SignalProtocolStore: Finished caching identityKeys data
INFO  2019-10-31T15:44:55.684Z ConversationController: done with initial fetch
INFO  2019-10-31T15:44:55.685Z SignalProtocolStore: Finished caching sessions data
INFO  2019-10-31T15:44:55.690Z SignalProtocolStore: Finished caching preKeys data
INFO  2019-10-31T15:44:55.692Z SignalProtocolStore: Finished caching signedPreKeys data
INFO  2019-10-31T15:44:55.693Z Cleanup: starting...
INFO  2019-10-31T15:44:56.338Z SQL channel job 21 (getOutgoingWithoutExpiresAt) succeeded in 644ms
INFO  2019-10-31T15:44:56.338Z Cleanup: Found 0 messages for cleanup
INFO  2019-10-31T15:44:56.338Z Cleanup: complete
INFO  2019-10-31T15:44:56.338Z listening for registration events
INFO  2019-10-31T15:44:56.340Z Next signed key rotation scheduled for 2019-11-01T08:35:04.491Z
INFO  2019-10-31T15:44:56.340Z refreshSenderCertificate: Getting new certificate...
INFO  2019-10-31T15:44:56.340Z GET https://textsecure-service.whispersystems.org/v1/certificate/delivery
INFO  2019-10-31T15:44:56.346Z connect
INFO  2019-10-31T15:44:56.346Z getAllFromCache
INFO  2019-10-31T15:44:56.346Z opening message socket https://textsecure-service.whispersystems.org
INFO  2019-10-31T15:44:56.348Z Start idle detector
INFO  2019-10-31T15:44:56.348Z open inbox
INFO  2019-10-31T15:44:56.354Z SQL channel job 22 (getNextExpiringMessage) succeeded in 15ms
INFO  2019-10-31T15:44:56.355Z SQL channel job 23 (getNextTapToViewMessageToAgeOut) succeeded in 15ms
INFO  2019-10-31T15:44:56.408Z SQL channel job 26 (getAllUnprocessed) succeeded in 53ms
INFO  2019-10-31T15:44:56.409Z getAllFromCache loaded 0 saved envelopes
INFO  2019-10-31T15:44:56.409Z SQL channel job 27 (getNextAttachmentDownloadJobs) succeeded in 54ms
INFO  2019-10-31T15:44:56.449Z Done preloading emoji images in 990ms
INFO  2019-10-31T15:44:56.978Z websocket open
INFO  2019-10-31T15:44:56.993Z GET https://textsecure-service.whispersystems.org/v1/certificate/delivery 200 Success
INFO  2019-10-31T15:44:56.999Z Next sender certificate refresh scheduled for 2019-11-01T15:44:56.997Z
INFO  2019-10-31T15:44:57.008Z GET https://textsecure-service.whispersystems.org/v1/profile/+[REDACTED]374 (unauth)
INFO  2019-10-31T15:44:57.012Z got request PUT /api/v1/queue/empty
INFO  2019-10-31T15:44:57.015Z MessageReceiver: finished processing messages after 'empty', now waiting for application
INFO  2019-10-31T15:44:57.015Z MessageReceiver: emitting 'empty' event
INFO  2019-10-31T15:44:57.016Z updater/start: Updates disabled - not starting new version checks
INFO  2019-10-31T15:44:57.016Z SQL channel job 28 (createOrUpdateItem) succeeded in 19ms
INFO  2019-10-31T15:44:57.570Z GET https://textsecure-service.whispersystems.org/v1/profile/+[REDACTED]374 200 Success
INFO  2019-10-31T15:44:57.570Z Setting sealedSender to ENABLED for conversation +[REDACTED]374
INFO  2019-10-31T15:44:57.571Z GET https://cdn.signal.org/profiles/t6E4bjVkSV526fRSm1MZxQ
INFO  2019-10-31T15:44:58.738Z GET https://cdn.signal.org/profiles/t6E4bjVkSV526fRSm1MZxQ 200 Success
INFO  2019-10-31T15:45:00.269Z Worker job 1 (arrayBufferToStringBase64) succeeded in 1ms
INFO  2019-10-31T15:45:00.276Z queueing envelope +[REDACTED]374.1 1572536700422 (c5e77095-13d9-40b2-9d99-a0c8c1dc3a0d)
INFO  2019-10-31T15:45:00.277Z message from +[REDACTED]374.1 1572536700422 (c5e77095-13d9-40b2-9d99-a0c8c1dc3a0d)
INFO  2019-10-31T15:45:00.277Z New remote ephemeral key
INFO  2019-10-31T15:45:00.281Z Deleting chain closed at 1572267768673
INFO  2019-10-31T15:45:00.289Z sent message to +[REDACTED]350 1572536700422 from +[REDACTED]374.1 1572536700422 (c5e77095-13d9-40b2-9d99-a0c8c1dc3a0d)
INFO  2019-10-31T15:45:00.291Z Worker job 2 (arrayBufferToStringBase64) succeeded in 0ms
INFO  2019-10-31T15:45:00.292Z Starting handleDataMessage for message +[REDACTED]374.1 1572536700422 in conversation +[REDACTED]350
INFO  2019-10-31T15:45:00.415Z SQL channel job 34 (updateUnprocessedWithData) succeeded in 124ms
INFO  2019-10-31T15:45:00.415Z SQL channel job 35 (saveMessage) succeeded in 116ms
INFO  2019-10-31T15:45:00.416Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:45:00.455Z SQL channel job 39 (updateConversation) succeeded in 37ms
INFO  2019-10-31T15:45:00.475Z SQL channel job 44 (updateConversation) succeeded in 15ms
INFO  2019-10-31T15:45:01.459Z Upgrade message schema (with index): {"done":true,"numProcessed":0,"fetchDuration":3,"upgradeDuration":0,"saveDuration":0,"totalDuration":3}
INFO  2019-10-31T15:45:01.459Z Background migration complete. Stopping idle detector.
INFO  2019-10-31T15:45:01.459Z Stop idle detector
INFO  2019-10-31T15:45:03.513Z Worker job 3 (arrayBufferToStringBase64) succeeded in 28ms
INFO  2019-10-31T15:45:03.523Z queueing envelope 4b8d5c6e-d7ad-4bbc-953f-6013931008d9
INFO  2019-10-31T15:45:03.523Z received unidentified sender message
INFO  2019-10-31T15:45:03.558Z delivery receipt from +[REDACTED]350.1 1572536700422
INFO  2019-10-31T15:45:03.568Z Worker job 4 (arrayBufferToStringBase64) succeeded in 1ms
INFO  2019-10-31T15:45:03.652Z SQL channel job 54 (saveMessage) succeeded in 85ms
INFO  2019-10-31T15:45:03.653Z SQL channel job 55 (updateUnprocessedWithData) succeeded in 86ms
INFO  2019-10-31T15:45:06.629Z SQL channel job 62 (searchMessages) succeeded in 458ms
INFO  2019-10-31T15:45:06.687Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:45:06.687Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:45:06.687Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:45:06.687Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:45:06.688Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:45:06.688Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:45:13.151Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:45:13.688Z open inbox
INFO  2019-10-31T15:45:13.784Z GET https://textsecure-service.whispersystems.org/v1/profile/+[REDACTED]350 (unauth)
INFO  2019-10-31T15:45:13.791Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:45:13.926Z GET https://textsecure-service.whispersystems.org/v1/profile/+[REDACTED]350 200 Success
INFO  2019-10-31T15:45:13.926Z Setting sealedSender to ENABLED for conversation +[REDACTED]350
INFO  2019-10-31T15:45:13.926Z GET https://cdn.signal.org/profiles/Prbx5FrHx2D2ZAGNoLoVfg
INFO  2019-10-31T15:45:14.450Z GET https://cdn.signal.org/profiles/Prbx5FrHx2D2ZAGNoLoVfg 200 Success
INFO  2019-10-31T15:45:14.593Z SQL channel job 63 (getMessageMetricsForConversation) succeeded in 885ms
INFO  2019-10-31T15:45:14.594Z SQL channel job 64 (getOlderMessagesByConversation) succeeded in 814ms
INFO  2019-10-31T15:45:26.380Z unloading conversation +[REDACTED]350 due to: delete messages
INFO  2019-10-31T15:45:36.545Z SQL channel job 69 (removeMessage) succeeded in 10090ms
INFO  2019-10-31T15:45:36.553Z SQL channel job 70 (createOrUpdateItem) succeeded in 9155ms
INFO  2019-10-31T15:45:46.349Z SQL channel job 72 (removeMessage) succeeded in 9785ms
INFO  2019-10-31T15:45:48.581Z Remove all notifications
INFO  2019-10-31T15:45:56.289Z SQL channel job 74 (removeMessage) succeeded in 9927ms
INFO  2019-10-31T15:45:58.488Z Sending a keepalive message
INFO  2019-10-31T15:46:06.199Z SQL channel job 76 (removeMessage) succeeded in 9895ms
INFO  2019-10-31T15:46:06.199Z SQL channel job 77 (getNextAttachmentDownloadJobs) succeeded in 9844ms
INFO  2019-10-31T15:46:16.194Z SQL channel job 79 (removeMessage) succeeded in 9981ms
INFO  2019-10-31T15:46:26.262Z SQL channel job 81 (removeMessage) succeeded in 10056ms
INFO  2019-10-31T15:46:35.511Z Remove all notifications
INFO  2019-10-31T15:46:36.167Z SQL channel job 83 (removeMessage) succeeded in 9894ms
INFO  2019-10-31T15:46:46.099Z SQL channel job 85 (removeMessage) succeeded in 9920ms
INFO  2019-10-31T15:46:46.511Z SQL channel job 86 (searchConversations) succeeded in 9102ms
INFO  2019-10-31T15:46:46.515Z SQL channel job 87 (searchMessages) succeeded in 9517ms
INFO  2019-10-31T15:46:46.536Z SQL channel job 88 (getOlderMessagesByConversation) succeeded in 436ms
INFO  2019-10-31T15:46:46.705Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:46:46.705Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:46:46.706Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:46:46.706Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:46:46.706Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:46:46.706Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:46:46.706Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:46:50.136Z Avatar: Image failed to load; failing over to placeholder
INFO  2019-10-31T15:46:50.308Z Loaded this list of log files from logPath: log.log, log.log.0, log.log.1, log.log.2

Maybe it just takes a long time to remove them? The search results do disappear from the pane, every 5 seconds or so.

scottnonnenberg-signal commented 5 years ago

Wow, yes, things are really taking a long time on your machine. When you choose to delete a conversation's messages, database requests start taking about 10 seconds.

INFO  2019-10-31T15:45:36.545Z SQL channel job 69 (removeMessage) succeeded in 10090ms
INFO  2019-10-31T15:45:36.553Z SQL channel job 70 (createOrUpdateItem) succeeded in 9155ms
INFO  2019-10-31T15:45:46.349Z SQL channel job 72 (removeMessage) succeeded in 9785ms
INFO  2019-10-31T15:45:56.289Z SQL channel job 74 (removeMessage) succeeded in 9927ms
INFO  2019-10-31T15:46:06.199Z SQL channel job 76 (removeMessage) succeeded in 9895ms
INFO  2019-10-31T15:46:06.199Z SQL channel job 77 (getNextAttachmentDownloadJobs) succeeded in 9844ms
INFO  2019-10-31T15:46:16.194Z SQL channel job 79 (removeMessage) succeeded in 9981ms
INFO  2019-10-31T15:46:26.262Z SQL channel job 81 (removeMessage) succeeded in 10056ms
INFO  2019-10-31T15:46:36.167Z SQL channel job 83 (removeMessage) succeeded in 9894ms
INFO  2019-10-31T15:46:46.099Z SQL channel job 85 (removeMessage) succeeded in 9920ms
INFO  2019-10-31T15:46:46.511Z SQL channel job 86 (searchConversations) succeeded in 9102ms
INFO  2019-10-31T15:46:46.515Z SQL channel job 87 (searchMessages) succeeded in 9517ms
lnicola commented 5 years ago

I guess a 100-200 MB database really is too large. Signal is much more snappy after clearing it.

aurelg commented 5 years ago

Same problem here, also solved by deleting some conversations, which is a pity. I wonder if a manual VACCUM/REINDEX of the sqlcipher DB could have restored the database speed so that deleting conversations is not need. Perhaps that's something to try, e.g.:

#!/usr/bin/env bash
set -euo pipefail
IFS=$'\n\t'

# Paths, on Linux
SIGBASE="$HOME/.config/Signal"
KEY="$(/usr/bin/jq -r '."key"' "$SIGBASE"/config.json)"
DB="$SIGBASE/sql/db.sqlite"

# Make sure Signal-Desktop is not running
echo "Kill signal first, then press enter to go on"
read -r

# Make a copy of the current database
if [ -d "$DB.bak" ]; then
  rm -rf "$DB.bak"
fi
cp -v "$DB" "$DB.bak"

# vacuum/reindex
sqlcipher "$DB" \
  "PRAGMA key = \"x'$KEY'\"; vacuum; reindex;"

# Show the size of the optimized and backup database
ls -lh "$DB" "$DB.bak"
scottnonnenberg-signal commented 5 years ago

@aurelg How big was your database file beforehand?

aurelg commented 5 years ago

It was 131 MB, both before and after the deletion of the conversations (which took ~3-4h). After the vaccum+reindex, it's now only 6.4 MB and Signal-Desktop is snappy again :+1: .

lnicola commented 5 years ago

Isn't it easier to delete the database instead? :confused: I wanted to try it on my old one, but the key must have changed.

aurelg commented 5 years ago

AFAIK, deleting the database means loosing all conversations? For some of us, this might not be an option.

lnicola commented 5 years ago

Yes, but you deleted them anyway, so..

aurelg commented 5 years ago

I deleted some conversations, not all.

I then realized that the vacuum+reindex script I posted above could have been sufficient to make Signal snappy again. Next time Signal lags, as discussed in this ticket, I'll test this script to see if it solves the issue. If it's the case, vacuum+reindex could provide an alternative to deleting conversations. If it's not the case, well... we'll need to find something else :-)

breversa commented 4 years ago

@aurelg : I get Error: file is encrypted or is not a database when running you script, with 

$ sqlcipher --version
3.15.2 2016-11-28 19:13:37 bbd85d235f7037c6a033a9690534391ffeacecc8

Any idea how to proceed further ?

aurelg commented 4 years ago

Strange. I use sqlcipher daily to connect and archive conversations, and it works perfectly. I use 3.31.0 2020-01-22 18:38:59 f6affdd41608946fcfcea914ece149038a8b25a62bbe719ed2561c649b86alt1 (SQLCipher 4.4.0 community) (Archlinux). You may want to update yours?

breversa commented 3 years ago

@aurelg Sadly I haven't found a way (so far) to update sqlcipher. I'm running Linux Mint 20.1.

breversa commented 3 years ago

Same problem here, also solved by deleting some conversations, which is a pity. I wonder if a manual VACCUM/REINDEX of the sqlcipher DB could have restored the database speed so that deleting conversations is not need. Perhaps that's something to try, e.g.:

#!/usr/bin/env bash
set -euo pipefail
IFS=$'\n\t'

# Paths, on Linux
SIGBASE="$HOME/.config/Signal"
KEY="$(/usr/bin/jq -r '."key"' "$SIGBASE"/config.json)"
DB="$SIGBASE/sql/db.sqlite"

# Make sure Signal-Desktop is not running
echo "Kill signal first, then press enter to go on"
read -r

# Make a copy of the current database
if [ -d "$DB.bak" ]; then
  rm -rf "$DB.bak"
fi
cp -v "$DB" "$DB.bak"

# vacuum/reindex
sqlcipher "$DB" \
  "PRAGMA key = \"x'$KEY'\"; vacuum; reindex;"

# Show the size of the optimized and backup database
ls -lh "$DB" "$DB.bak"

Couldn't this script be included in a (weekly ?) cron job built in Signal Desktop ?

My DB file (~/.config/Signal Beta/sql/db.sqlite) now weighs 247 MiB and I have more than 7 GiB of attachements (~/.config/Signal Beta/attachments.noindex/*), resulting in a very slow application opening (several minutes each time). Also, I'm unable to get a recent enough version of sqlcipher to manually run the above script.

aurelg commented 3 years ago

Also, I'm unable to get a recent enough version of sqlcipher to randomly run the above script.

I run sqlcipher:

3.34.1 2021-01-20 14:10:07 10e20c0b43500cfb9bbc0eaa061c57514f715d87238f4d835880cd846b9ealt1 (SQLCipher 4.4.3 community)

If you use docker/podman, you can probably install this version inside the Archlinux base image, and run the script above with only minor modification.

sgreadly commented 3 years ago

This! I've noticed the past month where the whole Signal app is excruciatingly sluggish. Not just typing messages, but even starting it up, switching from one conversation to another, scrolling, basically everything. It can lag up to 5-10 seconds before you see what you're typing.

The only oddity I found is Signal's directory being excessively large. 

➜  Signal pwd
/Users/**/Library/Application Support/Signal

➜  Signal du -hs
4.2G    .

➜  Signal du -hs *
 16K    Code Cache
  0B    Dictionaries
296K    GPUCache
 16K    IndexedDB
 72K    Local Storage
4.0K    Network Persistent State
4.0K    Preferences
 52K    QuotaManager
  0B    QuotaManager-journal
 56K    Session Storage
  0B    VideoDecodeStats
4.1G    attachments.noindex      <<<<<<<<<<<<<<<<<
  0B    blob_storage
4.0K    config.json
 28K    databases
  0B    drafts.noindex
4.0K    ephemeral.json
6.5M    logs
 40K    shared_proto_db
 87M    sql
 11M    stickers.noindex
  0B    temp

This is on an M1 2020 MacBook Air, 16G RAM, 11.5.

➜ Signal uname -a Darwin 20.6.0 Darwin Kernel Version 20.6.0: Wed Jun 23 00:26:27 PDT 2021; root:xnu-7195.141.2~5/RELEASE_ARM64_T8101 arm64

Screen Shot 2021-07-30 at 9 57 06 AM

hiqua commented 3 years ago

debug log?

sgreadly commented 3 years ago

debug log?

@hiqua Should be here: https://debuglogs.org/31cfdcf65d37941cf41ae5271eec2872e4b65ccea0dbcd58808b53d6991c1681.gz

Thanks.

sgreadly commented 3 years ago

Just checking if you managed to look into this? Issue still persists even after the last few version updates.

Ta.

sgreadly commented 3 years ago

@hiqua just wanted to bump this thread, as the issue still happens with the latest version (5.13.1).

hiqua commented 3 years ago

When you add a comment please add a new debug log.

What is the size like when you look at it from the storage manager from the mobile app?

sgreadly commented 3 years ago

Thanks @hiqua .

On my iOS, App Size: 154.6MB. Documents & Data: 7.26GB.

As for the Mac app,

➜ Signal du -hs * 16K Code Cache 0B Dictionaries 296K GPUCache 24K IndexedDB 84K Local Storage 4.0K Network Persistent State 4.0K Preferences 52K QuotaManager 0B QuotaManager-journal 0B SS 56K Session Storage 0B SingletonCookie 0B SingletonLock 0B VideoDecodeStats 4.6G attachments.noindex <<<<<<<<<<<<<<< 0B blob_storage 4.0K config.json 28K databases 0B drafts.noindex 4.0K ephemeral.json 5.7M logs 40K shared_proto_db 118M sql 14M stickers.noindex 0B temp

New debug log: https://debuglogs.org/df0c775acc0d3e4e5176fbb05f120ee9d5df147b670f5f2708876e80334129eb.gz

If there's anything else you need, let me know.

Ta.

hiqua commented 3 years ago

You could tell us what your computer is doing while it's being that unresponsive, is the hard drive being used? CPU? Something else?

Other than that, I'd suggest to wait for 5.14, which is supposed to have some rendering optimizations. I'd say it's unlikely to completely solve your problem, but hopefully it should improve a situation a bit. I don't see big errors in your log, so it just seems "normally" slow.

As an example, my data folder is 2.4GB and it's quite responsive, nothing I can complain about, but that's on Linux.

Edit: 5.14 has just been released, can you update and say whether that improves things?

sgreadly commented 3 years ago

Thanks,

The Mac isn't doing anything at all. I could reboot, and just have Signal start on its own, and it'll give the same symptoms.

Overall very very slow. Slow to start, slow to switch from one conversation to another (can take up to 5-10 seconds). Start typing, or in middle of typing, and it's hung for up to 10 seconds tun suddenly shows everything you typed instantly.

Want to click on System > Preferences, it again hangs for ~5 seconds then eventually pops it up.

Literally any action is far too slow.

Just upgraded to v5.14.0 and at first look it does seem much more responsive, thanks! I'll keep testing it out over the next few days and let you know if anything manifests.

https://debuglogs.org/0382b6fcb99768632eb6ef5f64dec005e1217862378f314d804c1fbb9ad043c1.gz

sgreadly commented 3 years ago

@hiqua

Update after few days of testing. While Signal is a bit more responsive now, it still suffers a lot from the lag / slowness above.

I don't believe it's related to the db/data anymore. I used AppCleaner to delete everything and start with a fresh install of Signal on the Mac, and it still suffers from the above slowness, albeit ~30% better now with the latest version.

What does seem to be related... Every time Signal is struggling, sandboxd in the background is going around 60% - 95%.

https://debuglogs.org/f4c6c613bd11039d6e12e126ac0eba694e0beb8c8c4a910e226c26f6f77122c2.gz

Sample of sandboxd.txt

hiqua commented 3 years ago

Fresh install == newly linked?

Did you try this by the way? https://github.com/signalapp/Signal-Desktop/issues/3713#issuecomment-547519012

sandboxd seems to point at a permission problem, if you look at your system logs there might be something relevant there, like signal trying to access stuff it shouldn't.

You could also try to have a look at the profiler by running Signal with: signal-desktop --enable-dev-tools, then view -> toggle developer tools and performance tab, and see if there's anything suspicious going on there.

sgreadly commented 3 years ago

Yep, fresh install as in deleted Signal app's files via AppCleaner, and did a new link to my phone with it. I can't see the older messages for security reasons etc..

I'll have a look at the system logs and let you know soon. May need a day or 2 to test without GPU acceleration.

Edit: Figured out how to do it on Mac. 

➜  /Applications/Signal.app/Contents/MacOS/ ./Signal --disable-gpu --enable-dev-tools
sgreadly commented 3 years ago

@hiqua , Update;

--disable-gpu : Wow! This hit the nail in the coffin. Signal app is as responsive as it should be now. I'll have to test with my external monitor too just to make sure no issues there, but I would say at lest for my issue this is a good workaround.

https://debuglogs.org/e05f12e89e8dade92a6309b9a29c5bd31d8180c640c9b357e1d587ed27ca4130.gz

I had a look at the console logs. I couldn't fully understand everything in there - googling wasn't as productive as I expected.. but I see a lot of repetition of the following,

''' default 09:55:46.637880+1200 kernel Sandbox: 259 duplicate reports for Signal Helper (G deny(1) sysctl-read sysctl.proc_translated '''

Attached: signal-console-log.log

And CLI output: Signal-cli-output.log

As for dev-tools, I do see a lot of output there, mostly warning messages. I'm not sure how to export its content to you so I have a few screenshots below. I'm hoping what's in there is included in the debug logs generated.

Debug: https://debuglogs.org/e05f12e89e8dade92a6309b9a29c5bd31d8180c640c9b357e1d587ed27ca4130.gz

Screen Shot 2021-09-01 at 1 38 50 PM Screen Shot 2021-09-01 at 1 32 39 PM Screen Shot 2021-09-01 at 1 32 16 PM Screen Shot 2021-09-01 at 1 32 10 PM

Moving forward, I'm wondering what can be done with the slowness happening with GPU acceleration.. Is this something that I'd need to file a bug with Apple? Or is it something that can be worked on from your end? Or ... something else?

Thanks for your help so far.

Apple M1:

  Chipset Model:    Apple M1
  Type: GPU
  Bus:  Built-In
  Total Number of Cores:    8
  Vendor:   Apple (0x106b)
  Metal Family: Supported, Metal GPUFamily Apple 7
  Displays:
Colour LCD:
  Resolution:   3360 x 2100
  UI Looks like:    1680 x 1050 @ 60.00Hz
  Main Display: Yes
  Mirror:   Off
  Online:   Yes
  Automatically Adjust Brightness:  No
  Connection Type:  Internal
sgreadly commented 3 years ago

For anyone in need of a quick DIY workaround for this provided they have the same issue as my above,

do shell script "/Applications/Signal.app/Contents/MacOS/Signal --disable-gpu --enable-dev-tools"

Then you can double click that new app instead. Or drag it to your Dock.

Screen Shot 2021-09-01 at 7 50 59 PM

@hiqua , is there anything else you'd like me to do for this? Branch out to another Issue specifically for the GPU issue? Or is there anything that hopefully can be done for this? :/

Ta.

hiqua commented 3 years ago

Honestly I think you shouldn't count on a fix anytime soon, so if the workaround is good enough I'd stick with it.

Do you have other electron apps beside Signal? Do they work properly?

I just find it surprising that there are not more complaints if it's reproducible on every M1, which makes me think there might be something specific to your config, but being GPU related makes it had to track down.

sgreadly commented 3 years ago

Are those electron apps here? No I haven't tried any (wasn't aware of them), but will definitely give a few a shot.

Yea I wonder if others on M1 thought the issue is elsewhere.. But I'm hoping if this is a common issue, it'll show up more..

I'll open up a new issue if I find anything else interesting, say with other electron apps, or if I discover something else.

Thanks for your help on this.

lnicola commented 3 years ago

You should consider filing another issue, this one was specifically about large databases. Disabling the typing indicator really helps with slow rendering issues.

stale[bot] commented 2 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

stale[bot] commented 2 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

stale[bot] commented 2 years ago

This issue has been closed due to inactivity.