Repository navigation
Some Postgres database queries are long running / blocking #3682
Description
Description
I installed synapse from source on Debian using virtualenv. I am using postgres 9.6 as a backend.
The client is behind a Let's Encrypted nginx reverse proxy.
The federation port is in the open.
The installation is pretty fresh, only one user (me) is on the system, however I already joined some big channels (#matrix:matrix.org).
When the instance boots, some queries blocks requests from my client (Riot), to unblock it, I need to kill the this query:
DROP INDEX IF EXISTS access_tokens_device_id to probably unblock this:
SELECT users.name, users.is_guest, access_tokens.id as token_id, access_tokens.device_id FROM users INNER JOIN access_tokens on users.name = access_tokens.user_id WHERE token = 'FOOBAR'
Afterwards I have new queries blocking:
LOCK TABLE user_ips in EXCLUSIVE MODE and
CREATE INDEX CONCURRENTLY user_ips_device_id ON user_ips (user_id, device_id, last_seen)
This query also sometimes hangs around:
SELECT room_id, MAX(stream_ordering) FROM events WHERE stream_ordering > 6131 - 100000 GROUP BY room_id
Steps to reproduce
- not really sure
this is my DB setup:
database:
name: "psycopg2"
args:
user: "user"
password: "xxx"
database: "synapse"
host: "127.0.0.1"
cp_min: 5
cp_max: 10Version information
- Version: 67dbe4c
- Install method: pip
- Platform: VPS with Debian Stretch
- Postgresql: 9.6
Activity
mguentner commentedon Aug 13, 2018
So, I changed the value of
deadlock_timeoutin /etc/postgresql/9.6/main/postgresql.confto
1slike this:Documentation: https://www.postgresql.org/docs/9.6/static/runtime-config-locks.html
I don't know whether the behavior I described is a bug of synapse or not. But the fact that these queries block themselves seems strange to me.
mguentner commentedon Aug 17, 2018
Apparently
deadlock_timeouthas little effect.I now have
lock_timeout = 2sin /etc/postgresql/9.6/main/postgresql.conf and see this in the log file:timoschwarzer commentedon Aug 20, 2018
I have the same problem.
Synapse sucessfully connects to PostgreSQL via the UNIX socket. I, too, changed the
lock_timeoutto five seconds which caused the Synapse background update to fail:mguentner commentedon Aug 20, 2018
@timoschwarzer Good to hear, thanks for confirming. What OS and PostgreSQL version are you running?
timoschwarzer commentedon Aug 21, 2018
Debian Stretch and PostgreSQL 9.6
richvdh commentedon Aug 22, 2018
Things logged against "background_updates" are one-time update jobs which happen when you upgrade synapse. They shouldn't take very long. I suggest you just let them run.
mguentner commentedon Aug 22, 2018
They never go away, even after hours. I let them run for ~ 24h. Almost no load while they ran.
richvdh commentedon Aug 22, 2018
ok, can you leave them running for a while, and then grep your logs for
background_updatesand share what you see there, along with the postgres queries you see in flight.problame commentedon Aug 22, 2018
I have the same issue:
richvdh commentedon Aug 22, 2018
@problame: thanks, that's very helpful. However in your case it looks like the background update has only been running for three minutes (and yes, it will block the user_ips update transaction while it happens; see also #3652). Could you leave it going for an hour or so and see how things look then?
problame commentedon Aug 22, 2018
Same thing, no changes. Also,
user_ipsis really small, so building an index shouldn't take long. (And all postgres processes are idle anyway):mguentner commentedon Aug 22, 2018
@richvdh
Disabled the
lock_timeout(so infinite)After synapse start, this query is taking very long (minutes, hours, days (?)).
SELECT room_id, MAX(stream_ordering) FROM events WHERE stream_ordering > 275 - 100000 GROUP BY room_idit blocks multiple
background_updateslikeDROP INDEX/CREATE INDEX CONCURRENTLY.after killing this
SELECT room_id, MAX...query I see this in the logs:The instance now runs rather smoothly but I suspect that it might go into a deadlock state soon. I switched back to
lock_timeout = 5s. I will try in a few hours again when the background processes will be scheduled again (?).@timoschwarzer Could you try the same and report what requests are blocking for you?
You can do that by opening a psql shell, best as the
postgresuser:They should also show up in
ps -ef. Try to kill the one that is blocking the other.I also found this mega statement here to figure out the dependency:
mguentner commentedon Aug 22, 2018
(Did not reload the thread before posting)
I also see that @problame has the same long running
SELECT room_id, MAX(stream_ordering) FROM events WHERE stream_ordering > 275 - 100000 GROUP BY room_idtimoschwarzer commentedon Aug 23, 2018
@mguentner
I recreated the entire database, so no tables were present before starting Synapse. Then I started it and these two queries are now running forever:
The result of the big query you found is:
Blocked PID: 8470
Blocked user: docker_matrix
Blocking PID: 8463
Blocking user: docker_matrix
Blocked statement:
Current statement in blocking process:
After killing %8463, Synapse works as expected.
problame commentedon Aug 23, 2018
@timoschwarzer can confirm that killing the
CREATE INDEXprocess solved the issue, also after restarts of synapse.timoschwarzer commentedon Aug 23, 2018
@problame I've actually killed the
SELECT room_id ...query. Appearantly, they are blocking each other so that you can just kill one of them to bring Synapse back to a working state.problame commentedon Aug 23, 2018
@timoschwarzer And you are right, the
SELECT room_idshows up again after restarts.What about those other COMMIT queries? shouldn't they go away? they are all in idle state (column not shown here).
problame commentedon Aug 23, 2018
Interestingly, when I execute the
SELECT room_id ...query on the database (even while all the other queries are running), I get an instant response (8 rows).mguentner commentedon Aug 23, 2018
@problame Can confirm. Saw the same behavior. Manually running the queries works.
richvdh commentedon Aug 24, 2018
No, those are normal idle connections. Synapse uses a connection pool to reduce the overhead of database queries.
richvdh commentedon Aug 24, 2018
Right, I think I know what's causing this. I'll sort out a fix.
richvdh commentedon Aug 28, 2018
Folks can you confirm if this is still a problem with synapse 0.33.3? If my theory is correct it was introduced in #3630 (which was in 0.33.2) but will then have been fixed by #3633 (which was in 0.33.3)
problame commentedon Aug 28, 2018
Yes, it's gone with 0.33.3 (verified with several synapse restarts). Thanks!
Make sure that we close db connections opened during init