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

Test timeouts on CentOS - interaction between server and client stops

    XMLWordPrintable

Details

    Description

      We are getting random (rare) timeouts in buildbot on kvm-bintar-centos5-amd64. Here is an example:

      http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-centos5-amd64/builds/4623/steps/test/logs/stdio

      parts.partition_float_myisam             w2 [ fail ]  timeout after 900 seconds
      		 
              Test ended at 2017-02-08 22:14:47
      		 
       
      Test case timeout after 900 seconds
      		 
       
      == /usr/local/mariadb-10.2.4-linux-x86_64/mysql-test/var/2/log/partition_float_myisam.log == 
      -2.2250738585072014e-208
      		 
      0
      		 
      1.5
      		 
      1234.567
      		 
      2.2250738585072016e208
      		 
      select * from t2 where a=1234.567;
      		 
      a
      		 
      1234.567
      		 
      delete from t2 where a=1234.567;
      		 
      select * from t2;
      		 
      a
      		 
      -2.2250738585072016e208
      		 
      -1.5
      		 
      -1
      		 
      -2.2250738585072014e-208
      		 
      0
      		 
      1.5
      		 
      2.2250738585072016e208
      		 
      delete from t2;
      		 
      16384*3 inserts;

      Normally the test takes ~20 seconds there.

      The problem is reproducible by running the test on the VM with very high --repeat value – it happens, very roughly, once in 300-400 runs.

      The main part of the test is running 16K of single-row INSERTs into a MyISAM table. There is no concurrency, INSERTs are executed one by one. The problem occurs somewhere during this process, in random places, not at a specific row. When it happens, the server is still reachable, show process shows the connection being idle:

      MariaDB [(none)]> show processlist;
      		 
      +----+------+-----------------+------+---------+------+-------+------------------+----------+
      		 
      | Id | User | Host            | db   | Command | Time | State | Info             | Progress |
      		 
      +----+------+-----------------+------+---------+------+-------+------------------+----------+
      		 
      | 11 | root | localhost       | test | Sleep   |  188 |       | NULL             |    0.000 |
      		 
      | 12 | root | localhost:39097 | NULL | Query   |    0 | init  | show processlist |    0.000 |
      		 
      +----+------+-----------------+------+---------+------+-------+------------------+----------+
      		 
      2 rows in set (0.00 sec)

      (connection 11 is the one which has been performing updates). The table is healthy and responds to SELECTs. There is no disk space problem.

      When it stops, it stops seemingly forever. However, running gdb on the server sometimes "wakes it up", makes the flow to be resumed.

      Example of a stack trace from the server when it's in this state:

      Thread 7 (Thread 0x40a5f940 (LWP 31197)):
      		 
      #0  0x00000036df40ab00 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      		 
      #1  0x0000000000de58b9 in inline_mysql_cond_timedwait (arg=<value optimized out>) at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1175
      		 
      #2  timer_handler (arg=<value optimized out>) at /home/buildbot/buildbot/build/mysys/thr_timer.c:292
      		 
      #3  0x0000000000ce2d19 in pfs_spawn_thread (arg=<value optimized out>) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1862
      		 
      #4  0x00000036df406367 in start_thread () from /lib64/libpthread.so.0
      		 
      #5  0x00000036decd2f7d in clone () from /lib64/libc.so.6
      		 
       
      		 
      Thread 6 (Thread 0x4149f940 (LWP 31198)):
      		 
      #0  0x00000036df40ab00 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      		 
      #1  0x0000000000d217b7 in inline_mysql_cond_timedwait (control=0x16e7020, sleep_time=<value optimized out>) at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1175
      		 
      #2  my_service_thread_sleep (control=0x16e7020, sleep_time=<value optimized out>) at /home/buildbot/buildbot/build/storage/maria/ma_servicethread.c:115
      		 
      #3  0x0000000000d1acd4 in ma_checkpoint_background (arg=<value optimized out>) at /home/buildbot/buildbot/build/storage/maria/ma_checkpoint.c:708
      		 
      #4  0x0000000000ce2d19 in pfs_spawn_thread (arg=<value optimized out>) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1862
      		 
      #5  0x00000036df406367 in start_thread () from /lib64/libpthread.so.0
      		 
      #6  0x00000036decd2f7d in clone () from /lib64/libc.so.6
      		 
       
      		 
      Thread 5 (Thread 0x41f80540 (LWP 31199)):
      		 
      #0  0x00000036df40e1e8 in do_sigwait () from /lib64/libpthread.so.0
      		 
      #1  0x00000036df40e28d in sigwait () from /lib64/libpthread.so.0
      		 
      #2  0x00000000005461eb in signal_hand (arg=<value optimized out>) at /home/buildbot/buildbot/build/sql/mysqld.cc:3560
      		 
      #3  0x0000000000ce2d19 in pfs_spawn_thread (arg=<value optimized out>) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1862
      		 
      #4  0x00000036df406367 in start_thread () from /lib64/libpthread.so.0
      		 
      #5  0x00000036decd2f7d in clone () from /lib64/libc.so.6
      		 
       
      		 
      Thread 4 (Thread 0x41fca540 (LWP 31200)):
      		 
      #0  0x00000036df40a899 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      		 
      #1  0x000000000056aa90 in inline_mysql_cond_wait (arg=<value optimized out>) at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1138
      		 
      #2  handle_slave_background (arg=<value optimized out>) at /home/buildbot/buildbot/build/sql/slave.cc:339
      		 
      #3  0x0000000000ce2d19 in pfs_spawn_thread (arg=<value optimized out>) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1862
      		 
      #4  0x00000036df406367 in start_thread () from /lib64/libpthread.so.0
      		 
      #5  0x00000036decd2f7d in clone () from /lib64/libc.so.6
      		 
       
      		 
      Thread 3 (Thread 0x42014540 (LWP 31203)):
      		 
      #0  0x00000036decca436 in poll () from /lib64/libc.so.6
      		 
      #1  0x0000000000e7cf73 in vio_io_wait (vio=0x2aaac242b808, event=<value optimized out>, timeout=28800000) at /home/buildbot/buildbot/build/vio/viosocket.c:945
      		 
      #2  0x0000000000e7d2f3 in vio_socket_io_wait (vio=0x420135e0, event=VIO_IO_EVENT_WRITE) at /home/buildbot/buildbot/build/vio/viosocket.c:108
      		 
      #3  0x0000000000e7d57e in vio_read (vio=0x2aaac242b808, buf=0x2aaaacc34008 "\a", size=4) at /home/buildbot/buildbot/build/vio/viosocket.c:184
      		 
      #4  0x000000000054ed89 in my_real_read (net=0x2aaaacc14248, complen=0x42013780, header=1 '\001') at /home/buildbot/buildbot/build/sql/net_serv.cc:888
      		 
      #5  0x000000000054f19d in my_net_read_packet_reallen (net=0x420135e0, read_from_server=1 '\001', reallen=0x420137c8) at /home/buildbot/buildbot/build/sql/net_serv.cc:1158
      		 
      #6  0x000000000054f29d in my_net_read_packet (net=0x420135e0, read_from_server=1 '\001') at /home/buildbot/buildbot/build/sql/net_serv.cc:1142
      		 
      #7  0x00000000005f4988 in do_command (thd=0x2aaaacc14008) at /home/buildbot/buildbot/build/sql/sql_parse.cc:1242
      		 
      #8  0x00000000006d1fd5 in do_handle_one_connection (connect=0x1) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1354
      		 
      #9  0x00000000006d219f in handle_one_connection (arg=0x2aaac245a508) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1260
      		 
      #10 0x0000000000ce2d19 in pfs_spawn_thread (arg=<value optimized out>) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1862
      		 
      #11 0x00000036df406367 in start_thread () from /lib64/libpthread.so.0
      		 
      #12 0x00000036decd2f7d in clone () from /lib64/libc.so.6
      		 
       
      		 
      Thread 2 (Thread 0x4205e540 (LWP 31248)):
      		 
      #0  0x00000036df40ab00 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      		 
      #1  0x000000000054da53 in one_thread_per_connection_end (thd=0x2aaaad414008, put_in_cache=<value optimized out>)
      		 
          at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1175
      		 
      #2  0x00000000006d1f38 in do_handle_one_connection (connect=<value optimized out>) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1373
      		 
      #3  0x00000000006d219f in handle_one_connection (arg=0x2aaac245a8c8) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1260
      		 
      #4  0x0000000000ce2d19 in pfs_spawn_thread (arg=<value optimized out>) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1862
      		 
      #5  0x00000036df406367 in start_thread () from /lib64/libpthread.so.0
      		 
      #6  0x00000036decd2f7d in clone () from /lib64/libc.so.6
      		 
       
      		 
      Thread 1 (Thread 0x2aaac1ea2730 (LWP 31196)):
      		 
      #0  0x00000036decca436 in poll () from /lib64/libc.so.6
      		 
      #1  0x00000000005451e3 in handle_connections_sockets () at /home/buildbot/buildbot/build/sql/mysqld.cc:6626
      		 
      #2  0x000000000054bc6d in mysqld_main (argc=127, argv=0x2aaac2447a58) at /home/buildbot/buildbot/build/sql/mysqld.cc:6092
      		 
      #3  0x00000036dec1d974 in __libc_start_main () from /lib64/libc.so.6
      		 
      #4  0x0000000000540909 in _start ()

      Example of a stack trace from mysqltest:

      Thread 1 (Thread 0x2b675ed3ead0 (LWP 31223)):
      		 
      #0  0x00000036decca3ff in poll () from /lib64/libc.so.6
      		 
      #1  0x0000000000467d90 in pvio_socket_wait_io_or_timeout (pvio=<value optimized out>, is_read=<value optimized out>, timeout=-1)
      		 
          at /home/buildbot/buildbot/build/libmariadb/plugins/pvio/pvio_socket.c:511
      		 
      #2  0x0000000000467e27 in pvio_socket_read (pvio=0x7fff4c072860, buffer=0x10cd4450 "\a", length=16384) at /home/buildbot/buildbot/build/libmariadb/plugins/pvio/pvio_socket.c:279
      		 
      #3  0x0000000000455df0 in ma_pvio_read (pvio=0x10cd43e0, buffer=0x10cd4450 "\a", length=16384) at /home/buildbot/buildbot/build/libmariadb/libmariadb/ma_pvio.c:251
      		 
      #4  0x0000000000455f01 in ma_pvio_cache_read (pvio=0x7fff4c072860, buffer=0x10cd8460 "\"", length=4) at /home/buildbot/buildbot/build/libmariadb/libmariadb/ma_pvio.c:293
      		 
      #5  0x000000000046b6fb in ma_real_read (net=0x10cc2c10, complen=0x7fff4c0729b0) at /home/buildbot/buildbot/build/libmariadb/libmariadb/ma_net.c:376
      		 
      #6  0x000000000046b861 in ma_net_read (net=0x7fff4c072860) at /home/buildbot/buildbot/build/libmariadb/libmariadb/ma_net.c:430
      		 
      #7  0x0000000000453131 in ma_net_safe_read (mysql=0x10cc2c10) at /home/buildbot/buildbot/build/libmariadb/libmariadb/mariadb_lib.c:188
      		 
      #8  0x0000000000453465 in mthd_my_read_query_result (mysql=0x7fff4c072860) at /home/buildbot/buildbot/build/libmariadb/libmariadb/mariadb_lib.c:1955
      		 
      #9  0x000000000044dfbe in mysql_read_query_result (mysql=0x7fff4c072860) at /home/buildbot/buildbot/build/libmariadb/libmariadb/mariadb_lib.c:2136
      		 
      #10 0x0000000000449f29 in wrap_mysql_read_query_result (cn=0x10cbff18, command=0x10ce5528, flags=<value optimized out>, query=0x1 <Address 0x1 out of bounds>, query_len=0, 
          ds=0xbb2e20, ds_warnings=0x7fff4c072e10) at /home/buildbot/buildbot/build/client/../tests/nonblock-wrappers.h:324
      		 
      #11 run_query_normal (cn=0x10cbff18, command=0x10ce5528, flags=<value optimized out>, query=0x1 <Address 0x1 out of bounds>, query_len=0, ds=0xbb2e20, ds_warnings=0x7fff4c072e10)
      		 
          at /home/buildbot/buildbot/build/client/mysqltest.cc:7745
      		 
      #12 0x000000000044a958 in run_query (cn=0x10cbff18, command=0x10ce5528, flags=3) at /home/buildbot/buildbot/build/client/mysqltest.cc:8516
      		 
      #13 0x000000000044cd1b in main (argc=<value optimized out>, argv=<value optimized out>) at /home/buildbot/buildbot/build/client/mysqltest.cc:9296

      Attachments

        1. test2.sh
          59 kB
          Andrew Hutchings

        Issue Links

          duplicates

          Bug - A problem which impairs or prevents the functions of the product. MDEV-11805 main.alter_table_trans failed in buildbot with timeout

          • Minor - Minor loss of function, or other problem where easy workaround is present.
          • Closed
          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-12174 sys_vars.innodb_status_output_basic failed with timeout in buildbot on centos5

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-12788 Server hangs or Assertion `0' fails in Protocol::end_statement on SELECT with UNION

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Task - A task that needs to be done. MDEV-22672 10.5 bintar builders

          • Blocker - Blocks development and/or testing work, production could not run.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-12247 Server does not respond for simple query execution

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Activity

            People

              georg Georg Richter
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.