Ralith's HS took 30 mins to process a single fed txn with 27 PDUs

[ara4n]

It could be the box was just being super-slow, but something else looks wrong here.

dhcp-lon-vl3-61:ralith3 matthew$ cat thrash.log  | egrep 'PUT-3947'
Jan 06 19:00:33 ralith.com synapse[4568]: synapse.access.http.8008: [PUT-3947] 81.0.239.106 - 8008 - Received request: PUT /_matrix/federation/v1/send/1483709314017/
Jan 06 19:00:33 ralith.com synapse[4568]: synapse.federation.transport.server: [PUT-3947] Request from de-fault.eu
Jan 06 19:00:33 ralith.com synapse[4568]: synapse.federation.transport.server: [PUT-3947] Received txn 1483709314017 from de-fault.eu. (PDUs: 27, EDUs: 0, failures: 0)
Jan 06 19:00:36 ralith.com synapse[4568]: synapse.storage.events: [PUT-3947] Loading 1 events
Jan 06 19:00:38 ralith.com synapse[4568]: synapse.storage.events: [PUT-3947] Loaded 1 events (0 rows)
Jan 06 19:00:48 ralith.com synapse[4568]: synapse.state: [PUT-3947] calling resolve_state_groups from compute_event_context
Jan 06 19:01:05 ralith.com synapse[4568]: synapse.storage.events: [PUT-3947] Loading 1 events
Jan 06 19:01:08 ralith.com synapse[4568]: synapse.storage.events: [PUT-3947] Loaded 1 events (0 rows)
Jan 06 19:01:21 ralith.com synapse[4568]: synapse.state: [PUT-3947] calling resolve_state_groups from compute_event_context
Jan 06 19:01:33 ralith.com synapse[4568]: synapse.storage.events: [PUT-3947] Loading 1 events
Jan 06 19:01:46 ralith.com synapse[4568]: synapse.storage.events: [PUT-3947] Loaded 1 events (0 rows)
Jan 06 19:01:58 ralith.com synapse[4568]: synapse.state: [PUT-3947] calling resolve_state_groups from compute_event_context
Jan 06 19:02:12 ralith.com synapse[4568]: synapse.storage.events: [PUT-3947] Loading 1 events
Jan 06 19:02:15 ralith.com synapse[4568]: synapse.storage.events: [PUT-3947] Loaded 1 events (0 rows)
Jan 06 19:02:28 ralith.com synapse[4568]: synapse.state: [PUT-3947] calling resolve_state_groups from compute_event_context
Jan 06 19:02:39 ralith.com synapse[4568]: synapse.storage.events: [PUT-3947] Loading 1 events
Jan 06 19:02:47 ralith.com synapse[4568]: synapse.storage.events: [PUT-3947] Loaded 1 events (0 rows)
Jan 06 19:03:02 ralith.com synapse[4568]: synapse.state: [PUT-3947] calling resolve_state_groups from compute_event_context

...

Jan 06 19:29:27 ralith.com synapse[4568]: synapse.storage.events: [PUT-3947] Loading 1 events
Jan 06 19:29:54 ralith.com synapse[4568]: synapse.storage.events: [PUT-3947] Loaded 1 events (0 rows)
Jan 06 19:30:17 ralith.com synapse[4568]: synapse.state: [PUT-3947] calling resolve_state_groups from compute_event_context
Jan 06 19:31:29 ralith.com synapse[4568]: synapse.federation.transport.server: [PUT-3947] Received txn 1483709314017 from de-fault.eu. (PDUs: 27, EDUs: 0, failures: 0)
Jan 06 19:31:29 ralith.com synapse[4568]: synapse.access.http.8008: [PUT-3947] 81.0.239.106 - 8008 - {de-fault.eu} Processed request: 1855580ms (3830ms, 99ms) (2244ms/106) 1060B 200 "PUT /_matrix/federation/v1/send/1483709314017/ HTTP/1.1" "Synapse/0.18.6-rc3"
Jan 06 19:31:42 ralith.com synapse[4568]: synapse.federation.transport.server: [PUT-3947] Received txn 1483709314017 from de-fault.eu. (PDUs: 27, EDUs: 0, failures: 0)

[richvdh]

at a guess it will have been waiting for state resolution locks. #2520 will probably help with this.