Received: from maia.hub.org (maia-5.hub.org [200.46.204.29]) by mail.postgresql.org (Postfix) with ESMTP id D4F661337B96 for ; Mon, 14 Feb 2011 01:09:34 -0400 (AST) Received: from mail.postgresql.org ([200.46.204.86]) by maia.hub.org (mx1.hub.org [200.46.204.29]) (amavisd-maia, port 10024) with ESMTP id 49034-05-2 for ; Mon, 14 Feb 2011 05:09:26 +0000 (UTC) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from mail.netbsd.org (mail.netbsd.org [204.152.190.11]) by mail.postgresql.org (Postfix) with ESMTP id AF7571337BB4 for ; Mon, 14 Feb 2011 01:09:25 -0400 (AST) Received: by mail.netbsd.org (Postfix, from userid 1270) id 2E5E119CE7A; Mon, 14 Feb 2011 05:09:24 +0000 (UTC) To: Kevin.Grittner@wicourts.gov Cc: pgsql-hackers@postgresql.org Subject: Re: SSI bug? In-Reply-To: Your message of "Sat, 12 Feb 2011 11:07:52 -0600" <4D566A08020000250003A90B@gw.wicourts.gov> References: <4D566A08020000250003A90B@gw.wicourts.gov> X-Mailer: Cue version 0.8 (100217-1432/takashi) Mime-Version: 1.0 Content-Type: Text/Plain; charset=us-ascii Message-Id: <20110214050924.2E5E119CE7A@mail.netbsd.org> Date: Mon, 14 Feb 2011 05:09:23 +0000 (UTC) From: yamt@mwd.biglobe.ne.jp (YAMAMOTO Takashi) X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-4.2 tagged_above=-5 required=5 tests=BAYES_00=-1.9, RCVD_IN_DNSWL_MED=-2.3 X-Spam-Level: X-Archive-Number: 201102/1231 X-Sequence-Number: 182020 hi, all of the following answers are with the patch you provided in other mail applied. > YAMAMOTO Takashi wrote: > >> i have seen this actually happen. i've confirmed the creation of >> the loop with the attached patch. it's easily reproducable with >> my application. i can provide the full source code of my >> application if you want. (but it isn't easy to run unless you are >> familiar with the recent version of NetBSD) >> i haven't found a smaller reproducible test case yet. > > I've never used NetBSD, so maybe a few details will help point me in > the right direction faster than the source code. > > Has your application ever triggered any of the assertions in the > code? (In particular, it would be interesting if it ever hit the > one right above where you patched.) the assertion right above is sometimes triggered. sometimes not. > > How long was the loop? see below. > Did you notice whether the loop involved multiple tuples within a > single page? if i understand correctly, yes. the following is a snippet of my debug code (dump targets when triggerCheckTargetForConflictsIn loops >1000 times) and its output. the same locktag_field3 value means the same page, right? + for (t = target, i = 0; t != NULL; i++) { + elog(WARNING, "[%u] target %p tag %" PRIx32 ":%" PRIx32 ":%" PRIx32 + ":%" PRIx16 ":%" PRIx16 " prior %p next %p", i, t, + t->tag.locktag_field1, + t->tag.locktag_field2, + t->tag.locktag_field3, + t->tag.locktag_field4, + t->tag.locktag_field5, + t->priorVersionOfRow, + t->nextVersionOfRow); + t = t->priorVersionOfRow; + if (t == target) { + elog(WARNING, "found a loop"); + break; + } + } WARNING: [0] target 0xbb51f238 tag 4000:4017:53b:6c:0 prior 0xbb51f350 next 0xbb51f350 WARNING: [1] target 0xbb51f350 tag 4000:4017:53b:69:0 prior 0xbb51f238 next 0xbb51f238 WARNING: found a loop another sample: WARNING: [0] target 0xbb51f530 tag 4000:4017:565:ae:0 prior 0xbb51f1e8 next 0xbb51f300 WARNING: [1] target 0xbb51f1e8 tag 4000:4017:565:ad:0 prior 0xbb51f580 next 0xbb51f530 WARNING: [2] target 0xbb51f580 tag 4000:4017:565:ac:0 prior 0xbb51f300 next 0xbb51f1e8 WARNING: [3] target 0xbb51f300 tag 4000:4017:565:ab:0 prior 0xbb51f530 next 0xbb51f580 WARNING: found a loop the table seems mostly hot-updated, if it matters. hoge=# select * from pg_stat_user_tables where relid=16407; -[ RECORD 1 ]-----+-------------------- relid | 16407 schemaname | pgfs relname | file seq_scan | 0 seq_tup_read | 0 idx_scan | 53681 idx_tup_fetch | 52253 n_tup_ins | 569 n_tup_upd | 12054 n_tup_del | 476 n_tup_hot_upd | 12041 n_live_tup | 93 n_dead_tup | 559 last_vacuum | last_autovacuum | last_analyze | last_autoanalyze | vacuum_count | 0 autovacuum_count | 0 analyze_count | 4922528128875102208 autoanalyze_count | 7598807461784802080 (values in the last two columns seems bogus. i don't know if it's related or not.) > Did this coincide with an autovacuum of the table? no. (assuming that autovacuum=off in postgresql.conf is enough to exclude the possibility.) > > These last two are of interest because it seems likely that such a > cycle might be related to this new code not properly allowing for > some aspect of tuple cleanup. > > Thanks for finding this and reporting it, and thanks in advance for > any further detail you can provide. thanks for looking. YAMAMOTO Takashi > > -Kevin > > -- > Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-hackers