Pgx: connection with write queries keeps running forever

[samtech09]

My project need to connect two db instances one for read/write and another as only read-only. I have created two pools as below

type DB struct {
    reader *pgxpool.Pool
    writer *pgxpool.Pool
}

//Conn provide reader or writer connection as per readonly state
func (db *DB) Conn(readonly bool) *pgxpool.Pool {
    if readonly {
        return db.reader
    }
    return db.writer
}

//DbConfig is config for disk persistent database (PostgreSQL)
type DbConfig struct {
    DbHost string
    DbPort uint16
    DbName string
    DbUser string
    DbPwd  string
    DbTimeout int
    DbSSLMode string
}

func InitDbPool(reader, writer DbConfig) *DB {
    db := DB{}
    if reader.DbHost != "" {
        db.reader = initdb(reader, "sql-reader")
    }
    if writer.DbHost != "" {
        db.writer = initdb(writer, "sql-writer")
    }
    return &db
}

func (db *DB) CloseDbPool() {
    if db.reader != nil {
        db.reader.Close()
    }
    if db.writer != nil {
        db.writer.Close()
    }
}

func initdb(config DbConfig, connName string) *pgxpool.Pool {
    var err error
    if config.DbPort < 1 {
        config.DbPort = 5432
    }
    connString := fmt.Sprintf("postgresql://%s:%s@%s:%d/%s?connect_timeout=%d&sslmode=%s",
        config.DbUser, config.DbPwd, config.DbHost, config.DbPort, config.DbName, config.DbTimeout, config.DbSSLMode)

    cfg, err := pgxpool.ParseConfig(connString)
    if err != nil {
        panic(fmt.Sprintf("pgsql connection parse error [%s]: %s", connName, err.Error()))
    }
    p, err := pgxpool.ConnectConfig(context.Background(), cfg)
    if err != nil {
        panic(fmt.Sprintf("pgsql connection failed [%s]: %s", connName, err.Error()))
    }
    return p
}

and calling it as below for writer,

sql := "delete from tabl1 where id=$1;"
db.Conn(false).Query(ctx, sql, arg0)

Few calls working fine after after some calls, it just hang on with connection and keep running forever and reaches context deadline.
If i use context.Background() then it keep running forever and do not raise any error as well.

Is it the issue with pgx or i am doing something wrong ?

Postgres and app both are on different machine, Postgres not restarted.
Delay between two machine is < 1 ms.

[jackc]

The thing that jumps out at me is using Query for a delete instead of Exec. While that can work, it requires you to completely read the result set. If you are not reading the result set that would cause the connection pool to eventually be exhausted which would then cause the subsequent requests to hang until context deadline or a connection is returned to the pool (which would never happen...)

[samtech09]

Sure i will try with Exec then update you. Allow me some time.

[samtech09]

I replace Query with Exec but it doesn't make difference. However when i increased number connections in pool from default 4 to 20 it started working.

Right now it is in staging and only one or two users working to test functionality of app. If it require 20 conn for those then when we move it to production how much it will require ?
Is it the thing to worry ?

Update:
Just want to update the we are properly closing rows by calling defer rows.Close() just after opening it. Also reader pool has no issues.

[jackc]

Changing from 4 to 20 connections shouldn't have made a difference. If there was a connection leak that would only slightly delay pool exhaustion.

Just want to update the we are properly closing rows by calling defer rows.Close() just after opening it. Also reader pool has no issues.

Hmm... are you doing multiple queries in the function with the defer rows.Close()? Since defer runs when the function returns you could end up with multiple connections busy at once.

[redbaron]

@samtech09 , do you see these delete queries in select * from pg_stat_activity ? If so, what is state, wait_event and wait_event_type for them?

[samtech09]

@redbaron, i am not able to see those queries in pg_state_activity. However when it is working fine, i could see them there with idle status, but as soon as problem appear, queries doesn't appear in activity. It looks queries are not reaching to Postgres.

After restarting the application, it works 2-3 times properly then start giving that issue again.

@jackc, Most of the write functions are called as below, there is no rows opened so no connection leak should happen.

func (a *ItemPrices) ItemPricesCreate(cntxt context.Context, ip ItemPrices) (int64, error) {
    stmt := "insert into itemprices(itemcode, price, discountpercentage, discountflat, duration, qty) values($1, $2, $3, $4, $5, $6);"

    co, err := g.Db.Conn(false).Exec(cntxt, stmt, ip.ItemCode, ip.Price, ip.Discountpercentage, ip.DiscountFlat, ip.Duration, ip.Qty)
    if err != nil {
        return 0, err
    }
    return co.RowsAffected(), nil
}

[redbaron]

@samtech09 , did you try compiling your binary with race detector enable? It might reveal something.

If it comes up with nothing, next thing I'd try is to add https://golang.org/pkg/net/http/pprof/ and make a goroutine stack dump when problem occurs

[samtech09]

@redbaron, as you wrote, i compiled binary with -race and run it, but it didn't detect any race.
Now next is to try pprof, for which first i need to go through docs then i will try it as well.

[redbaron]

@samtech09 , any luck?

[anoam]

Got the kinda same problem.

I have such code:

// dbPool, err := pgxpool.Connect(context.Background(), "*credentials_here* pool_max_conns=3")
// 3 is just for the demonstration purpose
// ...
// and than I do
go func() {
  if c, err = dbPool.Acquire(context.Background()); err != nil {
    log.Fatal(err)
  }
  defer c.Release()
  // some queries using c here
}()

I use gorutine here because actualy I get data via network and receive it in series but packages are independent and can be processed simultaneously.

And soon I get a lack of connection. The application keeps receiving new packages but doesn't process them.

Here is what I've got with pprof

goroutine profile: total 51
goroutine profile: total 3259
3251 @ 0x465940 0x478708 0x4786de 0x4b0a3e 0xae28f7 0xae8997 0xb095f2 0xb08a35 0xbb6824 0xbb5823 0x496771
#   0x4786dd    sync.runtime_notifyListWait+0xcd                                    /home/anoam/.local/go/src/runtime/sema.go:513
#   0x4b0a3d    sync.(*Cond).Wait+0x8d                                          /home/anoam/.local/go/src/sync/cond.go:56
#   0xae28f6    github.com/jackc/puddle.(*Pool).Acquire+0x1b6                               /home/anoam/go/pkg/mod/github.com/jackc/[email protected]/pool.go:326
#   0xae8996    github.com/jackc/pgx/v4/pgxpool.(*Pool).Acquire+0xa6                            /home/anoam/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:336
# reference to gorutine above

1 @ 0x465940 0x476c09 0xae8327 0x496771
#   0xae8326    github.com/jackc/pgx/v4/pgxpool.(*Pool).backgroundHealthCheck+0x166 /home/anoam/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:298

And I can't see any other goroutines working with connections:

1 @ 0x465940 0x45e8ea 0x45deb5 0x4fba64 0x4fd0d3 0x4fd099 0x74fca6 0x76bde1 0xa87dc2 0x496771
#   0x45deb4    internal/poll.runtime_pollWait+0x54     /home/anoam/.local/go/src/runtime/netpoll.go:203
#   0x4fba63    internal/poll.(*pollDesc).wait+0xe3     /home/anoam/.local/go/src/internal/poll/fd_poll_runtime.go:87
#   0x4fd0d2    internal/poll.(*pollDesc).waitRead+0x252    /home/anoam/.local/go/src/internal/poll/fd_poll_runtime.go:92
#   0x4fd098    internal/poll.(*FD).Read+0x218          /home/anoam/.local/go/src/internal/poll/fd_unix.go:169
#   0x74fca5    net.(*netFD).Read+0x65              /home/anoam/.local/go/src/net/fd_unix.go:202
#   0x76bde0    net.(*conn).Read+0xa0               /home/anoam/.local/go/src/net/net.go:184
#   0xa87dc1    net/http.(*connReader).backgroundRead+0x91  /home/anoam/.local/go/src/net/http/server.go:678

1 @ 0x465940 0x45e8ea 0x45deb5 0x4fba64 0x4fd0d3 0x4fd099 0x74fca6 0x76bde1 0xbb0856 0xbb47b7 0xc387be 0x465542 0x496771
#   0x45deb4    internal/poll.runtime_pollWait+0x54                     /home/anoam/.local/go/src/runtime/netpoll.go:203
#   0x4fba63    internal/poll.(*pollDesc).wait+0xe3                     /home/anoam/.local/go/src/internal/poll/fd_poll_runtime.go:87
#   0x4fd0d2    internal/poll.(*pollDesc).waitRead+0x252                    /home/anoam/.local/go/src/internal/poll/fd_poll_runtime.go:92
#   0x4fd098    internal/poll.(*FD).Read+0x218                          /home/anoam/.local/go/src/internal/poll/fd_unix.go:169
#   0x74fca5    net.(*netFD).Read+0x65                              /home/anoam/.local/go/src/net/fd_unix.go:202
#   0x76bde0    net.(*conn).Read+0xa0                               /home/anoam/.local/go/src/net/net.go:184

1 @ 0x465940 0x45e8ea 0x45deb5 0x4fba64 0x4ff5a9 0x4ff56f 0x7508c6 0x77bb20 0x779990 0xa9870e 0xa98273 0xc38a30 0xc38970 0x496771
#   0x45deb4    internal/poll.runtime_pollWait+0x54     /home/anoam/.local/go/src/runtime/netpoll.go:203
#   0x4fba63    internal/poll.(*pollDesc).wait+0xe3     /home/anoam/.local/go/src/internal/poll/fd_poll_runtime.go:87
#   0x4ff5a8    internal/poll.(*pollDesc).waitRead+0x2c8    /home/anoam/.local/go/src/internal/poll/fd_poll_runtime.go:92
#   0x4ff56e    internal/poll.(*FD).Accept+0x28e        /home/anoam/.local/go/src/internal/poll/fd_unix.go:384
#   0x7508c5    net.(*netFD).accept+0x55            /home/anoam/.local/go/src/net/fd_unix.go:238
#   0x77bb1f    net.(*TCPListener).accept+0x4f          /home/anoam/.local/go/src/net/tcpsock_posix.go:139
#   0x77998f    net.(*TCPListener).Accept+0x4f          /home/anoam/.local/go/src/net/tcpsock.go:261
#   0xa9870d    net/http.(*Server).Serve+0x3fd          /home/anoam/.local/go/src/net/http/server.go:2901
#   0xa98272    net/http.(*Server).ListenAndServe+0x102     /home/anoam/.local/go/src/net/http/server.go:2830
#   0xc38a2f    net/http.ListenAndServe+0xef            /home/anoam/.local/go/src/net/http/server.go:3086

1 @ 0xc282a3 0xc2806a 0xc241ac 0xc36b94 0xc3793a 0xa93642 0xa96329 0xa97f1f 0xa916b8 0x496771
#   0xc282a2    runtime/pprof.writeRuntimeProfile+0xa2  /home/anoam/.local/go/src/runtime/pprof/pprof.go:694
#   0xc28069    runtime/pprof.writeGoroutine+0xc9   /home/anoam/.local/go/src/runtime/pprof/pprof.go:656
#   0xc241ab    runtime/pprof.(*Profile).WriteTo+0x4fb  /home/anoam/.local/go/src/runtime/pprof/pprof.go:329
#   0xc36b93    net/http/pprof.handler.ServeHTTP+0x3b3  /home/anoam/.local/go/src/net/http/pprof/pprof.go:248
#   0xc37939    net/http/pprof.Index+0x9e9      /home/anoam/.local/go/src/net/http/pprof/pprof.go:271
#   0xa93641    net/http.HandlerFunc.ServeHTTP+0x51 /home/anoam/.local/go/src/net/http/server.go:2012
#   0xa96328    net/http.(*ServeMux).ServeHTTP+0x288    /home/anoam/.local/go/src/net/http/server.go:2387
#   0xa97f1e    net/http.serverHandler.ServeHTTP+0xce   /home/anoam/.local/go/src/net/http/server.go:2807
#   0xa916b7    net/http.(*conn).serve+0x837        /home/anoam/.local/go/src/net/http/server.go:1895

[redbaron]

@anoam , there is a mutex profile /debug/pprof/mutex (https://golang.org/pkg/net/http/pprof/), does it show you who else holds the lock?

[anoam]

@redbaron

Hah. Quite nothing actually.
Just some stuff like that.

--- mutex:
cycles/second=1992005232
sampling period=10

20300 1 @ 0x4b2bbb 0xb13bdc 0xbb05fb 0xbb05b0 0xbb055d 0xbb4767 0xc3877b 0x465542 0x496771
#   0x4b2bba    sync.(*Mutex).Unlock+0x7a                           /home/anoam/.local/go/src/sync/mutex.go:190
#   0xb13bdb    github.com/labstack/gommon/log.(*Logger).log+0x36b              /home/anoam/go/pkg/mod/github.com/labstack/[email protected]/log/log.go:415
#   0xbb05fa    github.com/labstack/gommon/log.(*Logger).Info+0x43a             /home/anoam/go/pkg/mod/github.com/labstack/[email protected]/log/log.go:165
#   0xbb05af    github.com/labstack/gommon/log.Info+0x3ef                   /home/anoam/go/pkg/mod/github.com/labstack/[email protected]/log/log.go:291

Have I misconfigured it somehow? :(

[samtech09]

@redbaron @jackc as @anoam provided stack dump, did you find there something odd ?

[smgladkovskiy]

Any progress on this problem? I faced with the same. Have the same picture in pprof as @redbaron showed...

[jackc]

Nothing jumps out at me from the stack traces.

There was a fix to the connection pool in v4.9.0. Don't think it would be the cause of this issue, but be sure to run with at least that version to test.

One other bit of information that could narrow the problem is to call pool.Stat() when it is hung. That could tell us whether the pool really has leaked or the goroutines waiting for an available connection are just not waking up.

[smgladkovskiy]

I spent a sleepless night trying to find the cause of the hang-up. As a result, I came up with a solution in the form of acquiring and releasing connection from the pool + ctx with timeout:

q := initQuery()

q, err := addArgumentsToQuery(someData, q)
if err != nil {
    return nil, err
}

_sql, argc, err := q.ToSql()
if err != nil {
    return err
}

db, err := dbPool.Acquire(ctxWithTimeout)
if err != nil {
    return err
}

defer db.Release()

rows, err := db.Query(ctxWithTimeout, _sql, argc...)
if err != nil {
    return err
}

defer rows.Close()

scanRows(rows)

Previously application hangs after a minute or so after start. Now it works already without hangs for about 8 hours.