Bug #60145 delay releasing process that used odbc connection
Submitted: 16 Feb 2011 16:52 Modified: 28 Feb 2011 8:52
Reporter: Flavio Martina Email Updates:
Status: In progress Impact on me:
None 
Category:Connector / ODBC Severity:S5 (Performance)
Version:5.01.08.00 OS:Microsoft Windows (x64)
Assigned to: CPU Architecture:Any
Tags: Delay, disconnect, ODBC, Process

[16 Feb 2011 16:52] Flavio Martina
Description:
I'm using the version 5.01.08.00 of mysql odbc driver in windows 7 x64 environment, i have found the same problems reported on mysql Bugs: #32366, where i have to wait at least second before a program that uses mysq odbc will disappears from task manager.
To reproduce the problems i report the same code and information as bug @ 32366
that has the state of closed but the problem still exist and create many problems when a program wait for a second one (using mysql odbc )to terminate before procede. Using a different odbc (for example microsoft sql or access) all works fine.

This is a MySQL / ODBC connector issue!

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.

Suggested fix:
No idea
[17 Feb 2011 7:57] Bogdan Degtyariov
Flavio,

I could not repeat the problem in my Windows 7 x64 system.
Both drivers (32 and 64-bit) worked well and wscript.exe (32 and 64-bit) disappeared from the process list immediately (I do not count 0.5 sec as significant delay).

Can you repeat your test in another x64 system?
Meanwhile setting the status "Can't repeat"
[17 Feb 2011 8:18] Flavio Martina
i did many test on windows server 2008 x86, windows server 2008 R2 x64, windows vista x64 and windows 7 and the results are the same, i have a long delay (about 20 seconds), before the process disappears.
My sql server is remote (another machine) connected via lan at 1 Gb.
Area you doing the test connecting locally ?
Flavio
[17 Feb 2011 8:41] Bogdan Degtyariov
Flavio,

I did tests for local and for remote mysql servers in a 1G LAN.
Result is the same - no delay.

Are you using ODBC pooling or ODBC trace? This could cause significant slow-down.

How much time does connecting take in average? Is it less than 20 sec?
[17 Feb 2011 9:09] Flavio Martina
I'm not using connection pooling and log are disabled.
The connection time is really fast and the disconnect too, the only problems is that the program that used the connection will not disappears fast from the task manager but remains active for at least 20 seconds after terminating.
The script is a simple way to reproduce the behavior.
It's strange that you don't have the same problems, on every machine i tested it (starting from vista, because xp and windows 2003 are working fine) i can reproduce the issue
[17 Feb 2011 11:13] Flavio Martina
Here is a depends trace about what is happening, after pushing the done button on the vbs there is a long delay before

Attachment: mysqltrace.txt (text/plain), 11.18 KiB.

[23 Feb 2011 7:35] Bogdan Degtyariov
Flavio,

I cannot explain why unloading myodbc5.dll takes so much time.
Perhaps you could try a free 64-bit developer version of Mimer ODBC trace, which puts the time and duration of ODBC operations in its trace:

http://developer.mimer.com/downloads/index.htm

At least it could give us a clue which function is causing the delay.
Thanks.
[24 Feb 2011 10:18] Flavio Martina
i cannot find the mimer odbc trace to download anywhere, but in the meantime i have found that the delay will occurs in the DLL_PROCESS_DETACH as show in the trace 
00:00:23.766: DllMain(0x6AFA0000, DLL_PROCESS_DETACH, 0x00000000) in "c:\program files\mysql\connector odbc 5.1\MYODBC5.DLL" called by thread 1.
00:00:46.266: DllMain(0x6AFA0000, DLL_PROCESS_DETACH, 0x00000000) in "c:\program files\mysql\connector odbc 5.1\MYODBC5.DLL" returned 1 (0x1) by thread 1.

I tried to recompile the connector odbc but i cannot find a version that i can download e recompile correctly, all that i test i will get different compilation error.
Any suggestion ?
[24 Feb 2011 15:19] Flavio Martina
After been able to recompile both the connector and the server (i had to download many different version to find one that could compile correctly), i have found that the delay will be introduced by the function WSACleanup called in my_end routine (source my_init.c inside library libmysql.dll), called during the event DLL_PROCESS_DETACH from dll.c in myodbc5 project.
I have found the following in microsoft WSACleanup documentation, that could explain my problem:

The WSACleanup function typically leads to protocol-specific helper DLLs being unloaded. As a result, the WSACleanup function should not be called from the DllMain function in a application DLL. This can potentially cause deadlocks. For more information, please see the DLL Main Function.

Removing the call to WSACleanup will remove my unload delay
[25 Feb 2011 5:59] Bogdan Degtyariov
Flavio,

There is no way WSACleanup() can be removed from DllMain() because WSACleanup() is actually called not in the driver, but in mysql client library, which is linked to the driver.

Probably my_init()/my_end() calls should be replaced by mysql_library_init()/mysql_library_end().
[25 Feb 2011 7:26] Flavio Martina
To verify that the problem was WSACleaup i have modified and recompiled the mysql client library and then i have linked to the driver, do you suggest to write a custom my_init and my_end calss directly inside the driver instead of linking the mysql client library ?
[25 Feb 2011 11:59] Bogdan Degtyariov
Flavio,

I built a 64-bit DLL for you, which uses mysql_library_init()/mysql_library_end() instead of my_init()/my_end.
It is really interesting to check how this change will affect the unloading time (for me it was still fractions of sec).

Please try from this FTP:

ftp.mysql.com/pub/mysql/download/myodbc5-5.1.8-Win64-r949.zip

Backup the old myodbc5.dll file and unzip the new one into the installation directory.
[25 Feb 2011 12:50] Flavio Martina
I have tested the dll you recompiled for me, and with this version the unload time is exactly the the same, but now i have the same wait time during connection (for example doing a test connection from odbc will need at least 20 seconds to complete, with previous drive was quite immediate.
Probably i'm missing something, but where can i find the mysql_library_init and mysql_library_end, i haven't found in mysql an mysql_connector_odbc project.

Rebuilding mysql project (release 5.1.54) commenting WSACleanup inside the my_end, ad then relinking the mysql_connector_odbc will result in fast unload, it seems that there is some deadlock as reported in the WSACleanup documentation.

void my_end(int infoflag)
{

....
....
...

#ifdef THREAD
  my_thread_end();
  my_thread_global_end();
#if defined(SAFE_MUTEX)
  /*
    Check on destroying of mutexes. A few may be left that will get cleaned
    up by C++ destructors
  */
  safe_mutex_end((infoflag & (MY_GIVE_INFO | MY_CHECK_ERROR)) ? stderr :
                 (FILE *) 0);
#endif /* defined(SAFE_MUTEX) */
#endif /* THREAD */
#ifdef __WIN__
  if (have_tcpip) {
//    WSACleanup();  -> I have commented this line of code
  }
#endif /* __WIN__ */
  my_init_done=0;
} /* my_end */
[25 Feb 2011 13:07] Flavio Martina
Here is the track with time about test, you will find a delay during startup (20 seconds) and a delay during unload 

00:00:01.498: Loaded "c:\windows\system32\WSHBTH.DLL" at address 0x000007FEF8EE0000.
00:00:01.529: Loaded "c:\program files\common files\microsoft shared\windows live\WLIDNSP.DLL" at address 0x000007FEF9280000.
00:00:01.560: Loaded "c:\windows\system32\PSAPI.DLL" at address 0x00000000772A0000.
00:00:21.590: Loaded "c:\windows\system32\WSHTCPIP.DLL" at address 0x000007FEFC1F0000.
00:00:21.590: Loaded "c:\windows\system32\RASADHLP.DLL" at address 0x000007FEF9270000.
00:00:21.684: Loaded "c:\windows\system32\ODBCCP32.DLL" at address 0x000007FEEB9F0000.
00:00:21.715: Loaded "c:\windows\system32\PROFAPI.DLL" at address 0x000007FEFD040000.
00:00:21.731: Loaded "c:\windows\system32\IPHLPAPI.DLL" at address 0x000007FEFABA0000.
00:00:21.731: Loaded "c:\windows\system32\WINNSI.DLL" at address 0x000007FEFAB90000.
00:00:21.731: Loaded "c:\windows\system32\FWPUCLNT.DLL" at address 0x000007FEF9E30000.
00:00:21.762: Loaded "c:\program files\widcomm\bluetooth software\BTMMHOOK.DLL" at address 0x0000000010000000.
00:00:48.267: Unloaded "c:\program files\mysql\connector odbc 5.1\MYODBC5.DLL" at address 0x000007FEE5210000.
00:00:48.267: Unloaded "c:\windows\system32\WSHTCPIP.DLL" at address 0x000007FEFC1F0000.
00:00:48.267: Unloaded "c:\windows\system32\NLAAPI.DLL" at address 0x000007FEFB310000.
00:00:48.267: Unloaded "c:\windows\system32\WINRNR.DLL" at address 0x000007FEF8F70000.
00:00:48.267: Unloaded "c:\windows\system32\NAPINSP.DLL" at address 0x000007FEF8F10000.
00:00:48.267: Unloaded "c:\windows\system32\PNRPNSP.DLL" at address 0x000007FEF8EF0000.
00:00:48.267: Unloaded "c:\windows\system32\WSHBTH.DLL" at address 0x000007FEF8EE0000.
00:00:48.267: Unloaded "c:\program files\common files\microsoft shared\windows live\WLIDNSP.DLL" at address 0x000007FEF9280000.
00:00:48.267: Unloaded "c:\windows\system32\FWPUCLNT.DLL" at address 0x000007FEF9E30000.
00:00:48.267: Unloaded "c:\windows\system32\MSISIP.DLL" at address 0x000007FEFAD20000.
00:00:48.267: Unloaded "c:\windows\system32\WSHEXT.DLL" at address 0x000007FEF2460000.
00:00:48.282: Unloaded "c:\windows\system32\COMDLG32.DLL" at address 0x000007FEFD4F0000.
00:00:48.282: Unloaded "c:\windows\winsxs\amd64_microsoft.windows.common-controls_6595b64144ccf1df_5.82.7600.16661_none_a44e1fc257f685f6\COMCTL32.DLL" at address 0x000007FEF5620000.
00:00:48.282: Unloaded "c:\program files (x86)\microsoft firewall client 2004\FWCWSP64.DLL" at address 0x0000000155600000.
00:00:48.282: Unloaded "c:\program files\common files\system\ole db\MSDASQLR.DLL" at address 0x0000000074BE0000.
00:00:48.282: Unloaded "c:\program files\common files\system\ado\MSADO15.DLL" at address 0x000007FEEA9A0000.
00:00:48.282: Unloaded "c:\windows\system32\SCROBJ.DLL" at address 0x000007FEF0CA0000.
00:00:48.282: Unloaded "c:\program files\common files\system\ole db\MSDASQL.DLL" at address 0x000007FEE9F60000.
00:00:48.282: Unloaded "c:\windows\system32\ODBC32.DLL" at address 0x000007FEED9C0000.
00:00:48.298: Unloaded "c:\program files\common files\system\ole db\MSDATL3.DLL" at address 0x000007FEF25D0000.
00:00:48.298: Unloaded "c:\windows\system32\COMSVCS.DLL" at address 0x000007FEE7440000.
00:00:48.298: Unloaded "c:\program files\common files\system\ole db\OLEDB32.DLL" at address 0x000007FEEA020000.
00:00:48.298: Unloaded "c:\program files\common files\system\ole db\OLEDB32R.DLL" at address 0x0000000074D20000.
00:00:48.298: Unloaded "c:\windows\system32\MSDART.DLL" at address 0x000007FEF0770000.
00:00:48.298: Unloaded "c:\windows\system32\VBSCRIPT.DLL" at address 0x000007FEEC030000.
00:00:48.298: Exited "c:\windows\system32\WSCRIPT.EXE" (process 0x18F8) with code 0 (0x0).
[28 Feb 2011 5:29] Bogdan Degtyariov
Flavio,

Thank you for your research, it is much appreciated.
If my_end() function causes delays during disconnect it means that other clients such as mysql command line (mysql.exe) is affected too.

Would you mind trying to connect to a remote server using 64-bit mysql command line (mysql.exe)? If the command line has this delay too it would be a very strong argument for removing WSACleanup() from the client library.

Thanks.
[28 Feb 2011 7:37] Flavio Martina
I seems that mysql is not affected by the delay to terminate the process after disconnecting.
Another point where i can find the delay is in the odbc test, after creating an odbc with odbcad32, i click on test button to verify if my configuration is working, the result will be connection successfully,after i have clicked ok i haveto wait about 20 second to get response fromthe odbcad (with recompiled myodbc5.dll without WSACleanup all works fine).
Keep in mind that i can find the problem even on x86 machines and not only x64, at today i have verified that only vista/7/2008 are affected (at today i not found a pc or server without the problem, and not only in my organization but outside too (completely different configuration), we have found it when some programs are waiting for a shell program using myodbc5.dll to terminate.
I't strange that you cannot reproduce the behavior.
[28 Feb 2011 8:14] Flavio Martina
Just one information about mysql and why it's working. The WSACleanup is documented that can potentially cause deadlocks if called inside DllMain function, that is the case of myodbc5.dll, mysql.exe is and executable with main function and not DllMain inside a .dll library, that's the difference.
Hope this help
Flavio
[28 Feb 2011 8:37] Flavio Martina
I have googled WSACleanup deadlocks, and i have found many interesting information, related to the fact that in the dllmain code is better to avoid calls to Winsock, and the information "When the Microsoft Internet Connection Firewall is enabled, the call to WSACleanup will produce a deadlock.". For testing i removed the isa client and in this environment condition the process terminates in less than one seconds. Reinstalling isa client will reintroduce the 20 seconds delay.
[28 Feb 2011 8:48] Bogdan Degtyariov
Thanks Flavio,

Your finding about Microsoft Internet Connection Firewall if very helpful.
I shall try to enable the MS Firewall and check if disconnect time changes.
[28 Feb 2011 8:52] Flavio Martina
For information, I was able to reproduce only with microsoft Isa Client and not with microsoft Firewall.
[14 Jun 2011 13:21] Fyodor Kupchik
If it help you guys - I have the same problem but I can describe two slightly different environments where the problem persists and where it isn't.
One computer has some device connected trough USB port (this USB device originally designed to work via COM port but also can work via adapter). The most interesting thing is that in case of USB connection application that should generate SQL statements via ODBC shows delay about 12 sec, sometimes less, sometimes much more. 
In case if the same device (well, not the same, but hardware is supposed to be the same - some Atmel based micro controller) is connected to computer via COM port the delay does not appear at all.

Hope it help to you to understand the cause of the error.

I'm trying to build mysql server from sources and apply mentioned above patch. 
Let's see if it can help.