[i-g-t] scripts/trace.pl: Update for preempt-to-busy, heartbeats and timeslicing
diff mbox series

Message ID 20200117184924.12600-1-tvrtko.ursulin@linux.intel.com
State New
Headers show
Series
  • [i-g-t] scripts/trace.pl: Update for preempt-to-busy, heartbeats and timeslicing
Related show

Commit Message

Tvrtko Ursulin Jan. 17, 2020, 6:49 p.m. UTC
From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

...

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: Tony Ye <tony.ye@intel.com>
---
Tony could you please check if this works for you and even send me some
raw trace files you might have so I see how it looks?

P.S.
I don't yet guarantee the results are 100% reliable and truthful. Or that
it won't crash.
---
 scripts/trace.pl | 283 +++++++++++++++++++++++++----------------------
 1 file changed, 151 insertions(+), 132 deletions(-)

Comments

Ye, Tony Jan. 17, 2020, 8:58 p.m. UTC | #1
Failed on parsing the trace log:
	Died at ./trace.pl line 296.
Raw data attached.

Regards,
Tony
On 1/17/2020 10:49 AM, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> 
> ...
> 
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> Cc: Tony Ye <tony.ye@intel.com>
> ---
> Tony could you please check if this works for you and even send me some
> raw trace files you might have so I see how it looks?
> 
> P.S.
> I don't yet guarantee the results are 100% reliable and truthful. Or that
> it won't crash.
> ---
>   scripts/trace.pl | 283 +++++++++++++++++++++++++----------------------
>   1 file changed, 151 insertions(+), 132 deletions(-)
> 
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index 77587f24197a..8cad7e6ef65b 100755
> --- a/scripts/trace.pl
> +++ b/scripts/trace.pl
> @@ -34,11 +34,10 @@ my $cid = 0;
>   my %queues;
>   my @freqs;
>   
> -use constant VENG => '255:254';
> +use constant VENG => '65534:65534';
>   
>   my $max_requests = 1000;
>   my $width_us = 32000;
> -my $correct_durations = 0;
>   my %ignore_ring;
>   my %skip_box;
>   my $html = 0;
> @@ -224,18 +223,6 @@ sub arg_zoom_width
>   	return @_;
>   }
>   
> -sub arg_split_requests
> -{
> -	return unless scalar(@_);
> -
> -	if ($_[0] eq '--split-requests' or $_[0] eq '-s') {
> -		shift @_;
> -		$correct_durations = 1;
> -	}
> -
> -	return @_;
> -}
> -
>   sub arg_ignore_ring
>   {
>   	my $val;
> @@ -299,7 +286,6 @@ while (@args) {
>   	@args = arg_trace(@args);
>   	@args = arg_max_requests(@args);
>   	@args = arg_zoom_width(@args);
> -	@args = arg_split_requests(@args);
>   	@args = arg_ignore_ring(@args);
>   	@args = arg_skip_box(@args);
>   	@args = arg_colour_contexts(@args);
> @@ -340,7 +326,79 @@ sub is_veng
>   {
>   	my ($class, $instance) = split ':', shift;
>   
> -	return $instance eq '254';
> +	return 1 if $instance eq '254' or $instance eq '65534';
> +}
> +
> +my (%port_keys, %port_times);
> +
> +sub port_in
> +{
> +	my ($ring, $port, $key, $time) = @_;
> +	my ($port_key, $port_time);
> +	my @slices;
> +
> +	$db{$key}->{'slices'} = \@slices
> +				unless exists $db{$key}->{'slices'};
> +
> +	$db{$key}->{'in'}++;
> +
> +	unless (exists $port_keys{$ring}) {
> +		my (@keys, @times);
> +
> +		$port_keys{$ring} = \@keys;
> +		$port_times{$ring} = \@times;
> +	}
> +
> +	$port_key = $port_keys{$ring};
> +	$port_time = $port_times{$ring};
> +
> +	unless (defined $port_key->[$port] and $port_key->[$port] eq $key) {
> +		$port_key->[$port] = $key;
> +		$port_time->[$port] = $time;
> +	}
> +}
> +
> +sub port_out
> +{
> +	my ($ring, $key, $time) = @_;
> +	my ($port_key, $port_time);
> +	my $port;
> +
> +	die unless $db{$key}->{'in'};
> +	$db{$key}->{'in'}--;
> +
> +	$port_key = $port_keys{$ring};
> +	$port_time = $port_times{$ring};
> +
> +	for (my $i = 0; $i < scalar(@{$port_key}); $i++) {
> +		next unless defined $port_key->[$i];
> +
> +		if ($port_key->[$i] eq $key) {
> +			$port = $i;
> +			last;
> +		}
> +	}
> +
> +	return unless defined $port;
> +
> +	if ($port == 0) {
> +		my $s = $db{$key}->{'slices'};
> +		my $next;
> +
> +		push @{$s}, [$port_time->[$port], $time];
> +
> +		$next = $port + 1;
> +		if (defined $port_key->[$next]) {
> +			$port_time->[$next] = $time;
> +			shift @{$port_key};
> +			shift @{$port_time};
> +		}
> +	}
> +
> +	if ($db{$key}->{'in'} == 0) {
> +		$port_key->[$port] = undef;
> +		$port_time->[$port] = undef;
> +	}
>   }
>   
>   # Main input loop - parse lines and build the internal representation of the
> @@ -368,7 +426,6 @@ while (<>) {
>   
>   		next unless $f =~ m/=/;
>   		($k, $v) = ($`, $');
> -		$k = 'global' if $k eq 'global_seqno';
>   		chop $v if substr($v, -1, 1) eq ',';
>   		$tp{$k} = $v;
>   
> @@ -433,76 +490,89 @@ while (<>) {
>   		}
>   	} elsif ($tp_name eq 'i915:i915_request_submit:') {
>   		die if exists $submit{$key};
> -		die unless exists $queue{$key};
> +		unless (exists $queue{$key}) { # i915 internal
> +			$queue{$key} = $time;
> +			$ctxdb{$orig_ctx} = 1;
> +		}
>   		die if $ring eq VENG and not exists $queues{$ctx};
>   
>   		$submit{$key} = $time;
>   	} elsif ($tp_name eq 'i915:i915_request_in:') {
> +		my $port = $tp{'port'};
>   		my ($q, $s);
>   		my %req;
>   
> -		# preemption
> -		delete $db{$key} if exists $db{$key};
> -
>   		unless (exists $queue{$key}) {
>   			# Virtual engine
>   			my $vkey = db_key(VENG, $ctx, $seqno);
>   			my %req;
>   
>   			die unless exists $queues{$ctx};
> -			die unless exists $queue{$vkey};
>   			die unless exists $submit{$vkey};
>   
> -			# Create separate request record on the queue timeline
>   			$q = $queue{$vkey};
>   			$s = $submit{$vkey};
> -			$req{'queue'} = $q;
> -			$req{'submit'} = $s;
> +
> +			unless (exists $vdb{$vkey}) {
> +				# Create separate request record on the queue
> +				# timeline.
> +				$req{'queue'} = $q;
> +				$req{'submit'} = $s;
> +				$req{'start'} = $time;
> +				$req{'end'} = $time;
> +				$req{'ring'} = VENG;
> +				$req{'phys-engine'} = $ring;
> +				$req{'seqno'} = $seqno;
> +				$req{'ctx'} = $ctx;
> +				$req{'name'} = $ctx . '/' . $seqno;
> +				$req{'port'} = $port;
> +
> +				$vdb{$vkey} = \%req;
> +			}
> +		} else {
> +			$q = $queue{$key};
> +			$s = $submit{$key};
> +		}
> +
> +		unless (exists $db{$key}) {
>   			$req{'start'} = $time;
> -			$req{'end'} = $time;
> -			$req{'ring'} = VENG;
> +			$req{'ring'} = $ring;
>   			$req{'seqno'} = $seqno;
>   			$req{'ctx'} = $ctx;
> +			$ctxtimelines{$ctx . '/' . $ring} = 1;
>   			$req{'name'} = $ctx . '/' . $seqno;
> -			$req{'global'} = $tp{'global'};
> -			$req{'port'} = $tp{'port'};
> +			$req{'port'} = $port;
> +			$req{'queue'} = $q;
> +			$req{'submit'} = $s;
> +			$req{'virtual'} = 1 if exists $queues{$ctx};
> +			$rings{$ring} = $gid++ unless exists $rings{$ring};
> +			$ringmap{$rings{$ring}} = $ring;
> +			$db{$key} = \%req;
>   
> -			$vdb{$vkey} = \%req;
> -		} else {
> -			$q = $queue{$key};
> -			$s = $submit{$key};
>   		}
>   
> -		$req{'start'} = $time;
> -		$req{'ring'} = $ring;
> -		$req{'seqno'} = $seqno;
> -		$req{'ctx'} = $ctx;
> -		$ctxtimelines{$ctx . '/' . $ring} = 1;
> -		$req{'name'} = $ctx . '/' . $seqno;
> -		$req{'global'} = $tp{'global'};
> -		$req{'port'} = $tp{'port'};
> -		$req{'queue'} = $q;
> -		$req{'submit'} = $s;
> -		$req{'virtual'} = 1 if exists $queues{$ctx};
> -		$rings{$ring} = $gid++ unless exists $rings{$ring};
> -		$ringmap{$rings{$ring}} = $ring;
> -		$db{$key} = \%req;
> +		port_in($ring, $port, $key, $time);
>   	} elsif ($tp_name eq 'i915:i915_request_out:') {
> -		if ($tp{'completed?'}) {
> -			my $nkey;
> +		my ($nkey, $completed, $prev_in);
>   
> -			die unless exists $db{$key};
> -			die unless exists $db{$key}->{'start'};
> -			die if exists $db{$key}->{'end'};
> -
> -			$nkey = notify_key($ctx, $seqno);
> +		if ($ring eq VENG and not exists $db{$key}) {
> +			my $vkey = db_key(VENG, $ctx, $seqno);
>   
> -			$db{$key}->{'end'} = $time;
> -			$db{$key}->{'notify'} = $notify{$nkey}
> -						if exists $notify{$nkey};
> -		} else {
> -			delete $db{$key};
> +			$ring = $vdb{$vkey}->{'phys-engine'};
> +			$key = db_key($ring, $ctx, $seqno);
>   		}
> +
> +		die unless exists $db{$key};
> +		die unless exists $db{$key}->{'start'};
> +
> +		$nkey = notify_key($ctx, $seqno);
> +
> +		port_out($ring, $key, $time);
> +
> +		$db{$key}->{'notify'} = $notify{$nkey}
> +					if exists $notify{$nkey};
> +		$db{$key}->{'end'} = $time;
> +		$db{$key}->{'completed'} = $tp{'completed?'};
>   	} elsif ($tp_name eq 'dma_fence:dma_fence_signaled:') {
>   		my $nkey;
>   
> @@ -561,6 +631,18 @@ sub sortStart {
>   	return $val;
>   }
>   
> +sub sortEnd {
> +	my $as = $db{$a}->{'end'};
> +	my $bs = $db{$b}->{'end'};
> +	my $val;
> +
> +say $a unless defined $as;
> +	$val = $as <=> $bs;
> +	$val = $a cmp $b if $val == 0;
> +
> +	return $val;
> +}
> +
>   sub get_engine_timeline {
>   	my ($ring) = @_;
>   	my @timeline;
> @@ -568,7 +650,7 @@ sub get_engine_timeline {
>   	return $engine_timelines{$ring} if exists $engine_timelines{$ring};
>   
>   	@timeline = grep { $db{$_}->{'ring'} eq $ring } keys %db;
> -	@timeline = sort sortStart @timeline;
> +	@timeline = sort sortEnd @timeline;
>   	$engine_timelines{$ring} = \@timeline;
>   
>   	return \@timeline;
> @@ -679,73 +761,6 @@ sub get_ctx_timeline {
>   	return \@timeline;
>   }
>   
> -# Split out merged batches if requested.
> -if ($correct_durations) {
> -	# Shift !port0 requests start time to after the previous context on the
> -	# same timeline has finished.
> -	foreach my $gid (sort keys %rings) {
> -		my $ring = $ringmap{$rings{$gid}};
> -		my $timeline = get_engine_timeline($ring);
> -		my $complete;
> -
> -		foreach my $pos (0..$#{$timeline}) {
> -			my $key = @{$timeline}[$pos];
> -			my $prev = $complete;
> -			my $pkey;
> -
> -			$complete = $key unless exists $db{$key}->{'no-end'};
> -			$pkey = $complete;
> -
> -			next if $db{$key}->{'port'} == 0;
> -
> -			$pkey = $prev if $complete eq $key;
> -
> -			die unless defined $pkey;
> -
> -			$db{$key}->{'start'} = $db{$pkey}->{'end'};
> -			$db{$key}->{'start'} = $db{$pkey}->{'notify'} if $db{$key}->{'start'} > $db{$key}->{'end'};
> -
> -			die if $db{$key}->{'start'} > $db{$key}->{'end'};
> -
> -			$re_sort = 1;
> -		}
> -	}
> -
> -	maybe_sort_keys();
> -
> -	# Batch with no-end (no request_out) means it was submitted as part of
> -	# coalesced context. This means it's start time should be set to the end
> -	# time of a following request on this context timeline.
> -	foreach my $tkey (sort keys %ctxtimelines) {
> -		my ($ctx, $ring) = split '/', $tkey;
> -		my $timeline = get_ctx_timeline($ctx, $ring, $tkey);
> -		my $last_complete = -1;
> -		my $complete;
> -
> -		foreach my $pos (0..$#{$timeline}) {
> -			my $key = @{$timeline}[$pos];
> -			my $next_key;
> -
> -			next unless exists $db{$key}->{'no-end'};
> -			last if $pos == $#{$timeline};
> -
> -			# Shift following request to start after the current
> -			# one, but only if that wouldn't make it zero duration,
> -			# which would indicate notify arrived after context
> -			# complete.
> -			$next_key = ${$timeline}[$pos + 1];
> -			if (exists $db{$key}->{'notify'} and
> -			    $db{$key}->{'notify'} < $db{$key}->{'end'}) {
> -				$db{$next_key}->{'engine-start'} = $db{$next_key}->{'start'};
> -				$db{$next_key}->{'start'} = $db{$key}->{'notify'};
> -				$re_sort = 1;
> -			}
> -		}
> -	}
> -}
> -
> -maybe_sort_keys();
> -
>   # GPU time accounting
>   my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
>   my (%submit_avg, %execute_avg, %ctxsave_avg);
> @@ -781,8 +796,7 @@ foreach my $key (@sorted_keys) {
>   		$db{$key}->{'duration'} = 0;
>   	}
>   
> -	$running{$ring} += $end - $start if $correct_durations or
> -					    not exists $db{$key}->{'no-end'};
> +	$running{$ring} += $end - $start if not exists $db{$key}->{'no-end'};
>   	unless (exists $db{$key}->{'virtual'}) {
>   		$runnable{$ring} += $db{$key}->{'execute-delay'};
>   		$queued{$ring} += $start - $db{$key}->{'execute-delay'} - $db{$key}->{'queue'};
> @@ -1324,9 +1338,14 @@ foreach my $key (sort sortQueue keys %db) {
>   		$content .= ' <small><i>++</i></small> ' if exists $db{$key}->{'no-end'};
>   		$content .= ' <small><i>+</i></small> ' if exists $db{$key}->{'no-notify'};
>   		$content .= "<br>$db{$key}->{'duration'}us <small>($db{$key}->{'context-complete-delay'}us)</small>";
> -		$startend = 'start: ' . $start . ', end: ' . $notify;
> -		print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n";
> -		$i++;
> +		foreach my $slice (@{$db{$key}->{'slices'}}) {
> +			my ($s, $e) = ($start, $notify);
> +			$s = @{$slice}[0] if @{$slice}[0] >= $start;
> +			$e = @{$slice}[1] if @{$slice}[1] <= $notify;
> +			$startend = 'start: ' . $s . ', end: ' . $e;
> +			print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n";
> +			$i++;
> +		}
>   	}
>   
>   	# user interrupt to context complete
>
Ye, Tony Jan. 17, 2020, 9:08 p.m. UTC | #2
Failed on parsing the trace log:
     Died at ./trace.pl line 296.

Regards,
Tony

On 1/17/2020 10:49 AM, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> 
> ...
> 
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> Cc: Tony Ye <tony.ye@intel.com>
> ---
> Tony could you please check if this works for you and even send me some
> raw trace files you might have so I see how it looks?
> 
> P.S.
> I don't yet guarantee the results are 100% reliable and truthful. Or that
> it won't crash.
> ---
>   scripts/trace.pl | 283 +++++++++++++++++++++++++----------------------
>   1 file changed, 151 insertions(+), 132 deletions(-)
> 
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index 77587f24197a..8cad7e6ef65b 100755
> --- a/scripts/trace.pl
> +++ b/scripts/trace.pl
> @@ -34,11 +34,10 @@ my $cid = 0;
>   my %queues;
>   my @freqs;
>   
> -use constant VENG => '255:254';
> +use constant VENG => '65534:65534';
>   
>   my $max_requests = 1000;
>   my $width_us = 32000;
> -my $correct_durations = 0;
>   my %ignore_ring;
>   my %skip_box;
>   my $html = 0;
> @@ -224,18 +223,6 @@ sub arg_zoom_width
>   	return @_;
>   }
>   
> -sub arg_split_requests
> -{
> -	return unless scalar(@_);
> -
> -	if ($_[0] eq '--split-requests' or $_[0] eq '-s') {
> -		shift @_;
> -		$correct_durations = 1;
> -	}
> -
> -	return @_;
> -}
> -
>   sub arg_ignore_ring
>   {
>   	my $val;
> @@ -299,7 +286,6 @@ while (@args) {
>   	@args = arg_trace(@args);
>   	@args = arg_max_requests(@args);
>   	@args = arg_zoom_width(@args);
> -	@args = arg_split_requests(@args);
>   	@args = arg_ignore_ring(@args);
>   	@args = arg_skip_box(@args);
>   	@args = arg_colour_contexts(@args);
> @@ -340,7 +326,79 @@ sub is_veng
>   {
>   	my ($class, $instance) = split ':', shift;
>   
> -	return $instance eq '254';
> +	return 1 if $instance eq '254' or $instance eq '65534';
> +}
> +
> +my (%port_keys, %port_times);
> +
> +sub port_in
> +{
> +	my ($ring, $port, $key, $time) = @_;
> +	my ($port_key, $port_time);
> +	my @slices;
> +
> +	$db{$key}->{'slices'} = \@slices
> +				unless exists $db{$key}->{'slices'};
> +
> +	$db{$key}->{'in'}++;
> +
> +	unless (exists $port_keys{$ring}) {
> +		my (@keys, @times);
> +
> +		$port_keys{$ring} = \@keys;
> +		$port_times{$ring} = \@times;
> +	}
> +
> +	$port_key = $port_keys{$ring};
> +	$port_time = $port_times{$ring};
> +
> +	unless (defined $port_key->[$port] and $port_key->[$port] eq $key) {
> +		$port_key->[$port] = $key;
> +		$port_time->[$port] = $time;
> +	}
> +}
> +
> +sub port_out
> +{
> +	my ($ring, $key, $time) = @_;
> +	my ($port_key, $port_time);
> +	my $port;
> +
> +	die unless $db{$key}->{'in'};
> +	$db{$key}->{'in'}--;
> +
> +	$port_key = $port_keys{$ring};
> +	$port_time = $port_times{$ring};
> +
> +	for (my $i = 0; $i < scalar(@{$port_key}); $i++) {
> +		next unless defined $port_key->[$i];
> +
> +		if ($port_key->[$i] eq $key) {
> +			$port = $i;
> +			last;
> +		}
> +	}
> +
> +	return unless defined $port;
> +
> +	if ($port == 0) {
> +		my $s = $db{$key}->{'slices'};
> +		my $next;
> +
> +		push @{$s}, [$port_time->[$port], $time];
> +
> +		$next = $port + 1;
> +		if (defined $port_key->[$next]) {
> +			$port_time->[$next] = $time;
> +			shift @{$port_key};
> +			shift @{$port_time};
> +		}
> +	}
> +
> +	if ($db{$key}->{'in'} == 0) {
> +		$port_key->[$port] = undef;
> +		$port_time->[$port] = undef;
> +	}
>   }
>   
>   # Main input loop - parse lines and build the internal representation of the
> @@ -368,7 +426,6 @@ while (<>) {
>   
>   		next unless $f =~ m/=/;
>   		($k, $v) = ($`, $');
> -		$k = 'global' if $k eq 'global_seqno';
>   		chop $v if substr($v, -1, 1) eq ',';
>   		$tp{$k} = $v;
>   
> @@ -433,76 +490,89 @@ while (<>) {
>   		}
>   	} elsif ($tp_name eq 'i915:i915_request_submit:') {
>   		die if exists $submit{$key};
> -		die unless exists $queue{$key};
> +		unless (exists $queue{$key}) { # i915 internal
> +			$queue{$key} = $time;
> +			$ctxdb{$orig_ctx} = 1;
> +		}
>   		die if $ring eq VENG and not exists $queues{$ctx};
>   
>   		$submit{$key} = $time;
>   	} elsif ($tp_name eq 'i915:i915_request_in:') {
> +		my $port = $tp{'port'};
>   		my ($q, $s);
>   		my %req;
>   
> -		# preemption
> -		delete $db{$key} if exists $db{$key};
> -
>   		unless (exists $queue{$key}) {
>   			# Virtual engine
>   			my $vkey = db_key(VENG, $ctx, $seqno);
>   			my %req;
>   
>   			die unless exists $queues{$ctx};
> -			die unless exists $queue{$vkey};
>   			die unless exists $submit{$vkey};
>   
> -			# Create separate request record on the queue timeline
>   			$q = $queue{$vkey};
>   			$s = $submit{$vkey};
> -			$req{'queue'} = $q;
> -			$req{'submit'} = $s;
> +
> +			unless (exists $vdb{$vkey}) {
> +				# Create separate request record on the queue
> +				# timeline.
> +				$req{'queue'} = $q;
> +				$req{'submit'} = $s;
> +				$req{'start'} = $time;
> +				$req{'end'} = $time;
> +				$req{'ring'} = VENG;
> +				$req{'phys-engine'} = $ring;
> +				$req{'seqno'} = $seqno;
> +				$req{'ctx'} = $ctx;
> +				$req{'name'} = $ctx . '/' . $seqno;
> +				$req{'port'} = $port;
> +
> +				$vdb{$vkey} = \%req;
> +			}
> +		} else {
> +			$q = $queue{$key};
> +			$s = $submit{$key};
> +		}
> +
> +		unless (exists $db{$key}) {
>   			$req{'start'} = $time;
> -			$req{'end'} = $time;
> -			$req{'ring'} = VENG;
> +			$req{'ring'} = $ring;
>   			$req{'seqno'} = $seqno;
>   			$req{'ctx'} = $ctx;
> +			$ctxtimelines{$ctx . '/' . $ring} = 1;
>   			$req{'name'} = $ctx . '/' . $seqno;
> -			$req{'global'} = $tp{'global'};
> -			$req{'port'} = $tp{'port'};
> +			$req{'port'} = $port;
> +			$req{'queue'} = $q;
> +			$req{'submit'} = $s;
> +			$req{'virtual'} = 1 if exists $queues{$ctx};
> +			$rings{$ring} = $gid++ unless exists $rings{$ring};
> +			$ringmap{$rings{$ring}} = $ring;
> +			$db{$key} = \%req;
>   
> -			$vdb{$vkey} = \%req;
> -		} else {
> -			$q = $queue{$key};
> -			$s = $submit{$key};
>   		}
>   
> -		$req{'start'} = $time;
> -		$req{'ring'} = $ring;
> -		$req{'seqno'} = $seqno;
> -		$req{'ctx'} = $ctx;
> -		$ctxtimelines{$ctx . '/' . $ring} = 1;
> -		$req{'name'} = $ctx . '/' . $seqno;
> -		$req{'global'} = $tp{'global'};
> -		$req{'port'} = $tp{'port'};
> -		$req{'queue'} = $q;
> -		$req{'submit'} = $s;
> -		$req{'virtual'} = 1 if exists $queues{$ctx};
> -		$rings{$ring} = $gid++ unless exists $rings{$ring};
> -		$ringmap{$rings{$ring}} = $ring;
> -		$db{$key} = \%req;
> +		port_in($ring, $port, $key, $time);
>   	} elsif ($tp_name eq 'i915:i915_request_out:') {
> -		if ($tp{'completed?'}) {
> -			my $nkey;
> +		my ($nkey, $completed, $prev_in);
>   
> -			die unless exists $db{$key};
> -			die unless exists $db{$key}->{'start'};
> -			die if exists $db{$key}->{'end'};
> -
> -			$nkey = notify_key($ctx, $seqno);
> +		if ($ring eq VENG and not exists $db{$key}) {
> +			my $vkey = db_key(VENG, $ctx, $seqno);
>   
> -			$db{$key}->{'end'} = $time;
> -			$db{$key}->{'notify'} = $notify{$nkey}
> -						if exists $notify{$nkey};
> -		} else {
> -			delete $db{$key};
> +			$ring = $vdb{$vkey}->{'phys-engine'};
> +			$key = db_key($ring, $ctx, $seqno);
>   		}
> +
> +		die unless exists $db{$key};
> +		die unless exists $db{$key}->{'start'};
> +
> +		$nkey = notify_key($ctx, $seqno);
> +
> +		port_out($ring, $key, $time);
> +
> +		$db{$key}->{'notify'} = $notify{$nkey}
> +					if exists $notify{$nkey};
> +		$db{$key}->{'end'} = $time;
> +		$db{$key}->{'completed'} = $tp{'completed?'};
>   	} elsif ($tp_name eq 'dma_fence:dma_fence_signaled:') {
>   		my $nkey;
>   
> @@ -561,6 +631,18 @@ sub sortStart {
>   	return $val;
>   }
>   
> +sub sortEnd {
> +	my $as = $db{$a}->{'end'};
> +	my $bs = $db{$b}->{'end'};
> +	my $val;
> +
> +say $a unless defined $as;
> +	$val = $as <=> $bs;
> +	$val = $a cmp $b if $val == 0;
> +
> +	return $val;
> +}
> +
>   sub get_engine_timeline {
>   	my ($ring) = @_;
>   	my @timeline;
> @@ -568,7 +650,7 @@ sub get_engine_timeline {
>   	return $engine_timelines{$ring} if exists $engine_timelines{$ring};
>   
>   	@timeline = grep { $db{$_}->{'ring'} eq $ring } keys %db;
> -	@timeline = sort sortStart @timeline;
> +	@timeline = sort sortEnd @timeline;
>   	$engine_timelines{$ring} = \@timeline;
>   
>   	return \@timeline;
> @@ -679,73 +761,6 @@ sub get_ctx_timeline {
>   	return \@timeline;
>   }
>   
> -# Split out merged batches if requested.
> -if ($correct_durations) {
> -	# Shift !port0 requests start time to after the previous context on the
> -	# same timeline has finished.
> -	foreach my $gid (sort keys %rings) {
> -		my $ring = $ringmap{$rings{$gid}};
> -		my $timeline = get_engine_timeline($ring);
> -		my $complete;
> -
> -		foreach my $pos (0..$#{$timeline}) {
> -			my $key = @{$timeline}[$pos];
> -			my $prev = $complete;
> -			my $pkey;
> -
> -			$complete = $key unless exists $db{$key}->{'no-end'};
> -			$pkey = $complete;
> -
> -			next if $db{$key}->{'port'} == 0;
> -
> -			$pkey = $prev if $complete eq $key;
> -
> -			die unless defined $pkey;
> -
> -			$db{$key}->{'start'} = $db{$pkey}->{'end'};
> -			$db{$key}->{'start'} = $db{$pkey}->{'notify'} if $db{$key}->{'start'} > $db{$key}->{'end'};
> -
> -			die if $db{$key}->{'start'} > $db{$key}->{'end'};
> -
> -			$re_sort = 1;
> -		}
> -	}
> -
> -	maybe_sort_keys();
> -
> -	# Batch with no-end (no request_out) means it was submitted as part of
> -	# coalesced context. This means it's start time should be set to the end
> -	# time of a following request on this context timeline.
> -	foreach my $tkey (sort keys %ctxtimelines) {
> -		my ($ctx, $ring) = split '/', $tkey;
> -		my $timeline = get_ctx_timeline($ctx, $ring, $tkey);
> -		my $last_complete = -1;
> -		my $complete;
> -
> -		foreach my $pos (0..$#{$timeline}) {
> -			my $key = @{$timeline}[$pos];
> -			my $next_key;
> -
> -			next unless exists $db{$key}->{'no-end'};
> -			last if $pos == $#{$timeline};
> -
> -			# Shift following request to start after the current
> -			# one, but only if that wouldn't make it zero duration,
> -			# which would indicate notify arrived after context
> -			# complete.
> -			$next_key = ${$timeline}[$pos + 1];
> -			if (exists $db{$key}->{'notify'} and
> -			    $db{$key}->{'notify'} < $db{$key}->{'end'}) {
> -				$db{$next_key}->{'engine-start'} = $db{$next_key}->{'start'};
> -				$db{$next_key}->{'start'} = $db{$key}->{'notify'};
> -				$re_sort = 1;
> -			}
> -		}
> -	}
> -}
> -
> -maybe_sort_keys();
> -
>   # GPU time accounting
>   my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
>   my (%submit_avg, %execute_avg, %ctxsave_avg);
> @@ -781,8 +796,7 @@ foreach my $key (@sorted_keys) {
>   		$db{$key}->{'duration'} = 0;
>   	}
>   
> -	$running{$ring} += $end - $start if $correct_durations or
> -					    not exists $db{$key}->{'no-end'};
> +	$running{$ring} += $end - $start if not exists $db{$key}->{'no-end'};
>   	unless (exists $db{$key}->{'virtual'}) {
>   		$runnable{$ring} += $db{$key}->{'execute-delay'};
>   		$queued{$ring} += $start - $db{$key}->{'execute-delay'} - $db{$key}->{'queue'};
> @@ -1324,9 +1338,14 @@ foreach my $key (sort sortQueue keys %db) {
>   		$content .= ' <small><i>++</i></small> ' if exists $db{$key}->{'no-end'};
>   		$content .= ' <small><i>+</i></small> ' if exists $db{$key}->{'no-notify'};
>   		$content .= "<br>$db{$key}->{'duration'}us <small>($db{$key}->{'context-complete-delay'}us)</small>";
> -		$startend = 'start: ' . $start . ', end: ' . $notify;
> -		print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n";
> -		$i++;
> +		foreach my $slice (@{$db{$key}->{'slices'}}) {
> +			my ($s, $e) = ($start, $notify);
> +			$s = @{$slice}[0] if @{$slice}[0] >= $start;
> +			$e = @{$slice}[1] if @{$slice}[1] <= $notify;
> +			$startend = 'start: ' . $s . ', end: ' . $e;
> +			print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n";
> +			$i++;
> +		}
>   	}
>   
>   	# user interrupt to context complete
>
Tvrtko Ursulin Jan. 20, 2020, 10:02 a.m. UTC | #3
On 17/01/2020 20:58, Ye, Tony wrote:
> Failed on parsing the trace log:
>      Died at ./trace.pl line 296.
> Raw data attached.

I need to add better error messages - that line is command line argument 
handling. I have dropped "-s" from this version in favour of always 
trying to track ELSP port occupancy.

Regardless, the logic still does not seem solid. Some parts of your 
trace file are not correctly represented in the HTML. Back to the 
drawing board.

Regards,

Tvrtko


> Regards,
> Tony
> On 1/17/2020 10:49 AM, Tvrtko Ursulin wrote:
>> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>>
>> ...
>>
>> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>> Cc: Tony Ye <tony.ye@intel.com>
>> ---
>> Tony could you please check if this works for you and even send me some
>> raw trace files you might have so I see how it looks?
>>
>> P.S.
>> I don't yet guarantee the results are 100% reliable and truthful. Or that
>> it won't crash.
>> ---
>>   scripts/trace.pl | 283 +++++++++++++++++++++++++----------------------
>>   1 file changed, 151 insertions(+), 132 deletions(-)
>>
>> diff --git a/scripts/trace.pl b/scripts/trace.pl
>> index 77587f24197a..8cad7e6ef65b 100755
>> --- a/scripts/trace.pl
>> +++ b/scripts/trace.pl
>> @@ -34,11 +34,10 @@ my $cid = 0;
>>   my %queues;
>>   my @freqs;
>> -use constant VENG => '255:254';
>> +use constant VENG => '65534:65534';
>>   my $max_requests = 1000;
>>   my $width_us = 32000;
>> -my $correct_durations = 0;
>>   my %ignore_ring;
>>   my %skip_box;
>>   my $html = 0;
>> @@ -224,18 +223,6 @@ sub arg_zoom_width
>>       return @_;
>>   }
>> -sub arg_split_requests
>> -{
>> -    return unless scalar(@_);
>> -
>> -    if ($_[0] eq '--split-requests' or $_[0] eq '-s') {
>> -        shift @_;
>> -        $correct_durations = 1;
>> -    }
>> -
>> -    return @_;
>> -}
>> -
>>   sub arg_ignore_ring
>>   {
>>       my $val;
>> @@ -299,7 +286,6 @@ while (@args) {
>>       @args = arg_trace(@args);
>>       @args = arg_max_requests(@args);
>>       @args = arg_zoom_width(@args);
>> -    @args = arg_split_requests(@args);
>>       @args = arg_ignore_ring(@args);
>>       @args = arg_skip_box(@args);
>>       @args = arg_colour_contexts(@args);
>> @@ -340,7 +326,79 @@ sub is_veng
>>   {
>>       my ($class, $instance) = split ':', shift;
>> -    return $instance eq '254';
>> +    return 1 if $instance eq '254' or $instance eq '65534';
>> +}
>> +
>> +my (%port_keys, %port_times);
>> +
>> +sub port_in
>> +{
>> +    my ($ring, $port, $key, $time) = @_;
>> +    my ($port_key, $port_time);
>> +    my @slices;
>> +
>> +    $db{$key}->{'slices'} = \@slices
>> +                unless exists $db{$key}->{'slices'};
>> +
>> +    $db{$key}->{'in'}++;
>> +
>> +    unless (exists $port_keys{$ring}) {
>> +        my (@keys, @times);
>> +
>> +        $port_keys{$ring} = \@keys;
>> +        $port_times{$ring} = \@times;
>> +    }
>> +
>> +    $port_key = $port_keys{$ring};
>> +    $port_time = $port_times{$ring};
>> +
>> +    unless (defined $port_key->[$port] and $port_key->[$port] eq $key) {
>> +        $port_key->[$port] = $key;
>> +        $port_time->[$port] = $time;
>> +    }
>> +}
>> +
>> +sub port_out
>> +{
>> +    my ($ring, $key, $time) = @_;
>> +    my ($port_key, $port_time);
>> +    my $port;
>> +
>> +    die unless $db{$key}->{'in'};
>> +    $db{$key}->{'in'}--;
>> +
>> +    $port_key = $port_keys{$ring};
>> +    $port_time = $port_times{$ring};
>> +
>> +    for (my $i = 0; $i < scalar(@{$port_key}); $i++) {
>> +        next unless defined $port_key->[$i];
>> +
>> +        if ($port_key->[$i] eq $key) {
>> +            $port = $i;
>> +            last;
>> +        }
>> +    }
>> +
>> +    return unless defined $port;
>> +
>> +    if ($port == 0) {
>> +        my $s = $db{$key}->{'slices'};
>> +        my $next;
>> +
>> +        push @{$s}, [$port_time->[$port], $time];
>> +
>> +        $next = $port + 1;
>> +        if (defined $port_key->[$next]) {
>> +            $port_time->[$next] = $time;
>> +            shift @{$port_key};
>> +            shift @{$port_time};
>> +        }
>> +    }
>> +
>> +    if ($db{$key}->{'in'} == 0) {
>> +        $port_key->[$port] = undef;
>> +        $port_time->[$port] = undef;
>> +    }
>>   }
>>   # Main input loop - parse lines and build the internal 
>> representation of the
>> @@ -368,7 +426,6 @@ while (<>) {
>>           next unless $f =~ m/=/;
>>           ($k, $v) = ($`, $');
>> -        $k = 'global' if $k eq 'global_seqno';
>>           chop $v if substr($v, -1, 1) eq ',';
>>           $tp{$k} = $v;
>> @@ -433,76 +490,89 @@ while (<>) {
>>           }
>>       } elsif ($tp_name eq 'i915:i915_request_submit:') {
>>           die if exists $submit{$key};
>> -        die unless exists $queue{$key};
>> +        unless (exists $queue{$key}) { # i915 internal
>> +            $queue{$key} = $time;
>> +            $ctxdb{$orig_ctx} = 1;
>> +        }
>>           die if $ring eq VENG and not exists $queues{$ctx};
>>           $submit{$key} = $time;
>>       } elsif ($tp_name eq 'i915:i915_request_in:') {
>> +        my $port = $tp{'port'};
>>           my ($q, $s);
>>           my %req;
>> -        # preemption
>> -        delete $db{$key} if exists $db{$key};
>> -
>>           unless (exists $queue{$key}) {
>>               # Virtual engine
>>               my $vkey = db_key(VENG, $ctx, $seqno);
>>               my %req;
>>               die unless exists $queues{$ctx};
>> -            die unless exists $queue{$vkey};
>>               die unless exists $submit{$vkey};
>> -            # Create separate request record on the queue timeline
>>               $q = $queue{$vkey};
>>               $s = $submit{$vkey};
>> -            $req{'queue'} = $q;
>> -            $req{'submit'} = $s;
>> +
>> +            unless (exists $vdb{$vkey}) {
>> +                # Create separate request record on the queue
>> +                # timeline.
>> +                $req{'queue'} = $q;
>> +                $req{'submit'} = $s;
>> +                $req{'start'} = $time;
>> +                $req{'end'} = $time;
>> +                $req{'ring'} = VENG;
>> +                $req{'phys-engine'} = $ring;
>> +                $req{'seqno'} = $seqno;
>> +                $req{'ctx'} = $ctx;
>> +                $req{'name'} = $ctx . '/' . $seqno;
>> +                $req{'port'} = $port;
>> +
>> +                $vdb{$vkey} = \%req;
>> +            }
>> +        } else {
>> +            $q = $queue{$key};
>> +            $s = $submit{$key};
>> +        }
>> +
>> +        unless (exists $db{$key}) {
>>               $req{'start'} = $time;
>> -            $req{'end'} = $time;
>> -            $req{'ring'} = VENG;
>> +            $req{'ring'} = $ring;
>>               $req{'seqno'} = $seqno;
>>               $req{'ctx'} = $ctx;
>> +            $ctxtimelines{$ctx . '/' . $ring} = 1;
>>               $req{'name'} = $ctx . '/' . $seqno;
>> -            $req{'global'} = $tp{'global'};
>> -            $req{'port'} = $tp{'port'};
>> +            $req{'port'} = $port;
>> +            $req{'queue'} = $q;
>> +            $req{'submit'} = $s;
>> +            $req{'virtual'} = 1 if exists $queues{$ctx};
>> +            $rings{$ring} = $gid++ unless exists $rings{$ring};
>> +            $ringmap{$rings{$ring}} = $ring;
>> +            $db{$key} = \%req;
>> -            $vdb{$vkey} = \%req;
>> -        } else {
>> -            $q = $queue{$key};
>> -            $s = $submit{$key};
>>           }
>> -        $req{'start'} = $time;
>> -        $req{'ring'} = $ring;
>> -        $req{'seqno'} = $seqno;
>> -        $req{'ctx'} = $ctx;
>> -        $ctxtimelines{$ctx . '/' . $ring} = 1;
>> -        $req{'name'} = $ctx . '/' . $seqno;
>> -        $req{'global'} = $tp{'global'};
>> -        $req{'port'} = $tp{'port'};
>> -        $req{'queue'} = $q;
>> -        $req{'submit'} = $s;
>> -        $req{'virtual'} = 1 if exists $queues{$ctx};
>> -        $rings{$ring} = $gid++ unless exists $rings{$ring};
>> -        $ringmap{$rings{$ring}} = $ring;
>> -        $db{$key} = \%req;
>> +        port_in($ring, $port, $key, $time);
>>       } elsif ($tp_name eq 'i915:i915_request_out:') {
>> -        if ($tp{'completed?'}) {
>> -            my $nkey;
>> +        my ($nkey, $completed, $prev_in);
>> -            die unless exists $db{$key};
>> -            die unless exists $db{$key}->{'start'};
>> -            die if exists $db{$key}->{'end'};
>> -
>> -            $nkey = notify_key($ctx, $seqno);
>> +        if ($ring eq VENG and not exists $db{$key}) {
>> +            my $vkey = db_key(VENG, $ctx, $seqno);
>> -            $db{$key}->{'end'} = $time;
>> -            $db{$key}->{'notify'} = $notify{$nkey}
>> -                        if exists $notify{$nkey};
>> -        } else {
>> -            delete $db{$key};
>> +            $ring = $vdb{$vkey}->{'phys-engine'};
>> +            $key = db_key($ring, $ctx, $seqno);
>>           }
>> +
>> +        die unless exists $db{$key};
>> +        die unless exists $db{$key}->{'start'};
>> +
>> +        $nkey = notify_key($ctx, $seqno);
>> +
>> +        port_out($ring, $key, $time);
>> +
>> +        $db{$key}->{'notify'} = $notify{$nkey}
>> +                    if exists $notify{$nkey};
>> +        $db{$key}->{'end'} = $time;
>> +        $db{$key}->{'completed'} = $tp{'completed?'};
>>       } elsif ($tp_name eq 'dma_fence:dma_fence_signaled:') {
>>           my $nkey;
>> @@ -561,6 +631,18 @@ sub sortStart {
>>       return $val;
>>   }
>> +sub sortEnd {
>> +    my $as = $db{$a}->{'end'};
>> +    my $bs = $db{$b}->{'end'};
>> +    my $val;
>> +
>> +say $a unless defined $as;
>> +    $val = $as <=> $bs;
>> +    $val = $a cmp $b if $val == 0;
>> +
>> +    return $val;
>> +}
>> +
>>   sub get_engine_timeline {
>>       my ($ring) = @_;
>>       my @timeline;
>> @@ -568,7 +650,7 @@ sub get_engine_timeline {
>>       return $engine_timelines{$ring} if exists $engine_timelines{$ring};
>>       @timeline = grep { $db{$_}->{'ring'} eq $ring } keys %db;
>> -    @timeline = sort sortStart @timeline;
>> +    @timeline = sort sortEnd @timeline;
>>       $engine_timelines{$ring} = \@timeline;
>>       return \@timeline;
>> @@ -679,73 +761,6 @@ sub get_ctx_timeline {
>>       return \@timeline;
>>   }
>> -# Split out merged batches if requested.
>> -if ($correct_durations) {
>> -    # Shift !port0 requests start time to after the previous context 
>> on the
>> -    # same timeline has finished.
>> -    foreach my $gid (sort keys %rings) {
>> -        my $ring = $ringmap{$rings{$gid}};
>> -        my $timeline = get_engine_timeline($ring);
>> -        my $complete;
>> -
>> -        foreach my $pos (0..$#{$timeline}) {
>> -            my $key = @{$timeline}[$pos];
>> -            my $prev = $complete;
>> -            my $pkey;
>> -
>> -            $complete = $key unless exists $db{$key}->{'no-end'};
>> -            $pkey = $complete;
>> -
>> -            next if $db{$key}->{'port'} == 0;
>> -
>> -            $pkey = $prev if $complete eq $key;
>> -
>> -            die unless defined $pkey;
>> -
>> -            $db{$key}->{'start'} = $db{$pkey}->{'end'};
>> -            $db{$key}->{'start'} = $db{$pkey}->{'notify'} if 
>> $db{$key}->{'start'} > $db{$key}->{'end'};
>> -
>> -            die if $db{$key}->{'start'} > $db{$key}->{'end'};
>> -
>> -            $re_sort = 1;
>> -        }
>> -    }
>> -
>> -    maybe_sort_keys();
>> -
>> -    # Batch with no-end (no request_out) means it was submitted as 
>> part of
>> -    # coalesced context. This means it's start time should be set to 
>> the end
>> -    # time of a following request on this context timeline.
>> -    foreach my $tkey (sort keys %ctxtimelines) {
>> -        my ($ctx, $ring) = split '/', $tkey;
>> -        my $timeline = get_ctx_timeline($ctx, $ring, $tkey);
>> -        my $last_complete = -1;
>> -        my $complete;
>> -
>> -        foreach my $pos (0..$#{$timeline}) {
>> -            my $key = @{$timeline}[$pos];
>> -            my $next_key;
>> -
>> -            next unless exists $db{$key}->{'no-end'};
>> -            last if $pos == $#{$timeline};
>> -
>> -            # Shift following request to start after the current
>> -            # one, but only if that wouldn't make it zero duration,
>> -            # which would indicate notify arrived after context
>> -            # complete.
>> -            $next_key = ${$timeline}[$pos + 1];
>> -            if (exists $db{$key}->{'notify'} and
>> -                $db{$key}->{'notify'} < $db{$key}->{'end'}) {
>> -                $db{$next_key}->{'engine-start'} = 
>> $db{$next_key}->{'start'};
>> -                $db{$next_key}->{'start'} = $db{$key}->{'notify'};
>> -                $re_sort = 1;
>> -            }
>> -        }
>> -    }
>> -}
>> -
>> -maybe_sort_keys();
>> -
>>   # GPU time accounting
>>   my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, 
>> %batch_count);
>>   my (%submit_avg, %execute_avg, %ctxsave_avg);
>> @@ -781,8 +796,7 @@ foreach my $key (@sorted_keys) {
>>           $db{$key}->{'duration'} = 0;
>>       }
>> -    $running{$ring} += $end - $start if $correct_durations or
>> -                        not exists $db{$key}->{'no-end'};
>> +    $running{$ring} += $end - $start if not exists 
>> $db{$key}->{'no-end'};
>>       unless (exists $db{$key}->{'virtual'}) {
>>           $runnable{$ring} += $db{$key}->{'execute-delay'};
>>           $queued{$ring} += $start - $db{$key}->{'execute-delay'} - 
>> $db{$key}->{'queue'};
>> @@ -1324,9 +1338,14 @@ foreach my $key (sort sortQueue keys %db) {
>>           $content .= ' <small><i>++</i></small> ' if exists 
>> $db{$key}->{'no-end'};
>>           $content .= ' <small><i>+</i></small> ' if exists 
>> $db{$key}->{'no-notify'};
>>           $content .= "<br>$db{$key}->{'duration'}us 
>> <small>($db{$key}->{'context-complete-delay'}us)</small>";
>> -        $startend = 'start: ' . $start . ', end: ' . $notify;
>> -        print "\t{id: $i, key: $skey, $type group: $group, subgroup: 
>> $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, 
>> style: \'$style\'},\n";
>> -        $i++;
>> +        foreach my $slice (@{$db{$key}->{'slices'}}) {
>> +            my ($s, $e) = ($start, $notify);
>> +            $s = @{$slice}[0] if @{$slice}[0] >= $start;
>> +            $e = @{$slice}[1] if @{$slice}[1] <= $notify;
>> +            $startend = 'start: ' . $s . ', end: ' . $e;
>> +            print "\t{id: $i, key: $skey, $type group: $group, 
>> subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', 
>> $startend, style: \'$style\'},\n";
>> +            $i++;
>> +        }
>>       }
>>       # user interrupt to context complete
>>

Patch
diff mbox series

diff --git a/scripts/trace.pl b/scripts/trace.pl
index 77587f24197a..8cad7e6ef65b 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -34,11 +34,10 @@  my $cid = 0;
 my %queues;
 my @freqs;
 
-use constant VENG => '255:254';
+use constant VENG => '65534:65534';
 
 my $max_requests = 1000;
 my $width_us = 32000;
-my $correct_durations = 0;
 my %ignore_ring;
 my %skip_box;
 my $html = 0;
@@ -224,18 +223,6 @@  sub arg_zoom_width
 	return @_;
 }
 
-sub arg_split_requests
-{
-	return unless scalar(@_);
-
-	if ($_[0] eq '--split-requests' or $_[0] eq '-s') {
-		shift @_;
-		$correct_durations = 1;
-	}
-
-	return @_;
-}
-
 sub arg_ignore_ring
 {
 	my $val;
@@ -299,7 +286,6 @@  while (@args) {
 	@args = arg_trace(@args);
 	@args = arg_max_requests(@args);
 	@args = arg_zoom_width(@args);
-	@args = arg_split_requests(@args);
 	@args = arg_ignore_ring(@args);
 	@args = arg_skip_box(@args);
 	@args = arg_colour_contexts(@args);
@@ -340,7 +326,79 @@  sub is_veng
 {
 	my ($class, $instance) = split ':', shift;
 
-	return $instance eq '254';
+	return 1 if $instance eq '254' or $instance eq '65534';
+}
+
+my (%port_keys, %port_times);
+
+sub port_in
+{
+	my ($ring, $port, $key, $time) = @_;
+	my ($port_key, $port_time);
+	my @slices;
+
+	$db{$key}->{'slices'} = \@slices
+				unless exists $db{$key}->{'slices'};
+
+	$db{$key}->{'in'}++;
+
+	unless (exists $port_keys{$ring}) {
+		my (@keys, @times);
+
+		$port_keys{$ring} = \@keys;
+		$port_times{$ring} = \@times;
+	}
+
+	$port_key = $port_keys{$ring};
+	$port_time = $port_times{$ring};
+
+	unless (defined $port_key->[$port] and $port_key->[$port] eq $key) {
+		$port_key->[$port] = $key;
+		$port_time->[$port] = $time;
+	}
+}
+
+sub port_out
+{
+	my ($ring, $key, $time) = @_;
+	my ($port_key, $port_time);
+	my $port;
+
+	die unless $db{$key}->{'in'};
+	$db{$key}->{'in'}--;
+
+	$port_key = $port_keys{$ring};
+	$port_time = $port_times{$ring};
+
+	for (my $i = 0; $i < scalar(@{$port_key}); $i++) {
+		next unless defined $port_key->[$i];
+
+		if ($port_key->[$i] eq $key) {
+			$port = $i;
+			last;
+		}
+	}
+
+	return unless defined $port;
+
+	if ($port == 0) {
+		my $s = $db{$key}->{'slices'};
+		my $next;
+
+		push @{$s}, [$port_time->[$port], $time];
+
+		$next = $port + 1;
+		if (defined $port_key->[$next]) {
+			$port_time->[$next] = $time;
+			shift @{$port_key};
+			shift @{$port_time};
+		}
+	}
+
+	if ($db{$key}->{'in'} == 0) {
+		$port_key->[$port] = undef;
+		$port_time->[$port] = undef;
+	}
 }
 
 # Main input loop - parse lines and build the internal representation of the
@@ -368,7 +426,6 @@  while (<>) {
 
 		next unless $f =~ m/=/;
 		($k, $v) = ($`, $');
-		$k = 'global' if $k eq 'global_seqno';
 		chop $v if substr($v, -1, 1) eq ',';
 		$tp{$k} = $v;
 
@@ -433,76 +490,89 @@  while (<>) {
 		}
 	} elsif ($tp_name eq 'i915:i915_request_submit:') {
 		die if exists $submit{$key};
-		die unless exists $queue{$key};
+		unless (exists $queue{$key}) { # i915 internal
+			$queue{$key} = $time;
+			$ctxdb{$orig_ctx} = 1;
+		}
 		die if $ring eq VENG and not exists $queues{$ctx};
 
 		$submit{$key} = $time;
 	} elsif ($tp_name eq 'i915:i915_request_in:') {
+		my $port = $tp{'port'};
 		my ($q, $s);
 		my %req;
 
-		# preemption
-		delete $db{$key} if exists $db{$key};
-
 		unless (exists $queue{$key}) {
 			# Virtual engine
 			my $vkey = db_key(VENG, $ctx, $seqno);
 			my %req;
 
 			die unless exists $queues{$ctx};
-			die unless exists $queue{$vkey};
 			die unless exists $submit{$vkey};
 
-			# Create separate request record on the queue timeline
 			$q = $queue{$vkey};
 			$s = $submit{$vkey};
-			$req{'queue'} = $q;
-			$req{'submit'} = $s;
+
+			unless (exists $vdb{$vkey}) {
+				# Create separate request record on the queue
+				# timeline.
+				$req{'queue'} = $q;
+				$req{'submit'} = $s;
+				$req{'start'} = $time;
+				$req{'end'} = $time;
+				$req{'ring'} = VENG;
+				$req{'phys-engine'} = $ring;
+				$req{'seqno'} = $seqno;
+				$req{'ctx'} = $ctx;
+				$req{'name'} = $ctx . '/' . $seqno;
+				$req{'port'} = $port;
+
+				$vdb{$vkey} = \%req;
+			}
+		} else {
+			$q = $queue{$key};
+			$s = $submit{$key};
+		}
+
+		unless (exists $db{$key}) {
 			$req{'start'} = $time;
-			$req{'end'} = $time;
-			$req{'ring'} = VENG;
+			$req{'ring'} = $ring;
 			$req{'seqno'} = $seqno;
 			$req{'ctx'} = $ctx;
+			$ctxtimelines{$ctx . '/' . $ring} = 1;
 			$req{'name'} = $ctx . '/' . $seqno;
-			$req{'global'} = $tp{'global'};
-			$req{'port'} = $tp{'port'};
+			$req{'port'} = $port;
+			$req{'queue'} = $q;
+			$req{'submit'} = $s;
+			$req{'virtual'} = 1 if exists $queues{$ctx};
+			$rings{$ring} = $gid++ unless exists $rings{$ring};
+			$ringmap{$rings{$ring}} = $ring;
+			$db{$key} = \%req;
 
-			$vdb{$vkey} = \%req;
-		} else {
-			$q = $queue{$key};
-			$s = $submit{$key};
 		}
 
-		$req{'start'} = $time;
-		$req{'ring'} = $ring;
-		$req{'seqno'} = $seqno;
-		$req{'ctx'} = $ctx;
-		$ctxtimelines{$ctx . '/' . $ring} = 1;
-		$req{'name'} = $ctx . '/' . $seqno;
-		$req{'global'} = $tp{'global'};
-		$req{'port'} = $tp{'port'};
-		$req{'queue'} = $q;
-		$req{'submit'} = $s;
-		$req{'virtual'} = 1 if exists $queues{$ctx};
-		$rings{$ring} = $gid++ unless exists $rings{$ring};
-		$ringmap{$rings{$ring}} = $ring;
-		$db{$key} = \%req;
+		port_in($ring, $port, $key, $time);
 	} elsif ($tp_name eq 'i915:i915_request_out:') {
-		if ($tp{'completed?'}) {
-			my $nkey;
+		my ($nkey, $completed, $prev_in);
 
-			die unless exists $db{$key};
-			die unless exists $db{$key}->{'start'};
-			die if exists $db{$key}->{'end'};
-
-			$nkey = notify_key($ctx, $seqno);
+		if ($ring eq VENG and not exists $db{$key}) {
+			my $vkey = db_key(VENG, $ctx, $seqno);
 
-			$db{$key}->{'end'} = $time;
-			$db{$key}->{'notify'} = $notify{$nkey}
-						if exists $notify{$nkey};
-		} else {
-			delete $db{$key};
+			$ring = $vdb{$vkey}->{'phys-engine'};
+			$key = db_key($ring, $ctx, $seqno);
 		}
+
+		die unless exists $db{$key};
+		die unless exists $db{$key}->{'start'};
+
+		$nkey = notify_key($ctx, $seqno);
+
+		port_out($ring, $key, $time);
+
+		$db{$key}->{'notify'} = $notify{$nkey}
+					if exists $notify{$nkey};
+		$db{$key}->{'end'} = $time;
+		$db{$key}->{'completed'} = $tp{'completed?'};
 	} elsif ($tp_name eq 'dma_fence:dma_fence_signaled:') {
 		my $nkey;
 
@@ -561,6 +631,18 @@  sub sortStart {
 	return $val;
 }
 
+sub sortEnd {
+	my $as = $db{$a}->{'end'};
+	my $bs = $db{$b}->{'end'};
+	my $val;
+
+say $a unless defined $as;
+	$val = $as <=> $bs;
+	$val = $a cmp $b if $val == 0;
+
+	return $val;
+}
+
 sub get_engine_timeline {
 	my ($ring) = @_;
 	my @timeline;
@@ -568,7 +650,7 @@  sub get_engine_timeline {
 	return $engine_timelines{$ring} if exists $engine_timelines{$ring};
 
 	@timeline = grep { $db{$_}->{'ring'} eq $ring } keys %db;
-	@timeline = sort sortStart @timeline;
+	@timeline = sort sortEnd @timeline;
 	$engine_timelines{$ring} = \@timeline;
 
 	return \@timeline;
@@ -679,73 +761,6 @@  sub get_ctx_timeline {
 	return \@timeline;
 }
 
-# Split out merged batches if requested.
-if ($correct_durations) {
-	# Shift !port0 requests start time to after the previous context on the
-	# same timeline has finished.
-	foreach my $gid (sort keys %rings) {
-		my $ring = $ringmap{$rings{$gid}};
-		my $timeline = get_engine_timeline($ring);
-		my $complete;
-
-		foreach my $pos (0..$#{$timeline}) {
-			my $key = @{$timeline}[$pos];
-			my $prev = $complete;
-			my $pkey;
-
-			$complete = $key unless exists $db{$key}->{'no-end'};
-			$pkey = $complete;
-
-			next if $db{$key}->{'port'} == 0;
-
-			$pkey = $prev if $complete eq $key;
-
-			die unless defined $pkey;
-
-			$db{$key}->{'start'} = $db{$pkey}->{'end'};
-			$db{$key}->{'start'} = $db{$pkey}->{'notify'} if $db{$key}->{'start'} > $db{$key}->{'end'};
-
-			die if $db{$key}->{'start'} > $db{$key}->{'end'};
-
-			$re_sort = 1;
-		}
-	}
-
-	maybe_sort_keys();
-
-	# Batch with no-end (no request_out) means it was submitted as part of
-	# coalesced context. This means it's start time should be set to the end
-	# time of a following request on this context timeline.
-	foreach my $tkey (sort keys %ctxtimelines) {
-		my ($ctx, $ring) = split '/', $tkey;
-		my $timeline = get_ctx_timeline($ctx, $ring, $tkey);
-		my $last_complete = -1;
-		my $complete;
-
-		foreach my $pos (0..$#{$timeline}) {
-			my $key = @{$timeline}[$pos];
-			my $next_key;
-
-			next unless exists $db{$key}->{'no-end'};
-			last if $pos == $#{$timeline};
-
-			# Shift following request to start after the current
-			# one, but only if that wouldn't make it zero duration,
-			# which would indicate notify arrived after context
-			# complete.
-			$next_key = ${$timeline}[$pos + 1];
-			if (exists $db{$key}->{'notify'} and
-			    $db{$key}->{'notify'} < $db{$key}->{'end'}) {
-				$db{$next_key}->{'engine-start'} = $db{$next_key}->{'start'};
-				$db{$next_key}->{'start'} = $db{$key}->{'notify'};
-				$re_sort = 1;
-			}
-		}
-	}
-}
-
-maybe_sort_keys();
-
 # GPU time accounting
 my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
 my (%submit_avg, %execute_avg, %ctxsave_avg);
@@ -781,8 +796,7 @@  foreach my $key (@sorted_keys) {
 		$db{$key}->{'duration'} = 0;
 	}
 
-	$running{$ring} += $end - $start if $correct_durations or
-					    not exists $db{$key}->{'no-end'};
+	$running{$ring} += $end - $start if not exists $db{$key}->{'no-end'};
 	unless (exists $db{$key}->{'virtual'}) {
 		$runnable{$ring} += $db{$key}->{'execute-delay'};
 		$queued{$ring} += $start - $db{$key}->{'execute-delay'} - $db{$key}->{'queue'};
@@ -1324,9 +1338,14 @@  foreach my $key (sort sortQueue keys %db) {
 		$content .= ' <small><i>++</i></small> ' if exists $db{$key}->{'no-end'};
 		$content .= ' <small><i>+</i></small> ' if exists $db{$key}->{'no-notify'};
 		$content .= "<br>$db{$key}->{'duration'}us <small>($db{$key}->{'context-complete-delay'}us)</small>";
-		$startend = 'start: ' . $start . ', end: ' . $notify;
-		print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n";
-		$i++;
+		foreach my $slice (@{$db{$key}->{'slices'}}) {
+			my ($s, $e) = ($start, $notify);
+			$s = @{$slice}[0] if @{$slice}[0] >= $start;
+			$e = @{$slice}[1] if @{$slice}[1] <= $notify;
+			$startend = 'start: ' . $s . ', end: ' . $e;
+			print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n";
+			$i++;
+		}
 	}
 
 	# user interrupt to context complete