Page MenuHomePhabricator

Hourly read spikes against s8 resulting in occasional user-visible latency & error spikes
Closed, ResolvedPublic

Description

Many hours, at the top of the hour, we're seeing load spikes of reads to all s8 replicas.

Every once in a while, this causes some impact, up to and including user-visible errors and paging of SREs.

The first time was 2020-10-02 22:06:48 where it caused restbase issues, and made the LVS healthchecks for wikifeeds and termbox fail:

2020-10-02 22:06:48     <+icinga-wm>      PROBLEM - LVS wikifeeds codfw port 4101/tcp - A node webservice supporting featured wiki content feeds. termbox.svc.eqiad.wmnet IPv4 #page on wikifeeds.svc.codfw.wmnet is CRITICAL: CRITICAL - Socket timeout after 10 seconds https://wikitech.wikimedia.org/wiki/LVS%23Diagnosing_problems

The second time was today:

2020-10-06 22:03:11     <+icinga-wm>      PROBLEM - Not enough idle PHP-FPM workers for Mediawiki api_appserver at codfw #page on alert1001 is CRITICAL: 0.2271 lt 0.3 https://bit.ly/wmf-fpmsat https://grafana.wikimedia.org/d/RIA1lzDZk/application-servers-red-dashboard?panelId=54&fullscreen&orgId=1&from=now-3h&to=now&var-datasource=codfw+prometheus/ops&var-cluster=api_appserver

The issue shows most clearly as read_key traffic, although read_next also shows the pattern as well:

Screenshot_20201006_193322.png (1,831×379 px, 153 KB)

grafana/explore link, be logged in on grafana first: https://w.wiki/fTq

Looking at the past week, whatever the load spike is seems especially heavy at 22:00UTC.

image.png (1,831×387 px, 193 KB)

What is this workload? Is it possible to get some query logs? And then to spread it out?

Event Timeline

Marostegui moved this task from Triage to In progress on the DBA board.
Marostegui added subscribers: Ladsgroup, Addshore.

Adding @Addshore and @Ladsgroup as they have lots of cool dashboards (that I am unable to find) where they maybe can check in a more granular way what is hitting the hosts.
I have checked all the s8 hosts and this seems to happen on every slave so it doesn't look related to an specific traffic (api, recentchanges etc).

Checking cronjobs on mwmaint2001 I can see this one starting at around that time (however it looks like it runs every 3 minutes anyways):

/usr/local/bin/mwscript extensions/Wikibase/repo/maintenance/dispatchChanges.php --wiki wikidatawiki

If it happens always around that time my guess would be some batch job or a bot?
If needed, I could capture some real query logs around the time it normally happens, I can try to capture an interval of 2-3 minutes (more might be difficult as the log might be huge). Before doing this I will wait for @Ladsgroup and @Addshore to see if they can find something on their logs

I forgot to paste:

root@mwmaint2001:~# crontab -l -uwww-data | grep -w wikidatawiki
*/3 * * * * echo "$$: Starting dispatcher" >> /var/log/wikidata/dispatchChanges-wikidatawiki.log; /usr/local/bin/mwscript extensions/Wikibase/repo/maintenance/dispatchChanges.php --wiki wikidatawiki >> /var/log/wikidata/dispatchChanges-wikidatawiki.log 2>&1; echo "$$: Dispatcher exited with $?" >> /var/log/wikidata/dispatchChanges-wikidatawiki.log

The only common query I have found that executes on all hosts is:

SELECT /* Wikibase\Lib\Store\Sql\Terms\DatabaseTermInLangIdsResolver::selectTermsViaJoin xx */ wbtl_id, wbtl_type_id, wbxl_language, wbx_text, wbpt_property_id FROM `wbt_term_in_lang` JOIN `wbt_text_in_lang` ON ((wbtl_text_in_lang_id=wbxl_id)) JOIN `wbt_text` ON ((wbxl_text_id=wbx_id)) JOIN `wbt_property_terms` ON ((`wbpt_term_in_lang_id` = wbtl_id)) WHERE wbtl_type_id = 1 AND wbxl_language = 'lez'

This query does increase the read_key and read_next which handlers, which are the ones spiking on the graphs:

root@db2081.codfw.wmnet[wikidatawiki]> FLUSH STATUS; pager cat > /dev/null;
Query OK, 0 rows affected (0.032 sec)

PAGER set to 'cat > /dev/null'
root@db2081.codfw.wmnet[wikidatawiki]> SELECT /* Wikibase\Lib\Store\Sql\Terms\DatabaseTermInLangIdsResolver::selectTermsViaJoin 4 */ wbtl_id, wbtl_type_id, wbxl_language, wbx_text, wbpt_property_id FROM `wbt_term_in_lang` JOIN `wbt_text_in_lang` ON ((wbtl_text_in_lang_id=wbxl_id)) JOIN `wbt_text` ON ((wbxl_text_id=wbx_id)) JOIN `wbt_property_terms` ON ((`wbpt_term_in_lang_id` = wbtl_id)) WHERE wbtl_type_id = 1 AND wbxl_language = 'lez' ; nopager;
14 rows in set (1.781 sec)

PAGER set to stdout
root@db2081.codfw.wmnet[wikidatawiki]> SHOW STATUS like 'Hand%';
+----------------------------+--------+
| Variable_name              | Value  |
+----------------------------+--------+
| Handler_commit             | 1      |
| Handler_delete             | 0      |
| Handler_discover           | 0      |
| Handler_external_lock      | 0      |
| Handler_icp_attempts       | 0      |
| Handler_icp_match          | 0      |
| Handler_mrr_init           | 0      |
| Handler_mrr_key_refills    | 0      |
| Handler_mrr_rowid_refills  | 0      |
| Handler_prepare            | 0      |
| Handler_read_first         | 1      |
| Handler_read_key           | 531005 |
| Handler_read_last          | 0      |
| Handler_read_next          | 364794 |
| Handler_read_prev          | 0      |
| Handler_read_retry         | 0      |
| Handler_read_rnd           | 0      |
| Handler_read_rnd_deleted   | 0      |
| Handler_read_rnd_next      | 0      |
| Handler_rollback           | 0      |
| Handler_savepoint          | 0      |
| Handler_savepoint_rollback | 0      |
| Handler_tmp_delete         | 0      |
| Handler_tmp_update         | 0      |
| Handler_tmp_write          | 0      |
| Handler_update             | 0      |
| Handler_write              | 0      |
+----------------------------+--------+
27 rows in set (0.033 sec)

The rest of slow queries I can see are mostly related to watchlistand IndexPager::buildQueryInfo which only arrives to special slaves, but from what I have seen, those spikes happens on all hosts, so I guess they can be discarded.

One of the places to look that should track all access to this term related storage is https://grafana.wikimedia.org/d/000000548/wikibase-sql-term-storage?orgId=1&refresh=30s&from=now-12h&to=now
I don't see any worrying looking spikes or abnormal access patterns there.

I doubt that the dispatching script has anything to do with this, it is a cron that runs every 3 mins indeed.
The actual outcome of that cron is that 3 of these scripts are running at all times slowly working through a list of wikis to send cache purges to (but not renders).
A dashboard for that process is https://grafana.wikimedia.org/d/000000156/wikidata-dispatch?orgId=1&from=now-24h&to=now but nothing lines up.

It could be that other queries end up causing these term related queries to take longer (a pattern that we have seen before).
If the SQL servers are "heavily loaded" then general these term queries are the ones that take the most significant hit.

1:23 PM <addshore> I also notice this? https://grafana.wikimedia.org/d/000000202/api-frontend-summary?orgId=1&from=1602020402068&to=1602023755950 REST API backend internla requests spike?
1:23 PM <addshore> also happened a week ago? https://grafana.wikimedia.org/d/000000202/api-frontend-summary?orgId=1&from=1601674802000&to=1601678155000
1:23 PM <addshore> zooming out I see even more spikes https://grafana.wikimedia.org/d/000000202/api-frontend-summary?orgId=1&from=now-7d&to=now
1:24 PM <addshore> I have 0 idea what this is though or thus if it may or may not be related
1:24 PM <marostegui> addshore: looks like it has been happening since 1st oct yeah
1:24 PM <marostegui> per the graphs reported
1:24 PM <addshore> but that is a regulrly occouring spike at the right time 
1:24 PM <addshore> I'll write that and those links in the ticket?
1:25 PM <marostegui> addshore: yeah, daily at 22 UTC, which is weeeeeeird
1:26 PM <addshore> yeah, also a correlation with RED dashboard issues on the 3rd https://grafana.wikimedia.org/d/RIA1lzDZk/application-servers-red-dashboard?orgId=1&from=1601760432456&to=1601764464836

Link showing a spike that may be related https://grafana.wikimedia.org/d/000000202/api-frontend-summary?orgId=1&from=1602020402068&to=1602023755950 REST API backend internal requests spike?
Looks like there are many other spikes, these all (well I looked at 3 of them) seem to line up with spikes in RED dahsboard repsonse times, https://grafana.wikimedia.org/d/000000202/api-frontend-summary?orgId=1&from=now-7d&to=now

We should dig into what is causing these "REST API backend internal"

1:57 PM <addshore> While i was browsing around I also saw spikes in action=query in grafana, but couldn't dive much deeper, but I guess wikifeeds calls that, and some of the wikibase api modules there Amir1
...
1:58 PM <addshore> which I guess is https://en.wikipedia.org/w/api.php?action=help&recursivesubmodules=1#query+pageterms Amir1 
1:58 PM <Amir1> hmm addshore maybe we can coordinate with them to improve their API calls or build something suited to their needs?
...
1:58 PM <Amir1> addshore: aaah, we don't cache pageterms
1:58 PM <addshore> Amir1: yeah, im not sure how much caching pageterms currently has?
1:59 PM <Amir1> I wanted to do it, you didn't let me 
1:59 PM <Amir1> :D
1:59 PM <addshore> Amir1: there you go, so thats why the spikes end up getting all the way down to s8? :P
1:59 PM <addshore> Amir1: well, now we have a reason to :D

We should confirm if our suspicion is the case, and if so file a ticket.

To clarify a bit - restbase has hourly spikes of requests for the feed endpoint, which go back to wikifeeds, which calls both restbase and the action api.

From the graphs of calls from wikifeeds it's clear we have hourly peaks happening at :00 in the number of requests, with the most prominent happening around 22:00 UTC. All of that traffic appears to originate from the iOS app.

I suppose it's possible there is some function to download a fresh daily feed exactly at midnight, causing this stampede (and a larger one when midnight happens in CET).

Removing DBA as there's nothing specific for us to do right now, do add us back if anything comes up.

JMeybohm triaged this task as Medium priority.Oct 13 2020, 10:07 AM
jijiki claimed this task.
jijiki subscribed.

Bluntly closing