[MDEV-12247] Server does not respond for simple query execution Created: 2017-03-13  Updated: 2017-09-26  Resolved: 2017-04-04

Status: Closed
Project: MariaDB Server
Component/s: Scripts & Clients
Affects Version/s: 10.2.4
Fix Version/s: 10.2.5

Type: Bug Priority: Critical
Reporter: FLAESCH Sebastien Assignee: Georg Richter
Resolution: Fixed Votes: 0
Labels: 10.2-rc
Environment:

Linux Debian 8.6 / 64bits, Windows 10 / 64bits


Attachments: File MDEV-12247.c     Text File gdb-mysqld-001.txt     Text File mysql-strace-MDEV-12247.txt    
Issue Links:
Relates
relates to MDEV-12084 Test timeouts on CentOS - interaction... Open
Sprint: 10.2.6-2, 10.2.6-3

 Description   

Same code working with 10.1 now hangs when executing a simple SELECT ...
So far could only enable server log to see what happens.
Must investigate to enable more detailed log or debug info... any suggestion is welcome.

Tcp port: 3309  Unix socket: /opt3/dbs/mdb/10.2/data/mysqld.sock
Time                 Id Command    Argument
170313 18:36:53	    7 Connect	mysuser@localhost as anonymous on test1
		    7 Query	SELECT @@version
		    7 Query	SET autocommit=1
		    7 Prepare	delete from dbit2
		    7 Execute	delete from dbit2
		    7 Close stmt	
		    7 Prepare	insert into dbit2 VALUES (1,'aaa','bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb')
		    7 Execute	insert into dbit2 VALUES (1,'aaa','bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb')
		    7 Close stmt	
		    7 Prepare	insert into dbit2 VALUES (2,'bbb','bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb')
		    7 Execute	insert into dbit2 VALUES (2,'bbb','bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb')
		    7 Close stmt	
		    7 Prepare	insert into dbit2 VALUES (3,'ccc','bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb')
		    7 Execute	insert into dbit2 VALUES (3,'ccc','bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb')
		    7 Prepare	select dbit2_key from   dbit2 where dbit2_key<?
		    7 Prepare	select dbit2_key from   dbit2 where dbit2_key<?
		    7 Execute	select dbit2_key from   dbit2 where dbit2_key<-1

Have stopped and restarted the server several times, only one single client connects.... strange.



 Comments   
Comment by FLAESCH Sebastien [ 2017-03-13 ]

Added mysql-strace-MDEV-12247.txt: This is the strace of the client process... was killed with kill (TERM)

Comment by Elena Stepanova [ 2017-03-13 ]

Could you please paste the output of SHOW CREATE TABLE dbit2` and attach your cnf file(s)?

Comment by FLAESCH Sebastien [ 2017-03-13 ]

The client ~/.my.cnf file:

[client]
default-character-set="utf8"
#default-character-set="latin1"
 
host = orion
#port = 3308 #-- mysql
port = 3309 #-- maria db

Server my.cnf:

[mysqld]
general_log      = 1
general_log_file = /tmp/mysql.log

Description of the dbit2 table:

mysql> SHOW CREATE TABLE dbit2;
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table | Create Table                                                                                                                                                                   |
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| dbit2 | CREATE TABLE `dbit2` (
  `dbit2_key` int(11) DEFAULT NULL,
  `dbit2_c10` char(10) DEFAULT NULL,
  `dbit2_vc200` varchar(200) DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> select * from dbit2;
+-----------+-----------+-----------------------------------+
| dbit2_key | dbit2_c10 | dbit2_vc200                       |
+-----------+-----------+-----------------------------------+
|         1 | aaa       | bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb |
|         2 | bbb       | bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb |
|         3 | ccc       | bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb |
+-----------+-----------+-----------------------------------+
3 rows in set (0.00 sec)

Comment by Daniel Black [ 2017-03-14 ]

Once stalled use the following with

{ ... }

replaced by the mariadb processes id for mysqld.

gdb --batch --eval-command="thread apply all bt" program {mysqld processid}

Can you clarify which server versions you are using 10.1.X/ 10.2.Y? Where did you install these from?

Comment by FLAESCH Sebastien [ 2017-03-14 ]

As written in the "Affects Version/s:" field, I have MariaDB 10.2.4
I have used the following package: mariadb-10.2.4-linux-glibc_214-x86_64.tar.gz

The gdb command output shows following:
(assuming "program" must be "mysqld" and

{procid}

is in fact procid without curly braces)

gdb --batch --eval-command="thread apply all bt" mysqld 1538 > /tmp/gdb-mysqld-001.txt

Produces gdb-mysqld-001.txt in attachment.

Comment by Elena Stepanova [ 2017-03-17 ]

Thanks for the stack trace, it helps.
I've seen this problem before and was able to reproduce it, however sporadically (MDEV-12084), but in our lab it has only been observed on CentOS 5, so it was considered specific to this environment and thus wasn't getting much attention (since CentOS 5 goes EOL in 2 weeks). If it's also happening on Jessie, that's another story. I'll try to get the draft bug report in proper shape and push it forward for further investigation.

sebflaesch, are you only running on Debian 8.6, or do you have other versions/systems? I'm very interested to know where else it is reproducible, the statistics could help to get to the bottom of it.

Comment by FLAESCH Sebastien [ 2017-03-18 ]

Thanks for considering this bug.
In fact I could also reproduce on Windows 10 / 64bits!
We have other Unix platforms available, so if really needed, we can do the test on other Unixes, but I think that having the bug on a stable Debian release (Jessie) and on Windows 10 should be good arguments to investigate this serious bug.
FYI, we go EAP end of the month, and our pre-release will be public for our customers. It would be nice to fix bug this before. On our side, we are ready to commit MariaDB 10.2 support with the new shared library libmariadb.so.3 ...

Comment by Elena Stepanova [ 2017-03-18 ]

No, thanks, there is no need to test on other Unixes, I was asking in case you already had some observations.

Is it absolutely reproducible for you? Like, every time when you run the query, it hangs?
Which connector is it?

Comment by FLAESCH Sebastien [ 2017-03-18 ]

In fact we have a C program using the MySQL C client API, it is linked with libmariadb.so.3.
Yes, we reproduce each time.
We have a quite complex QA test suite, but it happens also when running that single test as shown in the logs of first comment.
In fact other tests pass (no all but quite a few)
Look at the log in first comment... I wonder if it's not related to the fact that parameter is -1.
Table has only a fee rows..
The Query returns when using a parameter >=0...
No idea where the server hangs?

Comment by Elena Stepanova [ 2017-03-18 ]

Well, according to our stack traces, server hangs "in nowhere", just reading a packet, not doing anything significant, so the client side might be of importance here. My current suspect is libmariadb, but it's too early to say for sure.

The big difference between your case and mine is that yours is reproducible every time for you, while mine was only happening once in hundreds of attempts. So yours is definitely more promising.

I presume you can't reproduce it on your server if you just connect to it with the command-line client and do the same prepare/execute?

I've been trying to re-create your exact test case based on the log, not successful so far; so I have a question:

		    7 Prepare	select dbit2_key from   dbit2 where dbit2_key<?
		    7 Prepare	select dbit2_key from   dbit2 where dbit2_key<?
		    7 Execute	select dbit2_key from   dbit2 where dbit2_key<-1

Do you know why it does two Prepare for the select? Better still, do you think you could share the relevant part of your code, maybe there is something specific about prepare or binding (types, attributes, whatever) that the library processes wrongly

Comment by FLAESCH Sebastien [ 2017-03-18 ]

Double prepare:
To make it short, our programming language Genero BDL has 2 instructions to prepare and then declare a cursor:

  PREPARE s153 FROM "SELECT dbit2_key FROM dbit2 WHERE dbit2_key<?"    -- ends up as Prepare 1
  DECLARE c153 CURSOR FOR s153 -- ends up as Prepare 2
  LET n = -1
  OPEN c153 USING n -- ends up as Execute

In fact, the Genero BDL code does an OPEN USING followed by FOREACH loop. This ends up in a first call to mysql_stmt_bind_param() + mysql_stmt_execute(), and then the FOREACH makes again a call to mysql_stmt_execute()...
(I must admit this is very particular but legal code, that we have to support)

  LET n = -1
  OPEN c153 USING n -- ends up as a mysql_stmt_bind_param() + mysql_stmt_execute()
  FOREACH c153 -- ends up as a second mysql_stmt_execute()

I suspect however that MariaDB does not deal properly with these subsequent executes, or that we misuse the MariaDB client API in this case... (but our C code implementing these instructions exists for a while and is working fine with MySQL 5.7 client and MariaDB 10.1)

I will try to provide a pure MySQL C sample that reproduces the problem.

Comment by FLAESCH Sebastien [ 2017-03-19 ]

I could reproduce with a simplified program: Try attachment MDEV-12247.c

Seems to be related to the cursor type setting with mysql_stmt_attr_set()...

  • With default MYSQL_STMT settings = no issue
  • When setting STMT_ATTR_CURSOR_TYPE to CURSOR_TYPE_READ_ONLY, server does not respond on second execute...

Please try to reproduce on your side and let me know.
Here is the output I get when it hangs:

mysql_real_connect() ...
mysql_stmt_init() ...
mysql_stmt_prepare() ...
mysql_stmt_attr_set( ... STMT_ATTR_CURSOR_TYPE ... ) ...
mysql_stmt_execute()...
Re- mysql_stmt_execute()...
... must interrupt with CTRL-C / SIGINT ...

Comment by Elena Stepanova [ 2017-03-19 ]

Thanks a lot, reproducible for me with the libraries from 10.2.4 and mariadb-connector 3.0.1 (and not reproducible with libraries from 10.1).
wlad will be further looking into it.

Comment by Georg Richter [ 2017-03-21 ]

Fix pushed to Connector/C master branch

commit 63e0897d43881b6fcdcc4eff1d38b8e201dce631
Author: Georg Richter <georg@mariadb.com>
Date: Tue Mar 21 17:26:19 2017 +0100

Comment by FLAESCH Sebastien [ 2017-09-26 ]

Verified with 10.2.8

Generated at Thu Feb 08 07:56:14 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.