search

darold / pgbadger

A fast PostgreSQL Log Analyzer
http://pgbadger.darold.net/
PostgreSQL License
3.49k stars 349 forks source link

Unable to parse some automatic vacuum output in RDS mode #743

Closed dgilmanAIDENTIFIED closed 2 years ago

dgilmanAIDENTIFIED commented 2 years ago

pgbadger has this log output:

DEBUG: Starting reading file "logs/error_postgresql.log.2022-07-20-13"...
DEBUG: Start parsing postgresql log at offset 927 of file "logs/error_postgresql.log.2022-07-20-13" to 268912
DEBUG: Unknown rds log line format:     pages: 0 removed, 101 remain, 0 skipped due to pins, 0 skipped frozen
DEBUG: Unknown rds log line format:     tuples: 268 removed, 2156 remain, 0 are dead but not yet removable, oldest xmin: 75919126
DEBUG: Unknown rds log line format:     buffer usage: 289 hits, 35 misses, 7 dirtied
DEBUG: Unknown rds log line format:     avg read rate: 183.024 MB/s, avg write rate: 36.605 MB/s
DEBUG: Unknown rds log line format:     system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
DEBUG: Unknown rds log line format:     WAL usage: 88 records, 6 full page images, 14704 bytes
DEBUG: setting current position in log to 268912

The relevant part of the log file. There appears to be a similar vacuum right above the offending one in the logs:

2022-07-20 13:00:32 UTC::@:[17811]:LOG:  automatic vacuum of table "foo.public.auth_user": index scans: 0
    pages: 0 removed, 1 remain, 0 skipped due to pins, 0 skipped frozen
    tuples: 61 removed, 4 remain, 0 are dead but not yet removable, oldest xmin: 75918746
    buffer usage: 115 hits, 4 misses, 1 dirtied
    avg read rate: 103.477 MB/s, avg write rate: 25.869 MB/s
    system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
    WAL usage: 2 records, 1 full page images, 368 bytes
2022-07-20 13:00:32 UTC::@:[17811]:LOG:  automatic analyze of table "foo.public.auth_user" system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2022-07-20 13:00:37 UTC::@:[5935]:LOG:  checkpoint complete: wrote 1051 buffers (0.1%); 0 WAL file(s) added, 0 removed, 2 recycled; write=152.643 s, sync=0.004 s, total=152.674 s; sync files=81, longest=0.004 s, average=0.001 s; distance=192881 kB, estimate=192881 kB
2022-07-20 13:02:56 UTC::@:[20508]:LOG:  automatic vacuum of table "bar.public.api_v0_usagemonitor": index scans: 0
    pages: 0 removed, 101 remain, 0 skipped due to pins, 0 skipped frozen
    tuples: 268 removed, 2156 remain, 0 are dead but not yet removable, oldest xmin: 75919126
    buffer usage: 289 hits, 35 misses, 7 dirtied
    avg read rate: 183.024 MB/s, avg write rate: 36.605 MB/s
    system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
    WAL usage: 88 records, 6 full page images, 14704 bytes
2022-07-20 13:03:04 UTC::@:[5935]:LOG:  checkpoint starting: time
2022-07-20 13:03:57 UTC::@:[5935]:LOG:  checkpoint complete: wrote 525 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=52.726 s, sync=0.008 s, total=52.755 s; sync files=61, longest=0.008 s, average=0.001 s; distance=2606 kB, estimate=173853 kB

Running pgbadger as the following:

pgbadger -v -J 8 -X -q --prefix '%t:%r:%u@%d:[%p]:' -S -I logs/* -O reports/
darold commented 2 years ago

Thanks, commit 77303ec fixes this issue.