From: Darold Gilles <gilles@darold.net>
Date: Sat, 26 Nov 2016 10:05:24 +0000 (+0100)
Subject: Fix report of auto_explain output. Thanks to fch77700 for the report.
X-Git-Tag: v9.1~20^2
X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=a0e3cc23e8c1f1f52f9e6d2d2ccce65ea5f9f4b7;p=pgbadger

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

diff --git a/pgbadger b/pgbadger
index 2dc0c31..ac9ef80 100644
--- 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;