Bug #5787 mysql_stmt_prepare upto 8 times slower
Submitted: 28 Sep 2004 13:07 Modified: 25 Jan 2005 0:02
Reporter: Nathaniel Blanchard Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:4.1.5 OS:Windows (Windows XP)
Assigned to: Konstantin Osipov CPU Architecture:Any

[28 Sep 2004 13:07] Nathaniel Blanchard
Description:
mysql_stmt_prepare is upto 8 times slower when run against a remote windows mysql server vs a mysql server either on the same machine or on a remote machine running a different OS.

How to repeat:
/*
    CREATE TABLE test ( Col1 INTEGER, Col2 INTEGER );
*/
    MYSQL mysql;
    MYSQL_STMT    *stmt;

    #define SELECT_QUERY "SELECT Col1, Col2 FROM test"

    if ( mysql_init(&mysql) == NULL )
    {
        printf( "mysql_init failed\n" );
        return 0;
    }

    if ( mysql_real_connect(&mysql,"nate","nate","nate","nate",0,NULL,0) == NULL )
    {
        printf( "mysql_real_connect failed\n" );
        return 0;
    }

    for ( int i = 0; i < 200; i++ )
    {
        stmt = mysql_stmt_init(&mysql);
        if ( stmt == NULL )
        {
            printf( "mysql_stmt_init failed\n" );
            return 0;
        }

        if ( mysql_stmt_prepare(stmt, SELECT_QUERY, strlen(SELECT_QUERY) ) != 0 )
        {
            printf( "mysql_stmt_prepare failed !%s!\n", mysql_stmt_error(stmt) );
            return 0;
        }

        mysql_stmt_close(stmt);
    }

    mysql_close(&mysql);

    return 0;

When that code is run against a local windows based mysql server OR its run against a remote linux mysql server, it executes very fast.  If you then run it against a remote windows mysql server (of equal hardware and configuration), it is VERY slow.
[29 Nov 2004 14:58] Nathaniel Blanchard
Its been 2 months, any update on this?
[29 Nov 2004 15:33] MySQL Verification Team
Sorry, I will give you a feedback today.
[29 Nov 2004 16:44] MySQL Verification Team
Thank you for the bug report. I modified your code sample just to display
the Server Info and the time. Below the output:

Localhost XP:
C:\temp>bug5787.exe
MySQL Server 4.1.8-nt-log
Time:  (0.28 sec)

XP  against Linux Slackware:

C:\temp>bug5787.exe
MySQL Server 4.1.8-debug-log
Time:  (8.08 sec)

XP Pro against  XP Home Edition

C:\temp>bug5787.exe
MySQL Server 4.1.8-nt-log
Time:  (39.86 sec)

#ifdef WIN32
#include <windows.h>
#include <winsock.h>
typedef unsigned __int64 ulonglong;
typedef __int64 longlong;
typedef unsigned long ulong;
#endif

#include <stdio.h>
#include <string.h>
#include <my_global.h>
#include <m_ctype.h>
#include <m_string.h>
#include <mysql.h>

static ulong start_timer(void)
{
 return clock();
}

static void nice_time(double sec,char *buff,bool part_second)
{
  ulong tmp;
  if (sec >= 3600.0*24)
  {
    tmp=(ulong) floor(sec/(3600.0*24));
    sec-=3600.0*24*tmp;
    buff=int2str((long) tmp,buff,10,1);
    buff=strmov(buff,tmp > 1 ? " days " : " day ");
  }
  if (sec >= 3600.0)
  {
    tmp=(ulong) floor(sec/3600.0);
    sec-=3600.0*tmp;
    buff=int2str((long) tmp,buff,10,1);
    buff=strmov(buff,tmp > 1 ? " hours " : " hour ");
  }
  if (sec >= 60.0)
  {
    tmp=(ulong) floor(sec/60.0);
    sec-=60.0*tmp;
    buff=int2str((long) tmp,buff,10,1);
    buff=strmov(buff," min ");
  }
  if (part_second)
    sprintf(buff,"%.2f sec",sec);
  else
    sprintf(buff,"%d sec",(int) sec);
}

static void end_timer(ulong start_time,char *buff)
{
  nice_time((double) (start_timer() - start_time) /
	    CLOCKS_PER_SEC,buff,1);
}

static void mysql_end_timer(ulong start_time,char *buff)
{
  buff[0]=' ';
  buff[1]='(';
  end_timer(start_time,buff+2);
  strmov(strend(buff),")");
}
 char		buff[160],time_buff[32];
  ulong		timer;

#define SELECT_QUERY "SELECT Col1, Col2 FROM test"

int main()
{
  MYSQL mysql;
  MYSQL_STMT    *stmt;

  timer=start_timer();

   if ( mysql_init(&mysql) == NULL )
    {
        printf( "mysql_init failed\n" );
        return 0;
    }

    if ( mysql_real_connect(&mysql,"192.168.0.33","miguel","nana","test",0,NULL,0) == NULL)
    {
        printf( "mysql_real_connect failed\n" );
        return 0;
    }
    
    printf( "MySQL Server %s\n", mysql_get_server_info(&mysql));

    for ( int i = 0; i < 200; i++ )
    {
        stmt = mysql_stmt_init(&mysql);
        if ( stmt == NULL )
        {
            printf( "mysql_stmt_init failed\n" );
            return 0;
        }

        if ( mysql_stmt_prepare(stmt, SELECT_QUERY, strlen(SELECT_QUERY) ) != 0)
        {
            printf( "mysql_stmt_prepare failed !%s!\n", mysql_stmt_error(stmt));
            return 0;
        }

        mysql_stmt_close(stmt);
    }

    mysql_close(&mysql);
    mysql_end_timer(timer,time_buff);

  printf("Time: %s\n", time_buff);
  return 0;
}
[29 Nov 2004 23:52] Konstantin Osipov
Nathaniel, Miguel,
the problem is most probably in the communication layer.
Could you check if the slowdown is present for mysql_real_query or any other 
simple network-bound command as well?
[30 Nov 2004 18:41] MySQL Verification Team
Konstatin,

I did another test and I found that the slowdown happens with:

mysql_stmt_prepare time: (0.21 sec)

we had sometime ago the same issue with MyODBC please read
the bug report:

http://bugs.mysql.com/bug.php?id=482

maybe is useful for your analyze.
[7 Dec 2004 18:52] Nathaniel Blanchard
Are you still needing something from me, or was Miguel's tip helpful enough to point you in the right direction?
[7 Dec 2004 22:17] Andr? Schršder
I have the exact same issue. It is killing my application since it basically does not work over remote connections. The prepare problem only occurs on SELECT queries using prepared statements. I have other parts of my app running INSERTS over prepared statements and they work fine in terms of performance.
[7 Dec 2004 23:24] Konstantin Osipov
Nathaniel,
I have no debugging envirionment under Windows.
This is going to slow down bugfixing (I will need to install Windows/MSDEV first).
As  it's suggested in comment for Bug#482, it's most probably a Windows TCP/IP stack
specific bug, something like described here: http://www.sun.com/sun-on-net/performance/tcp.slowstart.html
In case it's what I think, all we can do is to workaround it by playing with the size
of logical tcp/ip packets.
While I'm installing Windows and stuff you  can try this patch and see if it helps:
===== protocol.cc 1.94 vs edited =====
--- 1.94/sql/protocol.cc        2004-11-02 21:13:23 +03:00
+++ edited/protocol.cc  2004-12-08 02:23:31 +03:00
@@ -606,6 +606,9 @@
   }
 
   my_net_write(&thd->net, eof_buff, 1);
+#ifdef __WIN32__
+  net_flush(&thd->net);
+#endif
   DBUG_RETURN(prepare_for_send(list));
 
 err:
[8 Dec 2004 0:40] Andr? Schršder
I have tried the patch but it did not help at all. No difference.
[8 Dec 2004 11:15] Andr? Schršder
I have tested the same against a Linux 4.1.7 mysql and it does not produce the same problem. I used the same application and the same client libs etc.

It is the server side on a Win32 mysql 4.1.7 that exposes this BUG.
[9 Dec 2004 2:35] luigi mazzetti
just like 
MySQL Bugs: #482: ODBC and MySQL v4.1.0 on Windows gives ultraslow performance

This was supposed to be fixed (thats what I understood)
[9 Dec 2004 8:04] Konstantin Osipov
Yes, it was supposed to. And the fix is there. Now it must be failing/flushing in some other place.
[10 Dec 2004 16:26] Andr? Schršder
I have done loads of testing and the problem is definetly the server-side.

Whenever a prepare is issued, the entire server stalls. All other connections have to wait until the server is done. In this time, nothing much happens anymore. Depending on the server specs, it may take several seconds.

Once the statement is prepared, the issue does not occur anymore.
[15 Dec 2004 15:28] Andr? Schršder
Any progress on this issue?
[10 Jan 2005 14:47] Nathaniel Blanchard
Status?
[10 Jan 2005 20:19] Konstantin Osipov
The first day I'm back from vacation.
[19 Jan 2005 15:29] Konstantin Osipov
Nathaniel, others:
I have prepared testing environment for this bug, and run the tests.
For 1000 mysql_stmt_prepare calls across my home LAN I get 3 seconds when server is under Linux and 4 seconds for Windows version.
I'm using the latest BitKeeper tree, which is marked 4.1.10.
Is the bug reproducible in debug versions of the server?
[19 Jan 2005 15:33] Konstantin Osipov
I've forgotten to add, I'm using the following hardware:
The client is Intel Pentium M 1.4 running SuSE Linux 9.1, wireless connectivity to Linksys WRT54G
The server is MS Windows 2000 SP 4 running on AMD Athlon 2200+ or SuSE Linux running on the same hardware.

Another question: is the time to run the statements stable across many test runs?
[19 Jan 2005 15:58] MySQL Verification Team
Konstantin,

Notice that the test must be Windows against Windows.
Windows against Linux don't has the slower issue.
[19 Jan 2005 16:55] Konstantin Osipov
Yes, I can see it from your benchmarks, but originally it's been said that Windows server is slow when used from Linux. Which one is correct?
[19 Jan 2005 16:56] Nathaniel Blanchard
The only time we've experienced a problem is when the client is running on windows connecting to a remove windows mysql server.  If the server is changed to linux, everything works fine.
[19 Jan 2005 20:02] Konstantin Osipov
Nathaniel, could you try this very test against the latest server?
[19 Jan 2005 20:03] Nathaniel Blanchard
By latest do you mean 4.1.9 or you want me to checkout the latest 4.1.10 tree and compile it myself?  If the later, I've never done a source install on windows before, only linux.
[19 Jan 2005 20:59] Konstantin Osipov
4.1.9 is ok
[20 Jan 2005 8:56] Konstantin Osipov
I was able to verify it today on the following configuration:
- MySQL Server 4.1.9-vanilla Windows 2000 SP 4 AMD Athlon 2200+
- client program on Windows 2000 SP 4 AMD Athlon 1000
I'm getting the same extremely slow execution times, ~10 prepares per second.
[20 Jan 2005 9:30] MySQL Verification Team
Konstantin,

However we can't to discard the possibility that the results can
be obtained by not well Windows's TCP tunning stuff.
Below some document we need to analyze:

http://www.microsoft.com/technet/itsolutions/network/deploy/depovg/tcpip2k.mspx#EFAA
[20 Jan 2005 11:48] Konstantin Osipov
I digget it further, and Linux server - Windows client configuration is also quite slow for
me.
Packet flow of Linux-Windows configuration is only 30% higher than Linux-Linux and it can not explain 10 times slowdown I observed. As far as I can see higher number of packets
is caused by ack packets which are not piggy-backed by Windows TCP/IP sometimes.
Moreover, I measured the actual time it takes the server to prepare a statement - it's the
same in all setups, so the problem is apparently in the network layer.
[21 Jan 2005 18:02] Konstantin Osipov
Nathaniel, others:
I was able to pinpoint the problem. Just as it was expected, it's not in MySQL.
I verified it by checking that 99% of execution time, both on server and client sides,
is taken by read/write calls (send()/recv()).
Looking further, we have the following sequence of client-server messages, executed in a loop:

client -> server: mysql_stmt_prepare
server -> client: statement prepared ok, statement metadata
client -> server: mysql_stmt_close

Unrolling the loop gives us:
client -> server: mysql_stmt_close
client -> server: mysql_stmt_prepare
server -> client: statement prepared ok, statement metadata
client -> server: mysql_stmt_close
client -> server: mysql_stmt_prepare
server -> client: statement prepared ok, statement metadata

As you can see, there are two messages from the client to the server with no reply
in between.
This is what causes MySQL client on Windows to go mad.
Although TCP/IP requires every packet to be confirmed with an ACK (acknowledgement) packet, most of modern TCP/IP stacks (including the one implemented in Windows) perform 2 optimizations of this rule:
- if there is a response to the packet on hand, the ACK packet will be piggy-backed with this response (sent along with it to save bandwidth).
- additonally TCP/IP stacks use 'delayed acknowledgement'
algorithm, which requires the server to wait for some time before sending empty ACK packet, to increase chances to catch a packet with data.

In Windows 2000 default delayed-ack wait time is 0.2 seconds (200 milliseconds), 
(it's described in more detail at the link provided by Miguel).
This is what gives us ~200 seconds to execute 1000 iterations of the loop.

The problem is that the Windows client for some reason will not send COM_PREPARE packet until it has recieved an ACK to previous COM_STMT_CLOSE packet.
But the server on its behalf will not send ACK until delayed ack time expires.
Consequently we have a delay which the client spends in send() and the server spends
in recv() between every iteration of the loop.

Possible solutions to this problem are:
- disable delayed acknowledgements algorithm on the server side.
Having a Windows 2000 server, it can be done by setting TcpDelAckTicks to 0 in the registry.
- add a reply to COM_STMT_CLOSE so that on Windows the ACK can be quickly piggy-backed along with it.
- find out why the Windows client waits for this bloody ACK before it sends COM_PREPARE, but I wasn't able to do this.

I should also note that the example as it is is rather artificial and it should have less influence to performance in real-life applications. 
Nevertheless we'are going to fix the problem by adding a reply to COM_STMT_CLOSE.
[21 Jan 2005 18:32] Nathaniel Blanchard
This is great news!

While I agree that the test case is a bit contrived, what prompted me to write it is that our QA dept reported vast differences in the speed of our application based on what OS the MySQL server was running on.  After a bunch of testing, we narrowed the issue down to somewhere in the mysql api calls and not our own code.
[24 Jan 2005 3:54] Konstantin Osipov
Subject: bk commit - 4.1 tree (konstantin:1.2161) BUG#5787

ChangeSet
  1.2161 05/01/24 06:52:13 konstantin@mysql.com +1 -0
  Proposed fix for Bug#5787 "mysql_stmt_prepare is upto 8 times slower":
  it's crucial to disable Nagle algorithm on client for no-reply commands
  like mysql_stmt_free to always work fast.
  Nagle algorithm instructs the sender to buffer (store) data if any
  unacknowledged data is outstanding and the size of to-send data is less than
  the network segment. It was exactly the case with COM_STMT_CLOSE after
  COM_STMT_PREPARE, so the client was waiting for Nagle timer to expire or
   for ACK from the server, while the server was holding up ACK because of
  delayed acknowledgement algorithm.
  The tricky part is that we have been already disabling Nagle
  algorithm (by setting TCP_NODELAY)
  almost everywhere except Windows (and maybe Netware).
  It is the reason why the bug was repeatable only with Windows client.

  vio/viosocket.c
    1.26 05/01/24 06:52:08 konstantin@mysql.com +20 -14
    Proposed fix for Bug#5787 "mysql_stmt_prepare is upto 8 times slower":
    if we disable Nagle algorithm, do it everywhere.
    TODO: check Netware.
[24 Jan 2005 23:33] Konstantin Osipov
Pushed into 4.1 tree which is currently marked 4.1.10
[25 Jan 2005 0:02] Paul DuBois
Mentioned in 4.1.10 change notes.

Thanks for the report.