Repository navigation
Serialisation errors keep occurring #7812
Description
Description
Postgresql keeps reporting serialisation errors
Steps to reproduce
- Start synapse
- Look at postgres log output
I honestly don't know what else is required to get these errors. I expect there to be no errors in my postgres log. There isn't any corresponding log output in homeserver.log either. The postgres logs show errors of the following type:
Jul 09 19:32:19 blackbird postgres[2834]: [24-1] 2020-07-09 14:02:19.105 UTC [3316] ERROR: could not serialize access due to concurrent delete
Jul 09 19:32:19 blackbird postgres[2834]: [24-2] 2020-07-09 14:02:19.105 UTC [3316] STATEMENT: DELETE FROM device_lists_stream WHERE user_id = '@redacted_id' AND device_id = 'redacted_id AND stream_id < redacted_id
Jul 09 19:37:53 blackbird postgres[2840]: [14-1] 2020-07-09 14:07:53.216 UTC [3318] ERROR: could not serialize access due to concurrent delete
Jul 09 19:37:53 blackbird postgres[2840]: [14-2] 2020-07-09 14:07:53.216 UTC [3318] STATEMENT: DELETE FROM device_lists_stream WHERE user_id = '@redacted_id' AND device_id = 'redacted_id' AND stream_id < redacted_id
Jul 09 19:49:39 blackbird postgres[2837]: [17-1] 2020-07-09 14:19:39.951 UTC [3317] ERROR: could not serialize access due to concurrent delete
Jul 09 19:49:39 blackbird postgres[2837]: [17-2] 2020-07-09 14:19:39.951 UTC [3317] STATEMENT: DELETE FROM presence_stream WHERE stream_id < redacted_id AND user_id =
Jul 09 19:49:39 blackbird postgres[2837]: [17-3] ANY(ARRAY['@redacted_id','@redacted_id','@redacted_id','@redacted_id','@jredacted_id','@redacted_id,'@redacted_id','@redacted_id','@redacted_id','@redacted_id,'... (37 ids)
Jul 09 19:49:39 blackbird postgres[2837]: [17-4] ','@redacted_id','@redacted_id','@redacted_id','@redacted_id','@redacted_id','@oredacted_id','@redacted_id'])
Jul 09 19:50:40 blackbird postgres[2837]: [18-1] 2020-07-09 14:20:40.722 UTC [3317] ERROR: could not serialize access due to concurrent delete
Jul 09 19:50:40 blackbird postgres[2837]: [18-2] 2020-07-09 14:20:40.722 UTC [3317] STATEMENT: DELETE FROM presence_stream WHERE stream_id < redacted_id AND user_id =
Jul 09 19:50:40 blackbird postgres[2837]: [18-3] ANY(ARRAY['Array similar to 17-3])
Jul 09 19:52:41 blackbird postgres[2829]: [17-1] 2020-07-09 14:22:41.751 UTC [3312] ERROR: could not serialize access due to concurrent delete
Jul 09 19:52:41 blackbird postgres[2829]: [17-2] 2020-07-09 14:22:41.751 UTC [3312] STATEMENT: DELETE FROM presence_stream WHERE stream_id < redacted_id AND user_id = ANY(ARRAY['@redacted_id'])
.
.
.
Jul 09 19:58:21 blackbird postgres[2831]: [14-1] 2020-07-09 14:28:21.260 UTC [3313] ERROR: duplicate key value violates unique constraint "device_uniqueness"
Jul 09 19:58:21 blackbird postgres[2831]: [14-2] 2020-07-09 14:28:21.260 UTC [3313] DETAIL: Key (user_id, device_id)=(@redacted_id, redacted_id) already exists.
Jul 09 19:58:21 blackbird postgres[2831]: [14-3] 2020-07-09 14:28:21.260 UTC [3313] STATEMENT: INSERT INTO devices (user_id, device_id, display_name, hidden) VALUES('@redacted_id', 'redacted_id', NULL, false)
Version information
- Homeserver: Not matrix.org
If not matrix.org:
-
Version: 1.16.0
-
Install method: Debian Package from Official Synapse repo
- Platform: Debian Buster
I'm running a custom build of postgresql 12.3 with the following configure options: ./configure --prefix=/usr --bindir=/usr/bin --sbindir=/usr/bin --libexecdir=/usr/libexec --sysconfdir=/etc --without-perl --without-python --without-tcl --without-gssapi --without-llvm --with-icu --without-openssl --without-pam --without-bsd-auth --without-ldap --without-systemd --with-uuid=e2fs --without-bonjour --with-libxml --with-libxslt --with-system-tzdata=/usr/share/zoneinfo --build=x86_64-linux-gnu --with-readline --with-libedit-preferred on a Debian Buster container.
Synapse is running in a deliberately stripped down container on lxc which is built to imitate distroless containers. It has these packages installed explicitly: matrix-synapse-py3, libpq5, tzdata, ca-certificates, libc6, libgcc1, libstdc++6. Apart from these, all other installed packages are dependencies of the above.
A full list of installed packages is: matrix-synapse-py3 libpq5 tzdata python3-distutils libpython3-stdlib libc6 libgcc1 libstdc++6 libsystemd0 python3.7 libgssapi-krb5-2 libldap-2.4-2 libssl1.1 python3-lib2to3 libpython3.7-stdlib gcc-8-base libgcrypt20 liblz4-1 liblzma5 python3.7-minimal mime-support libcom-err2 libk5crypto3 libkeyutils1 libkrb5-3 libkrb5support0 libgnutls30 libsasl2-2 libldap-common libpython3.7-minimal libbz2-1.0 libdb5.3 libffi6 libmpdec2 libncursesw6 libreadline7 libsqlite3-0 libtinfo6 libuuid1 libgpg-error0 libexpat1 zlib1g libgmp10 libhogweed4 libidn2-0 libnettle6 libp11-kit0 libtasn1-6 libunistring2 libsasl2-modules-db readline-common install-info.
Synapse runs as a non-root user. The postgres socket is mounted into synapse's container.
Activity
richvdh commentedon Jul 9, 2020
please share the synapse logs.
what symptoms are you seeing other than the log messages?
savyajha commentedon Jul 10, 2020
The synapse logs for the half hour time period I'm talking about are the following (The size of the logs is 35 mb, please bear that in mind):
https://go7box.xyz/public/synapse.txtThe postgres logs are the following:
https://go7box.xyz/public/postgres.txtThere's not much else I see except perhaps a performance penalty? But I don't know what else is happening because of this. We've certainly experienced no extreme problems except maybe a performance degradation.
Edit: corrected paths of log files
savyajha commentedon Jul 11, 2020
Update: I switched to jemalloc and the logs change substantially:
synapse:
https://go7box.xyz/public/synapse.new.txtpostgres:
https://go7box.xyz/public/postgres.new.txtI still see serialisation errors in the postgres log but I don't see the same volume of errors I saw in the previous synapse logs.
savyajha commentedon Jul 12, 2020
Update: I went through the Readme and the wiki and tweaked a few things about our installation:
SYNAPSE_CACHE_FACTOR=2.0This led to a drastic reduction of errors in my synapse logs. However, the serialisation errors in my postgresql logs still remain unchanged:
Note: I've removed the older log files because I don't think they're relevant in the light of these tweaks.
richvdh commentedon Jul 13, 2020
as a general rule, serialisation errors from postgres are not a problem. They will happen from time to time when synapse processes multiple requests in parallel; synapse will simply retry the failed transaction.
The slew of errors at
Jul 12 03:27:37are a bit surprising, but since you haven't included INFO-level logs from synapse, it's hard to say what caused them.I don't think there is a bug here.
richvdh commentedon Jul 17, 2020
see also #7882, which will reduce the number of warnings.
savyajha commentedon Jul 17, 2020
Happy to see this merged. :)