jackc / pgx

PostgreSQL driver and toolkit for Go
MIT License
10.84k stars 846 forks source link

chunkreader Next returns internal/poll.DeadlineExceededError when returning a column with some Kb data. #2069

Closed ndsistsys closed 4 months ago

ndsistsys commented 4 months ago

I am querying a table containing a JSONB column filled with an array containing thousands of element. When I try iterating over the result of Pool.Query method, using a Next call, I am not able to iterate even once.

Debugging, it turned out it's due to https://github.com/jackc/pgx/blob/161ce73ec1fef02dce1889036862e00d5fb9e1c6/pgconn/pgconn.go#L1563 and more precisely the call https://github.com/jackc/pgx/blob/161ce73ec1fef02dce1889036862e00d5fb9e1c6/pgproto3/chunkreader.go#L80 always returning a internal/poll.DeadlineExceededError.

If I remove the JSONB column in the SELECT, everything works fine. After some attempts, I was able to reproduce the problem using my postgres schema (which I can not report here exactly) even using a docker container posgres running on my laptop. In this case, the table was containing only one row with a JSONB of a size ~13kB. If I reduce enough the size of the JSONB everything works fine. If i try to cast the JSONB to TEXT, with the original JSONB with size ~13kB it works most of the time.

I am struggling to create a minimal reproducible example. Even with a schema defined 1:1 (apart from column and table renaming), the minimal example I have created works fine, so it seems the problem is related to the exact contents/schema definition of the DB.

Call stack which leads to the error:

poll.runtime_pollReset (go1.22.1/src/runtime/netpoll.go:319)
poll.(*pollDesc).prepare (go1.22.1/src/internal/poll/fd_poll_runtime.go:68)
poll.(*pollDesc).prepareRead (go1.22.1/src/internal/poll/fd_poll_runtime.go:73)
poll.(*FD).Read (go1.22.1/src/internal/poll/fd_unix.go:153)
net.(*netFD).Read (go1.22.1/src/net/fd_posix.go:55)
net.(*conn).Read (go1.22.1/src/net/net.go:179)
net.(*TCPConn).Read (Unknown Source:1)
bgreader.(*BGReader).Read (github.com/jackc/pgx/v5@v5.6.0/pgconn/internal/bgreader/bgreader.go:100)
io.ReadAtLeast (go1.22.1/src/io/io.go:335)
pgproto3.(*chunkReader).Next (github.com/jackc/pgx/v5@v5.6.0/pgproto3/chunkreader.go:80)
pgproto3.(*Frontend).Receive (github.com/jackc/pgx/v5@v5.6.0/pgproto3/frontend.go:323)
pgconn.(*PgConn).peekMessage (github.com/jackc/pgx/v5@v5.6.0/pgconn/pgconn.go:547)
pgconn.(*PgConn).receiveMessage (github.com/jackc/pgx/v5@v5.6.0/pgconn/pgconn.go:567)
pgconn.(*ResultReader).receiveMessage (github.com/jackc/pgx/v5@v5.6.0/pgconn/pgconn.go:1650)
pgconn.(*ResultReader).NextRow (github.com/jackc/pgx/v5@v5.6.0/pgconn/pgconn.go:1563)
v5.(*baseRows).Next (github.com/jackc/pgx/v5@v5.6.0/rows.go:217)
pgxpool.(*poolRows).Next (github.com/jackc/pgx/v5@v5.6.0/pgxpool/rows.go:62)

Go version: 1.22.1 Postgres version: 15.5, 15.7

Would you have some suggestion about what could be the root cause of this issue?

jackc commented 4 months ago

Does your context have a deadline set? Or are you manually setting a deadline on the net.Conn? That's the only way that error should occur.

ndsistsys commented 4 months ago

The problem was indeed related to a context cancellation. In the original code, there was a little "innocent" method setting a context deadline and wrapping the call of Pool.Query; this method was calling the cancellation function as a defer function. Moving at higher level the call of the defer function solved the problem.

I can finally attach a minimal reproducible example as a reference. Thank you very much for your answer!

package main

import (
    "context"
    "fmt"
    "strings"
    "time"

    "github.com/jackc/pgx/v5"
    "github.com/jackc/pgx/v5/pgxpool"
)

type myStruct struct {
    ID       string     `json:"id"`
    Metadata []metadata `json:"metadata"`
}

type metadata struct {
    description
    intCouple
    MyString string `json:"myString"`
}

type intCouple struct {
    First  int64 `json:"f"`
    Second int64 `json:"s"`
}

type description struct {
    ID        string `json:"id"`
    AnotherID string `json:"anotherID"`
}

func main() {
    // created a postgres container with the following command
    // >> docker run --name postgres-test -p 5432:5432 -e POSTGRES_PASSWORD=pwd -d postgres:15

    // created a table with the following command
    //
    // CREATE TABLE mytable (
    //   id VARCHAR(10) NOT NULL,
    //   metadata JSONB NOT NULL,
    //   PRIMARY KEY (id));
    //

    ctx := context.Background()
    connectionString := "postgresql://postgres:pwd@localhost:5432/postgres?application_name=mytest&sslmode=disable"
    roConfig, err := pgxpool.ParseConfig(connectionString)
    if err != nil {
        fmt.Println(err)
        return
    }

    pool, err := pgxpool.NewWithConfig(ctx, roConfig)
    if err != nil {
        fmt.Println(err)
        return
    }

    if err := pool.Ping(ctx); err != nil {
        fmt.Println(err)
        return
    }

    // with mdSize = 10, even the bugged implementation works
    mdSize := 1000

    md := make([]metadata, 0, mdSize)
    longString := strings.Repeat("z", 200)
    for i := 0; i < mdSize; i++ {
        md = append(md, metadata{
            description: description{
                ID:        fmt.Sprintf("id-%s-%d", longString, i),
                AnotherID: fmt.Sprintf("type-0123456789012345678901234567890123456789-%d", i),
            },
            intCouple: intCouple{
                First:  int64(i) * 1000,
                Second: (int64(i)+1)*1000 - 1,
            },
            MyString: fmt.Sprintf("myString0123456789012345678901234567890123456789-%d", i),
        })
    }

    s := &myStruct{
        ID:       "id",
        Metadata: md,
    }

    _, err = pool.Exec(ctx, "INSERT INTO mytable(id, metadata) VALUES($1, $2)", s.ID, s.Metadata)
    if err != nil {
        fmt.Println(err)
        return
    }

    // working implmentation
    //ctxTimeout, cancel := context.WithTimeout(ctx, time.Minute*5)
    //defer cancel()
    // rows, err := pool.Query(ctxTimeout, "SELECT id, metadata FROM mytable WHERE id = $1", s.ID)

    // bugged implementation
    rows, err := innocentFunc(ctx, pool, "SELECT id, metadata FROM mytable WHERE id = $1", s.ID)
    //------------------------------------------------------------
    if err != nil {
        fmt.Println(err)
        return
    }
    defer rows.Close()

    counter := 0
    for rows.Next() {
        counter++
    }

    fmt.Println("loop counter: ", counter)
}

func innocentFunc(
    ctx context.Context,
    pool *pgxpool.Pool,
    query string,
    args ...any,
) (pgx.Rows, error) {
    ctxTimeout, cancel := context.WithTimeout(ctx, time.Minute*5)
    defer cancel()

    return pool.Query(ctxTimeout, query, args...)
}
jackc commented 4 months ago

👍