Fix report of auto_explain output. Thanks to fch77700 for the report.

diff --git a/pgbadger b/pgbadger
index 2dc0c31c48b87f380c87107ff946e990f4a4109c..ac9ef80a2ae885a0940aa3fa805de15d7efe1105 100644 (file)
--- a/pgbadger
+++ b/pgbadger
@@ -2796,6 +2796,24 @@ sub process_file
 
                                @matches = ($line =~ $compiled_prefix);
                                if ($#matches >= 0) {
+
+                                       # Store auto explain plan when switching to an other log entry
+                                       foreach my $p (keys %cur_plan_info) {
+                                               if (exists $cur_plan_info{$p}{plan}) {
+                                                       # Extract the query part from the plan
+                                                       my $key = 'query';
+                                                       my @plan = split("\n", $cur_plan_info{$p}{plan});
+                                                       foreach my $l (@plan) {
+                                                               $key = 'plan' if ($l =~ /\(cost=\d+.*rows=\d+/);
+                                                               $cur_info{$p}{$key} .= "$l\n";
+                                                       }
+                                                       $cur_info{$p}{query} =~ s/^\s*Query Text:\s+//s;
+                                                       delete $cur_plan_info{$p};
+                                                       &store_queries($p);
+                                                       delete $cur_info{$p};
+                                               }
+                                       }
+
                                        for (my $i = 0 ; $i <= $#prefix_params ; $i++) {
                                                $prefix_vars{$prefix_params[$i]} = $matches[$i];
                                        }
@@ -12652,9 +12670,9 @@ sub parse_query
                $prefix_vars{'t_bind'} = 1;
        # Activate storage of the explain plan generated by auto_explain
        } elsif ($prefix_vars{'t_query'} =~ s/duration: ([0-9\.]+) ms\s+plan://is) {
-               $cur_plan_info{$t_pid}{duration} = $1;
                $prefix_vars{'t_duration'} = $1;
-               my $k = &get_hist_inbound($1, @histogram_query_time);
+               $cur_plan_info{$prefix_vars{'t_pid'}}{duration} = $prefix_vars{'t_duration'};
+               my $k = &get_hist_inbound($prefix_vars{'t_duration'}, @histogram_query_time);
                $overall_stat{histogram}{query_time}{$k}++;
                $overall_stat{histogram}{query_total}++;
        # Log line without duration at all
@@ -12692,6 +12710,7 @@ sub parse_query
                $cur_info{$t_pid}{context} = $prefix_vars{'t_context'};
                $cur_info{$t_pid}{statement} = $prefix_vars{'t_statement'}
        }
+
        &set_current_infos($t_pid);
 
        return 1;
@@ -12876,64 +12895,38 @@ sub set_current_infos
 
        my $t_pid = shift;
 
-       if (!$log_duration) {
-               $cur_info{$t_pid}{year}      = $prefix_vars{'t_year'};
-               $cur_info{$t_pid}{month}     = $prefix_vars{'t_month'};
-               $cur_info{$t_pid}{day}       = $prefix_vars{'t_day'};
-               $cur_info{$t_pid}{hour}      = $prefix_vars{'t_hour'};
-               $cur_info{$t_pid}{min}       = $prefix_vars{'t_min'};
-               $cur_info{$t_pid}{sec}       = $prefix_vars{'t_sec'};
-               $cur_info{$t_pid}{timestamp} = $prefix_vars{'t_timestamp'};
-               $cur_info{$t_pid}{ident}     = $prefix_vars{'t_ident'};
-               $cur_info{$t_pid}{query}     = $prefix_vars{'t_query'};
-               $cur_info{$t_pid}{duration}  = $prefix_vars{'t_duration'};
-               $cur_info{$t_pid}{pid}       = $prefix_vars{'t_pid'};
-               $cur_info{$t_pid}{session}   = $prefix_vars{'t_session_line'};
-               $cur_info{$t_pid}{loglevel}  = $prefix_vars{'t_loglevel'};
-               $cur_info{$t_pid}{dbname}    = $prefix_vars{'t_dbname'};
-               $cur_info{$t_pid}{dbuser}    = $prefix_vars{'t_dbuser'};
-               $cur_info{$t_pid}{dbclient}  = $prefix_vars{'t_client'} ||  $prefix_vars{'t_dbclient'};
-               $cur_info{$t_pid}{dbappname} = $prefix_vars{'t_appname'};
-               $cur_info{$t_pid}{date}      = $prefix_vars{'t_date'};
-               $cur_info{$t_pid}{bind}      = $prefix_vars{'t_bind'};
-
-               # Extract the query part from the plan
-               if (exists $cur_plan_info{$t_pid} && ($cur_plan_info{$t_pid}{plan} ne '')) {
-                       $cur_plan_info{$t_pid}{plan} =~ s/^(?:.*?)\t([^\t]+\(cost=?)/$1/s;
-                       $cur_info{$t_pid}{plan} = $cur_plan_info{$t_pid}{plan};
-                       delete $cur_plan_info{$t_pid};
-               }
-
-       } else {
-               $cur_info{$t_pid}{year}      = $prefix_vars{'t_year'} if (! $cur_info{$t_pid}{year});
-               $cur_info{$t_pid}{month}     = $prefix_vars{'t_month'} if (! $cur_info{$t_pid}{month});
-               $cur_info{$t_pid}{day}       = $prefix_vars{'t_day'} if (! $cur_info{$t_pid}{day});
-               $cur_info{$t_pid}{hour}      = $prefix_vars{'t_hour'} if ($cur_info{$t_pid}{hour} eq '');
-               $cur_info{$t_pid}{min}       = $prefix_vars{'t_min'} if (! $cur_info{$t_pid}{min} eq '');
-               $cur_info{$t_pid}{sec}       = $prefix_vars{'t_sec'} if (! $cur_info{$t_pid}{sec} eq '');
-               $cur_info{$t_pid}{timestamp} = $prefix_vars{'t_timestamp'} if (! $cur_info{$t_pid}{timestamp});
-               $cur_info{$t_pid}{ident}     = $prefix_vars{'t_ident'} if (! $cur_info{$t_pid}{ident});
-               $cur_info{$t_pid}{query}     = $prefix_vars{'t_query'} if (! $cur_info{$t_pid}{query});
-               $cur_info{$t_pid}{duration}  = $prefix_vars{'t_duration'} if (! $cur_info{$t_pid}{duration});
-               $cur_info{$t_pid}{pid}       = $prefix_vars{'t_pid'} if (! $cur_info{$t_pid}{pid});
-               $cur_info{$t_pid}{session}   = $prefix_vars{'t_session_line'} if (! $cur_info{$t_pid}{session});
-               $cur_info{$t_pid}{loglevel}  = $prefix_vars{'t_loglevel'} if (! $cur_info{$t_pid}{loglevel});
-               $cur_info{$t_pid}{dbname}    = $prefix_vars{'t_dbname'} if (! $cur_info{$t_pid}{dbname});
-               $cur_info{$t_pid}{dbuser}    = $prefix_vars{'t_dbuser'} if (! $cur_info{$t_pid}{dbuser});
-               $cur_info{$t_pid}{dbclient}  = $prefix_vars{'t_client'} || $prefix_vars{'t_dbclient'} if (! $cur_info{$t_pid}{dbclient});
-               $cur_info{$t_pid}{dbappname} = $prefix_vars{'t_appname'} if (! $cur_info{$t_pid}{dbappname});
-               $cur_info{$t_pid}{date}      = $prefix_vars{'t_date'} if (! $cur_info{$t_pid}{date});
-               $cur_info{$t_pid}{bind}      = $prefix_vars{'t_bind'} if (! $cur_info{$t_pid}{bind});
-
-               # Extract the query part from the plan
-               if (exists $cur_plan_info{$t_pid} && ($cur_plan_info{$t_pid}{plan} ne '')) {
-                       $cur_plan_info{$t_pid}{plan} =~ s/^\s*Query Text: (.*?);//s;
-                       $cur_info{$t_pid}{plan} = $cur_plan_info{$t_pid}{plan};
-                       delete $cur_plan_info{$t_pid};
-               }
-
+       $cur_info{$t_pid}{year}      = $prefix_vars{'t_year'} if (!$log_duration || !$cur_info{$t_pid}{year});
+       $cur_info{$t_pid}{month}     = $prefix_vars{'t_month'} if (!$log_duration || !$cur_info{$t_pid}{month});
+       $cur_info{$t_pid}{day}       = $prefix_vars{'t_day'} if (!$log_duration || !$cur_info{$t_pid}{day});
+       $cur_info{$t_pid}{hour}      = $prefix_vars{'t_hour'} if (!$log_duration || ($cur_info{$t_pid}{hour} eq ''));
+       $cur_info{$t_pid}{min}       = $prefix_vars{'t_min'} if (!$log_duration || !$cur_info{$t_pid}{min} eq '');
+       $cur_info{$t_pid}{sec}       = $prefix_vars{'t_sec'} if (!$log_duration || !$cur_info{$t_pid}{sec} eq '');
+       $cur_info{$t_pid}{timestamp} = $prefix_vars{'t_timestamp'} if (!$log_duration || !$cur_info{$t_pid}{timestamp});
+       $cur_info{$t_pid}{ident}     = $prefix_vars{'t_ident'} if (!$log_duration || !$cur_info{$t_pid}{ident});
+       $cur_info{$t_pid}{query}     = $prefix_vars{'t_query'} if (!$log_duration || !$cur_info{$t_pid}{query});
+       $cur_info{$t_pid}{duration}  = $prefix_vars{'t_duration'} if (!$log_duration || !$cur_info{$t_pid}{duration});
+       $cur_info{$t_pid}{pid}       = $prefix_vars{'t_pid'} if (!$log_duration || !$cur_info{$t_pid}{pid});
+       $cur_info{$t_pid}{session}   = $prefix_vars{'t_session_line'} if (!$log_duration || !$cur_info{$t_pid}{session});
+       $cur_info{$t_pid}{loglevel}  = $prefix_vars{'t_loglevel'} if (!$log_duration || !$cur_info{$t_pid}{loglevel});
+       $cur_info{$t_pid}{dbname}    = $prefix_vars{'t_dbname'} if (!$log_duration || !$cur_info{$t_pid}{dbname});
+       $cur_info{$t_pid}{dbuser}    = $prefix_vars{'t_dbuser'} if (!$log_duration || !$cur_info{$t_pid}{dbuser});
+       $cur_info{$t_pid}{dbclient}  = $prefix_vars{'t_client'} || $prefix_vars{'t_dbclient'} if (!$log_duration || !$cur_info{$t_pid}{dbclient});
+       $cur_info{$t_pid}{dbappname} = $prefix_vars{'t_appname'} if (!$log_duration || !$cur_info{$t_pid}{dbappname});
+       $cur_info{$t_pid}{date}      = $prefix_vars{'t_date'} if (!$log_duration || !$cur_info{$t_pid}{date});
+       $cur_info{$t_pid}{bind}      = $prefix_vars{'t_bind'} if (!$log_duration || !$cur_info{$t_pid}{bind});
+
+       # Extract the query part from the plan
+       if (exists $cur_plan_info{$t_pid}{plan} && ($cur_plan_info{$t_pid}{plan} ne '')) {
+               my $key = 'query';
+               my @plan = split("\n", $cur_plan_info{$t_pid}{plan});
+               $plan[0] =~ s/^\s*Query Text:\s+//;
+               foreach my $l (@plan) {
+                       $key = 'plan' if ($l =~ /\(cost=\d+.*rows=\d+/);
+                       $cur_info{$t_pid}{$key} .= "$l\n";
+               }
+               $cur_info{$t_pid}{query} =~ s/^\s*Query Text:\s+//s;
+               delete $cur_plan_info{$t_pid};
        }
-
 }
 
 sub store_tsung_session
@@ -12993,7 +12986,8 @@ sub store_queries
        my $end  = shift;
 
        # With separate log_duration and log_statement wait duration before storing the entry
-       return 0 if (!$end && $log_duration && ($cur_info{$t_pid}{duration} eq '') && ($cur_info{$t_pid}{log_level} eq 'LOG'));
+       return 0 if (!$end && $log_duration && ($cur_info{$t_pid}{duration} eq '')
+                                       && ($cur_info{$t_pid}{log_level} eq 'LOG'));
 
        # Remove comments if required
        if ($remove_comment) {
@@ -13005,9 +12999,11 @@ sub store_queries
                $cur_info{$t_pid}{query} = &anonymize_query($cur_info{$t_pid}{query});
        }
 
+#print STDERR "ZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZZ ", %{$cur_info{$t_pid}}, "\n";
        return 0 if (!exists $cur_info{$t_pid});
        return 1 if (!$cur_info{$t_pid}{year});
 
+
        # Cleanup and normalize the current query
        $cur_info{$t_pid}{query} =~ s/^\s+//s;
        $cur_info{$t_pid}{query} =~ s/[\s;]+$//s;