[CONJ-397] Query run by connector/j hungs in 'sending data' status Created: 2016-12-05  Updated: 2017-11-21  Resolved: 2017-11-21

Status: Closed
Project: MariaDB Connector/J
Component/s: Other
Affects Version/s: 1.5.5
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Ostap Demkovych Assignee: Diego Dupin
Resolution: Cannot Reproduce Votes: 0
Labels: None
Environment:

mariadb 10.1.19
os ubuntu 16.10
oracle jdk 1.8


Attachments: Text File long_batch_false.trace.txt     Text File short_batch_true.trace.txt    

 Description   

I am experiencing issue which crops up as long running query (25s). When I copy that query to heidysql it finishes within 300ms.
I've tried to debug it and figured out that when I set connector option 'rewriteBatchedStatements=true' the query is executed quickly. Set only useServerPrepStmts parameter to 'false' doesn't solve the issue.

Additionally the issue could depend on some DB server statistic because it is reproduced when I run it with filtering by 11/27/16 date. Probably some periods when there are more data are more likely to reproduce the bug.



 Comments   
Comment by Diego Dupin [ 2016-12-12 ]

Could you indicate the exact option used in connection string and indicate if maxscale is used ?
(it seems related to https://jira.mariadb.org/browse/MXS-1047. In this case, setting the useBatchMultiSend to false with then solve this issue)

Comment by Ostap Demkovych [ 2016-12-12 ]

MaxScale isn't used.
Connection string options: serverTimezone=GMT&useFractionalSeconds=true&useUnicode=true&characterEncoding=UTF-8&tcpNoDelay=true
MariaDB server and client encodings are set to utf8mb4

Comment by Diego Dupin [ 2016-12-12 ]

That's stange, because setting useServerPrepStmts to false will execute the query like in heidysql. The only change would be the escaping done on parameters.

Can you send the values of server SELECT @@SQL_MODE, @@GLOBAL.SQL_MODE; and the query ?

Comment by Ostap Demkovych [ 2016-12-12 ]

Yes, very strange issue. And I am sure it is the mariadb connector/j issue because mysql connectorj works fine.

SELECT @@SQL_MODE, @@GLOBAL.SQL_MODE
STRICT_TRANS_TABLES,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
STRICT_TRANS_TABLES,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION

SELECT COUNT(ca0.ca_id) AS col_0_0_
FROM ca ca0
INNER JOIN cabi cabi1 ON ca0.ca_id=cabi1.ca_id
INNER JOIN prca prca2 ON ca0.ca_id=prca2.ca_id
WHERE 
prca2.p_id=83 AND cabi1.ca_bf=1 AND ca0.ca_cr=1 AND cabi1.p_id=prca2.p_id 
AND ('2016-11-19 07:00:00' IS NULL OR ca0.created_on>='2016-11-19 07:00:00') 
AND (NULL IS NULL OR ca0.created_on<= NULL) 
AND 
(
 
	ca0.ca_parent_id IS NULL OR ('2016-11-19 07:00:00' IS NOT NULL) 
		AND (EXISTS (
		SELECT ca3.ca_id
		FROM ca ca3
		WHERE ca3.ca_id=ca0.ca_parent_id AND ca3.created_on>='2016-11-19 07:00:00')) 
 
	OR (EXISTS (
		SELECT ca4.ca_id
		FROM ca ca4
		WHERE ca4.ca_parent_id=ca0.ca_parent_id AND ca4.ca_id<>ca0.ca_id 
		AND ('2016-11-19 07:00:00' IS NULL OR ca4.created_on<'2016-11-19 07:00:00'))
		) 
 
	AND 
		(EXISTS (
		SELECT ca5.ca_id
		FROM ca ca5
		INNER JOIN cabi ca6 ON ca5.ca_id=ca6.ca_id
		WHERE ca6.ca_bf=0 AND ca6.p_id=prca2.p_id AND (ca5.ca_id IN (
		SELECT MAX(ca7.ca_id)
		FROM ca ca7
		WHERE ca7.ca_parent_id=ca0.ca_parent_id AND ca7.ca_id<>ca0.ca_id AND ('2016-11-19 07:00:00' IS NULL OR ca7.created_on<'2016-11-19 07:00:00'))))) 
 
	OR NOT (EXISTS (
		SELECT ca8.ca_id
		FROM ca ca8
		WHERE ca8.ca_parent_id=ca0.ca_parent_id AND ca8.ca_id<>ca0.ca_id AND ('2016-11-19 07:00:00' IS NULL OR ca8.created_on<'2016-11-19 07:00:00'))) 
 
	AND (EXISTS (
		SELECT ca9.ca_id
		FROM ca ca9
		INNER JOIN cabi ca10 ON ca9.ca_id=ca10.ca_id
		WHERE ca10.ca_bf=0 AND ca10.p_id=prca2.p_id AND ('2016-11-19 07:00:00' IS NULL OR ca9.created_on<'2016-11-19 07:00:00') AND ca9.ca_id=ca0.ca_parent_id))
 
)

Comment by Diego Dupin [ 2016-12-14 ]

Reading code, i don't see any issue.
i need other informations.

if you use SLF4j, have you the possibility to run this query with parameter log=true and set org.mariadb.jdbc logging level to trace ? or having a wireshark dump ? that's the only way to identify the issue.

Comment by Ostap Demkovych [ 2016-12-15 ]

I've run trace logging and will attach two txt files with results.

Meanwhile I was running log I've discovered one minor issue: org.mariadb.jdbc.internal.logging.LoggerFactory#init method isn't threadsafe.
When run application with log=true and use pool data source some threads crash with NullPointerException.

Comment by Diego Dupin [ 2016-12-15 ]

It seems data send to server are alright, it must not be driver related, but server perform badly on this particular request using binary protocol compare to text protocol.

If you have the possibility to test that, using MySQL connector with option "useServerPrepStmts" to true must be as slow.

searching why

Comment by Ostap Demkovych [ 2016-12-15 ]

I will try mysql connector. Also, how to explain that mariadb connector doesn't react to useServerPrepStmts=false and heidysql executes the query.

Comment by Diego Dupin [ 2016-12-15 ]

I cannot understand why useServerPrepStmts=false would have the issue. For a single query, there is very few differences with rewriteBatchedStatements=true that cannot explain that kind of problems.

I'll check tomorrow but I remember having see a server issue that make a full table scan on second execution of a prepare statement on certain condition.

Comment by Ostap Demkovych [ 2016-12-16 ]

I've checked one more time useServerPrepStmts=false in mariadb connectorj and it works. I must did some mistake when tried it at first time.
Also I've found similar issue MDEV-11161 which is fixed in mariadb 10.1.20. I've tried mariadb 10.1.20 and my issue still exists.

Comment by Ostap Demkovych [ 2016-12-21 ]

Should I reenter this issue as related to mariadb?

Comment by Diego Dupin [ 2016-12-22 ]

That would be better.
I've done some tests to reproduce your issue, but fail to have long execution time.
Since you can reproduced it, it would be great if you have reproduce it with a smaller query.

Comment by Diego Dupin [ 2017-11-21 ]

Closing since not reproduced.
Feel free to reopen it if reproduced

Generated at Thu Feb 08 03:15:21 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.