Very slow multiple add/delete operations

epiniguin commented 5 months ago

Subject of the issue

I installed Vaultwarden and Bitwarden Unified Beta for testing and comparing. Both are installed as Docker containers on the same Debian VM(It is 8 cores Intel Xeon with 4GB RAM. So it is not a slow server). Both vaults use a shared Postgresql installed on the same VM as Docker container.

Both vaults are empty before testing. Both are behind the same Nginx proxy installed on the router.

I use the web vault, the Firefox official Bitwarden extension and the Android official Bitwarden app.

The clients and the servers are in the same LAN.

For a testing purpose I exported 427 passwords from Firefox to CSV. I imported and after some pause deleted these items. After that I emptied the recycle bin. I tried to import from web vaults and a Firefox extension - the results were the same, so I guess it is not a client issue. Deleting and recycle bin emptying are possible only from the web vaults.

The results are in the table below. When testing Vaultwarden with enabled push notifications it was difficult to measure the times precise because of web vault 60s timeout errors. Besides, after these timeouts the data in the Vaultwarden web vault stopped to refresh and it needed to renew the page and to unlock the vault.

Operation	Vaultwarden(disabled push)	Vaultwarden(enabled push)	Bitwarden(enabled push)
Import 427 items	24s	24s	12s
Delete 427 items	14s	130-150s	3s
Empty recycle bin(427 items)	41s	130-150s	3s

Deployment environment

Your environment (Generated via diagnostics page)

Vaultwarden version: v1.30.5
Web-vault version: v2024.1.2b
OS/Arch: linux/x86_64
Running within a container: true (Base: Debian)
Environment settings overridden: false
Uses a reverse proxy: true
IP Header check: true (X-Real-IP)
Internet access: true
Internet access via a proxy: false
DNS Check: true
Browser/Server Time Check: true
Server/NTP Time Check: true
Domain Configuration Check: true
HTTPS Check: true
Database type: PostgreSQL
Database version: PostgreSQL 16.3 (Debian 16.3-1.pgdg120+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
Clients used:
Reverse proxy and version:
Other relevant information:

Config (Generated via diagnostics page)

Show Running Config

**Environment settings which are overridden:** ```json { "_duo_akey": null, "_enable_duo": true, "_enable_email_2fa": true, "_enable_smtp": true, "_enable_yubico": true, "_icon_service_csp": "", "_icon_service_url": "", "_ip_header_enabled": true, "_smtp_img_src": "cid:", "admin_ratelimit_max_burst": 3, "admin_ratelimit_seconds": 300, "admin_session_lifetime": 20, "admin_token": "***", "allowed_iframe_ancestors": "", "attachments_folder": "data/attachments", "auth_request_purge_schedule": "30 * * * * *", "authenticator_disable_time_drift": false, "data_folder": "data", "database_conn_init": "", "database_max_conns": 10, "database_timeout": 30, "database_url": "**********://**********************************************", "db_connection_retries": 15, "disable_2fa_remember": false, "disable_admin_token": false, "disable_icon_download": false, "domain": "*****://***************", "domain_origin": "*****://***************", "domain_path": "", "domain_set": true, "duo_host": null, "duo_ikey": null, "duo_skey": null, "email_attempts_limit": 3, "email_change_allowed": true, "email_expiration_time": 600, "email_token_size": 6, "emergency_access_allowed": true, "emergency_notification_reminder_schedule": "0 3 * * * *", "emergency_request_timeout_schedule": "0 7 * * * *", "enable_db_wal": true, "event_cleanup_schedule": "0 10 0 * * *", "events_days_retain": null, "experimental_client_feature_flags": "fido2-vault-credentials", "extended_logging": true, "helo_name": null, "hibp_api_key": null, "icon_blacklist_non_global_ips": true, "icon_blacklist_regex": null, "icon_cache_folder": "data/icon_cache", "icon_cache_negttl": 259200, "icon_cache_ttl": 2592000, "icon_download_timeout": 10, "icon_redirect_code": 302, "icon_service": "internal", "incomplete_2fa_schedule": "30 * * * * *", "incomplete_2fa_time_limit": 3, "invitation_expiration_hours": 120, "invitation_org_name": "Vaultwarden", "invitations_allowed": true, "ip_header": "X-Real-IP", "job_poll_interval_ms": 30000, "log_file": "/data/vaultwarden.log", "log_level": "Info", "log_timestamp_format": "%Y-%m-%d %H:%M:%S.%3f", "login_ratelimit_max_burst": 10, "login_ratelimit_seconds": 60, "org_attachment_limit": null, "org_creation_users": "", "org_events_enabled": false, "org_groups_enabled": false, "password_hints_allowed": true, "password_iterations": 600000, "push_enabled": true, "push_identity_uri": "https://identity.bitwarden.com", "push_installation_id": "***", "push_installation_key": "***", "push_relay_uri": "https://push.bitwarden.com", "reload_templates": false, "require_device_email": false, "rsa_key_filename": "data/rsa_key", "send_purge_schedule": "0 5 * * * *", "sendmail_command": null, "sends_allowed": true, "sends_folder": "data/sends", "show_password_hint": false, "signups_allowed": true, "signups_domains_whitelist": "", "signups_verify": false, "signups_verify_resend_limit": 6, "signups_verify_resend_time": 3600, "smtp_accept_invalid_certs": false, "smtp_accept_invalid_hostnames": false, "smtp_auth_mechanism": null, "smtp_debug": false, "smtp_embed_images": true, "smtp_explicit_tls": null, "smtp_from": "*************", "smtp_from_name": "Vaultwarden", "smtp_host": "*******************", "smtp_password": "***", "smtp_port": 587, "smtp_security": "starttls", "smtp_ssl": null, "smtp_timeout": 15, "smtp_username": "*************", "templates_folder": "data/templates", "tmp_folder": "data/tmp", "trash_auto_delete_days": null, "trash_purge_schedule": "0 5 0 * * *", "use_sendmail": false, "use_syslog": false, "user_attachment_limit": null, "user_send_limit": null, "web_vault_enabled": true, "web_vault_folder": "web-vault/", "websocket_address": "0.0.0.0", "websocket_enabled": false, "websocket_port": 3012, "yubico_client_id": null, "yubico_secret_key": null, "yubico_server": null } ```

vaultwarden version: 1.30.5

Install method: Docker
Clients used: web vault, firefox extension
Reverse proxy and version: nginx/1.26.1 installed on the router
MySQL/MariaDB or PostgreSQL version: PostgreSQL 16.3 (Debian 16.3-1.pgdg120+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit

Steps to reproduce

Import 300-500 items from CSV.
Delete these items.
Empty recycle bin.
Expected behaviour

Vaultwarden and Bitwarden should work at approximately the same speed.

Actual behaviour

Vaultwarden is much slower than Bitwarden particularly with enabled push notifications.

Troubleshooting data

BlackDex commented 5 months ago

Hmm, i thought we fixed that already in testing tagged images, but I'm not sure. Because we do not push on import, but we shouldn't do this on bulk delete/trash-clean too. But we should see if we can trigger a refresh or something else for the other clients, not sure if that is possible currently.

BlackDex commented 5 months ago

Also, there is a similar issue #4669. The only way i can think of is running the notifications in there own thread, and handle the pushes outside of the web/main threads.

epiniguin commented 5 months ago

It is slower without enabled push also. I guess that 427 items is not a problem at all for Postgresql. That's why Bitwarden deletes them for 3s(with https delays).

epiniguin commented 5 months ago

Also, there is a similar issue #4669.

In my case I don't have any delay for single operations. Only for multiple.

stefan0xC commented 5 months ago

I can't really reproduce your findings (with the vaultwarden/server:latest image and also using postgres 16). With 330 items each operation (in the web-vault) took about 1-1.5 seconds with Vaultwarden.

[2024-07-03 06:16:15.476][request][INFO] POST /api/ciphers/import
[2024-07-03 06:16:16.599][response][INFO] (post_ciphers_import) POST /api/ciphers/import => 200 OK
...
[2024-07-03 06:16:41.966][request][INFO] PUT /api/ciphers/delete
[2024-07-03 06:16:42.961][response][INFO] (delete_cipher_selected_put) PUT /api/ciphers/delete => 200 OK
...
[2024-07-03 06:16:53.331][request][INFO] DELETE /api/ciphers
[2024-07-03 06:16:54.417][response][INFO] (delete_cipher_selected) DELETE /api/ciphers => 200 OK

edit: even with 499 items it's 1.7-2 seconds for these requests.

epiniguin commented 5 months ago

It's my log. I don't know what is the difference between our systems. But as I wrote Bitwarden works fast on the same infrastructure.

What diagnostic could I do?

[2024-07-03 09:40:19.431][request][INFO] POST /api/ciphers/import
[2024-07-03 09:40:43.737][response][INFO] (post_ciphers_import) POST /api/ciphers/import => 200 OK
...
[2024-07-03 09:43:04.312][request][INFO] PUT /api/ciphers/delete
[2024-07-03 09:44:38.549][response][INFO] (delete_cipher_selected_put) PUT /api/ciphers/delete => 200 OK
....
[2024-07-03 09:46:49.204][request][INFO] DELETE /api/ciphers
[2024-07-03 09:48:26.149][response][INFO] (delete_cipher_selected) DELETE /api/ciphers => 200 OK

BlackDex commented 5 months ago

Try to enable LOG_LEVEL=debug and see if that provides more (and enough) details, else set it to trace that should give a lot details.

stefan0xC commented 5 months ago

Okay, I can only reproduce the issue if I enable push.

epiniguin commented 5 months ago

Okay, I can only reproduce the issue if I enable push.

Attached delete logs with enabled push.

delete_with_push.txt bin_with_push.txt

epiniguin commented 5 months ago

This is emptying bin trace with disabled push. I don't see anything bad, but my timing is 23s, not 1.5s as yours.

bin_wo_push_trace.txt

dani-garcia / vaultwarden