Page MenuHomePhabricator
Create Task
Maniphest T204531

Wikidata dumps creating large amounts of log spam
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Description

(Not sure yet if these are the regular dumps or the wikidata-specific ones)

Lots of errors coming from snapshot1008 related to replication lag and read only mode.

This is probably caused because the eqiad s8 master (passive datacenter) was being reimaged for upgrade to the latest kernel and security patches and the mariadb 10.1 upgrade. (Jaime's comment: This happens once every 3 years.)

We need to research why this was happening, and preventing on some way:

  • Can server maintenance be done on a better way, not creating log spam?
  • Can replication checks reduce its spam-icity so we get properly alerted but don't get the same message millions of time. Eg, give an error, but not on cached subsequent occurences or other different model
  • Why does the snapshots require not being lagged? Is lag important for those? If no, Can they just skip those checks? If yes, shouldn't they be running on the active datacenter instead, and not on eqiad?

While this didn't cause issues to final issues, this cause some issues on production due to impact to the logging infrastructure: https://grafana.wikimedia.org/dashboard/db/production-logging?orgId=1&from=1537184523025&to=1537197061054 https://grafana.wikimedia.org/dashboard/db/logstash?orgId=1&from=1537184523025&to=1537197061054

Details

SubjectRepoBranchLines +/-
rdbms: reduce LoadBalancer replication log spammediawiki/coreREL1_30+4 -2
rdbms: reduce LoadBalancer replication log spammediawiki/coreREL1_32+2 -1
rdbms: reduce LoadBalancer replication log spammediawiki/coreREL1_31+2 -1
rdbms: reduce LoadBalancer replication log spammediawiki/coremaster+1 -1
Customize query in gerrit

Event Timeline

jcrespo created this task.Sep 17 2018, 2:04 PM
• Marostegui subscribed.Sep 17 2018, 2:05 PM
Agabi10 subscribed.Sep 17 2018, 2:07 PM
ArielGlenn added a comment.Sep 17 2018, 2:16 PM

The wikidata weeklies are running now; the 'regular' (xml/sql) dumps completed on Sept 15th for the first run of the month.

jcrespo updated the task description. (Show Details)Sep 17 2018, 3:38 PM
Krinkle moved this task from Untriaged to Mar 2021 on the Wikimedia-production-error board.Sep 17 2018, 4:25 PM
ArielGlenn added a comment.Sep 18 2018, 8:33 AM
root@snapshot1008:~# netstat -a -p | grep php | grep eqiad | grep db
tcp        0      0 snapshot1008.eqia:41898 db1087.eqiad.wmne:mysql ESTABLISHED 105786/php7.0       
tcp        0      0 snapshot1008.eqia:42528 db1087.eqiad.wmne:mysql ESTABLISHED 107804/php7.0       
tcp        0      0 snapshot1008.eqia:39826 db1087.eqiad.wmne:mysql ESTABLISHED 120869/php7.0       
tcp        0      0 snapshot1008.eqia:36730 db1087.eqiad.wmne:mysql ESTABLISHED 118688/php7.0       
tcp        0      0 snapshot1008.eqia:39936 db1087.eqiad.wmne:mysql ESTABLISHED 104820/php7.0       
tcp        0      0 snapshot1008.eqia:35566 db1087.eqiad.wmne:mysql ESTABLISHED 118107/php7.0       
tcp        0      0 snapshot1008.eqia:36468 db1087.eqiad.wmne:mysql ESTABLISHED 118553/php7.0       
tcp        0      0 snapshot1008.eqia:35032 db1087.eqiad.wmne:mysql ESTABLISHED 117876/php7.0       

root@snapshot1008:~# ps ww -p 105786 107804 120869 118688 104820 118107 118553 117876
   PID TTY      STAT   TIME COMMAND
104820 ?        S     45:03 /usr/bin/php7.0 /srv/mediawiki/multiversion/MWScript.php extensions/Wikibase/repo/maintenance/dumpRdf.php --wiki wikidatawiki --shard 6 --sharding-factor 8 --batch-size 2000 --format ttl --flavor full-dump --entity-type item --entity-type property --no-cache --dbgroupdefault dump --part-id 6-11 --first-page-id 35200001 --last-page-id 38400000
105786 ?        S     41:08 /usr/bin/php7.0 /srv/mediawiki/multiversion/MWScript.php extensions/Wikibase/repo/maintenance/dumpRdf.php --wiki wikidatawiki --shard 4 --sharding-factor 8 --batch-size 2000 --format ttl --flavor full-dump --entity-type item --entity-type property --no-cache --dbgroupdefault dump --part-id 4-11 --first-page-id 35200001 --last-page-id 38400000
107804 ?        R     40:27 /usr/bin/php7.0 /srv/mediawiki/multiversion/MWScript.php extensions/Wikibase/repo/maintenance/dumpRdf.php --wiki wikidatawiki --shard 5 --sharding-factor 8 --batch-size 2000 --format ttl --flavor full-dump --entity-type item --entity-type property --no-cache --dbgroupdefault dump --part-id 5-11 --first-page-id 35200001 --last-page-id 38400000
117876 ?        S     16:24 /usr/bin/php7.0 /srv/mediawiki/multiversion/MWScript.php extensions/Wikibase/repo/maintenance/dumpRdf.php --wiki wikidatawiki --shard 7 --sharding-factor 8 --batch-size 2000 --format ttl --flavor full-dump --entity-type item --entity-type property --no-cache --dbgroupdefault dump --part-id 7-11 --first-page-id 35200001 --last-page-id 38400000
118107 ?        R     15:45 /usr/bin/php7.0 /srv/mediawiki/multiversion/MWScript.php extensions/Wikibase/repo/maintenance/dumpRdf.php --wiki wikidatawiki --shard 3 --sharding-factor 8 --batch-size 2000 --format ttl --flavor full-dump --entity-type item --entity-type property --no-cache --dbgroupdefault dump --part-id 3-11 --first-page-id 35200001 --last-page-id 38400000
118553 ?        R     14:28 /usr/bin/php7.0 /srv/mediawiki/multiversion/MWScript.php extensions/Wikibase/repo/maintenance/dumpRdf.php --wiki wikidatawiki --shard 1 --sharding-factor 8 --batch-size 2000 --format ttl --flavor full-dump --entity-type item --entity-type property --no-cache --dbgroupdefault dump --part-id 1-11 --first-page-id 35200001 --last-page-id 38400000
118688 ?        S     13:59 /usr/bin/php7.0 /srv/mediawiki/multiversion/MWScript.php extensions/Wikibase/repo/maintenance/dumpRdf.php --wiki wikidatawiki --shard 2 --sharding-factor 8 --batch-size 2000 --format ttl --flavor full-dump --entity-type item --entity-type property --no-cache --dbgroupdefault dump --part-id 2-11 --first-page-id 35200001 --last-page-id 38400000
120869 ?        S     12:03 /usr/bin/php7.0 /srv/mediawiki/multiversion/MWScript.php extensions/Wikibase/repo/maintenance/dumpRdf.php --wiki wikidatawiki --shard 0 --sharding-factor 8 --batch-size 2000 --format ttl --flavor full-dump --entity-type item --entity-type property --no-cache --dbgroupdefault dump --part-id 0-11 --first-page-id 35200001 --last-page-id 38400000

So they are indeed using eqiad. Why is that?

ArielGlenn added a subscriber: hoo.Sep 18 2018, 8:35 AM

Adding @hoo to see what insights he may have.

ArielGlenn added a comment.Sep 18 2018, 8:46 AM

Well, the mystery of 'why eqiad' is solved; the choice of whether to parse db-eqiad.php or db-codfw.php is determined by the global $wmfDatacenter. This is set in multiversion/MWRealm.php from the value of $wmfCluster, which is taken from the contents of /etc/wikimedia-cluster on the server itself. Since the dumps are run from servers in eqiad, there we have it.

jcrespo added a project: Datacenter-Switchover.Sep 18 2018, 9:03 AM
jcrespo added subscribers: akosiaris, Joe.

CC @Joe @akosiaris not to solve the specific issue, but to note it as a potential missed step/puppet code change related to switch datacenter.

Having said that, if dumps are run from eqiad, they probably should query local dbs to prevent privacy issues? So technically we are running active-active if we have to account dumps? Will that break something?

Addshore moved this task from incoming to monitoring on the Wikidata board.Sep 20 2018, 1:14 PM
hoo added a comment.EditedNov 6 2018, 1:10 PM

Just for the record, the errors were:
2018-09-19 07:13:15 [580058d7b2babd5f85e725ec] snapshot1008 wikidatawiki 1.32.0-wmf.20 DBReplication ERROR: Server db1109 has 29.26508808136 seconds of lag (>= 10) {"host":"db1109","lag":29.26508808136,"maxlag":10}
2018-09-19 07:13:31 [c36272088a424bcc438a31e9] snapshot1008 wikidatawiki 1.32.0-wmf.20 DBReplication ERROR: Wikimedia\Rdbms\LoadBalancer::getRandomNonLagged: server db1109 is not replicating? {"host":"db1109"}
Was there anything else?

To fix this, the following MediaWiki LB default config could be made adjustable (to use a null logger) by a maintenance-script argument (or by a config we would set for dump maintenance scripts):
MWLBFactory::applyDefaultConfig: 'replLogger' => LoggerFactory::getInstance( 'DBReplication' )

hoo added a comment.Dec 7 2018, 12:24 PM

I just looked into this some more… We could also create a new LB settings key which would be passed as lagWarnThreshold to LoadMonitor (currently this options is never set, as their is no way to do so, thus this always defaults to LoadMonitor::LAG_WARN_THRESHOLD (10s)).

With that, we could enable certain dump-related maintenance scripts to set it to a reasonable value for their operation… for the Wikidata dumpers, 10-20m of lag should pose no problem.
Something else which (I think) we could already do without altering LoadBalancer related code (but just live-changing DB configuration in Maintenance) is to entirely disabling the load monitoring (use LoadMonitorNull), but I'm not sure that is desirable.

Any thoughts?

hoo added a comment.Dec 7 2018, 12:28 PM

Or we could alter LoadMonitor::getServerStates to not log for a certain db-server more than every N seconds (where N could be derived from LAG_WARN_THRESHOLD, which currently is 10s).

hoo added a subscriber: aaron.Dec 7 2018, 12:28 PM
ArielGlenn added a comment.Dec 7 2018, 2:16 PM

Of the above options, I prefer the idea of explicitly increasing the LAG_WARN_THRESHOLD in scripts where that's desired. Anything that depends on a particular db server makes me uneasy, and I don't like the idea of turning off load monitoring completely either.

hoo added a comment.EditedDec 7 2018, 2:19 PM

Anything that depends on a particular db server makes me uneasy

Hm… above I meant that per DB server it should only ever warn each (like) LAG_WARN_THRESHOLD / 2 seconds… it makes little sense to let a single LoadMonitor instance create more log entries per DB.

(This limitation would be per LoadMonitor instance, so not spanning multiple maintenance runs or web requests (which we don't care for here anyway))

ArielGlenn added a comment.EditedDec 7 2018, 5:05 PM

Ah, I misread! Before we arbitrarily throttle though, I'd like the dbas to weigh in. It might be that having the flood actually flood may be helpful sometimes, in the case where it might mean something (not for dumps scripts).

Krinkle added a project: Performance-Team.Dec 7 2018, 11:16 PM

@aaron This task mentions various rdbms/LoadBalancer-related configuration options and how they interact with maintenance scripts that seemingly need to tolerate longer replication lag without warnings. I'm not 100% sure, but it looks like this is proposing changes to the library and/or ServiceWiring, if so, I think this might benefit from your feedback as well. Hereby solicited :)

gerritbot subscribed.Dec 10 2018, 8:29 PM

Change 478773 had a related patch set uploaded (by Aaron Schulz; owner: Aaron Schulz):
[mediawiki/core@master] rdbms: reduce LoadBalancer replication log spam

https://gerrit.wikimedia.org/r/478773

gerritbot added a project: Patch-For-Review.Dec 10 2018, 8:29 PM
• Imarlier assigned this task to aaron.Dec 10 2018, 9:04 PM
• Imarlier moved this task from Inbox, needs triage to Doing (old) on the Performance-Team board.
• Imarlier subscribed.

@aaron is going to see what else can be done to reduce spam, will then assign back to @ArielGlenn

hoo added a comment.EditedDec 11 2018, 11:01 AM

I just revisited the original logs… and I found that the way way way more common error back then was from LoadBalancer::getRandomNonLagged:

2018-09-19 07:13:27 [1d74bb1b0e64917ec3cd47e7] snapshot1008 wikidatawiki 1.32.0-wmf.20 DBReplication ERROR: Wikimedia\Rdbms\LoadBalancer::getRandomNonLagged: server db1109 is not replicating? {"host":"db1109"}

I'll try to have a look at this soon.

gerritbot added a comment.Dec 11 2018, 7:39 PM

Change 478773 merged by jenkins-bot:
[mediawiki/core@master] rdbms: reduce LoadBalancer replication log spam

https://gerrit.wikimedia.org/r/478773

ReleaseTaggerBot added a project: MW-1.33-notes (1.33.0-wmf.9; 2018-12-18).Dec 11 2018, 8:00 PM
hoo added a comment.Dec 13 2018, 7:26 PM
In T204531#4813322, @hoo wrote:

I just revisited the original logs… and I found that the way way way more common error back then was from LoadBalancer::getRandomNonLagged:

2018-09-19 07:13:27 [1d74bb1b0e64917ec3cd47e7] snapshot1008 wikidatawiki 1.32.0-wmf.20 DBReplication ERROR: Wikimedia\Rdbms\LoadBalancer::getRandomNonLagged: server db1109 is not replicating? {"host":"db1109"}

I'll try to have a look at this soon.

I just had a brief look at this… and it's not easy to resolve this one AFAICT, given we don't ever want to completely ignore the fact that a DB is not replicating at all, I guess. We could use a HashBagOStuff in LoadBalancer to determine that we only log this errors once every N seconds (per DB server)?!

Krinkle removed a project: Patch-For-Review.Dec 13 2018, 8:41 PM
gerritbot added a comment.Jan 11 2019, 9:06 PM

Change 483859 had a related patch set uploaded (by Paladox; owner: Aaron Schulz):
[mediawiki/core@REL1_32] rdbms: reduce LoadBalancer replication log spam

https://gerrit.wikimedia.org/r/483859

gerritbot added a project: Patch-For-Review.Jan 11 2019, 9:06 PM
gerritbot added a comment.Jan 12 2019, 5:56 PM

Change 483942 had a related patch set uploaded (by Reedy; owner: Aaron Schulz):
[mediawiki/core@REL1_31] rdbms: reduce LoadBalancer replication log spam

https://gerrit.wikimedia.org/r/483942

gerritbot added a comment.Jan 12 2019, 6:01 PM

Change 483943 had a related patch set uploaded (by Reedy; owner: Aaron Schulz):
[mediawiki/core@REL1_30] rdbms: reduce LoadBalancer replication log spam

https://gerrit.wikimedia.org/r/483943

gerritbot added a comment.Jan 12 2019, 6:09 PM

Change 483859 merged by jenkins-bot:
[mediawiki/core@REL1_32] rdbms: reduce LoadBalancer replication log spam

https://gerrit.wikimedia.org/r/483859

gerritbot added a comment.Jan 12 2019, 6:09 PM

Change 483942 merged by jenkins-bot:
[mediawiki/core@REL1_31] rdbms: reduce LoadBalancer replication log spam

https://gerrit.wikimedia.org/r/483942

gerritbot added a comment.Jan 12 2019, 6:15 PM

Change 483943 merged by jenkins-bot:
[mediawiki/core@REL1_30] rdbms: reduce LoadBalancer replication log spam

https://gerrit.wikimedia.org/r/483943

ReleaseTaggerBot added projects: MW-1.31-release-notes, MW-1.30-release-notes, MW-1.32-notes.Jan 12 2019, 7:00 PM
Krinkle closed this task as Resolved.Jan 22 2019, 3:18 AM
Krinkle removed projects: Patch-For-Review, MW-1.33-notes (1.33.0-wmf.9; 2018-12-18).
ArielGlenn moved this task from Backlog to Done on the Dumps-Generation board.Feb 6 2019, 1:40 PM
• mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:08 PM
Krinkle removed a project: Wikimedia-production-error.Feb 10 2021, 7:23 PM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL