Page MenuHomePhabricator
Create Task
Maniphest T96360

img_metadata queries for Djvu files regularly saturate s4 slaves
Closed, ResolvedPublic
Actions

Description

https://wikitech.wikimedia.org/wiki/Incidents/20150423-Commons

For the past few days, we've been seeing s4 slaves saturate their network port (1GbE) occasionally, in spikes that effectively quadruple their normal network usage.

db1070.png (373×747 px, 40 KB)

As far as I can see, these can be attributed to img_metadata queries about Djvu files, all coming from search engine IPs (i.e. Googlebot/MSNbot crawling some URL).

Example from a db1070 processlist a moment ago:

SELECT /* ForeignDBFile::loadExtraFromDB 207.46.13.84 */  img_metadata  FROM `image`   WHERE img_name = 'Dictionary_of_National_Biography_volume_27.djvu' AND img_timestamp = '20121213235036'  LIMIT 1 
SELECT /* ForeignDBFile::loadExtraFromDB 66.249.67.12 */  img_metadata  FROM `image`   WHERE img_name = 'Popular_Science_Monthly_Volume_68.djvu' AND img_timestamp = '20090517032649'  LIMIT 1  
SELECT /* ForeignDBFile::loadExtraFromDB 66.249.67.20 */  img_metadata  FROM `image`   WHERE img_name = 'United_States_Statutes_at_Large_Volume_116_Part_1.djvu' AND img_timestamp = '20110920010238'  LIMIT 1  
SELECT /* ForeignDBFile::loadExtraFromDB 66.249.67.20 */  img_metadata  FROM `image`   WHERE img_name = 'Title_3_CFR_2000_Compilation.djvu' AND img_timestamp = '20111001220528'  LIMIT 1       
SELECT /* ForeignDBFile::loadExtraFromDB 66.249.67.4 */  img_metadata  FROM `image`   WHERE img_name = 'United_States_Statutes_at_Large_Volume_115_Part_3.djvu' AND img_timestamp = '20110701153753'  LIMIT 1   
SELECT /* ForeignDBFile::loadExtraFromDB 66.249.67.20 */  img_metadata  FROM `image`   WHERE img_name = 'The_Methodist_Hymn-Book_Illustrated.djvu' AND img_timestamp = '20081102105445'  LIMIT 1        
SELECT /* ForeignDBFile::loadExtraFromDB 66.249.67.20 */  img_metadata  FROM `image`   WHERE img_name = 'The_Lusiad_(Camões,_tr._Mickle,_1791),_Volume_1.djvu' AND img_timestamp = '20100612172724'  LIMIT 1    
SELECT /* ForeignDBFile::loadExtraFromDB 66.249.67.20 */  img_metadata  FROM `image`   WHERE img_name = 'Riders_of_the_Purple_Sage.djvu' AND img_timestamp = '20130615001915'  LIMIT 1

The output of e.g. the first query is a 2.5MB <mw-djvu> XML; similar for the rest, which explains the network saturation.

Details

SubjectRepoBranchLines +/-
Added common metadata caching to the djvu handlermediawiki/coremaster+42 -16
Temporary hack to drain excess refreshLinks jobsmediawiki/coremaster+8 -0
Added common metadata caching to the djvu handlermediawiki/corewmf/1.26wmf5+42 -16
Set isExpensiveToThumbnail for the djvu handlermediawiki/corewmf/1.26wmf4+11 -0
Set isExpensiveToThumbnail for the djvu handlermediawiki/corewmf/1.26wmf5+11 -0
Set isExpensiveToThumbnail for the djvu handlermediawiki/coremaster+11 -0
Removed DjVu pageCount() check and let it surface in the shell commandmediawiki/coremaster+0 -8
Removed DjVu pageCount() check and let it surface in the shell commandmediawiki/corewmf/1.26wmf3+0 -8
Removed DjVu pageCount() check and let it surface in the shell commandmediawiki/corewmf/1.26wmf4+0 -8
Customize query in gerrit

Related Objects

Event Timeline

faidon created this task.Apr 17 2015, 11:43 AM
faidon raised the priority of this task from to Unbreak Now!.
faidon updated the task description. (Show Details)
faidon added projects: MediaWiki-General, acl*sre-team.
faidon added subscribers: faidon, • Springle.
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptApr 17 2015, 11:43 AM
GOIII added a project: MediaWiki-DjVu.Apr 21 2015, 12:15 AM
GOIII set Security to None.
GOIII subscribed.
Aklapper added projects: Sustainability, Multimedia.Apr 24 2015, 1:40 PM

these can be attributed to img_metadata queries about Djvu files, all coming from search engine IPs (i.e. Googlebot/MSNbot crawling some URL).

CC'ing Sustainability and Multimedia - anybody have any more insights?

• GWicke subscribed.EditedApr 25 2015, 7:32 PM

This seems to be caused by this call chain:

It is not clear to me why the xml is loaded at all:

		// Fetch XML and check it, to give a more informative error message than the one which
		// normaliseParams will inevitably give.
		$xml = $image->getMetadata();
		if ( !$xml ) {
			$width = isset( $params['width'] ) ? $params['width'] : 0;
			$height = isset( $params['height'] ) ? $params['height'] : 0;
			return new MediaTransformError( 'thumbnail_error', $width, $height,
				wfMessage( 'djvu_no_xml' )->text() );
		}

$xml is not referenced any further in doTransform.

• GWicke mentioned this in T75960: Limit the number of media files used on a wiki page.Apr 25 2015, 7:49 PM
• GWicke added a comment.Apr 25 2015, 8:10 PM

Patch to remove the XML loading at https://gerrit.wikimedia.org/r/#/c/206526/.

• GWicke mentioned this in rMW71107e750250: Don't load XML metadata on DjVu thumb generation.Apr 25 2015, 8:21 PM
• GWicke added a project: Incident-20150423-Commons.Apr 25 2015, 8:31 PM
aaron mentioned this in rMW40d702b8d2d0: Don't load XML metadata on DjVu thumb generation.Apr 27 2015, 5:15 PM
aaron mentioned this in rMWb980b0a9457b: Don't load XML metadata on DjVu thumb generation.
GOIII added a comment.Apr 28 2015, 2:10 AM

What is the story re: XMLs and DjVuImage.php ?

faidon added a comment.Apr 28 2015, 11:05 PM

I thought Aaron merged this and backported it but this is happening again right now. Example query:

SELECT /* ForeignDBFile::loadExtraFromDB 66.249.79.94 */  img_metadata  FROM `image`   WHERE img_name = 'Revue_des_Deux_Mondes_-_1874_-_tome_3.djvu' AND img_timestamp = '20100802045839'  LIMIT 1
BBlack assigned this task to • GWicke.Apr 29 2015, 2:51 PM
BBlack subscribed.

Triage-assigning this to @GWicke so it has an owner, since he's submitted the only patch for this so far. Will CC Aaron as well...

BBlack added a subscriber: aaron.Apr 29 2015, 2:51 PM
faidon added a subscriber: • Gilles.May 1 2015, 10:53 PM

This has been happening over and over again for all this time (happened just now again). Every time it does, the s4 slaves get saturated and are slower to respond to other queries, hence the UBN severity.

Can we get some attention to this bug please? Maybe @aaron or @Gilles?

aaron added a comment.May 1 2015, 11:33 PM

It probably just hits <<if ( $page > $this->pageCount( $image ) )>> and loads the metadata again with another code path.

img_metadata is *supposed* to be lighweight and easily loaded. The fact the Pdf/DjVu handlers don't do this makes things pretty awkward. They all need a ground-up rewrite to avoid this (and other problems).

gerritbot subscribed.May 1 2015, 11:37 PM

Change 208304 had a related patch set uploaded (by Aaron Schulz):
Removed DjVu pageCount() check and let it surface in the shell command

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

gerritbot added a project: Patch-For-Review.May 1 2015, 11:37 PM

Change 208306 had a related patch set uploaded (by Aaron Schulz):
Removed DjVu pageCount() check and let it surface in the shell command

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

gerritbot added a comment.May 1 2015, 11:39 PM

Change 208307 had a related patch set uploaded (by Aaron Schulz):
Removed DjVu pageCount() check and let it surface in the shell command

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

gerritbot added a comment.May 1 2015, 11:50 PM

Change 208304 merged by jenkins-bot:
Removed DjVu pageCount() check and let it surface in the shell command

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

aaron mentioned this in rMW54816e2071fc: Removed DjVu pageCount() check and let it surface in the shell command.May 1 2015, 11:50 PM
gerritbot added a comment.May 1 2015, 11:51 PM

Change 208306 merged by jenkins-bot:
Removed DjVu pageCount() check and let it surface in the shell command

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

gerritbot added a comment.May 1 2015, 11:51 PM

Change 208307 merged by jenkins-bot:
Removed DjVu pageCount() check and let it surface in the shell command

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

aaron mentioned this in rMW6cdb23c5d662: Removed DjVu pageCount() check and let it surface in the shell command.May 1 2015, 11:51 PM
aaron mentioned this in rMWcaa2efc0e76c: Removed DjVu pageCount() check and let it surface in the shell command.
faidon added a comment.May 2 2015, 1:30 PM
In T96360#1253818, @aaron wrote:

It probably just hits <<if ( $page > $this->pageCount( $image ) )>> and loads the metadata again with another code path.

img_metadata is *supposed* to be lighweight and easily loaded. The fact the Pdf/DjVu handlers don't do this makes things pretty awkward. They all need a ground-up rewrite to avoid this (and other problems).

Thanks! Is there a separate bug for tracking this?

555 subscribed.May 2 2015, 7:22 PM
aaron added a comment.May 10 2015, 6:23 PM
In T96360#1254487, @faidon wrote:
In T96360#1253818, @aaron wrote:

It probably just hits <<if ( $page > $this->pageCount( $image ) )>> and loads the metadata again with another code path.

img_metadata is *supposed* to be lighweight and easily loaded. The fact the Pdf/DjVu handlers don't do this makes things pretty awkward. They all need a ground-up rewrite to avoid this (and other problems).

Thanks! Is there a separate bug for tracking this?

I thought there was, but I didn't find it (just something about upgradeRow). It should be created.

gerritbot added a comment.May 10 2015, 7:32 PM

Change 209983 had a related patch set uploaded (by Aaron Schulz):
Added common metadata caching to the djvu handler

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

gerritbot added a comment.May 10 2015, 7:49 PM

Change 209984 had a related patch set uploaded (by Aaron Schulz):
Set isExpensiveToThumbnail for the djvu handler

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

gerritbot added a comment.May 10 2015, 7:55 PM

Change 209985 had a related patch set uploaded (by Aaron Schulz):
Set isExpensiveToThumbnail for the djvu handler

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

gerritbot added a comment.May 10 2015, 7:59 PM

Change 209986 had a related patch set uploaded (by Aaron Schulz):
Set isExpensiveToThumbnail for the djvu handler

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

gerritbot added a comment.May 10 2015, 8:04 PM

Change 209984 merged by jenkins-bot:
Set isExpensiveToThumbnail for the djvu handler

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

aaron mentioned this in rMW63df71ea72a1: Set isExpensiveToThumbnail for the djvu handler.May 10 2015, 8:06 PM
gerritbot added a comment.May 11 2015, 3:50 PM

Change 209985 merged by jenkins-bot:
Set isExpensiveToThumbnail for the djvu handler

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

aaron mentioned this in rMW7f1fdec68884: Set isExpensiveToThumbnail for the djvu handler.May 11 2015, 3:50 PM
gerritbot added a comment.May 11 2015, 3:52 PM

Change 209986 merged by jenkins-bot:
Set isExpensiveToThumbnail for the djvu handler

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

aaron mentioned this in rMW11c79de809d0: Set isExpensiveToThumbnail for the djvu handler.May 11 2015, 3:52 PM
Anomie subscribed.May 11 2015, 3:53 PM
In T96360#1236196, @GWicke wrote:

It is not clear to me why the xml is loaded at all:

You quoted the comment that explains why:

		// Fetch XML and check it, to give a more informative error message than the one which
		// normaliseParams will inevitably give.

$image->getMetadata() returning falsey is going to cause the $this->normaliseParams() call just after the quoted block to fail (root cause likely being that $this->pageCount(), $this->getPageDimensions(), and $this->getPageText() will return false instead of something expected), and it was thought that the error message given by that failure case was too uninformative.

Whether it's really too uninformative I have no idea.

gerritbot added a comment.May 12 2015, 5:59 AM

Change 209983 merged by jenkins-bot:
Added common metadata caching to the djvu handler

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

aaron mentioned this in rMW746c8ddc1d52: Added common metadata caching to the djvu handler.May 12 2015, 5:59 AM
aaron added a comment.EditedMay 12 2015, 6:24 AM
In T96360#1276379, @Anomie wrote:
In T96360#1236196, @GWicke wrote:

It is not clear to me why the xml is loaded at all:

You quoted the comment that explains why:

		// Fetch XML and check it, to give a more informative error message than the one which
		// normaliseParams will inevitably give.

$image->getMetadata() returning falsey is going to cause the $this->normaliseParams() call just after the quoted block to fail (root cause likely being that $this->pageCount(), $this->getPageDimensions(), and $this->getPageText() will return false instead of something expected), and it was thought that the error message given by that failure case was too uninformative.

Whether it's really too uninformative I have no idea.

It might make sense to revert those 1 of those patches, since it still hits getMetaTree anyway. We have poolcounter (merged) and hopefully caching based patches (pending) to address this.

• Springle added a comment.May 12 2015, 6:53 AM

jftr, S4 had ~2 hours of this again today. Mostly googlebot IPs.

aaron added a comment.May 12 2015, 8:19 AM

/srv/mediawiki/w/index.php;MediaWiki::run;MediaWiki::main;MediaWiki::performRequest;MediaWiki::performAction;ViewAction::show;CategoryPage::view;CategoryPage::closeShowCategory;CategoryViewer::getHTML;CategoryViewer::getImageSection;TraditionalImageGallery::toHTML;File::transform;File::canRender;ImageHandler::canRender;LocalFile::getWidth;DjVuHandler::getPageDimensions;DjVuHandler::getMetaTree;SimpleXMLElement::__construct 1

• GWicke added a comment.EditedMay 12 2015, 3:51 PM

It might make sense to revert those 1 of those patches, since it still hits getMetaTree anyway. We have poolcounter (merged) and hopefully caching based patches (pending) to address this.

I don't think that's true for cache hits?

aaron added a comment.May 12 2015, 4:57 PM

I was looking at 54816e2071fc3e38ad581a264967bd46cbb3647e. And the problem sean mentioned is due to the code for just getting a thumbnail URL (and doing basic checks) and not rendering it yet *still* wants to load getMetaTree, such as the category view stack above. Poolcounter does not cover this case, so something more will be needed there.

gerritbot added a comment.May 12 2015, 7:15 PM

Change 210409 had a related patch set uploaded (by Aaron Schulz):
Added common metadata caching to the djvu handler

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

Nemo_bis subscribed.May 12 2015, 7:20 PM
Ricordisamoa subscribed.May 12 2015, 7:25 PM
gerritbot added a comment.May 12 2015, 8:41 PM

Change 210608 had a related patch set uploaded (by Aaron Schulz):
Temporary hack to drain excess refreshLinks jobs

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

gerritbot added a comment.May 12 2015, 8:41 PM

Change 210610 had a related patch set uploaded (by Aaron Schulz):
Temporary hack to drain excess refreshLinks jobs

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

gerritbot added a comment.May 12 2015, 8:42 PM

Change 210611 had a related patch set uploaded (by Aaron Schulz):
Temporary hack to drain excess refreshLinks jobs

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

aaron added a comment.May 12 2015, 8:48 PM

Ignore the last 3 gerrit comments.

gerritbot added a comment.May 12 2015, 11:21 PM

Change 210409 merged by jenkins-bot:
Added common metadata caching to the djvu handler

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

aaron mentioned this in rMW9afa7531ed23: Added common metadata caching to the djvu handler.May 12 2015, 11:22 PM
aaron closed this task as Resolved.May 15 2015, 5:40 PM

Base i/o is down 33% and I have yet to see any new spikes at http://ganglia.wikimedia.org/latest/?r=week&cs=&ce=&m=cpu_report&c=MySQL+eqiad&h=db1064.eqiad.wmnet&tab=m&vn=&hide-hf=false&mc=2&z=medium&metric_group=ALLGROUPS

aaron mentioned this in T32906: Store DjVu, PDF extracted text in a structured table instead of img_metadata.May 15 2015, 5:42 PM
gerritbot added a comment.May 17 2015, 5:54 PM

Change 210608 abandoned by Aaron Schulz:
Temporary hack to drain excess refreshLinks jobs

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

waldyrious mentioned this in T107664: Some DjVu files not being rendered in commons (showing up as "0 × 0 pixels", despite the file size in MB being nonzero).Aug 3 2015, 12:42 PM
Volans mentioned this in T147296: img_metadata queries for PDF files saturates s4 replicas.Oct 4 2016, 10:12 AM
Aklapper removed a subscriber: Anomie.Oct 16 2020, 5:38 PM
Krinkle updated the task description. (Show Details)Sep 10 2022, 12:01 AM
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