GUI freezes after sync of many (~200) sources

cfm commented 2 years ago

Description

After each sync against a Server with many sources and entries—

sqlite> SELECT COUNT(*) FROM sources;
196
sqlite> SELECT COUNT(*) FROM messages;
374
sqlite> SELECT COUNT(*) FROM replies;
440
sqlite> SELECT COUNT(*) FROM draftreplies;
1
sqlite> SELECT COUNT(*) FROM files;
375

—the GUI freezes briefly.

Steps to Reproduce

On the Application Server:

sdadmin@app:~$ sudo -u www-data /var/www/securedrop/loaddata.py --count 200

On the Workstation:

Start the Client with LOGLEVEL=debug securedrop-client and log in.
Let the Client sync fully to catch up to the current server state.
Move your cursor rapidly back and forth between any two sources A and B in the source listing for ~30 seconds.

Expected Behavior

The source under your cursor is always highlighted, including across each 15-second sync interval.

Actual Behavior

Shortly after each sync, the highlight freezes on source A, even if you move your cursor to source B. (The rest of the GUI is also frozen; this is a minimal reproduction.)

Comments

First noticed on 0.7.0-rc1-dev-20220414-224612+buster for #1465. Reproduced on 0.6.0+buster.

sd-log at this moment shows:

[...]
Apr 14 18:01:10 localhost 2022-04-14 18:01:10,855 - securedrop_client.storage:450(update_replies) DEBUG: Updated reply 9fb424ef-b235-4c85-a92c-4eb5743cf584
Apr 14 18:01:10 localhost 2022-04-14 18:01:10,859 - securedrop_client.storage:450(update_replies) DEBUG: Updated reply 33062a80-fae4-47cf-8a7b-8a4aa83b538d
Apr 14 18:01:10 localhost 2022-04-14 18:01:10,862 - securedrop_client.storage:450(update_replies) DEBUG: Updated reply 37dba6c8-2b8e-42c3-bf77-fff5a50362e2
Apr 14 18:01:10 localhost 2022-04-14 18:01:10,872 - securedrop_client.storage:204(chronometer) INFO: update_replies duration: 1.6959s
Apr 14 18:01:14 localhost 2022-04-14 18:01:14,679 - securedrop_client.queue:268(resume_queues) DEBUG: Resuming main queue
Apr 14 18:01:14 localhost 2022-04-14 18:01:14,680 - securedrop_client.queue:271(resume_queues) DEBUG: Resuming download queue

The freeze is indeed approximately 1.7 seconds.

rocodes commented 2 years ago

Thank you for filing! Since this is not a regression, I suspect we will not address it in this release, but we should put some time aside for it for sure.

sssoleileraaa commented 2 years ago

During work on this issue, it would be helpful to take a look at our performance testing wiki page and update it with results as you go: https://github.com/freedomofpress/securedrop-client/wiki/Scalability-&-Performance

cfm commented 2 years ago

Looks like the culprit is a main-thread blocking call in MainView.show_sources() to SourceList.update():

May 24 14:21:53 localhost 2022-05-24 14:21:53,827 - securedrop_client.storage:640(update_replies) DEBUG: Updated reply 66e55446-12e4-4624-8949-1ea361f8c30b
May 24 14:21:53 localhost 2022-05-24 14:21:53,829 - securedrop_client.storage:640(update_replies) DEBUG: Updated reply 473d1e3b-6320-40f4-8345-8ab3c682ad1c
May 24 14:21:53 localhost 2022-05-24 14:21:53,834 - securedrop_client.storage:640(update_replies) DEBUG: Updated reply a2a99174-ba0d-4c9c-8e5a-423b544b920c
May 24 14:21:53 localhost 2022-05-24 14:21:53,851 - securedrop_client.storage:204(chronometer) INFO: update_replies duration: 4.5702s
May 24 14:21:53 localhost 2022-05-24 14:21:53,851 - securedrop_client.api_jobs.sync:204(chronometer) INFO: update_local_storage duration: 14.1887s
May 24 14:21:53 localhost 2022-05-24 14:21:53,853 - securedrop_client.api_jobs.sync:204(chronometer) INFO: _update_state duration: 0.0016s
May 24 14:21:53 localhost 2022-05-24 14:21:53,902 - securedrop_client.storage:204(chronometer) INFO: get_local_sources duration: 0.0058s
May 24 14:22:02 localhost 2022-05-24 14:22:02,331 - securedrop_client.gui.widgets:204(chronometer) INFO: source_list.update duration: 8.4274s
May 24 14:22:02 localhost 2022-05-24 14:22:02,332 - securedrop_client.gui.widgets:204(chronometer) INFO: show_sources loop duration: 0.0000s
May 24 14:22:02 localhost 2022-05-24 14:22:02,333 - securedrop_client.logic:204(chronometer) INFO: show_sources duration: 8.4295s
May 24 14:22:02 localhost 2022-05-24 14:22:02,333 - securedrop_client.logic:204(chronometer) INFO: update_sources duration: 8.4365s
May 24 14:22:02 localhost 2022-05-24 14:22:02,333 - securedrop_client.logic:204(chronometer) INFO: refresh_current_source_conversation duration: 0.0000s
May 24 14:22:02 localhost 2022-05-24 14:22:02,352 - securedrop_client.queue:320(resume_queues) DEBUG: Resuming main queue
May 24 14:22:02 localhost 2022-05-24 14:22:02,354 - securedrop_client.queue:323(resume_queues) DEBUG: Resuming download queue

Instrumentation (patch)

```diff diff --git a/securedrop_client/api_jobs/sync.py b/securedrop_client/api_jobs/sync.py index 06d275b..0fedcdf 100644 --- a/securedrop_client/api_jobs/sync.py +++ b/securedrop_client/api_jobs/sync.py @@ -9,6 +9,7 @@ from securedrop_client import state from securedrop_client.api_jobs.base import ApiJob from securedrop_client.db import DeletedUser, DraftReply, User from securedrop_client.storage import get_remote_data, update_local_storage +from securedrop_client.utils import chronometer logger = logging.getLogger(__name__) @@ -44,9 +45,11 @@ class MetadataSyncJob(ApiJob): users = api_client.get_users() MetadataSyncJob._update_users(session, users) sources, submissions, replies = get_remote_data(api_client) - update_local_storage(session, sources, submissions, replies, self.data_dir) + with chronometer(logger, 'update_local_storage'): + update_local_storage(session, sources, submissions, replies, self.data_dir) if self._state is not None: - _update_state(self._state, submissions) + with chronometer(logger, '_update_state'): + _update_state(self._state, submissions) def _update_users(session: Session, remote_users: List[SDKUser]) -> None: """ diff --git a/securedrop_client/app.py b/securedrop_client/app.py index 5a1d334..639aa73 100644 --- a/securedrop_client/app.py +++ b/securedrop_client/app.py @@ -24,6 +24,7 @@ import platform import signal import socket import sys +import traceback from argparse import ArgumentParser from gettext import gettext as _ from logging.handlers import SysLogHandler, TimedRotatingFileHandler @@ -124,7 +125,8 @@ def configure_logging(sdc_home: Path) -> None: def configure_signal_handlers(app: QApplication) -> None: - def signal_handler(*nargs) -> None: # type: ignore [no-untyped-def] + def signal_handler(signum, frame) -> None: # type: ignore [no-untyped-def] + traceback.print_stack(frame) app.quit() for sig in [signal.SIGINT, signal.SIGTERM]: diff --git a/securedrop_client/gui/widgets.py b/securedrop_client/gui/widgets.py index b469168..0930f59 100644 --- a/securedrop_client/gui/widgets.py +++ b/securedrop_client/gui/widgets.py @@ -86,7 +86,7 @@ from securedrop_client.gui.source import DeleteSourceDialog from securedrop_client.logic import Controller from securedrop_client.resources import load_css, load_icon, load_image, load_movie from securedrop_client.storage import source_exists -from securedrop_client.utils import humanize_filesize +from securedrop_client.utils import chronometer, humanize_filesize logger = logging.getLogger(__name__) @@ -642,12 +642,15 @@ class MainView(QWidget): # If the source list in the GUI is empty, then we will run the optimized intial update. # Otherwise, do a regular source list update. if not self.source_list.source_items: - self.source_list.initial_update(sources) + with chronometer(logger, 'initial_update'): + self.source_list.initial_update(sources) else: - deleted_sources = self.source_list.update(sources) - for source_uuid in deleted_sources: - # Then call the function to remove the wrapper and its children. - self.delete_conversation(source_uuid) + with chronometer(logger, 'source_list.update'): + deleted_sources = self.source_list.update(sources) + with chronometer(logger, 'show_sources loop'): + for source_uuid in deleted_sources: + # Then call the function to remove the wrapper and its children. + self.delete_conversation(source_uuid) def on_source_changed(self) -> None: """ diff --git a/securedrop_client/logic.py b/securedrop_client/logic.py index c227028..e8c0ed6 100644 --- a/securedrop_client/logic.py +++ b/securedrop_client/logic.py @@ -63,7 +63,7 @@ from securedrop_client.crypto import GpgHelper from securedrop_client.export import Export from securedrop_client.queue import ApiJobQueue from securedrop_client.sync import ApiSync -from securedrop_client.utils import check_dir_permissions +from securedrop_client.utils import chronometer, check_dir_permissions logger = logging.getLogger(__name__) @@ -627,8 +627,10 @@ class Controller(QObject): missing_files = storage.update_missing_files(self.data_dir, self.session) for missed_file in missing_files: self.file_missing.emit(missed_file.source.uuid, missed_file.uuid, str(missed_file)) - self.update_sources() - self.gui.refresh_current_source_conversation() + with chronometer(logger, 'update_sources'): + self.update_sources() + with chronometer(logger, 'refresh_current_source_conversation'): + self.gui.refresh_current_source_conversation() self.download_new_messages() self.download_new_replies() self.sync_succeeded.emit() @@ -684,7 +686,8 @@ class Controller(QObject): Display the updated list of sources with those found in local storage. """ sources = list(storage.get_local_sources(self.session)) - self.gui.show_sources(sources) + with chronometer(logger, 'show_sources'): + self.gui.show_sources(sources) def mark_seen(self, source: db.Source) -> None: """ diff --git a/securedrop_client/storage.py b/securedrop_client/storage.py index 0bce8fb..8977dc5 100644 --- a/securedrop_client/storage.py +++ b/securedrop_client/storage.py @@ -69,7 +69,8 @@ def get_local_sources(session: Session) -> List[Source]: """ Return all source objects from the local database, newest first. """ - return session.query(Source).order_by(desc(Source.last_updated)).all() + with chronometer(logger, "get_local_sources"): + return session.query(Source).order_by(desc(Source.last_updated)).all() def delete_local_source_by_uuid(session: Session, uuid: str, data_dir: str) -> None: ```

freedomofpress / securedrop-client