La query Postgres su ODBC è più lenta di un ordine di grandezza?

Abbiamo un'applicazione che ottiene alcuni dati da un database PostgreSQL 9.0.3 tramite il driver 09.00.0200 psqlodbc nel seguente modo:La query Postgres su ODBC è più lenta di un ordine di grandezza?

1) SQLExecDirect con START TRANSACTION
2) SQLExecDirect con

DECLARE foo SCROLL CURSOR FOR 
SELECT table.alotofcolumns 
FROM table 
ORDER BY name2, id LIMIT 10000

3) SQLPrepare con

SELECT table.alotofcolumns, l01.languagedescription 
FROM fetchcur('foo', ?, ?) table (column definitions) 
LEFT OUTER JOIN languagetable l01 ON (l01.lang = 'EN' 
            AND l01.type = 'some type' 
            AND l01.grp = 'some group' 
            AND l01.key = table.somecolumn) 
[~20 more LEFT OUTER JOINS in the same style, but for an other column]

4) SQLExecute con param1 impostato SQL_FETCH_RELATIVE e param2 impostato a 1
012.5) SQLExecute con impostato SQL_FETCH_RELATIVE e param2 impostato -1
6) SQLExecute con param1 impostato SQL_FETCH_RELATIVE e param2 impostato a 0
7) rilasciare tutto, chiudere cursore, param1 transazione END Esegue

La funzione fetchcur FETCH RELATIVE $3 IN $1 INTO rec dove rec è un record e restituisce quel record. I passaggi da 4 a 6 vengono eseguiti ancora e ancora su richiesta dell'utente e nel frattempo ci sono molti più querys eseguiti in questa transazione. Può anche richiedere parecchio tempo prima che venga fatta un'altra richiesta utente. Di solito i querys prende così a lungo:

4) ~ 130 ms
5) ~ 115 ms
6) ~ 110 ms

Questo è normalmente troppo lento per un'esperienza utente veloce. Così ho provato le stesse istruzioni dalla riga di comando di psql con \ timing on. Per il passaggio 3-6 ho usato che le dichiarazioni:

PREPARE p_foo (INTEGER, INTEGER) AS 
SELECT table.alotofcolumns, l01.languagedescription 
FROM fetchcur('foo', $1, $2) table (column definitions) 
LEFT OUTER JOIN languagetable l01 ON (l01.lang = 'EN' 
            AND l01.type = 'some type' 
            AND l01.grp = 'some group' 
            AND l01.key = table.somecolumn) 
[~20 more LEFT OUTER JOINS in the same style, but for an other column]

4-6)

EXPLAIN ANALYZE EXECUTE p_foo (6, x);

Per la prima eseguirlo sono voluti 89 ms, ma poi è andato giù a ~ 7 ms. Anche se attendo diversi minuti tra gli esegui, rimane a meno di 10 ms per query. Quindi dove potrebbero andare gli ulteriori 100 ms? L'applicazione e il database si trovano sullo stesso sistema, quindi il ritardo di rete non dovrebbe essere un problema. Ogni LEFT OUTER JOIN restituisce solo una riga e solo una colonna di quel risultato viene aggiunta al set di risultati. Quindi il risultato è una riga con ~ 200 colonne principalmente di tipo VARCHAR e INTEGER. Ma non dovrebbero essere così tanti dati da richiedere circa 100 ms per il trasferimento sulla stessa macchina. Quindi qualsiasi suggerimento sarebbe utile.

La macchina ha 2 GB di RAM e parametri sono impostati su:

shared_buffers = 512MB 
effective_cache_size = 256MB 
work_mem = 16MB 
maintenance_work_mem = 256MB 
temp_buffers = 8MB 
wal_buffers= 1MB

EDIT: ho appena scoperto come creare un mylog da psqlodbc, ma non riesco a trovare i tempi valori in là.

EDIT2: potrebbe anche aggiungere un timestamp a ogni riga. Ciò dimostra che ci vogliono> 100 ms fino a quando non viene ricevuta una risposta dal driver psqlodbc. Così ho provato di nuovo con psql e ho aggiunto l'opzione -h 127.0.0.1 per assicurarmi che vada anche su TCP/IP. Il risultato con psql è < 10 ms. Com'è possibile?

00:07:51.026 [3086550720][SQLExecute] 
00:07:51.026 [3086550720]PGAPI_Execute: entering...1 
00:07:51.026 [3086550720]PGAPI_Execute: clear errors... 
00:07:51.026 [3086550720]prepareParameters was not called, prepare state:3 
00:07:51.026 [3086550720]SC_recycle_statement: self= 0x943b1e8 
00:07:51.026 [3086550720]PDATA_free_params: ENTER, self=0x943b38c 
00:07:51.026 [3086550720]PDATA_free_params: EXIT 
00:07:51.026 [3086550720]Exec_with_parameters_resolved: copying statement params: trans_status=6, len=10128, stmt='SELECT [..]' 
00:07:51.026 [3086550720]ResolveOneParam: from(fcType)=-15, to(fSqlType)=4(23) 
00:07:51.026 [3086550720]cvt_null_date_string=0 pgtype=23 buf=(nil) 
00:07:51.026 [3086550720]ResolveOneParam: from(fcType)=4, to(fSqlType)=4(23) 
00:07:51.026 [3086550720]cvt_null_date_string=0 pgtype=23 buf=(nil) 
00:07:51.026 [3086550720] stmt_with_params = 'SELECT [..]' 
00:07:51.027 [3086550720]about to begin SC_execute 
00:07:51.027 [3086550720]  Sending SELECT statement on stmt=0x943b1e8, cursor_name='SQL_CUR0x943b1e8' qflag=0,1 
00:07:51.027 [3086550720]CC_send_query: conn=0x9424668, query='SELECT [..]' 
00:07:51.027 [3086550720]CC_send_query: conn=0x9424668, query='SAVEPOINT _EXEC_SVP_0x943b1e8' 
00:07:51.027 [3086550720]send_query: done sending query 35bytes flushed 
00:07:51.027 [3086550720]in QR_Constructor 
00:07:51.027 [3086550720]exit QR_Constructor 
00:07:51.027 [3086550720]read 21, global_socket_buffersize=4096 
00:07:51.027 [3086550720]send_query: got id = 'C' 
00:07:51.027 [3086550720]send_query: ok - 'C' - SAVEPOINT 
00:07:51.027 [3086550720]send_query: setting cmdbuffer = 'SAVEPOINT' 
00:07:51.027 [3086550720]send_query: returning res = 0x8781c90 
00:07:51.027 [3086550720]send_query: got id = 'Z' 
00:07:51.027 [3086550720]QResult: enter DESTRUCTOR 
00:07:51.027 [3086550720]QResult: in QR_close_result 
00:07:51.027 [3086550720]QResult: free memory in, fcount=0 
00:07:51.027 [3086550720]QResult: free memory out 
00:07:51.027 [3086550720]QResult: enter DESTRUCTOR 
00:07:51.027 [3086550720]QResult: exit close_result 
00:07:51.027 [3086550720]QResult: exit DESTRUCTOR 
00:07:51.027 [3086550720]send_query: done sending query 1942bytes flushed 
00:07:51.027 [3086550720]in QR_Constructor 
00:07:51.027 [3086550720]exit QR_Constructor 
00:07:51.027 [3086550720]read -1, global_socket_buffersize=4096 
00:07:51.027 [3086550720]Lasterror=11 
00:07:51.133 [3086550720]!!! poll ret=1 revents=1 
00:07:51.133 [3086550720]read 4096, global_socket_buffersize=4096 
00:07:51.133 [3086550720]send_query: got id = 'T' 
00:07:51.133 [3086550720]QR_fetch_tuples: cursor = '', self->cursor=(nil) 
00:07:51.133 [3086550720]num_fields = 166 
00:07:51.133 [3086550720]READING ATTTYPMOD 
00:07:51.133 [3086550720]CI_read_fields: fieldname='id', adtid=23, adtsize=4, atttypmod=-1 (rel,att)=(0,0) 
[last two lines repeated for the other columns] 
00:07:51.138 [3086550720]QR_fetch_tuples: past CI_read_fields: num_fields = 166 
00:07:51.138 [3086550720]MALLOC: tuple_size = 100, size = 132800 
00:07:51.138 [3086550720]QR_next_tuple: inTuples = true, falling through: fcount = 0, fetch_number = 0 
00:07:51.139 [3086550720]qresult: len=3, buffer='282' 
[last line repeated for the other columns] 
00:07:51.140 [3086550720]end of tuple list -- setting inUse to false: this = 0x87807e8 SELECT 1 
00:07:51.140 [3086550720]_QR_next_tuple: 'C' fetch_total = 1 & this_fetch = 1 
00:07:51.140 [3086550720]QR_next_tuple: backend_rows < CACHE_SIZE: brows = 0, cache_size = 0 
00:07:51.140 [3086550720]QR_next_tuple: reached eof now 
00:07:51.140 [3086550720]send_query: got id = 'Z' 
00:07:51.140 [3086550720]  done sending the query: 
00:07:51.140 [3086550720]extend_column_bindings: entering ... self=0x943b270, bindings_allocated=166, num_columns=166 
00:07:51.140 [3086550720]exit extend_column_bindings=0x9469500 
00:07:51.140 [3086550720]SC_set_Result(943b1e8, 87807e8) 
00:07:51.140 [3086550720]QResult: enter DESTRUCTOR 
00:07:51.140 [3086550720]retval=0 
00:07:51.140 [3086550720]CC_send_query: conn=0x9424668, query='RELEASE _EXEC_SVP_0x943b1e8' 
00:07:51.140 [3086550720]send_query: done sending query 33bytes flushed 
00:07:51.140 [3086550720]in QR_Constructor 
00:07:51.140 [3086550720]exit QR_Constructor 
00:07:51.140 [3086550720]read -1, global_socket_buffersize=4096 
00:07:51.140 [3086550720]Lasterror=11 
00:07:51.140 [3086550720]!!! poll ret=1 revents=1 
00:07:51.140 [3086550720]read 19, global_socket_buffersize=4096 
00:07:51.140 [3086550720]send_query: got id = 'C' 
00:07:51.140 [3086550720]send_query: ok - 'C' - RELEASE 
00:07:51.140 [3086550720]send_query: setting cmdbuffer = 'RELEASE' 
00:07:51.140 [3086550720]send_query: returning res = 0x877cd30 
00:07:51.140 [3086550720]send_query: got id = 'Z' 
00:07:51.140 [3086550720]QResult: enter DESTRUCTOR 
00:07:51.140 [3086550720]QResult: in QR_close_result 
00:07:51.140 [3086550720]QResult: free memory in, fcount=0 
00:07:51.140 [3086550720]QResult: free memory out 
00:07:51.140 [3086550720]QResult: enter DESTRUCTOR 
00:07:51.140 [3086550720]QResult: exit close_result 
00:07:51.140 [3086550720]QResult: exit DESTRUCTOR

Edit3: mi sono reso conto che non ho usato la stessa query dal mylog nel test psql prima. Sembra che psqlodbc non utilizzi uno PREPARE per SQLPrepare e SQLExecute. Aggiunge il valore param e invia la query. Come suggerito da araqnid, ho impostato il parametro log_duration su 0 e ho confrontato i risultati del registro postgresql con quello dall'app e da psql. Il risultato è il seguente:

      psql/app  pglog 
query executed from app:  110 ms  70 ms 
psql with PREPARE/EXECUTE:  10 ms  5 ms 
psql with full SELECT:   85 ms  70 ms

Quindi, come interpretare tali valori? Sembra che la maggior parte del tempo spenda inviare l'intera query al database (10000 caratteri) e generare un piano di esecuzione. Se ciò è vero, la modifica delle chiamate a SQLPrepare e SQLExecute su esplicite istruzioni PREPARE/EXECUTE eseguite su SQLExecDirect potrebbe risolvere il problema. Eventuali obiezioni?

fonte

2011-02-22 rudi-moore

"00: 07: 51.133 [3086550720] !!! poll ret = 1 revents = 1" - hai aggiunto i punti esclamativi per evidenziare questa linea o sono parte dell'output? Appena sopra, ha inviato un comando savepoint e ha ottenuto una risposta a doppio-veloce in modo che non sembri essere un ritardo di rete. Anche se sembra che si stia recuperando una grande quantità di dati per il risultato effettivo della query, che non è sorprendente ... – araqnid

qualcos'altro da provare - imposta 'log_duration' per quell'utente del database e vedi se postgresql sul lato server registra che la query richiede più tempo quando viene eseguita dal server rispetto a eseguirla direttamente con psql. – araqnid

I punti esclamativi fanno parte dell'output, non li ho aggiunti. 'psqlodbc' può anche essere ricompilato con l'opzione per usare' select() 'invece di' poll() '. Ho provato senza alcuna differenza. Grazie per il suggerimento con 'log_duration'. Ci proverò. –

Ho finalmente trovato il problema ed era che SQLPrepare/SQLExecute di psqlodbc per impostazione predefinita non esegue PREPARE/EXECUTE. Il driver stesso crea SELECT e lo invia.

La soluzione è aggiungere UseServerSidePrepare=1 all'odbc.ini o al ConnectionString per SQLDriverConnect. Il tempo di esecuzione totale per una query misurata dall'applicazione è scesa da> 100 ms a 5-10 ms.

fonte

2011-02-23 18:33:48

Non penso che i tempi tra psql e il programma siano comparabili.

Forse mi manca qualcosa, ma in psql si stanno solo preparando le istruzioni, ma non si è mai riusciti a recuperare i dati. EXPLAIN PLAN non sta inviando i dati

Quindi la differenza di tempo è molto probabilmente il traffico di rete necessario per inviare tutte le righe dal server al client.

L'unico modo per ridurre questo tempo è ottenere una rete più veloce o selezionare meno colonne. Hai davvero bisogno di tutte le colonne incluse in "alotofcolumns"?

fonte

2011-02-22 20:45:07

La parte 'ANALYZE' di' EXPLAIN ANALYZE' esegue veramente la query. Ho provato di nuovo la query senza 'EXPLAIN ANALYZE' per verificare e tranne la prima query è vicino ai risultati precedenti e inferiori a 10 ms. Nel nostro caso il client e il server si trovano sulla stessa macchina. Quindi c'è solo lo stack di rete dal localhost tra loro. Questo non dovrebbe costare tanto tempo o mi è mancato qualcosa? Continuo a pensare che sarebbe più costoso eseguire un'altra query più tardi se è stata rilevata una colonna mancante. E la sua unica riga. Non credo che ci siano più di un paio di KB di dati in quelle colonne –

Hai ragione "SPIEGARE ANALISI" esegue la query ma non invia i risultati al client. E se la quantità di dati inviati è grande (molte righe, grandi dati di colonna), questo può richiedere ancora una notevole quantità di tempo (la memoria deve essere allocata su entrambi i lati, i dati devono essere spinti attraverso vari livelli software e così via) . –

La query Postgres su ODBC è più lenta di un ordine di grandezza?

risposta

Problemi correlati