[igt-dev] [PATCH i-g-t v2 3/4] scripts/trace.pl: Calculate stats only after all munging

[Tvrtko Ursulin]

On 23/01/2018 06:32, John.C.Harrison at Intel.com wrote:
> From: John Harrison <John.C.Harrison at Intel.com>
> 
> There are various statistics being calculated multiple times in
> multiple places while the log file is being read in. Some of these are
> then re-calculated when the database is munged to correct various
> issues with the logs. This patch consolidates the calculations into a
> separate pass after all the reading and munging has been done.
> 
> Note that this actually produces a different final output as the
> 'execute-delay' values were not previously being re-calculated after
> all the fixups. Thus were based on an incorrect calculation.
> 
> v2: Reduce scope of some local variables [Tvrtko]
> 
> Signed-off-by: John Harrison <John.C.Harrison at intel.com>
> Cc: Tvrtko Ursulin <tvrtko.ursulin at intel.com>
> ---
>   scripts/trace.pl | 54 ++++++++++++++++++++++++++++--------------------------
>   1 file changed, 28 insertions(+), 26 deletions(-)
> 
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index b528d482..c984cef6 100755
> --- a/scripts/trace.pl
> +++ b/scripts/trace.pl
> @@ -437,8 +437,7 @@ while (<>) {
>   		$req{'global'} = $tp{'global'};
>   		$req{'port'} = $tp{'port'};
>   		$req{'queue'} = $queue{$key};
> -		$req{'submit-delay'} = $submit{$key} - $queue{$key};
> -		$req{'execute-delay'} = $req{'start'} - $submit{$key};
> +		$req{'submit'} = $submit{$key};
>   		$rings{$ring} = $gid++ unless exists $rings{$ring};
>   		$ringmap{$rings{$ring}} = $ring;
>   		$db{$key} = \%req;
> @@ -458,8 +457,6 @@ while (<>) {
>   			$db{$key}->{'notify'} = $db{$key}->{'end'};
>   			$db{$key}->{'no-notify'} = 1;
>   		}
> -		$db{$key}->{'duration'} = $db{$key}->{'notify'} - $db{$key}->{'start'};
> -		$db{$key}->{'context-complete-delay'} = $db{$key}->{'end'} - $db{$key}->{'notify'};
>   	} elsif ($tp_name eq 'i915:intel_engine_notify:') {
>   		$notify{global_key($ring, $seqno)} = $time;
>   	} elsif ($tp_name eq 'i915:intel_gpu_freq_change:') {
> @@ -493,16 +490,11 @@ foreach my $key (keys %db) {
>   			$db{$key}->{'notify'} = $db{$key}->{'end'};
>   			$db{$key}->{'incomplete'} = 1;
>   		}
> -
> -		$db{$key}->{'duration'} = $db{$key}->{'notify'} - $db{$key}->{'start'};
> -		$db{$key}->{'context-complete-delay'} = $db{$key}->{'end'} - $db{$key}->{'notify'};
>   	} else {
>   		# Notify arrived after context complete.
>   		if (exists $db{$key}->{'no-notify'} and exists $notify{$gkey}) {
>   			delete $db{$key}->{'no-notify'};
>   			$db{$key}->{'notify'} = $notify{$gkey};
> -			$db{$key}->{'duration'} = $db{$key}->{'notify'} - $db{$key}->{'start'};
> -			$db{$key}->{'context-complete-delay'} = $db{$key}->{'end'} - $db{$key}->{'notify'};
>   		}
>   	}
>   }
> @@ -528,8 +520,6 @@ foreach my $key (keys(%db)) {
>   	if (exists $db{$next_key}) {
>   		$db{$key}->{'notify'} = $db{$next_key}->{'end'};
>   		$db{$key}->{'end'} = $db{$key}->{'notify'};
> -		$db{$key}->{'duration'} = $db{$key}->{'notify'} - $db{$key}->{'start'};
> -		$db{$key}->{'context-complete-delay'} = $db{$key}->{'end'} - $db{$key}->{'notify'};
>   	}
>   }
>   
> @@ -572,17 +562,11 @@ foreach my $key (@sorted_keys) {
>   	$first_ts = $db{$key}->{'queue'} if not defined $first_ts or $db{$key}->{'queue'} < $first_ts;
>   	$last_ts = $end if $end > $last_ts;
>   
> -	$running{$ring} += $end - $db{$key}->{'start'} unless exists $db{$key}->{'no-end'};
> -	$runnable{$ring} += $db{$key}->{'execute-delay'};
> -	$queued{$ring} += $db{$key}->{'start'} - $db{$key}->{'execute-delay'} - $db{$key}->{'queue'};
> -
> -	$batch_count{$ring}++;
> -
>   	# correct duration of merged batches
>   	if ($correct_durations and exists $db{$key}->{'no-end'}) {
> -		my $start = $db{$key}->{'start'};
>   		my $ctx = $db{$key}->{'ctx'};
>   		my $seqno = $db{$key}->{'seqno'};
> +		my $start = $db{$key}->{'start'};
>   		my $next_key;
>   		my $i = 1;
>   
> @@ -593,25 +577,43 @@ foreach my $key (@sorted_keys) {
>   
>   		# 20us tolerance
>   		if (exists $db{$next_key} and $db{$next_key}->{'start'} < $start + 20) {
> +			my $notify = $db{$key}->{'notify'};
>   			$re_sort = 1;
> -			$db{$next_key}->{'start'} = $start + $db{$key}->{'duration'};
> +			$db{$next_key}->{'start'} = $notify;
>   			$db{$next_key}->{'start'} = $db{$next_key}->{'end'} if $db{$next_key}->{'start'} > $db{$next_key}->{'end'};
> -			$db{$next_key}->{'duration'} = $db{$next_key}->{'notify'} - $db{$next_key}->{'start'};
> -			$end = $db{$key}->{'notify'};
>   			die if $db{$next_key}->{'start'} > $db{$next_key}->{'end'};
>   		}

There is something going wrong with processing, well untangling, of 
merged batches after your changes. At least one trace shows a completely 
bad decision here, where a fully known batch gets adjusted needlessly 
and in a wrong way. I have to study this in more detail so merging the 
series will have to wait.

Regards,

Tvrtko


> -		die if $db{$key}->{'start'} > $db{$key}->{'end'};
> +		die if $start > $end;
>   	}
> +}
> +
> + at sorted_keys = sort sortStart keys %db if $re_sort;
> +
> +foreach my $key (@sorted_keys) {
> +	my $ring = $db{$key}->{'ring'};
> +	my $end = $db{$key}->{'end'};
> +	my $start = $db{$key}->{'start'};
> +	my $notify = $db{$key}->{'notify'};
> +
> +	$db{$key}->{'context-complete-delay'} = $end - $notify;
> +	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
> +	$db{$key}->{'submit-delay'} = $db{$key}->{'submit'} - $db{$key}->{'queue'};
> +	$db{$key}->{'duration'} = $notify - $start;
> +
> +	$running{$ring} += $end - $start unless exists $db{$key}->{'no-end'};
> +	$runnable{$ring} += $db{$key}->{'execute-delay'};
> +	$queued{$ring} += $start - $db{$key}->{'execute-delay'} - $db{$key}->{'queue'};
> +
> +	$batch_count{$ring}++;
> +
>   	$batch_avg{$ring} += $db{$key}->{'duration'};
> -	$batch_total_avg{$ring} += $end - $db{$key}->{'start'};
> +	$batch_total_avg{$ring} += $end - $start;
>   
>   	$submit_avg{$ring} += $db{$key}->{'submit-delay'};
>   	$execute_avg{$ring} += $db{$key}->{'execute-delay'};
> -	$ctxsave_avg{$ring} += $db{$key}->{'end'} - $db{$key}->{'notify'};
> +	$ctxsave_avg{$ring} += $end - $notify;
>   }
>   
> - at sorted_keys = sort sortStart keys %db if $re_sort;
> -
>   foreach my $ring (sort keys %batch_avg) {
>   	$batch_avg{$ring} /= $batch_count{$ring};
>   	$batch_total_avg{$ring} /= $batch_count{$ring};
>