Запрос Postgres по ODBC на порядок медленнее?
У нас есть приложение, которое получает данные из базы данных PostgreSQL 9.0.3 через драйвер psqlodbc 09.00.0200 следующим образом:
1) SQLExecDirect с START TRANSACTION
2) SQLExecDirect с
DECLARE foo SCROLL CURSOR FOR
SELECT table.alotofcolumns
FROM table
ORDER BY name2, id LIMIT 10000
3) SQLPrepare с
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 с параметром param1, установленным на SQL_FETCH_RELATIVE, и param2, установленным на 1
5) SQLExecute с параметром param1, установленным на SQL_FETCH_RELATIVE, и param2, установленным на -1
6) SQLExecute с параметром param1, установленным на SQL_FETCH_RELATIVE, и param2, установленным на 0
7) освободить все, закрыть курсор, завершить транзакцию
Функция fetchcur выполняет FETCH RELATIVE $ 3 IN $ 1 INTO rec , где rec - это запись, и возвращает эту запись. Шаги 4-6 выполняются снова и снова по запросу пользователя, и тем временем в этой транзакции выполняется гораздо больше запросов. Также может пройти некоторое время, прежде чем будет сделан следующий запрос пользователя. Обычно запросы занимают столько времени:
4) ~ 130 мс
5) ~ 115 мс
6) ~ 110 мс
Обычно это слишком медленно для быстрого взаимодействия с пользователем. Итак, я попробовал те же утверждения из командной строки psql с включенным \ timeing. На шаге 3-6 я использовал эти операторы:
3)
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);
Для первого EXECUTE потребовалось 89 мс, но затем оно снизилось до ~ 7 мс. Даже если я жду несколько минут между запусками, он остается менее 10 мс на запрос. Так куда же девать дополнительные 100 мс? Приложение и база данных находятся в одной системе, поэтому задержка в сети не должна быть проблемой. Каждое LEFT OUTER JOIN возвращает только одну строку, и только один столбец этого результата добавляется к набору результатов. Таким образом, результат - одна строка с ~ 200 столбцами, в основном типа VARCHAR и INTEGER. Но это не должно быть так много данных, чтобы их передача на одном компьютере занимала около 100 мс. Так что любые подсказки будут полезны.
У машины 2 ГБ ОЗУ, и параметры установлены на:
shared_buffers = 512MB
effective_cache_size = 256MB
work_mem = 16MB
maintenance_work_mem = 256MB
temp_buffers = 8MB
wal_buffers= 1MB
РЕДАКТИРОВАТЬ: Я только что узнал, как создать mylog из psqlodbc, но я не могу найти там значения времени.
РЕДАКТИРОВАТЬ2: Также можно добавить метку времени к каждой строке. Это действительно показывает, что до получения ответа драйвером psqlodbc требуется> 100 мс. Поэтому я попробовал еще раз с psql и добавил параметр -h 127.0.0.1 , чтобы убедиться, что он также проходит через TCP / IP. Результат с psql составляет <10 мс. Как это возможно?
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: Я понял, что раньше не использовал тот же запрос из mylog в тесте psql . Кажется, что psqlodbc не использует PREPARE для SQLPrepare и SQLExecute. Он добавляет значение параметра и отправляет запрос. Как предложил araqnid, я установил для параметра log_duration значение 0 и сравнил результаты журнала postgresql с результатами приложения и psql. Результат следующий:
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
Итак, как интерпретировать эти значения? Кажется, больше всего времени уходит на отправку полного запроса в базу данных (10000 символов) и создание плана выполнения. Если это так, изменение вызовов SQLPrepare и SQLExecute на явные операторы PREPARE / EXECUTE, выполняемые через SQLExecDirect, может решить проблему. Есть возражения?