trace.pl fixes and improvements

index ea6c667696f4..fd414f5a4b1e 100755
@@ -873,10 +873,30 @@ sub sortQueue {
 
 sub ctx_colour
 {
-	my ($ctx, $s, $l) = (@_);
+	my ($ctx, $stage) = (@_);
+	my ($s, $l);
 	my $val;
 
-	return 'Pink;' unless $colour_contexts;
+	unless ($colour_contexts) {
+		if ($stage eq 'queue') {
+			return 'lightblue;';
+		} elsif ($stage eq 'ready') {
+			return 'lightgrey;';
+		} elsif ($stage eq 'execute') {
+			return 'pink;';
+		}
+	} else {
+		if ($stage eq 'queue') {
+			$s = 35;
+			$l = 85;
+		} elsif ($stage eq 'ready') {
+			$s = 35;
+			$l = 45;
+		} elsif ($stage eq 'execute') {
+			$s = 80;
+			$l = 65;
+		}
+	}
 
 	$val = int(360 / ($max_ctx - $min_ctx + 1)) * ($ctx - $min_ctx);
 

@@ -898,7 +918,7 @@ foreach my $key (sort sortQueue keys %db) {
 	unless (exists $skip_box{'queue'}) {
 		$skey = 2 * $max_seqno * $ctx + 2 * $seqno;
 		$style = 'color: black; background-color: ' .
-			 ctx_colour($ctx, 35, 85);
+			 ctx_colour($ctx, 'queue');
 		$content = "$name<br>$db{$key}->{'submit-delay'}us <small>($db{$key}->{'execute-delay'}us)</small>";
 		$startend = 'start: \'' . ts($queue) . '\', end: \'' . ts($submit) . '\'';
 		print "\t{id: $i, key: $skey, $type group: $group, subgroup: 1, subgroupOrder: 1, content: '$content', $startend, style: \'$style\'},\n";

@@ -909,7 +929,7 @@ foreach my $key (sort sortQueue keys %db) {
 	unless (exists $skip_box{'ready'}) {
 		$skey = 2 * $max_seqno * $ctx + 2 * $seqno + 1;
 		$style = 'color: black; background-color: ' .
-			 ctx_colour($ctx, 35, 45);
+			 ctx_colour($ctx, 'ready');
 		$content = "<small>$name<br>$db{$key}->{'execute-delay'}us</small>";
 		$startend = 'start: \'' . ts($submit) . '\', end: \'' . ts($start) . '\'';
 		print "\t{id: $i, key: $skey, $type group: $group, subgroup: 1, subgroupOrder: 2, content: '$content', $startend, style: \'$style\'},\n";

@@ -923,7 +943,7 @@ foreach my $key (sort sortQueue keys %db) {
 			$style = 'color: white; background-color: red;';
 		} else {
 			$style = 'color: black; background-color: ' .
-				  ctx_colour($ctx, 80, 65);
+				  ctx_colour($ctx, 'execute');
 		}
 		$content = "$name <small>$db{$key}->{'port'}</small>";
 		$content .= ' <small><i>???</i></small> ' if exists $db{$key}->{'incomplete'};

index c5628c7f2836..375844d9cdf6 100755
@@ -207,7 +207,7 @@ sub trace_workload
 	show_cmd($cmd);
 	system($cmd);
 
-	$cmd = "perf script | $tracepl --html -x ctxsave -s ";
+	$cmd = "perf script | $tracepl --html -x ctxsave -s -c ";
 	$cmd .= join ' ', map("-i $_", @skip_engine);
 	$cmd .= " > ${file}.html";
 	show_cmd($cmd);

171 lines not on this page · raw message

index 1ec8b297d15e..4d3e06434f05 100755
@@ -40,6 +40,7 @@ my $trace = 0;
 my $avg_delay_stats = 0;
 my $gpu_timeline = 0;
 my $colour_contexts = 0;
+my $no_timeline_scaling = 0;
 
 my @args;
 

@@ -281,6 +282,18 @@ sub arg_colour_contexts
 	return @_;
 }
 
+sub arg_no_timeline_scaling
+{
+	return unless scalar(@_);
+
+	if ($_[0] eq '--no-timeline-scaling') {
+		shift @_;
+		$no_timeline_scaling = 1;
+	}
+
+	return @_;
+}
+
 @args = @ARGV;
 while (@args) {
 	my $left = scalar(@args);

@@ -296,6 +309,7 @@ while (@args) {
 	@args = arg_ignore_ring(@args);
 	@args = arg_skip_box(@args);
 	@args = arg_colour_contexts(@args);
+	@args = arg_no_timeline_scaling(@args);
 
 	last if $left == scalar(@args);
 }

@@ -334,6 +348,8 @@ sub ts
 	my ($us) = @_;
 	my ($d, $h, $m, $s);
 
+	$us *= 1000 unless $no_timeline_scaling;
+
 	$s = int($us / 1000000);
 	$us = $us % 1000000;
 

index 4d3e06434f05..e2978e5382c2 100755
@@ -768,9 +768,6 @@ print <<ENDHTML if $html;
   <link href="node_modules/vis//dist/vis.css" rel="stylesheet" type="text/css" />
 </head>
 <body>
-
-<button onclick="toggleStackSubgroups()">Toggle stacking</button>
-
 <p>
 <b>Timeline request view:</b>
 <table>

@@ -997,6 +994,7 @@ foreach my $key (sort sortQueue keys %db) {
 	my $submit = $queue + $db{$key}->{'submit-delay'};
 	my ($content, $style);
 	my $group = $engine_start_id + $rings{$db{$key}->{'ring'}};
+	my $subgroup = $ctx - $min_ctx;
 	my $type = ' type: \'range\',';
 	my $startend;
 	my $skey;

@@ -1007,7 +1005,7 @@ foreach my $key (sort sortQueue keys %db) {
 		$style = box_style($ctx, 'queue');
 		$content = "$name<br>$db{$key}->{'submit-delay'}us <small>($db{$key}->{'execute-delay'}us)</small>";
 		$startend = 'start: \'' . ts($queue) . '\', end: \'' . ts($submit) . '\'';
-		print "\t{id: $i, key: $skey, $type group: $group, subgroup: 1, subgroupOrder: 1, content: '$content', $startend, style: \'$style\'},\n";
+		print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n";
 		$i++;
 	}
 

@@ -1017,7 +1015,7 @@ foreach my $key (sort sortQueue keys %db) {
 		$style = box_style($ctx, 'ready');
 		$content = "<small>$name<br>$db{$key}->{'execute-delay'}us</small>";
 		$startend = 'start: \'' . ts($submit) . '\', end: \'' . ts($start) . '\'';
-		print "\t{id: $i, key: $skey, $type group: $group, subgroup: 1, subgroupOrder: 2, content: '$content', $startend, style: \'$style\'},\n";
+		print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n";
 		$i++;
 	}
 

@@ -1033,7 +1031,7 @@ foreach my $key (sort sortQueue keys %db) {
 		$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: \'' . ts($start) . '\', end: \'' . ts($notify) . '\'';
-		print "\t{id: $i, key: $skey, $type group: $group, subgroup: 2, subgroupOrder: 3, content: '$content', $startend, style: \'$style\'},\n";
+		print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n";
 		$i++;
 	}
 

@@ -1047,7 +1045,7 @@ 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'};
 		$startend = 'start: \'' . ts($notify) . '\', end: \'' . ts($end) . '\'';
-		print "\t{id: $i, key: $skey, $type group: $group, subgroup: 2, subgroupOrder: 4, content: '$content', $startend, style: \'$style\'},\n";
+		print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n";
 		$i++;
 	}
 

@@ -1090,29 +1088,18 @@ $first_ts = ts($first_ts);
 print <<ENDHTML;
   ]);
 
-  function customOrder (a, b) {
-  // order by id
-    return a.subgroupOrder - b.subgroupOrder;
-  }
-
   // Configuration for the Timeline
   var options = { groupOrder: 'content',
 		  horizontalScroll: true,
-		  stack: true,
+		  stack: false,
 		  stackSubgroups: false,
 		  zoomKey: 'ctrlKey',
 		  orientation: 'top',
-		  order: customOrder,
 		  start: '$first_ts',
 		  end: '$end_ts'};
 
   // Create a Timeline
   var timeline = new vis.Timeline(container, items, groups, options);
-
-    function toggleStackSubgroups() {
-        options.stackSubgroups = !options.stackSubgroups;
-        timeline.setOptions(options);
-    }
 ENDHTML
 
 print <<ENDHTML;

index e2978e5382c2..aeaf2392162e 100755
@@ -346,24 +346,17 @@ sub sanitize_ctx
 sub ts
 {
 	my ($us) = @_;
-	my ($d, $h, $m, $s);
+	my ($y, $mo, $d, $h, $m, $s);
 
 	$us *= 1000 unless $no_timeline_scaling;
 
 	$s = int($us / 1000000);
 	$us = $us % 1000000;
 
-	$m = int($s / 60);
-	$s = $s % 60;
+	($s, $m, $h, $d, $mo, $y) = gmtime($s);
 
-	$h = int($m / 60);
-	$m = $m % 60;
-
-	$d = 1 + int($h / 24);
-	$h = $h % 24;
-
-	return sprintf('2017-01-%02u %02u:%02u:%02u.%06u',
-		       int($d), int($h), int($m), int($s), int($us));
+	return sprintf('%04u-%02u-%02u %02u:%02u:%02u.%06u',
+		        1970 + $y, 1 + $mo, $d, $h, $m, $s, int($us));
 }
 
 # Main input loop - parse lines and build the internal representation of the

index aeaf2392162e..60a8e441c1d9 100755
@@ -336,7 +336,7 @@ sub sanitize_ctx
 {
 	my ($ctx, $ring) = @_;
 
-	if (exists $ctxdb{$ctx}) {
+	if (exists $ctxdb{$ctx} and $ctxdb{$ctx} > 1) {
 		return $ctx . '.' . $ctxdb{$ctx};
 	} else {
 		return $ctx;

@@ -425,6 +425,8 @@ while (<>) {
 			$ctxdb{$orig_ctx}++;
 			$ctx = sanitize_ctx($orig_ctx, $ring);
 			$key = db_key($ring, $ctx, $seqno);
+		} else {
+			$ctxdb{$orig_ctx} = 1;
 		}
 
 		$queue{$key} = $time;

@@ -592,7 +594,7 @@ foreach my $key (@sorted_keys) {
 
 my $last_ts = 0;
 my $first_ts;
-my ($min_ctx, $max_ctx);
+my $min_ctx;
 
 foreach my $key (@sorted_keys) {
 	my $ring = $db{$key}->{'ring'};

@@ -604,8 +606,6 @@ foreach my $key (@sorted_keys) {
 	$last_ts = $end if $end > $last_ts;
 	$min_ctx = $db{$key}->{'ctx'} if not defined $min_ctx or
 					 $db{$key}->{'ctx'} < $min_ctx;
-	$max_ctx = $db{$key}->{'ctx'} if not defined $max_ctx or
-					 $db{$key}->{'ctx'} > $max_ctx;
 
 	$db{$key}->{'context-complete-delay'} = $end - $notify;
 	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};

@@ -739,6 +739,21 @@ say sprintf('GPU: %.2f%% idle, %.2f%% busy',
 my $timeline_text = $colour_contexts ?
 		    'Per context coloured shading like:' : 'Box shading like:';
 
+my %ctx_colours;
+
+sub generate_ctx_colours
+{
+	my $num_ctx = keys %ctxdb;
+	my $i = 0;
+
+	foreach my $ctx (sort keys %ctxdb) {
+		$ctx_colours{$ctx} = int(360 / $num_ctx * $i++);
+	}
+}
+
+
+generate_ctx_colours() if $html and $colour_contexts;
+
 my $queued_style = box_style($min_ctx, 'queue');
 my $ready_style = box_style($min_ctx, 'ready');
 my $execute_style = box_style($min_ctx, 'execute');

@@ -947,7 +962,7 @@ sub ctx_colour
 			$l = 25;
 		}
 
-		$val = int(360 / ($max_ctx - $min_ctx + 1)) * ($ctx - $min_ctx);
+		$val = $ctx_colours{$ctx};
 	}
 
 	$l = int($l * $lfac);

index 60a8e441c1d9..52372e224da5 100755
@@ -612,7 +612,8 @@ foreach my $key (@sorted_keys) {
 	$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'};
+	$running{$ring} += $end - $start if $correct_durations or
+					    not exists $db{$key}->{'no-end'};
 	$runnable{$ring} += $db{$key}->{'execute-delay'};
 	$queued{$ring} += $start - $db{$key}->{'execute-delay'} - $db{$key}->{'queue'};
 

index 52372e224da5..379f6edce457 100755
@@ -607,7 +607,11 @@ foreach my $key (@sorted_keys) {
 	$min_ctx = $db{$key}->{'ctx'} if not defined $min_ctx or
 					 $db{$key}->{'ctx'} < $min_ctx;
 
-	$db{$key}->{'context-complete-delay'} = $end - $notify;
+	unless (exists $db{$key}->{'no-end'}) {
+		$db{$key}->{'context-complete-delay'} = $end - $notify;
+	} else {
+		$db{$key}->{'context-complete-delay'} = 0;
+	}
 	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
 	$db{$key}->{'submit-delay'} = $db{$key}->{'submit'} - $db{$key}->{'queue'};
 	$db{$key}->{'duration'} = $notify - $start;

@@ -624,7 +628,7 @@ foreach my $key (@sorted_keys) {
 
 	$submit_avg{$ring} += $db{$key}->{'submit-delay'};
 	$execute_avg{$ring} += $db{$key}->{'execute-delay'};
-	$ctxsave_avg{$ring} += $end - $notify;
+	$ctxsave_avg{$ring} += $db{$key}->{'context-complete-delay'};
 }
 
 foreach my $ring (sort keys %batch_avg) {

@@ -1045,7 +1049,7 @@ foreach my $key (sort sortQueue keys %db) {
 	}
 
 	# user interrupt to context complete
-	unless (exists $skip_box{'ctxsave'}) {
+	unless (exists $skip_box{'ctxsave'} or exists $db{$key}->{'no-end'}) {
 		$skey = -2 * $max_seqno * $ctx - 2 * $seqno;
 		$style = box_style($ctx, 'ctxsave');
 		my $ctxsave = $db{$key}->{'end'} - $db{$key}->{'notify'};

index 379f6edce457..6379dace5743 100755
@@ -462,16 +462,11 @@ while (<>) {
 		die if exists $db{$key}->{'end'};
 
 		$db{$key}->{'end'} = $time;
-		if (exists $notify{$gkey}) {
-			$db{$key}->{'notify'} = $notify{$gkey};
-		} else {
-			# No notify so far. Maybe it will arrive later which
-			# will be handled in the sanitation loop below.
-			$db{$key}->{'notify'} = $db{$key}->{'end'};
-			$db{$key}->{'no-notify'} = 1;
-		}
+		$db{$key}->{'notify'} = $notify{$gkey} if exists $notify{$gkey};
 	} elsif ($tp_name eq 'i915:intel_engine_notify:') {
-		$notify{global_key($ring, $seqno)} = $time;
+		my $gkey = global_key($ring, $seqno);
+
+		$notify{$gkey} = $time unless exists $notify{$gkey};
 	} elsif ($tp_name eq 'i915:intel_gpu_freq_change:') {
 		push @freqs, [$prev_freq_ts, $time, $prev_freq] if $prev_freq;
 		$prev_freq_ts = $time;

@@ -484,66 +479,116 @@ while (<>) {
 my $max_seqno = 0;
 foreach my $key (keys %db) {
 	my $gkey = global_key($db{$key}->{'ring'}, $db{$key}->{'global'});
-	my $notify = $notify{$gkey};
 
 	die unless exists $db{$key}->{'start'};
 
 	$max_seqno = $db{$key}->{'seqno'} if $db{$key}->{'seqno'} > $max_seqno;
 
-	unless (exists $db{$key}->{'end'}) {
-		# Context complete not received.
-		$db{$key}->{'no-end'} = 1;
+	# Notify arrived after context complete?
+	$db{$key}->{'notify'} = $notify{$gkey} if not exists $db{$key}->{'notify'}
+						  and exists $notify{$gkey};
 
-		if (defined($notify)) {
-			# No context complete due req merging - use notify.
-			$db{$key}->{'notify'} = $notify;
-			$db{$key}->{'end'} = $notify;
-		} else {
-			# No notify and no context complete - give up for now.
-			$db{$key}->{'incomplete'} = 1;
-		}
-	} else {
-		# Notify arrived after context complete.
-		if (exists $db{$key}->{'no-notify'} and defined($notify)) {
-			delete $db{$key}->{'no-notify'};
-			$db{$key}->{'notify'} = $notify;
-		}
+	# No notify but we have end?
+	$db{$key}->{'notify'} = $db{$key}->{'end'} if exists $db{$key}->{'end'} and
+						      not exists $db{$key}->{'notify'};
+
+	# If user interrupt arrived out of order push it back to be no later
+	# than request out.
+	if (exists $db{$key}->{'end'} and exists $db{$key}->{'notify'} and
+	    $db{$key}->{'notify'} > $db{$key}->{'end'}) {
+		$db{$key}->{'notify'} = $db{$key}->{'end'};
 	}
 }
 
-# Fix up incompletes
 my $key_count = scalar(keys %db);
-foreach my $key (keys %db) {
-	next unless exists $db{$key}->{'incomplete'};
 
-	# End the incomplete batch at the time next one starts
-	my $ring = $db{$key}->{'ring'};
-	my $ctx = $db{$key}->{'ctx'};
-	my $seqno = $db{$key}->{'seqno'};
-	my $next_key;
-	my $i = 1;
-	my $end;
-
-	do {
-		$next_key = db_key($ring, $ctx, $seqno + $i);
-		$i++;
-	} until ((exists $db{$next_key} and not exists $db{$next_key}->{'incomplete'})
-		 or $i > $key_count);  # ugly stop hack
+my %engine_timelines;
 
-	if (exists $db{$next_key}) {
-		$end = $db{$next_key}->{'end'};
-	} else {
-		# No info at all, fake it:
-		$end = $db{$key}->{'start'} + 999;
-	}
+sub sortEngine {
+	my $as = $db{$a}->{'global'};
+	my $bs = $db{$b}->{'global'};
+	my $val;
+
+	$val = $as <=> $bs;
 
-	$db{$key}->{'notify'} = $end;
-	$db{$key}->{'end'} = $end;
+	die if $val == 0;
+
+	return $val;
 }
 
-# GPU time accounting
-my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
-my (%submit_avg, %execute_avg, %ctxsave_avg);
+sub get_engine_timeline {
+	my ($ring) = @_;
+	my @timeline;
+
+	return $engine_timelines{$ring} if exists $engine_timelines{$ring};
+
+	@timeline = grep { $db{$_}->{'ring'} eq $ring } keys %db;
+	# FIXME seqno restart
+	@timeline = sort sortEngine @timeline;
+
+	$engine_timelines{$ring} = \@timeline;
+
+	return \@timeline;
+}
+
+# Fix up coalesced requests by ending them either when the following same
+# context request with known end ends, or when a different context starts.
+foreach my $gid (sort keys %rings) {
+	my $ring = $ringmap{$rings{$gid}};
+	my $timeline = get_engine_timeline($ring);
+	my $last_complete = -1;
+	my $last_ctx = -1;
+	my $complete;
+
+	foreach my $pos (0..$#{$timeline}) {
+		my $key = @{$timeline}[$pos];
+		my ($ctx, $end);
+
+		next if exists $db{$key}->{'end'};
+
+		$db{$key}->{'no-end'} = 1;
+		$ctx = $db{$key}->{'ctx'};
+
+		if ($pos > $last_complete or $ctx != $last_ctx) {
+			my $next = $pos;
+
+			undef $complete;
+
+			while ($next < $#{$timeline}) {
+				my $next_key = ${$timeline}[++$next];
+				if ($ctx == $db{$next_key}->{'ctx'} and
+				    exists $db{$next_key}->{'end'}) {
+					$last_ctx = $db{$next_key}->{'ctx'};
+					$last_complete = $next;
+					$complete = $next_key;
+					last;
+				}
+			}
+		}
+
+		if (defined $complete) {
+			if ($ctx == $db{$complete}->{'ctx'}) {
+				$end = $db{$complete}->{'end'};
+			} else {
+				$end = $db{$complete}->{'start'};
+			}
+		} else {
+			# No next submission. Use notify if available or give up.
+			if (exists $db{$key}->{'notify'}) {
+				$end = $db{$key}->{'notify'};
+			} else {
+				$end = $db{$key}->{'start'};
+				$db{$key}->{'incomplete'} = 1;
+			}
+		}
+
+		unless (exists $db{$key}->{'notify'}) {
+			$db{$key}->{'notify'} = $end;
+			$db{$key}->{'no-notify'} = 1;
+		}
+		$db{$key}->{'end'} = $end;
+	}
+}
 
 sub sortStart {
 	my $as = $db{$a}->{'start'};

@@ -592,6 +637,10 @@ foreach my $key (@sorted_keys) {
 
 @sorted_keys = sort sortStart keys %db if $re_sort;
 
+# GPU time accounting
+my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
+my (%submit_avg, %execute_avg, %ctxsave_avg);
+
 my $last_ts = 0;
 my $first_ts;
 my $min_ctx;

@@ -614,7 +663,11 @@ foreach my $key (@sorted_keys) {
 	}
 	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
 	$db{$key}->{'submit-delay'} = $db{$key}->{'submit'} - $db{$key}->{'queue'};
-	$db{$key}->{'duration'} = $notify - $start;
+	unless (exists $db{$key}->{'no-notify'}) {
+		$db{$key}->{'duration'} = $notify - $start;
+	} else {
+		$db{$key}->{'duration'} = 0;
+	}
 
 	$running{$ring} += $end - $start if $correct_durations or
 					    not exists $db{$key}->{'no-end'};

index 6379dace5743..5da5f5a14104 100755
@@ -438,7 +438,9 @@ while (<>) {
 	} elsif ($tp_name eq 'i915:i915_request_in:') {
 		my %req;
 
-		die if exists $db{$key};
+		# preemption
+		delete $db{$key} if exists $db{$key};
+
 		die unless exists $queue{$key};
 		die unless exists $submit{$key};
 

index 5da5f5a14104..de00fca0875e 100755
@@ -27,7 +27,7 @@ use warnings;
 use 5.010;
 
 my $gid = 0;
-my (%db, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait);
+my (%db, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait, %ctxtimelines);
 my @freqs;
 
 my $max_items = 3000;

@@ -448,6 +448,7 @@ while (<>) {
 		$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'};

@@ -603,41 +604,113 @@ sub sortStart {
 	return $val;
 }
 
-my @sorted_keys = sort sortStart keys %db;
-my $re_sort = 0;
+my $re_sort = 1;
+my @sorted_keys;
 
-die "Database changed size?!" unless scalar(@sorted_keys) == $key_count;
+sub maybe_sort_keys
+{
+	if ($re_sort) {
+		@sorted_keys = sort sortStart keys %db;
+		$re_sort = 0;
+		die "Database changed size?!" unless scalar(@sorted_keys) ==
+						     $key_count;
+	}
+}
 
-foreach my $key (@sorted_keys) {
-	my $ring = $db{$key}->{'ring'};
-	my $end = $db{$key}->{'end'};
+maybe_sort_keys();
+
+my %ctx_timelines;
+
+sub sortContext {
+	my $as = $db{$a}->{'seqno'};
+	my $bs = $db{$b}->{'seqno'};
+	my $val;
+
+	$val = $as <=> $bs;
+
+	die if $val == 0;
+
+	return $val;
+}
+
+sub get_ctx_timeline {
+	my ($ctx, $ring, $key) = @_;
+	my @timeline;
+
+	return $ctx_timelines{$key} if exists $ctx_timelines{$key};
+
+	@timeline = grep { $db{$_}->{'ring'} eq $ring and
+			   $db{$_}->{'ctx'} == $ctx } @sorted_keys;
+	# FIXME seqno restart
+	@timeline = sort sortContext @timeline;
+
+	$ctx_timelines{$key} = \@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'};
 
-	# correct duration of merged batches
-	if ($correct_durations and exists $db{$key}->{'no-end'}) {
-		my $ctx = $db{$key}->{'ctx'};
-		my $seqno = $db{$key}->{'seqno'};
-		my $start = $db{$key}->{'start'};
-		my $next_key;
-		my $i = 1;
-
-		do {
-			$next_key = db_key($ring, $ctx, $seqno + $i);
-			$i++;
-		} until (exists $db{$next_key} or $i > $key_count);  # ugly stop hack
-
-		# 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'} = $notify;
-			$db{$next_key}->{'start'} = $db{$next_key}->{'end'} if $db{$next_key}->{'start'} > $db{$next_key}->{'end'};
-			die if $db{$next_key}->{'start'} > $db{$next_key}->{'end'};
 		}
-		die if $start > $end;
+	}
+
+	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
+			$next_key = ${$timeline}[$pos + 1];
+			if (exists $db{$key}->{'notify'}) {
+				$db{$next_key}->{'engine-start'} = $db{$next_key}->{'start'};
+				$db{$next_key}->{'start'} = $db{$key}->{'notify'};
+				$re_sort = 1;
+			}
+		}
 	}
 }
 
-@sorted_keys = sort sortStart keys %db if $re_sort;
+maybe_sort_keys();
 
 # GPU time accounting
 my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);

@@ -651,6 +724,7 @@ foreach my $key (@sorted_keys) {
 	my $ring = $db{$key}->{'ring'};
 	my $end = $db{$key}->{'end'};
 	my $start = $db{$key}->{'start'};
+	my $engine_start = $db{$key}->{'engine_start'};
 	my $notify = $db{$key}->{'notify'};
 
 	$first_ts = $db{$key}->{'queue'} if not defined $first_ts or $db{$key}->{'queue'} < $first_ts;

@@ -663,7 +737,9 @@ foreach my $key (@sorted_keys) {
 	} else {
 		$db{$key}->{'context-complete-delay'} = 0;
 	}
-	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
+
+	$engine_start = $db{$key}->{'start'} unless defined $engine_start;
+	$db{$key}->{'execute-delay'} = $engine_start - $db{$key}->{'submit'};
 	$db{$key}->{'submit-delay'} = $db{$key}->{'submit'} - $db{$key}->{'queue'};
 	unless (exists $db{$key}->{'no-notify'}) {
 		$db{$key}->{'duration'} = $notify - $start;

@@ -1059,6 +1135,7 @@ my $i = 0;
 foreach my $key (sort sortQueue keys %db) {
 	my ($name, $ctx, $seqno) = ($db{$key}->{'name'}, $db{$key}->{'ctx'}, $db{$key}->{'seqno'});
 	my ($queue, $start, $notify, $end) = ($db{$key}->{'queue'}, $db{$key}->{'start'}, $db{$key}->{'notify'}, $db{$key}->{'end'});
+	my $engine_start = $db{$key}->{'engine-start'};
 	my $submit = $queue + $db{$key}->{'submit-delay'};
 	my ($content, $style);
 	my $group = $engine_start_id + $rings{$db{$key}->{'ring'}};

@@ -1078,11 +1155,12 @@ foreach my $key (sort sortQueue keys %db) {
 	}
 
 	# execute to start
+	$engine_start = $db{$key}->{'start'} unless defined $engine_start;
 	unless (exists $skip_box{'ready'}) {
 		$skey = 2 * $max_seqno * $ctx + 2 * $seqno + 1;
 		$style = box_style($ctx, 'ready');
 		$content = "<small>$name<br>$db{$key}->{'execute-delay'}us</small>";
-		$startend = 'start: \'' . ts($submit) . '\', end: \'' . ts($start) . '\'';
+		$startend = 'start: \'' . ts($submit) . '\', end: \'' . ts($engine_start) . '\'';
 		print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n";
 		$i++;
 	}