Movatterモバイル変換

[0]ホーム
URL:

Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

 Sign up
Appearance settings

Commit43e5346

Browse files
author
Marina Polyakova
committed
Pgbench Deadlock errors
Now session is not disconnected because of deadlock errors. If there was sucherror during script execution this "transaction" is marked appropriately in logs(if there was serialization error too, both failures are marked). Number ofdeadlock errors is printed in progress, in aggregation logs and in the end withother results (all and for each script).
1 parent6cc2ca8 commit43e5346

File tree

2 files changed

+151
-35
lines changed

2 files changed

+151
-35
lines changed

‎src/bin/pgbench/pgbench.c

Lines changed: 81 additions & 35 deletions
Original file line numberDiff line numberDiff line change
@@ -57,6 +57,7 @@
5757

5858
#defineERRCODE_IN_FAILED_SQL_TRANSACTION "25P02"
5959
#defineERRCODE_T_R_SERIALIZATION_FAILURE "40001"
60+
#defineERRCODE_T_R_DEADLOCK_DETECTED "40P01"
6061
#defineERRCODE_UNDEFINED_TABLE "42P01"
6162

6263
/*
@@ -236,6 +237,8 @@ typedef struct StatsData
236237
* and --latency-limit */
237238
int64serialization_failures;/* number of transactions with
238239
* serialization failures */
240+
int64deadlock_failures;/* number of transactions with deadlock
241+
* failures */
239242
SimpleStatslatency;
240243
SimpleStatslag;
241244
}StatsData;
@@ -266,6 +269,8 @@ typedef struct
266269
int64cnt;/* transaction count */
267270
boolserialization_failure;/* if there was serialization failure
268271
* during script execution */
272+
booldeadlock_failure;/* if there was deadlock failure during
273+
* script execution */
269274
intecnt;/* error count */
270275
}CState;
271276

@@ -744,6 +749,7 @@ initStats(StatsData *sd, double start_time)
744749
sd->cnt=0;
745750
sd->skipped=0;
746751
sd->serialization_failures=0;
752+
sd->deadlock_failures=0;
747753
initSimpleStats(&sd->latency);
748754
initSimpleStats(&sd->lag);
749755
}
@@ -753,19 +759,19 @@ initStats(StatsData *sd, double start_time)
753759
*/
754760
staticvoid
755761
accumStats(StatsData*stats,boolskipped,boolserialization_failure,
756-
doublelat,doublelag)
762+
booldeadlock_failure,doublelat,doublelag)
757763
{
758764
stats->cnt++;
759765

760-
if (skipped)
766+
if (skipped||serialization_failure||deadlock_failure)
761767
{
762-
/* no latency to record onskipped transactions */
763-
stats->skipped++;
764-
}
765-
elseif (serialization_failure)
766-
{
767-
/* no latency to record on transactions with serialization failures */
768-
stats->serialization_failures++;
768+
/* no latency to record onsuch transactions */
769+
if (skipped)
770+
stats->skipped++;
771+
if (serialization_failure)
772+
stats->serialization_failures++;
773+
if (deadlock_failure)
774+
stats->deadlock_failures++;
769775
}
770776
else
771777
{
@@ -1908,6 +1914,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
19081914
{
19091915
ExecStatusTyperesult_status;
19101916
boolserialization_failure= false;
1917+
booldeadlock_failure= false;
1918+
boolin_failed_transaction= false;
19111919

19121920
/* are we receiver? */
19131921
if (commands[st->state]->type==SQL_COMMAND)
@@ -1932,18 +1940,26 @@ doCustom(TState *thread, CState *st, StatsData *agg)
19321940
res=PQgetResult(st->con);
19331941
result_status=PQresultStatus(res);
19341942
sqlState=PQresultErrorField(res,PG_DIAG_SQLSTATE);
1935-
serialization_failure=sqlState&&
1936-
(strcmp(sqlState,ERRCODE_T_R_SERIALIZATION_FAILURE)==0||
1937-
strcmp(sqlState,ERRCODE_IN_FAILED_SQL_TRANSACTION)==0);
1938-
if (serialization_failure)
1939-
st->serialization_failure= true;
1943+
if (sqlState) {
1944+
serialization_failure=
1945+
strcmp(sqlState,ERRCODE_T_R_SERIALIZATION_FAILURE)==0;
1946+
deadlock_failure=
1947+
strcmp(sqlState,ERRCODE_T_R_DEADLOCK_DETECTED)==0;
1948+
in_failed_transaction=
1949+
strcmp(sqlState,ERRCODE_IN_FAILED_SQL_TRANSACTION)==0;
1950+
1951+
if (serialization_failure)
1952+
st->serialization_failure= true;
1953+
elseif (deadlock_failure)
1954+
st->deadlock_failure= true;
1955+
}
19401956
}
19411957

19421958
/*
19431959
* accumulate per-command execution times in thread-local data
19441960
* structure, if per-command latencies are requested
19451961
*/
1946-
if (is_latencies&& !serialization_failure)
1962+
if (is_latencies&& !serialization_failure&& !deadlock_failure)
19471963
{
19481964
if (INSTR_TIME_IS_ZERO(now))
19491965
INSTR_TIME_SET_CURRENT(now);
@@ -1967,6 +1983,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
19671983
thread->stats.cnt++;
19681984
if (st->serialization_failure)
19691985
thread->stats.serialization_failures++;
1986+
if (st->deadlock_failure)
1987+
thread->stats.deadlock_failures++;
19701988
}
19711989
}
19721990

@@ -1978,7 +1996,9 @@ doCustom(TState *thread, CState *st, StatsData *agg)
19781996
*/
19791997
if (!(result_status==PGRES_COMMAND_OK||
19801998
result_status==PGRES_TUPLES_OK||
1981-
serialization_failure))
1999+
serialization_failure||
2000+
deadlock_failure||
2001+
in_failed_transaction))
19822002
{
19832003
fprintf(stderr,"client %d aborted in state %d: %s",
19842004
st->id,st->state,PQerrorMessage(st->con));
@@ -2014,6 +2034,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
20142034
sql_script[st->use_file].desc);
20152035
st->is_throttled= false;
20162036
st->serialization_failure= false;
2037+
st->deadlock_failure= false;
20172038

20182039
/*
20192040
* No transaction is underway anymore, which means there is
@@ -2048,6 +2069,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
20482069
st->sleeping= false;
20492070
st->throttling= false;
20502071
st->serialization_failure= false;
2072+
st->deadlock_failure= false;
20512073
memset(st->prepared,0,sizeof(st->prepared));
20522074

20532075
/* set default isolation level */
@@ -2316,29 +2338,38 @@ doLog(TState *thread, CState *st, instr_time *now,
23162338
if (latency_limit)
23172339
fprintf(logfile," "INT64_FORMAT,agg->skipped);
23182340
}
2319-
fprintf(logfile," "INT64_FORMAT,agg->serialization_failures);
2341+
fprintf(logfile," "INT64_FORMAT" "INT64_FORMAT,
2342+
agg->serialization_failures,agg->deadlock_failures);
23202343
fputc('\n',logfile);
23212344

23222345
/* reset data and move to next interval */
23232346
initStats(agg,agg->start_time+agg_interval);
23242347
}
23252348

23262349
/* accumulate the current transaction */
2327-
accumStats(agg,skipped,st->serialization_failure,latency,lag);
2350+
accumStats(agg,skipped,st->serialization_failure,
2351+
st->deadlock_failure,latency,lag);
23282352
}
23292353
else
23302354
{
23312355
/* no, print raw transactions */
2356+
chartransaction_label[256];
2357+
2358+
if (skipped)
2359+
snprintf(transaction_label,sizeof(transaction_label),"skipped");
2360+
elseif (st->serialization_failure&&st->deadlock_failure)
2361+
snprintf(transaction_label,sizeof(transaction_label),
2362+
"serialization and deadlock failures");
2363+
elseif (st->serialization_failure||st->deadlock_failure)
2364+
snprintf(transaction_label,sizeof(transaction_label),"%s failure",
2365+
st->serialization_failure ?"serialization" :"deadlock");
2366+
23322367
#ifndefWIN32
23332368

23342369
/* This is more than we really ought to know about instr_time */
2335-
if (skipped)
2336-
fprintf(logfile,"%d "INT64_FORMAT" skipped %d %ld %ld",
2337-
st->id,st->cnt,st->use_file,
2338-
(long)now->tv_sec, (long)now->tv_usec);
2339-
elseif (st->serialization_failure)
2340-
fprintf(logfile,"%d "INT64_FORMAT" serialization failure %d %ld %ld",
2341-
st->id,st->cnt,st->use_file,
2370+
if (skipped||st->serialization_failure||st->deadlock_failure)
2371+
fprintf(logfile,"%d "INT64_FORMAT" %s %d %ld %ld",
2372+
st->id,st->cnt,transaction_label,st->use_file,
23422373
(long)now->tv_sec, (long)now->tv_usec);
23432374
else
23442375
fprintf(logfile,"%d "INT64_FORMAT" %.0f %d %ld %ld",
@@ -2347,12 +2378,9 @@ doLog(TState *thread, CState *st, instr_time *now,
23472378
#else
23482379

23492380
/* On Windows, instr_time doesn't provide a timestamp anyway */
2350-
if (skipped)
2351-
fprintf(logfile,"%d "INT64_FORMAT" skipped %d 0 0",
2352-
st->id,st->cnt,st->use_file);
2353-
elseif (st->serialization_failure)
2354-
fprintf(logfile,"%d "INT64_FORMAT" serialization failure %d 0 0",
2355-
st->id,st->cnt,st->use_file);
2381+
if (skipped||st->serialization_failure||st->deadlock_failure)
2382+
fprintf(logfile,"%d "INT64_FORMAT" %s %d 0 0",
2383+
st->id,st->cnt,transaction_label,st->use_file);
23562384
else
23572385
fprintf(logfile,"%d "INT64_FORMAT" %.0f %d 0 0",
23582386
st->id,st->cnt,latency,st->use_file);
@@ -2378,7 +2406,7 @@ processXactStats(TState *thread, CState *st, instr_time *now,
23782406
if ((!skipped||agg_interval)&&INSTR_TIME_IS_ZERO(*now))
23792407
INSTR_TIME_SET_CURRENT(*now);
23802408

2381-
if (!skipped&& !st->serialization_failure)
2409+
if (!skipped&& !st->serialization_failure&& !st->deadlock_failure)
23822410
{
23832411
/* compute latency & lag */
23842412
latency=INSTR_TIME_GET_MICROSEC(*now)-st->txn_scheduled;
@@ -2387,8 +2415,8 @@ processXactStats(TState *thread, CState *st, instr_time *now,
23872415

23882416
if (progress||throttle_delay||latency_limit)
23892417
{
2390-
accumStats(&thread->stats,skipped,st->serialization_failure,latency,
2391-
lag);
2418+
accumStats(&thread->stats,skipped,st->serialization_failure,
2419+
st->deadlock_failure,latency,lag);
23922420

23932421
/* count transactions over the latency limit, if needed */
23942422
if (latency_limit&&latency>latency_limit)
@@ -2399,6 +2427,8 @@ processXactStats(TState *thread, CState *st, instr_time *now,
23992427
thread->stats.cnt++;
24002428
if (st->serialization_failure)
24012429
thread->stats.serialization_failures++;
2430+
if (st->deadlock_failure)
2431+
thread->stats.deadlock_failures++;
24022432
}
24032433

24042434
if (use_log)
@@ -2407,7 +2437,8 @@ processXactStats(TState *thread, CState *st, instr_time *now,
24072437
/* XXX could use a mutex here, but we choose not to */
24082438
if (per_script_stats)
24092439
accumStats(&sql_script[st->use_file].stats,skipped,
2410-
st->serialization_failure,latency,lag);
2440+
st->serialization_failure,st->deadlock_failure,latency,
2441+
lag);
24112442
}
24122443

24132444

@@ -3389,6 +3420,10 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
33893420
total->serialization_failures,
33903421
(100.0*total->serialization_failures /total->cnt));
33913422

3423+
printf("number of transactions with deadlock failures: "INT64_FORMAT" (%.3f %%)\n",
3424+
total->deadlock_failures,
3425+
(100.0*total->deadlock_failures /total->cnt));
3426+
33923427
if (throttle_delay&&latency_limit)
33933428
printf("number of transactions skipped: "INT64_FORMAT" (%.3f %%)\n",
33943429
total->skipped,
@@ -3448,6 +3483,11 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
34483483
(100.0*sql_script[i].stats.serialization_failures /
34493484
sql_script[i].stats.cnt));
34503485

3486+
printf(" - number of transactions with deadlock failures: "INT64_FORMAT" (%.3f%%)\n",
3487+
sql_script[i].stats.deadlock_failures,
3488+
(100.0*sql_script[i].stats.deadlock_failures /
3489+
sql_script[i].stats.cnt));
3490+
34513491
if (latency_limit)
34523492
printf(" - number of transactions skipped: "INT64_FORMAT" (%.3f%%)\n",
34533493
sql_script[i].stats.skipped,
@@ -4235,6 +4275,7 @@ main(int argc, char **argv)
42354275
stats.cnt+=thread->stats.cnt;
42364276
stats.skipped+=thread->stats.skipped;
42374277
stats.serialization_failures+=thread->stats.serialization_failures;
4278+
stats.deadlock_failures+=thread->stats.deadlock_failures;
42384279
latency_late+=thread->latency_late;
42394280
INSTR_TIME_ADD(conn_total_time,thread->conn_time);
42404281
}
@@ -4391,6 +4432,7 @@ threadRun(void *arg)
43914432
st->sleeping= false;
43924433
st->throttling= false;
43934434
st->serialization_failure= false;
4435+
st->deadlock_failure= false;
43944436
PQfinish(st->con);
43954437
st->con=NULL;
43964438
continue;
@@ -4574,6 +4616,7 @@ threadRun(void *arg)
45744616
cur.skipped+=thread[i].stats.skipped;
45754617
cur.serialization_failures+=
45764618
thread[i].stats.serialization_failures;
4619+
cur.deadlock_failures+=thread[i].stats.deadlock_failures;
45774620
}
45784621

45794622
total_run= (now-thread_start) /1000000.0;
@@ -4606,6 +4649,9 @@ threadRun(void *arg)
46064649
fprintf(stderr,", "INT64_FORMAT" serialization failures",
46074650
(cur.serialization_failures-
46084651
last.serialization_failures));
4652+
fprintf(stderr,", "INT64_FORMAT" deadlock failures",
4653+
(cur.deadlock_failures-last.deadlock_failures));
4654+
46094655
fprintf(stderr,"\n");
46104656

46114657
last=cur;
Lines changed: 70 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,70 @@
1+
use strict;
2+
use warnings;
3+
4+
use PostgresNode;
5+
use TestLib;
6+
use Test::Moretests=> 18;
7+
8+
# Test concurrent deadlock updates in table with different default transaction
9+
# isolation levels.
10+
my$node = get_new_node('main');
11+
$node->init;
12+
$node->start;
13+
$node->safe_psql('postgres',
14+
'CREATE UNLOGGED TABLE xy (x integer, y integer);'
15+
.'INSERT INTO xy VALUES (1, 2), (2, 3);');
16+
17+
my$script1 =$node->basedir .'/pgbench_script1';
18+
append_to_file($script1,"\\set delta1 random(-5000, 5000)\n");
19+
append_to_file($script1,"\\set delta2 random(-5000, 5000)\n");
20+
append_to_file($script1,"BEGIN;");
21+
append_to_file($script1,"UPDATE xy SET y = y + :delta1 WHERE x = 1;");
22+
append_to_file($script1,"UPDATE xy SET y = y + :delta2 WHERE x = 2;");
23+
append_to_file($script1,"END;");
24+
25+
my$script2 =$node->basedir .'/pgbench_script2';
26+
append_to_file($script2,"\\set delta1 random(-5000, 5000)\n");
27+
append_to_file($script2,"\\set delta2 random(-5000, 5000)\n");
28+
append_to_file($script2,"BEGIN;");
29+
append_to_file($script2,"UPDATE xy SET y = y + :delta2 WHERE x = 2;");
30+
append_to_file($script2,"UPDATE xy SET y = y + :delta1 WHERE x = 1;");
31+
append_to_file($script2,"END;");
32+
33+
# Test deadlock transactions with Read committed default isolation level:
34+
$node->command_like(
35+
[qw(pgbench --no-vacuum --client=5 --transactions=10
36+
--default-isolation-level=RC --file),$script1,qw(--file),$script2],
37+
qr{processed: 50/50},
38+
'concurrent deadlock update: Read Committed: check processed transactions');
39+
40+
$node->command_like(
41+
[qw(pgbench --no-vacuum --client=5 --transactions=10
42+
--default-isolation-level=RC --file),$script1,qw(--file),$script2],
43+
qr{deadlock failures: [1-9]\d*\([1-9]\d*\.\d* %\)},
44+
'concurrent deadlock update: Read Committed: check deadlock failures');
45+
46+
# Test deadlock transactions with Repeatable read default isolation level:
47+
$node->command_like(
48+
[qw(pgbench --no-vacuum --client=5 --transactions=10
49+
--default-isolation-level=RR --file),$script1,qw(--file),$script2],
50+
qr{processed: 50/50},
51+
'concurrent deadlock update: Repeatable Read: check processed transactions');
52+
53+
$node->command_like(
54+
[qw(pgbench --no-vacuum --client=5 --transactions=10
55+
--default-isolation-level=RR --file),$script1,qw(--file),$script2],
56+
qr{deadlock failures: [1-9]\d*\([1-9]\d*\.\d* %\)},
57+
'concurrent deadlock update: Repeatable Read: check deadlock failures');
58+
59+
# Test deadlock transactions with Serializable default isolation level:
60+
$node->command_like(
61+
[qw(pgbench --no-vacuum --client=5 --transactions=10
62+
--default-isolation-level=S --file),$script1,qw(--file),$script2],
63+
qr{processed: 50/50},
64+
'concurrent deadlock update: Serializable: check processed transactions');
65+
66+
$node->command_like(
67+
[qw(pgbench --no-vacuum --client=5 --transactions=10
68+
--default-isolation-level=S --file),$script1,qw(--file),$script2],
69+
qr{deadlock failures: [1-9]\d*\([1-9]\d*\.\d* %\)},
70+
'concurrent deadlock update: Serializable: check deadlock failures');

0 commit comments

Comments
 (0)
[8]ページ先頭
©2009-2025 Movatter.jp