Re: Problem with MysqlConnectionPoolDataSource Connector/J 8.0.x
Hi Filipe,
Thanks for your answer. I took om time to do more testing.
> There's nothing else in the connection pool configuration, other than what you already pasted here?
No, nothing else.
> Could you please turn on the general log in the server (https://dev.mysql.com/doc/refman/8.0/en/query-log.html) and watch for "Connect" and "Quit" events while this process is running?
Done quite a few tests I will end this message with the results.
> BTW, have you tried profiling the running process? It could help identifying the real source of the problem.
Never had to do so, this is my next step if needed.
I have done some tests with 3 configurations. In all these I connect using MysqlConnectionPoolDataSource
With connector 8.0.15 and connection pool
With connector 8.0.15 without using the connection pool (Just for test as it is at least 3 times slower, it is not a possible solution for production)
With connector 5.1.47 and connection pool (This is the production environment, using sumiltaneous MySQL en MSSQL connections, very stable can be up several weeks with no errors and no restart)
8.0.15 and connection pool (problems appears after approx. 5 mn of running on developmeny machine)
2019-03-20T07:12:21.552612Z 8 Connect root@localhost on doliflags using TCP/IP
2019-03-20T07:12:21.555108Z 8 Query /* mysql-connector-java-8.0.15 (Revision: 79a4336f140499bd22dd07f02b708e163844e3d5) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server, @@collation_connection AS collation_connection, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_write_timeout AS net_write_timeout, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout
2019-03-20T07:12:21.565114Z 8 Query SET NAMES utf8mb4
2019-03-20T07:12:21.565278Z 8 Query SET character_set_results = NULL
2019-03-20T07:12:21.566419Z 8 Query SET autocommit=1
2019-03-20T07:12:21.572847Z 8 Change user root@localhost on doliflags using TCP/IP
2019-03-20T07:12:21.573098Z 8 Query SET NAMES utf8mb4
2019-03-20T07:12:21.573214Z 8 Query SET character_set_results = NULL
2019-03-20T07:12:21.583667Z 8 Query select count(*) from llx_bank
2019-03-20T07:12:53.112241Z 9 Connect root@localhost on doliflags using TCP/IP
2019-03-20T07:12:53.112713Z 9 Query /* mysql-connector-java-8.0.15 (Revision: 79a4336f140499bd22dd07f02b708e163844e3d5) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server, @@collation_connection AS collation_connection, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_write_timeout AS net_write_timeout, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout
2019-03-20T07:12:53.113134Z 9 Query SET NAMES utf8mb4
2019-03-20T07:12:53.113303Z 9 Query SET character_set_results = NULL
2019-03-20T07:12:53.113473Z 9 Query SET autocommit=1
2019-03-20T07:12:53.113932Z 9 Change user root@localhost on doliflags using TCP/IP
2019-03-20T07:12:53.114142Z 9 Query SET NAMES utf8mb4
2019-03-20T07:12:53.114271Z 9 Query SET character_set_results = NULL
2019-03-20T07:12:53.114653Z 9 Query SELECT (CASE WHEN ISNULL(SUM(`llx_product_stock`.`reel`)) THEN 0 ELSE SUM(`llx_product_stock`.`reel`) END) AS `stock` FROM (`llx_product` LEFT JOIN `llx_product_stock` ON (((`llx_product`.`rowid` = `llx_product_stock`.`fk_product`) AND (`llx_product_stock`.`fk_entrepot` IN (1,3))))) where llx_product.ref = 'AT_503'
Comment Thread 8 connect to database just to check that it is available and Thread 9 connect to database to initialize the cache
In mysqlerror.log
2019-03-20T07:18:27.978847Z 9 [Note] [MY-010914] [Server] Got timeout reading communication packets
2019-03-20T07:23:07.980403Z 10 [Note] [MY-010914] [Server] Got timeout reading communication packets
2019-03-20T07:24:20.274403Z 8 [Note] [MY-010914] [Server] Aborted connection 8 to db: 'doliflags' user: 'root' host: 'localhost' (Got an error reading communication packets).
Comment : I do not understand why I have sudenly an error in thread 8 which does nothing. This is where everything stop working
When first timeout occurs in mysqld.log
I have first a new thread 10 connection 30 sec. before and then all Queries are initiated in thread 10
2019-03-20T07:17:58.029453Z 10 Connect root@localhost on doliflags using TCP/IP
2019-03-20T07:17:58.029867Z 10 Query /* mysql-connector-java-8.0.15 (Revision: 79a4336f140499bd22dd07f02b708e163844e3d5) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server, @@collation_connection AS collation_connection, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_write_timeout AS net_write_timeout, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout
Comment : Then at the time when the error is registered in errorlog I have two lines following such as
2019-03-20T07:18:27.978820Z 9 Change user root@localhost on doliflags using TCP/IP
2019-03-20T07:18:27.984888Z 10 Change user root@localhost on doliflags using TCP/IP
The mysqld.log stop recording anything after the second timeout
The last 4 lines are
2019-03-20T07:22:37.970809Z 10 Change user root@localhost on doliflags using TCP/IP
2019-03-20T07:22:37.971363Z 10 Query SET NAMES utf8mb4
2019-03-20T07:22:37.971850Z 10 Query SET character_set_results = NULL
2019-03-20T07:22:37.972777Z 10 Query SELECT sum(llx_commande_fournisseurdet.qty) , max(llx_commande_fournisseur.date_livraison) from llx_commande_fournisseur , llx_commande_fournisseurdet , llx_product where llx_product.ref = 'FRD16_334' and llx_commande_fournisseurdet.fk_product = llx_product.rowid and llx_commande_fournisseurdet.fk_commande = llx_commande_fournisseur.rowid and fk_statut <= 2
2019-03-20T07:23:07.980271Z 10 Change user root@localhost on doliflags using TCP/IP
Typical call to database in mysqld.log
2019-03-20T07:18:27.945549Z 10 Change user root@localhost on doliflags using TCP/IP
2019-03-20T07:18:27.945802Z 10 Query SET NAMES utf8mb4
2019-03-20T07:18:27.945982Z 10 Query SET character_set_results = NULL
2019-03-20T07:18:27.946311Z 10 Query SELECT (CASE WHEN ISNULL(SUM(`llx_product_stock`.`reel`)) THEN 0 ELSE SUM(`llx_product_stock`.`reel`) END) AS `stock` FROM (`llx_product` LEFT JOIN `llx_product_stock` ON (((`llx_product`.`rowid` = `llx_product_stock`.`fk_product`) AND (`llx_product_stock`.`fk_entrepot` IN (1,3))))) where llx_product.ref = 'IM_CE_318'
8.0.15 without connection pool (no problems, reopens a new thread for each Query)
Typical Query without connection pool
2019-03-20T08:11:18.683946Z 64367 Connect root@localhost on doliflags using TCP/IP
2019-03-20T08:11:18.684146Z 64367 Query /* mysql-connector-java-8.0.15 (Revision: 79a4336f140499bd22dd07f02b708e163844e3d5) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server, @@collation_connection AS collation_connection, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_write_timeout AS net_write_timeout, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout
2019-03-20T08:11:18.684300Z 64367 Query SET NAMES utf8mb4
2019-03-20T08:11:18.684361Z 64367 Query SET character_set_results = NULL
2019-03-20T08:11:18.684415Z 64367 Query SET autocommit=1
2019-03-20T08:11:18.684540Z 64367 Query SELECT sum(llx_commande_fournisseurdet.qty) , max(llx_commande_fournisseur.date_livraison) from llx_commande_fournisseur , llx_commande_fournisseurdet , llx_product where llx_product.ref = 'FRVALLINGES_BLASON_1630' and llx_commande_fournisseurdet.fk_product = llx_product.rowid and llx_commande_fournisseurdet.fk_commande = llx_commande_fournisseur.rowid and fk_statut <= 2
2019-03-20T08:11:18.684822Z 64367 Quit
5.1.47 and connection pool (no problems)
Same initialization
2019-03-20T08:34:03.934192Z 8 Connect root@localhost on doliflags using TCP/IP
2019-03-20T08:34:03.938728Z 8 Query /* mysql-connector-java-5.1.47 ( Revision: fe1903b1ecb4a96a917f7ed3190d80c049b1de29 ) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server, @@collation_connection AS collation_connection, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_buffer_length AS net_buffer_length, @@net_write_timeout AS net_write_timeout, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout
2019-03-20T08:34:03.960017Z 8 Query SET NAMES utf8mb4
2019-03-20T08:34:03.960311Z 8 Query SET character_set_results = NULL
2019-03-20T08:34:03.960629Z 8 Query SET autocommit=1
2019-03-20T08:34:03.964483Z 8 Change user root@localhost on doliflags using TCP/IP
2019-03-20T08:34:03.964721Z 8 Query SET NAMES utf8mb4
2019-03-20T08:34:03.964884Z 8 Query SET character_set_results = NULL
2019-03-20T08:34:03.979406Z 8 Query select count(*) from llx_bank
2019-03-20T08:34:35.068590Z 9 Connect root@localhost on doliflags using TCP/IP
2019-03-20T08:34:35.069011Z 9 Query /* mysql-connector-java-5.1.47 ( Revision: fe1903b1ecb4a96a917f7ed3190d80c049b1de29 ) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server, @@collation_connection AS collation_connection, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_buffer_length AS net_buffer_length, @@net_write_timeout AS net_write_timeout, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout
2019-03-20T08:34:35.069520Z 9 Query SET NAMES utf8mb4
2019-03-20T08:34:35.069714Z 9 Query SET character_set_results = NULL
2019-03-20T08:34:35.069930Z 9 Query SET autocommit=1
2019-03-20T08:34:35.070419Z 9 Change user root@localhost on doliflags using TCP/IP
2019-03-20T08:34:35.070648Z 9 Query SET NAMES utf8mb4
2019-03-20T08:34:35.070817Z 9 Query SET character_set_results = NULL
2019-03-20T08:34:35.071153Z 9 Query SELECT (CASE WHEN ISNULL(SUM(`llx_product_stock`.`reel`)) THEN 0 ELSE SUM(`llx_product_stock`.`reel`) END) AS `stock` FROM (`llx_product` LEFT JOIN `llx_product_stock` ON (((`llx_product`.`rowid` = `llx_product_stock`.`fk_product`) AND (`llx_product_stock`.`fk_entrepot` IN (1,3))))) where llx_product.ref = 'AT_503'
Comment Thread 8 connect to database just to check that it is available and Thread 9 connect to database to initialize the cache and stay on thread 9 up to the end of initialization.
Typical call to database in mysqld.log
2019-03-20T08:44:43.227583Z 9 Change user root@localhost on doliflags using TCP/IP
2019-03-20T08:44:43.227778Z 9 Query SET NAMES utf8mb4
2019-03-20T08:44:43.227925Z 9 Query SET character_set_results = NULL
2019-03-20T08:44:43.228218Z 9 Query SELECT (CASE WHEN ISNULL(SUM(`llx_product_stock`.`reel`)) THEN 0 ELSE SUM(`llx_product_stock`.`reel`) END) AS `stock` FROM (`llx_product` LEFT JOIN `llx_product_stock` ON (((`llx_product`.`rowid` = `llx_product_stock`.`fk_product`) AND (`llx_product_stock`.`fk_entrepot` IN (1,3))))) where llx_product.ref = 'FRVDAX_332'