[MXS-2837] Router hints are ignored when executing a CallableStatement in a Java app using MariaDB Connector/J Created: 2020-01-16  Updated: 2020-02-14  Resolved: 2020-02-14

Status: Closed
Project: MariaDB MaxScale
Component/s: hintfilter
Affects Version/s: 2.4.3
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Rich Theobald Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: None
Environment:

Ubuntu 18.04, Java 1.8, MariaDB Connector/J 2.5.3

Issue Links:
Problem/Incident
is caused by MXS-2838 Add prepared statement support for hi... Closed

 Description   

In the following slow logs, the Callable Statement is executed before the maxscale end hint comment but after the maxscale begin comment. As is shown, the stored procedure is executed on the "master" node.

Slow log for Galera "Slave" (as defined by Maxscale):

# User@Host: vt_eucalyptus_local[vt_eucalyptus_local] @  [10.0.2.4]
 
# Thread_id: 329  Schema: vt_eucalyptus_local  QC_hit: No
 
# Query_time: 0.002670  Lock_time: 0.000111  Rows_sent: 0  Rows_examined: 0
 
# Rows_affected: 1  Bytes_sent: 13
 
SET timestamp=1579156660;
 
INSERT INTO diagnostic_log SET message=CONCAT_WS(' - ', @@wsrep_node_name, 1) /* maxscale begin route to slave */;
 
# User@Host: vt_eucalyptus_local[vt_eucalyptus_local] @  [10.0.2.4]
 
# Thread_id: 329  Schema: vt_eucalyptus_local  QC_hit: No
 
# Query_time: 0.000124  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
 
# Rows_affected: 0  Bytes_sent: 160
 
SET timestamp=1579156660;
 
# administrator command: Prepare;
 
# User@Host: vt_eucalyptus_local[vt_eucalyptus_local] @  [10.0.2.4]
 
# Thread_id: 329  Schema: vt_eucalyptus_local  QC_hit: No
 
# Query_time: 0.002937  Lock_time: 0.000093  Rows_sent: 0  Rows_examined: 0
 
# Rows_affected: 1  Bytes_sent: 13
 
SET timestamp=1579156660;
 
INSERT INTO diagnostic_log SET message=CONCAT_WS(' - ', @@wsrep_node_name, 2);
 
# User@Host: vt_eucalyptus_local[vt_eucalyptus_local] @  [10.0.2.4]
 
# Thread_id: 329  Schema: vt_eucalyptus_local  QC_hit: No
 
# Query_time: 0.002395  Lock_time: 0.000096  Rows_sent: 0  Rows_examined: 0
 
# Rows_affected: 1  Bytes_sent: 13
 
SET timestamp=1579156660;
 
INSERT INTO diagnostic_log SET message=CONCAT_WS(' - ', @@wsrep_node_name, 3);
 
# User@Host: vt_eucalyptus_local[vt_eucalyptus_local] @  [10.0.2.4]
 
# Thread_id: 329  Schema: vt_eucalyptus_local  QC_hit: No
 
# Query_time: 0.003113  Lock_time: 0.000091  Rows_sent: 0  Rows_examined: 0
 
# Rows_affected: 1  Bytes_sent: 13
 
SET timestamp=1579156660;
 
INSERT INTO diagnostic_log SET message=CONCAT_WS(' - ', @@wsrep_node_name, 4);
 
# User@Host: vt_eucalyptus_local[vt_eucalyptus_local] @  [10.0.2.4]
 
# Thread_id: 329  Schema: vt_eucalyptus_local  QC_hit: No
 
# Query_time: 0.000034  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
 
# Rows_affected: 0  Bytes_sent: 0
 
SET timestamp=1579156660;
 
# administrator command: Close stmt;

Slow log for Galera "Master":

# User@Host: vt_eucalyptus_local[vt_eucalyptus_local] @  [10.0.2.4]
 
# Thread_id: 970  Schema: vt_eucalyptus_local  QC_hit: No
 
# Query_time: 0.000167  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
 
# Rows_affected: 0  Bytes_sent: 187
 
SET timestamp=1579156660;
 
# administrator command: Prepare;
 
# User@Host: vt_eucalyptus_local[vt_eucalyptus_local] @  [10.0.2.4]
 
# Thread_id: 970  Schema: vt_eucalyptus_local  QC_hit: No
 
# Query_time: 0.003640  Lock_time: 0.000000  Rows_sent: 19  Rows_examined: 98
 
# Rows_affected: 0  Bytes_sent: 11610
 
SET timestamp=1579156660;
 
CALL p_store_item_list(10033,'en_GB','ITC',0,NULL,NULL);
 
# User@Host: vt_eucalyptus_local[vt_eucalyptus_local] @  [10.0.2.4]
 
# Thread_id: 970  Schema: vt_eucalyptus_local  QC_hit: No
 
# Query_time: 0.003174  Lock_time: 0.000119  Rows_sent: 0  Rows_examined: 0
 
# Rows_affected: 1  Bytes_sent: 13
 
SET timestamp=1579156660;
 
INSERT INTO diagnostic_log SET message=CONCAT_WS(' - ', @@wsrep_node_name, 5) /* maxscale end */;
 
# User@Host: vt_eucalyptus_local[vt_eucalyptus_local] @  [10.0.2.4]
 
# Thread_id: 970  Schema: vt_eucalyptus_local  QC_hit: No
 
# Query_time: 0.000027  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
 
# Rows_affected: 0  Bytes_sent: 0
 
SET timestamp=1579156660;
 
# administrator command: Close stmt;



 Comments   
Comment by markus makela [ 2020-01-16 ]

How are the queries executed? Do they use prepared statements?

Comment by Rich Theobald [ 2020-01-18 ]

Yes - using prepareCall method

The odd thing is, when I use a prepared statement from the MariaDB client, this works as expected except for the fact that the slow log shows explicit PREPARE statements as opposed to the posted log where it shows "administrator command: Prepare". I assumed this was due to using the Connector/J and JDBC.

Comment by markus makela [ 2020-01-18 ]

Yes, the prepared statements done with the command line client use the text protocol whereas the ones done with the Connector/J must've been done with the binary protocol. I filed MXS-2838 for adding support for it and documented the limitation.

Comment by markus makela [ 2020-02-14 ]

Closing as Incomplete since it's now a documented limitation and a feture request for it exists.

Generated at Thu Feb 08 04:17:02 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.