Skip to content

Commit 6b1ea9d

Browse files
darolddarold
authored
Merge pull request #879 from NikuleskoA/fix/csvlog-duration-leak
Fix csvlog duration leak for statement-only entries
2 parents bbe7341 + 35dbafb commit 6b1ea9d

3 files changed

Lines changed: 69 additions & 19 deletions

File tree

‎pgbadger‎

Lines changed: 33 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -4115,6 +4115,9 @@ sub process_file
41154115
$nlines++;
41164116
&update_progress_bar($tmpoutfile, $nlines, $stop_offset, $totalsize, \$cursize, \$old_queries_count, \$old_errors_count, $fmt);
41174117

4118+
# Reset state extracted from the previous csvlog row.
4119+
%prefix_vars = ();
4120+
41184121
next if ( ($row->[11] !~ $parse_regex) || ($row->[11] eq 'LOCATION'));
41194122

41204123
# Extract the date
@@ -15830,30 +15833,33 @@ sub load_stats
1583015833
{
1583115834
foreach my $stmt (keys %{$_normalyzed_info{$curdb}})
1583215835
{
15833-
foreach my $dt (keys %{$_normalyzed_info{$curdb}{$stmt}{samples}} )
15836+
if (exists $_normalyzed_info{$curdb}{$stmt}{samples})
1583415837
{
15835-
foreach my $k (keys %{$_normalyzed_info{$curdb}{$stmt}{samples}{$dt}} ) {
15836-
$normalyzed_info{$curdb}{$stmt}{samples}{$dt}{$k} = $_normalyzed_info{$curdb}{$stmt}{samples}{$dt}{$k};
15838+
foreach my $dt (keys %{$_normalyzed_info{$curdb}{$stmt}{samples}} )
15839+
{
15840+
foreach my $k (keys %{$_normalyzed_info{$curdb}{$stmt}{samples}{$dt}} ) {
15841+
$normalyzed_info{$curdb}{$stmt}{samples}{$dt}{$k} = $_normalyzed_info{$curdb}{$stmt}{samples}{$dt}{$k};
15842+
}
1583715843
}
15838-
}
1583915844

15840-
# Keep only the top N samples
15841-
my $i = 1;
15842-
foreach my $k (sort {$b <=> $a} keys %{$normalyzed_info{$curdb}{$stmt}{samples}})
15843-
{
15844-
if ($i > $sample) {
15845-
delete $normalyzed_info{$curdb}{$stmt}{samples}{$k};
15845+
# Keep only the top N samples
15846+
my $i = 1;
15847+
foreach my $k (sort {$b <=> $a} keys %{$normalyzed_info{$curdb}{$stmt}{samples}})
15848+
{
15849+
if ($i > $sample) {
15850+
delete $normalyzed_info{$curdb}{$stmt}{samples}{$k};
15851+
}
15852+
$i++;
1584615853
}
15847-
$i++;
1584815854
}
1584915855

1585015856
$normalyzed_info{$curdb}{$stmt}{count} += $_normalyzed_info{$curdb}{$stmt}{count};
1585115857

1585215858
# Set min / max duration for this query
15853-
if (!exists $normalyzed_info{$curdb}{$stmt}{min} || ($normalyzed_info{$curdb}{$stmt}{min} > $_normalyzed_info{$curdb}{$stmt}{min})) {
15859+
if (defined $_normalyzed_info{$curdb}{$stmt}{min} && (!exists $normalyzed_info{$curdb}{$stmt}{min} || ($normalyzed_info{$curdb}{$stmt}{min} > $_normalyzed_info{$curdb}{$stmt}{min}))) {
1585415860
$normalyzed_info{$curdb}{$stmt}{min} = $_normalyzed_info{$curdb}{$stmt}{min};
1585515861
}
15856-
if (!exists $normalyzed_info{$curdb}{$stmt}{max} || ($normalyzed_info{$curdb}{$stmt}{max} < $_normalyzed_info{$curdb}{$stmt}{max})) {
15862+
if (defined $_normalyzed_info{$curdb}{$stmt}{max} && (!exists $normalyzed_info{$curdb}{$stmt}{max} || ($normalyzed_info{$curdb}{$stmt}{max} < $_normalyzed_info{$curdb}{$stmt}{max}))) {
1585715863
$normalyzed_info{$curdb}{$stmt}{max} = $_normalyzed_info{$curdb}{$stmt}{max};
1585815864
}
1585915865

@@ -15863,22 +15869,30 @@ sub load_stats
1586315869
{
1586415870
$normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{count} +=
1586515871
$_normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{count};
15866-
$normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{duration} +=
15867-
$_normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{duration};
15872+
if (defined $_normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{duration})
15873+
{
15874+
$normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{duration} +=
15875+
$_normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{duration};
15876+
}
1586815877
foreach my $min (keys %{$_normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{min}} )
1586915878
{
1587015879
$normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{min}{$min} +=
1587115880
$_normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{min}{$min};
1587215881
}
15873-
foreach my $min (keys %{$_normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{min_duration}} )
15882+
if (exists $_normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{min_duration})
1587415883
{
15875-
$normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{min_duration}{$min} +=
15876-
$_normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{min_duration}{$min};
15884+
foreach my $min (keys %{$_normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{min_duration}} )
15885+
{
15886+
$normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{min_duration}{$min} +=
15887+
$_normalyzed_info{$curdb}{$stmt}{chronos}{$day}{$hour}{min_duration}{$min};
15888+
}
1587715889
}
1587815890
}
1587915891
}
1588015892

15881-
$normalyzed_info{$curdb}{$stmt}{duration} += $_normalyzed_info{$curdb}{$stmt}{duration};
15893+
if (defined $_normalyzed_info{$curdb}{$stmt}{duration}) {
15894+
$normalyzed_info{$curdb}{$stmt}{duration} += $_normalyzed_info{$curdb}{$stmt}{duration};
15895+
}
1588215896

1588315897
if (exists $_normalyzed_info{$curdb}{$stmt}{locks})
1588415898
{

‎t/07_csv_statement_duration.t‎

Lines changed: 34 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,34 @@
1+
use Test::More;
2+
use JSON::XS;
3+
4+
eval { require Text::CSV_XS; 1 }
5+
or plan skip_all => 'Text::CSV_XS is required for csvlog parsing';
6+
7+
plan tests => 5;
8+
9+
my $json = JSON::XS->new;
10+
my $LOG = 't/fixtures/csv_statement_without_duration.log';
11+
my $OUT = 't/csv_statement_without_duration.json';
12+
13+
unlink $OUT;
14+
15+
my $ret = `perl pgbadger -f csv -q -x json -o $OUT $LOG 2>&1`;
16+
is($?, 0, 'Generate json report from csvlog');
17+
diag($ret) if $?;
18+
19+
my $json_ref = $json->decode(`cat $OUT`);
20+
my $queries = $json_ref->{normalyzed_info}{postgres};
21+
my ($statement_key) = grep { /health_check/ } keys %{$queries};
22+
my ($duration_key) = grep { /slow_table/ } keys %{$queries};
23+
24+
ok($duration_key, 'Fixture contains a duration-bearing query');
25+
is($queries->{$duration_key}{duration}, '688786.283', 'Duration-bearing query keeps its duration');
26+
ok($statement_key, 'Fixture contains a statement-only query');
27+
ok(
28+
!exists $queries->{$statement_key}{duration}
29+
&& !exists $queries->{$statement_key}{min}
30+
&& !exists $queries->{$statement_key}{max},
31+
'Statement-only csvlog query does not inherit previous duration'
32+
);
33+
34+
unlink $OUT;

‎t/fixtures/csv_statement_without_duration.log‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,2 @@
1+
"2026-05-16 05:11:50.269 UTC","example_user","example_db",1001,"192.0.2.10:54321",00000001.000003e9,1,"SELECT","2026-05-16 05:00:00 UTC",1/1,0,LOG,00000,"duration: 688786.283 ms execute stmt_slow/stmt_slow: SELECT example_schema.slow_table.id FROM example_schema.slow_table",,,,,,,,,"example app","client backend",0
2+
"2026-05-16 05:20:03.994 UTC","health_user","health_db",1002,"192.0.2.20:54322",00000002.000003ea,2,"idle","2026-05-16 05:00:00 UTC",2/2,0,LOG,00000,"statement: SELECT example_schema.health_check()",,,,,,,,,"example healthcheck","client backend",0

0 commit comments

Comments
 (0)