Task #446
Updated by Aaron Marcuse-Kubitza almost 12 years ago
h3. Possible solutions
# -retry query on TransactionRollbackError-: _done, but doesn't fix the underlying problem_
# commit after each insert to release the tuple lock
** but may not be 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>