Utilizzare PostgreSQL JDBC
Slow ?!

L'accesso ai dati mediante un driver JDBC e' uno dei metodi piu' diffusi per raccogliere e trattare dati con un database relazionale.

Anche con il database Open Source PostgreSQL il driver JDBC e' uno dei metodi di accesso piu' utilizzati. Il driver JDBC di Postgres e' robusto, affidabile e ben performante... se utilizzato correttamente.
In questa paginetta vedremo l'esempio di una query che e' molto veloce quando provata in modo interattivo, ad esempio con il psql, ma che risulta lenta quando utilizzata in un programma java.

Naturalmente il trucco c'e'... ma non si vede: continuate a leggere!

Esempio

Vediamo un semplice esempio di utilizzo del driver JDBC di Postgres. Vogliamo leggere i dati da una tabella di grosse dimensioni con una query puntuale [NdA la base dati e' stata creata con pgbench utilizzando scale=100 e l'HASH partitioning]:

import java.sql.*; public class PgBenchQ1 { public static void main(String[] args) { String jdbcUrl = "jdbc:postgresql://localhost:5432/pgbench"; String username = "postgres"; String password = "xxx"; try { Connection connection = DriverManager.getConnection(jdbcUrl, username, password); PreparedStatement statement = connection.prepareStatement("SELECT abalance FROM pgbench_accounts WHERE aid = ?"); ...

Giustamente e' stato utilizzato uno statement prepared che consente di ridurre il planning time. Vediamo la parte finale dell'esempio:

... ResultSet resultSet = statement.executeQuery(); while (resultSet.next()) { int columnValue = resultSet.getInt("abalance"); System.out.println("Column Value: " + columnValue); } connection.close(); }

Funziona perfettamente ma... i tempi di risposta sono pessimi: circa un secondo per ottenere il dato cercato nonostante la presenza di un indice sulla colonna aid.

Lo stesso tipo di ricerca lanciata da psql risulta nettamente piu' veloce:

Statement statistics
Query	Calls	Average (sec.)	Max (sec.)	Total Time	Blks read /Call	Rows /Call	Hit Ratio%	WAL MB	T
SELECT abalance FROM pgbench_accounts WHERE aid = $1	2	1.223	1.281	2445	165.39	0.00	9.21	0	T
SELECT abalance FROM pgbench_accounts WHERE aid = $1	2	0.001	0.001	0.002	0.00	0.00	100.00	0	T

Lo statement e' apparentemente identico ma lanciato da client i tempi sono addirittura di tre ordini di grandezza inferiori.

I log applicativi e di PostgreSQL non sono di grande aiuto perche' la query appare identica. Una differenza di questo tipo puo' solo essere spiegata con un execution plan errato.

In effetti l'execution plan della query lanciata manualmente e' molto semplice:

                                                    QUERY PLAN                                                     
-------------------------------------------------------------------------------------------------------------------
 Index Scan using pgbench_accounts_2_pkey on pgbench_accounts_2 pgbench_accounts  (cost=0.42..8.44 rows=1 width=4) (actual time=0.159..0.161 rows=1 loops=1)
   Index Cond: (aid = 500)
 Planning Time: 0.213 ms
 Execution Time: 0.187 ms

E' un poco piu' laborioso ottenere il plan di uno statement senza utilizzare la clausola EXPLAIN perche' lanciato da un programma. Ma e' possibile farlo con l'estensione auto_explain. Il piano utilizzato dal programma Java e' completamente diverso:

 Gather  (cost=1000.00..234594.87 rows=50442 width=4) (actual time=857.335..858.748 rows=1 loops=1)
   Workers Planned: 2
   Workers Launched: 2
   ->  Parallel Append  (cost=0.00..228550.67 rows=21018 width=4) (actual time=653.850..835.784 rows=0 loops=3)
         ->  Parallel Seq Scan on pgbench_accounts_10  (cost=0.00..22889.80 rows=2106 width=4) (actual time=315.333..315.333 rows=0 loops=1)
               Filter: ((aid)::double precision = '500'::double precision)
               Rows Removed by Filter: 1001942
         ->  Parallel Seq Scan on pgbench_accounts_2  (cost=0.00..22873.17 rows=2105 width=4) (actual time=278.705..278.705 rows=1 loops=1)
               Filter: ((aid)::double precision = '500'::double precision)
               Rows Removed by Filter: 1001261
         ->  Parallel Seq Scan on pgbench_accounts_3  (cost=0.00..22849.77 rows=2102 width=4) (actual time=79.266..79.266 rows=0 loops=1)
               Filter: ((aid)::double precision = '500'::double precision)
               Rows Removed by Filter: 1000116
         ->  Parallel Seq Scan on pgbench_accounts_4  (cost=0.00..22844.34 rows=2102 width=4) (actual time=50.211..50.211 rows=0 loops=1)
               Filter: ((aid)::double precision = '500'::double precision)
               Rows Removed by Filter: 999888
         ->  Parallel Seq Scan on pgbench_accounts_8  (cost=0.00..22840.07 rows=2101 width=4) (actual time=49.864..49.865 rows=0 loops=1)
               Filter: ((aid)::double precision = '500'::double precision)
               Rows Removed by Filter: 999806
         ->  Parallel Seq Scan on pgbench_accounts_5  (cost=0.00..22836.16 rows=2101 width=4) (actual time=51.261..51.262 rows=0 loops=1)
               Filter: ((aid)::double precision = '500'::double precision)
               Rows Removed by Filter: 999661
         ->  Parallel Seq Scan on pgbench_accounts_9  (cost=0.00..22834.70 rows=2101 width=4) (actual time=303.493..303.493 rows=0 loops=3)
               Filter: ((aid)::double precision = '500'::double precision)
               Rows Removed by Filter: 333196
         ->  Parallel Seq Scan on pgbench_accounts_7  (cost=0.00..22831.76 rows=2100 width=4) (actual time=198.491..198.491 rows=0 loops=2)
               Filter: ((aid)::double precision = '500'::double precision)
               Rows Removed by Filter: 499748
         ->  Parallel Seq Scan on pgbench_accounts_1  (cost=0.00..22823.56 rows=2100 width=4) (actual time=75.779..75.779 rows=0 loops=1)
               Filter: ((aid)::double precision = '500'::double precision)
               Rows Removed by Filter: 999145
         ->  Parallel Seq Scan on pgbench_accounts_6  (cost=0.00..22822.25 rows=2100 width=4) (actual time=299.448..299.448 rows=0 loops=1)
               Filter: ((aid)::double precision = '500'::double precision)
               Rows Removed by Filter: 999096
 Planning Time: 0.628 ms
 Execution Time: 858.831 ms

Per il confronto della condizione anziche' una condizione (Index Cond) e' applicato un filtro (Filter), questa differenza e' importantissima con PostgreSQL. Anziche' una condizione valutata sull'indice (Index Cond) e' utilizzato un filtro (Filter) accedendo ai dati nella tabella eseguendo una scansione sequenziale (Seq Scan) di tutte le partizioni della tabella; e' il caso peggiore: non viene eseguito il pruning delle partizioni e non viene effettuata una ricerca per indice. Solo il parallelismo (Parallel Append) aiuta un poco perche' vengono utilizzati due workers in parallelo. Il tutto per individuare l'unica riga, su 100 milioni, che contiene il dato cercato.

Questo spiega la differenza di tempi ma non sappiamo ancora il motivo del problema... o forse si?

Il problema

Anche se sembra impossibile che lo stesso statement abbia un comportamento cosi' diverso in realta' c'e' una valida ragione della differenza. Il problema e' che l'applicazione Java utilizza un datatype non corretto per impostare la variabile di bind. Infatti nel codice sorgente troviamo:

... statement.setDouble(1, aid); ...

Ma in realta' il datatype corretto e' un integer!

pgbench=# \d  pgbench_accounts
        Partitioned table "public.pgbench_accounts"
  Column  |     Type      | Collation | Nullable | Default 
----------+---------------+-----------+----------+---------
 aid      | integer       |           | not null | 
 bid      | integer       |           |          | 
 abalance | integer       |           |          | 
 filler   | character(84) |           |          | 
Partition key: HASH (aid)
Indexes:
    "pgbench_accounts_pkey" PRIMARY KEY, btree (aid)
Number of partitions: 10 (Use \d+ to list them.)

Ma che differenza c'e' tra un numero ed un intero? Tantissima!
Il valore puo' essere lo stesso ma e' necessaria un conversione e se questa deve essera applicata ad una colonna gli eventuali indici costruiti sulla stessa non possono essere utilizzati [NdA questa e' la differenza per PostgreSQL... ma non e' l'unica: chiedete ad un matematico o provate il confronto in assembler].

Utilizzando l'istruzione corretta statement.setInt il problema si risolve e la query lanciata dal programma Java viene risolta in meno di un millisecondo come previsto.

Questo tipo di problema e' difficile da diagnosticare perche' lo statement nei log applicativi, nel log di PostgreSQL e nella vista pg_stat_statements appare identico. In caso di migrazione tra database diversi i datatype possono essere differenti ed altri RDBMS sono piu' permissivi di PostgreSQL nell'applicazione dei cast: quindi il problema presentato puo' verificarsi facilmente in caso di migrazioni.

Nell'esempio sono stati utilizzati datatype numerici ma e' ovviamente possibile che il problema si presenti con tutti gli altri datatype: affinche' vengano utilizzati gli indici e possa essere eseguito il pruning delle partizioni e' sempre necessario utilizzare i datatype corretti.

Prepared Statements

Nell'esempio abbiamo utilizzato i prepared statement. E' la tecnica migliore quendo vengono utilizzati gli stessi statement con parti variabili (bind) fornite ogni volta. In questo modo i tempi di parsing dello statement vengono ridotti al minimo.

E' sempre consigliato utilizzare i prepared statement ma vi e' un caso a cui fare attenzione: quando la distribuzione dei dati e' molto differente a seconda delle variabili passate. Infatti l'ottimizzatore PostgreSQL, dopo le prime esecuzioni, imposta un execution plan e lo mantiene per tutti i richiami sucessivi. Se la distribuzione dei dati e' uniforme non c'e' problema: il piano e' gia' quello ottimale e non viene ricalcolato consentendo un risparmio di CPU. Ma se la distribuzione dei dati non e' uniforme la query potrebbe avere tempi di risposta molto alti.

Quando si utilizzano i prepared statement e la distribuzione dei dati non e' uniforme per le variabili in bind e' possibile forzare il ricalcolo del piano di esecuzione impostando il parametro plan_cache_mode:

SET plan_cache_mode=force_custom_plan;

Naturalmente questo e' indipendente dalla modalita' di accesso alla base dati via JDBC. Infatti e' possibile utilizzare i prepared statement anche da psql come in questo semplice esempio:

PREPARE st01 (INT) AS SELECT abalance FROM pgbench_accounts WHERE aid = $1; EXECUTE st01(500);

Nell'esempio che abbiamo utilizzato il problema non era sulla distribuzione dei dati e l'impostazione del plan_cache_mode non avrebbe dato alcun vantaggio. L'utilizzo dei prepared statement e' un argomento un pochino piu' compesso di quanto riportato in questo breve paragrafo; ma e' un aspetto da tenere in considerazione perche', giustamente, con Java si fa spesso uso di prepared statement [NdA quando avro' tempo scrivero' una paginetta anche su questo... gia' fatto!].

Varie ed eventuali

Altre paginette sull'utilizzo del JDBC con PostreSQL sono: Utilizzare PostgreSQL JDBC - Prepared Statements, Utilizzare PostgreSQL JDBC senza OOM (Out Of Memory).

Le fonti definitive di tutte le informazioni sono il sito ufficiale JDBC PostgreSQL e GitHub.

Titolo: Raccolta dati con PostgreSQL JDBC - Slow ?!
Livello: Avanzato (3/5)
Data: 14 Febbraio 2024 ❤️
Versione: 1.0.2 - 31 Ottobre 2024 🎃
Autore: mail [AT] meo.bogliolo.name

Utilizzare PostgreSQL JDBCSlow ?!

Esempio

Il problema

Prepared Statements

Varie ed eventuali

Utilizzare PostgreSQL JDBC
Slow ?!