Mysql: Connection Pool seems not to be used properly (any longer)
Issue description
the connection pooling to the database server seems to be broken since golang version 1.13.1 or with the latest commit (14bb9c0).
running in version 1.12.9 and up to git commit 877a977 everything seemed to work
I have two servers, running each GO applications, that held two different connection pools to the same database-server - one connection is heavily used (DB1 with 20 Requests per second) and one is rarely used (DB2 with 1 Request per Minute)
server1 runs since round about 5-10 minutes,
server 2 runs since round about 3 days.
broken means that a part of the connections is no longer used and seems to be stale:
MariaDB [(none)]> SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST where HOST like '%server1%';
+--------+------+---------------+--------+---------+------+-------+------+------------+-------+-----------+----------+-------------+---------------+-----------+
| ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO | TIME_MS | STAGE | MAX_STAGE | PROGRESS | MEMORY_USED | EXAMINED_ROWS | QUERY_ID |
+--------+------+---------------+--------+---------+------+-------+------+------------+-------+-----------+----------+-------------+---------------+-----------+
| 599325 | dbuser | server1:41744 | DB1 | Sleep | 0 | | NULL | 423.089 | 0 | 0 | 0.000 | 83672 | 0 | 653926700 |
| 599233 | dbuser | server1:38024 | DB2 | Sleep | 57 | | NULL | 57283.466 | 0 | 0 | 0.000 | 83680 | 0 | 653885165 |
| 599232 | dbuser | server1:38022 | DB2 | Sleep | 117 | | NULL | 117233.167 | 0 | 0 | 0.000 | 83680 | 0 | 653840343 |
| 599205 | dbuser | server1:37538 | DB1 | Sleep | 0 | | NULL | 523.742 | 0 | 0 | 0.000 | 83680 | 0 | 653926568 |
| 599204 | dbuser | server1:37534 | DB1 | Sleep | 0 | | NULL | 356.378 | 0 | 0 | 0.000 | 83672 | 0 | 653926789 |
| 599203 | dbuser | server1:37532 | DB1 | Sleep | 0 | | NULL | 120.182 | 0 | 0 | 0.000 | 83672 | 0 | 653927036 |
| 599164 | dbuser | server1:36566 | DB1 | Sleep | 0 | | NULL | 118.011 | 0 | 0 | 0.000 | 100544 | 0 | 653927037 |
| 599163 | dbuser | server1:36522 | DB1 | Sleep | 0 | | NULL | 368.234 | 0 | 0 | 0.000 | 83688 | 0 | 653926767 |
| 599162 | dbuser | server1:36498 | DB1 | Sleep | 0 | | NULL | 413.715 | 0 | 0 | 0.000 | 83672 | 0 | 653926722 |
| 599161 | dbuser | server1:36496 | DB1 | Sleep | 0 | | NULL | 182.833 | 0 | 0 | 0.000 | 83688 | 0 | 653926948 |
| 599160 | dbuser | server1:36488 | DB1 | Sleep | 0 | | NULL | 170.804 | 0 | 0 | 0.000 | 83680 | 0 | 653926989 |
| 599159 | dbuser | server1:36486 | DB1 | Sleep | 0 | | NULL | 480.610 | 0 | 0 | 0.000 | 83672 | 0 | 653926634 |
| 599157 | dbuser | server1:36482 | DB2 | Sleep | 399 | | NULL | 399946.550 | 0 | 0 | 0.000 | 91896 | 0 | 653625317 |
| 599156 | dbuser | server1:36480 | DB1 | Sleep | 400 | | NULL | 400178.841 | 0 | 0 | 0.000 | 59664 | 0 | 653625282 |
| 599155 | dbuser | server1:36478 | DB1 | Sleep | 400 | | NULL | 400196.065 | 0 | 0 | 0.000 | 100032 | 0 | 653625241 |
+--------+------+---------------+--------+---------+------+-------+------+------------+-------+-----------+----------+-------------+---------------+-----------+
I am a little bit confused about those two conenctions at the end...
While on the other server go runs the old version and commit:
MariaDB [(none)]> SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST where HOST like '%server2%';
+--------+------+---------------------+--------+---------+------+-------+------+------------+-------+-----------+----------+-------------+---------------+-----------+
| ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO | TIME_MS | STAGE | MAX_STAGE | PROGRESS | MEMORY_USED | EXAMINED_ROWS | QUERY_ID |
+--------+------+---------------------+--------+---------+------+-------+------+------------+-------+-----------+----------+-------------+---------------+-----------+
| 453236 | dbuser | server2:33138 | DB1 | Sleep | 0 | | NULL | 954.053 | 0 | 0 | 0.000 | 83672 | 0 | 653925859 |
| 453235 | dbuser | server2:33136 | DB1 | Sleep | 2 | | NULL | 2311.532 | 0 | 0 | 0.000 | 83672 | 0 | 653925175 |
| 453234 | dbuser | server2:33132 | DB1 | Sleep | 0 | | NULL | 792.861 | 0 | 0 | 0.000 | 83672 | 0 | 653925992 |
| 453233 | dbuser | server2:33130 | DB1 | Sleep | 2 | | NULL | 2065.223 | 0 | 0 | 0.000 | 83672 | 0 | 653925349 |
| 453232 | dbuser | server2:33126 | DB1 | Sleep | 2 | | NULL | 2812.222 | 0 | 0 | 0.000 | 100560 | 0 | 653924906 |
| 453231 | dbuser | server2:33124 | DB1 | Sleep | 1 | | NULL | 1487.906 | 0 | 0 | 0.000 | 83672 | 0 | 653925637 |
| 453230 | dbuser | server2:33120 | DB1 | Sleep | 0 | | NULL | 287.197 | 0 | 0 | 0.000 | 83672 | 0 | 653926457 |
| 453229 | dbuser | server2:33118 | DB1 | Sleep | 0 | | NULL | 84.411 | 0 | 0 | 0.000 | 83672 | 0 | 653926656 |
| 453226 | dbuser | server2:33114 | DB1 | Sleep | 0 | | NULL | 121.208 | 0 | 0 | 0.000 | 100544 | 0 | 653926612 |
| 453225 | dbuser | server2:33112 | DB1 | Sleep | 0 | | NULL | 509.967 | 0 | 0 | 0.000 | 83672 | 0 | 653926103 |
| 453222 | dbuser | server2:33106 | DB1 | Sleep | 2 | | NULL | 2904.463 | 0 | 0 | 0.000 | 83672 | 0 | 653924840 |
| 453221 | dbuser | server2:33108 | DB1 | Sleep | 0 | | NULL | 363.417 | 0 | 0 | 0.000 | 83688 | 0 | 653926217 |
| 436446 | dbuser | server2:45546 | DB2 | Sleep | 175 | | NULL | 175585.732 | 0 | 0 | 0.000 | 83680 | 0 | 653799233 |
| 436445 | dbuser | server2:45544 | DB2 | Sleep | 55 | | NULL | 55673.248 | 0 | 0 | 0.000 | 83680 | 0 | 653885968 |
| 436443 | dbuser | server2:45534 | DB2 | Sleep | 115 | | NULL | 115555.698 | 0 | 0 | 0.000 | 83680 | 0 | 653840992 |
| 436442 | dbuser | server2:45532 | DB2 | Sleep | 235 | | NULL | 235540.642 | 0 | 0 | 0.000 | 83680 | 0 | 653751459 |
| 436438 | dbuser | server2:45372 | DB1 | Sleep | 0 | | NULL | 7.290 | 0 | 0 | 0.000 | 124632 | 0 | 653926744 |
| 436437 | dbuser | server2:45370 | DB1 | Sleep | 0 | | NULL | 314.409 | 0 | 0 | 0.000 | 83672 | 0 | 653926392 |
| 436436 | dbuser | server2:45344 | DB1 | Sleep | 1 | | NULL | 1791.661 | 0 | 0 | 0.000 | 83680 | 0 | 653925459 |
| 436435 | dbuser | server2:45342 | DB1 | Sleep | 2 | | NULL | 2208.515 | 0 | 0 | 0.000 | 116928 | 0 | 653925261 |
| 436434 | dbuser | server2:45340 | DB1 | Sleep | 1 | | NULL | 1391.047 | 0 | 0 | 0.000 | 100056 | 0 | 653925725 |
| 436433 | dbuser | server2:45338 | DB1 | Sleep | 2 | | NULL | 2441.613 | 0 | 0 | 0.000 | 100544 | 0 | 653925062 |
| 436432 | dbuser | server2:45336 | DB1 | Sleep | 1 | | NULL | 1806.901 | 0 | 0 | 0.000 | 83672 | 0 | 653925436 |
| 436431 | dbuser | server2:45334 | DB1 | Sleep | 0 | | NULL | 567.622 | 0 | 0 | 0.000 | 83672 | 0 | 653926059 |
| 436430 | dbuser | server2:45332 | DB1 | Sleep | 0 | | NULL | 840.094 | 0 | 0 | 0.000 | 100056 | 0 | 653925948 |
| 436429 | dbuser | server2:45330 | DB1 | Sleep | 1 | | NULL | 1152.405 | 0 | 0 | 0.000 | 83672 | 0 | 653925793 |
| 436428 | dbuser | server2:45324 | DB1 | Sleep | 2 | | NULL | 2424.172 | 0 | 0 | 0.000 | 83672 | 0 | 653925084 |
| 436427 | dbuser | server2:45322 | DB1 | Sleep | 0 | | NULL | 402.280 | 0 | 0 | 0.000 | 83672 | 0 | 653926193 |
+--------+------+---------------------+--------+---------+------+-------+------+------------+-------+-----------+----------+-------------+---------------+-----------+
The point why I've been paying attention to this is that all of my connections from server1 got stale after about 38 hours of running. The Connections were not interrupted (all 50 connections were stale) and new connections (i've started another instance of the same application) were able to create new connections to the database server.
Maybe you have an idea how to debug such a situation...
Example code
all of the databases requests look like this, while the initial connection is only initiated once and then the pool is used.
////////////////////// DB Connection
// establish database connection
var dsn = appConfiguration.dbuser + ":" + appConfiguration.dbpass + "@tcp(" + appConfiguration.dbhostname + ":" + appConfiguration.dbport + ")/" + appConfiguration.dbNamename
dbName, err := sql.Open("mysql", dsn)
dbName.SetConnMaxLifetime(0)
dbName.SetMaxIdleConns(50)
dbName.SetMaxOpenConns(50)
// if there is an error opening the connection, handle it
if err != nil {
panic(err.Error())
}
ctxVCspstoredprocedure := context.Background()
rowsResultsVCspstoredprocedure, err := dbName.QueryContext(ctxVCspstoredprocedure, "CALL storedprocedure((?),(?),(?),(?),(?),(?),(?),(?),(?));", "version", "xxx", "xxx", "p", "1", sql.NullString{}, sql.NullString{}, appConfiguration.identifier, 1)
if err != nil {
log.Fatal(err)
}
defer rowsResultsVCspstoredprocedure.Close()
for rowsResultsVCspstoredprocedure.Next() {
var spstoredprocedureVersion int
var spstoredprocedureVar1 int
var spstoredprocedureVar2 int
if err := rowsResultsVCspstoredprocedure.Scan(&spstoredprocedureVar1, &spstoredprocedureVar2, &spstoredprocedureVersion); err != nil {
log.Fatal(err)
}
if spstoredprocedureVersion != SPstoredprocedureVERSIONREQUIREMENT {
println(time.Now().Format(time.RFC3339) + " " + " - START - SPstoredprocedure VERSION check - ERROR: Version does not meet requirements by this version. Application requires: " + strconv.Itoa(SPstoredprocedureVERSIONREQUIREMENT) + " but DB seems to be: " + strconv.Itoa(spstoredprocedureVersion))
os.Exit(3)
} else {
println(time.Now().Format(time.RFC3339) + " - START - SPstoredprocedure VERSION check - PASSED")
}
}
if err := rowsResultsVCspstoredprocedure.Err(); err != nil {
// print error when something went wrong
println(time.Now().Format(time.RFC3339)+" - START - SPstoredprocedure VERSION check - GENERAL DB RESULTS ERROR:", err.Error())
println(time.Now().Format(time.RFC3339) + " - START - SPstoredprocedure VERSION check - Stored Predure and/or Table Structure missing - EXIT")
os.Exit(3)
}
Configuration
Server version: Maria.DB 10.0.38
Server OS: Debian 10 (buster) - latest updates applied, Go Applications running in Docker Container
mwiora
All 29 comments
I can not understand what's your point. What stale means? What is your issue?
Anyway, I strongly recommend not do this:
dbName.SetConnMaxLifetime(0)
I recommend a shorter (less than 5 min) lifetime. Long lifetime causes many random trobles.
I suppose your issue is one of them.
methane
on 9 Oct 2019
okay! I'll give it a try - let me check that and I'll report back asap.
with stale I mean that the connection is no longer used obviously.
Meanwhile after 2 hours I have the following connection processlist from server1, while server2 is unchanged (all connections are nearly 0 seconds from last time):
MariaDB [(none)]> SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST where HOST like '%server1%';
+--------+------+---------------+--------+---------+------+-------+------+-------------+-------+-----------+----------+-------------+---------------+-----------+
| ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO | TIME_MS | STAGE | MAX_STAGE | PROGRESS | MEMORY_USED | EXAMINED_ROWS | QUERY_ID |
+--------+------+---------------+--------+---------+------+-------+------+-------------+-------+-----------+----------+-------------+---------------+-----------+
| 599894 | dbuser | server1:39384 | DB1 | Sleep | 0 | | NULL | 87.569 | 0 | 0 | 0.000 | 83672 | 0 | 659699576 |
| 599893 | dbuser | server1:39382 | DB1 | Sleep | 364 | | NULL | 364457.042 | 0 | 0 | 0.000 | 83680 | 0 | 659410678 |
| 599892 | dbuser | server1:39380 | DB1 | Sleep | 0 | | NULL | 319.257 | 0 | 0 | 0.000 | 83672 | 0 | 659699378 |
| 599891 | dbuser | server1:39376 | DB1 | Sleep | 0 | | NULL | 13.775 | 0 | 0 | 0.000 | 83672 | 0 | 659699661 |
| 599890 | dbuser | server1:39374 | DB1 | Sleep | 0 | | NULL | 264.067 | 0 | 0 | 0.000 | 108248 | 0 | 659699466 |
| 599889 | dbuser | server1:39366 | DB1 | Sleep | 126 | | NULL | 126360.148 | 0 | 0 | 0.000 | 83664 | 0 | 659597390 |
| 599888 | dbuser | server1:39362 | DB1 | Sleep | 551 | | NULL | 551303.241 | 0 | 0 | 0.000 | 83672 | 0 | 659262113 |
| 599887 | dbuser | server1:39354 | DB1 | Sleep | 0 | | NULL | 149.435 | 0 | 0 | 0.000 | 83672 | 0 | 659699554 |
| 599886 | dbuser | server1:39350 | DB1 | Sleep | 0 | | NULL | 45.577 | 0 | 0 | 0.000 | 83688 | 0 | 659699621 |
| 599325 | dbuser | server1:41744 | DB1 | Sleep | 275 | | NULL | 275723.085 | 0 | 0 | 0.000 | 83680 | 0 | 659482988 |
| 599233 | dbuser | server1:38024 | DB2 | Sleep | 109 | | NULL | 109042.583 | 0 | 0 | 0.000 | 83680 | 0 | 659611987 |
| 599232 | dbuser | server1:38022 | DB2 | Sleep | 48 | | NULL | 48887.447 | 0 | 0 | 0.000 | 83680 | 0 | 659657714 |
| 599205 | dbuser | server1:37538 | DB1 | Sleep | 106 | | NULL | 106863.013 | 0 | 0 | 0.000 | 100072 | 0 | 659613951 |
| 599204 | dbuser | server1:37534 | DB1 | Sleep | 397 | | NULL | 397423.651 | 0 | 0 | 0.000 | 83688 | 0 | 659382964 |
| 599203 | dbuser | server1:37532 | DB1 | Sleep | 163 | | NULL | 163976.745 | 0 | 0 | 0.000 | 83688 | 0 | 659569290 |
| 599164 | dbuser | server1:36566 | DB1 | Sleep | 535 | | NULL | 535095.296 | 0 | 0 | 0.000 | 116944 | 0 | 659274593 |
| 599163 | dbuser | server1:36522 | DB1 | Sleep | 0 | | NULL | 190.129 | 0 | 0 | 0.000 | 121024 | 0 | 659699532 |
| 599162 | dbuser | server1:36498 | DB1 | Sleep | 804 | | NULL | 804635.906 | 0 | 0 | 0.000 | 83672 | 0 | 659055170 |
| 599161 | dbuser | server1:36496 | DB1 | Sleep | 0 | | NULL | 10.261 | 0 | 0 | 0.000 | 83672 | 0 | 659699665 |
| 599160 | dbuser | server1:36488 | DB1 | Sleep | 0 | | NULL | 267.253 | 0 | 0 | 0.000 | 83688 | 0 | 659699458 |
| 599159 | dbuser | server1:36486 | DB1 | Sleep | 383 | | NULL | 383663.115 | 0 | 0 | 0.000 | 83672 | 0 | 659394896 |
| 599157 | dbuser | server1:36482 | DB2 | Sleep | 7733 | | NULL | 7733659.086 | 0 | 0 | 0.000 | 91896 | 0 | 653625317 |
| 599156 | dbuser | server1:36480 | DB1 | Sleep | 7733 | | NULL | 7733891.377 | 0 | 0 | 0.000 | 59664 | 0 | 653625282 |
| 599155 | dbuser | server1:36478 | DB1 | Sleep | 7733 | | NULL | 7733908.601 | 0 | 0 | 0.000 | 100032 | 0 | 653625241 |
+--------+------+---------------+--------+---------+------+-------+------+-------------+-------+-----------+----------+-------------+---------------+-----------+
what I am confused about is the fact that the same code works with the old configuration (golang 1.12.9 and other updates not applied) - in case we find no working configuration I would update each component separately...
mwiora
on 9 Oct 2019
i've configured a maximum of 300ms
dbName.SetConnMaxLifetime(300)
dbName.SetMaxIdleConns(50)
dbName.SetMaxOpenConns(50)
the resulting connection processlist after a few minutes:
MariaDB [(none)]> SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST where HOST like '%server1%';
+--------+------+---------------+--------+---------+------+-------+------+------------+-------+-----------+----------+-------------+---------------+-----------+
| ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO | TIME_MS | STAGE | MAX_STAGE | PROGRESS | MEMORY_USED | EXAMINED_ROWS | QUERY_ID |
+--------+------+---------------+--------+---------+------+-------+------+------------+-------+-----------+----------+-------------+---------------+-----------+
| 712125 | dbuser | server1:58058 | DB1 | Sleep | 0 | | NULL | 14.037 | 0 | 0 | 0.000 | 83672 | 0 | 662372514 |
| 712124 | dbuser | server1:58056 | DB1 | Sleep | 0 | | NULL | 17.206 | 0 | 0 | 0.000 | 83672 | 0 | 662372510 |
| 712123 | dbuser | server1:58054 | DB1 | Sleep | 0 | | NULL | 32.314 | 0 | 0 | 0.000 | 51992 | 0 | 0 |
| 712122 | dbuser | server1:58050 | DB1 | Sleep | 0 | | NULL | 34.605 | 0 | 0 | 0.000 | 51992 | 0 | 0 |
| 712120 | dbuser | server1:58046 | DB1 | Sleep | 0 | | NULL | 25.449 | 0 | 0 | 0.000 | 83672 | 0 | 662372471 |
| 712118 | dbuser | server1:58044 | DB1 | Sleep | 0 | | NULL | 44.834 | 0 | 0 | 0.000 | 51992 | 0 | 0 |
| 684148 | dbuser | server1:60410 | DB2 | Sleep | 757 | | NULL | 757315.513 | 0 | 0 | 0.000 | 91896 | 0 | 661754354 |
| 684147 | dbuser | server1:60408 | DB1 | Sleep | 757 | | NULL | 757488.355 | 0 | 0 | 0.000 | 59664 | 0 | 661754342 |
| 684146 | dbuser | server1:60406 | DB1 | Sleep | 757 | | NULL | 757503.817 | 0 | 0 | 0.000 | 100032 | 0 | 661754299 |
+--------+------+---------------+--------+---------+------+-------+------+------------+-------+-----------+----------+-------------+---------------+-----------+
The connection that seem stale remain in the end of the list - all other connections above are getting killed and reestablished randomly.
I'll keep an eye on that and report back.
mwiora
on 9 Oct 2019
dbName.SetConnMaxLifetime(300)
It is not 300ms, but 300ns. It almost disable connection pooling.
And 300ms seems too short. Try 3 secs (e.g. db.SetConnMaxLifetime(time.Second * 3))
methane
on 9 Oct 2019
You should check you don't overwrite dbName. If you overwrite without dbName.Close(), old connections in the old pool are leaked.
methane
on 9 Oct 2019
thanks man. you were on the right way.
I've now configured the connection lifetime to 30s - meanwhile I was able to identify the stale (orphaned) connection issues:
This article https://medium.com/@rocketlaunchr.cloud/canceling-mysql-in-go-827ed8f83b30 gave me the hint, that defer the connection close seems not to be best practice as I'm working on the result set after the defer statement. So I've moved from defer to an absolute statement at the end of the function and it seems to work now. Actually I will have a look on that for the next few days.
My Processlist looks now:
MariaDB [(none)]> SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST where HOST like '%server1%';
+--------+------+---------------+-------+---------+------+-------+------+---------+-------+-----------+----------+-------------+---------------+-----------+
| ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO | TIME_MS | STAGE | MAX_STAGE | PROGRESS | MEMORY_USED | EXAMINED_ROWS | QUERY_ID |
+--------+------+---------------+-------+---------+------+-------+------+---------+-------+-----------+----------+-------------+---------------+-----------+
| 806004 | dbuser | server1:52238 | DB1 | Sleep | 0 | | NULL | 213.886 | 0 | 0 | 0.000 | 83672 | 0 | 682823042 |
| 806003 | dbuser | server1:52236 | DB1 | Sleep | 0 | | NULL | 199.730 | 0 | 0 | 0.000 | 83672 | 0 | 682823065 |
| 806002 | dbuser | server1:52234 | DB1 | Sleep | 0 | | NULL | 482.723 | 0 | 0 | 0.000 | 83672 | 0 | 682822882 |
| 806001 | dbuser | server1:52226 | DB1 | Sleep | 0 | | NULL | 414.633 | 0 | 0 | 0.000 | 83688 | 0 | 682822908 |
| 805996 | dbuser | server1:52146 | DB1 | Sleep | 0 | | NULL | 340.449 | 0 | 0 | 0.000 | 83672 | 0 | 682822952 |
| 805994 | dbuser | server1:52136 | DB1 | Sleep | 0 | | NULL | 222.041 | 0 | 0 | 0.000 | 83672 | 0 | 682823021 |
| 805993 | dbuser | server1:52086 | DB1 | Sleep | 0 | | NULL | 82.142 | 0 | 0 | 0.000 | 83672 | 0 | 682823167 |
| 805986 | dbuser | server1:51592 | DB1 | Sleep | 0 | | NULL | 327.405 | 0 | 0 | 0.000 | 83664 | 0 | 682822974 |
+--------+------+---------------+-------+---------+------+-------+------+---------+-------+-----------+----------+-------------+---------------+-----------+
8 rows in set (0.00 sec)
After that time I would close this issue for now, as it seems to be resolved. Maybe there will be a possibility to work on the defer connection close issue some day...
Any concerns/contras?
The code looks now like this:
////////////////////// DB Connection
// establish database connection
var dsn = appConfiguration.dbuser + ":" + appConfiguration.dbpass + "@tcp(" + appConfiguration.dbhostname + ":" + appConfiguration.dbport + ")/" + appConfiguration.dbNamename
dbName, err := sql.Open("mysql", dsn)
dbName.SetConnMaxLifetime(time.Second * 30)
dbName.SetMaxIdleConns(50)
dbName.SetMaxOpenConns(50)
// if there is an error opening the connection, handle it
if err != nil {
panic(err.Error())
}
ctxVCspstoredprocedure := context.Background()
rowsResultsVCspstoredprocedure, err := dbName.QueryContext(ctxVCspstoredprocedure, "CALL storedprocedure((?),(?),(?),(?),(?),(?),(?),(?),(?));", "version", "xxx", "xxx", "p", "1", sql.NullString{}, sql.NullString{}, appConfiguration.identifier, 1)
if err != nil {
log.Fatal(err)
}
for rowsResultsVCspstoredprocedure.Next() {
var spstoredprocedureVersion int
var spstoredprocedureVar1 int
var spstoredprocedureVar2 int
if err := rowsResultsVCspstoredprocedure.Scan(&spstoredprocedureVar1, &spstoredprocedureVar2, &spstoredprocedureVersion); err != nil {
log.Fatal(err)
}
if spstoredprocedureVersion != SPstoredprocedureVERSIONREQUIREMENT {
println(time.Now().Format(time.RFC3339) + " " + " - START - SPstoredprocedure VERSION check - ERROR: Version does not meet requirements by this version. Application requires: " + strconv.Itoa(SPstoredprocedureVERSIONREQUIREMENT) + " but DB seems to be: " + strconv.Itoa(spstoredprocedureVersion))
os.Exit(3)
} else {
println(time.Now().Format(time.RFC3339) + " - START - SPstoredprocedure VERSION check - PASSED")
}
}
rowsResultsVCspstoredprocedure.Close()
if err := rowsResultsVCspstoredprocedure.Err(); err != nil {
// print error when something went wrong
println(time.Now().Format(time.RFC3339)+" - START - SPstoredprocedure VERSION check - GENERAL DB RESULTS ERROR:", err.Error())
println(time.Now().Format(time.RFC3339) + " - START - SPstoredprocedure VERSION check - Stored Predure and/or Table Structure missing - EXIT")
os.Exit(3)
}
Hi all,
4 days uptime without any issues.
Yesterday a restart and after round about 14 hours the connections got again stuck - meanwhile the server running the old versions are still working.
MariaDB [(none)]> SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST where HOST like '%server1%';
+---------+------+---------------+-------+---------+-------+-------+------+--------------+-------+-----------+----------+-------------+---------------+------------+
| ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO | TIME_MS | STAGE | MAX_STAGE | PROGRESS | MEMORY_USED | EXAMINED_ROWS | QUERY_ID |
+---------+------+---------------+-------+---------+-------+-------+------+--------------+-------+-----------+----------+-------------+---------------+------------+
| 1193152 | dbuser | server1:37600 | DB1 | Sleep | 21818 | | NULL | 21818960.827 | 0 | 0 | 0.000 | 83672 | 0 | 1028458017 |
| 1193151 | dbuser | server1:37598 | DB1 | Sleep | 21818 | | NULL | 21818673.436 | 0 | 0 | 0.000 | 83672 | 0 | 1028459355 |
| 1193150 | dbuser | server1:37594 | DB1 | Sleep | 21828 | | NULL | 21828941.535 | 0 | 0 | 0.000 | 83672 | 0 | 1028456941 |
| 1193149 | dbuser | server1:37592 | DB1 | Sleep | 21829 | | NULL | 21829203.501 | 0 | 0 | 0.000 | 83680 | 0 | 1028456675 |
| 1193148 | dbuser | server1:37590 | DB1 | Sleep | 21818 | | NULL | 21818912.149 | 0 | 0 | 0.000 | 83672 | 0 | 1028458368 |
| 1193147 | dbuser | server1:37588 | DB1 | Sleep | 21818 | | NULL | 21818957.028 | 0 | 0 | 0.000 | 83688 | 0 | 1028458028 |
| 1193146 | dbuser | server1:37582 | DB1 | Sleep | 21818 | | NULL | 21818614.279 | 0 | 0 | 0.000 | 83680 | 0 | 1028460152 |
| 1193145 | dbuser | server1:37580 | DB1 | Sleep | 21818 | | NULL | 21818680.999 | 0 | 0 | 0.000 | 83672 | 0 | 1028459244 |
| 1193144 | dbuser | server1:37576 | DB1 | Sleep | 21829 | | NULL | 21829009.601 | 0 | 0 | 0.000 | 83672 | 0 | 1028456826 |
| 1193143 | dbuser | server1:37574 | DB1 | Sleep | 21829 | | NULL | 21829090.568 | 0 | 0 | 0.000 | 83672 | 0 | 1028456764 |
| 1193142 | dbuser | server1:37572 | DB1 | Sleep | 21819 | | NULL | 21819049.283 | 0 | 0 | 0.000 | 83672 | 0 | 1028457895 |
| 1193141 | dbuser | server1:37570 | DB1 | Sleep | 21819 | | NULL | 21819050.871 | 0 | 0 | 0.000 | 83672 | 0 | 1028457893 |
| 1193140 | dbuser | server1:37564 | DB1 | Sleep | 21829 | | NULL | 21829517.588 | 0 | 0 | 0.000 | 83672 | 0 | 1028456539 |
| 1193139 | dbuser | server1:37562 | DB1 | Sleep | 21819 | | NULL | 21819052.433 | 0 | 0 | 0.000 | 83672 | 0 | 1028457889 |
| 1193138 | dbuser | server1:37558 | DB1 | Sleep | 21818 | | NULL | 21818670.667 | 0 | 0 | 0.000 | 83672 | 0 | 1028459424 |
| 1193137 | dbuser | server1:37556 | DB1 | Sleep | 21819 | | NULL | 21819056.891 | 0 | 0 | 0.000 | 83672 | 0 | 1028457803 |
| 1193136 | dbuser | server1:37552 | DB1 | Sleep | 21829 | | NULL | 21829012.053 | 0 | 0 | 0.000 | 83672 | 0 | 1028456818 |
| 1193135 | dbuser | server1:37550 | DB1 | Sleep | 21818 | | NULL | 21818730.455 | 0 | 0 | 0.000 | 83672 | 0 | 1028458510 |
| 1193134 | dbuser | server1:37546 | DB1 | Sleep | 21830 | | NULL | 21830217.562 | 0 | 0 | 0.000 | 83672 | 0 | 1028456008 |
| 1193133 | dbuser | server1:37544 | DB1 | Sleep | 21818 | | NULL | 21818662.295 | 0 | 0 | 0.000 | 83672 | 0 | 1028459505 |
| 1193132 | dbuser | server1:37540 | DB1 | Sleep | 21829 | | NULL | 21829740.476 | 0 | 0 | 0.000 | 83688 | 0 | 1028456363 |
| 1193131 | dbuser | server1:37538 | DB1 | Sleep | 21818 | | NULL | 21818952.005 | 0 | 0 | 0.000 | 83672 | 0 | 1028458038 |
| 1193130 | dbuser | server1:37534 | DB1 | Sleep | 21818 | | NULL | 21818910.749 | 0 | 0 | 0.000 | 83672 | 0 | 1028458369 |
| 1193129 | dbuser | server1:37532 | DB1 | Sleep | 21818 | | NULL | 21818729.638 | 0 | 0 | 0.000 | 83688 | 0 | 1028458512 |
| 1193128 | dbuser | server1:37528 | DB1 | Sleep | 21818 | | NULL | 21818958.266 | 0 | 0 | 0.000 | 83672 | 0 | 1028458024 |
| 1193127 | dbuser | server1:37526 | DB1 | Sleep | 21818 | | NULL | 21818958.307 | 0 | 0 | 0.000 | 83672 | 0 | 1028458023 |
| 1193126 | dbuser | server1:37522 | DB1 | Sleep | 21829 | | NULL | 21829314.575 | 0 | 0 | 0.000 | 83672 | 0 | 1028456587 |
| 1193125 | dbuser | server1:37520 | DB1 | Sleep | 21818 | | NULL | 21818948.008 | 0 | 0 | 0.000 | 83672 | 0 | 1028458065 |
| 1193124 | dbuser | server1:37516 | DB1 | Sleep | 21818 | | NULL | 21818945.527 | 0 | 0 | 0.000 | 83672 | 0 | 1028458068 |
| 1193123 | dbuser | server1:37514 | DB1 | Sleep | 21818 | | NULL | 21818676.942 | 0 | 0 | 0.000 | 83672 | 0 | 1028459319 |
| 1193122 | dbuser | server1:37512 | DB1 | Sleep | 21829 | | NULL | 21829562.566 | 0 | 0 | 0.000 | 83672 | 0 | 1028456473 |
| 1193121 | dbuser | server1:37508 | DB1 | Sleep | 21818 | | NULL | 21818946.350 | 0 | 0 | 0.000 | 83672 | 0 | 1028458067 |
| 1193120 | dbuser | server1:37504 | DB1 | Sleep | 21829 | | NULL | 21829141.351 | 0 | 0 | 0.000 | 83672 | 0 | 1028456698 |
| 1193119 | dbuser | server1:37502 | DB1 | Sleep | 21818 | | NULL | 21818948.264 | 0 | 0 | 0.000 | 83672 | 0 | 1028458058 |
| 1193118 | dbuser | server1:37498 | DB1 | Sleep | 21818 | | NULL | 21818906.182 | 0 | 0 | 0.000 | 83672 | 0 | 1028458409 |
| 1193117 | dbuser | server1:37496 | DB1 | Sleep | 21818 | | NULL | 21818955.191 | 0 | 0 | 0.000 | 83672 | 0 | 1028458032 |
| 1193115 | dbuser | server1:37492 | DB1 | Sleep | 21830 | | NULL | 21830405.605 | 0 | 0 | 0.000 | 83664 | 0 | 1028455876 |
| 1193114 | dbuser | server1:37490 | DB1 | Sleep | 21819 | | NULL | 21819049.800 | 0 | 0 | 0.000 | 83680 | 0 | 1028457894 |
| 1193113 | dbuser | server1:37488 | DB1 | Sleep | 21818 | | NULL | 21818909.561 | 0 | 0 | 0.000 | 83672 | 0 | 1028458402 |
| 1193112 | dbuser | server1:37484 | DB1 | Sleep | 21818 | | NULL | 21818944.637 | 0 | 0 | 0.000 | 83672 | 0 | 1028458073 |
| 1193111 | dbuser | server1:37480 | DB1 | Sleep | 21830 | | NULL | 21830089.651 | 0 | 0 | 0.000 | 83672 | 0 | 1028456120 |
| 1193110 | dbuser | server1:37478 | DB1 | Sleep | 21830 | | NULL | 21830183.558 | 0 | 0 | 0.000 | 83672 | 0 | 1028456052 |
| 1193108 | dbuser | server1:37474 | DB1 | Sleep | 21818 | | NULL | 21818621.968 | 0 | 0 | 0.000 | 83672 | 0 | 1028460125 |
| 1193107 | dbuser | server1:37472 | DB1 | Sleep | 21818 | | NULL | 21818704.345 | 0 | 0 | 0.000 | 83672 | 0 | 1028458863 |
| 1193106 | dbuser | server1:37468 | DB1 | Sleep | 21830 | | NULL | 21830432.797 | 0 | 0 | 0.000 | 83672 | 0 | 1028455852 |
| 1193087 | dbuser | server1:37354 | DB1 | Sleep | 21829 | | NULL | 21829278.837 | 0 | 0 | 0.000 | 83688 | 0 | 1028456610 |
| 1193071 | dbuser | server1:37122 | DB1 | Sleep | 21829 | | NULL | 21829964.414 | 0 | 0 | 0.000 | 83680 | 0 | 1028456208 |
| 1193070 | dbuser | server1:37120 | DB1 | Sleep | 21830 | | NULL | 21830242.253 | 0 | 0 | 0.000 | 83672 | 0 | 1028455986 |
| 1193069 | dbuser | server1:37114 | DB1 | Sleep | 21818 | | NULL | 21818704.492 | 0 | 0 | 0.000 | 83664 | 0 | 1028458859 |
| 1193066 | dbuser | server1:37100 | DB1 | Sleep | 21829 | | NULL | 21829947.564 | 0 | 0 | 0.000 | 83672 | 0 | 1028456231 |
+---------+------+---------------+-------+---------+-------+-------+------+--------------+-------+-----------+----------+-------------+---------------+------------+
50 rows in set (0.01 sec)
Looks like a network interruption for me, while I would expect that the connections were dropped and reestablished. Might it be useful to ping the database periodically and the restart the application in case that the database cannot be reached?
Cheers,
Matthias
mwiora
on 15 Oct 2019
If you are using db.SetConnMaxLifetime(time.Second * 3), all connections are closed by 6secs. (2* lifetime). So no need to manual restart.
methane
on 15 Oct 2019
I've configured this SetConnMaxLifetime but actually that's what seems not to happen. It works for normal - but at one specific event (which I don't know) the connection gets no longer closed.
And when I have a look to the seconds of all connections this seems to be more or less at the same time (for example at an external event like network issues between the application and the database server).
Any ideas how to debug this?
I'll try to provoke network issues manually meanwhile.
// EDIT: I've interrupted the network connectivity for 2 seconds - the connections were reused when the network connectivity was reestablished.
In a second test I've interrupted the network connectivity for more than the defined time in SetConnMaxLifetime - the connections were sleeping for the time the network connectivity was interrupted. As soon as the networking connectivity has been reestablished new database connections have been established and the old ones were dropped after a few seconds. --> as it should be IMHO.
mwiora
on 15 Oct 2019
You should check TCP stats by netstat or ss, on both of client and server machine.
methane
on 15 Oct 2019
Hi @methane,
I found out that the behaviour is externally provoked far as I am able to observe - currently the issue occurs daily round about at the same time. I am investigating an will try to disable the backup mechanisms on the database server and report back here.
So currently the situation is:
Each day at around the same time my Go Application is no longer able to deliver the requested operations to the database and runs out of memory as the values are stored and kept in memory.
Cheers,
Matthias
mwiora
on 23 Oct 2019
@methane
Update: I could figure out what happens.... A short time before my golang application crashes, the database server runs a cronjob, that is performing a database backup. There is no problem during the mysqldump of the table or any other. But there is a problem during the TAR operation that takes all the logs into one file. This operation seems to busy the database server (while top shows no excessive use of the CPU) - in 8/10 cases of exactly this operation the golang application is no longer able to deliver new statements to the database server and the connections are no longer closed.
I am aware of the fact that the issue is database provoked, but I think there is indeed a bug that can lead to this situation.
I've updated from Go 13.1 to 13.3 and the issue persists.
Cheers,
Matthias
mwiora
on 27 Oct 2019
I think there is indeed a bug that can lead to this situation.
If you think so, please provide detailed information.
The stale connections in the processlist are not evidence for database/sql or go-sql-driver/mysql didn't close the connection.
Since your database server had been in an unusual state, there is a possibility the server may lose the FIN TCP packet.
- TCP state in Go application machine:
ss -tanornetstat -ts. DB.Stats()output.- Stackdump of all goroutines. It can be retrieved from net/http/pprof or debug/pprof (e.g.
pprof.Lookup("goroutine").WriteTo(dumpFile, 1)).
methane
on 28 Oct 2019
HI @methane
I'll try. I've simplified my environment - 10.0.0.1 is the Go app host, 10.0.0.2 is the database host
The states when everything runs normally:
db.DBStats(): {50 6 0 6 0 0s 0 1}
ss -tan @ go app host (only lines containing the ip of the Database Host):
# ss -tan | grep 10.0.0.2
TIME-WAIT 0 0 10.0.0.1:41544 10.0.0.2:3306
TIME-WAIT 0 0 10.0.0.1:40378 10.0.0.2:3306
TIME-WAIT 0 0 10.0.0.1:41048 10.0.0.2:3306
TIME-WAIT 0 0 10.0.0.1:42080 10.0.0.2:3306
TIME-WAIT 0 0 10.0.0.1:42078 10.0.0.2:3306
TIME-WAIT 0 0 10.0.0.1:41686 10.0.0.2:3306
TIME-WAIT 0 0 10.0.0.1:41804 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:42608 10.0.0.2:3306
TIME-WAIT 0 0 10.0.0.1:40336 10.0.0.2:3306
TIME-WAIT 0 0 10.0.0.1:41920 10.0.0.2:3306
TIME-WAIT 0 0 10.0.0.1:40376 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:43152 10.0.0.2:3306
TIME-WAIT 0 0 10.0.0.1:40590 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:42610 10.0.0.2:3306
TIME-WAIT 0 0 10.0.0.1:41356 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:43142 10.0.0.2:3306
ss -tan @ database host (only lines containing the ip of the GO App host):
# ss -tan | grep 10.0.0.1
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:41804
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:41920
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:41544
TIME-WAIT 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:40016
TIME-WAIT 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:40376
TIME-WAIT 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:40378
TIME-WAIT 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:40590
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:41356
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:42078
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:42080
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:41686
The states when I trigger the issue:
db.DBStats(): {50 50 50 0 1039 9m49.2539932s 0 4}
ss -tan @ go app host (only lines containing the ip of the Database Host):
# ss -tan | grep 10.0.0.2
ESTAB 0 0 10.0.0.1:59888 10.0.0.2:3306
TIME-WAIT 0 0 10.0.0.1:33540 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32828 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32836 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32912 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32914 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:59874 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32810 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32838 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32824 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:60036 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32812 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:60738 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:60736 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32910 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:59900 10.0.0.2:3306
TIME-WAIT 0 0 10.0.0.1:33542 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32834 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32926 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32832 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32848 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32840 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:59902 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32936 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32842 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:60032 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32814 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:60034 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32830 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:59920 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32920 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32808 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:60922 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32844 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32822 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:59912 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:60826 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32800 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:60058 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32932 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32916 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:59844 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32820 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32826 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32816 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:59832 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32846 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32934 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:59820 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32818 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:32918 10.0.0.2:3306
ESTAB 0 0 10.0.0.1:59860 10.0.0.2:3306
ss -tan @ database host (only lines containing the ip of the GO App host):
# ss -tan | grep 10.0.0.1
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32918
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32832
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32932
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32848
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32840
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:59912
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32842
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32916
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32810
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32910
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32814
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:60922
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32914
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:59900
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32920
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:60736
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32816
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:59832
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:59920
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32828
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32800
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32936
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32912
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:60058
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32812
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32836
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:59820
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32844
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:60826
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32818
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:60032
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32808
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32826
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32824
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32820
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:60738
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32846
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:59860
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:59888
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:60036
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:59844
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32926
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:59902
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32822
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32838
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32834
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:60034
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:59874
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32830
ESTAB 0 0 ::ffff:10.0.0.2:3306 ::ffff:10.0.0.1:32934
I've dumped the goroutines before the call and after - while the server was working fine (as it became unresponsive when the issue has been triggered):
BEFORE
Goroutine Dump: goroutine profile: total 8
2 @ 0x431bb0 0x440cab 0x4d5278 0x45c7c1
# 0x4d5277 database/sql.(*DB).connectionOpener+0xe7 /home/user/sdk/go1.13.3/src/database/sql/sql.go:1052
2 @ 0x431bb0 0x440cab 0x4d53ab 0x45c7c1
# 0x4d53aa database/sql.(*DB).connectionResetter+0xfa /home/user/sdk/go1.13.3/src/database/sql/sql.go:1065
1 @ 0x431bb0 0x42c94a 0x42bf15 0x4b5835 0x4b63cf 0x4b63b1 0x565d2f 0x5720f8 0x654894 0x533293 0x533f7d 0x5341b4 0x5f732c 0x6511e2 0x651211 0x655b8f 0x65a094 0x45c7c1
# 0x42bf14 internal/poll.runtime_pollWait+0x54 /home/user/sdk/go1.13.3/src/runtime/netpoll.go:184
# 0x4b5834 internal/poll.(*pollDesc).wait+0x44 /home/user/sdk/go1.13.3/src/internal/poll/fd_poll_runtime.go:87
# 0x4b63ce internal/poll.(*pollDesc).waitRead+0x1ce /home/user/sdk/go1.13.3/src/internal/poll/fd_poll_runtime.go:92
# 0x4b63b0 internal/poll.(*FD).Read+0x1b0 /home/user/sdk/go1.13.3/src/internal/poll/fd_unix.go:169
# 0x565d2e net.(*netFD).Read+0x4e /home/user/sdk/go1.13.3/src/net/fd_unix.go:202
# 0x5720f7 net.(*conn).Read+0x67 /home/user/sdk/go1.13.3/src/net/net.go:184
# 0x654893 net/http.(*connReader).Read+0xf3 /home/user/sdk/go1.13.3/src/net/http/server.go:785
# 0x533292 bufio.(*Reader).fill+0x102 /home/user/sdk/go1.13.3/src/bufio/bufio.go:100
# 0x533f7c bufio.(*Reader).ReadSlice+0x3c /home/user/sdk/go1.13.3/src/bufio/bufio.go:359
# 0x5341b3 bufio.(*Reader).ReadLine+0x33 /home/user/sdk/go1.13.3/src/bufio/bufio.go:388
# 0x5f732b net/textproto.(*Reader).readLineSlice+0x6b /home/user/sdk/go1.13.3/src/net/textproto/reader.go:57
# 0x6511e1 net/textproto.(*Reader).ReadLine+0x91 /home/user/sdk/go1.13.3/src/net/textproto/reader.go:38
# 0x651210 net/http.readRequest+0xc0 /home/user/sdk/go1.13.3/src/net/http/request.go:1012
# 0x655b8e net/http.(*conn).readRequest+0x15e /home/user/sdk/go1.13.3/src/net/http/server.go:965
# 0x65a093 net/http.(*conn).serve+0x6d3 /home/user/sdk/go1.13.3/src/net/http/server.go:1817
1 @ 0x431bb0 0x42c94a 0x42bf15 0x4b5835 0x4b7368 0x4b7347 0x5662c2 0x57b022 0x579dc7 0x65dc86 0x65d9a7 0x6d75b1 0x6d7500 0x4317de 0x45c7c1
# 0x42bf14 internal/poll.runtime_pollWait+0x54 /home/user/sdk/go1.13.3/src/runtime/netpoll.go:184
# 0x4b5834 internal/poll.(*pollDesc).wait+0x44 /home/user/sdk/go1.13.3/src/internal/poll/fd_poll_runtime.go:87
# 0x4b7367 internal/poll.(*pollDesc).waitRead+0x1f7 /home/user/sdk/go1.13.3/src/internal/poll/fd_poll_runtime.go:92
# 0x4b7346 internal/poll.(*FD).Accept+0x1d6 /home/user/sdk/go1.13.3/src/internal/poll/fd_unix.go:384
# 0x5662c1 net.(*netFD).accept+0x41 /home/user/sdk/go1.13.3/src/net/fd_unix.go:238
# 0x57b021 net.(*TCPListener).accept+0x31 /home/user/sdk/go1.13.3/src/net/tcpsock_posix.go:139
# 0x579dc6 net.(*TCPListener).Accept+0x46 /home/user/sdk/go1.13.3/src/net/tcpsock.go:261
# 0x65dc85 net/http.(*Server).Serve+0x285 /home/user/sdk/go1.13.3/src/net/http/server.go:2896
# 0x65d9a6 net/http.(*Server).ListenAndServe+0xb6 /home/user/sdk/go1.13.3/src/net/http/server.go:2825
# 0x6d75b0 net/http.ListenAndServe+0x1420 /home/user/sdk/go1.13.3/src/net/http/server.go:3080
# 0x6d74ff main.main+0x136f /home/user/go/src/appname/appname.go:265
# 0x4317dd runtime.main+0x21d /home/user/sdk/go1.13.3/src/runtime/proc.go:203
1 @ 0x6543f0 0x45c7c1
# 0x6543f0 net/http.(*connReader).backgroundRead+0x0 /home/user/sdk/go1.13.3/src/net/http/server.go:676
1 @ 0x6ad945 0x6ad760 0x6aa38a 0x6d519a 0x6d60a7 0x65d8c4 0x65a235 0x45c7c1
# 0x6ad944 runtime/pprof.writeRuntimeProfile+0x94 /home/user/sdk/go1.13.3/src/runtime/pprof/pprof.go:708
# 0x6ad75f runtime/pprof.writeGoroutine+0x9f /home/user/sdk/go1.13.3/src/runtime/pprof/pprof.go:670
# 0x6aa389 runtime/pprof.(*Profile).WriteTo+0x3d9 /home/user/sdk/go1.13.3/src/runtime/pprof/pprof.go:329
# 0x6d5199 main.handleUPDATE+0x1839 /home/user/go/src/appname/handleUPDATE.go:33
# 0x6d60a6 main.(*Service).ServeHTTP+0x616 /home/user/go/src/appname/appname.go:116
# 0x65d8c3 net/http.serverHandler.ServeHTTP+0xa3 /home/user/sdk/go1.13.3/src/net/http/server.go:2802
# 0x65a234 net/http.(*conn).serve+0x874 /home/user/sdk/go1.13.3/src/net/http/server.go:1890
AFTER
Goroutine Dump: goroutine profile: total 11
2 @ 0x431bb0 0x440cab 0x4d5278 0x45c7c1
# 0x4d5277 database/sql.(*DB).connectionOpener+0xe7 /home/user/sdk/go1.13.3/src/database/sql/sql.go:1052
2 @ 0x431bb0 0x440cab 0x4d53ab 0x45c7c1
# 0x4d53aa database/sql.(*DB).connectionResetter+0xfa /home/user/sdk/go1.13.3/src/database/sql/sql.go:1065
2 @ 0x431bb0 0x440cab 0x6cdcff 0x45c7c1
# 0x6cdcfe github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1+0xbe /home/user/go/src/github.com/go-sql-driver/mysql/connection.go:619
1 @ 0x431bb0 0x42c94a 0x42bf15 0x4b5835 0x4b63cf 0x4b63b1 0x565d2f 0x5720f8 0x654448 0x45c7c1
# 0x42bf14 internal/poll.runtime_pollWait+0x54 /home/user/sdk/go1.13.3/src/runtime/netpoll.go:184
# 0x4b5834 internal/poll.(*pollDesc).wait+0x44 /home/user/sdk/go1.13.3/src/internal/poll/fd_poll_runtime.go:87
# 0x4b63ce internal/poll.(*pollDesc).waitRead+0x1ce /home/user/sdk/go1.13.3/src/internal/poll/fd_poll_runtime.go:92
# 0x4b63b0 internal/poll.(*FD).Read+0x1b0 /home/user/sdk/go1.13.3/src/internal/poll/fd_unix.go:169
# 0x565d2e net.(*netFD).Read+0x4e /home/user/sdk/go1.13.3/src/net/fd_unix.go:202
# 0x5720f7 net.(*conn).Read+0x67 /home/user/sdk/go1.13.3/src/net/net.go:184
# 0x654447 net/http.(*connReader).backgroundRead+0x57 /home/user/sdk/go1.13.3/src/net/http/server.go:677
1 @ 0x431bb0 0x42c94a 0x42bf15 0x4b5835 0x4b63cf 0x4b63b1 0x565d2f 0x5720f8 0x654894 0x533293 0x533f7d 0x5341b4 0x5f732c 0x6511e2 0x651211 0x655b8f 0x65a094 0x45c7c1
# 0x42bf14 internal/poll.runtime_pollWait+0x54 /home/user/sdk/go1.13.3/src/runtime/netpoll.go:184
# 0x4b5834 internal/poll.(*pollDesc).wait+0x44 /home/user/sdk/go1.13.3/src/internal/poll/fd_poll_runtime.go:87
# 0x4b63ce internal/poll.(*pollDesc).waitRead+0x1ce /home/user/sdk/go1.13.3/src/internal/poll/fd_poll_runtime.go:92
# 0x4b63b0 internal/poll.(*FD).Read+0x1b0 /home/user/sdk/go1.13.3/src/internal/poll/fd_unix.go:169
# 0x565d2e net.(*netFD).Read+0x4e /home/user/sdk/go1.13.3/src/net/fd_unix.go:202
# 0x5720f7 net.(*conn).Read+0x67 /home/user/sdk/go1.13.3/src/net/net.go:184
# 0x654893 net/http.(*connReader).Read+0xf3 /home/user/sdk/go1.13.3/src/net/http/server.go:785
# 0x533292 bufio.(*Reader).fill+0x102 /home/user/sdk/go1.13.3/src/bufio/bufio.go:100
# 0x533f7c bufio.(*Reader).ReadSlice+0x3c /home/user/sdk/go1.13.3/src/bufio/bufio.go:359
# 0x5341b3 bufio.(*Reader).ReadLine+0x33 /home/user/sdk/go1.13.3/src/bufio/bufio.go:388
# 0x5f732b net/textproto.(*Reader).readLineSlice+0x6b /home/user/sdk/go1.13.3/src/net/textproto/reader.go:57
# 0x6511e1 net/textproto.(*Reader).ReadLine+0x91 /home/user/sdk/go1.13.3/src/net/textproto/reader.go:38
# 0x651210 net/http.readRequest+0xc0 /home/user/sdk/go1.13.3/src/net/http/request.go:1012
# 0x655b8e net/http.(*conn).readRequest+0x15e /home/user/sdk/go1.13.3/src/net/http/server.go:965
# 0x65a093 net/http.(*conn).serve+0x6d3 /home/user/sdk/go1.13.3/src/net/http/server.go:1817
1 @ 0x431bb0 0x42c94a 0x42bf15 0x4b5835 0x4b7368 0x4b7347 0x5662c2 0x57b022 0x579dc7 0x65dc86 0x65d9a7 0x6d75b1 0x6d7500 0x4317de 0x45c7c1
# 0x42bf14 internal/poll.runtime_pollWait+0x54 /home/user/sdk/go1.13.3/src/runtime/netpoll.go:184
# 0x4b5834 internal/poll.(*pollDesc).wait+0x44 /home/user/sdk/go1.13.3/src/internal/poll/fd_poll_runtime.go:87
# 0x4b7367 internal/poll.(*pollDesc).waitRead+0x1f7 /home/user/sdk/go1.13.3/src/internal/poll/fd_poll_runtime.go:92
# 0x4b7346 internal/poll.(*FD).Accept+0x1d6 /home/user/sdk/go1.13.3/src/internal/poll/fd_unix.go:384
# 0x5662c1 net.(*netFD).accept+0x41 /home/user/sdk/go1.13.3/src/net/fd_unix.go:238
# 0x57b021 net.(*TCPListener).accept+0x31 /home/user/sdk/go1.13.3/src/net/tcpsock_posix.go:139
# 0x579dc6 net.(*TCPListener).Accept+0x46 /home/user/sdk/go1.13.3/src/net/tcpsock.go:261
# 0x65dc85 net/http.(*Server).Serve+0x285 /home/user/sdk/go1.13.3/src/net/http/server.go:2896
# 0x65d9a6 net/http.(*Server).ListenAndServe+0xb6 /home/user/sdk/go1.13.3/src/net/http/server.go:2825
# 0x6d75b0 net/http.ListenAndServe+0x1420 /home/user/sdk/go1.13.3/src/net/http/server.go:3080
# 0x6d74ff main.main+0x136f /home/user/go/src/appname/appname.go:265
# 0x4317dd runtime.main+0x21d /home/user/sdk/go1.13.3/src/runtime/proc.go:203
1 @ 0x4d49f0 0x45c7c1
# 0x4d49f0 database/sql.(*DB).connectionCleaner+0x0 /home/user/sdk/go1.13.3/src/database/sql/sql.go:941
1 @ 0x6ad945 0x6ad760 0x6aa38a 0x6d4c76 0x6d60a7 0x65d8c4 0x65a235 0x45c7c1
# 0x6ad944 runtime/pprof.writeRuntimeProfile+0x94 /home/user/sdk/go1.13.3/src/runtime/pprof/pprof.go:708
# 0x6ad75f runtime/pprof.writeGoroutine+0x9f /home/user/sdk/go1.13.3/src/runtime/pprof/pprof.go:670
# 0x6aa389 runtime/pprof.(*Profile).WriteTo+0x3d9 /home/user/sdk/go1.13.3/src/runtime/pprof/pprof.go:329
# 0x6d4c75 main.handleUPDATE+0x1315 /home/user/go/src/appname/handleUPDATE.go:114
# 0x6d60a6 main.(*Service).ServeHTTP+0x616 /home/user/go/src/appname/appname.go:116
# 0x65d8c3 net/http.serverHandler.ServeHTTP+0xa3 /home/user/sdk/go1.13.3/src/net/http/server.go:2802
# 0x65a234 net/http.(*conn).serve+0x874 /home/user/sdk/go1.13.3/src/net/http/server.go:1890
DBStats() shows all of 50 connections are in use.
You may just forget closing Rows, Conn, or Tx.
methane
on 31 Oct 2019
mh. The application runs meanwhile days without any issue by round about 30 requests per second. Just when the database server is busy with the tar command the issue occurs. Thatswhy I thought that it could not be a forgotten closing.
Any other idea for information I could provide?
mwiora
on 31 Oct 2019
Having a smiliar issue:
db, err := sql.Open("mysql", "foo:bar@tcp(db:3306)/baz")
if err != nil {
panic(err.Error())
}
defer db.Close() // put back to the pool later
// Limit concurrency?
// db.SetMaxOpenConns(5)
// Retain 2 connections to the pool
db.SetMaxIdleConns(3)
// Discard connections that are getting old
db.SetConnMaxLifetime(time.Second * 10)
err = db.Ping()
if err != nil {
panic(err.Error())
}
Invoking this 10K times with a concurrency level of 50, afterwards show status like 'Conn%'; shows that the Connections status variable has incremented by precisely 10K. It seems no connection reuse took place. If pushed, I am running into OS limits eventually.
Golang 1.13.1, using v1.4.1 of this library.
lauri-elevant
on 31 Oct 2019
@mwiora
The application runs meanwhile days without any issue by round about 30 requests per second. Just when the database server is busy with the tar command the issue occurs. Thatswhy I thought that it could not be a forgotten closing.
Forgotten closing is common bug in error handling code:
if err != nil { // something bad happened.
return nil, err // Oh, forgot tx.Close(), conn.Close(), or rows.Close().
}
So it is not strange conn leak is not happend until your database server is busy.
Any other idea for information I could provide?
Try this patch: https://gist.github.com/methane/083497a1fed9fe1db84a40173c5b99c7
This patch adds db.Debug() which prints stacktrace where in-use connections are checked out.
methane
on 1 Nov 2019
@lauri-elevant
No connections are reused because you close the database.
And Connection is not the number of active connections. Read the manual.
https://dev.mysql.com/doc/refman/8.0/en/server-status-variables.html#statvar_Connections
methane
on 1 Nov 2019
No connections are reused because you close the database.
https://golang.org/pkg/database/sql/#Conn.Close
func (c *Conn) Close() error
Close returns the connection to the connection pool.
I think you have it wrong there.
As I understand, it is the prerogative of the connection pool implementation to retain the connection for further usage, or to actually close it, according to the set limits.
If you skip the Close(), you can see the connections start to line up in SHOW PROCESSLIST in huge numbers until the server finally drops them. Meanwhile the server will start returning Error 1040 "Too many connections". The implementation seems to make no attempt to reuse the connections, nor honor the max idle conns, nor max lifetime. I think following this advice you will be essentially leaking a connection and the server statistics seem consistent with this. Probably connected to the stability problems someone was relating to above.
Connections represents the number of connection attempts (successful or not) to the MySQL server. Straight from the manual. I maintain that this is an accurate tally of new connection attempts and indicates that the connection pool functionality is broken. Or perhaps it only works in a very narrow sense. I have not so far, in exhaustive testing, seen a single connection being reused.
I stand corrected. I misunderstood the API, sql.Open()does not return a Conn, as I had assumed, but a "database". There is indeed a distinction between closing a connection or "closing the database". I was doing the latter.
lauri-elevant
on 2 Nov 2019
@methane you were right - I did not close the connection after the log.fatal() - I've added it, but the issue persists. I would expect that, as there was never a log generated with any issue, so the close statement never will be reached.
mwiora
on 4 Nov 2019
@mwiora Have you tried my patch? What db.Debug() shows?
methane
on 5 Nov 2019
Any update? May I close this issue?
methane
on 11 Dec 2019
Hi man - thanks for reminder - I could not work on this for the last few weeks... I will give you an update until Friday...
mwiora
on 11 Dec 2019
try to add defer rowsResultsVCspstoredprocedure.Close() before rowsResultsVCspstoredprocedure.Next()
and don't exit the program in the rows.Next() loop
looks like
rows, err := dbName.QueryContext(xxx)
if err != nil {
log.Fatal(err)
}
defer rows.Close()
for rows.Next(){
if err := rows.Scan(xxx); err != nil {
log.Println(err)
return
}
}
because the for loop might fatal and exit, at this time the rows didn't closed. Be sure close the rows after exit.
abcdsxg
on 2 Jan 2020
Hi man - thanks for reminder - I could not work on this for the last few weeks... I will give you an update until Friday...
Hello锛孒ave you solve the prolem?
fishedee
on 21 May 2020
hi @fishedee - unfortunately not. It was not so easy to call and get the debug information and as this is a productive system - and I could not simulate the load adequately - I had to limit the tar-process on the database server.
So in the end I did not resolve this issue - do you actually have the same or a similar one?
mwiora
on 22 May 2020
No,I'm just curious.Maybe I will meet the same problem one day
fishedee
on 23 May 2020
closing this for now - reopening when needed :)
mwiora
on 23 May 2020
Related issues
mayurshivakumar
路
5Comments
pedromorgan
路
6Comments
knadh
路
6Comments
tanepiper
路
8Comments
zhaohui-kevin
路
5Comments
Most helpful comment
No,I'm just curious.Maybe I will meet the same problem one day