MySQL Bugs: #3757: Connection across network to 4.1.1a sporadically slow

Bug #3757	Connection across network to 4.1.1a sporadically slow
Submitted:	14 May 2004 8:10	Modified:	31 May 2013 6:57
Reporter:	Scott Huston	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	Connector / ODBC	Severity:	S3 (Non-critical)
Version:	4.1.1a	OS:	Windows (Win2000)
Assigned to:	Assigned Account	CPU Architecture:	Any

Description:
Client=ASP/MyODBC 3.51.06, Win2k server
Server=MySQL 4.0.x upgrade to 4.1.1a, Win2k server

Existing application connects remotely to 4.0.x server and the connections form in less than 10ms, often less than 1ms.  When the server was upgraded to 4.1.1a, connections regularly take 1500ms to form.  Sometimes, they form at 4.0.x speeds, but not often.

I don't believe this is a duplicate of #482 which addressed query performance, which in this case appears to be fine, though I haven't pursued as it is irrelevant given the connection performance.

Interestingly, if you run the script below on the server, the performance is fast, but not consistent, with most connections completing in an indistinguishably small period, but occassionally taking 70-90ms.

How to repeat:
Client: Install Win2k server, Install myODBC 3.51.06 (also reproduced with .04)
Server: Install Win2k server, Install 4.0.18
Create and run the following .vbs on the client
<BOF>
Dim oConnMaster

For x = 1 to 50
    ConnectMaster
    oConnMaster.Close
    Set oConnMaster=Nothing
    wscript.sleep 100
Next

Function ConnectMaster
    Dim tBegRtn

    tBegRtn=Timer

    On Error Resume Next
    ConnectMaster = False

	Set oConnMaster = CreateObject("ADODB.Connection")
	oConnMaster.mode = 3 'adModeReadWrite
	oConnMaster.Open "Driver={MySQL ODBC 3.51 Driver};" & _
		"server=database;" & _
		"database=rh5_master;" & _
		"Option=131072;" & _
		"uid=rhUser;" & _
		"pwd=inspectMe"
	If Err.Number = 0 Then ConnectMaster = True

	tTotal = (Timer-tBegRtn)
	'if tTotal <> 0 Then
	wscript.echo tTotal & " seconds<br>"

	On Error Goto 0
End Function
<EOF>

Observer time, install 4.1.1a on server, repeat.
<<Note: Without

Thank you for writting to us and thanks for the nice test case.

What we need to know additionally is whether you use 4.1.1 passwords as well.

In that case slowdown is expected, as beside many additional checks that new protocol has (and new features) authentication with new passwords will take much longer time.

I am not using 4.1+ passwords.  I first detected this when I was testing a server that was running 4.1.1a as a replication client to a 4.0.15 system.  Everything was replicated, including the mysql database.  I stopped replication to test further.  Ran 4.0.18 against the same data directories, switched back to 4.1.1a (several times) and had 100% reproducible results.  I did not run any conversion of any database structures or content.  It is probable that had not been done since 4.0.5, in fact.

Just retested this with 4.1.7-nt and 3.51.10.  Same behavior.  I explicitly reset the account passord using the OLD_PASSWORD() function, also.

I tested this issue using Connector/ODBC 3.51.09 and also with a C
API application linked against the mysqlclient.lib and I only was able
to reproduce the behavior between an XP Home Edition and XP Pro.

Between the XP Home Edition and Windows 2003 Server I wasn't 
able to repeat. When I got this result I did a new fresh install
of XP Pro (without to apply the SP2) and then the sporadic
slow connection goes away, so something  in the OS's
environment is causing this issue.

Tested against server 4.1.8.
The client application used is Access 2003.

Are you sure that NetBIOS name lookup performed by Windows during connection establishemnt is switched off or succeeds? 1500 milliseconds is the standard delay Windows will wait before re-attemting the NetBIOS name resolving procedure.
For example, this is tcpdump of an attempt to establish connection between Linux client
and Windows server, as you can see Windows performs 3 attempts to resolve NetBIOS name of the Linux machine, despite getting the response that the appropriate port is closed.
I haven't yet figured out how to disable this procedure (Hartmut, do you know?),
however, quick search suggests that it's a common problem and is possible to do.

dragonfly:/home/kostja # tcpdump host 192.168.1.104 and host 192.168.1.103
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth1, link-type EN10MB (Ethernet), capture size 96 bytes
19:11:21.022750 IP 192.168.1.104.48618 > 192.168.1.103.opsession-prxy: S 367259605:367259605(0) win 5840 <mss 1460,sackOK,timestamp 1136419301 0,nop,wscale 0>
19:11:21.024423 IP 192.168.1.103.opsession-prxy > 192.168.1.104.48618: S 2774199443:2774199443(0) ack 367259606 win 65535 <mss 1460,nop,wscale 0,nop,nop,timestamp 0 0,nop,nop,sackOK>
19:11:21.024471 IP 192.168.1.104.48618 > 192.168.1.103.opsession-prxy: . ack 1 win 5840 <nop,nop,timestamp 1136419303 0>
19:11:21.028822 IP 192.168.1.103.netbios-ns > 192.168.1.104.netbios-ns: NBT UDP PACKET(137): QUERY; REQUEST; BROADCAST
19:11:21.028842 IP 192.168.1.104 > 192.168.1.103: icmp 86: 192.168.1.104 udp port netbios-ns unreachable
19:11:22.527520 IP 192.168.1.103.netbios-ns > 192.168.1.104.netbios-ns: NBT UDP PACKET(137): QUERY; REQUEST; BROADCAST
19:11:22.527562 IP 192.168.1.104 > 192.168.1.103: icmp 86: 192.168.1.104 udp port netbios-ns unreachable
19:11:24.027540 IP 192.168.1.103.netbios-ns > 192.168.1.104.netbios-ns: NBT UDP PACKET(137): QUERY; REQUEST; BROADCAST
19:11:24.027583 IP 192.168.1.104 > 192.168.1.103: icmp 86: 192.168.1.104 udp port netbios-ns unreachable
19:11:25.527749 IP 192.168.1.103.opsession-prxy > 192.168.1.104.48618: P 1:59(58) ack 1 win 65535 <nop,nop,timestamp 9270 1136419303>
19:11:25.527957 IP 192.168.1.104.48618 > 192.168.1.103.opsession-prxy: . ack 59 win 5840 <nop,nop,timestamp 1136423807 9270>
19:11:25.528118 IP 192.168.1.104.48618 > 192.168.1.103.opsession-prxy: P 1:17(16) ack 59 win 5840 <nop,nop,timestamp 1136423807 9270>
19:11:25.530534 IP 192.168.1.103.opsession-prxy > 192.168.1.104.48618: P 59:134(75) ack 17 win 65519 <nop,nop,timestamp 9270 1136423807>
19:11:25.531250 IP 192.168.1.103.opsession-prxy > 192.168.1.104.48618: F 134:134(0) ack 17 win 65519 <nop,nop,timestamp 9270 1136423807>
19:11:25.531962 IP 192.168.1.104.48618 > 192.168.1.103.opsession-prxy: F 17:17(0) ack 135 win 5840 <nop,nop,timestamp 1136423811 9270>
19:11:25.533583 IP 192.168.1.103.opsession-prxy > 192.168.1.104.48618: . ack 18 win 65519 <nop,nop,timestamp 9270 1136423811>

This is the log of mysql -ukostja --host=192.168.1.103, the connection is refused by the server because there is no password provided. The client is Linux SuSE 9.1, the server is Windows 2000 SP4, MySQL 4.1.10.

If it happens to be another problem, I'd like to have a similar trace to work on it.
Thank you.

Given that I was reproducing this problem with the same client, going to the same server, and only changing what version of MySQL was running, I don't think  the NetBIOS resolution would have changed.

That said, I can not currently reproduce this with 
3.51.06/4.1.17-nt (both Win2K Srv SP4...both with all patches) or 
3.51.10/4.1.17-nt (WinXProSP2/Win2K Srv SP4...both with all patches.)

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Bingo.  I think that's it.  I'm not sure why there's a NetBIOS issue.  It happens even when I specify the host as an IP addr, but when I put the client node in the server's LMHOSTS file, no more delay.  Why wasn't this a reverse DNS?

Thank you for taking the time to write to us, but this is not a bug. Please double-check the documentation available at http://dev.mysql.com/doc/ and the instructions on
how to report a bug at http://bugs.mysql.com/how-to-report.php