[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Stashbot added a comment. Mentioned in SAL (#wikimedia-operations) [2020-05-04T15:45:54Z] Synchronized php-1.35.0-wmf.30/includes/libs/rdbms/database/DatabaseMysqlBase.php: T251457 rdbms: don't treat lock() as a write operation (duration: 01m 04s

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

gerritbot added a comment. Change 593765 **merged** by jenkins-bot: [mediawiki/core@wmf/1.35.0-wmf.30] rdbms: don't treat lock() as a write operation https://gerrit.wikimedia.org/r/593765 TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERENCES https://phabricator.w

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

daniel added a comment. In T251457#6105089 , @Jdforrester-WMF wrote: > UBN patches, and particularly train-blocking UBN patches, should not wait for SWAT, but be deployed immediately (in line with https://wikitech.wikimedia.org/wiki/Dep

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Jdforrester-WMF added a comment. UBN patches, and particularly train-blocking UBN patches, should not wait for SWAT, but be deployed immediately (in line with https://wikitech.wikimedia.org/wiki/Deployments/Emergencies). TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFEREN

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

LarsWirzenius added a comment. Thanks! TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: LarsWirzenius Cc: Ladsgroup, Nikerabbit, Tgr, Agusbou2015, Pchelolo, daniel, DannyS712, Jdforrester-WMF,

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

daniel added a comment. In T251457#6104041 , @LarsWirzenius wrote: > https://gerrit.wikimedia.org/r/593757 has been merged, but has it been deployed (I assume it will need to be backported to the 1.35.0-wmf.30 branch as well)? Train it

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

LarsWirzenius added a comment. https://gerrit.wikimedia.org/r/593757 has been merged, but has it been deployed (I assume it will need to be backported to the 1.35.0-wmf.30 branch as well)? Train it held until it has been. TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERE

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

gerritbot added a comment. Change 593757 **merged** by jenkins-bot: [mediawiki/core@master] rdbms: don't treat lock() as a write operation https://gerrit.wikimedia.org/r/593757 TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERENCES https://phabricator.wikimedia.org

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

gerritbot added a comment. Change 593765 had a related patch set uploaded (by Krinkle; owner: Daniel Kinzler): [mediawiki/core@wmf/1.35.0-wmf.30] rdbms: don't treat lock() as a write operation https://gerrit.wikimedia.org/r/593765 TASK DETAIL https://phabricator.wikimedia.org/T25145

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

daniel added a comment. While I was chatting with @Krinkle on IRC, he found out that https://gerrit.wikimedia.org/r/c/mediawiki/core/+/582022 caused Database::lock() to be treated as a write operation now. This was not the case before, and indeed should not be the case. This means the error

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

gerritbot added a comment. Change 593757 had a related patch set uploaded (by Daniel Kinzler; owner: Daniel Kinzler): [mediawiki/core@master] Database: don't count lock() as a write operation https://gerrit.wikimedia.org/r/593757 TASK DETAIL https://phabricator.wikimedia.org/T251457

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

daniel added a comment. In T251457#6099971 , @Tgr wrote: > MediaWiki automatically wraps the entire request in a transaction if it encounters a write which does not do its own transaction handling. So something unrelated to saving could

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Tgr added a comment. MediaWiki automatically wraps the entire request in a transaction if it encounters a write which does not do its own transaction handling. So something unrelated to saving could have started the transaction, like AbuseFilter taking an action, or a session refresh (althou

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

daniel added a comment. > I'm not entirely sure I understand it correctly, but PageEditStash::getAndWaitForStashValue uses ILoadBalancer::getAnyOpenConnection and by chance acquires a connection where a transaction was already open for edit? Yes. the question is, why is there a transact

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Pchelolo added a comment. Complete stack trace: Expectation (writeQueryTime <= 1) by MediaWiki::main not met (actual: 3.366758108139): query-m: SELECT GET_LOCK('X', N) AS lockstatus [TRX#7ad8fc] #0 /srv/mediawiki/php-1.35.0-wmf.30/includes/libs/rdbms/TransactionProfiler.php(255

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

daniel added a comment. @Pchelolo can you provide the rest of the stack trace? This is triggered via SpamBlacklistHooks, and I want to understand why that is being executed inside the DB transaction. TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERENCES https://phabric

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

daniel added a comment. In T251457#6098793 , @Krinkle wrote: > @daniel How did it work before? What needed to change? What actually changed? I'm not aware of any changes in that area. TASK DETAIL https://phabricator.wikimedia.org

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Krinkle added a comment. @daniel How did it work before? What needed to change? What actually changed? TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: Krinkle Cc: Agusbou2015, Pchelolo, daniel,

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

daniel added a comment. So, PageEditStash::parseAndCache() parses the page while holding the lock. PageEditStash->getAndWaitForStashValue() waits for that lock, and it apparently does so within the DB transaction that will be used to write the new revision. If parsing takes long, the process

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

daniel added a comment. In T251457#6098675 , @Pchelolo wrote: > It's PageEditStash. See my comment above. Saw it and already edited my comment ;) TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERENCES https://p

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Pchelolo added a comment. It's PageEditStash. See my comment above. TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: Pchelolo Cc: Agusbou2015, Pchelolo, daniel, DannyS712, Jdforrester-WMF, Krink

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

daniel added a comment. In T251457#6098402 , @Pchelolo wrote: > @daniel I don't think this is that lock showing up here. Reading the code, it seems like if that lock was taken, we should've seen a bunch more queries in this transaction,

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Pchelolo added a comment. The other associated log actually gives more insight on which lock is making the transaction timeout: Expectation (writeQueryTime <= 1) by MediaWiki::main not met (actual: 3.366758108139): query-m: SELECT GET_LOCK('X', N) AS lockstatus [TRX#7ad8fc] #0

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Marostegui added a comment. Quick answer from my side: no master switch has been done in the last few months on any of our s1-s8, x1 sections TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: Ma

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Pchelolo added a comment. @daniel I don't think this is that lock showing up here. Reading the code, it seems like if that lock was taken, we should've seen a bunch more queries in this transaction, like some deletes, read from the archive table etc. TASK DETAIL https://phabricator.wikimed

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Pchelolo added a comment. Looking at the requestId of one of these errors, the following log messages are found: https://logstash.wikimedia.org/goto/3e387a16e01ae0f02e72b413d6691539 The interesting one there is: Sub-optimal transaction on DB(s) [10.64.16.34 (frwiki) (TRX#7ad8fc)]:

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

gerritbot added a comment. Change 593578 **merged** by jenkins-bot: [operations/mediawiki-config@master] Group0 only to 1.35.0-wmf.30 https://gerrit.wikimedia.org/r/593578 TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERENCES https://phabricator.wikimedia.org/sett

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

gerritbot added a comment. Change 593578 had a related patch set uploaded (by Brennen Bearnes; owner: Brennen Bearnes): [operations/mediawiki-config@master] Group0 only to 1.35.0-wmf.30 https://gerrit.wikimedia.org/r/593578 TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

DannyS712 added a comment. In T251457#6097943 , @daniel wrote: > Pinging patch author @DannyS712 Which patch is believed to have caused this? TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERENCES https://phabr

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Krinkle added a comment. Definitely a new problem, and it is causing about 200 user actions per hour to be aborted/prevented (presumably edits, but may be other stuff as well). F31788692: Screenshot 2020-04-30 at 18.22.38.png TASK DETAIL h

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Hogue added a comment. It was a not so long text I wanted to add maybe two secentences with 20 words and 200 characters. TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: Hogue Cc: Marostegui, L

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Marostegui added a comment. This is preventing writes from happening with that particular action,so it must indeed be fixed or whatever caused that increase on time, reverted I would say. TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERENCES https://phabricator.wikimed

[Wikidata-bugs] [Maniphest] [Commented On] T251457: LoadBalancer: Transaction spent [n] second(s) in writes, exceeding the limit of [n]

Marostegui added a comment. It is just a big transaction that takes more than the limit we have for writes, which is 3 seconds. Nothing we can do from the DB infra. TASK DETAIL https://phabricator.wikimedia.org/T251457 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/