Task #446: fix deadlock in INSERT IGNORE replacement - BIEN 3 - NCEAS Projects

Actions

Copy link

Task #446

open

fix deadlock in INSERT IGNORE replacement

Added by Aaron Marcuse-Kubitza over 12 years ago. Updated almost 11 years ago.

Status:

New

Priority:

Normal

Assignee:

Aaron Marcuse-Kubitza

Start date:

07/19/2012

Due date:

% Done:

Estimated time:

Activity type:

Description

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 this is not possible in a SQL function

Questions¶

is ShareLock a row share?

Errors¶

2012-07-17 SpeciesLink:

/home/bien/svn/inputs/SpeciesLink/import/specimens.2012-07-17-23-12-36.log.sql line 50254 (vegbiendev):

[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)
*/

grep -F "deadlock detected" -C 20 /var/log/postgresql/postgresql-9.1-main.log (vegbiendev):

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)
    */

2012-12-19 ARIZ:

/home/bien/svn/inputs/ARIZ/Specimen/logs/r6963.log.sql line 19393 (vegbiendev):

[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@

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.

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)
    */
[...]