search

lurcher / unixODBC

The unixODBC Project goals are to develop and promote unixODBC to be the definitive standard for ODBC on non MS Windows platforms.
GNU Lesser General Public License v2.1
103 stars 52 forks source link

Sporadic delays between calls of SQLFetchScroll.c and SQLEndTran.c when retrieving data from DB2 for i #153

Closed ic1011 closed 11 months ago

ic1011 commented 11 months ago

Hello!

Usually everything works fine but every now and then there is this delay that varies from a few seconds up to a minute. Here is an excerpt from a trace:

[ODBC][1198197][1702470772.713006][SQLFetchScroll.c][159] Entry: Statement = 0x557d694b68e0 Fetch Orentation = 1 Fetch Offset = 0 [ODBC][1198197][1702470772.713081][SQLFetchScroll.c][356] Exit:[SQL_NO_DATA] [ODBC][1198197][1702470788.059248][SQLEndTran.c][417] Entry: Connection = 0x557d694301b0 Completion Type = 1 [ODBC][1198197][1702470788.059784][SQLGetInfo.c][236]

Notice the huge difference between the two timestamps 1702470772.713081 and 1702470788.059248. Now if the same set of queries (only SELECT statements) are executed again immediately after that, there won't be any delay.

Here is the content of odbcinst.ini:

[iSeries Access ODBC Driver] Description=IBM i Access for Linux 64-bit ODBC Driver Driver=/opt/ibm/iaccess/lib64/libcwbodbc.so Setup=/opt/ibm/iaccess/lib64/libcwbodbcs.so Threading=0 DontDLClose=1 UsageCount=1 CPTimeout=0

The app doesn't use explicit transactions, only implicit ones - auto-commit mode.

I'm not sure if the issue is due to unixODBC or PDO_ODBC, or even the app somehow, but I'll be thankful if you could shed some light on the matter and provide some pointers.

The system uses PDO_ODBC and unixODBC to connect to DB2 for i.

Thank you in advance.

kadler commented 11 months ago

Doing trace exit is almost the last thing that the driver manager does before returning to the caller: https://github.com/lurcher/unixODBC/blob/9b31cd228d01e768a7ad9126d5da8860f1ed72a9/DriverManager/SQLFetchScroll.c#L349-L362

The only other thing it does is call function_return, which depending on the return code and the defer type will retrieve diagnostics from the driver. @lurcher would be better to confirm that it is calling that, but that would be my guess. If not, then the time must be spent in app/middleware.

Looking at the driver, I don't think this would cause us to send a flow to the server. AFAICT, we just copy the data we have in to the buffer provided (though it may go through a couple levels of character conversion in the process). If you suspect there's something in the driver, you can open a ticket with IBM service and we can look at a driver trace.

lurcher commented 11 months ago

On 14/12/2023 10:44, ic1011 wrote:

Hello!

Usually everything works fine but every now and then there is this delay that varies from a few seconds up to a minute. Here is an excerpt from a trace:

[ODBC][1198197][1702470772.713006][SQLFetchScroll.c][159]
Entry:
Statement = 0x557d694b68e0
Fetch Orentation = 1
Fetch Offset = 0
[ODBC][1198197][1702470772.713081][SQLFetchScroll.c][356]
Exit:[SQL_NO_DATA]
[ODBC][1198197][1702470788.059248][SQLEndTran.c][417]
Entry:
Connection = 0x557d694301b0
Completion Type = 1
[ODBC][1198197][1702470788.059784][SQLGetInfo.c][236]

Notice the huge difference between the two timestamps 1702470772.713081 and 1702470788.059248. Now if the same set of queries (only SELECT statements) are executed again immediately after that, there won't be any delay.

Yep, as Kevin mentioned, AFAIK if I was presented with that log, I would suggest the 16 seconds is spent in the application. At 1702470772 (Wed, 13 Dec 2023 12:32:51 GMT) it exits the driver manager from a SQLFetchScroll() call. Then at 1702470788 (12:33:08) the application calls SQLEndTran()

ic1011 commented 11 months ago

Thank you, guys, for the quick and detailed response!

Any chance that the delay is due to the retrieval of diagnostics from the driver? AFAICT, in my case I think that the DM is skipping the retrieval of diagnostcs due to the value of the DEFER_R3 parameter, but I could be wrong.

Opening a ticket with IBM would be a bit cumbersome as I would have to go through some extra hoops in order to do it and I would rather take this path only as a last resort. But if it is of any help, here is a concerning part of a driver's trace (of different session):

Date;Time;Component;ProcessID;ThreadID;

2023-12-13;20:11:42.388;ODBC;1203018;1203018;10008;ODBC Application version: 3.x Wide

.....
.....

2023-12-13;20:11:46.407;ODBC;1203018;1203018;10008;0x5680: odbcapi.SQLCloseCursor Exit rc=0
2023-12-13;20:11:46.407;ODBC;1203018;1203018;10008;0x5680: odbcapi.SQLFreeHandle Entry
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:enq Entry
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:sendBeverly Entry
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;TCP:send Entry
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;send buffered:40
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;TCP:send Exit rc=0
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:sendBeverly Exit rc=0
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:enq Exit rc=0
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:enq Entry
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:sendBeverly Entry
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;TCP:send Entry
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;send buffered:40
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;TCP:send Exit rc=0
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:sendBeverly Exit rc=0
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:enq Exit rc=0
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:enq Entry
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:sendBeverly Entry
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;TCP:send Entry
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;send buffered:40
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;TCP:send Exit rc=0
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:sendBeverly Exit rc=0
2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:enq Exit rc=0
+2023-12-13;20:11:46.407;ODBC;1203018;1203018;10008;0x5680: odbcapi.SQLFreeHandle Exit rc=0
-2023-12-13;20:12:55.502;ODBC;1203018;1203018;10008;0x180: odbcapi.SQLEndTran Entry
2023-12-13;20:12:55.502;Comm-Base;1203018;1203018;2;SVR:enq Entry
2023-12-13;20:12:55.502;Comm-Base;1203018;1203018;2;SVR:sendBeverly Entry
2023-12-13;20:12:55.502;Comm-Base;1203018;1203018;2;TCP:send Entry
2023-12-13;20:12:55.502;Comm-Base;1203018;1203018;2;send buffered:47
2023-12-13;20:12:55.503;Comm-Base;1203018;1203018;2;TCP:send Exit rc=0

I'm going to open an issue with PHP as they support the PDO_ODBC.

Thank you again for taking the time to look into the issue.

lurcher commented 11 months ago

On 15/12/2023 17:01, ic1011 wrote:

Thank you, guys, for the quick and detailed response!

Any chance that the delay is due to the retrieval of diagnostics from the driver? AFAICT, in my case I think that the DM is skipping the retrieval of diagnostcs due to the value of the DEFER_R3 parameter, but I could be wrong.

Opening a ticket with IBM would be a bit cumbersome as I would have to go through some extra hoops in order to do it and I would rather take this path only as a last resort. But if it is of any help, here is a concerning part of a driver's trace (of different session):

I would have expected to see the diag calls in the driver manager log. TBH, I would not bother with the driver and asking IBM as the log you have sent suggests very strongly that its not spending any time in the driver or for that matter the driver manager.

Is the calling code part of a large PDO application, or can you strip it down to a small snippet of code that shows the problem? Perefably that could be run from the command line, given that it should be simple to debug whats going on the PDO.

Date;Time;Component;ProcessID;ThreadID;

2023-12-13;20:11:42.388;ODBC;1203018;1203018;10008;ODBC Application version: 3.x Wide

..... .....

2023-12-13;20:11:46.407;ODBC;1203018;1203018;10008;0x5680: odbcapi.SQLCloseCursor Exit rc=0 2023-12-13;20:11:46.407;ODBC;1203018;1203018;10008;0x5680: odbcapi.SQLFreeHandle Entry 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:enq Entry 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:sendBeverly Entry 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;TCP:send Entry 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;send buffered:40 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;TCP:send Exit rc=0 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:sendBeverly Exit rc=0 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:enq Exit rc=0 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:enq Entry 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:sendBeverly Entry 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;TCP:send Entry 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;send buffered:40 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;TCP:send Exit rc=0 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:sendBeverly Exit rc=0 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:enq Exit rc=0 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:enq Entry 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:sendBeverly Entry 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;TCP:send Entry 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;send buffered:40 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;TCP:send Exit rc=0 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:sendBeverly Exit rc=0 2023-12-13;20:11:46.407;Comm-Base;1203018;1203018;2;SVR:enq Exit rc=0 +2023-12-13;20:11:46.407;ODBC;1203018;1203018;10008;0x5680: odbcapi.SQLFreeHandle Exit rc=0 -2023-12-13;20:12:55.502;ODBC;1203018;1203018;10008;0x180: odbcapi.SQLEndTran Entry 2023-12-13;20:12:55.502;Comm-Base;1203018;1203018;2;SVR:enq Entry 2023-12-13;20:12:55.502;Comm-Base;1203018;1203018;2;SVR:sendBeverly Entry 2023-12-13;20:12:55.502;Comm-Base;1203018;1203018;2;TCP:send Entry 2023-12-13;20:12:55.502;Comm-Base;1203018;1203018;2;send buffered:47 2023-12-13;20:12:55.503;Comm-Base;1203018;1203018;2;TCP:send Exit rc=0

Again, the driver log is showing the time being lost between the SQLFreeHandle Exit and the SQLEndTran entry.

kadler commented 11 months ago

I agree with @lurcher's assessment, the time is definitely spent outside of the driver.

ic1011 commented 11 months ago

I would have expected to see the diag calls in the driver manager log. TBH, I would not bother with the driver and asking IBM as the log you have sent suggests very strongly that its not spending any time in the driver or for that matter the driver manager. Is the calling code part of a large PDO application, or can you strip it down to a small snippet of code that shows the problem? Perefably that could be run from the command line, given that it should be simple to debug whats going on the PDO.

Thank for your suggestion and apologies for not replying sooner.

The calling logic is part of a larger and complex enterprise application, but in the meantime I managed to trace the application server and it turned out, as you've already deduced, that the issue has nothing to do with the driver manager, the driver or the PDO.

Thank you both for your efforts and I wish you a happy New Year!