Lock tracing tools for PostgreSQL

This project provides tools that allow you to gain deep insights into PostgreSQL's locking activities and troubleshoot locking-related issues (e.g., performance problems or deadlocks).

• pg_lock_tracer - is a PostgreSQL table level lock tracer.
• pg_lw_lock_tracer - is a tracer for PostgreSQL lightweight locks (LWLocks).
• pg_row_lock_tracer - is a tracer for PostgreSQL row locks.
• animate_lock_graph - creates animated locks graphs based on the pg_lock_tracer output.

Note: These tools employ the eBPF (Extended Berkeley Packet Filter) technology. At the moment, PostgreSQL 12, 13, 14, 15, and 16 are supported (see additional information below).

pg_lock_tracer

pg_lock_tracer observes the locking activity of a running PostgreSQL process (using eBPF and UProbes). In contrast to the information that is present in the table pg_locks (which provides information about which locks are currently requested), pg_lock_tracer gives you a continuous view of the locking activity and collects statistics and timings.

The tracer also allows dumping the output as JSON formatted lines, which allows further processing with additional tools. This repository also contains the script animate_lock_graph, which provides an animated version of the taken looks.

Usage Examples

# Trace use binary '/home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres' for tracing
pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres

# Trace use binary '/home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres' for tracing and trace pid 1234
pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres -p 1234

# Trace two PIDs
pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres -p 1234 -p 5678

# Be verbose
pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres -p 1234 -v 

# Use the given db connection to access the catalog of PID 1234 to resolve OIDs
pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres -p 1234 -r 1234:psql://jan@localhost/test2

# Output in JSON format
pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres -p 1234 -j

# Print stacktrace on deadlock
pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres -p 1234 -s DEADLOCK

# Print stacktrace for locks and deadlocks
pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres -p 1234 -s LOCK DEADLOCK

# Trace only Transaction and Query related events
pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres -p 1234 -t TRANSACTION QUERY

# Write the output into file 'trace'
pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres -p 1234 -o trace

# Show statistics about locks
pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres -p 1234 --statistics

# Create an animated lock graph (with Oids)
pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres -p 1234 -j -o locks.json
animate_lock_graph -i lock -o locks.html

# Create an animated lock graph (with table names)
pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_15_1_DEBUG/bin/postgres -p 1234 -j -r 1234:psql://jan@localhost/test2 -o locks.json
animate_lock_graph -i lock -o locks.html

Example Output

CLI: pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_14_2_DEBUG/bin/postgres -p 327578 -r 327578:sql://jan@localhost/test2 --statistics

SQL Query: create table metrics(ts timestamptz NOT NULL, id int NOT NULL, value float);

Tracer Output:

745064333930117 [Pid 327578] Query begin 'create table metrics(ts timestamptz NOT NULL, id int NOT NULL, value float);'
745064333965769 [Pid 327578] Transaction begin
745064334157640 [Pid 327578] Table open 3079 (pg_catalog.pg_extension) AccessShareLock
745064334176147 [Pid 327578] Lock object 3079 (pg_catalog.pg_extension) AccessShareLock
745064334204453 [Pid 327578] Lock granted (fastpath) 3079 (pg_catalog.pg_extension) AccessShareLock
745064334224361 [Pid 327578] Lock granted (local) 3079 (pg_catalog.pg_extension) AccessShareLock (Already hold local 0)
745064334243659 [Pid 327578] Lock was acquired in 67512 ns
[...]

Statistics

Lock statistics:
================

Locks per oid
+----------------------------------------------+----------+------------------------------+
|                  Lock Name                   | Requests | Total Lock Request Time (ns) |
+----------------------------------------------+----------+------------------------------+
|     pg_catalog.pg_depend_reference_index     |    20    |           1174663            |
|             pg_catalog.pg_depend             |    8     |            456525            |
|              pg_catalog.pg_type              |    5     |            282986            |
|     pg_catalog.pg_type_typname_nsp_index     |    4     |            229317            |
|         pg_catalog.pg_type_oid_index         |    4     |            300239            |
|             pg_catalog.pg_class              |    3     |            180540            |
|        pg_catalog.pg_class_oid_index         |    3     |            172549            |
|     pg_catalog.pg_depend_depender_index      |    3     |            171186            |
|    pg_catalog.pg_class_relname_nsp_index     |    2     |            114311            |
|           pg_catalog.pg_attribute            |    2     |            113041            |
|  pg_catalog.pg_attribute_relid_attnum_index  |    2     |            113299            |
|                public.metrics                |    2     |            223162            |
| pg_catalog.pg_class_tblspc_relfilenode_index |    1     |            56426             |
|  pg_catalog.pg_attribute_relid_attnam_index  |    1     |            57238             |
|            pg_catalog.pg_shdepend            |    1     |            65878             |
|    pg_catalog.pg_shdepend_reference_index    |    1     |            63127             |
+----------------------------------------------+----------+------------------------------+

Lock types
+---------------------+---------------------------+
|      Lock Type      | Number of requested locks |
+---------------------+---------------------------+
|   AccessShareLock   |             32            |
|   RowExclusiveLock  |             28            |
| AccessExclusiveLock |             2             |
+---------------------+---------------------------+

Filter Trace Events

pg_lock_tracer traces per default all supported events. However, often only certain events are required for the analysis (e.g., which tables are opened?). The event tracing can be restricted to certain events using the -t <EVENT1> <EVENT2> parameter. The following events are currently supported:

pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_14_2_DEBUG/bin/postgres -p 2287921 -r 2287921:psql://jan@localhost/test2 --statistics -t TABLE
[...]
4111321097620311 [Pid 2290711] Table open (by range value) .metric_name_local AccessShareLock
4111321097626817 [Pid 2287921] Table close 343035 (public.metric_name_local) NoLock
4111321097722307 [Pid 2287921] Table open 3079 (pg_catalog.pg_extension) AccessShareLock
4111321097877109 [Pid 2287921] Table close 3079 (pg_catalog.pg_extension) AccessShareLock
4111321097904906 [Pid 2287921] Table open 3079 (pg_catalog.pg_extension) AccessShareLock
4111321098012011 [Pid 2287921] Table close 3079 (pg_catalog.pg_extension) AccessShareLock
4111321098049134 [Pid 2287921] Table open 343035 (public.metric_name_local) NoLock
4111321098072567 [Pid 2287921] Table close 343035 (public.metric_name_local) NoLock
4111321098089922 [Pid 2287921] Table open 343035 (public.metric_name_local) NoLock
4111321098116394 [Pid 2287921] Table close 343035 (public.metric_name_local) NoLock
4111321098350309 [Pid 2287921] Table open 343035 (public.metric_name_local) NoLock
4111321098484761 [Pid 2287921] Table close 343035 (public.metric_name_local) NoLock
4111321098795235 [Pid 2287921] Table open 343035 (public.metric_name_local) NoLock
4111321098931302 [Pid 2287921] Table close 343035 (public.metric_name_local) NoLock

Stack Traces

It is sometimes necessary to determine where in the source code a particular lock is requested. For this purpose, the option -s <Lock Event> can be used. In addition to the traces, stack traces are now also shown.

For example, by specifying -s LOCK a stack trace is generated and shown on each lock event. The following example shows where the lock for pg_catalog.pg_extension was requested.

pg_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_14_2_DEBUG/bin/postgres -p 1051967 -r 1051967:sql://jan@localhost/test2 -s LOCK
[...]
1990162746005798 [Pid 1051967] Lock object 3079 (pg_catalog.pg_extension) AccessShareLock
    LockRelationOid+0x0 [postgres]
    table_open+0x1d [postgres]
    parse_analyze+0xed [postgres]
    pg_analyze_and_rewrite+0x49 [postgres]
    exec_simple_query+0x2db [postgres]
    PostgresMain+0x833 [postgres]
    ExitPostmaster+0x0 [postgres]
    BackendStartup+0x1b1 [postgres]
    ServerLoop+0x2d9 [postgres]
    PostmasterMain+0x1286 [postgres]
    startup_hacks+0x0 [postgres]
    __libc_start_main+0xea [libc-2.31.so]
    [unknown]
[...]

Animated Lock Graphs

See the content of the examples directory for examples.

pg_lw_lock_tracer

pg_lw_lock_trace allows to trace lightweight locks (LWLocks) in a PostgreSQL process via Userland Statically Defined Tracing (USDT).

Usage Examples

# Trace the LW locks of the PID 1234
pg_lw_lock_tracer -p 1234

# Trace the LW locks of the PIDs 1234 and 5678
pg_lw_lock_tracer -p 1234 -p 5678

# Trace the LW locks of the PID 1234 and be verbose
pg_lw_lock_tracer -p 1234 -v

# Trace the LW locks of the PID 1234 and collect statistics
pg_lw_lock_tracer -p 1234 -v --statistics

Example output

SQL Query: insert into test values(2);

CLI: sudo pg_lw_lock_tracer -p 1698108 --statistics

Tracer output:

2904552881615298 [Pid 1704367] Acquired lock LockFastPath (mode LW_EXCLUSIVE) / LWLockAcquire()
2904552881673849 [Pid 1704367] Unlock LockFastPath
2904552881782910 [Pid 1704367] Acquired lock ProcArray (mode LW_SHARED) / LWLockAcquire()
2904552881803614 [Pid 1704367] Unlock ProcArray
2904552881865272 [Pid 1704367] Acquired lock LockFastPath (mode LW_EXCLUSIVE) / LWLockAcquire()
2904552881883641 [Pid 1704367] Unlock LockFastPath
[...]

Statistics

Lock statistics:
================

Locks per tranche
+---------------+----------+--------------------------+------------------------+-------------------------------+-----------------------------+-------+----------------+
|    Tranche    | Acquired | AcquireOrWait (Acquired) | AcquireOrWait (Waited) | ConditionalAcquire (Acquired) | ConditionalAcquire (Failed) | Waits | Wait time (ns) |
+---------------+----------+--------------------------+------------------------+-------------------------------+-----------------------------+-------+----------------+
| BufferContent |    1     |            0             |           0            |               0               |              0              |   0   |       0        |
| BufferMapping |    1     |            0             |           0            |               0               |              0              |   0   |       0        |
|  LockFastPath |    4     |            0             |           0            |               0               |              0              |   0   |       0        |
|  LockManager  |    2     |            0             |           0            |               0               |              0              |   0   |       0        |
|  PgStatsData  |    0     |            0             |           0            |               4               |              0              |   0   |       0        |
|   ProcArray   |    2     |            0             |           0            |               1               |              0              |   0   |       0        |
|   WALInsert   |    2     |            0             |           0            |               0               |              0              |   0   |       0        |
|    WALWrite   |    0     |            1             |           1            |               0               |              0              |   1   |   1518564057   |
|    XactSLRU   |    0     |            0             |           0            |               1               |              0              |   0   |       0        |
|     XidGen    |    1     |            0             |           0            |               0               |              0              |   0   |       0        |
+---------------+----------+--------------------------+------------------------+-------------------------------+-----------------------------+-------+----------------+

Locks per type
+--------------+----------+
|  Lock type   | Requests |
+--------------+----------+
| LW_EXCLUSIVE |    18    |
|  LW_SHARED   |    3     |
+--------------+----------+

pg_row_lock_tracer

pg_row_lock_tracer allows to trace row locks (see the PostgreSQL documentation) of a PostgreSQL process using eBPF and UProbes

Usage Examples

# Trace the row locks of the given PostgreSQL binary
pg_row_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_14_9_DEBUG/bin/postgres

# Trace the row locks of the PID 1234
pg_row_lock_tracer -p 1234 -x /home/jan/postgresql-sandbox/bin/REL_14_9_DEBUG/bin/postgres

# Trace the row locks of the PID 1234 and 5678
pg_row_lock_tracer -p 1234 -p 5678 -x /home/jan/postgresql-sandbox/bin/REL_14_9_DEBUG/bin/postgres

# Trace the row locks of the PID 1234 and be verbose
pg_row_lock_tracer -p 1234 -x /home/jan/postgresql-sandbox/bin/REL_14_9_DEBUG/bin/postgres -v

# Trace the row locks and show statistics
pg_row_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_14_9_DEBUG/bin/postgres --statistics

Example output

SQL Query: SELECT * FROM temperature FOR UPDATE;

CLI: sudo pg_row_lock_tracer -x /home/jan/postgresql-sandbox/bin/REL_14_9_DEBUG/bin/postgres --statistics

Tracer output:

[...]
2783502701862408 [Pid 2604491] LOCK_TUPLE_END TM_OK in 13100 ns
2783502701877081 [Pid 2604491] LOCK_TUPLE (Tablespace 1663 database 305234 relation 313419) - (Block and offset 7 143) - LOCK_TUPLE_EXCLUSIVE LOCK_WAIT_BLOCK
2783502701972367 [Pid 2604491] LOCK_TUPLE_END TM_OK in 95286 ns
2783502701988387 [Pid 2604491] LOCK_TUPLE (Tablespace 1663 database 305234 relation 313419) - (Block and offset 7 144) - LOCK_TUPLE_EXCLUSIVE LOCK_WAIT_BLOCK
2783502702001690 [Pid 2604491] LOCK_TUPLE_END TM_OK in 13303 ns
2783502702016387 [Pid 2604491] LOCK_TUPLE (Tablespace 1663 database 305234 relation 313419) - (Block and offset 7 145) - LOCK_TUPLE_EXCLUSIVE LOCK_WAIT_BLOCK
2783502702029375 [Pid 2604491] LOCK_TUPLE_END TM_OK in 12988 ns
^C
Lock statistics:
================

Used wait policies:
+---------+-----------------+----------------+-----------------+
|   PID   | LOCK_WAIT_BLOCK | LOCK_WAIT_SKIP | LOCK_WAIT_ERROR |
+---------+-----------------+----------------+-----------------+
| 2604491 |       1440      |       0        |        0        |
+---------+-----------------+----------------+-----------------+

Lock modes:
+---------+---------------------+------------------+---------------------------+----------------------+
|   PID   | LOCK_TUPLE_KEYSHARE | LOCK_TUPLE_SHARE | LOCK_TUPLE_NOKEYEXCLUSIVE | LOCK_TUPLE_EXCLUSIVE |
+---------+---------------------+------------------+---------------------------+----------------------+
| 2604491 |          0          |        0         |             0             |         1440         |
+---------+---------------------+------------------+---------------------------+----------------------+

Lock results:
+---------+-------+--------------+-----------------+------------+------------+------------------+---------------+
|   PID   | TM_OK | TM_INVISIBLE | TM_SELFMODIFIED | TM_UPDATED | TM_DELETED | TM_BEINGMODIFIED | TM_WOULDBLOCK |
+---------+-------+--------------+-----------------+------------+------------+------------------+---------------+
| 2604491 |  1440 |      0       |        0        |     0      |     0      |        0         |       0       |
+---------+-------+--------------+-----------------+------------+------------+------------------+---------------+

Additional Information

Installation

The PostgreSQL lock tracing tools are available as a Python package. These tools depend on the Python package for BPF. Unfortunately, this package is currently not available via pip (the Python package manager). Therefore, the package of the Linux distribution needs to be installed to provide this dependency. On Debian and Ubuntu, this can be done by executing the following command:

apt install python3-bpfcc

The tracing tools can be installed system-wide or in a dedicated virtual environment. To create and install the tools in such a virtual environment, the following steps must be performed. To install the tools system-wide, these steps can be skipped.

cd <installation directory>
python3 -m venv .venv
source .venv/bin/activate

# Copy the distribution Python BCC packages into this environment
cp -av /usr/lib/python3/dist-packages/bcc* $(python -c "from distutils.sysconfig import get_python_lib; print(get_python_lib())")

Now, the tracing tools can be installed directly via pip by executing:

pip install pg-lock-tracer

The tools are now installed and can be invoked by calling pg_lock_tracer or pg_lw_lock_tracer.

If you want to install the latest development snapshot and development dependencies of the tools, the following commands need to be executed:

pip install -r requirements_dev.txt
pip install git+https://github.com/jnidzwetzki/pg-lock-tracer

PostgreSQL Build

The software is tested with PostgreSQL versions 12, 13, 14, and 15. In order to be able to attach the uprobes to the functions, they should not to be optimized away (e.g., inlined) during the compilation of PostgreSQL. Otherwise errors like Unable to locate function XXX will occur when pg_lock_tracer is started.

It is recommended to compile PostgreSQL with following CFLAGS: CFLAGS="-ggdb -Og -g3 -fno-omit-frame-pointer".

pg_lw_lock_trace uses USDT probes. Therefore, PostgreSQL has to be compiled with --enable-dtrace to use this script.