Topic on Project:Support desk

Problem with Slow Saving

4
24.72.93.26 (talkcontribs)

To start off I am using:

MediaWiki 1.26.4 PHP 5.6.28 (apache2handler) MySQL 5.7.16

I do not understand why this is slowly saving... When I am debugging, I am refreshing the debug.log and it gets stuck on:

LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
[runJobs] Failed to start cron API (socket error 0): php_network_getaddresses: getaddrinfo failed: Temporary failure in name resolution
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
[runJobs] recentChangesUpdate Special:RecentChanges type=cacheUpdate (id=2,timestamp=20170327235552) STARTING
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
[runJobs] recentChangesUpdate Special:RecentChanges type=cacheUpdate (id=2,timestamp=20170327235552) t=6 good

What can I do to speed this up? I do not understand the "LoadBalancer::reuseConnection: this connection was not opened as a foreign connection". It takes about 30-40 seconds to save a page, but it takes around 2 seconds to load a page.

Does anyone have a fix?

Debug.log:

Start request POST /kb/index.php?title=IT:Test&action=submit
HTTP HEADERS:
HOST: kb.website.ca
CONNECTION: keep-alive
CONTENT-LENGTH: 2090
CACHE-CONTROL: max-age=0
ORIGIN: https://kb.website.ca
UPGRADE-INSECURE-REQUESTS: 1
USER-AGENT: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36
CONTENT-TYPE: multipart/form-data; boundary=----WebKitFormBoundaryTeFQhxdA7oriJst8
ACCEPT: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
REFERER: https://kb.website.ca/kb/index.php?title=IT:Test&action=edit
ACCEPT-ENCODING: gzip, deflate, br
ACCEPT-LANGUAGE: en-US,en;q=0.8
COOKIE: _ga=GA1.2.1383329811.1481045531; WikiMediapreview-limit-report=collapsed; __gads=ID=e231b6c91ee05378:T=1489694865:S=ALNI_Ma2zvrKr5qBTB5oNIG8BsakeWRNOQ; __zlcmid=e3g4OPVmM3M0F2; intercom-session-b4hlb1c7=R1doa1UzSWkrY09mTUhrcWJqS255MmFBSUh1dzlYVkg5SXNEU2ZOZndUVlVSMXNMMElGZHJUVUtqRVdLOEJYcy0tKzhNWWhkSDJQVXJxR0Mzbmp5QzNuUT09--be45c72cb29adfadf3a9699a5b2615ee286e0541; WikiMediaLoggedOut=1490638085; WikiMediaUserID=2; WikiMediaUserName=john.jacob; WikiMedia_session=dpammj8rjl693ai2smlt4692c0
[caches] main: EmptyBagOStuff, message: SqlBagOStuff, parser: SqlBagOStuff
[caches] LocalisationCache: using store LCStoreDB
Unstubbing $wgParser on call of $wgParser::setFunctionHook from haclfSetupExtension
Parser: using preprocessor: Preprocessor_DOM
Fully initialised
Connected to database 0 at 127.0.0.1
Title::getRestrictionTypes: applicable restrictions to 
[[IT:Test]]
are {edit,move}
[ContentHandler] Created handler for wikitext: WikitextContentHandler
User: cache miss for user 2
User: loading options for user 2 from database.
User: logged in from session
EditPage::edit: enter
Connected to database 0 at 127.0.0.1
DatabaseBase::query: Writes done: REPLACE INTO `objectcache` (keyname,value,exptime) VALUES ('X')
[MessageCache] MessageCache::load: Loading en... local cache is empty, global cache is expired/volatile, loading from database
EditPage::importFormData: Passed token check.
User: loading options for user 2 from override cache.
User::getBlockedStatus: checking...
IP: 10.26.16.132
timestamp: 20170327235414, edittime: 20170327235414
EditPage::internalAttemptSave: getting section 
[StashEdit] No cache value for key 'WikiMedia:prepared-edit:a723bc5a962a959b6ae6d6368b29f628:c08a48cf9a10dc63de12de5c446fe6706469c025'.
Unstubbing $wgLang on call of $wgLang::_unstub from ParserOptions::__construct
DatabaseBase::query: Writes done: INSERT INTO `text` (old_id,old_text,old_flags) VALUES (NULL,'X')
WikiPage::doEditUpdates: No vary-revision, using prepared edit...
Saved in parser cache with key WikiMedia:pcache:idhash:20-01!*!*!*!*!*!* and timestamp 20170327235552 and revision id 613
[cookie] setcookie: "WikiMediaPostEditRevision613", "saved", "1490660152", "/", "", "1", ""
MediaWiki::doPreOutputCommit completed; all transactions committed
OutputPage::sendCacheControl: private caching;  **
BacklinkCache::queryLinks: got results from DB
Title::getRestrictionTypes: applicable restrictions to 
[[IT:Test]]
are {edit,move}
BacklinkCache::partition: got from full result cache
BacklinkCache::queryLinks: got results from DB
BacklinkCache::partition: got from full result cache
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
[runJobs] Failed to start cron API (socket error 0): php_network_getaddresses: getaddrinfo failed: Temporary failure in name resolution
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
[runJobs] recentChangesUpdate Special:RecentChanges type=cacheUpdate (id=2,timestamp=20170327235552) STARTING
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
[runJobs] recentChangesUpdate Special:RecentChanges type=cacheUpdate (id=2,timestamp=20170327235552) t=6 good
Request ended normally
Start request GET /kb/index.php/IT:Test
HTTP HEADERS:
HOST: kb.website.ca
CONNECTION: keep-alive
CACHE-CONTROL: max-age=0
UPGRADE-INSECURE-REQUESTS: 1
USER-AGENT: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36
ACCEPT: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
REFERER: https://kb.website.ca/kb/index.php?title=IT:Test&action=edit
ACCEPT-ENCODING: gzip, deflate, sdch, br
ACCEPT-LANGUAGE: en-US,en;q=0.8
COOKIE: _ga=GA1.2.1383329811.1481045531; WikiMediapreview-limit-report=collapsed; __gads=ID=e231b6c91ee05378:T=1489694865:S=ALNI_Ma2zvrKr5qBTB5oNIG8BsakeWRNOQ; __zlcmid=e3g4OPVmM3M0F2; intercom-session-b4hlb1c7=R1doa1UzSWkrY09mTUhrcWJqS255MmFBSUh1dzlYVkg5SXNEU2ZOZndUVlVSMXNMMElGZHJUVUtqRVdLOEJYcy0tKzhNWWhkSDJQVXJxR0Mzbmp5QzNuUT09--be45c72cb29adfadf3a9699a5b2615ee286e0541; WikiMediaLoggedOut=1490638085; WikiMediaUserID=2; WikiMediaUserName=john.jacob; WikiMedia_session=dpammj8rjl693ai2smlt4692c0; WikiMediaPostEditRevision613=saved
[caches] main: EmptyBagOStuff, message: SqlBagOStuff, parser: SqlBagOStuff
[caches] LocalisationCache: using store LCStoreDB
Unstubbing $wgParser on call of $wgParser::setFunctionHook from haclfSetupExtension
Parser: using preprocessor: Preprocessor_DOM
Fully initialised
Connected to database 0 at 127.0.0.1
Title::getRestrictionTypes: applicable restrictions to 
[[IT:Test]]
are {edit,move}
[ContentHandler] Created handler for wikitext: WikitextContentHandler
User: cache miss for user 2
User: loading options for user 2 from database.
User: logged in from session
User: loading options for user 2 from override cache.
Connected to database 0 at 127.0.0.1
[DBPerformance] [GET] Expectation (masterConns <= 0) by MediaWiki::main not met:
[connect to 127.0.0.1 (WikiMedia)]
TransactionProfiler.php line 307 calls wfBacktrace()
TransactionProfiler.php line 146 calls TransactionProfiler->reportExpectationViolated()
LoadBalancer.php line 545 calls TransactionProfiler->recordConnection()
SqlBagOStuff.php line 170 calls LoadBalancer->getConnection()
SqlBagOStuff.php line 246 calls SqlBagOStuff->getDB()
SqlBagOStuff.php line 224 calls SqlBagOStuff->getMulti()
MessageCache.php line 287 calls SqlBagOStuff->get()
MessageCache.php line 909 calls MessageCache->load()
MessageCache.php line 828 calls MessageCache->getMsgFromNamespace()
MessageCache.php line 766 calls MessageCache->getMessageFromFallbackChain()
Message.php line 1146 calls MessageCache->get()
Message.php line 769 calls Message->fetchMessage()
Message.php line 860 calls Message->toString()
OutputPage.php line 946 calls Message->text()
OutputPage.php line 994 calls OutputPage->setHTMLTitle()
Article.php line 514 calls OutputPage->setPageTitle()
ViewAction.php line 44 calls Article->view()
MediaWiki.php line 490 calls ViewAction->show()
MediaWiki.php line 287 calls MediaWiki->performAction()
MediaWiki.php line 714 calls MediaWiki->performRequest()
MediaWiki.php line 508 calls MediaWiki->main()
index.php line 41 calls MediaWiki->run()

DatabaseBase::query: Writes done: REPLACE INTO `objectcache` (keyname,value,exptime) VALUES ('X')
[DBPerformance] [GET] Expectation (writes <= 0) by MediaWiki::main not met:
query: REPLACE INTO `objectcache` (keyname,value,exptime) VALUES ('X')
TransactionProfiler.php line 307 calls wfBacktrace()
TransactionProfiler.php line 200 calls TransactionProfiler->reportExpectationViolated()
Database.php line 1035 calls TransactionProfiler->recordQueryCompletion()
Database.php line 2786 calls DatabaseBase->query()
DatabaseMysqlBase.php line 442 calls DatabaseBase->nativeReplace()
SqlBagOStuff.php line 344 calls DatabaseMysqlBase->replace()
SqlBagOStuff.php line 364 calls SqlBagOStuff->setMulti()
BagOStuff.php line 393 calls SqlBagOStuff->set()
BagOStuff.php line 250 calls BagOStuff->add()
BagOStuff.php line 317 calls BagOStuff->lock()
MessageCache.php line 690 calls BagOStuff->getScopedLock()
MessageCache.php line 386 calls MessageCache->getReentrantScopedLock()
MessageCache.php line 315 calls MessageCache->loadFromDBWithLock()
MessageCache.php line 909 calls MessageCache->load()
MessageCache.php line 828 calls MessageCache->getMsgFromNamespace()
MessageCache.php line 766 calls MessageCache->getMessageFromFallbackChain()
Message.php line 1146 calls MessageCache->get()
Message.php line 769 calls Message->fetchMessage()
Message.php line 860 calls Message->toString()
OutputPage.php line 946 calls Message->text()
OutputPage.php line 994 calls OutputPage->setHTMLTitle()
Article.php line 514 calls OutputPage->setPageTitle()
ViewAction.php line 44 calls Article->view()
MediaWiki.php line 490 calls ViewAction->show()
MediaWiki.php line 287 calls MediaWiki->performAction()
MediaWiki.php line 714 calls MediaWiki->performRequest()
MediaWiki.php line 508 calls MediaWiki->main()
index.php line 41 calls MediaWiki->run()

[MessageCache] MessageCache::load: Loading en... local cache is empty, global cache is expired/volatile, loading from database
Unstubbing $wgLang on call of $wgLang::_unstub from ParserOptions::__construct
OutputPage::checkLastModified: client did not send If-Modified-Since header
Article::view using parser cache: yes
Parser options key expired, touched 20170327235552, epoch 20170327235723, cached 20170327235552
Article::view: doing uncached parse
Parser cache options found.
Saved in parser cache with key WikiMedia:pcache:idhash:20-01!*!*!*!*!*!* and timestamp 20170327235632 and revision id 613
MediaWiki::doPreOutputCommit completed; all transactions committed
User::getBlockedStatus: checking...
Title::getRestrictionTypes: applicable restrictions to 
[[IT:Test]]
are {edit,move}
Title::getRestrictionTypes: applicable restrictions to 
[[IT:Test]]
are {edit,move}
Title::getRestrictionTypes: applicable restrictions to 
[[IT:Test]]
are {edit,move}
Parser: using preprocessor: Preprocessor_DOM
DatabaseBase::query: Writes done: REPLACE INTO `msg_resource` (mr_resource,mr_lang,mr_blob,mr_timestamp) VALUES ('X')
Title::getRestrictionTypes: applicable restrictions to [[MediaWiki:Breadcrumbs]] are {edit,move}
OutputPage::sendCacheControl: private caching; Mon, 27 Mar 2017 23:57:23 GMT **
LoadBalancer::reuseConnection: this connection was not opened as a foreign connection
Request ended normally
Seb35 (talkcontribs)

Not sure but some ideas to test:

  • php_network_getaddresses: getaddrinfo failed: Temporary failure in name resolution: this seems to indicate there are issues on domain resolution (DNS), possibly intermittent but should be checked
  • Google has some references to this issue
  • Topic:S9ifgvvg522ckfw1
  • phabricator:T97028

Possibly try to disable cache $wgMainCache = CACHE_NONE; in a first time (although it should be enabled in production).

Ciencia Al Poder (talkcontribs)

The problem is probably the Job queue. First it tries to open a connection to itself but it fails to resolve its own domain, then it fallbacks to the on-request job runner.

I'd first try setting $wgRunJobsAsync = false; It should definitively help to go to the fallback directly and not spend time trying to unsuccessfully resolve a DNS

If it doesn't really help, jobs may take long to complete, so try $wgJobRunRate = 0; and then you should run maintenance/runJobs.php periodically through a cron job.

AKlapper (WMF) (talkcontribs)
Reply to "Problem with Slow Saving"