Postgres запрос через ODBC на порядок медленнее? - PullRequest
Новая
       17

Postgres запрос через ODBC на порядок медленнее?

6 голосов
/ 22 февраля 2011

У нас есть приложение, которое получает данные из базы данных 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 с параметром1, установленным в SQL_FETCH_RELATIVE, и параметром2, установленным в 0
7) освободить все, закрыть курсор, завершить транзакцию

Функция fetchcur выполняет FETCH RELATIVE $3 IN $1 INTO rec, где rec - это запись и возвращает эту запись. Шаги 4-6 выполняются снова и снова по запросу пользователя, и тем временем в этой транзакции выполняется намного больше запросов. Это может также занять некоторое время, прежде чем другой пользовательский запрос сделан. Обычно запросы занимают столько времени:

4) ~ 130 мс
5) ~ 115 мс
6) ~ 110 мс

Обычно это слишком медленно для быстрого взаимодействия с пользователем. Так что я попробовал те же операторы из командной строки PSQL с \ хронометражем. Для шага 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);

Для первого ИСПОЛНЕНИЯ потребовалось 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, но я не могу найти там значения синхронизации.

EDIT2: также может добавить отметку времени для каждой строки. Это действительно показывает, что до получения ответа драйвером psqlodbc требуется> 100 мс. Поэтому я попытался снова с psql и добавил опцию -h 127.0.0.1, чтобы убедиться, что он также работает по TCP / IP. Результат с psql составляет <10 мс. Как это возможно? </p> 

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, может решить проблему. Есть возражения?

Ответы [ 2 ]

6 голосов
/ 23 февраля 2011

Я наконец нашел проблему, и это было то, что SQLPrepare / SQLExecute psqlodbc по умолчанию не выполняет PREPARE / EXECUTE. Сам драйвер создает SELECT и отправляет его.

Решением является добавление UseServerSidePrepare=1 в файл odbc.ini или в ConnectionString для SQLDriverConnect. Общее время выполнения одного запроса, измеренного приложением, сократилось с> 100 мс до 5-10 мс.

1 голос
/ 22 февраля 2011

Я не думаю, что время между psql и вашей программой сопоставимо.

Может быть, я что-то упускаю, но в psql вы только готовите утверждения, но никогда не получаете данные.EXPLAIN PLAN также не отправляет данные

Таким образом, разница во времени, скорее всего, представляет собой сетевой трафик, необходимый для отправки всех строк с сервера на клиент.

Единственный способ сократить это время - либо получить более быструю сеть, либо выбрать меньшее количество столбцов.Вам действительно нужны все столбцы, которые включены в "alotofcolumns" ?

Добро пожаловать на сайт PullRequest, где вы можете задавать вопросы и получать ответы от других членов сообщества.

Нет похожих вопросов

...