Improvements - /account/balance performance

[Kartiiyer12]

• Library/Tool: cardano-rosetta-java (v1.2.1)
• Network: Mainnet
• Setup: Docker

Request API Call /account/balance

Request:

POST {{URL}}/account/balance
{
    "network_identifier": {
        "blockchain": "cardano",
        "network": "mainnet"
    },
    "account_identifier": {
        "address": "addr1v804tgee0m3ww7z93zh64wr9flqh9psdhnxg6cykfudgulg6f633p",
        "metadata": {}
    }
}

Result:
The query took 1 min 30 secs to get back the result. Interestingly,

• If queried again after few blocks, the response is under 2 seconds.
• Querying after 10 blocks takes 14 seconds to return the result.
• Querying after 50 blocks (aka 15 min) took a minute to get the response.

Issue
In the logs, I saw warnings as -
`WARN 161879 --- [l-1 housekeeper] com.zaxxer.hikari.pool.ProxyLeakTask : Connection leak detection triggered for org.postgresql.jdbc.PgConnection@13df6ef on thread http-nio-8082-exec-4, stack trace follows

java.lang.Exception: Apparent connection leak detected
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-5.0.1.jar!/:na]
at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) ~[hibernate-core-6.4.4.Final.jar!/:6.4.4.Final]
at `

For which I increased the below env variables-
SPRING_DATASOURCE_HIKARI_LEAKDETECTIONTHRESHOLD=180000

After setting the above env variable, no warning logs appeared as the initial leak detection was default to 1 min.

Background

There was a discussion earlier that we can address balances can be cached when queried and then subsequent call for the balance will only from the previous block when the balance was cached to the latest block which can improve the performance but can take up larger space. The rosetta-java even with only transaction data takes up 644 GB vs entire db-sync taking 512 GB.

[matiwinnetou]

@Kartiiyer12 can you reproduce this on 1.2.4 release because actually it is 2.5 seconds (even the first request), which is not super fast and even slow as it should probably be less than 1 sec but it is maybe not as disastrous as ticket appears to be on older versions.

[matiwinnetou]

This is about 2,5 - 3,5 seconds on main-net now for this very address with a lot of transactions, we would like to see this value as less than < 500 ms to close this ticket (SLA) on ideally at least 10 concurrent users.

[Kartiiyer12]

This is still an issue when running as a single docker image and the response times is still more than a minute. I checked the indexes for the address_utxo and tx_input table and they exist & are same to the db running as docker-compose.
Version tested - 1.2.4 mainnet

Checking at the database level for the Explain Analyze -

Query -

 explain analyze   select
        aue1_0.output_index,
        aue1_0.tx_hash,
        aue1_0.amounts,
        aue1_0.block,
        aue1_0.owner_addr,
        aue1_0.owner_stake_addr 
    from
        address_utxo aue1_0 
    where
        aue1_0.owner_addr='addr1v804tgee0m3ww7z93zh64wr9flqh9psdhnxg6cykfudgulg6f633p'
        and not exists(select
            1 
        from
            tx_input tie1_0 
        where
            tie1_0.tx_hash=aue1_0.tx_hash 
            and tie1_0.output_index=aue1_0.output_index 
            and tie1_0.spent_at_block<=11598335) 
        and aue1_0.block<=11598335;

Plan 1 - slower response (single docker image db)

Gather  (cost=1001.39..2072771.14 rows=1 width=469) (actual time=85335.578..85357.650 rows=5 loops=1)
  Workers Planned: 2
  Workers Launched: 2
  ->  Nested Loop Anti Join  (cost=1.40..2071771.04 rows=1 width=469) (actual time=85221.994..85224.175 rows=2 loops=3)
        ->  Parallel Index Scan using idx_address_utxo_owner_addr on address_utxo aue1_0  (cost=0.70..1846907.93 rows=203840 width=469) (actual time=266.391..27239.247 rows=127283 loops=3)
              Index Cond: ((owner_addr)::text = 'addr1v804tgee0m3ww7z93zh64wr9flqh9psdhnxg6cykfudgulg6f633p'::text)
              Filter: (block <= 11598335)
        ->  Index Scan using tx_input_pkey on tx_input tie1_0  (cost=0.70..12.38 rows=2 width=69) (actual time=0.454..0.454 rows=1 loops=381848)
              Index Cond: ((output_index = aue1_0.output_index) AND ((tx_hash)::text = (aue1_0.tx_hash)::text))
              Filter: (spent_at_block <= 11598335)
Planning Time: 49.592 ms
JIT:
  Functions: 36
  Options: Inlining true, Optimization true, Expressions true, Deforming true
  Timing: Generation 3.452 ms, Inlining 193.874 ms, Optimization 362.798 ms, Emission 235.627 ms, Total 795.751 ms
Execution Time: 85444.947 ms

plan 2 - better response (running as docker compose)

Gather  (cost=1001.39..1624580.89 rows=1 width=469) (actual time=2771.713..2774.572 rows=5 loops=1)
  Workers Planned: 2
  Workers Launched: 2
  ->  Nested Loop Anti Join  (cost=1.40..1623580.79 rows=1 width=469) (actual time=2751.567..2751.628 rows=2 loops=3)
        ->  Parallel Index Scan using idx_address_utxo_owner_addr on address_utxo aue1_0  (cost=0.70..1448970.72 rows=151430 width=469) (actual time=229.832..574.766 rows=127283 loops=3)
              Index Cond: ((owner_addr)::text = 'addr1v804tgee0m3ww7z93zh64wr9flqh9psdhnxg6cykfudgulg6f633p'::text)
              Filter: (block <= 11598335)
        ->  Index Scan using tx_input_pkey on tx_input tie1_0  (cost=0.70..16.10 rows=3 width=69) (actual time=0.017..0.017 rows=1 loops=381848)
              Index Cond: ((output_index = aue1_0.output_index) AND ((tx_hash)::text = (aue1_0.tx_hash)::text))
              Filter: (spent_at_block <= 11598335)
Planning Time: 2.945 ms
JIT:
  Functions: 36
  Options: Inlining true, Optimization true, Expressions true, Deforming true
  Timing: Generation 3.004 ms, Inlining 149.328 ms, Optimization 326.822 ms, Emission 212.361 ms, Total 691.515 ms
Execution Time: 2791.733 ms

There is a difference in the execution time. I am trying to reindex the tx_input and address_utxo table to remove the possiblities for indexes being bloated or fragmented. I will test once the reindexing process is complete.

[Kartiiyer12]

Testing on 1.2.5-dev the performance is 3 sec. Waiting for stress testing results before we can make the decision on this.

[matiwinnetou]

For testing, reproducing and analysis (e.g. explain plans) two addresses on the main-net which contain a lot of transactions are:

1. Ae2tdPwUPEYwNguM7TB3dMnZMfZxn1pjGHyGdjaF4mFqZF9L3bj6cdhiH8t
2. addr1v804tgee0m3ww7z93zh64wr9flqh9psdhnxg6cykfudgulg6f633p
3. addr1v8v3auqmw0eszza3ww29ea2pwftuqrqqyu26zvzjq9dt2ncydzvs5