Deciphered stacktrace
/home/vagrant/workspace/server/core/gateway.c:374
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0) [0x7f25541628d0]
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:85772
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:85016
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:85030 (discriminator 1)
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:86542
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:86566
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:86346
|
|
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:85118
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:86598
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:115112
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:115354
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:128253
|
/home/vagrant/workspace/query_classifier/qc_sqlite/qc_sqlite.c:1376
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:131795
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:133764
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:134961
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:110232
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:110320
|
/home/vagrant/workspace/_build/sqlite-bld-3110100/sqlite3.c:110384
|
/home/vagrant/workspace/query_classifier/qc_sqlite/qc_sqlite.c:394
|
/home/vagrant/workspace/query_classifier/qc_sqlite/qc_sqlite.c:506
|
/home/vagrant/workspace/query_classifier/qc_sqlite/qc_sqlite.c:296
|
/home/vagrant/workspace/query_classifier/qc_sqlite/qc_sqlite.c:322
|
/home/vagrant/workspace/query_classifier/qc_sqlite/qc_sqlite.c:2574
|
/usr/lib/x86_64-linux-gnu/maxscale/libmaxscale-common.so.1.0.0(qc_get_type+0x20) [0x7f2554a8c39b]
|
/home/vagrant/workspace/server/modules/routing/readwritesplit/readwritesplit.c:1918
|
/home/vagrant/workspace/server/modules/routing/readwritesplit/readwritesplit.c:1840
|
/home/vagrant/workspace/server/modules/protocol/mysql_client.c:1388
|
/home/vagrant/workspace/server/modules/protocol/mysql_client.c:898
|
/home/vagrant/workspace/server/modules/protocol/mysql_client.c:849
|
/home/vagrant/workspace/server/modules/protocol/mysql_client.c:532
|
/home/vagrant/workspace/server/core/poll.c:1004
|
/usr/lib/x86_64-linux-gnu/maxscale/libmaxscale-common.so.1.0.0(poll_waitevents+0x5f9) [0x7f2554a8e103]
|
/home/vagrant/workspace/server/core/gateway.c:943
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x80a4) [0x7f255415b0a4]
|
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f2552c2a62d]
|
mensonen Would you know what kind of statement is being handled when the crash occurs?
Not with any certainty, no. For the short duration that I ran this in production, the server was running for a while with info and debug logging enabled, but looking at the queries that the log reported prior to each crash, I can't find anything in common.
I can't really state with any certainty either whether there were queries outside of what was logged (apparently maxscale doesn't really log every single query?). Talking about about 700-800 queries per second at that particular time frame, all of them different in nature; a mixed set of selects, updates and inserts.
Not sure if this is of any help, but I extracted some snippets from the logs just before each crash:
Crash 1
2016-11-16 12:56:08 debug : 140640550168448 [gw_MySQLWrite_backend] write to dcb 0x7fe958012360 fd 28 protocol state MYSQL_IDLE.
|
2016-11-16 12:56:08 debug : 140640550168448 [dcb_write] Append to writequeue. 15 writes buffered for dcb 0x7fe958012360 in state DCB_STATE_POLLING fd 28
|
2016-11-16 12:56:08 debug : 140640550168448 [poll_waitevents] epoll_wait found 3 fds
|
2016-11-16 12:56:08 debug : 140640550168448 [poll_waitevents] event 5 dcb 0x7fe950014dc0 role DCB_ROLE_BACKEND_HANDLER
|
2016-11-16 12:56:08 debug : 140640550168448 [gw_write_backend_event] wrote to dcb 0x7fe950014dc0 fd 34, return 1
|
2016-11-16 12:56:08 debug : 140640550168448 [poll_waitevents] Read in dcb 0x7fe950014dc0 fd 34
|
2016-11-16 12:56:08 debug : 140640550168448 [gw_read_backend_event] Read dcb 0x7fe950014dc0 fd 34 protocol state 11, MYSQL_IDLE.
|
2016-11-16 12:56:08 debug : 140640550168448 [dcb_read] Read 52 bytes from dcb 0x7fe950014dc0 in state DCB_STATE_POLLING fd 34.
|
2016-11-16 12:56:08 debug : 140640550168448 [protocol_get_srv_command] Read command UNKNOWN MYSQL PACKET TYPE for fd 34.
|
2016-11-16 12:56:08 debug : 140640550168448 [dcb_write] Append to writequeue. 18 writes buffered for dcb 0x7fe948011f80 in state DCB_STATE_POLLING fd 31
|
2016-11-16 12:56:08 debug : 140640550168448 [poll_waitevents] epoll_wait found 1 fds
|
2016-11-16 12:56:08 debug : 140640550168448 [poll_waitevents] event 5 dcb 0xac98e0 role DCB_ROLE_CLIENT_HANDLER
|
2016-11-16 12:56:08 debug : 140640550168448 [poll_waitevents] Read in dcb 0xac98e0 fd 42
|
2016-11-16 12:56:08 debug : 140640550168448 [dcb_read] Read 372 bytes from dcb 0xac98e0 in state DCB_STATE_POLLING fd 42.
|
2016-11-16 12:56:08 debug : qc_sqlite: Token 5 not handled explicitly.
|
2016-11-16 12:56:08 debug : qc_sqlite: Token 34 not handled explicitly.
|
2016-11-16 12:56:08 debug : qc_sqlite: Token 125 not handled explicitly.
|
2016-11-16 12:56:08 debug : qc_sqlite: Token 5 not handled explicitly.
|
2016-11-16 12:56:08 [18] info : > Autocommit: [enabled], trx is [open], cmd: COM_QUERY, type: QUERY_TYPE_WRITE, stmt: INSERT INTO customer.wallet_reservation
|
(wallet_id, reference_id, reason, reservation)
|
VALUES (705211, '82197896', NULL, 4950)
|
ON DUPLICATE KEY UPDATE
|
reservation = reservation + VALUES(reservation)
|
|
2016-11-16 12:56:08 [18] info : Route query to master sql02.dbc01....net:3306 <
|
2016-11-16 12:56:08 debug : 140640550168448 [gw_MySQLWrite_backend] write to dcb 0x7fe9580146b0 fd 44 protocol state MYSQL_IDLE.
|
2016-11-16 12:56:08 debug : 140640550168448 [dcb_write] Append to writequeue. 16 writes buffered for dcb 0x7fe9580146b0 in state DCB_STATE_POLLING fd 44
|
2016-11-16 12:56:08 debug : 140640550168448 [poll_waitevents] event 5 dcb 0x7fe950015e70 role DCB_ROLE_CLIENT_HANDLER
|
2016-11-16 12:56:08 debug : 140640550168448 [poll_waitevents] Read in dcb 0x7fe950015e70 fd 25
|
2016-11-16 12:56:08 debug : 140640550168448 [dcb_read] Read 40 bytes from dcb 0x7fe950015e70 in state DCB_STATE_POLLING fd 25.
|
2016-11-16 12:56:08 error : Fatal: MaxScale 2.0.1 received fatal signal 11. Attempting backtrace.
|
Crash 2
2016-11-16 12:56:11 debug : 140079120885504 [poll_waitevents] epoll_wait found 1 fds
|
2016-11-16 12:56:11 debug : 140079120885504 [poll_waitevents] event 5 dcb 0x7f66a00140e0 role DCB_ROLE_BACKEND_HANDLER
|
2016-11-16 12:56:11 debug : 140079120885504 [gw_write_backend_event] wrote to dcb 0x7f66a00140e0 fd 19, return 1
|
2016-11-16 12:56:11 debug : 140079120885504 [poll_waitevents] Read in dcb 0x7f66a00140e0 fd 19
|
2016-11-16 12:56:11 debug : 140079120885504 [gw_read_backend_event] Read dcb 0x7f66a00140e0 fd 19 protocol state 11, MYSQL_IDLE.
|
2016-11-16 12:56:11 debug : 140079120885504 [dcb_read] Read 11 bytes from dcb 0x7f66a00140e0 in state DCB_STATE_POLLING fd 19.
|
2016-11-16 12:56:11 debug : 140079120885504 [protocol_get_srv_command] Read command COM_PING for fd 19.
|
2016-11-16 12:56:11 debug : 140079120885504 [protocol_get_srv_command] Read command COM_PING for fd 19.
|
2016-11-16 12:56:11 debug : 140079120885504 [process_response_data] Read command COM_PING for DCB 0x7f66a00140e0 fd 19.
|
2016-11-16 12:56:11 debug : 140079120885504 [poll_waitevents] epoll_wait found 1 fds
|
2016-11-16 12:56:11 debug : 140079120885504 [poll_waitevents] event 5 dcb 0x7f66a0012ac0 role DCB_ROLE_CLIENT_HANDLER
|
2016-11-16 12:56:11 debug : 140079120885504 [poll_waitevents] Read in dcb 0x7f66a0012ac0 fd 16
|
2016-11-16 12:56:11 debug : 140079120885504 [dcb_read] Read 13 bytes from dcb 0x7f66a0012ac0 in state DCB_STATE_POLLING fd 16.
|
2016-11-16 12:56:11 debug : qc_sqlite: Token 5 not handled explicitly.
|
2016-11-16 12:56:11 [6] info : > Autocommit: [enabled], trx is [not open], cmd: COM_QUERY, type: QUERY_TYPE_READ, stmt: SELECT 1
|
2016-11-16 12:56:11 [6] info : Route query to slave sql01.dbc01....net:3306 <
|
2016-11-16 12:56:11 debug : 140079120885504 [gw_MySQLWrite_backend] write to dcb 0x7f66a0013120 fd 17 protocol state MYSQL_IDLE.
|
2016-11-16 12:56:11 debug : 140079120885504 [dcb_write] Append to writequeue. 276 writes buffered for dcb 0x7f66a0013120 in state DCB_STATE_POLLING fd 17
|
2016-11-16 12:56:11 debug : 140079120885504 [poll_waitevents] epoll_wait found 1 fds
|
2016-11-16 12:56:11 debug : 140079120885504 [poll_waitevents] event 5 dcb 0x7f66a0013120 role DCB_ROLE_BACKEND_HANDLER
|
2016-11-16 12:56:11 debug : 140079120885504 [gw_write_backend_event] wrote to dcb 0x7f66a0013120 fd 17, return 1
|
2016-11-16 12:56:11 debug : 140079120885504 [poll_waitevents] Read in dcb 0x7f66a0013120 fd 17
|
2016-11-16 12:56:11 debug : 140079120885504 [gw_read_backend_event] Read dcb 0x7f66a0013120 fd 17 protocol state 11, MYSQL_IDLE.
|
2016-11-16 12:56:11 debug : 140079120885504 [dcb_read] Read 56 bytes from dcb 0x7f66a0013120 in state DCB_STATE_POLLING fd 17.
|
2016-11-16 12:56:11 debug : 140079120885504 [protocol_get_srv_command] Read command UNKNOWN MYSQL PACKET TYPE for fd 17.
|
2016-11-16 12:56:11 debug : 140079120885504 [dcb_write] Append to writequeue. 380 writes buffered for dcb 0x7f66a0012ac0 in state DCB_STATE_POLLING fd 16
|
2016-11-16 12:56:11 debug : 140079120885504 [poll_waitevents] epoll_wait found 1 fds
|
2016-11-16 12:56:11 debug : 140079120885504 [poll_waitevents] event 5 dcb 0x7f66a001de60 role DCB_ROLE_CLIENT_HANDLER
|
2016-11-16 12:56:11 debug : 140079120885504 [poll_waitevents] Read in dcb 0x7f66a001de60 fd 86
|
2016-11-16 12:56:11 debug : 140079120885504 [dcb_read] Read 40 bytes from dcb 0x7f66a001de60 in state DCB_STATE_POLLING fd 86.
|
2016-11-16 12:56:11 error : Fatal: MaxScale 2.0.1 received fatal signal 11. Attempting backtrace
|
Crash 3
2016-11-16 12:56:25 debug : qc_sqlite: Token 5 not handled explicitly.
|
2016-11-16 12:56:25 debug : qc_sqlite: Token 5 not handled explicitly.
|
2016-11-16 12:56:25 debug : qc_sqlite: Token 5 not handled explicitly.
|
2016-11-16 12:56:25 debug : qc_sqlite: Token 5 not handled explicitly.
|
2016-11-16 12:56:25 debug : qc_sqlite: Token 103 not handled explicitly.
|
2016-11-16 12:56:25 debug : qc_sqlite: Token 34 not handled explicitly.
|
2016-11-16 12:56:25 [5] info : > Autocommit: [enabled], trx is [not open], cmd: COM_QUERY, type: QUERY_TYPE_READ, stmt: SELECT <snip>
|
2016-11-16 12:56:25 [5] info : Route query to slave sql01.dbc01....net:3306 <
|
2016-11-16 12:56:25 debug : 139798090082048 [gw_MySQLWrite_backend] write to dcb 0x7f25380125e0 fd 16 protocol state MYSQL_IDLE.
|
2016-11-16 12:56:25 debug : 139798090082048 [dcb_write] Append to writequeue. 1204 writes buffered for dcb 0x7f25380125e0 in state DCB_STATE_POLLING fd 16
|
2016-11-16 12:56:25 debug : 139798090082048 [poll_waitevents] epoll_wait found 1 fds
|
2016-11-16 12:56:25 debug : 139798090082048 [poll_waitevents] event 5 dcb 0x1ee1c30 role DCB_ROLE_CLIENT_HANDLER
|
2016-11-16 12:56:25 debug : 139798090082048 [poll_waitevents] Read in dcb 0x1ee1c30 fd 98
|
2016-11-16 12:56:25 debug : 139798090082048 [dcb_read] Read 40 bytes from dcb 0x1ee1c30 in state DCB_STATE_POLLING fd 98.
|
2016-11-16 12:56:25 error : Fatal: MaxScale 2.0.1 received fatal signal 11. Attempting backtrace.
|
Thanks for the log snippets, even though there were no smoking gun 
The QLA filter https://mariadb.com/kb/en/mariadb-enterprise/mariadb-maxscale-14/maxscale-query-log-all-filter can be used for logging all queries, although in a crash case like this, the logged query might not hit the disk before the process crashes.
If I were to build a version of `qc_sqlite` that logs all queries to disk before parsing them, would you be interested in testing with that, so that we would get the precise statement that is being processed when the crash occurs? I understand if you are not, since it will cause a performance hit.
I might add that I'm actually pretty convinced this is not related to the precise statement. Namely, MXS-970 reports a crash with exactly the same stack trace.
If you have a core file that it is possible to share, please let me know.
Yes, I saw MXS-970 too and the scenario looked entirely different to what we're experiencing here.
We do have one person using sequel pro, just like in that ticket, but they weren't trying to connect at the time of the crash. Just to be sure, I ran now an isolated test, letting them connect alone to the maxscale instance that crashed yesterday and run some queries that they usually do, but everything ran smoothly.
The only other client tool we use is mysql workbench and I tested that too - no crashes.
Also tried throwing similar traffic to it as at the time of the crash, but from a test bench (so considerably lower query rate than with production traffic), also no crashes.
I'm willing to run a special build for a short while under production load, if you think that will reveal something (but as you said, probably not a single statement..). No core dump from that time, but I can try to produce one.
Thanks. I'll continue investigating for a while before making any modifications, because I think I am on to something.
Namely, the crash occurs when sqlite is parsing a select of its own, due to some other statement being parsed. That it does, for instance, at least, when a CREATE TABLE statement is parsed for the first time, for the current thread. I'll see if I could change that, so that all needed initialization would be performed at startup.
A minor update; I have been running maxscale in terminal against production traffic for 45 minutes now, trying to produce a core dump, but no crash has taken place (yet). The only difference is that the average query rate is today considerably lower than it was yesterday (only ~100 / second, compared to yesterday's ~500 / second).
I can now reliably reproduce the crash, simply by attempting to login onto the server with Sequel Pro, versions at least 1.0.2 or 1.1-rc1, while maxscale is otherwise idling with no traffic at all. Newest Sequel Pro version does not seem to produce a crash at all (1.1.2 tested too).
Core dump is available if you still need it.
Thanks, that's good to know.
No, a core dump is not needed anymore as I've successfully reproduced this myself now. But thanks for the offer!
Fixed by commit https://github.com/mariadb-corporation/MaxScale/commit/ecb6680e71f064e1f14c316558ab4f688fec9265