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

[Tvrtko Ursulin]

On 20/01/2018 00:24, 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.
> 
> 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 cf841b7e..c5d822aa 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};

You only use the submit key to look up things two times, so you could 
use the %submit hash directly to save some lookups, but on the other 
hand maybe you were going for nicer split between data structures over 
performance.

When I look at it again, I was using the same approach for 'queue' when 
%queue was also available so never mind.. maybe an optimisation 
opportunity with both for later, if would be worth it.

>   		$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'};
>   		}
>   	}
>   }
> @@ -529,8 +521,6 @@ foreach my $key (@keys) {
>   	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'};
>   	}
>   }
>   
> @@ -565,19 +555,14 @@ die "Database changed size?!" unless scalar(@sorted_keys) == $keyCount;
>   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'};

Why did you move/put these two here since they are not used outside the 
$correct_durations block? I'd avoid hash queries if not needed.

>   
>   	$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 $next_key;
> @@ -591,24 +576,41 @@ foreach my $key (@sorted_keys) {
>   		# 20us tolerance
>   		if (exists $db{$next_key} and $db{$next_key}->{'start'} < $start + 20) {
>   			$re_sort = 1;
> -			$db{$next_key}->{'start'} = $start + $db{$key}->{'duration'};
> +			$db{$next_key}->{'start'} = $notify;

Makes sense, mine was silly!

>   			$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'};
>   		}
> -		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};
> 

A great improvement! I didn't spot that you've changed anything which 
would break the flow.

I'd move those two locals in the if block, but otherwise:

Reviewed-by: Tvrtko Ursulin <tvrtko.ursulin at intel.com>

Regards,

Tvrtko