| • Nuria | |
| Jan 14 2016, 4:05 PM |
| F3227882: El_by_schema.png | |
| Jan 14 2016, 4:42 PM |
We have thus far seen that one schema was accounting for about 90% of eventlogging flow and we have blacklisted it: MobileWebSectionUsage (see image)
We have also dropped the MobileWebSectionUsage tables as the db was having disk space issues for a while (this was a just a shot in the dark though)
Looks like we have several long running queries we need to kill?
| Subject | Repo | Branch | Lines +/- | |
|---|---|---|---|---|
| Batch eventlogging_sync custom mysqldump replication | operations/puppet | production | +8 -2 |
From ops list:
"SELECT * FROM information_schema.processlist ORDER BY time DESC"
informs us of this:
| 5599890 | research | 10.64.36.103:53669 | enwiki | Query | 133527 | Queried about 890000 rows | CREATE TEMPORARY TA |
SELECT
page_id, views
FROM (
SELECT
page_namespace,
page_title,
SUM(views) AS views
FROM staging.page_name_views_dupes
WHERE page_namespace = 0
GROUP BY 1,2) AS group_page_name_views
INNER JOIN enwiki.page USING (page_namespace, page_title)
Column 6 is "time", i.e. this query was running for 133527 seconds at
the time (i.e. ~1.5 days!), which is obviously Not Good™. I just ran
"KILL QUERY 5599890;", hopefully this will help.
The second-next long-standing query has been running for over 6 hours
now and it way too long to paste (87 lines, starts with "INSERT INTO
editor_month_global", inline comments, all kinds of subselects in inner
joins etc., queried "about 2470000 rows"). I left it be for now, we'll
see how that goes and I may eventually kill it too, as I/O is still
pegged at 100%.
From mobile team:
https://gerrit.wikimedia.org/r/263538 was merged Monday 11th so new
sampling rate of 0 should be applied to all wikis from tomorrow
(Thursday 14th) around 5 PM PST. Please let team know if that doesn't
look right (note I am out tomorrow and Friday)
Looks we can whitelist table again as of Friday.
Change 264115 had a related patch set uploaded (by Ottomata):
Batch eventlogging_sync custom mysqldump replication
Change 264115 merged by Ottomata:
Batch eventlogging_sync custom mysqldump replication
Ok, I've modified the eventlogging_sync.sh script to do the custom mysqldump | insert based replication in batches of 1000 rows. This means that each mysqldump | insert step will only insert 1000 rows for each eventlogging table at a time. Large tables with many inserts may still lag, (and may not catch up?), but at least they won't starve out replication of smaller eventlogging tables.
https://gerrit.wikimedia.org/r/#/c/264115/2/files/mariadb/eventlogging_sync.sh
This is looking better so far. I can see many more tables with rows being inserted. If you have a particular table for which your data has not updated, let me know and I'll see if I can special case speed that one along.
db1047(???) big tables:
MariaDB EVENTLOGGING m4 localhost log > SELECT table_name, (DATA_LENGTH + INDEX_LENGTH)/1024/1024/1024 as `TOTAL SIZE (GB)`, ENGINE, CREATE_OPTIONS FROM information_schema.tables WHERE TABLE_SCHEMA='log' /* AND `ENGINE` <> 'TokuDB' */ ORDER BY (DATA_LENGTH + INDEX_LENGTH) DESC LIMIT 30; +--------------------------------------------+------------------+--------+---------------------------------------------+ | table_name | TOTAL SIZE (GB) | ENGINE | CREATE_OPTIONS | +--------------------------------------------+------------------+--------+---------------------------------------------+ | MobileWebUIClickTracking_10742159 | 521.135482054204 | TokuDB | `compression`='tokudb_zlib' | | PageContentSaveComplete_5588433 | 240.877661335282 | TokuDB | `compression`='tokudb_zlib' | | MediaViewer_10867062 | 199.722940413281 | TokuDB | page_checksum=1 `compression`='tokudb_zlib' | | Edit_11448630 | 178.264423341490 | TokuDB | page_checksum=1 `compression`='tokudb_zlib' | | MobileWikiAppToCInteraction_10375484 | 137.553305364214 | TokuDB | `compression`='tokudb_zlib' | | Edit_13457736 | 115.713233947754 | Aria | | | MobileWebEditing_8599025 | 81.299430885352 | TokuDB | `compression`='tokudb_zlib' | | MobileWikiAppSearch_10641988 | 80.191341589205 | TokuDB | page_checksum=1 `compression`='tokudb_zlib' | | MobileWikiAppToCInteraction_8461467 | 79.605804484338 | TokuDB | `compression`='tokudb_zlib' | | DeprecatedUsage_7906187 | 79.030134613626 | TokuDB | `compression`='tokudb_zlib' | | MobileWikiAppArticleSuggestions_11448426 | 74.080303261057 | TokuDB | page_checksum=1 `compression`='tokudb_zlib' | | MediaViewer_8572637 | 53.530012690462 | TokuDB | `compression`='tokudb_zlib' | | MediaViewer_8245578 | 52.663764884695 | TokuDB | `compression`='tokudb_zlib' | | MobileWebSectionUsage_15038458 | 47.344238281250 | Aria | | | MobileWebSectionUsage_14321266 | 46.843498229980 | Aria | | | MobileWikiAppMediaGallery_10923135 | 44.132686159573 | TokuDB | page_checksum=1 `compression`='tokudb_zlib' | | MultimediaViewerNetworkPerformance_7917896 | 37.447020443156 | TokuDB | `compression`='tokudb_zlib' | | NavigationTiming_10785754 | 34.445742438547 | TokuDB | page_checksum=1 `compression`='tokudb_zlib' | | PersonalBar_7829128 | 33.486920169555 | TokuDB | `compression`='tokudb_zlib' | | MobileWikiAppArticleSuggestions_12443791 | 31.112564086914 | Aria | | | EchoInteraction_5782287 | 31.024022584781 | TokuDB | page_checksum=1 `compression`='tokudb_zlib' | | MediaViewer_10606177 | 30.944609669037 | TokuDB | page_checksum=1 `compression`='tokudb_zlib' | | _EchoInteraction_5782287 | 28.228873762302 | TokuDB | `compression`='tokudb_zlib' | | MobileWikiAppArticleSuggestions_10590869 | 27.256117259152 | TokuDB | page_checksum=1 `compression`='tokudb_zlib' | | PageCreation_7481635 | 24.524119151756 | TokuDB | `compression`='tokudb_zlib' | | MediaViewer_8935662 | 24.144366898574 | TokuDB | `compression`='tokudb_zlib' | | NavigationTiming_8365252 | 21.527939989232 | TokuDB | `compression`='tokudb_zlib' | | UniversalLanguageSelector_7327441 | 21.329904851504 | TokuDB | `compression`='tokudb_zlib' | | MediaViewer_10308479 | 20.706761780195 | TokuDB | `compression`='tokudb_zlib' | | CentralAuth_5690875 | 20.173187393695 | TokuDB | `compression`='tokudb_zlib' | +--------------------------------------------+------------------+--------+---------------------------------------------+ 30 rows in set (0.64 sec)
Replag is ~50,000 seconds now, slowly decreasing since I killed that big query yesterday.
This query is still running, for more than a day now:
| 5761690 | research | 10.64.36.103:46490 | staging | Query | 116980 | Sending data
SELECT
user_name,
STR_TO_DATE( CONCAT(month, "01") , "%Y%m%d" ),
SUM(revisions),
SUM(archived),
STR_TO_DATE( first_registration, "%Y%m%d%H%i%S" )
FROM editor_month
LEFT JOIN (
SELECT
user_name,
MIN(user_registration) AS first_registration
FROM editor_month
GROUP BY user_name
) reg USING (user_name)
GROUP BY user_name, monthI talked to Neil p Quinn about it. Decided to just let it go, since I was able to find a work around to allow some EL tables to sync. Neil said we could kill it if it was absolutely necessary.
"CREATE TEMPORARY TABLE SELECT" is not recommended (any kind of DDL + SELECTing/going over lots of rows) because it will create a huge amount of locking/contention for other queries, delaying replication during its execution.
cc-ing @Neil_P._Quinn_WMF. Please take a look at @jcrespo (dba) recommendations regarding your selects
If you mean s1-s7 replication, I found Faidon's analysis to be quite accurate, plus I already gave some recommendations regarding queries to be rewritten. The only protection for replication about those kind of queries is having your permission to kill queries [automatically] that are creating more than X amount of replication lag (as we currently do for labs).
If you mean enventlogging lag, we still have pending maintenance (T120187), which is important to keep it low - I mentioned several times to include partitioning/keep table size low to keep it healthy, but my recommendations, which some require application changes, have been many times ignored. @Ottomata patch is a good try, but having working with this dataset for a while I think is not a good term solution, more changes have to be done to improve the script (which I merely inherited from Sean and puppetized it unchanged). I think dbstore1002 is so saturated that it would be better to run it from a separate host, which I am doing right now manually to reduce the current ongoing issues.
This is the current state of m4 replication:
$ bash check_eventlogging_lag.sh dbstore1002 [Warning] EchoInteraction_15180901 lag: 01:08:45 [CRITICAL] Echo_7731316 lag > 1 day (146813 seconds) [CRITICAL] Edit_13457736 lag > 1 day (292472 seconds) [Warning] MediaViewer_10867062 lag: 01:20:40 [CRITICAL] MobileAppUploadAttempts_5257716 lag > 1 day (22242114 seconds) [Warning] MobileWebUIClickTracking_10742159 lag: 01:07:22 [CRITICAL] PageContentSaveComplete_5588433 lag > 1 day (598602 seconds)
(all not shown tables have less than 1 hour of lag)
sX replication lag is a non-issue right now:
mysql -h dbstore1002 -e "SHOW ALL SLAVES STATUS\G" | grep Seconds
Seconds_Behind_Master: 0
Seconds_Behind_Master: 1
Seconds_Behind_Master: 0
Seconds_Behind_Master: 0
Seconds_Behind_Master: 0
Seconds_Behind_Master: 0
Seconds_Behind_Master: 0
Seconds_Behind_Master: 0
Seconds_Behind_Master: 0Oh! I didn't know of a check_eventlogging_lag.sh script. Cool!
Thanks for looking into this Jaime.
I think all issues are gone, except on MobileAppUploadAttempts_5257716, which may be a false positive or something else that makes the check complain, I will check it:
$ bash check_eventlogging_lag.sh dbstore1002 [Warning] EchoInteraction_15180901 lag: 01:12:47 [Warning] Edit_13457736 lag: 02:18:46 [CRITICAL] MobileAppUploadAttempts_5257716 lag > 1 day (22242114 seconds) [Warning] NavigationTiming_13317958 lag: 01:44:28
There is definitely something wrong with that table, but it is not related to replication:
root@iron:~$ mysql -h dbstore1002 log -e "SELECT count(*), max(id), min(id) FROM MobileAppUploadAttempts_5257716" +----------+---------+---------+ | count(*) | max(id) | min(id) | +----------+---------+---------+ | 1779 | 3695 | 1 | +----------+---------+---------+ root@iron:~$ mysql -h db1046 log -e "SELECT count(*), max(id), min(id) FROM MobileAppUploadAttempts_5257716" +----------+---------+---------+ | count(*) | max(id) | min(id) | +----------+---------+---------+ | 12 | 70 | 59 | +----------+---------+---------+
FYI, I ended up killing that query (the one which started INSERT INTO editor_month_global) Sunday morning as it still hadn't completed. Sorry for the burden it caused.
@jcrespo, thank you for the advice. I have a couple questions about it (@Nuria, @Ottomata, maybe you know the answers as well). Reading recommendations would be welcome.
For those kind of questions "general consultancy/help", it is quicker if you schedule a chat/meeting. I am trying to organize a session for developers on query optimization, but here you have some quick answers:
The truth is, as infrastructure owners, that once we receive complains, we use tendril, graphana server's board and db-specific profiling to search a root cause and perform immediate actions to solve on-going issues, but we do not have the manpower to followup and help tuning queries (even if I'd love to), as this is just 1 out of the 200 mysql we host, and the thousands of users and applications we run). Sorry for that :-/