Deadlocks in v4

[CharlieC3]

Describe the bug
We're seeing a high amount of deadlocks being caused in Postgres since upgrading to v4.

This is intermittently causing microblock processing errors to occur:

error: deadlock detected
    at Parser.parseErrorMessage (/app/node_modules/pg-protocol/src/parser.ts:369:69)
    at Parser.handlePacket (/app/node_modules/pg-protocol/src/parser.ts:188:21)
    at Parser.parse (/app/node_modules/pg-protocol/src/parser.ts:103:30)
    at Socket.<anonymous> (/app/node_modules/pg-protocol/src/index.ts:7:48)
    at Socket.emit (node:events:527:28)
    at addChunk (node:internal/streams/readable:315:12)
    at readableAddChunk (node:internal/streams/readable:289:9)
    at Socket.Readable.push (node:internal/streams/readable:228:10)
    at TCP.onStreamRead (node:internal/stream_base_commons:190:23) 

 
--
Process 1774416 waits for AccessExclusiveLock on relation 1035814 of database 16384; blocked by process 1774556. Process 1774556 waits for AccessShareLock on relation 1035792 of database 16384; blocked by process 1774416.

and increasing response times during a deadlock.

[CharlieC3]

@rafaelcr @zone117x
Here are some logs I found from the PG DB which may help:

2022-06-14 17:45:33.026 GMT [2577263] ERROR:  deadlock detected at character 36
2022-06-14 17:45:33.026 GMT [2577263] DETAIL:  Process 2577263 waits for AccessShareLock on relation 1035784 of database 16384; blocked by process 2576913.
	Process 2576913 waits for AccessExclusiveLock on relation 1035814 of database 16384; blocked by process 2577263.
	Process 2577263:
	        SELECT value
	        FROM nft_custody
	        WHERE recipient <> $1 AND value = ANY($2)

	Process 2576913: REFRESH MATERIALIZED VIEW chain_tip
2022-06-14 17:45:33.026 GMT [2577263] HINT:  See server log for query details.
2022-06-14 17:45:33.026 GMT [2577263] STATEMENT:
	        SELECT value
	        FROM nft_custody
	        WHERE recipient <> $1 AND value = ANY($2)

2022-06-14 17:45:33.036 GMT [2577413] ERROR:  deadlock detected at character 36
2022-06-14 17:45:33.036 GMT [2577413] DETAIL:  Process 2577413 waits for AccessShareLock on relation 1035784 of database 16384; blocked by process 2576913.
	Process 2576913 waits for AccessExclusiveLock on relation 1035814 of database 16384; blocked by process 2577413.
	Process 2577413:
	        SELECT value
	        FROM nft_custody
	        WHERE recipient <> $1 AND value = ANY($2)

	Process 2576913: REFRESH MATERIALIZED VIEW chain_tip
2022-06-14 17:45:33.036 GMT [2577413] HINT:  See server log for query details.
2022-06-14 17:45:33.036 GMT [2577413] STATEMENT:
	        SELECT value
	        FROM nft_custody
	        WHERE recipient <> $1 AND value = ANY($2)

PGHero also shows a large amount of time being spent on this query. Not sure if it's related to the deadlocks though.

WITH stx_txs AS (
          SELECT tx_id, index_block_hash, microblock_hash, (COUNT(*) OVER())::INTEGER AS count
          FROM principal_stx_txs
          WHERE principal = $1 AND block_height <= $4
          AND canonical = $5 AND microblock_canonical = $6
          ORDER BY block_height DESC, microblock_sequence DESC, tx_index DESC
          LIMIT $2
          OFFSET $3
        )
        SELECT txs.tx_id,txs.raw_tx,txs.tx_index,txs.index_block_hash,txs.parent_index_block_hash,txs.block_hash,txs.parent_block_hash,txs.block_height,txs.burn_block_time,txs.parent_burn_block_time,txs.type_id,txs.anchor_mode,txs.status,txs.canonical,txs.post_conditions,txs.nonce,txs.fee_rate,txs.sponsored,txs.sponsor_address,txs.sponsor_nonce,txs.sender_address,txs.origin_hash_mode,txs.microblock_canonical,txs.microblock_sequence,txs.microblock_hash,txs.token_transfer_recipient_address,txs.token_transfer_amount,txs.token_transfer_memo,txs.smart_contract_contract_id,txs.smart_contract_source_code,txs.contract_call_contract_id,txs.contract_call_function_name,txs.contract_call_function_args,txs.poison_microblock_header_1,txs.poison_microblock_header_2,txs.coinbase_payload,txs.raw_result,txs.event_count,txs.execution_cost_read_count,txs.execution_cost_read_length,txs.execution_cost_runtime,txs.execution_cost_write_count,txs.execution_cost_write_length, 
    CASE WHEN txs.type_id = $7 THEN (
      SELECT abi
      FROM smart_contracts
      WHERE smart_contracts.contract_id = txs.contract_call_contract_id
      ORDER BY abi != $8 DESC, canonical DESC, microblock_canonical DESC, block_height DESC
      LIMIT $9
    ) END as abi
    , count
        FROM stx_txs
        INNER JOIN txs USING (tx_id, index_block_hash, microblock_hash)

[rafaelcr]

Interesting, thanks @CharlieC3 ... I'll check if that nft_custody is missing an index.
The stx_txs query's performance is normal (that's the heaviest query we have).

[CharlieC3]

@rafaelcr The PR index, implemented in one of our environments, did not seem to reduce the deadlocks. In fact, by happenstance I came across the deadlock issue when hitting our API:

I saw this when hitting /v1/names/dylan.btc in the environment with the PR's index.

[rafaelcr]

@CharlieC3 does PgHero give you data for this deadlock? I'm curious to see if it's from the same query

[zone117x]

Can we see how much time pg replications are taking? Those are configured to synchronous mode right? I'm curious if the additional writes performed with the mempool state hash updates are causing a lot of time spent in replication.

[CharlieC3]

@rafaelcr PGHero doesn't expose information on deadlocks unfortunately. However, the Postgres logs are pretty informative:

2022-06-16 13:38:15.186 GMT [926] ERROR:  deadlock detected at character 44
2022-06-16 13:38:15.186 GMT [926] DETAIL:  Process 926 waits for AccessShareLock on relation 1035784 of database 16384; blocked by process 102.
	Process 102 waits for AccessExclusiveLock on relation 1035814 of database 16384; blocked by process 926.
	Process 926:
	          SELECT recipient
	          FROM nft_custody
	          WHERE asset_identifier = $1 AND value = $2

	Process 102: <backend information not available>
2022-06-16 13:38:15.186 GMT [926] HINT:  See server log for query details.
2022-06-16 13:38:15.186 GMT [926] STATEMENT:
	          SELECT recipient
	          FROM nft_custody
	          WHERE asset_identifier = $1 AND value = $2

@zone117x The replication lag metrics can be found in Grafana. Will send you a link separately.

Also, see here for info on synchronous commit modes. The synchronous commit mode we use is on. There is one additional level above that which may help at the cost of lower performance.

However, I still think it would be useful to fully understand the root cause of these deadlocks and determine if it can be fixed in the API. Prior to v4, there were never any deadlocks, so it's possible this is a regression in the API.

[rafaelcr]

Thanks @CharlieC3 , I think we're moving in the right direction because that is a different query causing the deadlock... I'll run the analyzer there and check if we can optimize further

[rafaelcr]

I looked into the query @CharlieC3 but couldn't find any missing indexes 🤔
I believe @zone117x 's theory about synchronous commit mode is making more sense here

[zone117x]

Reading more into pg replica configurations -- I think this is most likely the cause.

This behavior also seems somewhat intended due to the read/write and pub/sub model we're using:

Due to a PG limitation, we direct PG LISTEN queries to the write instance, then once a notification is received, it's queried from a PG read instance. This means we had to configure the replica in a blocking mode where the read instance will be locked until any outstanding write+replication processes are completed. If we switched to a different mode that did not perform this locking, then we'd have situations where the write instance sends an update notification but when we query the read instance queried has stale data.

As an example, if a subscriber is listening for a txid, the write instance could send a "tx_status = mined" to a readonly API instance, then when it queries the read pg instance, we could end up with stale data for the tx (e.g. still in the mempool) and send that to the client -- because the write instance's db updates haven't been synced to the read instances.

I'm not sure there's an easy solution for this. If I'm correct, then we could fix the locks by switching to a different replication config, but then we'd break many web socket notification payloads. The real crux of the issue is that PG has a limitation where we can't perform LISTEN queries on a read instance (a known, very old pg bug). Perhaps we could investigate switching from LISTEN/NOTIFY to "real time notifications" like https://github.com/porsager/postgres#realtime-subscribe

Or, we could look into other pg replication configurations that avoided this limitation https://www.postgresql.org/docs/current/different-replication-solutions.html -- not sure if any of these would work.