Other ideas:

• bootstraps: SAL says that 2004 was started 24 hours later, so unlikely.
• repairs

Top user agents in error messages over the last 10 days:

Term Count Action
Magnus labs tools 28227
MediaWiki/1.27.0-wmf.18 (RestbaseUpdateJob) 21209
Ruby 19052
wikimedia/multi-http-client v1.0 1421
pageviews.jsv1.0.7 (git+https://github.com/tomayac/pageviews.js.git) 1290
MediaWiki/1.27.0-wmf.19 (RestbaseUpdateJob) 674
http-kit/2.0 329
Mozilla/5.0 (compatible; Google-Apps-Script) 165
REST-API-Crawler-Google/1.0 (+wikidata-external@google.com) 132
Missing field 1736109
Other values 1188

The top ones do not seem to align with the increase in internal requests & 1012-b traffic.

Interestingly, read request completed looks fairly even between nodes & instances:

Actually, https://grafana-admin.wikimedia.org/dashboard/db/restbase-cassandra-client-requests?panelId=32&fullscreen&from=1459248919680&to=1459313279864&var-datacenter=1&var-node=All&var-quantile=99percentile&edit is showing a *latency* rate, and not requests per second:

cassandra.$node.org.apache.cassandra.metrics.ClientRequest.Read.Latency.1MinuteRate

I'm inclined to close this task as invalid. @fgiunchedi @Eevans: Any objections?

I have updated restbase-cassandra-client-requests to use the same read request metrics as the cassandra-restbase-eqiad dashboard.

In T131370#2165904, @Eevans wrote:

In T131370#2165465, @GWicke wrote:

Actually, https://grafana-admin.wikimedia.org/dashboard/db/restbase-cassandra-client-requests?panelId=32&fullscreen&from=1459248919680&to=1459313279864&var-datacenter=1&var-node=All&var-quantile=99percentile&edit is showing a *latency* rate, and not requests per second:

cassandra.$node.org.apache.cassandra.metrics.ClientRequest.Read.Latency.1MinuteRate

I'm inclined to close this task as invalid. @fgiunchedi @Eevans: Any objections?

I'm not sure this is right. cassandra.$node.org.apache.cassandra.metrics.ClientRequest.Read.Latency is a dropwizard timer (see: https://dropwizard.github.io/metrics/3.1.0/getting-started/#timers), which "...measures both the rate that a particular piece of code is called and the distribution of its duration".

Also, it seems like too much of a coincidence that the jump in rate so closely matches the jump in internal request rate:

I'm not sure this is right. cassandra.$node.org.apache.cassandra.metrics.ClientRequest.Read.Latency is a dropwizard timer (see: https://dropwizard.github.io/metrics/3.1.0/getting-started/#timers), which "...measures both the rate that a particular piece of code is called and the distribution of its duration".

Which means that requests / second is only one ingredient to the sum, with latency being the other, and labeling this as a request rate with unit req/s is misleading.

The client metrics for 1012-b don't seem to agree with thread stats on rates or latency. Thread metrics have so far proven accurate, and they do agree with secondary metrics like gc times in the concrete case. I'm inclined to continue using them as the primary request rate / latency metrics.

In T131370#2165939, @GWicke wrote:

I'm not sure this is right. cassandra.$node.org.apache.cassandra.metrics.ClientRequest.Read.Latency is a dropwizard timer (see: https://dropwizard.github.io/metrics/3.1.0/getting-started/#timers), which "...measures both the rate that a particular piece of code is called and the distribution of its duration".

Which means that requests / second is only one ingredient to the sum, with latency being the other, and labeling this as a request rate with unit req/s is misleading.

I don't follow. The timer that records how long a request method takes (latency) is able to provide the rate at which that method is called, for free. The name might be misleading, but the rate produced is valid. In this case, the method that is being timed is o.a.c.service.StorageProxy#read, which corresponds to every read request a node receives from a client (including those that are coordinated). That sounds exactly right for a graph of client requests.

The client metrics for 1012-b don't seem to agree with thread stats on rates or latency. Thread metrics have so far proven accurate, and they do agree with secondary metrics like gc times in the concrete case. I'm inclined to continue using them as the primary request rate / latency metrics.

We see a jump in restbase requests to, ~1.5k/s, starting at ~14:00 on the 29th, and a corresponding jump in client requests (~1.5k/s) on 1012-b at the same time. That doesn't strike you as a useful and interesting correlation?

This is interesting:

There seems to be a disproportionate amount of traffic directed at https://en.wikipedia.org/wiki/Communications_and_Information_Services_Corps (and CIS Corps (Ireland), which redirects https://en.wikipedia.org/wiki/Communications_and_Information_Services_Corps). It has been this way for the past 30 minutes or so (at least).

We see a jump in restbase requests to, ~1.5k/s, starting at ~14:00 on the 29th, and a corresponding jump in client requests (~1.5k/s) on 1012-b at the same time. That doesn't strike you as a useful and interesting correlation?

It is an interesting correlation, which is why I pointed it out originally.

I think we have established that the original metric does not indicate read rates or read latency processed on a particular node. We have reliable numbers for those, and they indicate a fairly even distribution of reads and latency. If anything, latency on 1012 is on the lower end of the scale on those metrics. This means that we are not dealing with a repeat request for a single key.

This leaves the question of whether those client metrics are reliable, and what they mean. Generally, client metrics are supposed to be requests to a node acting as a coordinator, which means that the actual reads / writes don't necessarily happen on the node itself. This would leave the option that this node would be picked more often than usual as a coordinator by the driver. If this was the case, then I would expect the instance to be more heavily loaded, which would manifest itself as higher GC and CPU load. So far, I have not seen any indications that this is indeed the case for 1012-b.

@Eevans, the toppartition results are consistent with https://grafana.wikimedia.org/dashboard/db/cassandra-restbase-eqiad?panelId=24&fullscreen.

To me, it looks like some internal tool has a bug in redirect handling.

We are preparing to deploy sampled request logging in production, which should give us an idea on which client is hitting those titles.

The only related log message I have found in logstash is a timeout from a request from restbase to http://mobileapps.svc.eqiad.wmnet:8888/en.wikipedia.org/v1/page/mobile-sections/Communications_and_Information_Services_Corps. However, https://en.wikipedia.org/api/rest_v1/page/mobile-sections/Communications_and_Information_Services_Corps is returned just fine.

Okay, @Pchelolo resolved the mystery by deploying the sampled logging logic. The source of those requests is the mobile content service, and there was indeed a redirect loop involved. Purging one of the pages in RESTBase broke the redirect loop, and request levels are back to normal.

Bugs:

• Mobile content service redirect loop regression: T131416
• Missed RESTBase update from move. The general logic in the RESTBaseUpdateExtension looks correct, and running the no-cache request manually worked. This might just be a case of a dropped update request (blip in job queue, no retries). Moving to change propagation should help fix this by letting us retry reliably.

In T131370#2166709, @GWicke wrote:

Okay, @Pchelolo resolved the mystery by deploying the sampled logging logic. The source of those requests is the mobile content service, and there was indeed a redirect loop involved. Purging one of the pages in RESTBase broke the redirect loop, and request levels are back to normal.

Bugs:

• Mobile content service redirect loop regression: T131416
• Missed RESTBase update from move. The general logic in the RESTBaseUpdateExtension looks correct, and running the no-cache request manually worked. This might just be a case of a dropped update request (blip in job queue, no retries). Moving to change propagation should help fix this by letting us retry reliably.

Great work guys!