search

cardano-community / guild-operators

Artifacts and scripts created by Guild operators
https://cardano-community.github.io/guild-operators
MIT License
354 stars 178 forks source link

SELECT GREST.STAKE_DISTRIBUTION_CACHE_UPDATE_CHECK(); taking hours on testnet instances #1332

Closed pyromaniac3010 closed 2 years ago

pyromaniac3010 commented 2 years ago

Describe the bug We are monitoring the haproxys from our grest-instances via zabbix and getting constantly errors for the grest local backend on our testnet instances. I get a lot of "Stake Distribution cache too far from tip !!" timeouts in haproxy for the local grest backend on my testnet instances. After checking postgresql I see that there is a running query "SELECT GREST.STAKE_DISTRIBUTION_CACHE_UPDATE_CHECK(); " which is running for a very long time:

SELECT pid, age(clock_timestamp(), query_start), usename, query
FROM pg_stat_activity
WHERE query != '<IDLE>' AND query NOT ILIKE '%pg_stat_activity%'
ORDER BY query_start desc;
  pid  |       age       | usename  |                                        query
-------+-----------------+----------+-------------------------------------------------------------------------------------
 27662 | 02:18:49.286034 | cardano  | SELECT GREST.STAKE_DISTRIBUTION_CACHE_UPDATE_CHECK();
  1490 | 02:41:39.990768 | cardano  | LISTEN "pgrst"

All instances were setup and optimized according to the docs (including postgres optimizations) and I used alpha branch, becaus master branch does not work for grest. I was using AWS r5a.xlarge for testnet and r5a.2xlarge for mainnet. I did not experience these problems with mainnet yet. Only my testnet instances report the local haproxy backends going down. I switched to t3a.2xlarge for one testnet instance but still get these long running querys and the local haproxy backend goes down.

To Reproduce Steps to reproduce the behavior:

  1. setup grest with testnet

Expected behavior It should not take many hours on testnet.

Screenshots If applicable, add screenshots to help explain your problem.

Version:

Additional context

dostrelith678 commented 2 years ago

One more thing to check for useful info here are logs under CNODE_HOME/logs/stake-distribution-update.log

pyromaniac3010 commented 2 years ago

@DamjanOstrelic Here the stake-distribution-update.log from one testnet grest setup: stake-distribution-update.log

dostrelith678 commented 2 years ago

Looks like it's taking ~5 hours to complete the query. I can confirm same happening on my testnet instance. The grest-poll.sh that haproxy runs has a check for 1000 blocks up to tip for stake distribution cache on alpha. So I think you were only getting Stake Distribution cache too far from tip !! message at the start of the logs, as from the logs I see around 600 blocks lag on each new run (after previous has finished), e.g. NOTICE: Last stake distribution update was 552 blocks ago...

But it doesn't make sense for this to take 5 hours on testnet. @rdlrt @Scitz0 @hodlonaut Can you check your instances related to this cache query?

hodlonaut commented 2 years ago

Everything looking okay on my testnet instance, the ' Last stake distribution update was ' message gets up to about 250 blocks max before the catch-up is done. As far as initial population of the stake cache table, my testnet instance did it in about 30 seconds:

2022-01-02_12:30:01 Running stake distribution update... NOTICE: Last stake distribution update was 3203832 blocks ago... NOTICE: Re-running... NOTICE: table "accounts_with_delegated_pools" does not exist, skipping NOTICE: table "pool_ids" does not exist, skipping NOTICE: table "account_total_utxo" does not exist, skipping NOTICE: table "account_total_rewards" does not exist, skipping NOTICE: table "account_total_withdrawals" does not exist, skipping NOTICE: table "account_last_withdrawal" does not exist, skipping NOTICE: table "account_total_reserves" does not exist, skipping NOTICE: table "account_total_treasury" does not exist, skipping NOTICE: relation "idx_stake_address_id" already exists, skipping NOTICE: relation "idx_stake_address_id" already exists, skipping NOTICE: relation "idx_stake_address_id" already exists, skipping NOTICE: relation "idx_stake_address_id" already exists, skipping NOTICE: relation "idx_stake_address_id" already exists, skipping NOTICE: relation "idx_stake_address_id" already exists, skipping NOTICE: relation "idx_stake_address_id" already exists, skipping 2022-01-02_12:30:32 Job done!

Worth noting the multiple 'NOTICE: relation "idx_stake_address_id" already exists, skipping' messages in my log, and just one of those in the pyromaniac3010's logs, maybe that's a clue of some kind.

Scitz0 commented 2 years ago

Same here, nothing strange in logs. Takes ~9s to complete on testnet. The notices are expected due to temp table and index usage.

dostrelith678 commented 2 years ago

I ran setup-grest.sh -r -q to reset everything. It is still taking the same time, around 5 hours.

I am on Postgres 14.

dostrelith678 commented 2 years ago

@pyromaniac3010 can you run the following and post the output file please?

psql cexplorer -c "explain analyze CREATE TEMP TABLE account_total_utxo AS ( SELECT accounts_with_delegated_pools.stake_address_id, COALESCE(SUM(TX_OUT.VALUE), 0) AS UTXO FROM tx_out INNER JOIN accounts_with_delegated_pools on tx_out.stake_address_id = accounts_with_delegated_pools.stake_address_id INNER JOIN TX ON TX.ID = TX_OUT.TX_ID LEFT JOIN TX_IN ON TX_OUT.TX_ID = TX_IN.TX_OUT_ID AND TX_OUT.INDEX::smallint = TX_IN.TX_OUT_INDEX::smallint WHERE TX.BLOCK_ID <= 3329407 AND TX_IN.TX_IN_ID IS NULL GROUP BY accounts_with_delegated_pools.stake_address_id, accounts_with_delegated_pools.stake_address )" > out.log

It's the part of the query that is the pain point on my instance, manual run of this took 10 hours for some reason.

pyromaniac3010 commented 2 years ago

@DamjanOstrelic Here the requested output: ` $ psql cexplorer -c "explain analyze CREATE TEMP TABLE account_total_utxo AS ( SELECT accounts_with_delegated_pools.stake_address_id, COALESCE(SUM(TX_OUT.VALUE), 0) AS UTXO FROM tx_out INNER JOIN accounts_with_delegated_pools on tx_out.stake_address_id = accounts_with_delegated_pools.stake_address_id INNER JOIN TX ON TX.ID = TX_OUT.TX_ID LEFT JOIN TX_IN ON TX_OUT.TX_ID = TX_IN.TX_OUT_ID AND TX_OUT.INDEX::smallint = TX_IN.TX_OUT_INDEX::smallint WHERE TX.BLOCK_ID <= 3329407 AND TX_IN.TX_IN_ID IS NULL GROUP BY accounts_with_delegated_pools.stake_address_id, accounts_with_delegated_pools.stake_address )" > out.log ERROR: relation "accounts_with_delegated_pools" does not exist LINE 1: ...(TX_OUT.VALUE), 0) AS UTXO FROM tx_out INNER JOIN accounts_w...

` Looks like a missing table name to me.

dostrelith678 commented 2 years ago

Thx, my bad - you will need to create this TEMP table in the same session for this to work, so:

CREATE TEMP TABLE accounts_with_delegated_pools AS (
  SELECT DISTINCT ON (STAKE_ADDRESS.ID) stake_address.id as stake_address_id,
    stake_address.view as stake_address,
    pool_hash_id
  FROM STAKE_ADDRESS
    INNER JOIN DELEGATION ON DELEGATION.ADDR_ID = STAKE_ADDRESS.ID
  WHERE NOT EXISTS (
      SELECT TRUE
      FROM DELEGATION D
      WHERE D.ADDR_ID = DELEGATION.ADDR_ID
        AND D.ID > DELEGATION.ID
    )
    AND NOT EXISTS (
      SELECT TRUE
      FROM STAKE_DEREGISTRATION
      WHERE STAKE_DEREGISTRATION.ADDR_ID = DELEGATION.ADDR_ID
        AND STAKE_DEREGISTRATION.TX_ID > DELEGATION.TX_ID
    )
);

CREATE INDEX IF NOT EXISTS idx_stake_address_id ON accounts_with_delegated_pools (stake_address_id);
CREATE INDEX IF NOT EXISTS idx_pool_hash_id ON accounts_with_delegated_pools (pool_hash_id);

And then:

EXPLAIN ANALYZE CREATE TEMP TABLE account_total_utxo AS (
  SELECT accounts_with_delegated_pools.stake_address_id,
    COALESCE(SUM(TX_OUT.VALUE), 0) AS UTXO
  FROM tx_out
    INNER JOIN accounts_with_delegated_pools on tx_out.stake_address_id = accounts_with_delegated_pools.stake_address_id
    INNER JOIN TX ON TX.ID = TX_OUT.TX_ID
    LEFT JOIN TX_IN ON TX_OUT.TX_ID = TX_IN.TX_OUT_ID
    AND TX_OUT.INDEX::smallint = TX_IN.TX_OUT_INDEX::smallint
  WHERE TX.BLOCK_ID <= _last_accounted_block_id
    AND TX_IN.TX_IN_ID IS NULL
  GROUP BY accounts_with_delegated_pools.stake_address_id,
    accounts_with_delegated_pools.stake_address
);

Might be best to do in the psql shell.

pyromaniac3010 commented 2 years ago

Here the new output:

$ psql cexplorer
psql (14.2 (Ubuntu 14.2-1.pgdg20.04+1))
Type "help" for help.

cexplorer=# CREATE TEMP TABLE accounts_with_delegated_pools AS (
cexplorer(#   SELECT DISTINCT ON (STAKE_ADDRESS.ID) stake_address.id as stake_address_id,
cexplorer(#     stake_address.view as stake_address,
cexplorer(#     pool_hash_id
cexplorer(#   FROM STAKE_ADDRESS
cexplorer(#     INNER JOIN DELEGATION ON DELEGATION.ADDR_ID = STAKE_ADDRESS.ID
cexplorer(#   WHERE NOT EXISTS (
cexplorer(#       SELECT TRUE
cexplorer(#       FROM DELEGATION D
cexplorer(#       WHERE D.ADDR_ID = DELEGATION.ADDR_ID
cexplorer(#         AND D.ID > DELEGATION.ID
cexplorer(#     )
cexplorer(#     AND NOT EXISTS (
cexplorer(#       SELECT TRUE
cexplorer(#       FROM STAKE_DEREGISTRATION
cexplorer(#       WHERE STAKE_DEREGISTRATION.ADDR_ID = DELEGATION.ADDR_ID
cexplorer(#         AND STAKE_DEREGISTRATION.TX_ID > DELEGATION.TX_ID
cexplorer(#     )
cexplorer(# );
SELECT 84868
cexplorer=#
cexplorer=# CREATE INDEX IF NOT EXISTS idx_stake_address_id ON accounts_with_delegated_pools (stake_address_id);
CREATE INDEX
cexplorer=# CREATE INDEX IF NOT EXISTS idx_pool_hash_id ON accounts_with_delegated_pools (pool_hash_id);
CREATE INDEX
cexplorer=# EXPLAIN ANALYZE CREATE TEMP TABLE account_total_utxo AS (
cexplorer(#   SELECT accounts_with_delegated_pools.stake_address_id,
cexplorer(#     COALESCE(SUM(TX_OUT.VALUE), 0) AS UTXO
cexplorer(#   FROM tx_out
cexplorer(#     INNER JOIN accounts_with_delegated_pools on tx_out.stake_address_id = accounts_with_delegated_pools.stake_address_id
cexplorer(#     INNER JOIN TX ON TX.ID = TX_OUT.TX_ID
cexplorer(#     LEFT JOIN TX_IN ON TX_OUT.TX_ID = TX_IN.TX_OUT_ID
cexplorer(#     AND TX_OUT.INDEX::smallint = TX_IN.TX_OUT_INDEX::smallint
cexplorer(#   WHERE TX.BLOCK_ID <= _last_accounted_block_id
cexplorer(#     AND TX_IN.TX_IN_ID IS NULL
cexplorer(#   GROUP BY accounts_with_delegated_pools.stake_address_id,
cexplorer(#     accounts_with_delegated_pools.stake_address
cexplorer(# );
ERROR:  column "_last_accounted_block_id" does not exist
LINE 9:   WHERE TX.BLOCK_ID <= _last_accounted_block_id
dostrelith678 commented 2 years ago

My bad again, limit the block_id:

EXPLAIN ANALYZE CREATE TEMP TABLE account_total_utxo AS (
  SELECT accounts_with_delegated_pools.stake_address_id,
    COALESCE(SUM(TX_OUT.VALUE), 0) AS UTXO
  FROM tx_out
    INNER JOIN accounts_with_delegated_pools on tx_out.stake_address_id = accounts_with_delegated_pools.stake_address_id
    INNER JOIN TX ON TX.ID = TX_OUT.TX_ID
    LEFT JOIN TX_IN ON TX_OUT.TX_ID = TX_IN.TX_OUT_ID
    AND TX_OUT.INDEX::smallint = TX_IN.TX_OUT_INDEX::smallint
  WHERE TX.BLOCK_ID <= 3342661
    AND TX_IN.TX_IN_ID IS NULL
  GROUP BY accounts_with_delegated_pools.stake_address_id,
    accounts_with_delegated_pools.stake_address
);
pyromaniac3010 commented 2 years ago

And after waiting for a loooooong time I finally got this output:

                                                                                        QUERY PLAN                                                       
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 GroupAggregate  (cost=324425.23..512750.92 rows=1 width=72) (actual time=9686.421..29407438.301 rows=84138 loops=1)
   Group Key: accounts_with_delegated_pools.stake_address_id, accounts_with_delegated_pools.stake_address
   ->  Incremental Sort  (cost=324425.23..512750.89 rows=2 width=46) (actual time=9686.392..29407314.453 rows=133172 loops=1)
         Sort Key: accounts_with_delegated_pools.stake_address_id, accounts_with_delegated_pools.stake_address
         Presorted Key: accounts_with_delegated_pools.stake_address_id
         Full-sort Groups: 2985  Sort Method: quicksort  Average Memory: 29kB  Peak Memory: 29kB
         Pre-sorted Groups: 341  Sort Method: quicksort  Average Memory: 637kB  Peak Memory: 2113kB
         ->  Nested Loop  (cost=136099.64..512750.80 rows=1 width=46) (actual time=3335.421..29407051.651 rows=133172 loops=1)
               ->  Nested Loop  (cost=136099.21..512750.34 rows=1 width=54) (actual time=3335.306..29404248.271 rows=150194 loops=1)
                     Join Filter: (tx_out.stake_address_id = accounts_with_delegated_pools.stake_address_id)
                     Rows Removed by Join Filter: 171727773874
                     ->  Index Scan using idx_stake_address_id on accounts_with_delegated_pools  (cost=0.29..2865.48 rows=84899 width=40) (actual time=0.023..567.309 rows=84899 loops=1)
                     ->  Materialize  (cost=136098.92..508611.38 rows=1 width=22) (actual time=0.033..216.908 rows=2022732 loops=84899)
                           ->  Gather  (cost=136098.92..508611.37 rows=1 width=22) (actual time=2593.605..3883.346 rows=2022732 loops=1)
                                 Workers Planned: 2
                                 Workers Launched: 2
                                 ->  Parallel Hash Left Join  (cost=135098.92..507611.27 rows=1 width=22) (actual time=2568.208..3812.743 rows=674244 loops=3)
                                       Hash Cond: ((tx_out.tx_id = tx_in.tx_out_id) AND ((tx_out.index)::smallint = (tx_in.tx_out_index)::smallint))
                                       Filter: (tx_in.tx_in_id IS NULL)
                                       Rows Removed by Filter: 2211778
                                       ->  Parallel Seq Scan on tx_out  (cost=0.00..295027.41 rows=3610841 width=24) (actual time=0.071..613.398 rows=2886022 loops=3)
                                       ->  Parallel Hash  (cost=77385.57..77385.57 rows=2766757 width=18) (actual time=1238.338..1238.339 rows=2211778 loops=3)
                                             Buckets: 262144  Batches: 64  Memory Usage: 7776kB
                                             ->  Parallel Seq Scan on tx_in  (cost=0.00..77385.57 rows=2766757 width=18) (actual time=261.033..595.596 rows=2211778 loops=3)
               ->  Index Scan using tx_pkey on tx  (cost=0.43..0.46 rows=1 width=8) (actual time=0.014..0.014 rows=1 loops=150194)
                     Index Cond: (id = tx_out.tx_id)
                     Filter: (block_id <= 3342661)
                     Rows Removed by Filter: 0
 Planning Time: 6.375 ms
 JIT:
   Functions: 56
   Options: Inlining true, Optimization true, Expressions true, Deforming true
   Timing: Generation 7.103 ms, Inlining 246.216 ms, Optimization 326.433 ms, Emission 209.419 ms, Total 789.171 ms
 Execution Time: 29407568.089 ms
(34 rows)
dostrelith678 commented 2 years ago

Thanks, a similar result to mine, which was ~10 hours. Now we have to analyse the these explains to see if we can spot any obvious issues 😄

reqlez commented 2 years ago

I have the same issue! And here I assumed it was just me lol Query running 24/7 pinning one of my CPU cores to 100%

2022-03-01_21:30:02 Running stake distribution update... ERROR: Previous query still running but should have completed! Exiting... CONTEXT: PL/pgSQL function grest.stake_distribution_cache_update_check() line 13 at RAISE STATEMENT: SELECT GREST.STAKE_DISTRIBUTION_CACHE_UPDATE_CHECK(); 2022-03-01_21:30:02 Job done! 2022-03-01_22:00:02 Running stake distribution update... ERROR: Previous query still running but should have completed! Exiting... CONTEXT: PL/pgSQL function grest.stake_distribution_cache_update_check() line 13 at RAISE STATEMENT: SELECT GREST.STAKE_DISTRIBUTION_CACHE_UPDATE_CHECK(); 2022-03-01_22:00:02 Job done!