Skip to content

Commit f63ad29

Browse files
jberkusjberkus
committed
New lock logging setup. Logs to file instead of a table.
1 parent 0efb7eb commit f63ad29

File tree

5 files changed

+255
-256
lines changed

5 files changed

+255
-256
lines changed

‎locks/README.rst‎

Lines changed: 17 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -4,13 +4,26 @@ Lock-Logging Scripts
44
Since the amount of information you can usefully get out of log_lock_waits is limited, these
55
scripts add a way to log complex information to PostgreSQL tables.
66

7-
1. Run table_locks_setup.sql and transaction_locks_setup.sql against the target database
8-
This will create 2 tables and 2 functions for logging.
7+
Run the script as follows:
98

10-
2. Add a cron job to execute log_locks.sh every 1 to 10 minutes.
9+
./log_locks.sh INTERVAL XNUMBER
10+
11+
INTERVAL: number of seconds at which to repeat the logging
12+
XNUMBER: number of times to poll the locks
13+
14+
So for example, to log every 30 seconds for 1 hour, you'd do:
15+
16+
./log_locks.sh 30 120
17+
18+
This script can be terminated using ctrl-C or kill without consequences.
19+
20+
This produces two logs in the current directory, lock_table.log and lock_transaction.log. These
21+
logs can be loaded into a database using the table definitions in lock_tables.sql. If you run the
22+
script more than once, new output will be appended to those files.
1123

1224
Note that, under pathological conditions, querying the locks tables can have significant overhead,
1325
and the lock logging query itself can become blocked or bog down. For that reason, we recommend
14-
discretion on how frequently you run the cron job.
26+
discretion on how frequently you poll the locks. Polling locks more often than every 10 seconds
27+
is never recommended.
1528

1629
**Requires PostgreSQL 9.2 or Later**

‎locks/lock_tables.sql‎

Lines changed: 57 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,57 @@
1+
CREATE TABLE table_locks (
2+
lock_ts TIMESTAMPTZ,
3+
dbname TEXT,
4+
waiting_pid INT,
5+
wait_xid TEXT,
6+
locked_pid INT,
7+
locked_xid TEXT,
8+
locked_relation TEXT,
9+
waiting_type TEXT,
10+
waiting_mode TEXT,
11+
waiting_tuple TEXT,
12+
locked_type TEXT,
13+
locked_mode TEXT,
14+
locked_tuple TEXT,
15+
waiting_app TEXT,
16+
waiting_addr TEXT,
17+
waiting_xact_start TIMESTAMPTZ,
18+
waiting_query_start TIMESTAMPTZ,
19+
waiting_start TIMESTAMPTZ,
20+
waiting_query TEXT,
21+
locked_app TEXT,
22+
locked_addr TEXT,
23+
locked_xact_start TIMESTAMPTZ,
24+
locked_query_start TIMESTAMPTZ,
25+
locked_state TEXT,
26+
locked_state_start TIMESTAMPTZ,
27+
locked_last_query TEXT
28+
);
29+
30+
CREATE TABLE transaction_locks (
31+
lock_ts TIMESTAMPTZ,
32+
dbname TEXT,
33+
waiting_pid INT,
34+
waiting_xid TEXT,
35+
locked_pid INT,
36+
waiting_app TEXT,
37+
waiting_addr TEXT,
38+
waiting_xact_start TIMESTAMPTZ,
39+
waiting_query_start TIMESTAMPTZ,
40+
waiting_start TIMESTAMPTZ,
41+
waiting_query TEXT,
42+
locked_app TEXT,
43+
locked_addr TEXT,
44+
locked_xact_start TIMESTAMPTZ,
45+
locked_query_start TIMESTAMPTZ,
46+
locked_state TEXT,
47+
locked_state_start TIMESTAMPTZ,
48+
locked_last_query TEXT,
49+
waiting_relations TEXT[],
50+
waiting_modes TEXT[],
51+
waiting_lock_types TEXT[],
52+
locked_relations TEXT[],
53+
locked_modes TEXT[],
54+
locked_lock_types TEXT[]
55+
);
56+
57+

‎locks/log_locks.sh‎

Lines changed: 181 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -3,21 +3,195 @@
33
# simple script to log transaction locks to a table
44
# assumes that you're running it as the postgres user and don't need a password
55

6+
# set interval and number of executions
7+
# interval is set in seconds
8+
# defaults to 1000 minutes once per minute
9+
# not recommended to run this more than 4X per minute
10+
INTERVAL=${1:-60}
11+
XNUMBER=${2:-1000}
12+
613
# change to path of psql
7-
PSQL='/usr/pgsql-9.2/bin/psql'
14+
PSQL='psql'
815

916
# list all databases you're targeting, space separated
10-
DBNAMES='postgres mydatabase'
17+
DBNAMES='postgres flo'
1118

1219
# modify if required
20+
# statement timeout is required to keep the lock query
21+
# from hanging
1322
DBPORT=''
1423
DBHOST=''
24+
STATTIMEOUT=2000
25+
SUPER="josh"
1526

16-
for DBNAME in $DBNAMES; do
17-
$PSQL -c "SELECT log_transaction_locks();" -U postgres $DBNAME $DBPORT $DBHOST
18-
$PSQL -c "SELECT log_table_locks();" -U postgres $DBNAME $DBPORT $DBHOST
19-
done
27+
# output files. you shouldn't need to modify these
28+
# unless you're doing something special
29+
TABLELOG='lock_table.log'
30+
XTNLOG='lock_transaction.log'
31+
32+
# queries; you should not need to modify these
33+
TABLEQUERY="WITH table_locks AS (
34+
select pid,
35+
relation::int as relation,
36+
(relation::regclass)::text as locked_relation,
37+
mode,
38+
page || ':' || tuple as locked_tuple,
39+
locktype,
40+
coalesce(transactionid::text, virtualxid) as lxid,
41+
granted
42+
from pg_locks
43+
join pg_database
44+
ON pg_locks.database = pg_database.oid
45+
where relation is not null
46+
and pg_database.datname = current_database()
47+
and locktype IN ( 'relation', 'extend', 'page', 'tuple' )
48+
),
49+
lock_granted AS (
50+
select * from table_locks
51+
where granted
52+
),
53+
lock_waiting AS (
54+
select * from table_locks
55+
where not granted
56+
)
57+
select now() as lock_ts,
58+
current_database() as dbname,
59+
lock_waiting.pid as waiting_pid,
60+
lock_waiting.lxid as wait_xid,
61+
lock_granted.pid as locked_pid,
62+
lock_granted.lxid as locked_xid,
63+
lock_granted.locked_relation,
64+
lock_waiting.locktype as waiting_type,
65+
lock_waiting.mode as waiting_mode,
66+
lock_waiting.locked_tuple as tuple_waiting,
67+
lock_granted.locktype as locked_type,
68+
lock_granted.mode as lock_mode,
69+
lock_granted.locked_tuple as tuple_locked,
70+
waiting_proc.application_name as waiting_app,
71+
waiting_proc.client_addr as waiting_addr,
72+
waiting_proc.xact_start as waiting_xact_start,
73+
waiting_proc.query_start as waiting_query_start,
74+
waiting_proc.state_change as waiting_start,
75+
waiting_proc.query as waiting_query,
76+
locked_proc.application_name as locked_app,
77+
locked_proc.client_addr as locked_addr,
78+
locked_proc.xact_start as locked_xact_start,
79+
locked_proc.query_start as locked_query_start,
80+
locked_proc.state as locked_state,
81+
locked_proc.state_change as locked_state_start,
82+
locked_proc.query as locked_last_query
83+
from lock_waiting
84+
JOIN pg_stat_activity as waiting_proc
85+
ON lock_waiting.pid = waiting_proc.pid
86+
LEFT OUTER JOIN lock_granted
87+
ON lock_waiting.relation = lock_granted.relation
88+
LEFT OUTER JOIN pg_stat_activity as locked_proc
89+
ON lock_granted.pid = locked_proc.pid
90+
order by locked_pid, locked_relation;"
91+
92+
XTNQUERY="WITH mylocks AS (
93+
SELECT * FROM pg_locks
94+
WHERE locktype IN ( 'transactionid', 'virtualxid' )
95+
),
96+
table_locks AS (
97+
select pid,
98+
(relation::regclass)::TEXT as lockobj,
99+
case when page is not null and tuple is not null then
100+
mode || ' on ' || page::text || ':' || tuple::text
101+
else
102+
mode
103+
end as lock_mode,
104+
locktype
105+
from mylocks
106+
join pg_database
107+
ON mylocks.database = pg_database.oid
108+
where relation is not null
109+
and pg_database.datname = current_database()
110+
order by lockobj
111+
),
112+
locked_list AS (
113+
select pid,
114+
array_agg(lockobj) as lock_relations,
115+
array_agg(lock_mode) as lock_modes,
116+
array_agg(locktype) as lock_types
117+
from table_locks
118+
group by pid
119+
),
120+
txn_locks AS (
121+
select pid, transactionid::text as lxid, granted
122+
from mylocks
123+
where locktype = 'transactionid'
124+
union all
125+
select pid, virtualxid::text as lxid, granted
126+
from mylocks
127+
where locktype = 'virtualxid'
128+
),
129+
txn_granted AS (
130+
select pid, lxid from txn_locks
131+
where granted
132+
),
133+
txn_waiting AS (
134+
select pid, lxid from txn_locks
135+
where not granted
136+
)
137+
select now() as lock_ts,
138+
current_database() AS dbname,
139+
txn_waiting.pid as waiting_pid,
140+
txn_waiting.lxid as wait_xid,
141+
txn_granted.pid as locked_pid,
142+
waiting_proc.application_name as waiting_app,
143+
waiting_proc.client_addr as waiting_addr,
144+
waiting_proc.xact_start as waiting_xact_start,
145+
waiting_proc.query_start as waiting_query_start,
146+
waiting_proc.state_change as waiting_start,
147+
waiting_proc.query as waiting_query,
148+
locked_proc.application_name as locked_app,
149+
locked_proc.client_addr as locked_addr,
150+
locked_proc.xact_start as locked_xact_start,
151+
locked_proc.query_start as locked_query_start,
152+
locked_proc.state as locked_state,
153+
locked_proc.state_change as locked_state_start,
154+
locked_proc.query as locked_last_query,
155+
waiting_locks.lock_relations as waiting_relations,
156+
waiting_locks.lock_modes as waiting_modes,
157+
waiting_locks.lock_types as waiting_lock_types,
158+
locked_locks.lock_relations as locked_relations,
159+
locked_locks.lock_modes as locked_modes,
160+
locked_locks.lock_types as locked_lock_types
161+
from txn_waiting
162+
JOIN pg_stat_activity as waiting_proc
163+
ON txn_waiting.pid = waiting_proc.pid
164+
LEFT OUTER JOIN txn_granted
165+
ON txn_waiting.lxid = txn_granted.lxid
166+
LEFT OUTER JOIN pg_stat_activity as locked_proc
167+
ON txn_granted.pid = locked_proc.pid
168+
LEFT OUTER JOIN locked_list AS waiting_locks
169+
ON txn_waiting.pid = waiting_locks.pid
170+
LEFT OUTER JOIN locked_list AS locked_locks
171+
ON txn_granted.pid = locked_locks.pid;"
20172

21-
# $PSQL -c "INSERT INTO activity_log SELECT * FROM pg_stat_activity;" -U postgres $DBNAME $DBPORT $DBHOST
173+
# write headers
174+
if [ ! -f $TABLELOG ]; then
175+
echo 'lock_ts|dbname|waiting_pid|wait_xid|locked_pid|locked_xid|locked_relation|waiting_type|waiting_mode|waiting_tuple|locked_type|locked_mode|locked_tuple|waiting_app|waiting_addr|waiting_xact_start|waiting_query_start|waiting_start|waiting_query|locked_app|locked_addr|locked_xact_start|locked_query_start|locked_state|locked_state_start|locked_last_query' > $TABLELOG
176+
fi
177+
178+
if [ ! -f XTNLOG ]; then
179+
echo 'lock_ts|dbname|waiting_pid|waiting_xid|locked_pid|waiting_app|waiting_addr|waiting_xact_start|waiting_query_start|waiting_start|waiting_query|locked_app|locked_addr|locked_xact_start|locked_query_start|locked_state|locked_state_start|locked_last_query|waiting_relations|waiting_modes|waiting_lock_types|locked_relations|locked_modes|locked_lock_types' > $XTNLOG
180+
fi
181+
182+
for ((i=0; i<$XNUMBER; i++)); do
183+
184+
for DBNAME in $DBNAMES; do
185+
$PSQL -A -q -t -c "SET STATEMENT_TIMEOUT=${STATTIMEOUT}; ${TABLEQUERY}" -U $SUPER $DBNAME $DBPORT $DBHOST >> $TABLELOG
186+
$PSQL -A -q -t -c "SET STATEMENT_TIMEOUT=${STATTIMEOUT}; ${XTNQUERY}" -U $SUPER $DBNAME $DBPORT $DBHOST >> $XTNLOG
187+
done
188+
189+
if (($i%10==0)); then
190+
echo "locks polled $i times"
191+
fi
192+
193+
sleep $INTERVAL
194+
195+
done
22196

23197
exit 0

0 commit comments

Comments
 (0)