Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

connection_pool crash #1370

Closed
cggy2012 opened this issue Feb 8, 2018 · 34 comments
Closed

connection_pool crash #1370

cggy2012 opened this issue Feb 8, 2018 · 34 comments

Comments

@cggy2012
Copy link

cggy2012 commented Feb 8, 2018

mysql> select * from stats_mysql_connection_pool;
+-----------+----------------+----------+--------------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+
| hostgroup | srv_host | srv_port | status | ConnUsed | ConnFree | ConnOK | ConnERR | Queries | Bytes_data_sent | Bytes_data_recv | Latency_us |
+-----------+----------------+----------+--------------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+
| 0 | 192.168.11.185 | 3306 | ONLINE | 1 | 18 | 19 | 0 | 11352 | 502377 | 29366200 | 0 |
| 1 | 192.168.11.185 | 3306 | OFFLINE_SOFT | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| 1 | 192.168.11.186 | 3306 | ONLINE | 0 | 12 | 12 | 0 | 11322 | 2765800 | 5704774 | 0 |
| 1 | 192.168.11.187 | 3306 | ONLINE | 1 | 6 | 7 | 0 | 11321 | 2676833 | 6125501 | 0 |
| 1 | 192.168.11.188 | 3306 | ONLINE | 0 | 7 | 7 | 0 | 11553 | 2794793 | 5585408 | 0 |
| 1 | 192.168.11.189 | 3306 | ONLINE | 0 | 12 | 12 | 0 | 10401 | 2443517 | 6888625 | 0 |
| 2 | 192.168.11.190 | 3306 | ONLINE | 0 | 2 | 2 | 0 | 30 | 37086 | 885092 | 0 |
| 2 | 192.168.11.191 | 3306 | ONLINE | 0 | 2 | 2 | 0 | 33 | 41411 | 1515162 | 0 |
+-----------+----------------+----------+--------------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+
8 rows in set (0.00 sec)

mysql> select * from stats_mysql_connection_pool;
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql> select * from stats_mysql_connection_pool;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id: 1
Current database: *** NONE ***

+-----------+----------------+----------+--------------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+
| hostgroup | srv_host | srv_port | status | ConnUsed | ConnFree | ConnOK | ConnERR | Queries | Bytes_data_sent | Bytes_data_recv | Latency_us |
+-----------+----------------+----------+--------------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+
| 0 | 192.168.11.185 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| 1 | 192.168.11.185 | 3306 | OFFLINE_SOFT | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| 1 | 192.168.11.186 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| 1 | 192.168.11.187 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| 1 | 192.168.11.188 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| 1 | 192.168.11.189 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| 2 | 192.168.11.190 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| 2 | 192.168.11.191 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
+-----------+----------------+----------+--------------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+

@cggy2012
Copy link
Author

cggy2012 commented Feb 8, 2018

+-----------------------------------------------------+--------------------+
| variable_name | variable_value |
+-----------------------------------------------------+--------------------+
| mysql-shun_on_failures | 5 |
| mysql-shun_recovery_time_sec | 10 |
| mysql-query_retries_on_failure | 1 |
| mysql-connect_retries_delay | 1 |
| mysql-connection_delay_multiplex_ms | 0 |
| mysql-connection_max_age_ms | 0 |
| mysql-connect_timeout_server_max | 10000 |
| mysql-eventslog_filename | |
| mysql-eventslog_filesize | 104857600 |
| mysql-default_charset | utf8 |
| mysql-free_connections_pct | 50 |
| mysql-session_idle_ms | 1000 |
| mysql-client_found_rows | false |
| mysql-monitor_enabled | false |
| mysql-monitor_connect_timeout | 600 |
| mysql-monitor_ping_max_failures | 3 |
| mysql-monitor_ping_timeout | 1000 |
| mysql-monitor_replication_lag_interval | 10000 |
| mysql-monitor_replication_lag_timeout | 1000 |
| mysql-monitor_groupreplication_healthcheck_interval | 5000 |
| mysql-monitor_groupreplication_healthcheck_timeout | 800 |
| mysql-monitor_replication_lag_use_percona_heartbeat | |
| mysql-monitor_query_interval | 60000 |
| mysql-monitor_query_timeout | 100 |
| mysql-monitor_slave_lag_when_null | 60 |
| mysql-monitor_wait_timeout | true |
| mysql-monitor_writer_is_also_reader | true |
| mysql-max_allowed_packet | 100000000 |
| mysql-throttle_connections_per_sec_to_hostgroup | 1000000 |
| mysql-max_transaction_time | 14400000 |
| mysql-multiplexing | true |
| mysql-forward_autocommit | false |
| mysql-enforce_autocommit_on_reads | false |
| mysql-autocommit_false_not_reusable | false |
| mysql-autocommit_false_is_transaction | false |
| mysql-verbose_query_error | false |
| mysql-hostgroup_manager_verbose | 1 |
| mysql-threshold_query_length | 524288 |
| mysql-threshold_resultset_size | 4194304 |
| mysql-query_digests_max_digest_length | 2048 |
| mysql-query_digests_max_query_length | 65000 |
| mysql-wait_timeout | 1800000 |
| mysql-throttle_max_bytes_per_second_to_client | 2147483647 |
| mysql-throttle_ratio_server_to_client | 0 |
| mysql-max_stmts_per_connection | 100 |
| mysql-max_stmts_cache | 10000 |
| mysql-mirror_max_concurrency | 16 |
| mysql-mirror_max_queue_length | 32000 |
| mysql-default_max_latency_ms | 1000 |
| mysql-query_processor_iterations | 0 |
| mysql-query_processor_regex | 1 |
| mysql-long_query_time | 1000 |
| mysql-query_cache_size_MB | 256 |
| mysql-poll_timeout_on_failure | 100 |
| mysql-server_capabilities | 45578 |
| mysql-session_idle_show_processlist | true |
| mysql-query_digests | false |
| mysql-query_digests_lowercase | false |
| mysql-servers_stats | true |
| mysql-default_reconnect | true |
| mysql-ssl_p2s_ca | (null) |
| mysql-ssl_p2s_cert | (null) |
| mysql-ssl_p2s_key | (null) |
| mysql-ssl_p2s_cipher | (null) |
| mysql-init_connect | (null) |
| mysql-default_sql_mode | |
| mysql-default_time_zone | SYSTEM |
| mysql-connpoll_reset_queue_length | 50 |
| mysql-stats_time_backend_query | false |
| mysql-stats_time_query_processor | false |
| mysql-max_connections | 10000 |
| mysql-default_query_delay | 0 |
| mysql-default_query_timeout | 30000 |
| mysql-have_compress | true |
| mysql-poll_timeout | 2000 |
| mysql-interfaces | 0.0.0.0:6033 |
| mysql-default_schema | information_schema |
| mysql-stacksize | 1048576 |
| mysql-server_version | 5.7.20 |
| mysql-connect_timeout_server | 3000 |
| mysql-monitor_username | mon_proxysql |
| mysql-monitor_password | qingtaokeDB520 |
| mysql-monitor_history | 600000 |
| mysql-monitor_connect_interval | 60000 |
| mysql-monitor_ping_interval | 10000 |
| mysql-monitor_read_only_interval | 1500 |
| mysql-monitor_read_only_timeout | 500 |
| mysql-ping_interval_server_msec | 120000 |
| mysql-ping_timeout_server | 500 |
| mysql-commands_stats | true |
| mysql-sessions_sort | true |
| mysql-connect_retries_on_failure | 10 |
| mysql-threads | 4 |
| admin-stats_credentials | stats:stats |
| admin-stats_mysql_connections | 60 |
| admin-stats_mysql_connection_pool | 60 |
| admin-stats_mysql_query_cache | 60 |
| admin-stats_system_cpu | 60 |
| admin-stats_system_memory | 60 |
| admin-telnet_admin_ifaces | (null) |
| admin-telnet_stats_ifaces | (null) |
| admin-refresh_interval | 2000 |
| admin-read_only | false |
| admin-hash_passwords | true |
| admin-cluster_username | |
| admin-cluster_password | |
| admin-cluster_check_interval_ms | 1000 |
| admin-cluster_check_status_frequency | 10 |
| admin-cluster_mysql_query_rules_diffs_before_sync | 3 |
| admin-cluster_mysql_servers_diffs_before_sync | 3 |
| admin-cluster_mysql_users_diffs_before_sync | 3 |
| admin-cluster_proxysql_servers_diffs_before_sync | 3 |
| admin-cluster_mysql_query_rules_save_to_disk | true |
| admin-cluster_mysql_servers_save_to_disk | true |
| admin-cluster_mysql_users_save_to_disk | true |
| admin-cluster_proxysql_servers_save_to_disk | true |
| admin-checksum_mysql_query_rules | true |
| admin-checksum_mysql_servers | true |
| admin-checksum_mysql_users | true |
| admin-web_enabled | false |
| admin-web_port | 6080 |
| admin-version | 1.4.6-7-g3b9e4a6 |
| admin-admin_credentials | admin:admin |
| admin-mysql_ifaces | 0.0.0.0:6032 |
+-----------------------------------------------------+--------------------+
124 rows in set (0.00 sec)

@cggy2012
Copy link
Author

cggy2012 commented Feb 8, 2018

proxysql version 1.4.6

@cggy2012
Copy link
Author

cggy2012 commented Feb 8, 2018

proxysql(_ZN15Query_Processor28query_parser_update_countersEP13MySQL_Session23MYSQL_COM_QUERY_commandP20__SQP_query_parser_ty+0x61)[0x496981]
proxysql(_ZN10Query_Info28query_parser_update_countersEv+0x4a)[0x47b61a]
proxysql(_ZN10Query_Info3endEv+0xe)[0x47b65e]
proxysql(_ZN13MySQL_Session10RequestEndEP17MySQL_Data_Stream+0x84)[0x47ead4]
proxysql(_ZN13MySQL_Session7handlerEv+0x228c)[0x488bbc]
proxysql(_ZN12MySQL_Thread20process_all_sessionsEv+0x1fc)[0x47021c]
proxysql(_ZN12MySQL_Thread3runEv+0xd76)[0x478ef6]
proxysql(_Z24mysql_worker_thread_funcPv+0x6c)[0x449b3c]
/lib64/libpthread.so.0(+0x7aa1)[0x7f41a6b66aa1]
/lib64/libc.so.6(clone+0x6d)[0x7f41a54a0bcd]v

@renecannao
Copy link
Contributor

Hi. From the backtrace, the crash isn't related to connection pool but command counter.
Do you have a core dump?
What OS are you running?

@cggy2012
Copy link
Author

cggy2012 commented Feb 8, 2018

@cggy2012
Copy link
Author

cggy2012 commented Feb 8, 2018

my OS is Linux 2.6.32-696.20.1.el6.x86_64 #1 SMP Fri Jan 26 17:51:45 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

@cggy2012
Copy link
Author

cggy2012 commented Feb 8, 2018

We have a query of about 4000 per second,Load balancing by 3 proxysql.

@renecannao
Copy link
Contributor

Thank you for the core dump.
I am still analyzing them, but I suspect is due to mysql-query_digests=false . Can you set it to true ?

renecannao added a commit that referenced this issue Feb 9, 2018
This happens for prepared statements, and mysql-query_digests=false
@renecannao
Copy link
Contributor

Fixed in 1.4.7

@cggy2012
Copy link
Author

cggy2012 commented Feb 9, 2018

I will test this version after 2hours , thank you.

@renecannao
Copy link
Contributor

hi @cggy2012 : any result?
Thanks

pondix pushed a commit to pondix/proxysql that referenced this issue Feb 12, 2018
This happens for prepared statements, and mysql-query_digests=false
@cggy2012
Copy link
Author

I'm sorry to reply to you so late , Because I can't test during the Spring Festival , Now one node is online , If there is no problem , I'll replace two other nodes tomorrow morning . by the way , I suggest setting mysql-client_found_rows default false.

@renecannao
Copy link
Contributor

No problem, let me know when you have some result.
About mysql-client_found_rows : a lot of our users use Python + SQLAlchemy, that strongly rely on client_found_rows : this is why it is set to true by default.
But it is configurable, that is what matters!

@cggy2012
Copy link
Author

OK , I will run 24 hours in production to test this version , Testing requires under high loads , And then I'll tell you the result .

@cggy2012
Copy link
Author

cggy2012 commented Feb 23, 2018

hello , So far , I haven't found any problems , I will continue to run in the production . There are two suggestions . first I have a error "MySQL_Session.cpp:2837:handler(): [WARNING] Error during query on (0,,3306): 1048, Column '' cannot be null" , I don't know which table or which sql have problem . second , I expect to have a function like general_log to find the cli_host of query . At last , If there is any problem I will be the first time to communicate with you .

@cggy2012
Copy link
Author

cggy2012 commented Feb 23, 2018

an other error "MySQL_Session.cpp:2837:handler(): [WARNING] Error during query on (1,,3306): 1290, The MySQL server is running with the --read-only option so it cannot execute this statement" , Occasionally, an update statement is sent to the wrong group .

@cggy2012
Copy link
Author

cggy2012 commented Feb 23, 2018

group 0 is read write , group 1 is read only .

mysql> select * from runtime_mysql_query_rules \G
*************************** 1. row ***************************
rule_id: 1
active: 1
username: NULL
schemaname: NULL
flagIN: 0
client_addr: NULL
proxy_addr: NULL
proxy_port: NULL
digest: NULL
match_digest: NULL
match_pattern: ^SELECT.*FOR UPDATE$
negate_match_pattern: 0
re_modifiers: CASELESS
flagOUT: NULL
replace_pattern: NULL
destination_hostgroup: 0
cache_ttl: NULL
reconnect: NULL
timeout: NULL
retries: NULL
delay: NULL
next_query_flagIN: NULL
mirror_flagOUT: NULL
mirror_hostgroup: NULL
error_msg: NULL
OK_msg: NULL
sticky_conn: NULL
multiplex: NULL
log: NULL
apply: 1
comment: NULL
*************************** 2. row ***************************
rule_id: 2
active: 1
username: NULL
schemaname: NULL
flagIN: 0
client_addr: NULL
proxy_addr: NULL
proxy_port: NULL
digest: NULL
match_digest: NULL
match_pattern: ^SELECT
negate_match_pattern: 0
re_modifiers: CASELESS
flagOUT: NULL
replace_pattern: NULL
destination_hostgroup: 1
cache_ttl: NULL
reconnect: NULL
timeout: NULL
retries: NULL
delay: NULL
next_query_flagIN: NULL
mirror_flagOUT: NULL
mirror_hostgroup: NULL
error_msg: NULL
OK_msg: NULL
sticky_conn: NULL
multiplex: NULL
log: NULL
apply: 1
comment: NULL
*************************** 3. row ***************************
rule_id: 3
active: 1
username: NULL
schemaname: NULL
flagIN: 0
client_addr: NULL
proxy_addr: NULL
proxy_port: NULL
digest: NULL
match_digest: NULL
match_pattern: ^(?SELECT
negate_match_pattern: 0
re_modifiers: CASELESS
flagOUT: NULL
replace_pattern: NULL
destination_hostgroup: 1
cache_ttl: NULL
reconnect: NULL
timeout: NULL
retries: NULL
delay: NULL
next_query_flagIN: NULL
mirror_flagOUT: NULL
mirror_hostgroup: NULL
error_msg: NULL
OK_msg: NULL
sticky_conn: NULL
multiplex: NULL
log: NULL
apply: 1
comment: NULL
3 rows in set (0.00 sec)

@cggy2012
Copy link
Author

the sql is UPDATE table SET activity_id=?, item_id=?, pic_url=?, price=?, sale_price=?, istmall=?, start_time=?, end_time=?, update_time=? WHERE id = ?

@renecannao
Copy link
Contributor

About the additional information in the error log, see #1060 (comment) .
About the query sent to the wrong server, how did you identify it?

@cggy2012
Copy link
Author

I use mysql group replication , 192.168.11.185 is primary node (read-write) , the other is slave node (read-only).

proxySQL mysql_server
mysql> select hostgroup_id,hostname,port,status,weight from runtime_mysql_servers;
+--------------+----------------+------+--------------+--------+
| hostgroup_id | hostname | port | status | weight |
+--------------+----------------+------+--------------+--------+
| 0 | 192.168.11.185 | 3306 | ONLINE | 1 |
| 1 | 192.168.11.191 | 3306 | ONLINE | 1 |
| 1 | 192.168.11.190 | 3306 | ONLINE | 1 |
| 1 | 192.168.11.189 | 3306 | ONLINE | 1 |
| 1 | 192.168.11.188 | 3306 | ONLINE | 1 |
| 1 | 192.168.11.187 | 3306 | ONLINE | 1 |
| 1 | 192.168.11.186 | 3306 | ONLINE | 1 |
| 1 | 192.168.11.185 | 3306 | OFFLINE_SOFT | 1 |
+--------------+----------------+------+--------------+--------+

proxySQL query_rules
mysql> select rule_id,active,flagIN,match_pattern,negate_match_pattern,destination_hostgroup,apply from runtime_mysql_query_rules;
+---------+--------+--------+----------------------+----------------------+-----------------------+-------+
| rule_id | active | flagIN | match_pattern | negate_match_pattern | destination_hostgroup | apply |
+---------+--------+--------+----------------------+----------------------+-----------------------+-------+
| 1 | 1 | 0 | ^SELECT.*FOR UPDATE$ | 0 | 0 | 1 |
| 2 | 1 | 0 | ^SELECT | 0 | 1 | 1 |
| 3 | 1 | 0 | ^(?SELECT | 0 | 1 | 1 |
+---------+--------+--------+----------------------+----------------------+-----------------------+-------+

Run for a few hours , I get a error in proxysql.log "2018-02-23 16:38:02 MySQL_Session.cpp:2837:handler(): [WARNING] Error during query on (1,192.168.11.190,3306): 1290, The MySQL server is running with the --read-only option so it cannot execute this statement"

normal , the update should sent to destination_hostgroup 0 , I used to have this problem , Especially in the morning rush hour .

@renecannao
Copy link
Contributor

Are you using native support for Group Replication ?
Can you send me the full error log for further investigation?

@cggy2012
Copy link
Author

About the additional information in the error log, see #1060 (comment) .
it is great ! Can you update the Global Variables of wiki , I do not know the meaning of some variables .

@cggy2012
Copy link
Author

I think this problem is had to find out , because the error is very sample .
proxysql.zip

@cggy2012
Copy link
Author

search for the keyword “read-only”

@cggy2012
Copy link
Author

cggy2012 commented Feb 23, 2018

I use a script to detect the status of the mysql group replication and update mysql_server table .
gr_sw_mode_checker.zip

@renecannao
Copy link
Contributor

You should use native support for Group Replication, instead of this script.
You are running LOAD MYSQL SERVERS TO RUNTIME every 10 seconds, that is not recommended.

$ grep "LOAD MYSQL SERVERS TO RUNTIME" proxysql.log | wc -l
1018

Native group replication is faster.

Can you also attach the output of SELECT * FROM stats_mysql_connection_pool ?

@cggy2012
Copy link
Author

thank you , I will make some adjustments .

mysql> SELECT * FROM stats_mysql_connection_pool;
+-----------+----------------+----------+--------------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+
| hostgroup | srv_host | srv_port | status | ConnUsed | ConnFree | ConnOK | ConnERR | Queries | Bytes_data_sent | Bytes_data_recv | Latency_us |
+-----------+----------------+----------+--------------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+
| 0 | 192.168.11.185 | 3306 | ONLINE | 2 | 9 | 11 | 0 | 3872303 | 167947957 | 6247638310 | 149 |
| 1 | 192.168.11.185 | 3306 | OFFLINE_SOFT | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 149 |
| 1 | 192.168.11.186 | 3306 | ONLINE | 0 | 4 | 4 | 0 | 2693722 | 557668243 | 1712497343 | 157 |
| 1 | 192.168.11.187 | 3306 | ONLINE | 0 | 4 | 4 | 0 | 2439591 | 556797801 | 1997393108 | 161 |
| 1 | 192.168.11.188 | 3306 | ONLINE | 0 | 4 | 4 | 0 | 2440846 | 557340412 | 1834757174 | 161 |
| 1 | 192.168.11.189 | 3306 | ONLINE | 0 | 4 | 4 | 0 | 2423518 | 553313616 | 1743347804 | 158 |
| 1 | 192.168.11.190 | 3306 | ONLINE | 0 | 4 | 5 | 0 | 2532220 | 550259825 | 1638590750 | 169 |
| 1 | 192.168.11.191 | 3306 | ONLINE | 0 | 4 | 4 | 0 | 2438021 | 557781697 | 1968764128 | 160 |
+-----------+----------------+----------+--------------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+

@renecannao
Copy link
Contributor

It is not clear what is happening here. Neither it is clear if it is a problem with ProxySQL routing (probably not).
Have you checked MySQL's error log on 192.168.11.190 ?

@cggy2012
Copy link
Author

There is no error in error log , I will use native support for Group Replication first , Then determine if there is still this problem .

@cggy2012
Copy link
Author

Yesterday there have been three read-only error .

@renecannao
Copy link
Contributor

Is there a reason why mysql-query_digests=false ?
Can you verify if you still have errors with mysql-query_digests=true ?

@cggy2012
Copy link
Author

cggy2012 commented Mar 6, 2018

I want to turn off some of the features I will not use . I will try to set mysql-query_digests=true .

@cggy2012
Copy link
Author

cggy2012 commented Mar 6, 2018

mysql> set mysql-query_digests = 'true';
Query OK, 1 row affected (0.00 sec)

mysql> LOAD MYSQL VARIABLES TO RUNTIME;
Query OK, 0 rows affected (0.00 sec)

mysql> SAVE MYSQL VARIABLES TO DISK;
Query OK, 93 rows affected (0.00 sec)

mysql> show variables like '%dig%';
+---------------------------------------+-------+
| Variable_name | Value |
+---------------------------------------+-------+
| mysql-query_digests_max_digest_length | 2048 |
| mysql-query_digests_max_query_length | 65000 |
| mysql-query_digests | true |
| mysql-query_digests_lowercase | false |
+---------------------------------------+-------+
4 rows in set (0.00 sec)

mysql> select * from stats_mysql_query_digest;
Empty set (0.00 sec)

mysql> select * from stats_mysql_query_digest;
Empty set (0.00 sec)

When I set set mysql-query_digests = 'true' , It did not work ..

@renecannao
Copy link
Contributor

also mysql-commands_stats needs to be enabled.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants