search

darold / pgbadger

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

Tempfile issue #758

Closed blogh closed 1 year ago

blogh commented 1 year ago

Hi,

I recently came across a tempfile calculation error.

Here is a sample logfile :

2022-10-18 14:50:10 CEST [6152]: [1-1] user=[unknown],db=[unknown] {10.1.32.31} LOG:  connection received: host=10.1.32.31 port=33017
2022-10-18 14:50:10 CEST [6152]: [2-1] user=myuser,db=mydb {10.1.32.31} LOG:  connection authorized: user=myuser database=mydb
2022-10-18 14:50:13 CEST [6152]: [3-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.0", size 20480000
2022-10-18 14:50:15 CEST [6152]: [4-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.1", size 20480000
2022-10-18 14:50:16 CEST [6152]: [5-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.2", size 20480000
2022-10-18 14:50:17 CEST [6152]: [6-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.3", size 20480000
2022-10-18 14:50:19 CEST [6152]: [7-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.4", size 20480000
2022-10-18 14:50:20 CEST [6152]: [8-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.5", size 20480000
2022-10-18 14:50:21 CEST [6152]: [9-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.6", size 20480000
2022-10-18 14:50:22 CEST [6152]: [10-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.7", size 20480000
2022-10-18 14:50:23 CEST [6152]: [11-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.8", size 20480000
2022-10-18 14:50:25 CEST [6152]: [12-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.9", size 20480000
2022-10-18 14:50:26 CEST [6152]: [13-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.10", size 20480000
2022-10-18 14:50:27 CEST [6152]: [14-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.11", size 20480000
2022-10-18 14:50:28 CEST [6152]: [15-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.12", size 20480000
2022-10-18 14:50:30 CEST [6152]: [16-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.13", size 20480000
2022-10-18 14:50:31 CEST [6152]: [17-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.14", size 20480000
2022-10-18 14:50:32 CEST [6152]: [18-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.15", size 20480000
2022-10-18 14:50:33 CEST [6152]: [19-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.16", size 20480000
2022-10-18 14:50:35 CEST [6152]: [20-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.17", size 20480000
2022-10-18 14:50:36 CEST [6152]: [21-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.18", size 20480000
2022-10-18 14:50:37 CEST [6152]: [22-1] user=myuser,db=mydb {10.1.32.31} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.19", size 20480000
2022-10-18 14:50:37 CEST [6152]: [23-1] user=myuser,db=mydb {10.1.32.31} LOG:  disconnection: session time: 0:00:27.058 user=myuser database=mydb host=10.1.32.31 port=33017
2022-10-18 15:01:16 CEST [6152]: [1-1] user=[unknown],db=[unknown] {192.168.29.101} LOG:  connection received: host=192.168.29.101 port=57582
2022-10-18 15:01:16 CEST [6152]: [2-1] user=that_user,db=thatdb {192.168.29.101} LOG:  connection authorized: user=that_user database=thatdb
2022-10-18 15:01:16 CEST [6152]: [3-1] user=that_user,db=thatdb {192.168.29.101} LOG:  disconnection: session time: 0:00:00.015 user=that_user database=thatdb host=192.168.29.101 port=57582
2022-10-18 18:35:23 CEST [6152]: [2-1] user=another_user,db=anotherdb {192.168.29.209} LOG:  connection authorized: user=another_user database=anotherdb
2022-10-18 18:35:49 CEST [6152]: [3-1] user=another_user,db=anotherdb {192.168.29.209} LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp6152.0", size 5703885
2022-10-18 18:35:49 CEST [6152]: [4-1] user=another_user,db=anotherdb {192.168.29.209} CONTEXT:  SQL statement "SELECT my_function();"
    PL/pgSQL function myfunction() line 54 at assignment
2022-10-18 18:35:49 CEST [6152]: [5-1] user=another_user,db=anotherdb {192.168.29.209} STATEMENT:  UPDATE "my"."table" SET "jsonfield" = '[{"date":"2026-12-19T15:00:00.000Z","type":"SECRET_DATA","value":1}]'
    WHERE "id_device" = '1486'
2022-10-18 18:37:04 CEST [6152]: [6-1] user=another_user,db=anotherdb {192.168.29.209} LOG:  could not receive data from client: unrecognized winsock error 10054
2022-10-18 18:37:04 CEST [6152]: [7-1] user=another_user,db=anotherdb {192.168.29.209} LOG:  disconnection: session time: 0:01:40.689 user=another_user database=anotherdb host=192.168.29.209 port=56325

The report :

pgBadger :: 

- Global information ---------------------------------------------------

Generated on Wed Oct 26 11:32:18 2022
Log file: issue.log
Parsed 62 log entries in 2s
Log start from 2022-10-18 14:50:10 to 2022-10-18 18:37:04

- Overall statistics ---------------------------------------------------

Number of unique normalized queries: 1
Number of queries: 0
Total query duration: 0ms
First query: -
Last query: -
Query peak: 0 queries/s at 2022-10-18 14:50:22
Number of events: 1
Number of unique normalized events: 1
Number temporary files: 21
Max size of temporary files: 396.06 MiB
Average size of temporary files: 18.86 MiB

- Queries generating the most temporary files (N) ---------------------------

Rank   Count   Total size    Min/Max/Avg size    Query
1)   1 - 415,303,885 - 415,303,885/415,303,885/415,303,885.00 - update "my"."table" set "jsonfield" = ? where "id_device" = ?;
--
    - Example 1: 0ms - 2022-10-18 14:50:13 - database: mydb, user: myuser, remote: 10.1.32.31 - UPDATE "my"."table" SET "jsonfield" = '[{"date":"2026-12-19T15:00:00.000Z","type":"SECRET_DATA","value":1}]'
    WHERE "id_device" = '1486';

- Queries generating the largest temporary files ----------------------------

Rank   Size    Query
1)   415,303,885 - 2022-10-18 14:50:13 - database: mydb, user: myuser, remote: 10.1.32.31 - UPDATE "my"."table" SET "jsonfield" = '[{"date":"2026-12-19T15:00:00.000Z","type":"SECRET_DATA","value":1}]'
    WHERE "id_device" = '1486';

- Most frequent queries (N) --------------------------------------------

Rank     Times executed     Total duration     Min/Max/Avg duration (s)     Query

- Most frequent events (N) ---------------------------------------------

1) 1 - LOG:  could not receive data from client: unrecognized winsock error 10054
--
    - Date: 2022-10-18 18:37:04
        Database: anotherdb

- Logs per type ---------------------------------------------

Logs type   Count   Percentage
CONTEXT     1   3.12%
LOG     30  93.75%
STATEMENT       1   3.12%

Generation command (--disable-error breaks the report even more for me) :

pgbadger issue.log -o issue.txt --disable-session --disable-connection --disable-lock --disable-checkpoint --disable-autovacuum --prefix '%t [%p]: [%l-1] user=%u,db=%d {%h} '

It looks like the script is not catching up on the fact that the first tempfiles have nothing to do with the last one and the size is computed with: 20,480,000*20+5,703,885 = 415,303,885

gilles-migops commented 1 year ago

I'm surprised that the pid 6152 doesn't change in the whole log especially after the disconnection. Where does this log come from or maybe it has been edited?

blogh commented 1 year ago

I extracted the relevant part from a 400MB client file where I initially found this problem. I then edited the user names, database names, modified the update and the function.

The rest didn't change.

darold commented 1 year ago

The report correspond to the log, this is the same pid on all log lines which prevent pgbadger to detect that this is a different connection.