Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-3758

LP:1035271 - ruby dbi connection to Mariadb break after beeing idle for 10 minutes

    Details

    • Type: Bug
    • Status: Closed
    • Resolution: Incomplete
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None
    • Labels:

      Description

      ruby dbi connection to Mariadb break after beeing idle for 10 minutes

      I use:

      • debian squeeze
      • mariadb 5.3.7-mariadb116~squeeze
      • libdbd-mysql-ruby1.8 0.4.4-1
      • libdbi-ruby1.8 0.4.3-2
      • libmysql-ruby1.8 2.8.2-1
      • libruby1.8 1.8.7.302-2squeeze1
      • libmysqlclient16 5.3.7-mariadb116~squeeze

      ruby dbi connection to Mariadb break after beeing idle for 10 minutes and doing
      a query again. Code to reproduce:

      #!/usr/bin/env ruby

      require 'dbi'
      require 'date'

      DBNAME='test'
      DBSOCKET='/var/run/mysqld/mysqld.sock'
      DBUSER='test'
      DBPASS='test'

      1. for testing purpose just create a test db:
      2. create database test;
      3. and grant select:
      4. grant select on test.* to 'test'@'localhost' identified by 'test';

      wait_min=[9,10,11]

      db = DBI.connect("DBI:Mysql:database=#

      {DBNAME}

      ;socket=#

      {DBSOCKET}

      ", DBUSER, DBPASS)

      wait_min.each do | n |
      i = n*60
      puts DateTime.now()
      puts "do query: SELECT 1;"
      query=db.prepare("SELECT 1;")
      query.execute
      query.fetch_array
      query.finish
      puts "sleep for #

      {n}

      min."
      sleep
      end

      puts "Disconnect:"
      db.disconnect

      Waiting for 9 minutes and doing a 'SELECT 1;' works, waiting for 10 minutes lead to the error:

      /usr/lib/ruby/1.8/dbd/Mysql.rb:106:in `error': MySQL server has gone away (DBI::DatabaseError)
      from /usr/lib/ruby/1.8/dbd/mysql/statement.rb:42:in `execute'
      from /usr/lib/ruby/1.8/dbi/handles/statement.rb:116:in `execute'
      from test_db2.rb:25
      from test_db2.rb:20:in `each'
      from test_db2.rb:20

      An excerpt of an strace log running these program:

      connect(3,

      {sa_family=AF_FILE, path="/var/run/mysqld/mysqld.sock"}

      , 110) = 0
      setsockopt(3, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0\0\0\0\0\0\0\0\0\0\0\0", 16) = 0
      setsockopt(3, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0\0\0\0\0\0\0\0\0\0\0\0", 16) = 0
      brk(0xde7000) = 0xde7000
      setsockopt(3, SOL_IP, IP_TOS, [8], 4) = -1 EOPNOTSUPP (Operation not supported)
      setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
      read(3, "c\0\0\0\n5.3.7-MariaDB-mariadb116~sq"..., 16384) = 103
      stat("/usr/share/mysql/charsets/Index.xml",

      {st_mode=S_IFREG|0644, st_size=18261, ...}

      ) = 0
      open("/usr/share/mysql/charsets/Index.xml", O_RDONLY) = 4
      read(4, "<?xml version='1.0' encoding=\"ut"..., 18261) = 18261
      close(4) = 0
      write(3, "U\0\0\1\215\242\10\0\0\0\0@\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 89) = 89
      read(3, "\7\0\0\2\0\0\0\2\0\0\0", 16384) = 11
      stat("/etc/localtime",

      {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
      fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
      mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f489e3d4000
      write(1, "2012-08-10T11:51:16+02:00\n", 26) = 26
      write(1, "do query: SELECT 1;\n", 20) = 20
      poll([{fd=3, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
      write(3, "\n\0\0\0\3SELECT 1;", 14) = 14
      read(3, "\1\0\0\1\1\27\0\0\2\3def\0\0\0\0011\0\f?\0\1\0\0\0\10\201\0\0\0\0"..., 16384) = 56
      write(1, "sleep for 9 min.\n", 17) = 17
      select(0, NULL, NULL, NULL, {540, 0}) = 0 (Timeout)
      stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}

      ) = 0
      write(1, "2012-08-10T12:00:16+02:00\n", 26) = 26
      write(1, "do query: SELECT 1;\n", 20) = 20
      poll([

      {fd=3, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
      write(3, "\n\0\0\0\3SELECT 1;", 14) = 14
      read(3, "\1\0\0\1\1\27\0\0\2\3def\0\0\0\0011\0\f?\0\1\0\0\0\10\201\0\0\0\0"..., 16384) = 56
      write(1, "sleep for 10 min.\n", 18) = 18
      select(0, NULL, NULL, NULL, {600, 0}) = 0 (Timeout)
      stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
      brk(0xe0a000) = 0xe0a000
      brk(0xe05000) = 0xe05000
      write(1, "2012-08-10T12:10:16+02:00\n", 26) = 26
      write(1, "do query: SELECT 1;\n", 20) = 20
      poll([{fd=3, events=POLLIN|POLLPRI}

      ], 1, 0) = 1 ([

      {fd=3, revents=POLLIN|POLLHUP}

      ])
      read(3, "", 8192) = 0
      shutdown(3, 2 /* send and receive */) = 0
      close(3) = 0
      rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
      rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
      write(2, "/usr/lib/ruby/1.8/dbd/Mysql.rb:1"..., 45) = 45
      write(2, ": ", 2) = 2
      write(2, "MySQL server has gone away", 26) = 26
      write(2, " (", 2) = 2
      write(2, "DBI::DatabaseError", 18) = 18
      write(2, ")\n", 2) = 2
      write(2, "\tfrom /usr/lib/ruby/1.8/dbd/mysq"..., 63) = 63
      write(2, "\tfrom /usr/lib/ruby/1.8/dbi/hand"..., 66) = 66
      write(2, "\tfrom test_db2.rb:25\n", 21) = 21
      write(2, "\tfrom test_db2.rb:20:in `each'\n", 31) = 31
      write(2, "\tfrom test_db2.rb:20\n", 21) = 21
      rt_sigaction(SIGINT,

      {SIG_DFL, [INT], SA_RESTORER|SA_RESTART, 0x7f489d0a8230}

      ,

      {0x7f489df4fd60, [], SA_RESTORER, 0x7f489dcabff0}

      , 8) = 0
      exit_group(1) = ?

      I have tested this Program with mysqld 5.1.63 and it works as expected. The difference between mysqld 5.1.63 and
      mariadb 5.3.7-mariadb116~squeeze is that the poll before sending the new query will be answered by Mariadb after 10 minutes idle,
      but not by mysqld 5.1.63. (look at line 19,27,37 of the strace log).

      The only workaround I can imagin is to do keep alive querys on idle connections.

        Gliffy Diagrams

          Attachments

            Activity

            Hide
            elenst Elena Stepanova added a comment -

            Re: ruby dbi connection to Mariadb break after beeing idle for 10 minutes
            Hi,

            I ran your script on MariaDB 5.3.7 (my local installation from a binary tarball), and I didn't hit the issue, both 10 and 11 min work as expected.

            What you observe looks like you have wait_timeout=600 configured somewhere for your MariaDB instance (but not for MySQL).

            Could you please connect to your servers, both of them, and check the value of wait_timeout?
            Only, if you do it with an interactive client, you need to check the GLOBAL value, e.g.

            SELECT @@global.wait_timeout;

            (It is important because the session timeout would be initialized differently).

            Thanks.

            Show
            elenst Elena Stepanova added a comment - Re: ruby dbi connection to Mariadb break after beeing idle for 10 minutes Hi, I ran your script on MariaDB 5.3.7 (my local installation from a binary tarball), and I didn't hit the issue, both 10 and 11 min work as expected. What you observe looks like you have wait_timeout=600 configured somewhere for your MariaDB instance (but not for MySQL). Could you please connect to your servers, both of them, and check the value of wait_timeout? Only, if you do it with an interactive client, you need to check the GLOBAL value, e.g. SELECT @@global.wait_timeout; (It is important because the session timeout would be initialized differently). Thanks.
            Hide
            hubertkrause Hubert Krause added a comment -

            Re: ruby dbi connection to Mariadb break after beeing idle for 10 minutes
            Hi,

            Sorry, I've send my reply with the wrong email adress, thats why it take so long. Now here my reply:

            I am Sorry for this wrong Bugreport because:

            > SELECT @@global.wait_timeout;

            gives 28800 on the mysql5.1 server and 600 on the mariadb server. If I
            delete the setting "wait_timeout = 600" from my.cnf (yes, I didn't look
            there before reporting this bug... sorry again) "SELECT @@global.wait_timeout;"
            gives 28800.

            But nevertheless it is a strange default in my.cnf for wait_timeout
            because the difference between internal default of 28800 and the
            configured default of 600 in the my.cnf delivered by
            mysql-common_5.3.7-mariadb116~squeeze package from
            http://mirror2.hs-esslingen.de/mariadb/repo/5.3/debian is big. Maybe
            this setting should be removed in future versions of this package.

            Thank you very much for your help,

            Hubert Krause

            Show
            hubertkrause Hubert Krause added a comment - Re: ruby dbi connection to Mariadb break after beeing idle for 10 minutes Hi, Sorry, I've send my reply with the wrong email adress, thats why it take so long. Now here my reply: I am Sorry for this wrong Bugreport because: > SELECT @@global.wait_timeout; gives 28800 on the mysql5.1 server and 600 on the mariadb server. If I delete the setting "wait_timeout = 600" from my.cnf (yes, I didn't look there before reporting this bug... sorry again) "SELECT @@global.wait_timeout;" gives 28800. But nevertheless it is a strange default in my.cnf for wait_timeout because the difference between internal default of 28800 and the configured default of 600 in the my.cnf delivered by mysql-common_5.3.7-mariadb116~squeeze package from http://mirror2.hs-esslingen.de/mariadb/repo/5.3/debian is big. Maybe this setting should be removed in future versions of this package. Thank you very much for your help, Hubert Krause
            Hide
            ratzpo Rasmus Johansson added a comment -

            Launchpad bug id: 1035271

            Show
            ratzpo Rasmus Johansson added a comment - Launchpad bug id: 1035271

              People

              • Assignee:
                Unassigned
                Reporter:
                hubertkrause Hubert Krause
              • Votes:
                0 Vote for this issue
                Watchers:
                0 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: