Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Signal Desktop becomes unresponsive when sending a message #2070

Closed
1 task done
ghost opened this issue Feb 25, 2018 · 45 comments
Closed
1 task done

Signal Desktop becomes unresponsive when sending a message #2070

ghost opened this issue Feb 25, 2018 · 45 comments

Comments

@ghost
Copy link

ghost commented Feb 25, 2018

  • I have searched open and closed issues for duplicates

Bug description

When I type a message, then send it, it takes many seconds before the message is effectively sent.

Steps to reproduce

  1. Type something (even short) in the chat box
  2. Immediately hit Enter

Actual result:

It takes severals seconds for the message to be sent.

Expected result:

The message is sent almost instantly.

Screenshots

output

Platform info

Signal version:

Signal v1.3.0

Operating System:

macOS 10.13.3

Linked device version:

iOS 11.2.6

Debug log

INFO  2018-02-25T11:42:09.251Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]200
INFO  2018-02-25T11:42:09.336Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]472 200 Success
INFO  2018-02-25T11:42:09.909Z queueing envelope +[REDACTED]472.1 1519558928657
INFO  2018-02-25T11:42:09.909Z delivery receipt from +[REDACTED]472.1 1519558928657
INFO  2018-02-25T11:42:09.909Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]200 200 Success
INFO  2018-02-25T11:42:09.910Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]200
INFO  2018-02-25T11:42:09.915Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]200 200 Success
INFO  2018-02-25T11:42:10.244Z queueing envelope +[REDACTED]472.1 1519558929863
INFO  2018-02-25T11:42:10.245Z message from +[REDACTED]472.1 1519558929863
INFO  2018-02-25T11:42:10.246Z New remote ephemeral key
INFO  2018-02-25T11:42:20.870Z queueing envelope +[REDACTED]472.2 1519558928657
INFO  2018-02-25T11:42:20.931Z queueing envelope +[REDACTED]472.1 1519558938165
INFO  2018-02-25T11:42:21.024Z Deleting chain closed at 1519512115806
INFO  2018-02-25T11:42:21.090Z read receipt +[REDACTED]472 1519558928657
INFO  2018-02-25T11:42:21.106Z delivery receipt from +[REDACTED]472.2 1519558928657
INFO  2018-02-25T11:42:21.141Z message from +[REDACTED]472.1 1519558938165
INFO  2018-02-25T11:42:21.508Z data message from +[REDACTED]472.1 1519558938165
INFO  2018-02-25T11:42:21.747Z adding notification
INFO  2018-02-25T11:42:21.748Z updating notifications - count: 1 focused: true enabled: true
INFO  2018-02-25T11:42:21.748Z remove all notifications
INFO  2018-02-25T11:42:21.798Z Sending 1 read receipts
INFO  2018-02-25T11:42:22.093Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]200
INFO  2018-02-25T11:42:22.528Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]200 200 Success

All other apps on my MacBook works well, I only get lag on this one. It really looks like a lack of performances from the ElectronJs plateforme.
Maybe I sound ridiculous but isn't it a bit odd to use this kind of stuff? I already use a web-browser on daily basis, running a lot of tabs with his engine. Dedicate another one web-browser, with his own engine, to a chat app looks overkill to me.
And I mean, my machine is already a beast: recent CPU, decent amount of RAM, PCI-e storage. Should I buy an IBM Blue Gene/P to exchange encrypted messages through internet?

Thanks in advance!

@scottnonnenberg
Copy link
Contributor

Hi there, @Mathias-B. Sorry you're having some delays.

We appreciate the partial debug log you provided, but it's not nearly enough to help us debug this issue. There should be an entry that starts with 'Sending message to' which relates to that period of time when we're trying to send the message. The other messages around that entry are important because they'll let us know what else the application is doing at the time.

Thanks!

@ghost
Copy link
Author

ghost commented Feb 26, 2018

Okay, thanks for the information.
Give me some time, as soon as I get back to my MacBook I'll submit the correct logs.

@MarcSN311
Copy link

MarcSN311 commented Mar 5, 2018

My girlfriend and I have the same problem.

Steps to reproduce:

Send 2 consecutive Messages. First message is send fast, second takes a long time. (Sometimes even the first one is slow)

INFO  2018-03-05T18:36:03.035Z Sending a keepalive message
INFO  2018-03-05T18:36:58.141Z Sending a keepalive message
INFO  2018-03-05T18:36:59.372Z GET https://textsecure-service.whispersystems.org/v1/profile/+[REDACTED]942
INFO  2018-03-05T18:37:00.127Z GET https://textsecure-service.whispersystems.org/v1/profile/+[REDACTED]942 200 Success
INFO  2018-03-05T18:37:00.129Z done with status fetch
INFO  2018-03-05T18:37:14.085Z Send pre-checks took 10 milliseconds
INFO  2018-03-05T18:37:14.095Z Sending message to conversation +[REDACTED]942 with timestamp 1520275034093
INFO  2018-03-05T18:37:14.136Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]942
INFO  2018-03-05T18:37:14.465Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]942 200 Success
INFO  2018-03-05T18:37:14.485Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]651
INFO  2018-03-05T18:37:14.665Z queueing envelope +[REDACTED]942.1 1520275034093
INFO  2018-03-05T18:37:14.666Z delivery receipt from +[REDACTED]942.1 1520275034093
INFO  2018-03-05T18:37:14.817Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]651 200 Success
INFO  2018-03-05T18:37:21.400Z Send pre-checks took 5448 milliseconds
INFO  2018-03-05T18:37:21.409Z Sending message to conversation +[REDACTED]942 with timestamp 1520275041408
INFO  2018-03-05T18:37:21.476Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]942
INFO  2018-03-05T18:37:21.799Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]942 200 Success
INFO  2018-03-05T18:37:21.826Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]651
INFO  2018-03-05T18:37:22.028Z queueing envelope +[REDACTED]942.1 1520275041408
INFO  2018-03-05T18:37:22.028Z delivery receipt from +[REDACTED]942.1 1520275041408
INFO  2018-03-05T18:37:22.154Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]651 200 Success

@scottnonnenberg scottnonnenberg changed the title Signal Desktop is very slow and mostly unresponsive Signal Desktop becomes unresponsive when sending a message Mar 6, 2018
@qcGVkzEG
Copy link

I have the same problem and I suspect this is some kind of concurrency/locking issue rather than simple resource consumption: In my experience, this happens mostly when sending two messages in quick succession, and when the receipt confirmation (double checkmark) for the previous message is not shown yet. Thus I guess this delay occurs because Signal is still waiting for some step of sending the previous message to finish.

(If the recipient is in fact offline, the same thing still happens for some limited timespan even though the double checkmark for the previous message does not show up at all, so I think this is only tangentially related to the checkmark. But there is definitely some correlation.)

I've also experienced the same delay when trying to send a message after having received a message a moment ago, supporting the idea that this is somehow related to the scheduling of operations while sending/receiving.

@MarcSN311
Copy link

@scottnonnenberg do you need any more information/debug logs?

@scottnonnenberg-signal
Copy link
Contributor

@MarcSN311 Yes, we definitely need more information. As we can't reproduce these delays on the computers we have access to, we need full debug logs from everyone reporting this. And, your help in being a detective: does slowness happen at other times? When did the slowness start happening - immediately after a new installation, or after it built up a message history? Or did you import from the Chrome app, so you started with a lot of messages?

@MarcSN311
Copy link

I did some testing. The long sending times seem to correlate with long conversations. In short conversations the send pre-checks take reproducible 2-10ms. In Long conversations it takes longer:

INFO  2018-03-14T11:59:48.374Z Send pre-checks took 2353 milliseconds
INFO  2018-03-14T11:59:48.383Z Sending message to conversation group([REDACTED]ÑâÆ) with timestamp 1521028788381
INFO  2018-03-14T11:59:48.435Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]904
INFO  2018-03-14T11:59:48.722Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]904 200 Success
INFO  2018-03-14T11:59:48.745Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]651
INFO  2018-03-14T11:59:49.031Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]651 200 Success
INFO  2018-03-14T11:59:53.285Z Send pre-checks took 3273 milliseconds
INFO  2018-03-14T11:59:53.295Z Sending message to conversation group([REDACTED]ÑâÆ) with timestamp 1521028793293
INFO  2018-03-14T11:59:53.328Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]904
INFO  2018-03-14T11:59:53.608Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]904 200 Success
INFO  2018-03-14T11:59:53.630Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]651
INFO  2018-03-14T11:59:53.905Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]651 200 Success
INFO  2018-03-14T11:59:58.208Z Send pre-checks took 3476 milliseconds
INFO  2018-03-14T11:59:58.216Z Sending message to conversation group([REDACTED]ÑâÆ) with timestamp 1521028798216
INFO  2018-03-14T11:59:58.269Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]904
INFO  2018-03-14T11:59:58.557Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]904 200 Success
INFO  2018-03-14T11:59:58.577Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]651
INFO  2018-03-14T11:59:58.860Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]651 200 Success

This might be a consequence of #1887

@brianreumere
Copy link

I'm having this same issue for a while now (at least a couple of months, maybe longer). I've only noticed it intermittently on really large conversations, but it sometimes will hang for almost 10 seconds before a message is sent. I've uploaded two debug logs, both taken shortly after an almost 10-second delay in sending a message.

Platform info

Signal version: v1.6.0

Operating System: macOS 10.13.3

Linked Device Version: iOS 11.2.6

Link to debug log

https://gist.github.com/anonymous/0e2a9364e1d330c5e002ae361eea82cc

https://gist.github.com/anonymous/c5eeb013a444aa38c444c03311870b1a

@MarcSN311
Copy link

@brianpcurran your log is quite long, it might be helpful if you told us the time and the last 3 digits of the receipients phone number to isolate to corresponding log messages.

in your second log there is this portion:

INFO  2018-03-13T16:49:43.983Z Send pre-checks took 23 milliseconds
INFO  2018-03-13T16:49:44.005Z Sending message to conversation +[REDACTED]674 with timestamp 1520959784004
INFO  2018-03-13T16:49:44.245Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]674
INFO  2018-03-13T16:49:44.350Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]674 200 Success
INFO  2018-03-13T16:49:44.466Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]169
INFO  2018-03-13T16:49:44.540Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]169 200 Success
INFO  2018-03-13T16:49:44.695Z queueing envelope +[REDACTED]674.5 1520959784004
INFO  2018-03-13T16:49:44.696Z delivery receipt from +[REDACTED]674.5 1520959784004
INFO  2018-03-13T16:49:55.583Z Send pre-checks took 7240 milliseconds
INFO  2018-03-13T16:49:55.603Z Sending message to conversation +[REDACTED]674 with timestamp 1520959795603
INFO  2018-03-13T16:49:55.631Z queueing envelope +[REDACTED]674.1 1520959784004
INFO  2018-03-13T16:49:55.632Z delivery receipt from +[REDACTED]674.1 1520959784004
INFO  2018-03-13T16:49:55.941Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]674
INFO  2018-03-13T16:49:56.054Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]674 200 Success
INFO  2018-03-13T16:49:56.193Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]169
INFO  2018-03-13T16:49:56.203Z queueing envelope +[REDACTED]674.1 1520959795603
INFO  2018-03-13T16:49:56.204Z delivery receipt from +[REDACTED]674.1 1520959795603
INFO  2018-03-13T16:49:56.293Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]169 200 Success
INFO  2018-03-13T16:49:56.370Z queueing envelope +[REDACTED]674.5 1520959795603
INFO 2018-03-13T16:49:56.370Z delivery receipt from +[REDACTED]674.5 1520959795603

but i can't find a simmilar part in your first log.

@MarcSN311
Copy link

MarcSN311 commented Mar 15, 2018

@scottnonnenberg-signal i did some further debugging:
https://github.com/signalapp/Signal-Desktop/blob/fb2ebddaa326b283eed22d6175992ba8ecf2fee1/js/views/conversation_view.js
most of the time is spent in line 932 this.model.updateVerified().then(function() {

INFO  2018-03-15T20:03:56.593Z line 933.   took 3695 milliseconds
INFO  2018-03-15T20:03:56.594Z line 934.   getUnverified took 0 milliseconds
INFO  2018-03-15T20:03:56.597Z line 1017. now in sendMessage. took 4 millisecond
INFO  2018-03-15T20:03:56.601Z Send pre-checks took 4 milliseconds

(time was reset after eacht log)

@scottnonnenberg-signal
Copy link
Contributor

@MarcSN311 Yep, and those are needed roundtrips with the database to get the latest trust state for the contacts you're about to send to. I'm not sure there's much we can do about that, aside from large-scale changes to better cache that information in memory (and update it there when things change).

Would you say that your app in general is slow? We've started to see a pattern where continued heavy use of the app makes everything slower. Every database access takes longer, no matter what it's doing.

@brianreumere
Copy link

@MarcSN311 I mean to mention that in both cases the ~10-second delays happened just before I generated the debug logs.

@MarcSN311
Copy link

Switching to long conversations (over 10k messages) is very slow (up to 20s), the shorter the conversation, the shorter loading times (down to about a second). This is on a Quadcore i7, SSD, 32GB Ram system.

How about loading the trust state when opening a conversation and keeping it in memory (obviously updating it when sending/receiving a new message)?

@rubin110
Copy link

I'm in the same boat. Sending some messages causes the client to be unresponsive for ~10-20 seconds, as does simply clicking on previous conversations that have a long backlog.

@scottnonnenberg-signal
Copy link
Contributor

@rubin110 When you say 'unresponsive' you mean that you can't do anything, including opening the OS menu or switching conversations? I want to be very careful about waiting on a loading screen vs. waiting for the app to come back from a true hang.

@rubin110
Copy link

Mmm, you're right there's a difference here.

After typing a message into a conversation with a long backlog and hitting enter, the text of the message will remain in the input text field, however I can still scroll through the conversation and jump over to other conversations.

Similarly when clicking on a conversation with a long backlog and getting the loading triple circle throbber animation, I can still click onto other conversations without issue.

@dmzpkts
Copy link

dmzpkts commented Mar 22, 2018

What are pre-checks? Because sometimes they take OVER A MINUTE, before my messages send.

Debug Log: https://debuglogs.org/a1017f840ec530e8676944218ea3b23a676182a089bb01d6227eb4ea8d693a94

INFO 2018-03-22T19:53:58.025Z Sending a keepalive message
INFO 2018-03-22T19:54:00.500Z queueing envelope +[REDACTED]657.1 1521748438865
INFO 2018-03-22T19:54:00.501Z message from +[REDACTED]657.1 1521748438865
INFO 2018-03-22T19:54:00.845Z data message from +[REDACTED]657.1 1521748438865
INFO 2018-03-22T19:54:01.573Z adding notification
INFO 2018-03-22T19:54:01.573Z Update notifications: isFocused: false isEnabled: true numNotifications: 1 shouldPlayNotificationSound: true
INFO 2018-03-22T19:54:01.574Z draw attention
INFO 2018-03-22T19:54:01.575Z remove all notifications
INFO 2018-03-22T19:54:09.874Z show window
INFO 2018-03-22T19:54:09.886Z open inbox
INFO 2018-03-22T19:54:10.383Z Updating BrowserWindow config: {"maximized":false,"autoHideMenuBar":false,"width":1536,"height":824,"x":0,"y":0}
INFO 2018-03-22T19:54:55.206Z Sending a keepalive message
INFO 2018-03-22T19:55:31.884Z Sending 1 read receipts
INFO 2018-03-22T19:55:31.886Z Sending 1 read receipts

INFO 2018-03-22T19:55:31.896Z Send pre-checks took 79452 milliseconds <------WTF!?!?!?!?!?!? This was also accompanied by INTENSE disk usage by signal. Over 20MB/s and higher spikes.

INFO 2018-03-22T19:55:31.905Z Sending message to conversation +[REDACTED]657 with timestamp 1521748531905
INFO 2018-03-22T19:55:31.911Z Sending 1 read receipts
INFO 2018-03-22T19:55:31.913Z Sending 1 read receipts
INFO 2018-03-22T19:55:31.914Z Sending 1 read receipts
INFO 2018-03-22T19:55:31.916Z Sending 1 read receipts
INFO 2018-03-22T19:55:31.917Z Sending 1 read receipts
INFO 2018-03-22T19:55:32.892Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665
INFO 2018-03-22T19:55:33.176Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665 200 Success
INFO 2018-03-22T19:55:37.725Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657
INFO 2018-03-22T19:55:37.923Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657 200 Success
INFO 2018-03-22T19:55:37.935Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665
INFO 2018-03-22T19:55:38.189Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665 200 Success
INFO 2018-03-22T19:55:38.190Z queueing envelope +[REDACTED]657.4 1521748531884
INFO 2018-03-22T19:55:38.191Z delivery receipt from +[REDACTED]657.4 1521748531884
INFO 2018-03-22T19:55:38.192Z No message for delivery receipt +[REDACTED]657 1521748531884
INFO 2018-03-22T19:55:38.355Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657
INFO 2018-03-22T19:55:38.411Z queueing envelope +[REDACTED]657.1 1521748531884
INFO 2018-03-22T19:55:38.411Z delivery receipt from +[REDACTED]657.1 1521748531884
INFO 2018-03-22T19:55:38.412Z No message for delivery receipt +[REDACTED]657 1521748531884
INFO 2018-03-22T19:55:38.558Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657 200 Success
INFO 2018-03-22T19:55:38.590Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665
INFO 2018-03-22T19:55:38.644Z queueing envelope +[REDACTED]657.4 1521748531886
INFO 2018-03-22T19:55:38.644Z delivery receipt from +[REDACTED]657.4 1521748531886
INFO 2018-03-22T19:55:38.648Z No message for delivery receipt +[REDACTED]657 1521748531886
INFO 2018-03-22T19:55:38.785Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665 200 Success
INFO 2018-03-22T19:55:38.968Z queueing envelope +[REDACTED]657.1 1521748531886
INFO 2018-03-22T19:55:38.968Z delivery receipt from +[REDACTED]657.1 1521748531886
INFO 2018-03-22T19:55:39.023Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657
INFO 2018-03-22T19:55:39.028Z No message for delivery receipt +[REDACTED]657 1521748531886
INFO 2018-03-22T19:55:39.200Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665
INFO 2018-03-22T19:55:39.231Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657 200 Success
INFO 2018-03-22T19:55:39.332Z queueing envelope +[REDACTED]657.4 1521748531905
INFO 2018-03-22T19:55:39.332Z delivery receipt from +[REDACTED]657.4 1521748531905
INFO 2018-03-22T19:55:39.399Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665 200 Success
INFO 2018-03-22T19:55:39.533Z queueing envelope +[REDACTED]657.1 1521748531905
INFO 2018-03-22T19:55:39.533Z delivery receipt from +[REDACTED]657.1 1521748531905
INFO 2018-03-22T19:55:39.886Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657
INFO 2018-03-22T19:55:39.989Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665
INFO 2018-03-22T19:55:40.094Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657 200 Success
INFO 2018-03-22T19:55:40.182Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665 200 Success
INFO 2018-03-22T19:55:40.276Z queueing envelope +[REDACTED]657.4 1521748531912
INFO 2018-03-22T19:55:40.276Z delivery receipt from +[REDACTED]657.4 1521748531912
INFO 2018-03-22T19:55:40.277Z No message for delivery receipt +[REDACTED]657 1521748531912
INFO 2018-03-22T19:55:40.430Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657
INFO 2018-03-22T19:55:40.486Z queueing envelope +[REDACTED]657.1 1521748531912
INFO 2018-03-22T19:55:40.486Z delivery receipt from +[REDACTED]657.1 1521748531912
INFO 2018-03-22T19:55:40.487Z No message for delivery receipt +[REDACTED]657 1521748531912
INFO 2018-03-22T19:55:40.635Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657 200 Success
INFO 2018-03-22T19:55:40.718Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665
INFO 2018-03-22T19:55:40.774Z queueing envelope +[REDACTED]657.4 1521748531914
INFO 2018-03-22T19:55:40.774Z delivery receipt from +[REDACTED]657.4 1521748531914
INFO 2018-03-22T19:55:40.774Z No message for delivery receipt +[REDACTED]657 1521748531914
INFO 2018-03-22T19:55:40.912Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665 200 Success
INFO 2018-03-22T19:55:40.996Z queueing envelope +[REDACTED]657.1 1521748531914
INFO 2018-03-22T19:55:40.996Z delivery receipt from +[REDACTED]657.1 1521748531914
INFO 2018-03-22T19:55:40.997Z No message for delivery receipt +[REDACTED]657 1521748531914
INFO 2018-03-22T19:55:41.165Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657
INFO 2018-03-22T19:55:41.285Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665
INFO 2018-03-22T19:55:41.359Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657 200 Success
INFO 2018-03-22T19:55:41.526Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665 200 Success
INFO 2018-03-22T19:55:41.765Z queueing envelope +[REDACTED]657.1 1521748531915
INFO 2018-03-22T19:55:41.765Z delivery receipt from +[REDACTED]657.1 1521748531915
INFO 2018-03-22T19:55:41.805Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657
INFO 2018-03-22T19:55:41.807Z No message for delivery receipt +[REDACTED]657 1521748531915
INFO 2018-03-22T19:55:42.002Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657 200 Success
INFO 2018-03-22T19:55:42.008Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665
INFO 2018-03-22T19:55:42.202Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665 200 Success
INFO 2018-03-22T19:55:42.241Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657
INFO 2018-03-22T19:55:42.349Z queueing envelope +[REDACTED]657.1 1521748531916
INFO 2018-03-22T19:55:42.349Z delivery receipt from +[REDACTED]657.1 1521748531916
INFO 2018-03-22T19:55:42.351Z No message for delivery receipt +[REDACTED]657 1521748531916
INFO 2018-03-22T19:55:42.437Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657 200 Success
INFO 2018-03-22T19:55:42.494Z queueing envelope +[REDACTED]657.4 1521748531915
INFO 2018-03-22T19:55:42.494Z delivery receipt from +[REDACTED]657.4 1521748531915
INFO 2018-03-22T19:55:42.495Z No message for delivery receipt +[REDACTED]657 1521748531915
INFO 2018-03-22T19:55:42.552Z queueing envelope +[REDACTED]657.4 1521748531916
INFO 2018-03-22T19:55:42.552Z delivery receipt from +[REDACTED]657.4 1521748531916
INFO 2018-03-22T19:55:42.552Z No message for delivery receipt +[REDACTED]657 1521748531916
INFO 2018-03-22T19:55:42.671Z queueing envelope +[REDACTED]657.4 1521748531917
INFO 2018-03-22T19:55:42.671Z delivery receipt from +[REDACTED]657.4 1521748531917
INFO 2018-03-22T19:55:42.672Z No message for delivery receipt +[REDACTED]657 1521748531917
INFO 2018-03-22T19:55:42.830Z queueing envelope +[REDACTED]657.1 1521748531917
INFO 2018-03-22T19:55:42.830Z delivery receipt from +[REDACTED]657.1 1521748531917
INFO 2018-03-22T19:55:42.831Z No message for delivery receipt +[REDACTED]657 1521748531917
INFO 2018-03-22T19:55:45.614Z queueing envelope +[REDACTED]657.1 1521748544241
INFO 2018-03-22T19:55:45.614Z message from +[REDACTED]657.1 1521748544241
INFO 2018-03-22T19:55:45.614Z New remote ephemeral key
INFO 2018-03-22T19:55:45.703Z Deleting chain closed at 1521631510048
INFO 2018-03-22T19:55:45.922Z read receipt +[REDACTED]657 1521748531905
INFO 2018-03-22T19:55:54.919Z queueing envelope +[REDACTED]657.1 1521748553410
INFO 2018-03-22T19:55:54.920Z message from +[REDACTED]657.1 1521748553410
INFO 2018-03-22T19:55:55.032Z data message from +[REDACTED]657.1 1521748553410
INFO 2018-03-22T19:55:55.147Z adding notification
INFO 2018-03-22T19:55:55.147Z Update notifications: isFocused: false isEnabled: true numNotifications: 1 shouldPlayNotificationSound: true
INFO 2018-03-22T19:55:55.147Z draw attention
INFO 2018-03-22T19:55:55.148Z remove all notifications
INFO 2018-03-22T19:56:42.468Z Sending 1 read receipts
INFO 2018-03-22T19:56:42.651Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665
INFO 2018-03-22T19:56:42.775Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657
INFO 2018-03-22T19:56:42.894Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665 200 Success
INFO 2018-03-22T19:56:42.967Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657 200 Success
INFO 2018-03-22T19:56:43.062Z queueing envelope +[REDACTED]657.4 1521748602467
INFO 2018-03-22T19:56:43.062Z delivery receipt from +[REDACTED]657.4 1521748602467
INFO 2018-03-22T19:56:43.063Z No message for delivery receipt +[REDACTED]657 1521748602467
INFO 2018-03-22T19:56:43.427Z queueing envelope +[REDACTED]657.1 1521748602467
INFO 2018-03-22T19:56:43.428Z delivery receipt from +[REDACTED]657.1 1521748602467
INFO 2018-03-22T19:56:43.430Z No message for delivery receipt +[REDACTED]657 1521748602467
INFO 2018-03-22T19:57:01.198Z Send pre-checks took 10 milliseconds
INFO 2018-03-22T19:57:01.211Z Sending message to conversation +[REDACTED]657 with timestamp 1521748621210
INFO 2018-03-22T19:57:01.493Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657
INFO 2018-03-22T19:57:01.692Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]657 200 Success
INFO 2018-03-22T19:57:01.795Z queueing envelope +[REDACTED]657.4 1521748621210
INFO 2018-03-22T19:57:01.795Z delivery receipt from +[REDACTED]657.4 1521748621210
INFO 2018-03-22T19:57:01.922Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665
INFO 2018-03-22T19:57:01.961Z queueing envelope +[REDACTED]657.1 1521748621210
INFO 2018-03-22T19:57:01.962Z delivery receipt from +[REDACTED]657.1 1521748621210
INFO 2018-03-22T19:57:02.123Z PUT https://textsecure-service.whispersystems.org/v1/messages/+[REDACTED]665 200 Success
INFO 2018-03-22T19:57:56.927Z Sending a keepalive message

`

@dmzpkts
Copy link

dmzpkts commented Mar 23, 2018

If anyone cares, here's two days-ish worth of pre-check lines grepped out of a very large debug.log

https://0bin.net/paste/6IQad7O2Sdl6rJW6#HJnp4TmnTzTy1lXyfqPKensjK2eyMGI7TU8bMqIynoc

@scottnonnenberg-signal
Copy link
Contributor

@dmzpkts Thanks for that detective work! You really do have some outliers in there. First, pre-checks are a series of queries to the database to figure out if the people you're sending to are still trusted.

If they take a really long time, I wonder if you're sending to really large groups? Or perhaps your database/app/computer is overloaded - can you tell me anything else about what's going on with your computer, or what has happened recently in Signal Desktop when you see those long delays? Does anything else take a long time like that?

@dmzpkts
Copy link

dmzpkts commented Mar 25, 2018

Nope. One on one messages.

And no. Only in the conversation that had probably 3-4k messages in it.

The slowdown was gradual and progressive as the conversation message length increased. It felt like a bell curve. It started getting exponentially worse.

I ended up having to delete %appdata%\local\signal
Unlink
And relinking...

I couldnt take it anymore. It was getting worse and worse.

Since doing that my messages send instantly.

@scottnonnenberg-signal
Copy link
Contributor

@dmzpkts Thanks for the follow-up. Sorry to hear that you needed to start over from scratch! But it is extremely useful for us to know that your performance characteristics changed so radically before and after. The good news is that we're making some pretty big changes to the way we store data that should help!

@tfish77
Copy link

tfish77 commented Apr 3, 2018

Same issue here on Windows 10 w/Signal 1.6.1. (Though I've seen it on my Macbook as well.)

Debug log: https://debuglogs.org/6a9491ec94a5a48d09eed26e1043f3cd59c887d6b8d3b9943f6fce21b7e3ea6e

@gasi-signal
Copy link
Contributor

gasi-signal commented Apr 3, 2018

@dmzpkts @tfish77 Could you please provide us the size of the IndexedDB folder in your Signal profile, e.g.

macOS: ~/Library/Application Support/Signal/IndexedDB (or similar)
Windows: %appdata%\Roaming\Signal\IndexedDB (or similar)

We are working on optimizing the database to improve the overall performance of accessing and interacting with large conversation threads. Your help is greatly appreciated.

@tfish77
Copy link

tfish77 commented Apr 4, 2018 via email

@gasi-signal
Copy link
Contributor

@tfish77 Thanks, that’s very helpful. We are actively working on reducing the database size by moving attachments to a folder on disk instead of storing them in the database. This should make the app more robust and faster. If you’d like to try this sooner, consider installing our beta: https://github.com/signalapp/Signal-Desktop/tree/3ae17528d3dea1960eb7947922f3163e88d55087#install-the-beta

@tfish77
Copy link

tfish77 commented Apr 4, 2018 via email

@rubin110
Copy link

rubin110 commented Apr 5, 2018

With Signal beta 1.7.0-beta.3 on Debian Sid, after some amount of loading while the app launched, clicking on my conversations now is responsive and takes about ~5-7 seconds for ones with a long backlog. Typing in a message and hitting enter, it posts the message and gives me access back to the text field within a second.

As stated in #2163, the process while loading didn't ever go over about 300mb of real memory or about 2.5gb of virtual. Currently idling at 225mb real, 1.86gb virtual.

Do note I did just upgrade to a ThinkPad T480s with 24GB of ram, but it looks like whatever change has happened with 1.7.0-beta.3, it hardly used any of that available memory.

bitmoji

@frioux
Copy link

frioux commented Apr 7, 2018

Really looking forward to this upgrade ;) I just got a 225 meg strace to help debug, but I guess it's already solved

@dmzpkts
Copy link

dmzpkts commented Apr 12, 2018

image

Problem is beginning to return.

@gasi-signal
Copy link
Contributor

@dmzpkts Thanks for letting us know. That size information is that for IndexedDB or the whole Signal folder? We are slowly migrating attachments to disk and will probably speed up that process in upcoming releases to provide some relief. Can you share some specifics in terms of how you notice a slow-down, e.g. conversation history / length, number / size of attachments, etc.?

@rubin110
Copy link

For what it's worth, here's where my Signal user directory currently is after running on 1.7.0-beta3 since its release:

20180413-113202 rubin110@lines:~/.config/Signal Beta$ du -hd1
44K     ./GPUCache
4.0K    ./Local Storage
441M    ./attachments.noindex
4.8M    ./logs
25M     ./blob_storage
5.5G    ./IndexedDB
12K     ./databases
6.0G    .

You can see what it was 21 days ago when I was running 1.7.0-beta2 here.

@gasi-signal
Copy link
Contributor

@rubin110 Thanks for sharing. I can see that we pulled out 441MB of attachments (attachments.noindex) and your IndexedDB has shrunk by ~100MB (5.6GB --> 5.5GB).

Sadly, IndexedDB does not eagerly compact itself and we don’t have any mechanism / API to trigger compaction. However, we found that repeated writes to the database trigger background compaction.

We are hopeful this will improve the situation with continued use of the app. In the meantime, this means disk usage for Signal will grow (as attachments are saved to disk and the database doesn’t shrink right away) in favor of better performance and stability.

@frioux
Copy link

frioux commented Apr 14, 2018

Sadly this does not seem to have helped the performance on mine. Here's the size information for Signal 1.7.1:

4.0K    /home/frew/.config/Signal/Local Storage
1.6M    /home/frew/.config/Signal/attachments.noindex/31
36K     /home/frew/.config/Signal/attachments.noindex/ba
1.6M    /home/frew/.config/Signal/attachments.noindex
592K    /home/frew/.config/Signal/GPUCache
1.6M    /home/frew/.config/Signal/logs
4.0K    /home/frew/.config/Signal/blob_storage
2.1G    /home/frew/.config/Signal/IndexedDB/file__0.indexeddb.leveldb
2.1G    /home/frew/.config/Signal/IndexedDB
28K     /home/frew/.config/Signal/databases
2.1G    /home/frew/.config/Signal

Let me know what I can do to help, if anything.

@scottnonnenberg-signal
Copy link
Contributor

@frioux Please keep Signal Desktop open, since it is always moving attachments to disk in background. The more files it is able to move out of the database, the better your performance should get.

@frioux
Copy link

frioux commented Apr 16, 2018

Oh ok for sure! It's usually open if my laptop is on, which has to be something like 12 hours a day. I do see that there are many, many more attachments (was 1.6M, now it's 248M) so it's doing it's thing. Any idea how to know when it's done or what the progress is?

@scottnonnenberg-signal
Copy link
Contributor

@frioux If you pop open the log, you'll see log entries that start with Upgrade message schema: - you can tell how far you are on the upgrade roughly by looking at the lastProcessedIndex in the expanded log object. The first character of that ID will go from zero to F. When it gets to F, you know you're getting close to being done.

@frioux
Copy link

frioux commented Apr 17, 2018

Thanks! Looks like it's about halfway through.

@rubin110
Copy link

Wow, Signal has been running nonstop whenever my laptop's been awake since he 1.7.0-beta3 update, and it's only up to "2..." in the processedindex.

Anyway I can tell Signal to just to max out on all cores and get this done sooner?

@scottnonnenberg-signal
Copy link
Contributor

@rubin110 We were very conservative in this first take on background export, just a few messages at a time. We expect that it might take ~20 minutes all at once on a big installation, so we haven't enabled the bulk export yet. But it sounds like you want it! Thanks for the feedback.

@frioux
Copy link

frioux commented Apr 18, 2018 via email

@dmzpkts
Copy link

dmzpkts commented Apr 19, 2018

@gasi-signal It was the indexdb folder. Going back and looking now after the most recent updates, my whole installation is down to ~611MB with 244MB in the attachments folder.

IDK what changes you guys made but they seem to help.. I havent noticed any lag after hitting "enter" lately.

@rubin110
Copy link

6 days later, I'm up to 39f.... :(

@rubin110
Copy link

About a month later...

cdc...

So close.

I'm also noticing Signal 1.11.0-beta.5 eating about 15% - 20% of my CPU now.

@scottnonnenberg-signal
Copy link
Contributor

scottnonnenberg-signal commented May 16, 2018

@rubin110 Yup, we increased the rate of background migrations: #2314

You really had a lot of attachments in your database!

@ghost
Copy link
Author

ghost commented May 20, 2018

Hello there,

Thanks all for sharing your insights. As mentioned before the issue has been solved. I no longer encounter theses lags.

🎉

@ghost ghost closed this as completed May 20, 2018
This issue was closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

No branches or pull requests

10 participants