Message-ID: <b5f39987-edba-4b40-9b88-56760a4267db@gmail.com>
Date: Tue, 13 Jun 2023 11:00:41 +0300
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:102.0)
 Gecko/20100101 Thunderbird/102.11.2
Subject: Re: BUG #17949: Adding an index introduces serialisation anomalies.
Content-Language: en-US
To: Thomas Munro <thomas.munro@gmail.com>, pgsql-bugs@lists.postgresql.org
References: <17949-a0f17035294a55e2@postgresql.org>
 <CA+hUKGLgtMZbzm5md-eKtoKQo7tZU+FVM95YPTfH9k+3UQcvSQ@mail.gmail.com>
From: Artem Anisimov <artem.anisimov.255@gmail.com>
In-Reply-To: 
 <CA+hUKGLgtMZbzm5md-eKtoKQo7tZU+FVM95YPTfH9k+3UQcvSQ@mail.gmail.com>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit
Archived-At: 
 <https://www.postgresql.org/message-id/b5f39987-edba-4b40-9b88-56760a4267db%40gmail.com>
Precedence: bulk

Hi Thomas,


thank you for the confirmation and analysis. Did you have a chance to 
take a more detailed look at the problem?


Best regards,

Artem.


On 30/05/2023 04:29, Thomas Munro wrote:
> Hi,
>
> Reproduced here.  Thanks for the reproducer.  I agree that something
> is wrong here, but I haven't had time to figure out what, yet, but let
> me share what I noticed so far... I modified your test to add a pid
> column to the locks table and to insert insert pg_backend_pid() into
> it, and got:
>
> postgres=# select xmin, * from locks;
>
> ┌───────┬──────┬───────┐
> │ xmin  │ path │  pid  │
> ├───────┼──────┼───────┤
> │ 17634 │ xyz  │ 32932 │
> │ 17639 │ xyz  │ 32957 │
> └───────┴──────┴───────┘
>
> Then I filtered the logs (having turned the logging up to capture all
> queries) so I could see just those PIDs and saw this sequence:
>
> 2023-05-29 00:15:43.933 EDT [32932] LOG:  duration: 0.182 ms
> statement: BEGIN TRANSACTION ISOLATION LEVEL SERIALIZABLE
> 2023-05-29 00:15:43.934 EDT [32957] LOG:  duration: 0.276 ms
> statement: BEGIN TRANSACTION ISOLATION LEVEL SERIALIZABLE
> 2023-05-29 00:15:43.935 EDT [32932] LOG:  duration: 1.563 ms
> statement: SELECT * FROM locks WHERE path = 'xyz'
> 2023-05-29 00:15:43.936 EDT [32932] LOG:  duration: 0.126 ms
> statement: INSERT INTO locks(path, pid) VALUES('xyz',
> pg_backend_pid())
> 2023-05-29 00:15:43.937 EDT [32957] LOG:  duration: 2.191 ms
> statement: SELECT * FROM locks WHERE path = 'xyz'
> 2023-05-29 00:15:43.937 EDT [32957] LOG:  duration: 0.261 ms
> statement: INSERT INTO locks(path, pid) VALUES('xyz',
> pg_backend_pid())
> 2023-05-29 00:15:43.937 EDT [32932] LOG:  duration: 0.222 ms  statement: COMMIT
> 2023-05-29 00:15:43.939 EDT [32957] LOG:  duration: 1.775 ms  statement: COMMIT
>
> That sequence if run (without overlap) in the logged order is normally
> rejected.  The query plan being used (at least when I run the query
> myself) looks like this:
>
> Query Text: SELECT * FROM locks WHERE path = 'xyz'
> Bitmap Heap Scan on locks  (cost=4.20..13.67 rows=6 width=36)
>    Recheck Cond: (path = 'xyz'::text)
>    ->  Bitmap Index Scan on locks_path_idx  (cost=0.00..4.20 rows=6 width=0)
>          Index Cond: (path = 'xyz'::text)