Page MenuHomePhabricator

Maximum execution time exceeded from Memcached (on page views)
Closed, DuplicatePublic

Description

Dunno if this is another "my wiki" type problem.. But I've been seeing a load of these recently too

( ! ) Fatal error: Maximum execution time of 120 seconds exceeded in /var/www/wiki/mediawiki/core/includes/libs/objectcache/MemcachedBagOStuff.php on line 79
Call Stack
#	Time	Memory	Function	Location
1	0.0002	361248	{main}( )	.../index.php:0
2	0.0736	3245016	MediaWiki->run( )	.../index.php:43
3	0.0740	3245016	MediaWiki->main( )	.../MediaWiki.php:512
4	2.5681	7371008	MediaWiki->{closure:/var/www/wiki/mediawiki/core/includes/MediaWiki.php:856-862}( )	.../MediaWiki.php:870
5	2.5681	7371008	OutputPage->output( )	.../MediaWiki.php:858
6	2.5725	7462632	SkinTemplate->outputPage( )	.../OutputPage.php:2366
7	2.5777	7468032	SkinTemplate->prepareQuickTemplate( )	.../SkinTemplate.php:249
8	2.6534	7578240	Skin->bottomScripts( )	.../SkinTemplate.php:483
9	2.6534	7578240	OutputPage->getBottomScripts( )	.../Skin.php:604
10	2.6534	7578240	OutputPage->getRlClient( )	.../OutputPage.php:2961
11	2.6676	7832576	ResourceLoaderWikiModule::preloadTitleInfo( )	.../OutputPage.php:2756
12	2.6679	7834808	WANObjectCache->getWithSetCallback( )	.../ResourceLoaderWikiModule.php:377
13	2.6679	7834808	WANObjectCache->doGetWithSetCallback( )	.../WANObjectCache.php:906
14	2.6679	7834856	WANObjectCache->get( )	.../WANObjectCache.php:943
15	2.6679	7835280	WANObjectCache->getMulti( )	.../WANObjectCache.php:246
16	2.6690	7837680	WANObjectCache->processCheckKeys( )	.../WANObjectCache.php:304
17	2.6691	7837736	MemcachedPeclBagOStuff->add( )	.../WANObjectCache.php:362
18	2.6695	7837848	MemcachedBagOStuff->add( )	.../MemcachedPeclBagOStuff.php:173
19	2.6695	7837848	add ( )	.../MemcachedBagOStuff.php:79

Event Timeline

Reedy created this task.Dec 4 2016, 1:56 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptDec 4 2016, 1:56 PM
Paladox added a subscriber: Paladox.Dec 4 2016, 2:04 PM
aaron added a subscriber: aaron.Dec 22 2016, 10:40 PM

I don't see this in production, but there are some oddities in querying the heartbeat table or closing the trx that does so when an uncached getLagTimes() call is made. This sometimes takes 5+ sec and effects this code path. I doubt that's the same thing as what's going on with a dev wiki though...

@Reedy Can you still reproduce and/or see in logs? Also, the time column, is that time in seconds? If so, does that mean that after 2s in various code paths, it got locked for 118s in native Memcached::add()?

Krinkle triaged this task as Low priority.Dec 22 2016, 10:44 PM
Krinkle removed a project: Performance-Team.
Krinkle moved this task from Inbox to Backlog on the MediaWiki-ResourceLoader board.

Not exactly the same, but yeah, still there... I think it's seconds, so yeah, most of the 2 minutes doing memcached stuff

( ! ) Fatal error: Maximum execution time of 120 seconds exceeded in /var/www/wiki/mediawiki/core/includes/libs/objectcache/MemcachedBagOStuff.php on line 70
Call Stack
#	Time	Memory	Function	Location
1	0.0000	361672	{main}( )	.../index.php:0
2	0.0769	3803064	MediaWiki->run( )	.../index.php:43
3	0.0773	3803064	MediaWiki->main( )	.../MediaWiki.php:512
4	0.7603	5320784	MediaWiki->{closure:/var/www/wiki/mediawiki/core/includes/MediaWiki.php:856-862}( )	.../MediaWiki.php:870
5	0.7603	5320784	OutputPage->output( )	.../MediaWiki.php:858
6	0.7622	5376384	SkinTemplate->outputPage( )	.../OutputPage.php:2366
7	0.7677	5383832	SkinTemplate->prepareQuickTemplate( )	.../SkinTemplate.php:249
8	0.9244	6202000	OutputPage->headElement( )	.../SkinTemplate.php:486
9	0.9376	6222648	Action::getActionName( )	.../OutputPage.php:2876
10	0.9376	6222648	Action::factory( )	.../Action.php:154
11	0.9376	6222648	WikiPage->getActionOverrides( )	.../Action.php:96
12	0.9377	6222648	WikiPage->getContentHandler( )	.../WikiPage.php:212
13	0.9377	6222648	WikiPage->getContentModel( )	.../WikiPage.php:225
14	0.9378	6223032	WANObjectCache->getWithSetCallback( )	.../WikiPage.php:516
15	0.9378	6223032	WANObjectCache->doGetWithSetCallback( )	.../WANObjectCache.php:906
16	0.9383	6223600	WANObjectCache->set( )	.../WANObjectCache.php:1030
17	0.9383	6224752	MemcachedBagOStuff->merge( )	.../WANObjectCache.php:475
18	0.9383	6224752	BagOStuff->mergeViaCas( )	.../MemcachedBagOStuff.php:83
19	0.9386	6225288	MemcachedPeclBagOStuff->cas( )	.../BagOStuff.php:313
20	0.9387	6225384	MemcachedBagOStuff->cas( )	.../MemcachedPeclBagOStuff.php:157
21	0.9387	6225384	cas ( )	.../MemcachedBagOStuff.php:70

Got it again

( ! ) Fatal error: Maximum execution time of 120 seconds exceeded in /var/www/wiki/mediawiki/core/includes/libs/objectcache/MemcachedBagOStuff.php on line 79
Call Stack
#	Time	Memory	Function	Location
1	0.0021	362016	{main}( )	.../index.php:0
2	4.4070	7508056	MediaWiki->run( )	.../index.php:43
3	4.4074	7508056	MediaWiki->main( )	.../MediaWiki.php:512
4	9.0818	9286992	MediaWiki->{closure:/var/www/wiki/mediawiki/core/includes/MediaWiki.php:856-862}( )	.../MediaWiki.php:870
5	9.0818	9286992	OutputPage->output( )	.../MediaWiki.php:858
6	9.1457	9495608	SkinTemplate->outputPage( )	.../OutputPage.php:2366
7	9.1508	9502496	SkinTemplate->prepareQuickTemplate( )	.../SkinTemplate.php:249
8	12.1028	12387840	Skin->bottomScripts( )	.../SkinTemplate.php:483
9	12.1028	12387840	OutputPage->getBottomScripts( )	.../Skin.php:604
10	12.1028	12387840	OutputPage->getRlClient( )	.../OutputPage.php:2961
11	12.1900	12711168	ResourceLoaderWikiModule::preloadTitleInfo( )	.../OutputPage.php:2757
12	12.1941	12723664	WANObjectCache->getWithSetCallback( )	.../ResourceLoaderWikiModule.php:377
13	12.1941	12723664	WANObjectCache->doGetWithSetCallback( )	.../WANObjectCache.php:906
14	12.1941	12723712	WANObjectCache->get( )	.../WANObjectCache.php:943
15	12.1941	12724136	WANObjectCache->getMulti( )	.../WANObjectCache.php:246
16	12.1946	12726128	WANObjectCache->processCheckKeys( )	.../WANObjectCache.php:304
17	12.1947	12726184	MemcachedPeclBagOStuff->add( )	.../WANObjectCache.php:362
18	12.1948	12726296	MemcachedBagOStuff->add( )	.../MemcachedPeclBagOStuff.php:173
19	12.1948	12726296	add ( )	.../MemcachedBagOStuff.php:79

Not exactly the same, but yeah, still there... I think it's seconds, so yeah, most of the 2 minutes doing memcached stuff

( ! ) Fatal error: Maximum execution time of 120 seconds exceeded in /var/www/wiki/mediawiki/core/includes/libs/objectcache/MemcachedBagOStuff.php on line 70
Call Stack
#	Time	Memory	Function	Location
1	0.0000	361672	..
5	0.7603	5320784	OutputPage->output( )	.../MediaWiki.php:858
6	0.7622	5376384	SkinTemplate->outputPage( )	.../OutputPage.php:2366
7	0.7677	5383832	SkinTemplate->prepareQuickTemplate( )	.../SkinTemplate.php:249
8	0.9244	6202000	OutputPage->headElement( )	.../SkinTemplate.php:486
9	0.9376	6222648	Action::getActionName( )	.../OutputPage.php:2876
10	0.9376	6222648	Action::factory( )	.../Action.php:154
11	0.9376	6222648	WikiPage->getActionOverrides( )	.../Action.php:96
12	0.9377	6222648	WikiPage->getContentHandler( )	.../WikiPage.php:212
13	0.9377	6222648	WikiPage->getContentModel( )	.../WikiPage.php:225
14	0.9378	6223032	WANObjectCache->getWithSetCallback( )	.../WikiPage.php:516
16	0.9383	6223600	..
21	0.9387	6225384	cas ( )	.../MemcachedBagOStuff.php:70

This one isn't from ResourceLoaderWikiModule::preloadTitleInfo(), so perhaps this isn't related to that particular query? Either way, untagging from ResourceLoader because there is nothing special about the memcached query in preloadTitleInfo() compared to anywhere else. It seems that something is causing memcached to be slow in general for you.

Either each memcached query takes long and so when the timeout is reached it's most likely somewhere in Memcached. Alternatively, maybe it's usually fast but every once in a while something causes it to lock up and then that random query is slow.

See also T150289: Fatal error: Maximum execution time of 30 seconds exceeded in MemcachedBagOStuff.php on line 70

Krinkle renamed this task from Maximum execution time exceeded via ResourceLoaderWikiModule::preloadTitleInfo( ) into Memcached to Maximum execution time exceeded from Memcached (on page views).Apr 7 2017, 10:55 PM
Reedy added a comment.Jun 6 2018, 12:27 AM

Seems to have been fixed by T196125: php-memcached 3.0 (PHP 7) incompatible with BagOStuff, merging into that as appropriate