postgresql/src/test/isolation/expected/insert-conflict-specconflic...

Ignoring revisions in .git-blame-ignore-revs. Click here to bypass and see the normal blame view.

554 lines
18 KiB
Plaintext
Raw Normal View History

Parsed test spec with 3 sessions
starting permutation: controller_locks controller_show s1_upsert s2_upsert controller_show controller_unlock_1_1 controller_unlock_2_1 controller_unlock_1_3 controller_unlock_2_3 controller_show controller_unlock_2_2 controller_show controller_unlock_1_2 controller_show
step controller_locks: SELECT pg_advisory_lock(sess, lock), sess, lock FROM generate_series(1, 2) a(sess), generate_series(1,3) b(lock);
pg_advisory_lock|sess|lock
----------------+----+----
| 1| 1
| 1| 2
| 1| 3
| 2| 1
| 2| 2
| 2| 3
(6 rows)
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 3
step s1_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s1') ON CONFLICT (blurt_and_lock_123(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s1'; <waiting ...>
s2: NOTICE: blurt_and_lock_123() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 3
step s2_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s2') ON CONFLICT (blurt_and_lock_123(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s2'; <waiting ...>
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step controller_unlock_1_1: SELECT pg_advisory_unlock(1, 1);
pg_advisory_unlock
------------------
t
(1 row)
step controller_unlock_2_1: SELECT pg_advisory_unlock(2, 1);
pg_advisory_unlock
------------------
t
(1 row)
step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
pg_advisory_unlock
------------------
t
(1 row)
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 2
step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
pg_advisory_unlock
------------------
t
(1 row)
s2: NOTICE: blurt_and_lock_123() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 2
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step controller_unlock_2_2: SELECT pg_advisory_unlock(2, 2);
pg_advisory_unlock
------------------
t
(1 row)
step s2_upsert: <... completed>
step controller_show: SELECT * FROM upserttest;
key|data
---+-----------
k1 |inserted s2
(1 row)
step controller_unlock_1_2: SELECT pg_advisory_unlock(1, 2);
pg_advisory_unlock
------------------
t
(1 row)
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 2
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 2
step s1_upsert: <... completed>
step controller_show: SELECT * FROM upserttest;
key|data
---+-----------------------------------
k1 |inserted s2 with conflict update s1
(1 row)
starting permutation: controller_locks controller_show s1_upsert s2_upsert controller_show controller_unlock_1_1 controller_unlock_2_1 controller_unlock_1_3 controller_unlock_2_3 controller_show controller_unlock_1_2 controller_show controller_unlock_2_2 controller_show
step controller_locks: SELECT pg_advisory_lock(sess, lock), sess, lock FROM generate_series(1, 2) a(sess), generate_series(1,3) b(lock);
pg_advisory_lock|sess|lock
----------------+----+----
| 1| 1
| 1| 2
| 1| 3
| 2| 1
| 2| 2
| 2| 3
(6 rows)
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 3
step s1_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s1') ON CONFLICT (blurt_and_lock_123(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s1'; <waiting ...>
s2: NOTICE: blurt_and_lock_123() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 3
step s2_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s2') ON CONFLICT (blurt_and_lock_123(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s2'; <waiting ...>
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step controller_unlock_1_1: SELECT pg_advisory_unlock(1, 1);
pg_advisory_unlock
------------------
t
(1 row)
step controller_unlock_2_1: SELECT pg_advisory_unlock(2, 1);
pg_advisory_unlock
------------------
t
(1 row)
step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
pg_advisory_unlock
------------------
t
(1 row)
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 2
step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
pg_advisory_unlock
------------------
t
(1 row)
s2: NOTICE: blurt_and_lock_123() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 2
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step controller_unlock_1_2: SELECT pg_advisory_unlock(1, 2);
pg_advisory_unlock
------------------
t
(1 row)
step s1_upsert: <... completed>
step controller_show: SELECT * FROM upserttest;
key|data
---+-----------
k1 |inserted s1
(1 row)
step controller_unlock_2_2: SELECT pg_advisory_unlock(2, 2);
pg_advisory_unlock
------------------
t
(1 row)
s2: NOTICE: blurt_and_lock_123() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 2
s2: NOTICE: blurt_and_lock_123() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 2
step s2_upsert: <... completed>
step controller_show: SELECT * FROM upserttest;
key|data
---+-----------------------------------
k1 |inserted s1 with conflict update s2
(1 row)
starting permutation: controller_locks controller_show s1_insert_toast s2_insert_toast controller_show controller_unlock_1_1 controller_unlock_2_1 controller_unlock_1_3 controller_unlock_2_3 controller_show controller_unlock_1_2 controller_show_count controller_unlock_2_2 controller_show_count
step controller_locks: SELECT pg_advisory_lock(sess, lock), sess, lock FROM generate_series(1, 2) a(sess), generate_series(1,3) b(lock);
pg_advisory_lock|sess|lock
----------------+----+----
| 1| 1
| 1| 2
| 1| 3
| 2| 1
| 2| 2
| 2| 3
(6 rows)
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
s1: NOTICE: blurt_and_lock_123() called for k2 in session 1
s1: NOTICE: acquiring advisory lock on 3
step s1_insert_toast: INSERT INTO upserttest VALUES('k2', ctoast_large_val()) ON CONFLICT DO NOTHING; <waiting ...>
s2: NOTICE: blurt_and_lock_123() called for k2 in session 2
s2: NOTICE: acquiring advisory lock on 3
step s2_insert_toast: INSERT INTO upserttest VALUES('k2', ctoast_large_val()) ON CONFLICT DO NOTHING; <waiting ...>
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step controller_unlock_1_1: SELECT pg_advisory_unlock(1, 1);
pg_advisory_unlock
------------------
t
(1 row)
step controller_unlock_2_1: SELECT pg_advisory_unlock(2, 1);
pg_advisory_unlock
------------------
t
(1 row)
step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
pg_advisory_unlock
------------------
t
(1 row)
s1: NOTICE: blurt_and_lock_123() called for k2 in session 1
s1: NOTICE: acquiring advisory lock on 2
step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
pg_advisory_unlock
------------------
t
(1 row)
s2: NOTICE: blurt_and_lock_123() called for k2 in session 2
s2: NOTICE: acquiring advisory lock on 2
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step controller_unlock_1_2: SELECT pg_advisory_unlock(1, 2);
pg_advisory_unlock
------------------
t
(1 row)
step s1_insert_toast: <... completed>
step controller_show_count: SELECT COUNT(*) FROM upserttest;
count
-----
1
(1 row)
step controller_unlock_2_2: SELECT pg_advisory_unlock(2, 2);
pg_advisory_unlock
------------------
t
(1 row)
s2: NOTICE: blurt_and_lock_123() called for k2 in session 2
s2: NOTICE: acquiring advisory lock on 2
s2: NOTICE: blurt_and_lock_123() called for k2 in session 2
s2: NOTICE: acquiring advisory lock on 2
step s2_insert_toast: <... completed>
step controller_show_count: SELECT COUNT(*) FROM upserttest;
count
-----
1
(1 row)
starting permutation: controller_locks controller_show s1_begin s2_begin s1_upsert s2_upsert controller_show controller_unlock_1_1 controller_unlock_2_1 controller_unlock_1_3 controller_unlock_2_3 controller_show controller_unlock_1_2 controller_show controller_unlock_2_2 controller_show s1_commit controller_show s2_commit controller_show
step controller_locks: SELECT pg_advisory_lock(sess, lock), sess, lock FROM generate_series(1, 2) a(sess), generate_series(1,3) b(lock);
pg_advisory_lock|sess|lock
----------------+----+----
| 1| 1
| 1| 2
| 1| 3
| 2| 1
| 2| 2
| 2| 3
(6 rows)
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step s1_begin: BEGIN;
step s2_begin: BEGIN;
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 3
step s1_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s1') ON CONFLICT (blurt_and_lock_123(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s1'; <waiting ...>
s2: NOTICE: blurt_and_lock_123() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 3
step s2_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s2') ON CONFLICT (blurt_and_lock_123(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s2'; <waiting ...>
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step controller_unlock_1_1: SELECT pg_advisory_unlock(1, 1);
pg_advisory_unlock
------------------
t
(1 row)
step controller_unlock_2_1: SELECT pg_advisory_unlock(2, 1);
pg_advisory_unlock
------------------
t
(1 row)
step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
pg_advisory_unlock
------------------
t
(1 row)
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 2
step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
pg_advisory_unlock
------------------
t
(1 row)
s2: NOTICE: blurt_and_lock_123() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 2
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step controller_unlock_1_2: SELECT pg_advisory_unlock(1, 2);
pg_advisory_unlock
------------------
t
(1 row)
step s1_upsert: <... completed>
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step controller_unlock_2_2: SELECT pg_advisory_unlock(2, 2);
pg_advisory_unlock
------------------
t
(1 row)
s2: NOTICE: blurt_and_lock_123() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 2
s2: NOTICE: blurt_and_lock_123() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 2
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step s1_commit: COMMIT;
s2: NOTICE: blurt_and_lock_123() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 2
step s2_upsert: <... completed>
step controller_show: SELECT * FROM upserttest;
key|data
---+-----------
k1 |inserted s1
(1 row)
step s2_commit: COMMIT;
step controller_show: SELECT * FROM upserttest;
key|data
---+-----------------------------------
k1 |inserted s1 with conflict update s2
(1 row)
Use annotations to reduce instability of isolation-test results. We've long contended with isolation test results that aren't entirely stable. Some test scripts insert long delays to try to force stable results, which is not terribly desirable; but other erratic failure modes remain, causing unrepeatable buildfarm failures. I've spent a fair amount of time trying to solve this by improving the server-side support code, without much success: that way is fundamentally unable to cope with diffs that stem from chance ordering of arrival of messages from different server processes. We can improve matters on the client side, however, by annotating the test scripts themselves to show the desired reporting order of events that might occur in different orders. This patch adds three types of annotations to deal with (a) test steps that might or might not complete their waits before the isolationtester can see them waiting; (b) test steps in different sessions that can legitimately complete in either order; and (c) NOTIFY messages that might arrive before or after the completion of a step in another session. We might need more annotation types later, but this seems to be enough to deal with the instabilities we've seen in the buildfarm. It also lets us get rid of all the long delays that were previously used, cutting more than a minute off the runtime of the isolation tests. Back-patch to all supported branches, because the buildfarm instabilities affect all the branches, and because it seems desirable to keep isolationtester's capabilities the same across all branches to simplify possible future back-patching of tests. Discussion: https://postgr.es/m/327948.1623725828@sss.pgh.pa.us
2021-06-23 03:43:12 +02:00
starting permutation: s1_create_non_unique_index s1_confirm_index_order controller_locks controller_show s2_begin s1_upsert s2_upsert controller_show controller_unlock_1_1 controller_unlock_2_1 controller_unlock_1_3 controller_unlock_2_3 controller_show controller_lock_2_4 controller_unlock_2_2 controller_show controller_unlock_1_2 controller_print_speculative_locks controller_unlock_2_4 s2_noop controller_print_speculative_locks s2_commit s1_noop controller_show controller_print_speculative_locks
step s1_create_non_unique_index: CREATE INDEX upserttest_key_idx ON upserttest((blurt_and_lock_4(key)));
step s1_confirm_index_order: SELECT 'upserttest_key_uniq_idx'::regclass::int8 < 'upserttest_key_idx'::regclass::int8;
?column?
--------
t
(1 row)
step controller_locks: SELECT pg_advisory_lock(sess, lock), sess, lock FROM generate_series(1, 2) a(sess), generate_series(1,3) b(lock);
pg_advisory_lock|sess|lock
----------------+----+----
| 1| 1
| 1| 2
| 1| 3
| 2| 1
| 2| 2
| 2| 3
(6 rows)
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step s2_begin: BEGIN;
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 3
step s1_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s1') ON CONFLICT (blurt_and_lock_123(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s1'; <waiting ...>
s2: NOTICE: blurt_and_lock_123() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 3
step s2_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s2') ON CONFLICT (blurt_and_lock_123(key)) DO UPDATE SET data = upserttest.data || ' with conflict update s2'; <waiting ...>
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step controller_unlock_1_1: SELECT pg_advisory_unlock(1, 1);
pg_advisory_unlock
------------------
t
(1 row)
step controller_unlock_2_1: SELECT pg_advisory_unlock(2, 1);
pg_advisory_unlock
------------------
t
(1 row)
step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
pg_advisory_unlock
------------------
t
(1 row)
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 2
step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
pg_advisory_unlock
------------------
t
(1 row)
s2: NOTICE: blurt_and_lock_123() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 2
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step controller_lock_2_4: SELECT pg_advisory_lock(2, 4);
pg_advisory_lock
----------------
(1 row)
step controller_unlock_2_2: SELECT pg_advisory_unlock(2, 2);
pg_advisory_unlock
------------------
t
(1 row)
s2: NOTICE: blurt_and_lock_4() called for k1 in session 2
s2: NOTICE: acquiring advisory lock on 4
step controller_show: SELECT * FROM upserttest;
key|data
---+----
(0 rows)
step controller_unlock_1_2: SELECT pg_advisory_unlock(1, 2);
pg_advisory_unlock
------------------
t
(1 row)
s1: NOTICE: blurt_and_lock_4() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 4
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 2
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 2
step controller_print_speculative_locks:
SELECT pa.application_name, locktype, mode, granted
FROM pg_locks pl JOIN pg_stat_activity pa USING (pid)
WHERE
locktype IN ('spectoken', 'transactionid')
AND pa.datname = current_database()
AND pa.application_name LIKE 'isolation/insert-conflict-specconflict/s%'
ORDER BY 1, 2, 3, 4;
application_name |locktype |mode |granted
-----------------------------------------+-------------+-------------+-------
isolation/insert-conflict-specconflict/s1|spectoken |ShareLock |f
isolation/insert-conflict-specconflict/s1|transactionid|ExclusiveLock|t
isolation/insert-conflict-specconflict/s2|spectoken |ExclusiveLock|t
isolation/insert-conflict-specconflict/s2|transactionid|ExclusiveLock|t
(4 rows)
step controller_unlock_2_4: SELECT pg_advisory_unlock(2, 4);
pg_advisory_unlock
------------------
t
(1 row)
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 2
step s2_upsert: <... completed>
Use annotations to reduce instability of isolation-test results. We've long contended with isolation test results that aren't entirely stable. Some test scripts insert long delays to try to force stable results, which is not terribly desirable; but other erratic failure modes remain, causing unrepeatable buildfarm failures. I've spent a fair amount of time trying to solve this by improving the server-side support code, without much success: that way is fundamentally unable to cope with diffs that stem from chance ordering of arrival of messages from different server processes. We can improve matters on the client side, however, by annotating the test scripts themselves to show the desired reporting order of events that might occur in different orders. This patch adds three types of annotations to deal with (a) test steps that might or might not complete their waits before the isolationtester can see them waiting; (b) test steps in different sessions that can legitimately complete in either order; and (c) NOTIFY messages that might arrive before or after the completion of a step in another session. We might need more annotation types later, but this seems to be enough to deal with the instabilities we've seen in the buildfarm. It also lets us get rid of all the long delays that were previously used, cutting more than a minute off the runtime of the isolation tests. Back-patch to all supported branches, because the buildfarm instabilities affect all the branches, and because it seems desirable to keep isolationtester's capabilities the same across all branches to simplify possible future back-patching of tests. Discussion: https://postgr.es/m/327948.1623725828@sss.pgh.pa.us
2021-06-23 03:43:12 +02:00
step s2_noop:
step controller_print_speculative_locks:
SELECT pa.application_name, locktype, mode, granted
FROM pg_locks pl JOIN pg_stat_activity pa USING (pid)
WHERE
locktype IN ('spectoken', 'transactionid')
AND pa.datname = current_database()
AND pa.application_name LIKE 'isolation/insert-conflict-specconflict/s%'
ORDER BY 1, 2, 3, 4;
application_name |locktype |mode |granted
-----------------------------------------+-------------+-------------+-------
isolation/insert-conflict-specconflict/s1|transactionid|ExclusiveLock|t
isolation/insert-conflict-specconflict/s1|transactionid|ShareLock |f
isolation/insert-conflict-specconflict/s2|transactionid|ExclusiveLock|t
(3 rows)
step s2_commit: COMMIT;
s1: NOTICE: blurt_and_lock_123() called for k1 in session 1
s1: NOTICE: acquiring advisory lock on 2
step s1_upsert: <... completed>
Use annotations to reduce instability of isolation-test results. We've long contended with isolation test results that aren't entirely stable. Some test scripts insert long delays to try to force stable results, which is not terribly desirable; but other erratic failure modes remain, causing unrepeatable buildfarm failures. I've spent a fair amount of time trying to solve this by improving the server-side support code, without much success: that way is fundamentally unable to cope with diffs that stem from chance ordering of arrival of messages from different server processes. We can improve matters on the client side, however, by annotating the test scripts themselves to show the desired reporting order of events that might occur in different orders. This patch adds three types of annotations to deal with (a) test steps that might or might not complete their waits before the isolationtester can see them waiting; (b) test steps in different sessions that can legitimately complete in either order; and (c) NOTIFY messages that might arrive before or after the completion of a step in another session. We might need more annotation types later, but this seems to be enough to deal with the instabilities we've seen in the buildfarm. It also lets us get rid of all the long delays that were previously used, cutting more than a minute off the runtime of the isolation tests. Back-patch to all supported branches, because the buildfarm instabilities affect all the branches, and because it seems desirable to keep isolationtester's capabilities the same across all branches to simplify possible future back-patching of tests. Discussion: https://postgr.es/m/327948.1623725828@sss.pgh.pa.us
2021-06-23 03:43:12 +02:00
step s1_noop:
step controller_show: SELECT * FROM upserttest;
key|data
---+-----------------------------------
k1 |inserted s2 with conflict update s1
(1 row)
step controller_print_speculative_locks:
SELECT pa.application_name, locktype, mode, granted
FROM pg_locks pl JOIN pg_stat_activity pa USING (pid)
WHERE
locktype IN ('spectoken', 'transactionid')
AND pa.datname = current_database()
AND pa.application_name LIKE 'isolation/insert-conflict-specconflict/s%'
ORDER BY 1, 2, 3, 4;
application_name|locktype|mode|granted
----------------+--------+----+-------
(0 rows)