Bug #32366 ODBC Connection to MySQL using VBScript (WScript.exe)
Submitted: 14 Nov 2007 10:07 Modified: 11 Jan 2008 23:00
Reporter: dan matting Email Updates:
Status: Closed Impact on me:
None 
Category:Connector / ODBC Severity:S5 (Performance)
Version:3.51, 5.1 OS:Any
Assigned to: Jim Winstead CPU Architecture:Any

[14 Nov 2007 10:07] dan matting
Description:
I am having an issue with using the ODBC connector to MySQL in that when you use VBScript with this it takes 5 seconds to close WScript.exe after it has completed running the code.
This only occurs when you .Open an ADODB connection

My current MySQL version =
My current MySQL ODBC version =

This only occurs with MySQL, MsAccess doesn't cause this issue.

This is causing a massive issue as 5 times this script needs to be called but the software has to wait for WScript.exe to close before moving to the next one leaving a lag time of 5 seconds for each one!

How to repeat:
Create a file named VbScript.vbs and add this code:

Dim conn
Set conn = CreateObject("ADODB.Connection")
conn.open "DSN=DSNMy"
conn.close
set conn = Nothing
msgbox "done!"

Then save that and add an ODBC connection to MySQL database and table, providing login details etc.

Then open up task manager and select tab "Processes", run the the script by double clicking. Select OK to the message and look in task manager and count the seconds the Wscript.exe stays there after the message box has been selected.

This is a MySQL / ODBC connector issue!
[14 Nov 2007 10:09] dan matting
Oh dear forgot to add the versions: 
mysql-5.0.45-win32
mysql-connector-odbc-3.51.21-win32
[14 Nov 2007 10:10] dan matting
Test VBS file

Attachment: testdb.vbs (application/octet-stream, text), 116 bytes.

[14 Nov 2007 15:06] dan matting
This is I believe contributing to the fact the the simply "SELECT <field> from table" is taking 5 seconds to return, the table has 10 fields in it and only 64 rows!

Really is so
[15 Nov 2007 8:46] Mats Nilsson
I got the same thing. 

I have the same problem with an odbc-connection that I use in Paradox. 
Since the release of MySql ODBC Driver 3.51.16 my odbc-connections disconnects much slower then before, from instantaneously to 4-5 seconds. This may not sound much but in an application this becomes very annoying… 

The easiest way to test this is by hitting the Test-button in the ODBC Data Source Administrator and directly after closing the result messagebox try to close the connector window. I get that annoying delay. It used to close at once. 

My experiences so far: 
* MySql ODBC Driver 3.51.14 and 3.51.15 WinXP, disconnects is as fast as one can expect 
* MySql ODBC Driver 3.51.16 to 3.51.21 WinXP SP2, slow 
* MySql ODBC Driver 5.1.0-alpha WinXP SP2, slow 
* MySql ODBC Driver 3.51.19 Win2k, fast 
* MySql ODBC Driver 3.51.19 Win 2003 server, fast 
* MySql ODBC Driver 3.51.19 Win Vista, slow 
* I have tested against multiple servers, both linux and win, same result 
* I have tested against a server on localhost, same thing 
* I have tested against a MS SQL Server, fast 
* I have no problem with the reverse-dns loopup 
* I have tested with incorrect login, no difference from a correct login 
* I have tested to put skip-host-cache and skip-name-resolve in my.ini, still slow
[15 Nov 2007 9:46] dan matting
Also tried todays release of the new ODBC, still the problem remains!
Is anyone from MySQL looking at this yet?
[16 Nov 2007 7:56] dan matting
Has this even been reviewed yet?
[16 Nov 2007 9:19] Susanne Ebrecht
Hi,

do you check process rotation too? Are you really sure, that the process was the process with highest priority at the system?
Can it be, that windows first worked on other processes, before it kills this process?
[16 Nov 2007 9:33] Mats Nilsson
I can verify Dan’s problems with my way of testing it. (I have also verified his “version”) 

I have tested this many times on several computers with 100% accuracy regarding this problem, always the same delay. When we looked at the network traffic that occurs during this, the only thing that differs between 3.51.15 and the newer releases are that delay. The same network traffic occurs. When we did this we run the test computer as “clean” as possible to get the most reliable result. In my opinion this is not a problem due to a busy processor.
[19 Nov 2007 7:50] dan matting
Any progress?
[19 Nov 2007 12:02] Susanne Ebrecht
Please, add the trace file with the issue.
[19 Nov 2007 12:14] Mats Nilsson
Trace when hitting the test-button in ODBC-admin

Attachment: bug-data-32366-sql-trace.LOG (application/octet-stream, text), 2.72 KiB.

[19 Nov 2007 13:10] Susanne Ebrecht
Sorry, you told us, this only occurs with VB, so of course, we need the trace of the process of your VB script.
[19 Nov 2007 13:20] dan matting
where would I find this?
[19 Nov 2007 13:21] Mats Nilsson
Please check the history of this bug. Both Dan and I (Mats) have the same problem but two different ways to regenerate it. I have noticed that it only occurs when the last connection to the db closes.
[19 Nov 2007 14:53] Tonci Grgin
Hello all. I am sorry but this doesn't seem to be the problem with MyODBC but rather a problem with various SW/HW configurations...

I tested attached script on MySQL 5.0.50pb running on WinXP Pro SP2 localhost with  QCore CPU. MySQL server was idle (i.e. script was the only client). MyODBC is 3.51.21. Neither processlist nor CPU monitor show any deviation at all, as a matter of fact, I had hard time noticing script is running...

Please reconsider your environment, AV/FW software, server load etc. and retest.
[19 Nov 2007 15:01] Tonci Grgin
A few remarks:

1) Does not occur with 3 clients either on my box.
2) DM trace shows nothing of interest. Maybe "SHOW PROCESSLIST" (or even NETSTAT -a) at the time of lockup would help?
[19 Nov 2007 15:24] dan matting
Hello.  Just to confirm, you ran the vb script while task manager was open an Wscript.exe disappeared shortly after (under 5 seconds)?

Also on review I am getting this error in my Apache error log:
Error in my_thread_global_end(): 2 threads didn't exit

NOT using PHP and as I am using Apache cgi-bin a new connection is created everytime. and everytime it attempts to close I get that error in the log file.  This is the properable cause then?
[20 Nov 2007 6:55] Tonci Grgin
Dan, right. Maybe a better choice would be in a blink of an eye. Now I do not suggest there is absolutely no problem here but I need to be able to reproduce it before it can be fixed, right?

As for the second part of your problem, please check on Bug#29497, Bug#31687 or Bug#31802. There could be a connection to originally reported problem but it's not apparent to me. For the end, let me say MyODBC does not include any pooling mechanism so if this proves to be the source then it's in MySQL cli API and/or in Apache pooling...
[20 Nov 2007 8:16] dan matting
Thank you for your comments unfortunatly those links to prevouis bugs do not seem to be related in any way to this issue.

The issue is as mentioned that queries I taking 5 seconds each to return, these are simple queries on a very small table!
As stated in the WScript issue first raised there is a time delay for me using the VBScript NO APACHE involved in that area.  The issue must lay with the ODBC connector. 

There are countless forum entries for this thread issue in your forums and across the internet, stating the the libmysql.dll file must be replaced in the PHP and mySQL directories that then corrects this problem, but this also exists for VB uses whether this is Script or ASP and no solution is given. this is no doubt what is causing the problem of speed, as these last threads are being timed out.

I am willing to send over any log files you require, but please let me know where they are typically located.

Many thanks
[20 Nov 2007 11:01] Tonci Grgin
Dan, I'm simply saying that:
 1) I can't reproduce this behavior with script attached and nothing in between MyODBC and MySQL server 5.0.50.
 2) "Error in my_thread_global_end(): 2 threads didn't exit" should be C API bug report, not MyODBC, and definitely related to bugs mentioned above.

As for what logs you may provide let's try with:
 1) ODBC DM trace (Control Panel/Administrative Tasks/Data Sources (ODBC) "Tracing" tab
 2) Server error log (usually in datadir, named like <your host name>.err
 3) Relevant part of general query log (usually in datadir, named <your host name>.sql). If your MySQL server is started without logging, start it with --log or add "log" (no quotes) to [mysqld] in my.ini/cnf file
[20 Nov 2007 15:25] dan matting
these will be sent to you within the next 18 hours
Thank you
[21 Nov 2007 6:35] Mats Nilsson
Tonci, have you looked at my way of repeating this?
[21 Nov 2007 9:36] dan matting
Apologies for the delay:

My.INI settings:
---------------
#Enter a name for the query log file. Otherwise a default name will be used.
log=Q
#Enter a name for the error log file. Otherwise a default name will be used.
log-error=Errorlog

Q Content:
----------
071120 15:09:52	      4 Connect     test@100.1.100.01 on test
		      5 Connect     test@100.1.100.01 on test
		      4 Query       SET SQL_AUTO_IS_NULL = 0
		      5 Query       SET SQL_AUTO_IS_NULL = 0
		      4 Query       select database()
		      5 Query       select database()
		      4 Query       SELECT @@tx_isolation
		      5 Query       SELECT @@tx_isolation
		      4 Query       SELECT DISTINCT Id FROM table WHERE Id =                '109953' OR Id = '108' OR Id ='109953' OR Id = '1'
		      5 Query       SELECT DISTINCT text, tId FROM table WHERE Id = '109953' OR Id = '108' OR Id = '109953' OR Id='1'
		      4 Init DB     test
		      5 Init DB     test
		      4 Quit       
		      5 Quit       
071120 15:09:57	      6 Connect     test@100.1.100.01 on test
		      6 Query       SET SQL_AUTO_IS_NULL = 0
		      6 Query       select database()
		      6 Query       SELECT @@tx_isolation
		      6 Query       SELECT DISTINCT DATE_FORMAT(time, '%Y/%m/%d') date, DATE_FORMAT(time, '%T') time FROM table WHERE Id ='109953' OR Id = 				'108' OR Id = '109953' OR Id = '1' ORDER BY date
		      6 Query       SELECT DISTINCT DATE_FORMAT(time, '%Y/%m/%d') date, DATE_FORMAT(time, '%T') time FROM table WHERE Id = '109953' OR Id = 				'108' OR Id = '109953' OR Id = '1' ORDER BY date
		      6 Init DB     test
		      6 Quit

ErrorLog Content:
-----------------
071120 15:23:10  InnoDB: Starting shutdown...
071120 15:23:13  InnoDB: Shutdown completed; log sequence number 0 138846
071120 15:23:13 [Note] C:\Program Files\MySQL\MySQL Server 5.0\bin\mysqld-nt: Shutdown complete

071121  8:55:33  InnoDB: Started; log sequence number 0 138846
071121  8:55:36 [Note] C:\Program Files\MySQL\MySQL Server 5.0\bin\mysqld-nt: ready for connections.
Version: '5.0.45-community-nt-log'  socket: ''  port: 3306  MySQL Community Edition (GPL)

And the trace log "SQL.LOG", here I set to trace and returned to the DSN and selected "TEST" following this run the code:
----------------------------

odbcad32        7bc-564	ENTER SQLAllocHandle 
		SQLSMALLINT                  1 <SQL_HANDLE_ENV>
		SQLHANDLE           00000000
		SQLHANDLE *         0006D1E0

odbcad32        7bc-564	EXIT  SQLAllocHandle  with return code 0 (SQL_SUCCESS)
		SQLSMALLINT                  1 <SQL_HANDLE_ENV>
		SQLHANDLE           00000000
		SQLHANDLE *         0x0006D1E0 ( 0x00c61540)

odbcad32        7bc-564	ENTER SQLSetEnvAttr 
		SQLHENV             00C61540
		SQLINTEGER                 200 <SQL_ATTR_ODBC_VERSION>
		SQLPOINTER          0x00000003
		SQLINTEGER                   0 

odbcad32        7bc-564	EXIT  SQLSetEnvAttr  with return code 0 (SQL_SUCCESS)
		SQLHENV             00C61540
		SQLINTEGER                 200 <SQL_ATTR_ODBC_VERSION>
		SQLPOINTER          0x00000003 (BADMEM)
		SQLINTEGER                   0 

odbcad32        7bc-564	ENTER SQLAllocHandle 
		SQLSMALLINT                  2 <SQL_HANDLE_DBC>
		SQLHANDLE           00C61540
		SQLHANDLE *         0006D1E4

odbcad32        7bc-564	EXIT  SQLAllocHandle  with return code 0 (SQL_SUCCESS)
		SQLSMALLINT                  2 <SQL_HANDLE_DBC>
		SQLHANDLE           00C61540
		SQLHANDLE *         0x0006D1E4 ( 0x00c615e8)

odbcad32        7bc-564	ENTER SQLDriverConnectW 
		HDBC                00C615E8
		HWND                00000000
		WCHAR *             0x1F7A9B98 [      -3] "******\ 0"
		SWORD                       -3 
		WCHAR *             0x1F7A9B98 
		SWORD                        2 
		SWORD *             0x00000000
		UWORD                        0 <SQL_DRIVER_NOPROMPT>

odbcad32        7bc-564	EXIT  SQLDriverConnectW  with return code 0 (SQL_SUCCESS)
		HDBC                00C615E8
		HWND                00000000
		WCHAR *             0x1F7A9B98 [      -3] "******\ 0"
		SWORD                       -3 
		WCHAR *             0x1F7A9B98 
		SWORD                        2 
		SWORD *             0x00000000
		UWORD                        0 <SQL_DRIVER_NOPROMPT>

odbcad32        7bc-564	ENTER SQLDisconnect 
		HDBC                00C615E8

odbcad32        7bc-564	EXIT  SQLDisconnect  with return code 0 (SQL_SUCCESS)
		HDBC                00C615E8

odbcad32        7bc-564	ENTER SQLFreeHandle 
		SQLSMALLINT                  2 <SQL_HANDLE_DBC>
		SQLHANDLE           00C615E8

odbcad32        7bc-564	EXIT  SQLFreeHandle  with return code 0 (SQL_SUCCESS)
		SQLSMALLINT                  2 <SQL_HANDLE_DBC>
		SQLHANDLE           00C615E8

odbcad32        7bc-564	ENTER SQLFreeHandle 
		SQLSMALLINT                  1 <SQL_HANDLE_ENV>
		SQLHANDLE           00C61540

odbcad32        7bc-564	EXIT  SQLFreeHandle  with return code 0 (SQL_SUCCESS)
		SQLSMALLINT                  1 <SQL_HANDLE_ENV>
		SQLHANDLE           00C61540

Many thanks,

Dan
[22 Nov 2007 7:54] dan matting
Any progress?
[22 Nov 2007 8:33] Tonci Grgin
Hmm, there seems to be a problem as I'm able to see the delay as Mats reported:
"The easiest way to test this is by hitting the Test-button in the ODBC Data Source Administrator and directly after closing the result messagebox try to close the connector window. I get that annoying delay. It used to close at once."

This is not a CPU issue as my QCore does not go beyond 1% load on odbcad32.exe
So, to summarize, occasionally MyODBC disconnects slowly as of version 3.51.15. This seems to be related to some sort of cleanup as MySQL server general query log shows no delay:
071122  9:29:40	      6 Connect     root@localhost on test
		      6 Query       SET SQL_AUTO_IS_NULL = 0
071122  9:29:41	      6 Quit       
All logs look normal.

Will consult on this.
[22 Nov 2007 11:58] Tonci Grgin
Seems this is related to Bug#25621 (thanks Shane), in my_thread_global_end there's a delay to wait for threads to end:

uint 		my_thread_end_wait_time= 5;

void my_thread_global_end(void)
{
   struct timespec abstime;
   my_bool all_threads_killed= 1;
   set_timespec(abstime, my_thread_end_wait_time);
   pthread_mutex_lock(&THR_LOCK_threads);
   while (THR_thread_count > 0)
   {
     int error= pthread_cond_timedwait(&THR_COND_threads, &THR_LOCK_threads,
                                       &abstime);
     if (error == ETIMEDOUT || error == ETIME)
     {
       if (THR_thread_count)
         fprintf(stderr,
                 "Error in my_thread_global_end(): %d threads didn't exit\n",
                 THR_thread_count);
       all_threads_killed= 0;
       break;
     }
   }
[22 Nov 2007 12:16] dan matting
Thank you for the response.
Whoever as this is VBScript code how do you suggest I connect to mysqlclient.lib, rather than using the standard:

driver={MySQL ODBC 3.51 Driver}
or using ODBC?
?
[22 Nov 2007 12:17] dan matting
Also that file mysqlclient doesn't appear to be within the installation files?
[23 Nov 2007 7:47] dan matting
Any update on this? I am really pushed for time now and am going to have to consider using a different product to need my needs very soon, which is a real same as I am very very happy with the product minus this big fundimental issue.
[23 Nov 2007 12:59] dan matting
Has there been any developments on this issue from the post added yesterday?
[24 Nov 2007 1:41] Jim Winstead
This problem is caused by the application (or its environment) creating threads after the driver is loaded, but those threads not ending before the driver is unloaded again. This causes a delay on unloading as the client library gives those extra threads time to end.

It may be possible to disable this timeout from within the driver, and it's something we're looking into doing.

A workaround for this problem is to keep the driver loaded.

A full solution to this problem is going to take some time, but I hope we can resolve it before the next monthly release.

Note: this problem is easy to reproduce using the 'Test' button on the setup dialog. I was not able to reproduce it using a VBS script that just opened and closed a connection.
[26 Nov 2007 7:47] dan matting
Thank you for your response.
Unfortuantly the connection cannot be kept open as the VBScript has to be called each time for this process to work, this is the way the app intergrates with Apache and it simply is not possible to change.

I hope this can be completed soon as this problem has been an issue reported on so many forums and gone unanswered for non-PHP users!

I look forward to your fix soon,

Thank you again
[27 Nov 2007 8:35] dan matting
Any chance you have a date for the next ODBC release?
[28 Nov 2007 10:48] dan matting
Sorry for pushing but I really do need an expected date, is this likely to be in the next week or before christmas or after?
Thank you again for the support
[29 Nov 2007 8:06] dan matting
Any developments?
[29 Nov 2007 8:20] Jess Balint
Dan, The next release of the 3.51 series of drivers will likely be released early to mid December. If the patch is submitted and reviewed before that release, the fix will be included.
[3 Dec 2007 16:45] Don Cohen
Just to clarify ...

I think this all means that the message from MySQL server
  Error in my_thread_global_end(): xxx threads didn't exit
is now considered to be a bug in ODBC 3.51.<some number of recent versions>

Is that correct?  

And that we can fix it in the near future by getting the next version of ODBC 3.51, right?
[3 Dec 2007 16:52] Jim Winstead
No, an error message from the server is not an ODBC driver bug. Such an error message from an application that uses the ODBC driver is a problem with the ODBC driver that we hope to have fixed in the next 3.51 release.
[3 Dec 2007 17:20] Don Cohen
The last comment makes no sense to me.  My interpretation of the first sentence is exactly the opposite of my interpretation of the second sentence.

 > No, an error message from the server is not an ODBC driver bug.
says this particular bug, which results in a message that originates from the the server and shows up in the application that is using the odbc driver, is not a bug in the odbc driver
 > Such an error message from an application that uses the ODBC driver is a 
 > problem with the ODBC driver that we hope to have fixed in the next 3.51 
 > release.
says that this error message IS a bug in the odbc driver

Please clarify.
[3 Dec 2007 17:29] Jim Winstead
Your misunderstanding is "this particular bug, which results in a message that originates from the the server". The message you are seeing does not originate from the server, it comes from the client library used by the driver. There was an older bug where the server itself would print this message (to wherever it is that server output is set to go, not to client applications), but this bug was fixed in recent server versions.
[3 Dec 2007 17:45] Don Cohen
I begin to understand, but how can I tell whether the error message I see in the shell where I run an application originates from the server or from the odbc driver?  When I found the error message in the server code I assumed that was the origin.  In fact I'm using server version 5.0.18, which I understand is before the fix.  Perhaps you're saying that the server message would end up in the server log, and would not be sent to the application?
[18 Dec 2007 20:25] Jim Winstead
Simplify thread init/deinit and avoid delay when closing driver with un-deinited threads

Attachment: bug32366.diff (text/plain), 3.28 KiB.

[19 Dec 2007 12:42] dan mat
So is a new version of the driver ready to download?
Can't see it.
Cheers,
[19 Dec 2007 13:58] Tonci Grgin
Dan, it's "Patch pending" so I don't see it committed in source trees. Latest snapshots can be found at http://downloads.mysql.com/snapshots.php.
[21 Dec 2007 21:18] Lawrenty Novitsky
patch has been reviewed
[4 Jan 2008 8:14] dan mat
Is there going to be a full release on the 3.51 version of the ODBC driver? If so when?

Cheers,

Dan
[4 Jan 2008 10:04] Tonci Grgin
Dan, we have our procedure... you should be patient just for little while as patch is approved thus you'll probably find it in next release. Or you may test snapshots (check in ChangeLog if it contains fix for your problem). As for release cycle, we try to keep it on monthly basis but that might not be possible in all cases.
[10 Jan 2008 8:47] MC Brown
A note has been added to the 3.51.23 changelog: 

Cleaning up environment handles in multithread environments
could result in a five (or more) second delay.
[11 Jan 2008 23:00] Jim Winstead
This is fixed in 3.51.23, and will also be fixed in the next 5.1 release.
[4 Mar 2008 0:39] Mary Miller-Clark
I have been having same problem as dan.  Where can I download ODBC 3.51.23? I am looking at Commercial MySQL (Connector) download page https://oem.mysql.com/connector-odbc.php?product=c-odbc&version=3.51 and can't find it there.
thanks,
mary
[5 Mar 2008 8:22] Tonci Grgin
Mary, it will take couple of weeks more until release is out. If you want you can open support issue regarding this but I don't think it's a good idea to press ODBC team to release prematurely.
[26 Oct 2010 6:35] Bogdan Degtyariov
The problem has not been solved for Unix/Linux systems.
To be continued in bug #57727