Most of the change is from the sync endpoint producing lotsof 5s responses, but the others also show slower responses, event though their request count didn't really change.

GET /changes/since/...
number of calls	median response time	p99 response time
POST /lists
POST /lists/{id}/entries/

@Fjalapeno have not had the time to do much useful about this, will continue tomorrow. At a glance though, times on the MediaWiki side (as reported by ApiAction) don't seem long.

Queried MW backend times from ApiAction with

select day, params['action'], params['command'], !params['list'], !params['meta'], avg(timeSpentBackend) from ApiAction where year = 2018 and month = 4 and day >= 20 and (params['action'] = 'readinglists' or params['meta'] = 'readinglists' or params['list'] = 'readinglistentries') group by day, params['action'], params['command'], !params['list'], !params['meta'];

(results and some stats here); those are suspiciously fast (20-40ms), not sure how much that can be trusted.

@mobrovac @Pchelolo does RESTBase log anything that I could use to cross-correlate MW API request durations?

@Dbrant @JoeWalsh did you notice anything strange or any error reports from users? Most sync requests result in a 4xx error, but with T192896: Frequent client-side errors for reading list service and lack of more detailed logging of those kinds of errors ATM (T189360) it's hard to tell if that's normal or not.

Another ApiAction query with p99 times:

select day, case when params['list'] is not null then 'readinglists' when params['meta'] is not null then 'readinglistentries' else params['command'] end action, hadError, avg(timeSpentBackend) avg_time, percentile_approx(timeSpentBackend, 0.99) p99_time from ApiAction where year = 2018 and month = 4 and day >= 20 and (params['action'] = 'readinglists' or params['meta'] = 'readinglists' or params['list'] = 'readinglistentries') group by day, case when params['list'] is not null then 'readinglists' when params['meta'] is not null then 'readinglistentries' else params['command'] end, hadError

(added to the same sheet)

The processing times are tiny and don't change over time. Either the ApiAction numbers are completely wrong or the delays are after the API has generated the response. The API logs these times before committing the open DB transaction, so maybe that's where the delays happen.

In T193417#4170727, @Tgr wrote:

with T192896: Frequent client-side errors for reading list service and lack of more detailed logging of those kinds of errors ATM (T189360) it's hard to tell if that's normal or not.

Breakdown is in T192896#4170798, seems all normal (unless ApiAction does not log certain errors at all... RESTBase statsd logs say approx. 200K successful requests and 165K 4xx errors since the 27th, ApiAction logs say 700K successful requests and 560K 4xx errors, which both give a ~40% error rate, so while statsd sampling probably changes the request counts somehow, it doesn't seem like a large class of failed requests are missing from one or the other log.)

(Also, looks like T189360 was fixed already, cool!)

There are a few 504 errors from MediaWiki but not too many (260 for the last few days), and they seem to correlate with the sync request count but not with the sudden jump in response times: https://logstash.wikimedia.org/goto/8009262e31d5a1a6eb6a520125a8c292

Sync (/data/lists/changed/since/...) stats for the last 7 days (choosing sync as it's about 80% of total ReadingLists traffic):

sync request count, 2xx	sync request count, 4xx	sync response time, median	sync response time, p99	504 response count

@mobrovac @Pchelolo does RESTBase log anything that I could use to cross-correlate MW API request durations?

We do log slow requests with a 1% probability, and it's not per-request type, but across the board. There is a couple of log entries for reading lists here: https://logstash.wikimedia.org/goto/6a66a622663f986a90221b0f8d35fadf

Also, playing with latencies dashboard on RESTBase level, we have the ability to separate latencies by response code and I can see the same degradation for 2xx as for 4xx:

2XX Responses:

4xx Responses:

3xx and 5xx are negligible in rate, so no way to properly say whether their latencies changed or not.

Thanks @Pchelolo, that doesn't really tell me anything about where the time is spent though. What I would like to confirm is that only a trivial amount of time is spent on the RESTBase side and it's the action API subrequest that's slow.

@Tgr we don't have stats JUST for the Action API request itself, but we do have stats for calls to the action.js module. Since it's such a thin wrapper over a pure request to the Action API, an since for reading lists we only use rawquery that is even thinner, I guess the stats for restbase.external.sys_action_rawquery.ALL.ALL.p95 woul be a decent representation of the actual latencies we see in requests from RESTBase to Action API:

Thanks, that make it pretty clear that the issue is on the MediaWiki side.

T191282: Wikimedia\Rdbms\LoadBalancer::{closure}: found writes pending is one possible culprit.

One thing that jumps out is that the long requests typically take some multiple of 500ms to finish:

GET request times, p75	GET request times, p95

That suggests something times out and gets retried but I have no idea what that something might be.

That suggests something times out and gets retried but I have no idea what that something might be.

The RESTBase -> Action API the connect timeout is 5s and request timeout is 2 minutes, so it's not initiated by RESTBase.

GET and POST queries show the same pattern of behavior, so it probably is not related to the bug above or to transaction commit times:

FWIW I don't believe we've seen any direct user complaints about slowdowns or breakage of syncing...

https://gerrit.wikimedia.org/r/c/430116/ might fix this.

In T193417#4175536, @Tgr wrote:

https://gerrit.wikimedia.org/r/c/430116/ might fix this.

Unfortunately it didn't.

Response times have been slowly improving since May 25 or so, but still way worse than in the past:

median	p99

Possibly coordinated with getting rid of the invalid domain names, might be coincidental though:

median response times

non-batch list entry creation count