Page MenuHomePhabricator

SqlBagOStuff breaks PostgreSQL transactions
Closed, ResolvedPublic

Description

Got a few "WARNING: there is already a transaction in progress" which shows that a BEGIN was given without ending the previous transaction. Excerpt from the logs:

2011-02-09 13:07:13 EST LOG: statement: BEGIN
2011-02-09 13:07:13 EST LOG: statement: SELECT /* User::idFromName */ user_id FROM mwuser WHERE user_name = 'Graham87' LIMIT 1
2011-02-09 13:07:13 EST LOG: statement: SELECT /* LinkCache::addLinkObj */ page_id,page_len,page_is_redirect,page_latest FROM page WHERE page_namespace = '0' AND page_title = 'Analysis_of_var
iance/Degrees_of_freedom' LIMIT 1
2011-02-09 13:07:13 EST LOG: statement: SELECT /* */ nextval('page_page_id_seq')
2011-02-09 13:07:13 EST LOG: statement: SAVEPOINT mw
2011-02-09 13:07:13 EST LOG: statement: INSERT /* Article::insertOn */ INTO page (page_id,page_namespace,page_title,page_counter,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES ('438','0','Analysis_of_variance/Degrees_of_freedom','0','','0','1','0.708513577845','2011-02-09 18:07:13 GMT','0','0')
2011-02-09 13:07:13 EST LOG: statement: BEGIN
2011-02-09 13:07:13 EST WARNING: there is already a transaction in progress
2011-02-09 13:07:13 EST LOG: statement: DELETE /* SqlBagOStuff::set 127.0.0.1 */ FROM objectcache WHERE (keyname='my_wiki:pcache:idhash:438-0!*!0!!*!*!*')


Version: 1.21.x
Severity: normal

Details

Reference
bz27283

Related Objects

View Standalone Graph
This task is connected to more than 200 other tasks. Only direct parents and subtasks are shown here. Use View Standalone Graph to show more of the graph.
StatusSubtypeAssignedTask
InvalidNone
ResolvedNone

Event Timeline

bzimport raised the priority of this task from to Medium.Nov 21 2014, 11:21 PM
bzimport set Reference to bz27283.
bzimport added a subscriber: Unknown Object (MLST).

I don't think they nest in MySQL either, so this likely exposes general bugs.

This should be easy enough to trap in the begin() method, no? I saw *tons* of these in 1.15, but it's gotten much better in 1.16 and on.

This problem probably led to bug #32351

This probably happens every time we do MySQL's "REPLACE" or "INSERT IGNORE".
We fake them using an extra savepoint; unfortunately there are problems with proper rollback.

Can you check if r113534 fixes this (it's actually a whole series starting with r113408, sorry for the mess).

Please enable

$wgDebugDBTransactions = true;

to see transaction state transitions.

Created attachment 10262
section of log with errors and such

I'm still getting a number of errors in the pg log when I have

log_min_error_statement = error
log_min_duration_statement = 0
log_error_verbosity = verbose

in my postgresql.conf

attachment tmp.log ignored as obsolete

Created attachment 10263
section of log with errors and such

Better section of the logs

Attached:

Setting

$wgMainCacheType    = CACHE_MEMCACHED;

keeps SqlBagOStuff from being used which is where a lot of the messages come from.

Created attachment 10271
importdump fix

Another place that causes problems is "INSERT IGNORE" handling for Pg. In importDump.php, this happens with category count updates. The attached patch fixes this, but probably in a not very good way.

Attached:

Yeah, if we are not in a transaction, this is a race condition.

Are you using trunk? Are you getting

Transaction state changed from

in the debug log?

Which dump are trying to load?

(In reply to comment #11)

Yeah, if we are not in a transaction, this is a race condition.

Exactly. :)

Are you using trunk?

Yes.

Are you getting

Transaction state changed from

in the debug log?

Let me enable the debug log and re-try.

Which dump are trying to load?

I was using zhwiki which was fun, but made testing a little to difficult. I've been using simplewiki since.

Created attachment 10274
start of debug log with messed up transaction

Another problems happens once right at the beginning of every import:

BEGIN

SELECT -- LCStore_DB::get
  • BEGIN -- fails DELETE -- LCStore_DB::startWrite INSERT -- LCStore_DB::set

...

(In reply to comment #11)

Are you getting

Transaction state changed from

in the debug log?

Attaching the bit of the log that covers this section above.

Attached:

And, as suspected, setting

$wgCacheDirectory = "$IP/cache";

got rid of the problem with found in comment #13 -- which is still a real problem, of course.

Some relevant discussions from wikitech-l:

http://thread.gmane.org/gmane.science.linguistics.wikipedia.technical/49500

http://thread.gmane.org/gmane.science.linguistics.wikipedia.technical/39827

we cannot (possibly) have a single transaction for a whole web request, which would be the best solution, or can we?

Split comment #13 off to Bug #35357

Should be fixed by gerrit change 3962

Has this really been fixed or was it broken again in the meantime? I (still) see a lot of those warnings (cf. https://travis-ci.org/scfc/mediawiki/jobs/2904641):

PHP Notice: DatabaseBase::rollback: No transaction to rollback, something got out of sync! [Called from DatabaseBase::rollback in /home/travis/builds/scfc/mediawiki/includes/db/Database.php at line 3030] in /home/travis/builds/scfc/mediawiki/includes/debug/Debug.php on line 283

I remember some discussion about warnings on MySQL, but I don't know if and how they are related.

I am seeing such errors when running various unit tests:

DatabaseBase::rollback: No transaction to rollback, something got out of sync! [Called from DatabaseBase::rollback in /var/www/common/mw-pg/includes/db/Database.php at line 3088]

/var/www/common/mw-pg/includes/debug/Debug.php:283
/var/www/common/mw-pg/includes/debug/Debug.php:144
/var/www/common/mw-pg/includes/GlobalFunctions.php:1103
/var/www/common/mw-pg/includes/db/Database.php:3088
/var/www/common/mw-pg/includes/db/DatabasePostgres.php:234
/var/www/common/mw-pg/includes/Block.php:475
/var/www/common/mw-pg/includes/Block.php:475
/var/www/common/mw-pg/tests/phpunit/includes/BlockTest.php:214
/var/www/common/mw-pg/tests/phpunit/MediaWikiTestCase.php:116
/var/www/common/mw-pg/tests/phpunit/MediaWikiPHPUnitCommand.php:60
/var/www/common/mw-pg/tests/phpunit/MediaWikiPHPUnitCommand.php:46
/var/www/common/mw-pg/tests/phpunit/phpunit.php:107

not so sure this is fixed, or it's broken again :( reopening....

No transaction to rollback, something got out of sync!
[Called from DatabaseBase::rollback in
/var/www/common/mw-pg/includes/db/Database.php

is actually a cover-up of some other database error. This is caused by bug 58095.

Closing this case which was specific to SqlBagOfStuff.

Jdforrester-WMF subscribed.

Migrating from the old tracking task to a tag for PostgreSQL-related tasks.