[sr-dev] mysql_ping in db_mysql_submit_query

[Daniel-Constantin Mierla]

I haven't looked at the code of mysql library, but the parameters
suggest there should be a timeout for poll(), with the value 2000ms
(2sec), which obviously does not happen.

If there is no attempt to use the 2nd connection, then the interference
of db_cluster should be minimal, it just passes parameters to the real
db connector module. And in general, db cluster doesn't do anything
special with the db connector module, it should be like sqlops dealing
with two connections, when execution a query on one connection fails,
will try via the second.

Not exactly, but somehow a similar blocking of mysql operation happens
in an issue reported to the tracker (there leads to mem leak as the
timer gets blocked and transactions not removed anymore):

  * https://github.com/kamailio/kamailio/issues/1895

I have little reasons to suspect now the db_cluster code, if you can
test with a newer lib would be good to see the results.

Cheers,
Daniel

On 18.09.19 10:46, Juha Heinanen wrote:
> I build libmariadbclient18 with symbols (below) and got a new backtrace
> of the hanging process.
>
> I guess the only choice is to try with the newer lib that comes with
> Debian Buster or give up use of db_cluster module with MySQL.
>
> -- Juha
>
> ---start 24717 -----------------------------------------------------
> [Thread debugging using libthread_db enabled]
> Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
> 0x00007f517466d8a0 in __poll_nocancel () at ../sysdeps/unix/syscall-template.S:84
> 84	../sysdeps/unix/syscall-template.S: No such file or directory.
> #0  0x00007f517466d8a0 in __poll_nocancel () at ../sysdeps/unix/syscall-template.S:84
> No locals.
> #1  0x00007f51725f3ef1 in poll (__timeout=2000, __nfds=1, __fds=0x7ffed132f808) at /usr/include/x86_64-linux-gnu/bits/poll2.h:46
> No locals.
> #2  vio_io_wait (vio=vio at entry=0x560529eb39d8, event=event at entry=VIO_IO_EVENT_READ, timeout=2000) at ./vio/viosocket.c:992
>         ret = <optimized out>
>         revents = <optimized out>
>         pfd = {fd = 18, events = 3, revents = 0}
>         state = {m_flags = 3509778656, m_socket = 0x7ffed132f820, m_thread = 0x0, m_number_of_bytes = 21474836512, m_timer_start = 140732408199414, m_timer = 0x7ffed132f8fc, m_operation = 3509778680, m_src_file = 0x7ffed132f8fc "\376\177", m_src_line = 16, m_wait = 0x7f517398d010}
> #3  0x00007f51725f3f78 in vio_socket_io_wait (vio=vio at entry=0x560529eb39d8, event=event at entry=VIO_IO_EVENT_READ) at ./vio/viosocket.c:108
>         timeout = <optimized out>
>         ret = -516
> #4  0x00007f51725f4082 in vio_read (vio=vio at entry=0x560529eb39d8, buf=0x560529eb3bd8 "\001", size=size at entry=16384) at ./vio/viosocket.c:184
>         error = <optimized out>
>         ret = <optimized out>
>         flags = 64
> #5  0x00007f51725f4145 in vio_read_buff (vio=0x560529eb39d8, buf=0x560529eb7be8 "\001", size=4) at ./vio/viosocket.c:232
>         rc = <optimized out>
> #6  0x00007f51725cfe91 in my_real_read (net=0x7f5173d674e0, complen=complen at entry=0x7ffed132f9f8, header=0 '\000') at ./sql/net_serv.cc:877
>         pos = 0x560529eb7be8 "\001"
>         length = <optimized out>
>         i = <optimized out>
>         retry_count = <optimized out>
>         len = <optimized out>
>         expect_error_packet = <optimized out>
>         alarmed = 0 '\000'
>         remain = 4
> #7  0x00007f51725d0d1c in my_net_read_packet (net=net at entry=0x7f5173d674e0, read_from_server=read_from_server at entry=0 '\000') at ./sql/net_serv.cc:1140
>         len = <optimized out>
>         complen = 0
> #8  0x00007f51725c28af in cli_safe_read (mysql=mysql at entry=0x7f5173d674e0) at ./sql-common/client.c:587
>         net = 0x7f5173d674e0
>         len = <optimized out>
> #9  0x00007f51725c8323 in cli_advanced_command (mysql=0x7f5173d674e0, command=<optimized out>, header=0x0, header_length=0, arg=0x0, arg_length=0, skip_check=0 '\000', stmt=0x0) at ./sql-common/client.c:729
>         net = 0x7f5173d674e0
>         result = 0 '\000'
>         stmt_skip = <optimized out>
> #10 0x00007f51725be2a1 in mysql_ping (mysql=<optimized out>) at ./libmysql/libmysql.c:982
>         res = <optimized out>
> #11 0x00007f5172bb14e6 in db_mysql_submit_query (_h=0x7f51739ecff0, _s=0x7f5172fff2d0 <sql_str>) at km_dbase.c:83
>         t = 1568791290
>         i = 0
>         code = 22021
>         __func__ = "db_mysql_submit_query"
> #12 0x00007f5172deeb88 in db_do_submit_query (_h=0x7f51739ecff0, _query=0x7f5172fff2d0 <sql_str>, submit_query=0x7f5172bb1149 <db_mysql_submit_query>) at db_query.c:58
>         ret = 32593
>         tvb = {tv_sec = 94580176772804, tv_usec = 139987808866288}
>         tve = {tv_sec = 109108585221, tv_usec = 1365799600152}
>         tz = {tz_minuteswest = 24, tz_dsttime = 65147}
>         tdiff = 1755212864
>         __func__ = "db_do_submit_query"
> #13 0x00007f5172df11ca in db_do_insert_cmd (_h=0x7f51739ecff0, _k=0x7f51689e6960 <db_keys>, _v=0x7f51689e6c40 <db_vals>, _n=24, val2str=0x7f5172baf7b8 <db_mysql_val2str>, submit_query=0x7f5172bb1149 <db_mysql_submit_query>, mode=0) at db_query.c:242
>         off = 707
>         ret = 318
>         __func__ = "db_do_insert_cmd"
> ...
>
>
-- 
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio Advanced Training, Oct 21-23, 2019, Berlin, Germany -- https://asipto.com/u/kat