Bug #32366 ODBC Connection to MySQL using VBScript (WScript.exe)
Submitted: 14 Nov 2007 11:07 Modified: 12 Jan 2008 0:00
Reporter: dan matting
Status: Closed
Category:Connector/ODBC Severity:S5 (Performance)
Version:3.51, 5.1 OS:Any
Assigned to: Jim Winstead Target Version:

[14 Nov 2007 11: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 11: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 11:10] dan matting
Test VBS file

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

[14 Nov 2007 16: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 9: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 10: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 8:56] dan matting
Has this even been reviewed yet?
[16 Nov 2007 10: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 10: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 8:50] dan matting
Any progress?
[19 Nov 2007 13:02] Susanne Ebrecht
Please, add the trace file with the issue.
[19 Nov 2007 13: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 14: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 14:20] dan matting
where would I find this?
[19 Nov 2007 14: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 15: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 16: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 16: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 7: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 9: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 12: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 16:25] dan matting
these will be sent to you within the next 18 hours
Thank you
[21 Nov 2007 7:35] Mats Nilsson
Tonci, have you looked at my way of repeating this?
[21 Nov 2007 10: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 8:54] dan matting
Any progress?
[22 Nov 2007 9: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 12: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 13: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 13:17] dan matting
Also that file mysqlclient doesn't appear to be within the installation files?
[23 Nov 2007 8: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 13:59] dan matting
Has there been any developments on this issue from the post added yesterday?
[24 Nov 2007 2: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 8: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 9:35] dan matting
Any chance you have a date for the next ODBC release?
[28 Nov 2007 11: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 9:06] dan matting
Any developments?
[29 Nov 2007 9: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 17: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 17: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 18: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 18: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 18: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 21: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 13:42] dan mat
So is a new version of the driver ready to download?
Can't see it.
Cheers,
[19 Dec 2007 14: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 22:18] Lawrin Novitsky
patch has been reviewed
[4 Jan 2008 9: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 11: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 9: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.
[12 Jan 2008 0:00] Jim Winstead
This is fixed in 3.51.23, and will also be fixed in the next 5.1 release.
[4 Mar 2008 1: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 9: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.