Task #446
Updated by Aaron Marcuse-Kubitza almost 11 years ago
h3. Possible solutions # -retry query on TransactionRollbackError-: _done, but doesn't fix the underlying problem and the deadlock sometimes reoccurs_ # order inserts so rows are inserted in the same order by all datasources ** not possible to instead commit after each insert to release the tuple lock, because lock ** but unfortunately, this is not possible in a SQL function # order inserts so rows are inserted in the same order by all datasources h3. Questions * is ShareLock a row share? h3. Errors *2012-07-17 SpeciesLink:* @/home/bien/svn/inputs/SpeciesLink/import/specimens.2012-07-17-23-12-36.log.sql@ line 50254 (vegbiendev): <pre><code class="SQL"> [1.5] Caught exception: TransactionRollbackError: deadlock detected [1.5] No handler for exception [101;97m TransactionRollbackError: deadlock detected [0m DETAIL: Process 27259 waits for ShareLock on transaction 1894759460; blocked by process 14386. Process 14386 waits for ShareLock on transaction 1894570722; blocked by process 27259. HINT: See server log for query details. CONTEXT: PL/pgSQL function "INSERT INTO party#3" line 23 at RETURN QUERY query: [input] /*SpeciesLink.specimens*/ CREATE TEMP TABLE "rowcount#33" AS SELECT * FROM "pg_temp"."INSERT INTO party#3"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO party#3" f (cost=0.25..10.25 rows=1000 width=32) */ </code></pre> @grep -F "deadlock detected" -C 20 /var/log/postgresql/postgresql-9.1-main.log@ (vegbiendev): <pre><code class="SQL"> 2012-07-18 02:51:42 PDT ERROR: deadlock detected 2012-07-18 02:51:42 PDT DETAIL: Process 27259 waits for ShareLock on transaction 1894759460; blocked by process 14386. Process 14386 waits for ShareLock on transaction 1894570722; blocked by process 27259. Process 27259: /*SpeciesLink.specimens*/ CREATE TEMP TABLE "rowcount#33" AS SELECT * FROM "pg_temp"."INSERT INTO party#3"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO party#3" f (cost=0.25..10.25 rows=1000 width=32) */ Process 14386: /*GBIF.specimens*/ CREATE TEMP TABLE "rowcount#21" AS SELECT * FROM "pg_temp"."INSERT INTO party#3"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO party#3" f (cost=0.25..10.25 rows=1000 width=32) */ 2012-07-18 02:51:42 PDT HINT: See server log for query details. 2012-07-18 02:51:42 PDT CONTEXT: PL/pgSQL function "INSERT INTO party#3" line 23 at RETURN QUERY 2012-07-18 02:51:42 PDT STATEMENT: /*SpeciesLink.specimens*/ CREATE TEMP TABLE "rowcount#33" AS SELECT * FROM "pg_temp"."INSERT INTO party#3"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO party#3" f (cost=0.25..10.25 rows=1000 width=32) */ </code></pre> *2012-12-19 ARIZ:* @/home/bien/svn/inputs/ARIZ/Specimen/logs/r6963.log.sql@ line 19393 (vegbiendev): <pre><code class="SQL"> [1.5] Caught exception: TransactionRollbackError: deadlock detected [1.5] Trying to insert new rows [2] DB query: cache hit: Took 0:00:00.000037 sec /*ARIZ.Specimen*/ CREATE FUNCTION "pg_temp"."INSERT INTO place#1"() RETURNS SETOF unknown LANGUAGE plpgsql AS $$ DECLARE "row" "place"%ROWTYPE; BEGIN FOR "row"."source_id", "row"."coordinates_id", "row"."stateprovince", "row"."county", "row"."country" IN SELECT 1 AS "source_id" , "in#64_distinct"."coordinates_pkeys#1.out.coordinates_id" , "in#64_distinct"."ARIZ.Specimen.StateProvince" , "in#64_distinct"."ARIZ.Specimen.County" , "in#64_distinct"."ARIZ.Specimen.Country" FROM "in#64_distinct" ORDER BY row_num /* EXPLAIN: Index Scan using "in#64_distinct_pkey" on "in#64_distinct" (cost=0.00..2324.05 rows=36166 width=41) */ LOOP BEGIN RETURN QUERY INSERT INTO "place" ("source_id", "coordinates_id", "stateprovince", "county", "country") VALUES ("row"."source_id", "row"."coordinates_id", "row"."stateprovince", "row"."county", "row"."country") RETURNING NULL AS "NULL" ; EXCEPTION WHEN unique_violation THEN NULL; END; END LOOP; END; $$; [2] DB query: non-cacheable: Took 0:00:05.068492 sec /*ARIZ.Specimen*/ CREATE TEMP TABLE "rowcount#16" AS SELECT * FROM "pg_temp"."INSERT INTO place#1"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO place#1" f (cost=0.25..10.25 rows=1000 width=32) */ [1.5] Caught exception: TransactionRollbackError: deadlock detected [1.5] Exception already seen, handler broken [101;97m TransactionRollbackError: deadlock detected [0m DETAIL: Process 9177 waits for ShareLock on transaction 1096939461; blocked by process 15858. Process 15858 waits for ShareLock on transaction 1096975485; blocked by process 9177. HINT: See server log for query details. CONTEXT: PL/pgSQL function "INSERT INTO place#1" line 19 at RETURN QUERY query: [input] /*ARIZ.Specimen*/ CREATE TEMP TABLE "rowcount#16" AS SELECT * FROM "pg_temp"."INSERT INTO place#1"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO place#1" f (cost=0.25..10.25 rows=1000 width=32) */ node: [...] Traceback (most recent call last): File "../../bin/../lib/sql_io.py", line 656, in put_table main_select, **insert_args) File "../../bin/../lib/sql.py", line 932, in insert_select into, recover=recover, cacheable=cacheable, log_level=log_level) File "../../bin/../lib/sql.py", line 721, in run_query_into cur = run_query(db, create_query, **kw_args) File "../../bin/../lib/sql.py", line 652, in run_query parse_exception(db, e, recover) File "../../bin/../lib/sql.py", line 646, in run_query return with_savepoint(db, run) File "../../bin/../lib/sql.py", line 629, in with_savepoint def with_savepoint(db, func): return db.with_savepoint(func) File "../../bin/../lib/sql.py", line 440, in with_savepoint return func() File "../../bin/../lib/sql.py", line 644, in run debug_msg_ref, **kw_args) File "../../bin/../lib/sql.py", line 384, in run_query try: cur.execute(query) [1.5] Ignoring all rows [2.1] Default value column @'parent_id'@ does not exist in mapping, falling back to None [1.5] Returning default: @None@ </code></pre> @grep -F "deadlock detected" -A 20 /var/lib/postgresql/9.1/main/pg_log/postgresql-2012-12-19_182909.log@ (vegbiendev): _Error occurs 3 times because the import whose transaction was aborted retries the query once._ <pre><code class="SQL"> 2012-12-19 18:49:23 PST ERROR: deadlock detected 2012-12-19 18:49:23 PST DETAIL: Process 15858 waits for ShareLock on transaction 1096887692; blocked by process 9177. Process 9177 waits for ShareLock on transaction 1096930673; blocked by process 15858. Process 15858: /*UBC.Specimen*/ CREATE TEMP TABLE "rowcount#15" AS SELECT * FROM "pg_temp"."INSERT INTO place#1"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO place#1" f (cost=0.25..10.25 rows=1000 width=32) */ Process 9177: /*ARIZ.Specimen*/ CREATE TEMP TABLE "rowcount#16" AS SELECT * FROM "pg_temp"."INSERT INTO place#1"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO place#1" f (cost=0.25..10.25 rows=1000 width=32) */ 2012-12-19 18:49:23 PST HINT: See server log for query details. 2012-12-19 18:49:23 PST CONTEXT: PL/pgSQL function "INSERT INTO place#1" line 18 at RETURN QUERY 2012-12-19 18:49:23 PST STATEMENT: /*UBC.Specimen*/ CREATE TEMP TABLE "rowcount#15" AS SELECT * FROM "pg_temp"."INSERT INTO place#1"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO place#1" f (cost=0.25..10.25 rows=1000 width=32) */ [...] -- 2012-12-19 18:49:31 PST ERROR: deadlock detected 2012-12-19 18:49:31 PST DETAIL: Process 9177 waits for ShareLock on transaction 1096939461; blocked by process 15858. Process 15858 waits for ShareLock on transaction 1096887692; blocked by process 9177. Process 9177: /*ARIZ.Specimen*/ CREATE TEMP TABLE "rowcount#16" AS SELECT * FROM "pg_temp"."INSERT INTO place#1"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO place#1" f (cost=0.25..10.25 rows=1000 width=32) */ Process 15858: /*UBC.Specimen*/ CREATE TEMP TABLE "rowcount#15" AS SELECT * FROM "pg_temp"."INSERT INTO place#1"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO place#1" f (cost=0.25..10.25 rows=1000 width=32) */ 2012-12-19 18:49:31 PST HINT: See server log for query details. 2012-12-19 18:49:31 PST CONTEXT: PL/pgSQL function "INSERT INTO place#1" line 19 at RETURN QUERY 2012-12-19 18:49:31 PST STATEMENT: /*ARIZ.Specimen*/ CREATE TEMP TABLE "rowcount#16" AS SELECT * FROM "pg_temp"."INSERT INTO place#1"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO place#1" f (cost=0.25..10.25 rows=1000 width=32) */ [...] -- 2012-12-19 18:49:36 PST ERROR: deadlock detected 2012-12-19 18:49:36 PST DETAIL: Process 9177 waits for ShareLock on transaction 1096939461; blocked by process 15858. Process 15858 waits for ShareLock on transaction 1096975485; blocked by process 9177. Process 9177: /*ARIZ.Specimen*/ CREATE TEMP TABLE "rowcount#16" AS SELECT * FROM "pg_temp"."INSERT INTO place#1"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO place#1" f (cost=0.25..10.25 rows=1000 width=32) */ Process 15858: /*UBC.Specimen*/ CREATE TEMP TABLE "rowcount#15" AS SELECT * FROM "pg_temp"."INSERT INTO place#1"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO place#1" f (cost=0.25..10.25 rows=1000 width=32) */ 2012-12-19 18:49:36 PST HINT: See server log for query details. 2012-12-19 18:49:36 PST CONTEXT: PL/pgSQL function "INSERT INTO place#1" line 19 at RETURN QUERY 2012-12-19 18:49:36 PST STATEMENT: /*ARIZ.Specimen*/ CREATE TEMP TABLE "rowcount#16" AS SELECT * FROM "pg_temp"."INSERT INTO place#1"() AS "f" ("NULL") /* EXPLAIN: Function Scan on "INSERT INTO place#1" f (cost=0.25..10.25 rows=1000 width=32) */ [...] </code></pre>