Resource leakage: Error 1461: Can't create more than max_prepared_stmt_count statements (current value: 16382)

[ThrosturX]

Issue description

For some reason, this suddenly started happening. It seems like this is happening because queries built as strings are being "Prepared" behind the scenes, which is not something you want when every query is unique. The queries are executed with tx.Exec(str) and therefore there is no obvious indication to the user that statements are being prepared, causing this error to be extremely confusing.

Please note, that I'm still not entirely sure what the issue is, but this ticket represents my best guess.

Example code

// Lazy error handling, because example
func (sqlConf DBConfig) ExampleOverPrepare(items map[uint64]SomeStruct) (affected []uint64) {
    db, err := sql.Open("mysql", sqlConf.String()+"?parseTime=true")
    if err != nil { return }
    defer db.Close()
    tx, err := db.Begin()
    if err != nil { return }
    for uid, item := range items {
        queryStr := buildQuery(item) /* func(item SomeStruct) string */
        res, err := tx.Exec(queryStr)
        /* rest of block stubbed out */
    }
    if err := tx.Commit(); err != nil {
         log.Println("[ERROR]", err)
        return
    }
    return affected /* would have been set in stubbed out block */
}

Error log

Error 1461: Can't create more than max_prepared_stmt_count statements (current value: 16382)

(this is the only error message relating to DB at all, and they appear every time DB is accessed)

Configuration

Driver version (or git SHA):
0b58b37b664c21f3010e836f1b931e1d0b0b0685

Go version: run go version in your console
go version go1.9.2 linux/amd64

Server version: E.g. MySQL 5.6, MariaDB 10.0.20
MySQL 5.6.32-78.0-log

Server OS: E.g. Debian 8.1 (Jessie), Windows 10
Unknown

[ThrosturX]

I realize that the supplied code is "playing with fire" (by creating SQL queries with their unique parameters as strings and not preparing them), but the point I'm trying to illustrate here is that the code seems perfectly fine until you suddenly run out of resources.

[percona-csalguero]

You can use interpolateParams to prevent queries being prepared

[ThrosturX]

Thanks a ton! That parameter actually does prevent the error, but I still feel that there could be room for improvement here (albeit perhaps not necessarily warranted improvement), so I'm leaving this issue open for triage just in case.

[julienschmidt]

Can you try, e.g. by adding some debug output, if it uses https://github.com/go-sql-driver/mysql/blob/master/connection.go#L339 ?
If the query doesn't contain any parameter, it should use https://golang.org/pkg/database/sql/driver/#Execer or https://golang.org/pkg/database/sql/driver/#ExecerContext by default, interpolateParams shouldn't make any difference in that case.

[ThrosturX]

I'm not sure how I can test this as proposed in the comment above, as this only happens in production when the code has been running for a very long time. Unfortunately, I cannot reproduce this in production as it would result in downtime of our systems. I am open to other, less invasive suggestions.

[macdabby]

I just ran into this using PHP, so it doesn't seem to be in the driver itself. I was iterating the following query:
select * from table where id between 22141972 and 22144472
This was with Doctrine, and although I was using whereBetween(), it appears it's not using placeholders, so it's the same issue. The error appeared as I had to iterate over 3 million records, 2500 at a time. So you might be able to reproduce this with a simple select loop, changing the range. It took several thousand iterations - i suppose more than what's defined in max_prepared_stmt_count

I have a php service calling apis on a go service. they are on the same box and same mysql instance for my dev env

[macdabby]

Correction to above - PHP was unable to create a new statement, but it looks like Go was consuming the statements. I was able to find this out:

mysql -uroot -e 'SHOW PROCESSLIST' | grep 'MYSQL_USER_FROM_GO_CLIENT' | wc -l

As I am hammering that API, i can see the number of processes increase.

The processes look like this

3772    services_use_m  127.0.0.1:50155 MYSQL_USER_FROM_GO_CLIENT  Sleep   166             NULL    0.000
3774    services_use_m  127.0.0.1:50163 MYSQL_USER_FROM_GO_CLIENT  Sleep   166             NULL    0.000
3776    services_use_m  127.0.0.1:50169 MYSQL_USER_FROM_GO_CLIENT  Sleep   166             NULL    0.000
3777    services_use_m  127.0.0.1:50170 MYSQL_USER_FROM_GO_CLIENT  Sleep   166             NULL    0.000
3779    services_use_m  127.0.0.1:50178 MYSQL_USER_FROM_GO_CLIENT  Sleep   165             NULL    0.000
3795    services_use_m  127.0.0.1:50228 MYSQL_USER_FROM_GO_CLIENT  Sleep   165             NULL    0.000
3797    services_use_m  127.0.0.1:50234 MYSQL_USER_FROM_GO_CLIENT  Sleep   164             NULL    0.000
3812    services_use_m  127.0.0.1:50281 MYSQL_USER_FROM_GO_CLIENT  Sleep   164             NULL    0.000

Those connections never go away, not even after several minutes of waiting. However if i restart the Go service, i see them all disappear. The Go service is a daemon web server running with gin.

I'm looking further into this, but i assume it's got something to do with opening a connection and not correctly closing it - so the leak would either be in my code or the driver.

[methane]

@macdabby You need DB.SetConnMaxLifetime(time.Second * 10).
Default setting will keep connections eternally and it is very bad for MySQL.

[macdabby]

I can see how that would solve the problem, but it still sounds like a bad idea. If the limit is 16k connections and we get 16k requests in 10 seconds, it's still possible to hit that limit. I believe I read that the project itself is supposed to keep a pool of open connections and reuse them as needed. Setting the timoeut might work but I think it's a bit hacky.

[methane]

@macdabby You said "Those connections never go away, not even after several minutes of waiting."
My advice is for solving it.

If the limit is 16k connections and we get 16k requests in 10 seconds, it's still possible to hit that limit.

So what?
It means just you should configure MySQL and clients properly. Is there any problem?

You need enough max_prepared_stmt_count.
You need keep max connections small enough.

There are no problem.

[methane]

To configure max_prepared_stmt_count properly, you should know this:

• When you use DB.Exec(query, arg...), it may consume MaxConnections statements on server side.
• When you have N statements created by DB.Prepare(), it may consume N * MaxConnections statements.
• When you have N Tx.Prepare() in transaction, it may consume N * MaxConnections statements.

So max_prepared_stmt_count should be larger than sum of all above.
And you can reduce statement count easily by reducing connection.
When you use some ORM or other toolkit which automatically manages prepared statement,
you should know how many statements are used in it.

I close this issue for now. If you sure about there is leak, please reopen with reproducible complete example code.

[macdabby]

This is consistently reproducing the problem. Processes continue to increase until execution completes, then they all disappear. After the process runs but before the program terminates, you can run mysql -uroot -e 'SHOW PROCESSLIST' | grep 'MYSQL_USER_FROM_GO_CLIENT' | wc -l to see all the processes still alive by the go client.

package main

import (
	"fmt"
	"time"
	"database/sql"
)

var connection, err = sql.Open("mysql", "connection-uril")

func query() {
	// TODO: what about uuid for the item?
	var sql = `select *
		from table
		where id = ? order by update_date desc
		`

	//var sc = utils.GetSQLConnector()
	stmt, err := connection.Prepare(sql)
	if err != nil {
		return
	}
	rows, err := stmt.Query(123)
	rows = rows
	stmt.Close()
	return

}

func main() {
	for i := 1; i <= 10000; i++ {
		query()
	}

	fmt.Println("queries complete")
	time.Sleep(30 * time.Second)

	return
}

What's interesting is the number of processes. If the look is set to 100, processes at the end are 100. 1000 is 1000. but 10,000 is 1017. There is some sort of cap that's not getting me to hit the max_prepared_stmt_count - however this is still the same problem because the processes are left open. It's possible that this problem is exacerbated by using gin on top of the problem itself.

[methane]

@macdabby What is the "problem"?
Your code doesn't DB.SetConnMaxLifetime(time.Second * 10) which I strongly recommend.
That's why "all the processes still alive by the go client." It's expected behavior. No problem.

[methane]

FYI, http://mysqlblog.fivefarmers.com/2012/07/05/whos-leaking-prepared-statements/

If prepared statements / connection is continuously growing, your application has leak.
If your application code is fine, there may be leak in database/sql or this driver.
If you believe your code is fine and there is leak in driver, please write reproducible example
which leak statement continuously.

Unless reproducible example, your problem is just an expected behavior, or your leak.