2017-04-06 93 views
1

我正在調試使用JPA/Hibernate和Postgres(9.6.2)的Java應用程序的奇怪行爲。Postgres:奇怪的行爲樂觀鎖定

應用程序有3個實體:用戶,國家,用戶事件

Hibernate將其映射到4個表格:用戶,國家,userevent,hibernate_sequences

用戶實體具有版本列(@版本)和樂觀鎖定的主題。 @GeneratedValue(策略= GenerationType.TABLE),其主鍵爲「id」。用戶表將獲得最多的讀寫次數(最受歡迎的表格)。

我創建了一個情侶的壓力測試來模擬高負載,發現以下錯誤,當我運行它們在Postgres的記錄(請注意,導致它的更新查詢):

ERROR: deadlock detected 
DETAIL: Process 46758 waits for ShareLock on transaction 1580660; blocked by process 46759. 
    Process 46759 waits for AccessExclusiveLock on tuple (97,26) of relation 17353 of database 16385; blocked by process 46758. 

    Process 46758: update users set confirmationState=$1, country_iso=$2, dateOfBirth=$3, email=$4, firstName=$5, gender=$6, lastName=$7, lastUsedLocale=$8, middleName=$9, passwordHash=$10, passwordSalt=$11, phone=$12, role=$13, signInState=$14, updated=$15, username=$16, version=$17 where id=$18 and version=$19 
    Process 46759: update users set confirmationState=$1, country_iso=$2, dateOfBirth=$3, email=$4, firstName=$5, gender=$6, lastName=$7, lastUsedLocale=$8, middleName=$9, passwordHash=$10, passwordSalt=$11, phone=$12, role=$13, signInState=$14, updated=$15, username=$16, version=$17 where id=$18 and version=$19 

    HINT: See server log for query details. 
    CONTEXT: while updating tuple (97,26) in relation "users" 

我瞭解Postgres已經共享和獨家;行,表或索引級鎖。以錯誤順序獲取相同對象可能會導致死鎖。

但是對於這個特定的情況,爲什麼我會樂觀鎖定得到死鎖?我期望一個事務成功,一個在這種情況下返回0個UPDATE。

表,FK,它們的指標描述如下:

################################################################################################## 

             Table "public.users" 
     Column  |   Type    | Modifiers | Storage | Stats target | Description 
-------------------+-----------------------------+-----------+----------+--------------+------------- 
id    | bigint      | not null | plain |    | 
confirmationstate | character varying(20)  | not null | extended |    | 
created   | timestamp without time zone | not null | plain |    | 
dateofbirth  | date      | not null | plain |    | 
email    | character varying(255)  | not null | extended |    | 
firstname   | character varying(100)  | not null | extended |    | 
gender   | character varying(10)  | not null | extended |    | 
lastname   | character varying(100)  | not null | extended |    | 
lastusedlocale | character varying(5)  |   | extended |    | 
middlename  | character varying(100)  |   | extended |    | 
passwordhash  | bytea      | not null | extended |    | 
passwordsalt  | bytea      | not null | extended |    | 
phone    | character varying(50)  |   | extended |    | 
role    | character varying(50)  | not null | extended |    | 
signinstate  | character varying(20)  | not null | extended |    | 
updated   | timestamp without time zone | not null | plain |    | 
username   | character varying(255)  |   | extended |    | 
version   | bigint      |   | plain |    | 
country_iso  | character varying(2)  |   | extended |    | 
Indexes: 
    "users_pkey" PRIMARY KEY, btree (id) 
    "email_idx" UNIQUE CONSTRAINT, btree (email) 
    "username_idx" UNIQUE CONSTRAINT, btree (username) 
    "firstname_idx" btree (firstname) 
    "lastname_idx" btree (lastname) 
    "phone_idx" btree (phone) 
Foreign-key constraints: 
    "fk_ghgfskd1hgobolp0fh20i6h14" FOREIGN KEY (country_iso) REFERENCES countries(iso) 
Referenced by: 
    TABLE "userevents" CONSTRAINT "fk_69tm2wh9hkakap0uyjw41c61h" FOREIGN KEY (targetuser_id) REFERENCES users(id) 
    TABLE "userevents" CONSTRAINT "fk_nov1tso5k93h4m88unjy4f2kl" FOREIGN KEY (user_id) REFERENCES users(id) 

################################################################################################## 

           Table "public.countries" 
    Column |   Type   | Modifiers | Storage | Stats target | Description 
------------+------------------------+-----------+----------+--------------+------------- 
iso  | character varying(2) | not null | extended |    | 
iso3  | character varying(3) |   | extended |    | 
name  | character varying(80) |   | extended |    | 
nativename | character varying(150) |   | extended |    | 
numcode | integer    |   | plain |    | 
phonecode | integer    | not null | plain |    | 
Indexes: 
    "countries_pkey" PRIMARY KEY, btree (iso) 
    "iso3_idx" UNIQUE CONSTRAINT, btree (iso3) 
    "nativename_idx" btree (nativename) 
Referenced by: 
    TABLE "users" CONSTRAINT "fk_ghgfskd1hgobolp0fh20i6h14" FOREIGN KEY (country_iso) REFERENCES countries(iso)  

################################################################################################## 

            Table "public.userevents" 
    Column  |   Type    | Modifiers | Storage | Stats target | Description 
---------------+-----------------------------+-----------+----------+--------------+------------- 
id   | bigint      | not null | plain |    | 
data   | bytea      |   | extended |    | 
ip   | character varying(255)  | not null | extended |    | 
time   | timestamp without time zone | not null | plain |    | 
type   | character varying(15)  | not null | extended |    | 
url   | character varying(2000)  |   | extended |    | 
targetuser_id | bigint      |   | plain |    | 
user_id  | bigint      | not null | plain |    | 
Indexes: 
    "userevents_pkey" PRIMARY KEY, btree (id) 
    "usertypetime_idx" btree (user_id, type, "time") 
Foreign-key constraints: 
    "fk_69tm2wh9hkakap0uyjw41c61h" FOREIGN KEY (targetuser_id) REFERENCES users(id) 
    "fk_nov1tso5k93h4m88unjy4f2kl" FOREIGN KEY (user_id) REFERENCES users(id) 

##################################################################################################  

Table "public.hibernate_sequences" 
     Column   |   Type   | Modifiers | Storage | Stats target | Description 
------------------------+------------------------+-----------+----------+--------------+------------- 
sequence_name   | character varying(255) |   | extended |    | 
sequence_next_hi_value | integer    |   | plain |    | 

################################################################################################## 

編輯1:

先生pozs建議看一下現有的圓形FKS問題,並提供更多的細節在交易中發生了什麼。在這個模式中我沒有循環FK,所以我在Postgres中設置了日誌記錄並試圖找出問題。

以下是導致死鎖的2個進程的所有語句的完整日誌。

過程1日誌:

2017-04-11 12:41:31 PDT  73842 LOG: 00000: execute S_2: BEGIN  
2017-04-11 12:41:31 PDT  73842 LOG: 00000: execute S_3: select user0_.id as id1_2_0_, user0_.confirmationState as confirma2_2_0_, user0_.country_iso as country19_2_0_, user0_.created as created3_2_0_, user0_.dateOfBirth as dateOfBi4_2_0_, user0_.email as email5_2_0_, user0_.firstName as firstNam6_2_0_, user0_.gender as gender7_2_0_, user0_.lastName as lastName8_2_0_, user0_.lastUsedLocale as lastUsed9_2_0_, user0_.middleName as middleN10_2_0_, user0_.passwordHash as passwor11_2_0_, user0_.passwordSalt as passwor12_2_0_, user0_.phone as phone13_2_0_, user0_.role as role14_2_0_, user0_.signInState as signInS15_2_0_, user0_.updated as updated16_2_0_, user0_.username as usernam17_2_0_, user0_.version as version18_2_0_, country1_.iso as iso1_0_1_, country1_.iso3 as iso2_0_1_, country1_.name as name3_0_1_, country1_.nativeName as nativeNa4_0_1_, country1_.numCode as numCode5_0_1_, country1_.phoneCode as phoneCod6_0_1_ from users user0_ left outer join countries country1_ on user0_.country_iso=country1_.iso where user0_.id=$1 
2017-04-11 12:41:31 PDT  73842 DETAIL: parameters: $1 = '10' 
2017-04-11 12:41:31 PDT  73842 LOG: 00000: execute S_10: select country0_.iso as iso1_0_, country0_.iso3 as iso2_0_, country0_.name as name3_0_, country0_.nativeName as nativeNa4_0_, country0_.numCode as numCode5_0_, country0_.phoneCode as phoneCod6_0_ from countries country0_ order by country0_.nativeName, country0_.name 
2017-04-11 12:41:31 PDT  73842 LOG: 00000: execute S_4: insert into userEvents (data, ip, targetUser_id, time, type, url, user_id, id) values ($1, $2, $3, $4, $5, $6, $7, $8) 
2017-04-11 12:41:31 PDT  73842 DETAIL: parameters: $1 = '\x04545...LONG_BINARY_DATA...d', $2 = '192.168.1.2', $3 = '10', $4 = '2017-04-11 19:41:31.268', $5 = 'UPDATE', $6 = 'http://example.org', $7 = '10', $8 = '201243' 
2017-04-11 12:41:31 PDT  73842 LOG: 00000: execute S_7: update users set confirmationState=$1, country_iso=$2, dateOfBirth=$3, email=$4, firstName=$5, gender=$6, lastName=$7, lastUsedLocale=$8, middleName=$9, passwordHash=$10, passwordSalt=$11, phone=$12, role=$13, signInState=$14, updated=$15, username=$16, version=$17 where id=$18 and version=$19 
2017-04-11 12:41:31 PDT  73842 DETAIL: parameters: $1 = 'CONFIRMED', $2 = 'IS', $3 = '1984-10-10', $4 = '[email protected]', $5 = 's7w7j5cdm1bg', $6 = 'FEMALE', $7 = 'Terrier9', $8 = 'en', $9 = 'Russel', $10 = '\x64..6439', $11 = '\x33...3836', $12 = '+16509876945', $13 = 'USER', $14 = 'ENABLED', $15 = '2017-04-11 19:41:31.268', $16 = 'demouser9', $17 = '547', $18 = '10', $19 = '546' 
2017-04-11 12:41:32 PDT  73842 LOG: 00000: process 73842 detected deadlock while waiting for ExclusiveLock on tuple (206,43) of relation 17992 of database 16385 after 1000.114 ms 
2017-04-11 12:41:32 PDT  73842 DETAIL: Process holding the lock: 73817. Wait queue: . 
2017-04-11 12:41:32 PDT  73842 LOCATION: ProcSleep, proc.c:1415 
2017-04-11 12:41:32 PDT  73842 STATEMENT: update users set confirmationState=$1, country_iso=$2, dateOfBirth=$3, email=$4, firstName=$5, gender=$6, lastName=$7, lastUsedLocale=$8, middleName=$9, passwordHash=$10, passwordSalt=$11, phone=$12, role=$13, signInState=$14, updated=$15, username=$16, version=$17 where id=$18 and version=$19 
2017-04-11 12:41:32 PDT  73842 ERROR: 40P01: deadlock detected 
2017-04-11 12:41:32 PDT  73842 DETAIL: Process 73842 waits for ExclusiveLock on tuple (206,43) of relation 17992 of database 16385; blocked by process 73817. 
     Process 73817 waits for ShareLock on transaction 2716972; blocked by process 73842. 
     Process 73842: update users set confirmationState=$1, country_iso=$2, dateOfBirth=$3, email=$4, firstName=$5, gender=$6, lastName=$7, lastUsedLocale=$8, middleName=$9, passwordHash=$10, passwordSalt=$11, phone=$12, role=$13, signInState=$14, updated=$15, username=$16, version=$17 where id=$18 and version=$19 
2017-04-11 12:41:32 PDT  73842 HINT: See server log for query details. 
2017-04-11 12:41:32 PDT  73842 LOCATION: DeadLockReport, deadlock.c:1140 
2017-04-11 12:41:32 PDT  73842 STATEMENT: update users set confirmationState=$1, country_iso=$2, dateOfBirth=$3, email=$4, firstName=$5, gender=$6, lastName=$7, lastUsedLocale=$8, middleName=$9, passwordHash=$10, passwordSalt=$11, phone=$12, role=$13, signInState=$14, updated=$15, username=$16, version=$17 where id=$18 and version=$19 
2017-04-11 12:41:32 PDT  73842 ERROR: 25P02: current transaction is aborted, commands ignored until end of transaction block 
2017-04-11 12:41:32 PDT  73842 LOCATION: exec_parse_message, postgres.c:1303 
2017-04-11 12:41:32 PDT  73842 STATEMENT: SELECT NULL AS TABLE_CAT, n.nspname AS TABLE_SCHEM, c.relname AS TABLE_NAME, CASE n.nspname ~ '^pg_' OR n.nspname = 'information_schema' WHEN true THEN CASE WHEN n.nspname = 'pg_catalog' OR n.nspname = 'information_schema' THEN CASE c.relkind WHEN 'r' THEN 'SYSTEM TABLE' WHEN 'v' THEN 'SYSTEM VIEW' WHEN 'i' THEN 'SYSTEM INDEX' ELSE NULL END WHEN n.nspname = 'pg_toast' THEN CASE c.relkind WHEN 'r' THEN 'SYSTEM TOAST TABLE' WHEN 'i' THEN 'SYSTEM TOAST INDEX' ELSE NULL END ELSE CASE c.relkind WHEN 'r' THEN 'TEMPORARY TABLE' WHEN 'i' THEN 'TEMPORARY INDEX' WHEN 'S' THEN 'TEMPORARY SEQUENCE' WHEN 'v' THEN 'TEMPORARY VIEW' ELSE NULL END END WHEN false THEN CASE c.relkind WHEN 'r' THEN 'TABLE' WHEN 'i' THEN 'INDEX' WHEN 'S' THEN 'SEQUENCE' WHEN 'v' THEN 'VIEW' WHEN 'c' THEN 'TYPE' WHEN 'f' THEN 'FOREIGN TABLE' WHEN 'm' THEN 'MATERIALIZED VIEW' ELSE NULL END ELSE NULL END AS TABLE_TYPE, d.description AS REMARKS FROM pg_catalog.pg_namespace n, pg_catalog.pg_class c LEFT JOIN pg_catalog.pg_description d ON (c.oid = d.objoid AND d.objsubid = 0) LEFT JOIN pg_catalog.pg_class dc ON (d.classoid=dc.oid AND dc.relname='pg_class') LEFT JOIN pg_catalog.pg_namespace dn ON (dn.oid=dc.relnamespace AND dn.nspname='pg_catalog') WHERE c.relnamespace = n.oid AND c.relname LIKE 'PROBABLYNOT' AND (false OR (c.relkind = 'r' AND n.nspname !~ '^pg_' AND n.nspname <> 'information_schema')) ORDER BY TABLE_TYPE,TABLE_SCHEM,TABLE_NAME 
2017-04-11 12:41:32 PDT  73842 LOG: 00000: execute S_11: ROLLBACK 

過程2日誌:

2017-04-11 12:41:31 PDT  73817 LOG: 00000: execute S_2: BEGIN 
2017-04-11 12:41:31 PDT  73817 LOG: 00000: execute S_3: select user0_.id as id1_2_0_, user0_.confirmationState as confirma2_2_0_, user0_.country_iso as country19_2_0_, user0_.created as created3_2_0_, user0_.dateOfBirth as dateOfBi4_2_0_, user0_.email as email5_2_0_, user0_.firstName as firstNam6_2_0_, user0_.gender as gender7_2_0_, user0_.lastName as lastName8_2_0_, user0_.lastUsedLocale as lastUsed9_2_0_, user0_.middleName as middleN10_2_0_, user0_.passwordHash as passwor11_2_0_, user0_.passwordSalt as passwor12_2_0_, user0_.phone as phone13_2_0_, user0_.role as role14_2_0_, user0_.signInState as signInS15_2_0_, user0_.updated as updated16_2_0_, user0_.username as usernam17_2_0_, user0_.version as version18_2_0_, country1_.iso as iso1_0_1_, country1_.iso3 as iso2_0_1_, country1_.name as name3_0_1_, country1_.nativeName as nativeNa4_0_1_, country1_.numCode as numCode5_0_1_, country1_.phoneCode as phoneCod6_0_1_ from users user0_ left outer join countries country1_ on user0_.country_iso=country1_.iso where user0_.id=$1 
2017-04-11 12:41:31 PDT  73817 DETAIL: parameters: $1 = '10' 
2017-04-11 12:41:31 PDT  73817 LOG: 00000: execute S_6: select country0_.iso as iso1_0_0_, country0_.iso3 as iso2_0_0_, country0_.name as name3_0_0_, country0_.nativeName as nativeNa4_0_0_, country0_.numCode as numCode5_0_0_, country0_.phoneCode as phoneCod6_0_0_ from countries country0_ where country0_.iso=$1 
2017-04-11 12:41:31 PDT  73817 DETAIL: parameters: $1 = 'JP' 
2017-04-11 12:41:31 PDT  73817  
2017-04-11 12:41:31 PDT  73817 LOG: 00000: execute S_5: update users set confirmationState=$1, country_iso=$2, dateOfBirth=$3, email=$4, firstName=$5, gender=$6, lastName=$7, lastUsedLocale=$8, middleName=$9, passwordHash=$10, passwordSalt=$11, phone=$12, role=$13, signInState=$14, updated=$15, username=$16, version=$17 where id=$18 and version=$19 
2017-04-11 12:41:31 PDT  73817 DETAIL: parameters: $1 = 'CONFIRMED', $2 = 'JP', $3 = '1984-10-10', $4 = '[email protected]', $5 = '-1kcg4facio48g', $6 = 'FEMALE', $7 = 'Terrier9', $8 = 'en', $9 = 'Russel', $10 = '\x64656d6f7573657270617373776f726439', $11 = '\x33...3836', $12 = '+16509876905', $13 = 'USER', $14 = 'ENABLED', $15 = '2017-04-11 19:41:31.188', $16 = 'demouser9', $17 = '547', $18 = '10', $19 = '546' 
2017-04-11 12:41:32 PDT  73842 DETAIL: Process holding the lock: 73817. Wait queue: . 
2017-04-11 12:41:32 PDT  73842 DETAIL: Process 73842 waits for ExclusiveLock on tuple (206,43) of relation 17992 of database 16385; blocked by process 73817. 
     Process 73817 waits for ShareLock on transaction 2716972; blocked by process 73842. 
     Process 73817: update users set confirmationState=$1, country_iso=$2, dateOfBirth=$3, email=$4, firstName=$5, gender=$6, lastName=$7, lastUsedLocale=$8, middleName=$9, passwordHash=$10, passwordSalt=$11, phone=$12, role=$13, signInState=$14, updated=$15, username=$16, version=$17 where id=$18 and version=$19 
2017-04-11 12:41:32 PDT  73817 LOG: 00000: execute S_10: ROLLBACK 

用於過程1的流程爲:

  1. BEGIN;
  2. SELECT * FROM users WHERE id = 10;
  3. SELECT * FROM countries; //不影響問題
  4. INSERT INTO userEvents(...,user_id,...)VALUES(...,10,...);
  5. UPDATE users SET [..fields to update ..] WHERE id = 10 AND version = 546;
  6. COMMIT;

爲處理2的流程爲:

  1. BEGIN;
  2. SELECT * FROM users WHERE id = 10;
  3. UPDATE users SET [..fields to update ..] WHERE id = 10 AND version = 546;
  4. COMMIT;

是因爲在第一交易獲取上FK(userEvents.user_id)的排他鎖爲INSERT後來上UPDATE的獨佔鎖(users.id = 10)的順序的和(users.id = 10)(userEvents.user_id)在更新第二

因爲當我強迫「用戶更新」「INSERT INTO userEvents」之前我沒有看到死鎖在高負載下了

+0

你在這些交易中還做了什麼?是f.ex.觸發器涉及?或者,插入另一個表中? - 你讀過這個相關的問題嗎? http://stackoverflow.com/questions/18297478/deadlock-in-postgres-on-simple-update-query – pozs

回答

0

如果兩個事務試圖同時更新同一行,並且同一行同時有version,那麼其中一個將獲取該行的鎖,另一個將會阻塞。

只要第一筆交易處於活動狀態,第二筆交易就無法決定是否「獲得」了樂觀鎖。如果第一筆交易成功,第二筆交易將發現version不再匹配,並且將返回而不更新任何內容。但是,如果第一筆交易回滾,第二筆交易將獲得舊版version的鎖定並繼續更新。與此同時,它只需等待,一旦你有交易等待,死鎖場景很容易構建。