Pregunta de Postgres sobre ODBC un orden de magnitud más lento?

Tenemos una aplicación que recibe algunos datos de una base de datos PostgreSQL 9.0.3 a través del controlador 09.00.0200 psqlodbc de la siguiente manera:Pregunta de Postgres sobre ODBC un orden de magnitud más lento?

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 ajustado a SQL_FETCH_RELATIVE y param2 establece en 1
5) SQLExecute con param1 ajustado a SQL_FETCH_RELATIVE y param2 establece en -1
6) SQLExecute con param1 ajustado a SQL_FETCH_RELATIVE y param2 establecido en 0
7) desasignar todo, cursor cerca, transacción final ejecuta

La función fetchcur FETCH RELATIVE $3 IN $1 INTO rec donde rec es un registro y devuelve ese registro. Los pasos 4-6 se ejecutan una y otra vez a petición del usuario y mientras tanto, se ejecutan muchas más consultas en esta transacción. También puede tomar bastante tiempo antes de que se realice otra solicitud de usuario. Por lo general, los querys necesita ese tiempo:

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

Ésta es normalmente demasiado lento para una experiencia de usuario rápida. Así que probé las mismas declaraciones desde la línea de comando psql con \ timing on. Para el paso 3-6 utilicé que las declaraciones:

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);

Por primera ejecutarlo tomó 89 ms, pero luego fui a ~ 7 ms. Incluso si espero varios minutos entre los ejecutados, permanece en menos de 10 ms por consulta. Entonces, ¿dónde podrían haber desaparecido los 100 ms adicionales? La aplicación y la base de datos están en el mismo sistema, por lo que la demora de la red no debería ser un problema. Cada UNIÓN EXTERIOR IZQUIERDA solo devuelve una fila y solo se agrega una columna de ese resultado al conjunto de resultados. Entonces el resultado es una fila con ~ 200 columnas en su mayoría de tipo VARCHAR e INTEGER. Pero eso no debería ser tanta información que tomar alrededor de 100 ms para transferir en la misma máquina. Entonces cualquier sugerencia sería útil.

La máquina cuenta con 2 GB de RAM y parámetros se ajustan a:

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

EDIT: acabo de descubrir cómo crear una mylog de psqlodbc, pero no puedo encontrar el tiempo valores allí.

EDIT2: También podría agregar una marca de tiempo a cada línea. Esto realmente muestra que lleva> 100 ms hasta que el controlador psqlodbc reciba una respuesta. Así que intenté de nuevo con psql y agregué la opción -h 127.0.0.1 para asegurarme de que también pasa por TCP/IP. El resultado con psql es < 10ms. ¿Cómo es esto posible?

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: Me di cuenta que no utilicé la misma consulta del mylog en la prueba psql antes. Parece que psqlodbc no usa un PREPARE para SQLPrepare y SQLExecute. Agrega el valor de parámetro y envía la consulta. Como araqnid sugirió que establezca el parámetro log_duration en 0 y comparé los resultados del registro postgresql con los de la aplicación y psql. El resultado es el siguiente:

      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

Entonces, ¿cómo interpretar esos valores? Parece que la mayor parte del tiempo es pasar la consulta completa a la base de datos (10000 caracteres) y generar un plan de ejecución. Si eso es cierto, el cambio de las llamadas a SQLPrepare y SQLExecute a las instrucciones explícitas PREPARE/EXECUTE ejecutadas sobre SQLExecDirect podría resolver el problema. ¿Alguna objeción?

Fuente

2011-02-22 rudi-moore

"00: 07: 51.133 [3086550720] !!! poll ret = 1 revents = 1" - ¿ha agregado los signos de admiración para resaltar esta línea o son parte de la salida? Justo encima, envió un comando de punto de rescate y recibió una respuesta doblemente rápida por lo que no parece ser un retraso de red. Aunque parece estar recuperando una mayor cantidad de datos para el resultado de la consulta real, lo cual no es sorprendente ... – araqnid

algo más para probar- establecer 'log_duration' para ese usuario de base de datos y ver si postgresql en el servidor registra eso la consulta tarda más cuando la ejecuta desde su servidor en comparación con ejecutarla directamente con psql. – araqnid

Las exclamaciones son parte de la salida, no las agregué. 'psqlodbc' también se puede volver a compilar con la opción de usar' select() 'en lugar de' poll() '. Intenté eso sin ninguna diferencia. Gracias por la pista con 'log_duration'. Voy a intentar eso. –

Finalmente encontré el problema y fue que el SQLPrepare/SQLExecute de psqlodbc de forma predeterminada no ejecuta un PREPARE/EXECUTE. El controlador crea el SELECT y lo envía.

La solución es agregar UseServerSidePrepare=1 al odbc.ini o al ConnectionString para SQLDriverConnect. El tiempo de ejecución total para una consulta medida desde la aplicación cayó de> 100ms a 5-10ms.

Fuente

2011-02-23 18:33:48

No creo que el tiempo entre psql y su programa sea comparable.

Tal vez me falta algo, pero en psql solo estás preparando las declaraciones, pero nunca realmente buscando los datos. EXPLAIN PLAN no está enviando datos

Por lo tanto, la diferencia de tiempo es probablemente el tráfico de red necesario para enviar todas las filas del servidor al cliente.

La única manera de reducir este tiempo es obtener una red más rápida o seleccionar menos columnas. ¿Realmente necesita todas las columnas que se incluyen en "alotofcolumns"?

Fuente

2011-02-22 20:45:07

La parte 'ANALYZE' de' EXPLAIN ANALYZE' realmente ejecuta la consulta. Intenté la consulta nuevamente sin 'EXPLAIN ANALYZE' para verificar y salvo la primera consulta, está cerca de los resultados anteriores y menores a 10 ms. En nuestro caso, el cliente y el servidor están en la misma máquina. Entonces, solo existe la pila de red del localhost entre ellos. ¿Eso no debería sumar tanto tiempo o perdí algo? Sigo pensando que sería más costoso ejecutar otra consulta más adelante si se detecta una columna faltante. Y es solo una fila. No creo que haya más que un poco de KB de datos en las columnas –

Tiene razón, 'EXPLAIN ANALYZE' ejecuta la consulta pero no envía los resultados al cliente. Y si la cantidad de datos enviados es grande (muchas filas, datos de columna de gran tamaño), esto puede llevar una cantidad sustancial de tiempo (la memoria debe asignarse en ambos lados, los datos deben enviarse a través de varias capas de software, etc.) . –

Pregunta de Postgres sobre ODBC un orden de magnitud más lento?

Respuesta

Cuestiones relacionadas