Page MenuHomePhabricator

Investigate some Wikidata write api queries taking over 30 seconds. (In EntityContent::collectValues?)
Closed, ResolvedPublic

Description

While investigating T97368#4576389 I noticed that the particular query that I was looking at took over 30 seconds to finish executing according to the api.log

... [W5jEGwpAAK4AAKd9eigAAAAV] ... API POST ... T=31327ms action=wbsetqualifier format=json claim=Q56596767$BD081022-A6F4-4297-B7A2-484F2918094A property=P1932 value=%22A.%20Zucchetta%22 snaktype=value ... baserevid=744943483 bot=1

I recreated the edit to profile and the result can be seen on https://performance.wikimedia.org/xhgui/run/view?id=5b98dd85bb85446306a75aae

This appears to indicate that most of the time is spent in a single method in EntityContent:

Wikibase\EntityContent::collectValues@2
3,530,113 µs

Which is apparently called 30 times?
I might need someone from Performance-Team, perhaps @Krinkle to make sure I am reading xhgui correctly

We should investigate this and see if we can speed this code path up.
It would be great to create a copy of this item on our test wiki to benchmark against.

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 12 2018, 9:44 AM

It looks like generally the loading took around 2 seconds, EditFilterHookRunner took around 11 seconds and the actual saveEntity took 10 seconds.

Wikibase\EntityContent::collectValues doesn't look like it is that big of an issue, and it contributes 3 of the EditFilterHookRunner seconds.

I think there is an improvement to be made in Wikibase\EntityContent::collectValues.
it currently has a hard coded list of keys to ignore:

		//XXX: $ignore contains knowledge about the Entity's internal representation.
		//     This list should therefore rather be maintained in the Entity class.
		static $ignore = [
			'language',
			'site',
			'type',
		];

This should be provided by each entity type as they can be different.
For regular items and properties there are keys missing that should be added.
For lexeme etc there are other keys that possible need to be added / thought about that have no way of getting into that list.

Ignoring more keys here will result in less data for AbuseFilter to then run through which would increase performance...
Right now for example the AbuseFilter will get handed all of the reference hashes and snak types etc.

After some experimenting I managed to add a bunch of keys to the ignore which are probably fine to ignore:

$ignore = array(
	'language',
	'site',
	'type',
	'hash',
	'id',
	'rank',
	'entity-type',
	'datatype',
	'snaktype',
	'qualifiers-order',
	'property',
);

For Q56596767 on wikidata.org running collectValues:
Before:
Total execution time: 1.4714670181274
Number of strings: 30426
After:
Total execution time: 0.12493205070496
Number of strings: 4673

I have no doubt that this will have knock on effects in Abusefilter, probably reducing the run time by ~60%?

/me should file some tickets.....

Change 461697 had a related patch set uploaded (by Addshore; owner: Addshore):
[mediawiki/extensions/Wikibase@master] Improve the performance of EntityContent::collectValues

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

Restricted Application added a project: User-Addshore. · View Herald TranscriptSep 20 2018, 6:00 PM
Krinkle renamed this task from Investigate some Wikdata write api queries taking over 30 seconds. (In EntityContent::collectValues ?) to Investigate some Wikdata write api queries taking over 30 seconds. (In EntityContent::collectValues?).Sep 20 2018, 6:04 PM
Aklapper renamed this task from Investigate some Wikdata write api queries taking over 30 seconds. (In EntityContent::collectValues?) to Investigate some Wikidata write api queries taking over 30 seconds. (In EntityContent::collectValues?).Sep 20 2018, 7:59 PM

Change 461755 had a related patch set uploaded (by Addshore; owner: Addshore):
[mediawiki/extensions/Wikibase@master] Track entity save times in detail in statsd

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

Addshore triaged this task as Normal priority.Sep 21 2018, 9:52 AM
Addshore moved this task from incoming to in progress on the Wikidata board.Sep 26 2018, 6:23 AM

Change 473790 had a related patch set uploaded (by Addshore; owner: Addshore):
[mediawiki/extensions/Wikibase@master] EditEntity, Track EditFilterHook run times in statsd

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

Change 473791 had a related patch set uploaded (by Addshore; owner: Addshore):
[mediawiki/extensions/Wikibase@master] EditEntity, Track EntityStore save times in statsd

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

Change 473802 had a related patch set uploaded (by Addshore; owner: Addshore):
[mediawiki/extensions/Wikibase@master] EntityContent::collectValues, add some basic test coverage

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

For reviewers, i made a topic with all of the commits in:

Change 461755 merged by jenkins-bot:
[mediawiki/extensions/Wikibase@master] EditEntity, Track entity save times in statsd

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

Change 473790 merged by jenkins-bot:
[mediawiki/extensions/Wikibase@master] EditEntity, Track EditFilterHook run times in statsd

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

Change 473791 merged by jenkins-bot:
[mediawiki/extensions/Wikibase@master] EditEntity, Track EntityStore save times in statsd

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

Change 473802 merged by jenkins-bot:
[mediawiki/extensions/Wikibase@master] EntityContent::collectValues, add some basic test coverage

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

The rest of the chain has been deployed with wmf.6, so I tried putting the data into a Grafana dashboard: Wikidata EditEntity.

If my interpretation is correct, then the “Item” panel tells us that the total time of EditEntity.attemptSave is almost entirely taken up by EditFilterHookRunner.run and EntityStore.saveEntity, with everything else being almost negligible; and the “Item, store vs. hooks” panel shows more clearly that the majority of that time, somewhere around 60%, is taken up by EditFilterHookRunner.run, not EntityStore.saveEntity.

When we merge and deploy the end of the chain, we should see that ratio drop drastically, since EditFilterHookRunner.run should now be much more efficient, and the overall timings in the “Item” panel should decrease accordingly, and now probably be dominated by EntityStore.saveEntity alone.

Does that sound right?

Krinkle moved this task from Watching to Perf issue on the Performance-Team (Radar) board.

Looking forward to the results :)

Change 461697 merged by jenkins-bot:
[mediawiki/extensions/Wikibase@master] ArrayValueCollector, Improve the performance

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

As far as I can tell, all the changes relevant to this task are merged now (there are still some open for the subtask T205252). Moving to the verification column – hopefully we should see the Grafana stats improve once this goes out with the train.

But because there’s no train this week (releng offsite), that would be next week, on December 12th. Do we wait until then or do we want to backport the “improve performance” patch?

Addshore closed this task as Resolved.Dec 14 2018, 12:11 PM

So the monitoring was deployed with wmf6
The improvement was deployed with wmf.8
I added annotations (which we can now do) to https://grafana.wikimedia.org/d/000000615/wikidata-editentity for these deploys.

Looking specifically at EditFilterHookRunner p99 this decreases form a range of 10-7.5 seconds to 7-2.5 seconds after deployment
For p95 this didn't really decrease a significant amount.

This totally makes sense and I'm glad we have decreased this save time for these larger entities :)
The saved time will have effects across all entities but it's much harder to see for the smaller entities.

I'm closing this task as the easiest subtask has been tackled.

T205252 & T205254 Should still be picked up but are blocked on finding out how abuse filter is currently used.
Fixing these would save more time agian!