Get best of the week

DBA: dalam mengejar kunci terbang

Dalam artikel sebelumnya, di mana saya berbicara tentang pemantauan database PostgreSQL , ada ungkapan seperti itu:
Grow wait- aplikasi telah "beristirahat" di kunci seseorang . Jika ini adalah anomali satu kali yang lalu - suatu kesempatan untuk memahami alasan aslinya.
Situasi ini adalah salah satu yang paling tidak menyenangkan untuk DBA:

  • pada pandangan pertama, pangkalan berfungsi
  • tidak ada sumber daya server yang habis
  • ... tetapi beberapa permintaan "melambat"

Kemungkinan menangkap kunci "saat ini" sangat kecil, dan mereka hanya dapat bertahan beberapa detik, tetapi memperburuk waktu eksekusi yang direncanakan dari permintaan tersebut puluhan kali. Tetapi Anda hanya tidak ingin duduk dan menangkap apa yang sedang terjadi secara online, tetapi dalam lingkungan yang tenang untuk mencari tahu fakta dari pengembang mana yang menghukum apa sebenarnya masalahnya - siapa, dengan siapa dan karena sumber daya mana dari basis data itu mengalami konflik.

Tapi bagaimana caranya? Memang, tidak seperti permintaan dengan rencananya, yang memungkinkan Anda untuk memahami secara terperinci apa yang terjadi dengan sumber daya dan berapa lama, kuncinya tidak meninggalkan jejak yang jelas ...

Kecuali entri log pendek: Tapi mari kita coba menangkapnya!
process ... still waiting for ...


Kami menangkap kunci dalam log


Tetapi bahkan untuk setidaknya baris ini muncul di log, server harus dikonfigurasi dengan benar:
log_lock_waits = 'on'
... dan menetapkan batas minimum untuk analisis kami:
deadlock_timeout = '100ms'

Ketika parameter diaktifkan log_lock_waits, parameter ini juga menentukan setelah waktu berapa pesan tentang menunggu pemblokiran akan ditulis ke log server. Jika Anda mencoba menyelidiki penundaan yang disebabkan oleh kunci, masuk akal untuk menguranginya dibandingkan dengan nilai biasanya deadlock_timeout.
Semua kebuntuan yang tidak punya waktu untuk "melepaskan" selama waktu ini akan robek. Dan di sini adalah kunci "biasa" - dibuang ke log oleh beberapa entri:
2019-03-27 00:06:46.026 MSK [38162:84/166010018] [inside.tensor.ru] [local] csr-inside-bl10:10081: MergeRequest LOG: process 38162 still waiting for ExclusiveLock on advisory lock [225382138,225386226,141586103,2] after 100.047 ms

2019-03-27 00:06:46.026 MSK [38162:84/166010018] [inside.tensor.ru] [local] csr-inside-bl10:10081: MergeRequest DETAIL: Process holding the lock: 38154. Wait queue: 38162.

2019-03-27 00:06:46.026 MSK [38162:84/166010018] [inside.tensor.ru] [local] csr-inside-bl10:10081: MergeRequest CONTEXT: SQL statement "SELECT pg_advisory_xact_lock( '""'::regclass::oid::integer, 141586103::integer )"
PL/pgSQL function inline_code_block line 2 at PERFORM

2019-03-27 00:06:46.026 MSK [38162:84/166010018] [inside.tensor.ru] [local] csr-inside-bl10:10081: MergeRequest STATEMENT: DO $$ BEGIN
PERFORM pg_advisory_xact_lock( '""'::regclass::oid::integer, 141586103::integer );
EXCEPTION
WHEN query_canceled THEN RETURN;
END; $$;
…

2019-03-27 00:06:46.077 MSK [38162:84/166010018] [inside.tensor.ru] [local] csr-inside-bl10:10081: MergeRequest LOG: process 38162 acquired ExclusiveLock on advisory lock [225382138,225386226,141586103,2] after 150.741 ms
Contoh ini menunjukkan bahwa kita hanya memiliki 50 ms dari saat kunci muncul di log hingga saat resolusi. Hanya dalam interval ini kita dapat memperoleh setidaknya beberapa informasi tentangnya, dan semakin cepat kita dapat melakukan ini, semakin banyak kunci yang dapat kita analisis.

Di sini informasi paling penting bagi kami adalah PID dari proses yang menunggu kunci. Di atasnya kita dapat membandingkan informasi antara log dan keadaan database. Dan pada saat yang sama untuk mengetahui seberapa bermasalah kunci tertentu - yaitu, berapa lama "tergantung".

Untuk melakukan ini, kita hanya perlu beberapa RegExp pada LOGcatatan konten :

const RE_lock_detect = /^process (\d+) still waiting for (.*) on (.*) after (\d+\.\d{3}) ms(?: at character \d+)?$/; //    
const RE_lock_acquire = /^process (\d+) acquired (.*) on (.*) after (\d+\.\d{3}) ms(?: at character \d+)?$/; //

Kita sampai ke log


Sebenarnya, ini tetap sedikit - untuk mengambil log, belajar bagaimana memonitor dan meresponsnya.

Kami sudah memiliki segalanya untuk ini - parser log online dan koneksi basis data yang sudah diaktifkan, yang saya bicarakan dalam sebuah artikel tentang sistem pemantauan PostgreSQL kami :


Tetapi jika Anda tidak memiliki sistem serupa yang digunakan, maka tidak apa-apa, kami akan melakukan semuanya “Langsung dari konsol”!

Jika versi PostgreSQL 10 yang diinstal dan yang lebih tinggi beruntung, karena muncul fungsi pg_current_logfile () , yang secara eksplisit memberikan nama file log saat ini. Mendapatkannya dari konsol akan cukup mudah:

psql -U postgres postgres -t -A -c "SELECT CASE WHEN substr(current_setting('log_directory'), 1, 1) <> '/' THEN current_setting('data_directory') ELSE '' END || '/' || pg_current_logfile()"

Jika versi ini tiba-tiba lebih muda - semuanya akan berubah, tetapi sedikit lebih rumit:

ps uw -U postgres \
  | grep [l]ogger \
  | awk '{print "/proc/"$2"/fd"}' \
  | xargs ls -l \
  | grep `cd; psql -U postgres postgres -t -A -c "SELECT CASE WHEN substr(current_setting('log_directory'), 1, 1) = '/' THEN current_setting('log_directory') ELSE current_setting('data_directory') || '/' || current_setting('log_directory') END"` \
  | awk '{print $NF}'

Kami tail -fmendapatkan nama file lengkap, yang kami berikan dan akan menangkap penampilan di sana 'still waiting for'.

Nah, begitu sesuatu muncul di utas ini, kami menyebutnya ...

Permintaan Parsing


Sayangnya, objek pemblokiran dalam log bukan berarti selalu sumber daya yang menyebabkan konflik. Misalnya, jika Anda mencoba membuat indeks dengan nama yang sama secara paralel, hanya akan ada sesuatu seperti itu di log still waiting for ExclusiveLock on transaction 12345.

Karena itu, kami harus menghapus status semua kunci dari basis data untuk proses yang menarik bagi kami. Dan informasi hanya tentang sepasang proses (yang memasang kunci / siapa yang mengharapkannya) tidak cukup, karena sering kali ada "rantai" harapan dari sumber daya yang berbeda antara transaksi:

tx1 [resA] -> tx2 [resA]
tx2 [resB] -> tx3 [resB]
...

Klasik: "Kakek untuk lobak, nenek untuk kakek, cucu untuk nenek, ..."

Oleh karena itu, kami akan menulis permintaan yang akan memberi tahu kami dengan tepat siapa yang menjadi akar penyebab masalah di sepanjang seluruh rantai kunci untuk PID tertentu:

WITH RECURSIVE lm AS (
-- lock modes
  SELECT
    rn
  , CASE
      WHEN lm <> 'Share' THEN row_number() OVER(PARTITION BY lm <> 'Share' ORDER BY rn)
    END rx
  , lm || 'Lock' lm
  FROM (
    SELECT
      row_number() OVER() rn
    , lm
    FROM
      unnest(
        ARRAY[
          'AccessShare'
        , 'RowShare'
        , 'RowExclusive'
        , 'ShareUpdateExclusive'
        , 'Share'
        , 'ShareRowExclusive'
        , 'Exclusive'
        , 'AccessExclusive'
        ]
      ) T(lm)
  ) T
)
-- lock types
, lt AS (
  SELECT
    row_number() OVER() rn
  , lt
  FROM
    unnest(
      ARRAY[
        'relation'
      , 'extend'
      , 'page'
      , 'tuple'
      , 'transactionid'
      , 'virtualxid'
      , 'object'
      , 'userlock'
      , 'advisory'
      , ''
      ]
    ) T(lt)
)
-- lock modes conflicts
, lmx AS (
  SELECT
    lr.rn lrn
  , lr.rx lrx
  , lr.lm lr
  , ld.rn ldn
  , ld.rx ldx
  , ld.lm ld
  FROM
    lm lr
  JOIN
    lm ld ON
      ld.rx > (SELECT max(rx) FROM lm) - lr.rx OR
      (
        (lr.rx = ld.rx) IS NULL AND
        (lr.rx, ld.rx) IS DISTINCT FROM (NULL, NULL) AND
        ld.rn >= (SELECT max(rn) FROM lm) - lr.rn
      )
)
-- locked targets/pids
, lcx AS (
  SELECT DISTINCT
    (lr.locktype, lr.database, lr.relation, lr.page, lr.tuple, lr.virtualxid, lr.transactionid::text::bigint, lr.classid, lr.objid, lr.objsubid) target
  , ld.pid  ldp
  , ld.mode ldm
  , lr.pid  lrp
  , lr.mode lrm
  FROM
    pg_locks ld
  JOIN
    pg_locks lr ON
      lr.pid <> ld.pid AND
      (lr.locktype, lr.database, lr.relation, lr.page, lr.tuple, lr.virtualxid, lr.transactionid::text::bigint, lr.classid, lr.objid, lr.objsubid) IS NOT DISTINCT FROM (ld.locktype, ld.database, ld.relation, ld.page, ld.tuple, ld.virtualxid, ld.transactionid::text::bigint, ld.classid, ld.objid, ld.objsubid) AND
      (lr.granted, ld.granted) = (TRUE, FALSE)
  JOIN
    lmx ON
      (lmx.lr, lmx.ld) = (lr.mode, ld.mode)
  WHERE
    (ld.pid, ld.granted) = ($1::integer, FALSE) -- PID
)
SELECT
  lc.locktype "type"
, CASE lc.locktype
    WHEN 'relation'      THEN ARRAY[relation::text]
    WHEN 'extend'        THEN ARRAY[relation::text]
    WHEN 'page'          THEN ARRAY[relation, page]::text[]
    WHEN 'tuple'         THEN ARRAY[relation, page, tuple]::text[]
    WHEN 'transactionid' THEN ARRAY[transactionid::text]
    WHEN 'virtualxid'    THEN regexp_split_to_array(virtualxid::text, '/')
    WHEN 'object'        THEN ARRAY[classid, objid, objsubid]::text[]
    WHEN 'userlock'      THEN ARRAY[classid::text]
    WHEN 'advisory'      THEN ARRAY[classid, objid, objsubid]::text[]
  END target
, lc.pid = lcx.ldp "locked"
, lc.pid
, regexp_replace(lc.mode, 'Lock$', '') "mode"
, lc.granted
, (lc.locktype, lc.database, lc.relation, lc.page, lc.tuple, lc.virtualxid, lc.transactionid::text::bigint, lc.classid, lc.objid, lc.objsubid) IS NOT DISTINCT FROM lcx.target "conflict"
FROM
  lcx
JOIN
  pg_locks lc ON
    lc.pid IN (lcx.ldp, lcx.lrp);

Masalah # 1 - Mulai Lambat


Seperti yang dapat Anda lihat pada contoh dari log, di sebelah baris yang memberi tanda terjadinya kunci ( LOG), ada 3 baris lagi ( DETAIL, CONTEXT, STATEMENT) yang melaporkan informasi tambahan.

Pertama, kami menunggu pembentukan "paket" lengkap dari semua 4 entri dan hanya setelah itu kami beralih ke database. Tetapi kita dapat menyelesaikan pembentukan paket hanya ketika Rekaman berikutnya (sudah ke-5!) Tiba, dengan rincian proses lain, atau dengan batas waktu. Jelas bahwa kedua opsi memancing menunggu yang tidak perlu.

Untuk menghilangkan penundaan ini, kami beralih ke aliran memproses catatan kunci. Yaitu, sekarang kita beralih ke database target segera setelah kami mengurutkan catatan pertama, dan menyadari bahwa itu adalah kunci yang dijelaskan di sana.

Masalah # 2 - permintaan lambat


Tapi tetap saja, beberapa kunci tidak punya waktu untuk dianalisis. Mereka mulai menggali lebih dalam - dan menemukan bahwa di beberapa server permintaan analisis kami dijalankan selama 15-20 ms !

Alasannya ternyata biasa - jumlah kunci aktif di pangkalan, mencapai beberapa ribu:



pg_locks


Di sini harus dicatat bahwa kunci di PostgreSQL tidak "disimpan" di mana saja, tetapi disajikan hanya dalam tampilan sistem pg_locks , yang merupakan refleksi langsung dari fungsi tersebut pg_lock_status. Dan dalam permintaan kami, kami membacanya tiga kali ! Sementara itu, kami membaca ribuan contoh kunci ini, dan membuang yang tidak terkait dengan PID kami, kunci itu sendiri berhasil "menyelesaikan" ...

Solusinya adalah "mematerialisasikan" keadaan pg_locks di CTE - setelah itu Anda dapat menjalankannya sebanyak yang Anda inginkan, itu sudah tidak berubah. Selain itu, setelah duduk di algoritma, adalah mungkin untuk mengurangi semuanya menjadi hanya dua pemindaiannya.

Dinamika Berlebihan


Dan bahkan jika sedikit melihat lebih dekat pada query di atas, kita dapat melihat bahwa CTE lmdan lmxtidak dengan cara apa pun terkait dengan data, tetapi hanya menghitung selalu definisi "statis" matriks yang sama dari konflik antara mode pemblokiran . Jadi mari kita atur sebagai kualitas VALUES.

Masalah # 3 - tetangga


Tetapi sebagian dari kunci masih dilewati. Biasanya ini terjadi sesuai dengan skema berikut - seseorang memblokir sumber daya populer, dan beberapa proses dengan cepat dan cepat berlari ke dalamnya atau sepanjang rantai lebih lanjut .

Akibatnya, kami menangkap PID pertama, pergi ke basis target (dan agar tidak membebani itu, kami hanya menyimpan satu koneksi), apakah analisis, kembali dengan hasilnya, mengambil PID berikutnya ... Tapi hidup tidak sepadan di pangkalan, dan PID mengunci # 2 sudah hilang!

Sebenarnya, mengapa kita perlu membuka database untuk setiap PID secara terpisah, jika kita masih memfilter kunci dari daftar umum dalam permintaan? Mari kita segera mengambil seluruh daftar proses yang saling bertentangan langsung dari database dan mendistribusikan kunci mereka di semua PID yang jatuh selama pelaksanaan permintaan:

WITH lm(ld, lr) AS (
  VALUES
    ('AccessShareLock', '{AccessExclusiveLock}'::text[])
  , ('RowShareLock', '{ExclusiveLock,AccessExclusiveLock}'::text[])
  , ('RowExclusiveLock', '{ShareLock,ShareRowExclusiveLock,ExclusiveLock,AccessExclusiveLock}'::text[])
  , ('ShareUpdateExclusiveLock', '{ShareUpdateExclusiveLock,ShareLock,ShareRowExclusiveLock,ExclusiveLock,AccessExclusiveLock}'::text[])
  , ('ShareLock', '{RowExclusiveLock,ShareUpdateExclusiveLock,ShareRowExclusiveLock,ExclusiveLock,AccessExclusiveLock}'::text[])
  , ('ShareRowExclusiveLock', '{RowExclusiveLock,ShareUpdateExclusiveLock,ShareLock,ShareRowExclusiveLock,ExclusiveLock,AccessExclusiveLock}'::text[])
  , ('ExclusiveLock', '{RowShareLock,RowExclusiveLock,ShareUpdateExclusiveLock,ShareLock,ShareRowExclusiveLock,ExclusiveLock,AccessExclusiveLock}'::text[])
  , ('AccessExclusiveLock', '{AccessShareLock,RowShareLock,RowExclusiveLock,ShareUpdateExclusiveLock,ShareLock,ShareRowExclusiveLock,ExclusiveLock,AccessExclusiveLock}'::text[])
)
, locks AS (
  SELECT
    (
      locktype
    , database
    , relation
    , page
    , tuple
    , virtualxid
    , transactionid::text::bigint
    , classid
    , objid
    , objsubid
    ) target
  , *
  FROM
    pg_locks
)
, ld AS (
  SELECT
    *
  FROM
    locks
  WHERE
    NOT granted
)
, lr AS (
  SELECT
    *
  FROM
    locks
  WHERE
    target::text = ANY(ARRAY(
      SELECT DISTINCT
        target::text
      FROM
        ld
    )) AND
    granted
)
, lcx AS (
  SELECT DISTINCT
    lr.target
  , ld.pid ldp
  , ld.mode ldm
  , lr.pid lrp
  , lr.mode lrm
  FROM
    ld
  JOIN
    lr
      ON lr.pid <> ld.pid AND
        lr.target IS NOT DISTINCT FROM ld.target
)
SELECT
  lc.locktype "type"
, CASE lc.locktype
    WHEN 'relation' THEN
      ARRAY[relation::text]
    WHEN 'extend' THEN
      ARRAY[relation::text]
    WHEN 'page' THEN
      ARRAY[relation, page]::text[]
    WHEN 'tuple' THEN
      ARRAY[relation, page, tuple]::text[]
    WHEN 'transactionid' THEN
      ARRAY[transactionid::text]
    WHEN 'virtualxid' THEN
      regexp_split_to_array(virtualxid::text, '/')
    WHEN 'object' THEN
      ARRAY[classid, objid, objsubid]::text[]
    WHEN 'userlock' THEN
      ARRAY[classid::text]
    WHEN 'advisory' THEN
      ARRAY[classid, objid, objsubid]::text[]
  END target
, lc.pid = lcx.ldp as locked
, lc.pid
, regexp_replace(lc.mode, 'Lock$', '') "mode"
, lc.granted
, lc.target IS NOT DISTINCT FROM lcx.target as conflict
FROM
  lcx
JOIN
  locks lc
    ON lc.pid IN (lcx.ldp, lcx.lrp);

Sekarang kita punya waktu untuk menganalisis bahkan kunci yang ada hanya 1-2 ms setelah masuk ke log.

Analisa ini


Sebenarnya, mengapa kami mencoba begitu lama? Apa yang ini memberi kita sebagai hasilnya? ..

type     | target                  | locked | pid    | mode        | granted | conflict
---------------------------------------------------------------------------------------
relation | {225388639}             | f      | 216547 | AccessShare | t       | f
relation | {423576026}             | f      | 216547 | AccessShare | t       | f
advisory | {225386226,194303167,2} | t      |  24964 | Exclusive   | f       | t
relation | {341894815}             | t      |  24964 | AccessShare | t       | f
relation | {416441672}             | f      | 216547 | AccessShare | t       | f
relation | {225964322}             | f      | 216547 | AccessShare | t       | f
...

Dalam lempeng ini, nilai targetdengan tipe berguna bagi kami relation, karena setiap nilai tersebut adalah OID dari tabel atau indeks . Sekarang hanya ada sedikit yang tersisa - untuk belajar menginterogasi database OID yang masih belum diketahui oleh kami, untuk menerjemahkannya ke dalam bentuk yang dapat dibaca manusia:

SELECT $1::oid::regclass;

Sekarang, mengetahui "matriks" penuh dari kunci dan semua objek di mana mereka ditumpangkan oleh masing-masing transaksi, kita dapat menyimpulkan "apa yang terjadi sama sekali" dan sumber daya apa yang menyebabkan konflik, bahkan jika permintaan diblokir, kita tidak tahu. Ini dapat dengan mudah terjadi, misalnya, ketika waktu eksekusi permintaan pemblokiran tidak cukup lama untuk sampai ke log, tetapi transaksi aktif setelah selesai dan menciptakan masalah untuk waktu yang lama.



Tetapi tentang ini - di artikel lain.

"Semua dengan sendirinya"


Sementara itu, kami akan mengumpulkan versi lengkap "pemantauan", yang secara otomatis akan menghapus status kunci untuk arsip kami segera setelah sesuatu yang mencurigakan muncul di log:

ps uw -U postgres \
  | grep [l]ogger \
  | awk '{print "/proc/"$2"/fd"}' \
  | xargs ls -l \
  | grep `cd; psql -U postgres postgres -t -A -c "SELECT CASE WHEN substr(current_setting('log_directory'), 1, 1) = '/' THEN current_setting('log_directory') ELSE current_setting('data_directory') || '/' || current_setting('log_directory') END"` \
  | awk '{print $NF}' \
  | xargs -l -I{} tail -f {} \
  | stdbuf -o0 grep 'still waiting for' \
  | xargs -l -I{} date '+%Y%m%d-%H%M%S.%N' \
  | xargs -l -I{} psql -U postgres postgres -f detect-lock.sql -o {}-lock.log

Dan selanjutnya untuk detect-lock.sqlmenempatkan permintaan terakhir. Jalankan - dan dapatkan banyak file dengan konten yang diinginkan di dalamnya:

# cat 20200526-181433.331839375-lock.log
     type      |     target     | locked |  pid   |     mode     | granted | conflict
---------------+----------------+--------+--------+--------------+---------+----------
 relation      | {279588430}    | t      | 136325 | RowExclusive | t       | f
 relation      | {279588422}    | t      | 136325 | RowExclusive | t       | f
 relation      | {17157}        | t      | 136325 | RowExclusive | t       | f
 virtualxid    | {110,12171420} | t      | 136325 | Exclusive    | t       | f
 relation      | {279588430}    | f      |  39339 | RowExclusive | t       | f
 relation      | {279588422}    | f      |  39339 | RowExclusive | t       | f
 relation      | {17157}        | f      |  39339 | RowExclusive | t       | f
 virtualxid    | {360,11744113} | f      |  39339 | Exclusive    | t       | f
 virtualxid    | {638,4806358}  | t      |  80553 | Exclusive    | t       | f
 advisory      | {1,1,2}        | t      |  80553 | Exclusive    | f       | t
 advisory      | {1,1,2}        | f      |  80258 | Exclusive    | t       | t
 transactionid | {3852607686}   | t      | 136325 | Exclusive    | t       | f
 extend        | {279588422}    | t      | 136325 | Exclusive    | f       | t
 extend        | {279588422}    | f      |  39339 | Exclusive    | t       | t
 transactionid | {3852607712}   | f      |  39339 | Exclusive    | t       | f
(15 rows)

Nah, lalu - duduk dan menganalisis ...

More articles:


All Articles