duration is associated with wrong sentence in some conditions

[kaiko]

Duration is associated with wrong statement if some database requests are excluded.

In the pg log file:

2024-01-13 11:04:58 EET [281794]: user=u,db=dba,app=myapp: dba,client=[local] LOG:  statement: SELECT 'this is real slow' 
2024-01-13 11:04:58 EET [281794]: user=u,db=dba,app=myapp: dba,client=[local] LOG:  duration: 489.168 ms 
2024-01-13 11:04:58 EET [281794]: user=u,db=dba,app=myapp: dba,client=[local] LOG:  statement: SELECT 1 AS "this is fast 
2024-01-13 11:04:58 EET [281794]: user=u,db=dba,app=myapp: dba,client=[local] LOG:  duration: 0.960 ms 

Command: pgbadger -x txt -q --log-duration --exclude-db spec -i log-file.txt -o report.txt

And slowest queries shows (expecting 'this is real slow' query):

1) 489ms/489ms/489ms - 1 - 489ms - SELECT 1 AS "this is fast;

Full logfile content for testing: log-example.log

[darold]

This is a know limitation about log_statement+log_duration versus log_min_duration_statement. In the first case if the duration trace doesn't follow immediately the related statement trace you will have wrong result. This is why it is recommended to use log_min_duration_statement.