1. 首頁
  2. 問答
  3. Postgres通過ODBC查詢速度慢一個數量級？

Postgres通過ODBC查詢速度慢一個數量級？

2011-02-22 134 views
6

我們有一個應用程序，它通過psqlodbc 09.00.0200司機會從一個PostgreSQL 9.0.3數據庫中的一些數據如下方式：Postgres通過ODBC查詢速度慢一個數量級？

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與參數1設置爲SQL_FETCH_RELATIVE和參數2設定爲1
5）SQLExecute與參數1設置爲SQL_FETCH_RELATIVE和參數2設定爲-1
6）SQLExecute與參數1設置爲SQL_FETCH_RELATIVE和參數2設定爲0
7）解除分配所有，靠近光標，結束事務

功能fetchcur執行FETCH RELATIVE $3 IN $1 INTO rec其中rec是記錄並返回該記錄。在用戶請求中一再執行步驟4-6，同時在此事務中執行更多的查詢。在另一個用戶請求發出之前還需要相當長的時間。通常情況下，需要querys該長：

4）〜130毫秒
5）〜115毫秒
6）〜110毫秒

這通常太慢了快捷的用戶體驗。所以我從psql命令行\ timing中嘗試了相同的語句。對於步驟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 GB的RAM和參數設置爲：

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


編輯：我剛剛發現瞭如何創建一個psqlodbc mylog，但我找不到時機值在那裏。

編輯2：也可以添加時間戳到每一行。這真的表明，在psqlodbc驅動程序收到響應之前，它需要> 100ms。所以我再次嘗試psql並添加了選項-h 127.0.0.1以確保它也通過TCP/IP。 psql的結果是< 10ms。這怎麼可能？

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：我意識到我沒有在psql測試之前使用的相同的查詢從mylog。看起來psqlodbc對於SQLPrepare和SQLExecute不使用PREPARE。它添加參數值併發送查詢。 as araqnid建議我將log_duration param設置爲0，並將postgresql日誌的結果與app和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的調用更改爲通過SQLExecDirect執行的顯式PREPARE/EXECUTE語句可以解決該問題。有什麼異議？

來源

2011-02-22 rudi-moore

+0

「00：07：51.133 [3086550720] !!! poll ret = 1 revents = 1」 - 您是否添加了感嘆號來突出顯示此行或者它們是輸出的一部分？就在上面，它發送了一個保存點命令，並且得到了一個快速響應，所以它似乎沒有網絡滯後。儘管它似乎正在爲實際查詢結果獲得更大的數據塊，這並不奇怪...... – araqnid 2011-02-23 00:31:53

+1

嘗試爲該數據庫用戶設置`log_duration`，並查看服務器端上的postgresql是否記錄了從服務器運行它比使用psql直接運行時花費的時間更長。 – araqnid 2011-02-23 00:35:12

回答

6

我終於找到了問題，它是psqlodbc的SQLPrepare/SQLExecute默認不執行PREPARE/EXECUTE。驅動程序本身構建SELECT併發送它。

解決方法是將UseServerSidePrepare=1添加到odbc.ini或SQLDriverConnect的ConnectionString。從應用程序測量的一個查詢的總執行時間從> 100ms降至5-10ms。

來源

2011-02-23 18:33:48

1

我不認爲psql和你的程序之間的時間是可比的。

也許我錯過了一些東西，但在psql中，您只准備了語句，但從未真正獲取數據。 EXPLAIN PLAN不發送數據

因此，時差最可能是將所有行從服務器發送到客戶端所需的網絡流量。

減少這個時間的唯一方法是獲得更快的網絡或選擇更少的列。您是否真的需要包含在「alotofcolumns」中的所有列？

來源

2011-02-22 20:45:07

相關問題

 相關問題