Skip to content
Merged
Show file tree
Hide file tree
Changes from 2 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
55 changes: 25 additions & 30 deletions input/full.go
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,6 @@ import (
"github.com/pganalyze/collector/input/postgres"
"github.com/pganalyze/collector/input/system"
"github.com/pganalyze/collector/logs"
"github.com/pganalyze/collector/scheduler"
"github.com/pganalyze/collector/state"
"github.com/pganalyze/collector/util"
)
Expand Down Expand Up @@ -116,7 +115,8 @@ func CollectFull(ctx context.Context, server *state.Server, connection *sql.DB,
logger.PrintError("Error setting query text timeout: %s", err)
return
}
ts.Statements, ts.StatementTexts, err = postgres.GetStatementTexts(ctx, c, connection)
var statementSize int
ts.Statements, ts.StatementTexts, statementSize, err = postgres.GetStatementTexts(ctx, c, connection)
if err != nil {
// Despite query performance data being an essential part of pganalyze, there are
// situations where it may not be available (or it timed out), so treat it as a
Expand Down Expand Up @@ -151,41 +151,36 @@ func CollectFull(ctx context.Context, server *state.Server, connection *sql.DB,
return
}

// Reset query stats and texts if needed (this must run after the query text collection)
ps.StatementResetCounter = server.PrevState.StatementResetCounter + 1
config := server.Grant.Load().Config
if config.Features.StatementResetFrequency != 0 && ps.StatementResetCounter >= int(config.Features.StatementResetFrequency) {
// Block concurrent collection of query stats, as that may see the actual Postgres-side
// reset before we updated the struct that the collector diffs against.
if opts.CollectPostgresSettings {
ts.Settings, err = postgres.GetSettings(ctx, connection)
if err != nil {
logger.PrintError("Error collecting config settings: %s", err)
return
}
}

shouldReset, err := postgres.ShouldResetStatements(server, &ps, &ts, statementSize)
if err != nil {
logger.PrintError("Error checking if should reset statements: %s", err)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should we explicitly log that we're skipping the reset in this case. It's the logical conclusion, but the statement is technically a little ambiguous.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logger.PrintError("Error checking if should reset statements: %s", err)
logger.PrintError("Failed to determine if reset of pg_stat_statements needed, skipping reset: %s", err)

err = nil
} else if shouldReset {
server.HighFreqStateMutex.Lock()
ps.StatementResetCounter = 0
err = postgres.ResetStatements(ctx, c, connection)
if err != nil {
logger.PrintError("Error calling pg_stat_statements_reset() as requested: %s", err)
logger.PrintError("Error calling pg_stat_statements_reset(): %s", err)
err = nil
} else {
logger.PrintInfo("Successfully called pg_stat_statements_reset() for all queries, next reset in %d hours", config.Features.StatementResetFrequency/scheduler.FullSnapshotsPerHour)

// Make sure the next high frequency run has an empty reference point
newHighFreqState.LastStatementStatsAt = time.Now()
resetStatementStats, err := postgres.GetStatementStats(ctx, c, connection)
if err != nil {
logger.PrintError("Error collecting pg_stat_statements after reset: %s", err)
err = nil
newHighFreqState.StatementStats = make(state.PostgresStatementStatsMap)
} else {
newHighFreqState.StatementStats = resetStatementStats
}
}
server.HighFreqStateMutex.Unlock()
}

if opts.CollectPostgresSettings {
ts.Settings, err = postgres.GetSettings(ctx, connection)
// Make sure the next high frequency run has an empty reference point
newHighFreqState.LastStatementStatsAt = time.Now()
resetStatementStats, err := postgres.GetStatementStats(ctx, c, connection)
if err != nil {
logger.PrintError("Error collecting config settings: %s", err)
return
logger.PrintError("Error collecting pg_stat_statements after reset: %s", err)
err = nil
newHighFreqState.StatementStats = make(state.PostgresStatementStatsMap)
} else {
newHighFreqState.StatementStats = resetStatementStats

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do we need to call GetStatementStats here? Why not always set newHighFreqState.StatementStats to an empty map?

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

+1, I've also wondered about that.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just discussed this with Sean, the problem is that we can't just take an empty map always since that would cause followUpRun to be false here: https://github.com/pganalyze/collector/blob/main/input/full_1min.go#L68

Sean is going to investigate reworking that in a follow-up PR.

}
server.HighFreqStateMutex.Unlock()
}

// CollectAllSchemas relies on GetBufferCache to access the filenode OIDs before that data is discarded
Expand Down
68 changes: 49 additions & 19 deletions input/postgres/statements.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,9 +6,12 @@ import (
"fmt"
"io"
"os"
"strconv"
"strings"
"time"

"github.com/guregu/null"
"github.com/pganalyze/collector/scheduler"
"github.com/pganalyze/collector/selftest"
"github.com/pganalyze/collector/state"
"github.com/pganalyze/collector/util"
Expand Down Expand Up @@ -59,7 +62,35 @@ func insufficientPrivilege(query string) bool {
return query == "<insufficient privilege>"
}

func ResetStatements(ctx context.Context, c *Collection, db *sql.DB) error {
func ShouldResetStatements(server *state.Server, ps *state.PersistedState, ts *state.TransientState, size int) (reset bool, err error) {
config := server.Grant.Load().Config
lastReset := ps.PgStatStatementsStats.Reset
resetFreq := config.Features.StatementResetFrequency * scheduler.FullSnapshotMinutes
maxSize := int(config.Features.StatementMaxSize)
if !lastReset.Valid {
return // It's always set on PG14+ with the extension enabled. Older versions aren't supported
}
if maxSize == 0 {
maxSize = 250
}
count := len(ts.Statements)
max := 5_000

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
count := len(ts.Statements)
max := 5_000
entryCount := len(ts.Statements)
entryMax := 5_000

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(nice to have, not sure its needed)

for _, setting := range ts.Settings {
if setting.Name == "pg_stat_statements.max" && setting.CurrentValue.Valid {
max, err = strconv.Atoi(setting.CurrentValue.String)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we could separate this out into a helper (but we can do that in a follow-up PR) - also worth noting that you can use ResetValue and CurrentValue interchangeably here, since this can only be set at server start.

if err != nil {
return
}
}
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we want to fall back to 5,000 (rather than error out) if we don't find the setting? It should rarely happen, so it's not a big deal either way, but this behavior might be harder to track down if for some reason the setting can't be read.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Assuming I read your comment right, I agree - we should error out if we can't read the setting, since we can't be sure what the actual value is. It should be rare in practice, but could happen on platforms that don't grant pg_read_all_settings to the pganalyze user (maybe Heroku or Aiven?).

timeElapsed := resetFreq > 0 && time.Since(lastReset.Time).Minutes() >= float64(resetFreq)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just to confirm what I checked: Minutes() will convert the hour/etc portion to minutes, so this will work as expected. See https://pkg.go.dev/time#Duration.Minutes

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also maybe resetAllowed is a more clear name?

tooMany := float64(count) >= 0.9*float64(max)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We could put the 0.9 into a constant just before the function so it jumps out more that this the thershold.

tooLarge := size > maxSize*1024*1024
reset = timeElapsed && (tooMany || tooLarge)
return
}

func ResetStatements(ctx context.Context, c *Collection, db *sql.DB) (err error) {
var method string
if c.HelperExists("reset_stat_statements", nil) {
c.Logger.PrintVerbose("Found pganalyze.reset_stat_statements() stats helper")
Expand All @@ -71,11 +102,9 @@ func ResetStatements(ctx context.Context, c *Collection, db *sql.DB) error {
}
method = "pg_stat_statements_reset()"
}
_, err := db.ExecContext(ctx, QueryMarkerSQL+"SELECT "+method)
if err != nil {
return err
}
return nil
c.Logger.PrintInfo("Resetting pg_stat_statements")

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
c.Logger.PrintInfo("Resetting pg_stat_statements")
c.Logger.PrintInfo("Executing pg_stat_statements_reset() for all queries")

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Or move it back to the top-level function and reword slightly to make it after the fact (like it was before).

_, err = db.ExecContext(ctx, QueryMarkerSQL+"SELECT "+method)
return
}

func GetStatementStats(ctx context.Context, c *Collection, db *sql.DB) (state.PostgresStatementStatsMap, error) {
Expand Down Expand Up @@ -152,10 +181,10 @@ func GetStatementStats(ctx context.Context, c *Collection, db *sql.DB) (state.Po
return statementStats, nil
}

func GetStatementTexts(ctx context.Context, c *Collection, db *sql.DB) (state.PostgresStatementMap, state.PostgresStatementTextMap, error) {
func GetStatementTexts(ctx context.Context, c *Collection, db *sql.DB) (statements state.PostgresStatementMap, statementTextsByFp state.PostgresStatementTextMap, querySize int, err error) {
sourceTable, foundExtMinorVersion, err := getStatementSource(ctx, c, db, true)
if err != nil {
return nil, nil, err
return
}

topLevelField := statementSQLTopLevelFieldDefault
Expand All @@ -166,28 +195,27 @@ func GetStatementTexts(ctx context.Context, c *Collection, db *sql.DB) (state.Po
querySql := QueryMarkerSQL + fmt.Sprintf(statementTextSQL, topLevelField, sourceTable)
stmt, err := db.PrepareContext(ctx, querySql)
if err != nil {
return nil, nil, err
return
}
defer stmt.Close()

rows, err := stmt.QueryContext(ctx)
if err != nil {
return nil, nil, err
return
}
defer rows.Close()

var tmpFile *os.File

tmpFile, err = os.CreateTemp("", util.TempFilePrefix)
if err != nil {
return nil, nil, err
return
}
defer tmpFile.Close()
defer os.Remove(tmpFile.Name())

statements := make(state.PostgresStatementMap)
statementTextsByFp := make(state.PostgresStatementTextMap)

statements = make(state.PostgresStatementMap)
statementTextsByFp = make(state.PostgresStatementTextMap)
queryKeys := make([]state.PostgresStatementKey, 0)
queryLengths := make([]int, 0)

Expand All @@ -198,8 +226,9 @@ func GetStatementTexts(ctx context.Context, c *Collection, db *sql.DB) (state.Po

err = rows.Scan(&key.DatabaseOid, &key.UserOid, &queryID, &key.TopLevel, &receivedQuery)
if err != nil {
return nil, nil, err
return
}
querySize += len(receivedQuery.String)

if queryID.Valid {
key.QueryID = queryID.Int64
Expand All @@ -214,31 +243,32 @@ func GetStatementTexts(ctx context.Context, c *Collection, db *sql.DB) (state.Po
}

if err = rows.Err(); err != nil {
return nil, nil, err
return
}

tmpFile.Seek(0, io.SeekStart)
for idx, length := range queryLengths {
bytes := make([]byte, length)
_, err = io.ReadFull(tmpFile, bytes)
if err != nil {
return nil, nil, err
return
}
query := string(bytes)
ignoreIoTiming := ignoreIOTiming(c.PostgresVersion, query)
key := queryKeys[idx]
select {
// Since normalizing can take time, explicitly check for cancellations
case <-ctx.Done():
return nil, nil, ctx.Err()
err = ctx.Err()
return
default:
fingerprintAndNormalize(c, key, key.QueryID, query, statements, statementTextsByFp, ignoreIoTiming)
}
}

c.SelfTest.MarkCollectionAspectOk(state.CollectionAspectPgStatStatements)

return statements, statementTextsByFp, nil
return
}

func getStatementSource(ctx context.Context, c *Collection, db *sql.DB, showtext bool) (string, int16, error) {
Expand Down
3 changes: 3 additions & 0 deletions output/full.go
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,9 @@ import (

func SendFull(ctx context.Context, server *state.Server, collectionOpts state.CollectionOpts, logger *util.Logger, newState state.PersistedState, diffState state.DiffState, transientState state.TransientState, collectedIntervalSecs uint32) error {
s := transform.StateToSnapshot(newState, diffState, transientState, server)
if s.ServerStatistic.PgStatStatementsDealloc > 0 {
logger.PrintWarning("pg_stat_statements deallocation detected. We recommend enabling automatic resets on the pganalyze server settings page to avoid <query text unavailable>")

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logger.PrintWarning("pg_stat_statements deallocation detected. We recommend enabling automatic resets on the pganalyze server settings page to avoid <query text unavailable>")
logger.PrintWarning("Detected %d pg_stat_statements deallocations in the last %d minutes. Enable/adjust automatic reset settings in pganalyze to avoid <query text unavailable>", s.ServerStatistic.PgStatStatementsDealloc, scheduler.FullSnapshotMinutes)

}
s.CollectedIntervalSecs = collectedIntervalSecs
err := verifyIntegrity(&s)
if err != nil {
Expand Down
Loading
Loading