[Sqlrelay-discussion] Unknown prepared statement handler?

[<ni...@sk...>]

Hi Folks,

I've recently been evaluating SqlRelay and have been impressed by what
it's been able to do for my problem. Thanks for making it available!

What's going on?
----------------

Before deploying it, I ran a soak test to investigate it's ability to
handle sustained load. The actual soak test went very well, but I did
encounter one problem in this situation:

  * SqlRelay is configured to have between 50 and 100 client connections
  * SqlRelay starts up fine
  * Load test runs successfully and completes OK
  * SqlRelay ramps down the number of open client connections to 0
  * A number of hours pass...
  * Subsequent accesses to SqlRelay fail with the following error message:

Unknown prepared statement handler (322816) given to mysql_stmt_close

This appears to be repeatable, and only occurs after the SqlRelay process
has been idle for some time.

Has anyone experienced this, and did you manage to fix it?


Thanks in advance for your help,


Nick


============
System setup
============

Source and OS versions
----------------------

  Sql Relay version : 0.40, built from source
  Rudiments version : 0.32, built from source

  SqlRelay host OS version : Redhat Enterprise Linux 4

  Database : MySQL enterprise 5.0.48-enterprise-gpl-log
  Database host OS version : Redhat linux 5

  Perl version : 5.8.8, 64 bit compile

Config file setup
-----------------

  <?xml version="1.0"?>
  <!DOCTYPE instances SYSTEM "sqlrelay.dtd">
  <instances>

  <!--
  This is some junk to make SQLrelay parse its XML correctly.
  Without this, one part of the system doesn't start up properly.

  It isn't actually used.
  -->

  <instance id="dummy" port="12009" socket="/tmp/sybase-dummy.socket"
  dbase="freetds" connections="5" maxconnections="20" maxqueuelength="5"
  growby="1" ttl="60" endofsession="commit" sessiontimeout="600"
  runasuser="studma" runasgroup="users" cursors="10" authtier="listener"
  handoff="pass" deniedips="" allowedips="" debug="none"
  maxquerysize="65536" maxstringbindvaluelength="4000"
  maxlobbindvaluelength="71680" idleclienttimeout="-1" maxlisteners="-1"
  listenertimeout="0" reloginatstart="false">
  <users>
  <user user="user" password="pw"/>
  </users>
  <connections>
  <connection connectionid="sybase-ba1"
  string="user=sa;password=;server=SYBTEST;db=ba31;charset=iso_1;"
  metric="1" behindloadbalancer="no"/>
  </connections>
  </instance>

  <!-- This is the configuration which I actually use -->

  <instance id="mysqltest" port="9000" socket="/tmp/mysqltest.socket"
   dbase="mysql" connections="50" maxconnections="100" maxqueuelength="0"
   growby="5" ttl="60" endofsession="commit" sessiontimeout="600"
   runasuser="npavey" runasgroup="design" cursors="25" authtier="listener"
   handoff="pass" idleclientimeout="10" maxlisteners="100"
   listenertimeout="120">

   <users>
      <user user="mysqltest" password="mysqltest"/>
   </users>

   <connections>
      <connection connectionid="mysqltest" string="user=redbase_ad
password=nezjJGDG;db=trs_benchmarking;host=
bd-midir005;port=3306" metric="1"/>
   </connections>

   </instance>

   </instances>


Command line used
-----------------

  sqlr-start -id mysqltest -config <absolute path
root>/sqlrelay-0.40/config_file/conf.xml


client side code being issued
------------------------------

use SQLRelay::Connection;
use SQLRelay::Cursor;

my $sqlr_con = SQLRelay::Connection->new($host,$port,"",$user,$password,0,1);
my $sqlr_cur = SQLRelay::Cursor->new($sqlr_con);

my $sql = "SELECT MIN(test_id) FROM test_table";
my $start_tid = select_scalar($sqlr_cur, $dat_file, $sql);


sub select_scalar {
  my ($sqlr_cur, $dat_file, $sql) = @_;

  my $limit = 5;
  my $count = 0;

  for ($count; $count < $limit; $count++) {
    my $rtn = $sqlr_cur->sendQuery($sql);

    if ($rtn == 0) {
      my $err_msg = $sqlr_cur->errorMessage();

      # These errors are generally caused by too much
      # traffic at the SQLrelay. They should be recoverable
      # provided the traffic doesn't stay high for very long periods.
      SWITCH : {

	if ($err_msg =~ /Too many listeners/ ) {
	  print "\nEncountered 'too many listeners' error - backing off and
retrying\n";
	  last SWITCH;
	}

	if ($err_msg =~ /Failed to authenticate/ ) {
	  print "\nEncountered 'failed to authenticate' error - backing off and
retrying\n";
	  last SWITCH;
	}

	# If we didn't match the error, then throw a fatal error.
	write_cx_error($sqlr_cur->errorMessage(), $dat_file);

      } # end of SWITCH

      my $delay = int (rand (15) );

      print "  current retry : $count\n";
      print "  retry limit : $limit\n";
      print "  backoff length : $delay\n\n";

      sleep $delay;

    } else {

      # We got a success code, so we don't need to repeat the query
      # drop out of the FOR loop
      last;
    }

  } # end of FOR loop

  if ($count == $limit) {
    my $msg = "Retry limit reached.\n";
    $msg .= "$sql\n";

    die "$msg\n";
  }

  my $data_val = $sqlr_cur->getField(0,0);

  return $data_val;
}

Investigation so far
--------------------

I did check whether the system is still running. I checked the contents of
the 'pids' directory and things appear to be OK. The listener, scalar,
cachemanager and connection processes are still running.

I also ran 'strace' on the listener when I ran the SQL which caused the
problem:

  strace -p 5788
  Process 5788 attached - interrupt to quit
  select(8, [3 4 5 6 7], NULL, NULL, NULL) = 1 (in [6])
  accept(6, {sa_family=AF_INET, sin_port=htons(59954),
    sin_addr=inet_addr("165.204.20.21")}, [3668744855036624912]) = 58
  setsockopt(58, SOL_TCP, TCP_NODELAY, [4294967297], 4) = 0
  semop(2031623, 0x4, 5340896)            = 0
  clone(child_stack=0,
     flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
     child_tidptr=0x2a95c438b0) = 31717
  close(58)                               = 0
  select(8, [3 4 5 6 7], NULL, NULL, NULL) = ? ERESTARTNOHAND (To be
restarted)
  --- SIGCHLD (Child exited) @ 0 (0) ---
  wait4(-1, NULL, WNOHANG, NULL)          = 31717
  wait4(-1, NULL, WNOHANG, NULL)          = -1 ECHILD (No child processes)
  rt_sigreturn(0xffffffffffffffff)        = -1 EINTR (Interrupted system
call)
  select(8, [3 4 5 6 7], NULL, NULL, NULL <unfinished ...>

And I also ran strace on the scaler:

  strace -p 6877
  Process 6877 attached - interrupt to quit
  semop(2031623, 0x8, 5313712)            = 0
  semop(2031623, 0x8, 5313488)            = 0
  semop(2031623, 0x8, 5313552)            = 0
  semop(2031623, 0x8, 5313904)            = 0
  semop(2031623, 0x8, 5313712 <unfinished ...>