ResourceLoader DepStore lock acquired twice?
Closed, ResolvedPublic
Actions

Assigned To

Authored By

	Krinkle
	May 16 2020, 7:56 PM

Description

In Logstash (Perf Team dashboard) most the messages are from failed attempts to acquire a Memcached lock (presumably due to TKOs and link saturation etc.)

It's not very frequent, but whenever it happens, it logs the following twice for the same reqId/url:

reqId: XsA-pQpAEJkAAn5JFC8AAABM

2020-05-16T19:31:49 ERROR memcached mw1395
Memcached error for key "rl-deps:skins.minerva.base.styles|minerva|ne:lock" on server "127.0.0.1:11213": A TIMEOUT OCCURRED

2020-05-16T19:31:50 ERROR memcached mw1395
Memcached error for key "rl-deps:skins.minerva.base.styles|minerva|ne:lock" on server "127.0.0.1:11213": A TIMEOUT OCCURRED

This suggests it's attempting the lock twice, which seems contrary to what the code says. A bug perhaps?

Details

	Subject	Repo	Branch	Lines +/-
	objectcache: set error status codes in MemcachedPhpBagOStuff	mediawiki/core	master	+122 -12
	objectcache: improve error status codes in MemcachedPeclBagOStuff	mediawiki/core	master	+19 -4

Customize query in gerrit

Related Objects
Search...

Status	Subtype	Assigned	Task
Resolved		aaron	T252951 ResourceLoader DepStore lock acquired twice?
Resolved		Krinkle	T113916 Switch ResourceLoader file dependency tracking to MultiDC-friendly backend
Resolved		aaron	T247028 Database 'INSERT' query rate doubled (module_deps regression?)
Resolved		tstarling	T253433 Web installer CSS fails with ServiceDisabledException
Declined		aaron	T253697 Support hash-based deduplication in KeyValueDependencyStore
Resolved		aaron	T212129 Move MainStash out of Redis to a simpler multi-dc aware solution
Resolved		Eevans	T222851 Improve Echo seentime code for multi-DC access
Resolved		aaron	T229062 Look into a simple way to have global keys with db-replicated
Resolved		Krinkle	T254634 Determine and implement multi-dc strategy for ChronologyProtector
			Unknown Object (Task)
Resolved		Papaul	T267041 (Need By: 2020-11-29) rack/setup/install db214[234]
Resolved		• Marostegui	T269324 Productionize x2 databases
Resolved		aaron	T274174 Add modtoken field and flags to objectcache table
Resolved		Krinkle	T288998 Significant ParserCache space increase after 2021-08-12 (1.37.0-wmf.18 regression)
Resolved		tstarling	T306118 Notify DBA prior to sending db traffic to x2
Resolved		tstarling	T315271 db1151, db2144 X2 masters error: Could not execute Delete_rows_v1 event on table mainstash.objectstash
Resolved	PRODUCTION ERROR	jcrespo	T315274 Wikimedia\Rdbms\DBTransactionError: Explicit transaction still active; a caller might have failed to call endAtomic() or cancelAtomic().
Resolved		tstarling	T315427 Create a puppet role for x2 hosts
Resolved		• Marostegui	T315853 reclone x2 codfw hosts
Resolved		tstarling	T315995 Document how to disable x2 per DC

Event Timeline

Krinkle created this task.May 16 2020, 7:56 PM

Restricted Application added a subscriber: Masumrezarock100. · View Herald TranscriptMay 16 2020, 7:56 PM

• Gilles added a project: EngProd-Virtual-Hackathon.May 20 2020, 4:14 PM

• Gilles moved this task from Inbox, needs triage to Backlog: Maintenance, non-prioritized on the Performance-Team board.

Krinkle triaged this task as Medium priority.Jun 15 2020, 11:27 PM

Krinkle moved this task from Inbox to Confirmed Problem on the MediaWiki-ResourceLoader board.

Searching for << +channel:memcached +message:/.*deps.*/ >> I still see this sometimes.

I see plenty of timeouts where the error is not logged twice. Those that happen twice seem to be about 200 ms apart.

Do we know from the code why the same load.php web request process would be entering that path twice?

Krinkle lowered the priority of this task from Medium to Low.Dec 22 2020, 9:29 PM

Krinkle removed a parent task: T113916: Switch ResourceLoader file dependency tracking to MultiDC-friendly backend.

Krinkle removed a project: EngProd-Virtual-Hackathon.

To be re-evaluated after T113916. Either way, it's a fairly mild inefficienty at worst, so not a high priority either way.

Krinkle removed aaron as the assignee of this task.Sep 24 2021, 9:45 PM

Krinkle removed a project: MediaWiki-ResourceLoader.

Krinkle added a subscriber: aaron.

Aklapper added a subtask: T113916: Switch ResourceLoader file dependency tracking to MultiDC-friendly backend.Sep 28 2021, 4:11 PM

Change 724528 had a related patch set uploaded (by Aaron Schulz; author: Aaron Schulz):

[mediawiki/core@master] objectcache: improve error status codes in MemcachedPeclBagOStuff

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

gerritbot added a project: Patch-For-Review.Sep 28 2021, 11:10 PM

Change 724541 had a related patch set uploaded (by Aaron Schulz; author: Aaron Schulz):

[mediawiki/core@master] objectcache: set error status codes in MemcachedPhpBagOStuff

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

Logstash query:

channel:memcached AND message:*lock* AND url:*load.php*

https://logstash.wikimedia.org/goto/3c49860f3ebaead845660bf7593ff432

I do see a handful of entries with "Memcached error for key "...:rl-deps:...:lock" on server 127.0.0.1:11213: A TIMEOUT OCCURRED". But, I do not see any entries where the same lock is tried (and failed) twice in a row, or otherwise more than one entry from the same reqId.