Skip to content

mysql driver freeze, and hang the query progress,Does this normal? #392

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

Closed
ghost opened this issue Dec 10, 2015 · 13 comments
Closed

mysql driver freeze, and hang the query progress,Does this normal? #392

ghost opened this issue Dec 10, 2015 · 13 comments

Comments

@ghost
Copy link

ghost commented Dec 10, 2015

here is strace output

{{EPOLLIN|EPOLLOUT, {u32=1179919736, u64=140029998671224}}}, 128, -1) = 1
12:01:55 futex(0xc820028e90, FUTEX_WAKE, 1) = 1
12:01:55 futex(0x7ea700, FUTEX_WAKE, 1) = 1
12:01:55 futex(0x7ea640, FUTEX_WAKE, 1) = 1
12:01:55 read(103, "\f\0\0\1\0\2\0\0\0\1\0\1\0\0\0\0\27\0\0\2\3def\0\0\0\1?\0\f?"..., 4096) = 89
12:01:55 write(103, "\26\0\0\0\27\2\0\0\0\0\1\0\0\0\0\1\10\0\313\234\n\0\0\0\0\0", 26) = 26
12:01:55 read(103, 0xc82026f000, 4096)  = -1 EAGAIN (Resource temporarily unavailable)
12:01:55 futex(0x7eadd0, FUTEX_WAIT, 0, NULL

) = 0

@ghost
Copy link
Author

ghost commented Dec 10, 2015

[pid  5951] 12:25:56 futex(0xc820028e90, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  5949] 12:25:56 <... select resumed> ) = 0 (Timeout)
[pid  5949] 12:25:56 futex(0x7ea700, FUTEX_WAIT, 0, {60, 0} <unfinished ...>
[pid  5948] 12:25:56 <... epoll_wait resumed> {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1616539456, u64=140597370974016}}}, 128, -1) = 1
[pid  5948] 12:25:56 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1616539264, u64=140597370973824}}}, 128, -1) = 1
[pid  5948] 12:25:56 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1616539072, u64=140597370973632}}}, 128, -1) = 1
[pid  5948] 12:25:56 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1616538880, u64=140597370973440}}}, 128, -1) = 1
[pid  5948] 12:25:56 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1616538688, u64=140597370973248}}}, 128, -1) = 1
[pid  5948] 12:25:57 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1616538496, u64=140597370973056}}}, 128, -1) = 1
[pid  5948] 12:25:57 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1616538304, u64=140597370972864}}}, 128, -1) = 1
[pid  5948] 12:25:57 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1616538112, u64=140597370972672}}}, 128, -1) = 1
[pid  5948] 12:25:57 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1616537920, u64=140597370972480}}}, 128, -1) = 1
[pid  5948] 12:25:57 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1616537728, u64=140597370972288}}}, 128, -1) = 1
[pid  5948] 12:25:57 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1616537536, u64=140597370972096}}}, 128, -1) = 1
[pid  5948] 12:25:57 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1616537344, u64=140597370971904}}}, 128, -1) = 1
[pid  5948] 12:25:57 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584771064, u64=140597339205624}}}, 128, -1) = 1
[pid  5948] 12:25:57 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584770872, u64=140597339205432}}}, 128, -1) = 1
[pid  5948] 12:25:58 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584770680, u64=140597339205240}}}, 128, -1) = 1
[pid  5948] 12:25:58 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584770488, u64=140597339205048}}}, 128, -1) = 1
[pid  5948] 12:25:58 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584770296, u64=140597339204856}}}, 128, -1) = 1
[pid  5948] 12:25:58 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584770104, u64=140597339204664}}}, 128, -1) = 1
[pid  5948] 12:25:58 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584769912, u64=140597339204472}}}, 128, -1) = 1
[pid  5948] 12:25:58 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584769720, u64=140597339204280}}}, 128, -1) = 1
[pid  5948] 12:25:58 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584769528, u64=140597339204088}}}, 128, -1) = 1
[pid  5948] 12:25:58 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584769336, u64=140597339203896}}}, 128, -1) = 1
[pid  5948] 12:25:58 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584769144, u64=140597339203704}}}, 128, -1) = 1
[pid  5948] 12:25:59 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584768952, u64=140597339203512}}}, 128, -1) = 1
[pid  5948] 12:25:59 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584768760, u64=140597339203320}}}, 128, -1) = 1
[pid  5948] 12:25:59 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584768568, u64=140597339203128}}}, 128, -1) = 1
[pid  5948] 12:25:59 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=1584768376, u64=140597339202936}}}, 128, -1) = 1
[pid  5948] 12:25:59 epoll_wait(4, {{EPOLLIN|EPOLLOUT|EPOLLRDH

@ghost ghost changed the title mysql driver freeze, and hang the query progress mysql driver freeze, and hang the query progress,Does this normal? Dec 10, 2015
@ghost
Copy link
Author

ghost commented Dec 10, 2015

[pid 23383] 15:28:21 futex(0x814080, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 23382] 15:28:21 restart_syscall(<... resuming interrupted call ...> <unfinished ...>
[pid 23387] 15:28:21 futex(0xc820025790, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 23386] 15:28:21 futex(0xc8200a0110, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 23385] 15:28:21 epoll_wait(4,  <unfinished ...>
[pid 23384] 15:28:21 futex(0xc820024e90, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 23373] 15:28:21 futex(0x7f0010, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid 23382] 15:29:05 <... restart_syscall resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 23382] 15:29:05 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
[pid 23382] 15:29:05 futex(0x7ef720, FUTEX_WAIT, 0, {60, 0}) = -1 ETIMEDOUT (Connection timed out)
[pid 23382] 15:30:05 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
[pid 23382] 15:30:05 futex(0x7ef720, FUTEX_WAIT, 0, {60, 0}

@methane
Copy link
Member

methane commented Dec 12, 2015

You don't write about what did you do.
No one can say about it's normal or not.

@ghost
Copy link
Author

ghost commented Dec 12, 2015

The common DB.Query, DB.Exec sql command.

nothing serious

@methane
Copy link
Member

methane commented Dec 12, 2015

strace output you wrote looks very common for Go's runtime.

What query do you send?
Have you tried same query from mysql cli? How long it takes?

@ghost
Copy link
Author

ghost commented Dec 12, 2015

I am wrote the same program using php, it works well with mysql.
The golang version program will freeze after a while.
The connection seems broken, but not disconnected. so we can not handle the hangs up.

@methane
Copy link
Member

methane commented Dec 12, 2015

I am wrote the same program using php, it works well with mysql.

No one verify it until you share reproducible sample code.

The connection seems broken,

Why? There are only two lines about mysql in your strace.

12:01:55 read(103, "\f\0\0\1\0\2\0\0\0\1\0\1\0\0\0\0\27\0\0\2\3def\0\0\0\1?\0\f?"..., 4096) = 89
12:01:55 write(103, "\26\0\0\0\27\2\0\0\0\0\1\0\0\0\0\1\10\0\313\234\n\0\0\0\0\0", 26) = 26

First line is receiving OK packet. You should be able to fetch results if your program doesn't have bugs.
Second line tells mysql driver sends something. But it seems not a valid mysql packet.
Parhaps, you forgot -f option of strace. Since there are no [pid xxxx] prefix in your first post.

Another strace output are meaningless. futex and epoll_wait is used in Go's runtime.
It's not relating to mysql.

@ghost
Copy link
Author

ghost commented Dec 12, 2015

this package, mysql go sql driver using network library to communicate mysql server via tcp protocol.
The problems was : the connection broken , but there is no way to set read timeout / wait timeout at our client side.
so if not success read here, lead connection hangs up.

@ghost
Copy link
Author

ghost commented Dec 12, 2015

[pid 23382] 15:29:05 <... restart_syscall resumed> ) = -1 ETIMEDOUT (Connection timed out)

As strace output said. the connection already timed out.
so we should close the connection , but currently we have no way to terminate the connection

@ghost
Copy link
Author

ghost commented Dec 12, 2015

I hope the IPConn.SetReadDeadline will helpful with my situation.
https://golang.org/pkg/net/#IPConn.SetReadDeadline

@ghost ghost mentioned this issue Dec 12, 2015
@methane
Copy link
Member

methane commented Dec 12, 2015

@netroby Your strace doesn't include which syscall returns ETIMEDOUT.

[pid 23382] 15:28:21 restart_syscall(<... resuming interrupted call ...> <unfinished ...>
[pid 23382] 15:29:05 <... restart_syscall resumed> ) = -1 ETIMEDOUT (Connection timed out)

It may not be related to mysql connection.

@methane
Copy link
Member

methane commented Dec 12, 2015

For example, futex may return ETIMEDOUT and it's not related TCP.
http://man7.org/linux/man-pages/man2/futex.2.html

@methane
Copy link
Member

methane commented Dec 12, 2015

Your strace doesn't have important part.
I recommend you to use strace -f -s300 -e!futex,epoll_wait and report enough outout.

tcpdump is also good tool to know TCP state.

But, reporting reproducible code is best.

@ghost ghost closed this as completed Dec 15, 2015
This issue was closed.
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

1 participant