Experiencing "slow write timer already active" Panic with pgx During Load Testing

[jpkontreras]

Context

Hello everyone,

I'm reaching out to the community for insights into a panic I've encountered while using the pgx library for PostgreSQL during HTTP load testing with Baton. The panic is consistently reproducible and relates to the connection pool management, specifically when connections are being closed.

Error Encountered

The error message is as follows:

panic: BUG: slow write timer already active
goroutine 186 [running]:
github.com/jackc/pgx/v5/pgconn.(*PgConn).enterPotentialWriteReadDeadlock(...)
/home/user/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/pgconn/pgconn.go:1741
github.com/jackc/pgx/v5/pgconn.(*PgConn).flushWithPotentialWriteReadDeadlock(0xc00031a900)
/home/user/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/pgconn/pgconn.go:1760 +0xaf
github.com/jackc/pgx/v5/pgconn.(*PgConn).Close(0xc00031a900, {0x9b3b80?, 0xc0004b4230})
/home/user/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/pgconn/pgconn.go:633 +0x19f
github.com/jackc/pgx/v5.(*Conn).Close(0x9b39c0?, {0x9b3b80?, 0xc0004b4230?})
/home/user/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/conn.go:285 +0x31
github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func2(0xc0004b41c0)
/home/user/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/pgxpool/pool.go:248 +0x9a
github.com/jackc/puddle/v2.(*Pool[...]).destructResourceValue(0xc00008afd0, 0x6e3101?)
/home/user/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:694 +0x1f
github.com/jackc/puddle/v2.(*Pool[...]).destroyAcquiredResource(0xc0002041e0, 0xc00021ef00?)
/home/user/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:674 +0x39
created by github.com/jackc/puddle/v2.(*Resource[...]).Destroy in goroutine 37
/home/user/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:76 +0x90

Seeking Guidance

1. Has anyone else encountered this issue, or does it ring any bells?
2. Could this be related to the specific way Baton performs load testing?
3. Are there recommended practices for pgx pool management under heavy load that I might be overlooking?

Environment

• pgx version: v5
• Go version: 1.21
• PostgreSQL version: docker latest
• Operating System: WSL ubuntu 22.04

I'm curious to hear if others have faced similar issues or have thoughts on what might be going wrong. Any insights or directions would be greatly appreciated!

This is the code that im using

here im running baton -u http://localhost:8080/number -c 10 -r 1000
-c concurrent users
-r requests

Thank you for your time and help.

[jackc]

That panic indicates an internal state that should be impossible for user code to cause. However, I've reviewed the pgx code and I can't find any way it could happen. Can you run this with the race detector?

...

Ah... I think I see the problem.

If I'm reading this correctly the acquired connection is released, but the underlying *pgx.Conn is still is used later. I think that could trigger this. And I'm pretty confident that the race detector will detect problems with this code.

[jpkontreras]

it logs lots of WARNING: DATA RACE messages this is one of them

WARNING: DATA RACE
Write at 0x00c0004236a0 by goroutine 436:
github.com/jackc/pgx/v5/pgproto3.(*Frontend).Send()
/home/neo/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/pgproto3/frontend.go:76 +0xa4
github.com/jackc/pgx/v5/pgconn.(*PgConn).Close()
/home/neo/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/pgconn/pgconn.go:632 +0x2a5
github.com/jackc/pgx/v5.(*Conn).Close()
/home/neo/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/conn.go:285 +0x8f
github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func2()
/home/neo/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/pgxpool/pool.go:248 +0xef
github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).destructResourceValue()
/home/neo/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:694 +0x4a
github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).destroyAcquiredResource()
/home/neo/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:674 +0xa7
github.com/jackc/puddle/v2.(*Resource[go.shape.*uint8]).Destroy.func1()
/home/neo/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:76 +0x4f

Previous read at 0x00c0004236a0 by goroutine 8:
github.com/jackc/pgx/v5/pgproto3.(*Frontend).Flush()
/home/neo/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/pgproto3/frontend.go:84 +0x3c
github.com/jackc/pgx/v5/pgconn.(*PgConn).flushWithPotentialWriteReadDeadlock()
/home/neo/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/pgconn/pgconn.go:1762 +0xc4
github.com/jackc/pgx/v5/pgconn.(*PgConn).execExtendedSuffix()
/home/neo/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/pgconn/pgconn.go:1133 +0xdb
github.com/jackc/pgx/v5/pgconn.(*PgConn).ExecPrepared()
/home/neo/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/pgconn/pgconn.go:1088 +0x1cc
github.com/jackc/pgx/v5.(*Conn).Query()
/home/neo/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/conn.go:789 +0x214b
rondas/internal/query.(*Queries).ListAuthors()
/home/neo/code/go/rondas/internal/query/query.sql.go:63 +0xae
rondas/internal/server.(*Server).Handler()
/home/neo/code/go/rondas/internal/server/user.go:10 +0xc4
rondas/internal/server.(*Server).Handler-fm()
:1 +0x51
net/http.HandlerFunc.ServeHTTP()
/usr/local/go/src/net/http/server.go:2136 +0x47
github.com/go-chi/chi/v5.(*Mux).routeHTTP()
/home/neo/go/pkg/mod/github.com/go-chi/chi/v5@v5.0.10/mux.go:444 +0x525
github.com/go-chi/chi/v5.(*Mux).routeHTTP-fm()
:1 +0x51
net/http.HandlerFunc.ServeHTTP()
/usr/local/go/src/net/http/server.go:2136 +0x47
github.com/go-chi/chi/v5/middleware.init.0.RequestLogger.func1.1()
/home/neo/go/pkg/mod/github.com/go-chi/chi/v5@v5.0.10/middleware/logger.go:54 +0x1eb
net/http.HandlerFunc.ServeHTTP()
/usr/local/go/src/net/http/server.go:2136 +0x47
github.com/go-chi/chi/v5.(*Mux).ServeHTTP()
/home/neo/go/pkg/mod/github.com/go-chi/chi/v5@v5.0.10/mux.go:90 +0x63b
net/http.serverHandler.ServeHTTP()
/usr/local/go/src/net/http/server.go:2938 +0x2a1
net/http.(*conn).serve()
/usr/local/go/src/net/http/server.go:2009 +0xc24
net/http.(*Server).Serve.func3()
/usr/local/go/src/net/http/server.go:3086 +0x4f

Goroutine 436 (running) created at:
github.com/jackc/puddle/v2.(*Resource[go.shape.*uint8]).Destroy()
/home/neo/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:76 +0x169
github.com/jackc/pgx/v5/pgxpool.(*Conn).Release()
/home/neo/go/pkg/mod/github.com/jackc/pgx/v5@v5.5.0/pgxpool/conn.go:30 +0x1b5
rondas/internal/database.(*service).Query.func1()
/home/neo/code/go/rondas/internal/database/database.go:51 +0x2e
runtime.deferreturn()
/usr/local/go/src/runtime/panic.go:477 +0x30
rondas/internal/server.(*Server).Handler()
/home/neo/code/go/rondas/internal/server/user.go:10 +0x57
rondas/internal/server.(*Server).Handler-fm()
:1 +0x51
net/http.HandlerFunc.ServeHTTP()
/usr/local/go/src/net/http/server.go:2136 +0x47
github.com/go-chi/chi/v5.(*Mux).routeHTTP()
/home/neo/go/pkg/mod/github.com/go-chi/chi/v5@v5.0.10/mux.go:444 +0x525
github.com/go-chi/chi/v5.(*Mux).routeHTTP-fm()
:1 +0x51
net/http.HandlerFunc.ServeHTTP()
/usr/local/go/src/net/http/server.go:2136 +0x47
github.com/go-chi/chi/v5/middleware.init.0.RequestLogger.func1.1()
/home/neo/go/pkg/mod/github.com/go-chi/chi/v5@v5.0.10/middleware/logger.go:54 +0x1eb
net/http.HandlerFunc.ServeHTTP()
/usr/local/go/src/net/http/server.go:2136 +0x47
github.com/go-chi/chi/v5.(*Mux).ServeHTTP()
/home/neo/go/pkg/mod/github.com/go-chi/chi/v5@v5.0.10/mux.go:90 +0x63b
net/http.serverHandler.ServeHTTP()
/usr/local/go/src/net/http/server.go:2938 +0x2a1
net/http.(*conn).serve()
/usr/local/go/src/net/http/server.go:2009 +0xc24
net/http.(*Server).Serve.func3()
/usr/local/go/src/net/http/server.go:3086 +0x4f

Goroutine 8 (running) created at:
net/http.(*Server).Serve()
/usr/local/go/src/net/http/server.go:3086 +0x80c
net/http.(*Server).ListenAndServe()
/usr/local/go/src/net/http/server.go:2985 +0xbc
main.main()
/home/neo/code/go/rondas/cmd/api/main.go:12 +0x24

[jpkontreras]

FYI im using sqlc to generate the queries so im not really writing that much code

[jpkontreras]

this solved it thanks!