All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH i-g-t v3 0/4] trace.pl fixes
@ 2018-04-23  9:52 ` Tvrtko Ursulin
  0 siblings, 0 replies; 16+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23  9:52 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Remaining unreviewed (and one almost reviewed) patches to fix known outstanding
issues in trace.pl and improve its request split mode.

This will be useful for Virtual Engine development which is currently ongoing.

Tvrtko Ursulin (4):
  trace.pl: Add support for colouring context execution
  trace.pl: Fix engine busy accounting in split mode
  trace.pl: Fix incomplete request handling
  trace.pl: Fix request split mode

 scripts/trace.pl | 264 +++++++++++++++++++++++++++++++++++++++++++------------
 1 file changed, 210 insertions(+), 54 deletions(-)

-- 
2.14.1

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

^ permalink raw reply	[flat|nested] 16+ messages in thread
* [igt-dev] [PATCH i-g-t v3 0/4] trace.pl fixes
@ 2018-04-23  9:52 ` Tvrtko Ursulin
  0 siblings, 0 replies; 16+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23  9:52 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Remaining unreviewed (and one almost reviewed) patches to fix known outstanding
issues in trace.pl and improve its request split mode.

This will be useful for Virtual Engine development which is currently ongoing.

Tvrtko Ursulin (4):
  trace.pl: Add support for colouring context execution
  trace.pl: Fix engine busy accounting in split mode
  trace.pl: Fix incomplete request handling
  trace.pl: Fix request split mode

 scripts/trace.pl | 264 +++++++++++++++++++++++++++++++++++++++++++------------
 1 file changed, 210 insertions(+), 54 deletions(-)

-- 
2.14.1

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

^ permalink raw reply	[flat|nested] 16+ messages in thread
* [PATCH i-g-t 1/4] trace.pl: Add support for colouring context execution
  2018-04-23  9:52 ` [igt-dev] " Tvrtko Ursulin
@ 2018-04-23  9:52   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 16+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23  9:52 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Add the command line switch which uses different colours for different
context execution boxes.

v2:
 * Use HSL to simplify color generation. (Lionel)
 * Colour other boxes in the same colour but different shade so it is
   easier to follow the timeline.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: John Harrison <John.C.Harrison@intel.com>
Reviewed-by: Lionel Landwerlin <lionel.g.landwerlin@intel.com> # v1
---
 scripts/trace.pl | 54 ++++++++++++++++++++++++++++++++++++++++++++++++------
 1 file changed, 48 insertions(+), 6 deletions(-)

diff --git a/scripts/trace.pl b/scripts/trace.pl
index 27b39efcebbd..c8182a8ea86d 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -40,6 +40,7 @@ my $trace = 0;
 my $avg_delay_stats = 0;
 my $squash_context_id = 0;
 my $gpu_timeline = 0;
+my $colour_contexts = 0;
 
 my @args;
 
@@ -110,6 +111,8 @@ Usage:
       --squash-ctx-id			Squash context id by substracting engine
 					id from ctx id.
       --gpu-timeline			Draw overall GPU busy timeline.
+      --colour-contexts / -c		Use different colours for different
+					context execution boxes.
 ENDHELP
 
 		exit 0;
@@ -279,6 +282,20 @@ sub arg_skip_box
 	return @_;
 }
 
+sub arg_colour_contexts
+{
+	return unless scalar(@_);
+
+	if ($_[0] eq '--colour-contexts' or
+	    $_[0] eq '--color-contexts' or
+	    $_[0] eq '-c') {
+		shift @_;
+		$colour_contexts = 1;
+	}
+
+	return @_;
+}
+
 @args = @ARGV;
 while (@args) {
 	my $left = scalar(@args);
@@ -294,6 +311,7 @@ while (@args) {
 	@args = arg_split_requests(@args);
 	@args = arg_ignore_ring(@args);
 	@args = arg_skip_box(@args);
+	@args = arg_colour_contexts(@args);
 
 	last if $left == scalar(@args);
 }
@@ -581,6 +599,7 @@ foreach my $key (@sorted_keys) {
 
 my $last_ts = 0;
 my $first_ts;
+my ($min_ctx, $max_ctx);
 
 foreach my $key (@sorted_keys) {
 	my $ring = $db{$key}->{'ring'};
@@ -590,6 +609,10 @@ 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;
+	$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'};
@@ -720,6 +743,10 @@ foreach my $key (keys %reqwait) {
 say sprintf('GPU: %.2f%% idle, %.2f%% busy',
 	     $flat_busy{'gpu-idle'}, $flat_busy{'gpu-busy'}) unless $html;
 
+my $queued_colour = $colour_contexts ? 'multi-colour light' : 'blue';
+my $runnable_colour = $colour_contexts ? 'multi-colour dark' : 'grey';
+my $execute_colour = $colour_contexts ? 'multi-colour' : 'pink';
+
 print <<ENDHTML if $html;
 <!DOCTYPE HTML>
 <html>
@@ -740,9 +767,9 @@ print <<ENDHTML if $html;
 <button onclick="toggleStackSubgroups()">Toggle stacking</button>
 
 <p>
-pink = requests executing on the GPU<br>
-grey = runnable requests waiting for a slot on GPU<br>
-blue = requests waiting on fences and dependencies before they are runnable<br>
+$execute_colour = requests executing on the GPU<br>
+$runnable_colour = runnable requests waiting for a slot on GPU<br>
+$queued_colour = requests waiting on fences and dependencies before they are runnable<br>
 </p>
 <p>
 Boxes are in format 'ctx-id/seqno'.
@@ -860,6 +887,18 @@ sub sortQueue {
 	return $val;
 }
 
+sub ctx_colour
+{
+	my ($ctx, $s, $l) = (@_);
+	my $val;
+
+	return 'Pink;' unless $colour_contexts;
+
+	$val = int(360 / ($max_ctx - $min_ctx + 1)) * ($ctx - $min_ctx);
+
+	return "hsl($val, $s%, $l%);";
+}
+
 my $i = 0;
 foreach my $key (sort sortQueue keys %db) {
 	my ($name, $ctx, $seqno) = ($db{$key}->{'name'}, $db{$key}->{'ctx'}, $db{$key}->{'seqno'});
@@ -874,7 +913,8 @@ foreach my $key (sort sortQueue keys %db) {
 	# submit to execute
 	unless (exists $skip_box{'queue'}) {
 		$skey = 2 * $max_seqno * $ctx + 2 * $seqno;
-		$style = 'color: black; background-color: lightblue;';
+		$style = 'color: black; background-color: ' .
+			 ctx_colour($ctx, 35, 85);
 		$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";
@@ -884,7 +924,8 @@ foreach my $key (sort sortQueue keys %db) {
 	# execute to start
 	unless (exists $skip_box{'ready'}) {
 		$skey = 2 * $max_seqno * $ctx + 2 * $seqno + 1;
-		$style = 'color: black; background-color: lightgrey;';
+		$style = 'color: black; background-color: ' .
+			 ctx_colour($ctx, 35, 45);
 		$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";
@@ -897,7 +938,8 @@ foreach my $key (sort sortQueue keys %db) {
 		if (exists $db{$key}->{'incomplete'}) {
 			$style = 'color: white; background-color: red;';
 		} else {
-			$style = 'color: black; background-color: pink;';
+			$style = 'color: black; background-color: ' .
+				  ctx_colour($ctx, 80, 65);
 		}
 		$content = "$name <small>$db{$key}->{'port'}</small>";
 		$content .= ' <small><i>???</i></small> ' if exists $db{$key}->{'incomplete'};
-- 
2.14.1

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

^ permalink raw reply related	[flat|nested] 16+ messages in thread
* [igt-dev] [PATCH i-g-t 1/4] trace.pl: Add support for colouring context execution
@ 2018-04-23  9:52   ` Tvrtko Ursulin
  0 siblings, 0 replies; 16+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23  9:52 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Add the command line switch which uses different colours for different
context execution boxes.

v2:
 * Use HSL to simplify color generation. (Lionel)
 * Colour other boxes in the same colour but different shade so it is
   easier to follow the timeline.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: John Harrison <John.C.Harrison@intel.com>
Reviewed-by: Lionel Landwerlin <lionel.g.landwerlin@intel.com> # v1
---
 scripts/trace.pl | 54 ++++++++++++++++++++++++++++++++++++++++++++++++------
 1 file changed, 48 insertions(+), 6 deletions(-)

diff --git a/scripts/trace.pl b/scripts/trace.pl
index 27b39efcebbd..c8182a8ea86d 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -40,6 +40,7 @@ my $trace = 0;
 my $avg_delay_stats = 0;
 my $squash_context_id = 0;
 my $gpu_timeline = 0;
+my $colour_contexts = 0;
 
 my @args;
 
@@ -110,6 +111,8 @@ Usage:
       --squash-ctx-id			Squash context id by substracting engine
 					id from ctx id.
       --gpu-timeline			Draw overall GPU busy timeline.
+      --colour-contexts / -c		Use different colours for different
+					context execution boxes.
 ENDHELP
 
 		exit 0;
@@ -279,6 +282,20 @@ sub arg_skip_box
 	return @_;
 }
 
+sub arg_colour_contexts
+{
+	return unless scalar(@_);
+
+	if ($_[0] eq '--colour-contexts' or
+	    $_[0] eq '--color-contexts' or
+	    $_[0] eq '-c') {
+		shift @_;
+		$colour_contexts = 1;
+	}
+
+	return @_;
+}
+
 @args = @ARGV;
 while (@args) {
 	my $left = scalar(@args);
@@ -294,6 +311,7 @@ while (@args) {
 	@args = arg_split_requests(@args);
 	@args = arg_ignore_ring(@args);
 	@args = arg_skip_box(@args);
+	@args = arg_colour_contexts(@args);
 
 	last if $left == scalar(@args);
 }
@@ -581,6 +599,7 @@ foreach my $key (@sorted_keys) {
 
 my $last_ts = 0;
 my $first_ts;
+my ($min_ctx, $max_ctx);
 
 foreach my $key (@sorted_keys) {
 	my $ring = $db{$key}->{'ring'};
@@ -590,6 +609,10 @@ 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;
+	$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'};
@@ -720,6 +743,10 @@ foreach my $key (keys %reqwait) {
 say sprintf('GPU: %.2f%% idle, %.2f%% busy',
 	     $flat_busy{'gpu-idle'}, $flat_busy{'gpu-busy'}) unless $html;
 
+my $queued_colour = $colour_contexts ? 'multi-colour light' : 'blue';
+my $runnable_colour = $colour_contexts ? 'multi-colour dark' : 'grey';
+my $execute_colour = $colour_contexts ? 'multi-colour' : 'pink';
+
 print <<ENDHTML if $html;
 <!DOCTYPE HTML>
 <html>
@@ -740,9 +767,9 @@ print <<ENDHTML if $html;
 <button onclick="toggleStackSubgroups()">Toggle stacking</button>
 
 <p>
-pink = requests executing on the GPU<br>
-grey = runnable requests waiting for a slot on GPU<br>
-blue = requests waiting on fences and dependencies before they are runnable<br>
+$execute_colour = requests executing on the GPU<br>
+$runnable_colour = runnable requests waiting for a slot on GPU<br>
+$queued_colour = requests waiting on fences and dependencies before they are runnable<br>
 </p>
 <p>
 Boxes are in format 'ctx-id/seqno'.
@@ -860,6 +887,18 @@ sub sortQueue {
 	return $val;
 }
 
+sub ctx_colour
+{
+	my ($ctx, $s, $l) = (@_);
+	my $val;
+
+	return 'Pink;' unless $colour_contexts;
+
+	$val = int(360 / ($max_ctx - $min_ctx + 1)) * ($ctx - $min_ctx);
+
+	return "hsl($val, $s%, $l%);";
+}
+
 my $i = 0;
 foreach my $key (sort sortQueue keys %db) {
 	my ($name, $ctx, $seqno) = ($db{$key}->{'name'}, $db{$key}->{'ctx'}, $db{$key}->{'seqno'});
@@ -874,7 +913,8 @@ foreach my $key (sort sortQueue keys %db) {
 	# submit to execute
 	unless (exists $skip_box{'queue'}) {
 		$skey = 2 * $max_seqno * $ctx + 2 * $seqno;
-		$style = 'color: black; background-color: lightblue;';
+		$style = 'color: black; background-color: ' .
+			 ctx_colour($ctx, 35, 85);
 		$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";
@@ -884,7 +924,8 @@ foreach my $key (sort sortQueue keys %db) {
 	# execute to start
 	unless (exists $skip_box{'ready'}) {
 		$skey = 2 * $max_seqno * $ctx + 2 * $seqno + 1;
-		$style = 'color: black; background-color: lightgrey;';
+		$style = 'color: black; background-color: ' .
+			 ctx_colour($ctx, 35, 45);
 		$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";
@@ -897,7 +938,8 @@ foreach my $key (sort sortQueue keys %db) {
 		if (exists $db{$key}->{'incomplete'}) {
 			$style = 'color: white; background-color: red;';
 		} else {
-			$style = 'color: black; background-color: pink;';
+			$style = 'color: black; background-color: ' .
+				  ctx_colour($ctx, 80, 65);
 		}
 		$content = "$name <small>$db{$key}->{'port'}</small>";
 		$content .= ' <small><i>???</i></small> ' if exists $db{$key}->{'incomplete'};
-- 
2.14.1

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

^ permalink raw reply related	[flat|nested] 16+ messages in thread
* [PATCH i-g-t 2/4] trace.pl: Fix engine busy accounting in split mode
  2018-04-23  9:52 ` [igt-dev] " Tvrtko Ursulin
@ 2018-04-23  9:52   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 16+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23  9:52 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

In split mode all requests have to be added up since they were previously
re-arranged so there is no overlap.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: John Harrison <John.C.Harrison@intel.com>
---
 scripts/trace.pl | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/scripts/trace.pl b/scripts/trace.pl
index c8182a8ea86d..eb5a36b91a5c 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -619,7 +619,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'};
 
-- 
2.14.1

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

^ permalink raw reply related	[flat|nested] 16+ messages in thread
* [igt-dev] [PATCH i-g-t 2/4] trace.pl: Fix engine busy accounting in split mode
@ 2018-04-23  9:52   ` Tvrtko Ursulin
  0 siblings, 0 replies; 16+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23  9:52 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

In split mode all requests have to be added up since they were previously
re-arranged so there is no overlap.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: John Harrison <John.C.Harrison@intel.com>
---
 scripts/trace.pl | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/scripts/trace.pl b/scripts/trace.pl
index c8182a8ea86d..eb5a36b91a5c 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -619,7 +619,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'};
 
-- 
2.14.1

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

^ permalink raw reply related	[flat|nested] 16+ messages in thread
* [PATCH i-g-t 3/4] trace.pl: Fix incomplete request handling
  2018-04-23  9:52 ` [igt-dev] " Tvrtko Ursulin
@ 2018-04-23  9:52   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 16+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23  9:52 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Incomplete requests (no notify, no context complete) have to be corrected
by looking at the engine timeline, and not the sorted-by-start-time view
as was previously used.

Per-engine timelines are generated on demand and cached for later use.

v2: Find end of current context on the engine timeline instead of just
    using the next request for adjusting the incomplete start time.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: John Harrison <John.C.Harrison@intel.com>
---
 scripts/trace.pl | 86 ++++++++++++++++++++++++++++++++++++++++++--------------
 1 file changed, 65 insertions(+), 21 deletions(-)

diff --git a/scripts/trace.pl b/scripts/trace.pl
index eb5a36b91a5c..b48f43225fc1 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -26,6 +26,8 @@ use strict;
 use warnings;
 use 5.010;
 
+use List::Util;
+
 my $gid = 0;
 my (%db, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait);
 my @freqs;
@@ -516,29 +518,71 @@ foreach my $key (keys %db) {
 	}
 }
 
-# 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 %engine_timelines;
+
+sub sortEngine {
+	my $as = $db{$a}->{'global'};
+	my $bs = $db{$b}->{'global'};
+	my $val;
+
+	$val = $as <=> $bs;
+
+	die if $val == 0;
+
+	return $val;
+}
+
+sub get_engine_timeline {
+	my ($ring) = @_;
+	my @timeline;
+
+	return $engine_timelines{$ring} if exists $engine_timelines{$ring};
+
+	@timeline = grep { $db{$_}->{'ring'} == $ring } keys %db;
+	# FIXME seqno restart
+	@timeline = sort sortEngine @timeline;
+
+	$engine_timelines{$ring} = \@timeline;
+
+	return \@timeline;
+}
+
+# Fix up incompletes by ending them when the last request of a coalesced group
+# ends. Start by filtering out the incomplete requests.
+my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
+
+foreach my $key (@incompletes) {
+	my $timeline;
+	my $last_key;
 	my $end;
+	my $i;
 
-	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
+	# Find the next request on the engine timeline.
+	$timeline = get_engine_timeline($db{$key}->{'ring'});
+	$i = List::Util::first { ${$timeline}[$_] eq $key } 0..$#{$timeline};
+
+	while ($i < $#{$timeline}) {
+		my $next;
+
+		$i = $i + 1;
+		$next = ${$timeline}[$i];
+
+		next if exists $db{$next}->{'incomplete'};
 
-	if (exists $db{$next_key}) {
-		$end = $db{$next_key}->{'end'};
+		$last_key = $next;
+		last;
+	}
+
+	if (defined $last_key) {
+		if ($db{$key}->{'ctx'} eq $db{$last_key}->{'ctx'}) {
+			$end = $db{$last_key}->{'end'};
+		} else {
+			$end = $db{$last_key}->{'start'};
+		}
 	} else {
-		# No info at all, fake it:
+		# No next submission, fake it.
 		$end = $db{$key}->{'start'} + 999;
 	}
 
@@ -546,10 +590,6 @@ foreach my $key (keys %db) {
 	$db{$key}->{'end'} = $end;
 }
 
-# GPU time accounting
-my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
-my (%submit_avg, %execute_avg, %ctxsave_avg);
-
 sub sortStart {
 	my $as = $db{$a}->{'start'};
 	my $bs = $db{$b}->{'start'};
@@ -597,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, $max_ctx);
-- 
2.14.1

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

^ permalink raw reply related	[flat|nested] 16+ messages in thread
* [igt-dev] [PATCH i-g-t 3/4] trace.pl: Fix incomplete request handling
@ 2018-04-23  9:52   ` Tvrtko Ursulin
  0 siblings, 0 replies; 16+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23  9:52 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Incomplete requests (no notify, no context complete) have to be corrected
by looking at the engine timeline, and not the sorted-by-start-time view
as was previously used.

Per-engine timelines are generated on demand and cached for later use.

v2: Find end of current context on the engine timeline instead of just
    using the next request for adjusting the incomplete start time.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: John Harrison <John.C.Harrison@intel.com>
---
 scripts/trace.pl | 86 ++++++++++++++++++++++++++++++++++++++++++--------------
 1 file changed, 65 insertions(+), 21 deletions(-)

diff --git a/scripts/trace.pl b/scripts/trace.pl
index eb5a36b91a5c..b48f43225fc1 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -26,6 +26,8 @@ use strict;
 use warnings;
 use 5.010;
 
+use List::Util;
+
 my $gid = 0;
 my (%db, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait);
 my @freqs;
@@ -516,29 +518,71 @@ foreach my $key (keys %db) {
 	}
 }
 
-# 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 %engine_timelines;
+
+sub sortEngine {
+	my $as = $db{$a}->{'global'};
+	my $bs = $db{$b}->{'global'};
+	my $val;
+
+	$val = $as <=> $bs;
+
+	die if $val == 0;
+
+	return $val;
+}
+
+sub get_engine_timeline {
+	my ($ring) = @_;
+	my @timeline;
+
+	return $engine_timelines{$ring} if exists $engine_timelines{$ring};
+
+	@timeline = grep { $db{$_}->{'ring'} == $ring } keys %db;
+	# FIXME seqno restart
+	@timeline = sort sortEngine @timeline;
+
+	$engine_timelines{$ring} = \@timeline;
+
+	return \@timeline;
+}
+
+# Fix up incompletes by ending them when the last request of a coalesced group
+# ends. Start by filtering out the incomplete requests.
+my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
+
+foreach my $key (@incompletes) {
+	my $timeline;
+	my $last_key;
 	my $end;
+	my $i;
 
-	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
+	# Find the next request on the engine timeline.
+	$timeline = get_engine_timeline($db{$key}->{'ring'});
+	$i = List::Util::first { ${$timeline}[$_] eq $key } 0..$#{$timeline};
+
+	while ($i < $#{$timeline}) {
+		my $next;
+
+		$i = $i + 1;
+		$next = ${$timeline}[$i];
+
+		next if exists $db{$next}->{'incomplete'};
 
-	if (exists $db{$next_key}) {
-		$end = $db{$next_key}->{'end'};
+		$last_key = $next;
+		last;
+	}
+
+	if (defined $last_key) {
+		if ($db{$key}->{'ctx'} eq $db{$last_key}->{'ctx'}) {
+			$end = $db{$last_key}->{'end'};
+		} else {
+			$end = $db{$last_key}->{'start'};
+		}
 	} else {
-		# No info at all, fake it:
+		# No next submission, fake it.
 		$end = $db{$key}->{'start'} + 999;
 	}
 
@@ -546,10 +590,6 @@ foreach my $key (keys %db) {
 	$db{$key}->{'end'} = $end;
 }
 
-# GPU time accounting
-my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
-my (%submit_avg, %execute_avg, %ctxsave_avg);
-
 sub sortStart {
 	my $as = $db{$a}->{'start'};
 	my $bs = $db{$b}->{'start'};
@@ -597,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, $max_ctx);
-- 
2.14.1

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

^ permalink raw reply related	[flat|nested] 16+ messages in thread
* [PATCH i-g-t 4/4] trace.pl: Fix request split mode
  2018-04-23  9:52 ` [igt-dev] " Tvrtko Ursulin
@ 2018-04-23  9:52   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 16+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23  9:52 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Request split mode had several bugs, both in the original version and also
after the recent refactorings.

One big one was that it wasn't considering different submit ports as a
reason to split execution, and also that it was too time based instead of
looking at relevant timelines.

In this refactoring we address the former by using the engine timelines
introduced in the previous patch. Secondary port submissions are moved
to follow the preceding submission as a first step in the correction
process.

In the second step, we add context timelines and use then in a similar
fashion to separate start and end time of coalesced requests. For each
coalesced request we know its boundaries by looking at the engine
timeline (via global seqnos), and we know the previous request it should
only start after, by looking at the context timeline.

v2:
 * Remove some dead code.
 * Fix !port0 shifting logic.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: John Harrison <John.C.Harrison@intel.com>
---
 scripts/trace.pl | 121 +++++++++++++++++++++++++++++++++++++++++++------------
 1 file changed, 95 insertions(+), 26 deletions(-)

diff --git a/scripts/trace.pl b/scripts/trace.pl
index b48f43225fc1..88aa667df2d4 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -601,41 +601,110 @@ 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;
 
-	# correct duration of merged batches
-	if ($correct_durations and exists $db{$key}->{'no-end'}) {
+	return $ctx_timelines{$key} if exists $ctx_timelines{$key};
+
+	@timeline = grep { $db{$_}->{'ring'} == $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) {
+	my @port1;
+	my @no_end;
+
+	# Shift !port0 requests start time to after the previous context on the
+	# same timeline has finished.
+	@port1 = grep { $db{$_}->{'port'} != 0 } @sorted_keys;
+	foreach my $key (@port1) {
+		my $timeline = get_engine_timeline($db{$key}->{'ring'});
+		my $i = List::Util::first { ${$timeline}[$_] eq $key } 0..$#{$timeline};
+		my $prev_key;
+		my $start;
+
+		while ($i > 0) {
+			my $prev;
+
+			$i = $i - 1;
+			$prev = ${$timeline}[$i];
+
+			next if exists $db{$prev}->{'no-end'};
+
+			$prev_key = $prev;
+			last;
+		}
+
+		$start = $db{$prev_key}->{'end'};
+		$db{$key}->{'start'} = $start;
+		die if $start > $db{$key}->{'end'};
+
+		$re_sort = 1;
+	}
+
+	maybe_sort_keys();
+
+	# Batch with no-end (no request_out) means it was submitted as part of
+	# colaesced context. This means it's start time should be set to the end
+	# time of a precedeing request on this timeline.
+	@no_end = grep { exists $db{$_}->{'no-end'} } @sorted_keys;
+	foreach my $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'};
+		my $ring = $db{$key}->{'ring'};
+		my $tkey = $ctx . '/' . $ring;
+		my $timeline = get_ctx_timeline($ctx, $ring, $tkey);
+		my $i;
+
+		$i = List::Util::first { ${$timeline}[$_] eq $key } 0..$#{$timeline};
+
+		# Shift following request to start after the current one.
+		if ($i < $#{$timeline}) {
+			my $next_key = ${$timeline}[$i + 1];
+
+			$db{$next_key}->{'start'} = $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;
 	}
 }
 
-@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);
-- 
2.14.1

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

^ permalink raw reply related	[flat|nested] 16+ messages in thread
* [igt-dev] [PATCH i-g-t 4/4] trace.pl: Fix request split mode
@ 2018-04-23  9:52   ` Tvrtko Ursulin
  0 siblings, 0 replies; 16+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23  9:52 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin

From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Request split mode had several bugs, both in the original version and also
after the recent refactorings.

One big one was that it wasn't considering different submit ports as a
reason to split execution, and also that it was too time based instead of
looking at relevant timelines.

In this refactoring we address the former by using the engine timelines
introduced in the previous patch. Secondary port submissions are moved
to follow the preceding submission as a first step in the correction
process.

In the second step, we add context timelines and use then in a similar
fashion to separate start and end time of coalesced requests. For each
coalesced request we know its boundaries by looking at the engine
timeline (via global seqnos), and we know the previous request it should
only start after, by looking at the context timeline.

v2:
 * Remove some dead code.
 * Fix !port0 shifting logic.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: John Harrison <John.C.Harrison@intel.com>
---
 scripts/trace.pl | 121 +++++++++++++++++++++++++++++++++++++++++++------------
 1 file changed, 95 insertions(+), 26 deletions(-)

diff --git a/scripts/trace.pl b/scripts/trace.pl
index b48f43225fc1..88aa667df2d4 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -601,41 +601,110 @@ 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;
 
-	# correct duration of merged batches
-	if ($correct_durations and exists $db{$key}->{'no-end'}) {
+	return $ctx_timelines{$key} if exists $ctx_timelines{$key};
+
+	@timeline = grep { $db{$_}->{'ring'} == $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) {
+	my @port1;
+	my @no_end;
+
+	# Shift !port0 requests start time to after the previous context on the
+	# same timeline has finished.
+	@port1 = grep { $db{$_}->{'port'} != 0 } @sorted_keys;
+	foreach my $key (@port1) {
+		my $timeline = get_engine_timeline($db{$key}->{'ring'});
+		my $i = List::Util::first { ${$timeline}[$_] eq $key } 0..$#{$timeline};
+		my $prev_key;
+		my $start;
+
+		while ($i > 0) {
+			my $prev;
+
+			$i = $i - 1;
+			$prev = ${$timeline}[$i];
+
+			next if exists $db{$prev}->{'no-end'};
+
+			$prev_key = $prev;
+			last;
+		}
+
+		$start = $db{$prev_key}->{'end'};
+		$db{$key}->{'start'} = $start;
+		die if $start > $db{$key}->{'end'};
+
+		$re_sort = 1;
+	}
+
+	maybe_sort_keys();
+
+	# Batch with no-end (no request_out) means it was submitted as part of
+	# colaesced context. This means it's start time should be set to the end
+	# time of a precedeing request on this timeline.
+	@no_end = grep { exists $db{$_}->{'no-end'} } @sorted_keys;
+	foreach my $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'};
+		my $ring = $db{$key}->{'ring'};
+		my $tkey = $ctx . '/' . $ring;
+		my $timeline = get_ctx_timeline($ctx, $ring, $tkey);
+		my $i;
+
+		$i = List::Util::first { ${$timeline}[$_] eq $key } 0..$#{$timeline};
+
+		# Shift following request to start after the current one.
+		if ($i < $#{$timeline}) {
+			my $next_key = ${$timeline}[$i + 1];
+
+			$db{$next_key}->{'start'} = $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;
 	}
 }
 
-@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);
-- 
2.14.1

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

^ permalink raw reply related	[flat|nested] 16+ messages in thread
* [igt-dev] ✓ Fi.CI.BAT: success for trace.pl fixes (rev3)
  2018-04-23  9:52 ` [igt-dev] " Tvrtko Ursulin
                   ` (4 preceding siblings ...)
  (?)
@ 2018-04-23 14:46 ` Patchwork
  -1 siblings, 0 replies; 16+ messages in thread
From: Patchwork @ 2018-04-23 14:46 UTC (permalink / raw)
  To: Tvrtko Ursulin; +Cc: igt-dev

== Series Details ==

Series: trace.pl fixes (rev3)
URL   : https://patchwork.freedesktop.org/series/37330/
State : success

== Summary ==

= CI Bug Log - changes from CI_DRM_4078 -> IGTPW_1290 =

== Summary - SUCCESS ==

  No regressions found.

  External URL: https://patchwork.freedesktop.org/api/1.0/series/37330/revisions/3/mbox/

== Known issues ==

  Here are the changes found in IGTPW_1290 that come from known issues:

  === IGT changes ===

    ==== Issues hit ====

    igt@kms_pipe_crc_basic@nonblocking-crc-pipe-a-frame-sequence:
      fi-elk-e7500:       PASS -> INCOMPLETE (fdo#103989)

    igt@kms_pipe_crc_basic@read-crc-pipe-b-frame-sequence:
      fi-glk-j4005:       PASS -> DMESG-WARN (fdo#106097) +2

    igt@kms_pipe_crc_basic@suspend-read-crc-pipe-b:
      fi-cnl-psr:         PASS -> DMESG-WARN (fdo#104951) +1

    
    ==== Possible fixes ====

    igt@kms_pipe_crc_basic@suspend-read-crc-pipe-c:
      fi-ivb-3520m:       DMESG-WARN (fdo#106084) -> PASS

    
  fdo#103989 https://bugs.freedesktop.org/show_bug.cgi?id=103989
  fdo#104951 https://bugs.freedesktop.org/show_bug.cgi?id=104951
  fdo#106084 https://bugs.freedesktop.org/show_bug.cgi?id=106084
  fdo#106097 https://bugs.freedesktop.org/show_bug.cgi?id=106097


== Participating hosts (36 -> 32) ==

  Missing    (4): fi-byt-j1900 fi-ctg-p8600 fi-ilk-m540 fi-skl-6700hq 


== Build changes ==

    * IGT: IGT_4444 -> IGTPW_1290

  CI_DRM_4078: 9391010824b34ec58217f816ba5e314e7312191d @ git://anongit.freedesktop.org/gfx-ci/linux
  IGTPW_1290: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_1290/
  IGT_4444: dcc44347494231feabc588c2a76998cbc9afdf8c @ git://anongit.freedesktop.org/xorg/app/intel-gpu-tools
  piglit_4444: a2f486679f467cd6e82578384f56d4aabaa8cf2e @ git://anongit.freedesktop.org/piglit

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_1290/issues.html
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

^ permalink raw reply	[flat|nested] 16+ messages in thread
* [igt-dev] ✓ Fi.CI.IGT: success for trace.pl fixes (rev3)
  2018-04-23  9:52 ` [igt-dev] " Tvrtko Ursulin
                   ` (5 preceding siblings ...)
  (?)
@ 2018-04-23 18:20 ` Patchwork
  -1 siblings, 0 replies; 16+ messages in thread
From: Patchwork @ 2018-04-23 18:20 UTC (permalink / raw)
  To: Tvrtko Ursulin; +Cc: igt-dev

== Series Details ==

Series: trace.pl fixes (rev3)
URL   : https://patchwork.freedesktop.org/series/37330/
State : success

== Summary ==

= CI Bug Log - changes from IGT_4444_full -> IGTPW_1290_full =

== Summary - WARNING ==

  Minor unknown changes coming with IGTPW_1290_full need to be verified
  manually.
  
  If you think the reported changes have nothing to do with the changes
  introduced in IGTPW_1290_full, please notify your bug team to allow them
  to document this new failure mode, which will reduce false positives in CI.

  External URL: https://patchwork.freedesktop.org/api/1.0/series/37330/revisions/3/mbox/

== Possible new issues ==

  Here are the unknown changes that may have been introduced in IGTPW_1290_full:

  === IGT changes ===

    ==== Warnings ====

    igt@gem_exec_schedule@deep-blt:
      shard-kbl:          PASS -> SKIP +1

    igt@gem_mocs_settings@mocs-rc6-blt:
      shard-kbl:          SKIP -> PASS +1

    
== Known issues ==

  Here are the changes found in IGTPW_1290_full that come from known issues:

  === IGT changes ===

    ==== Issues hit ====

    igt@kms_cursor_crc@cursor-128x128-suspend:
      shard-kbl:          PASS -> INCOMPLETE (fdo#103665, fdo#106024)

    igt@kms_flip@2x-flip-vs-expired-vblank-interruptible:
      shard-hsw:          PASS -> FAIL (fdo#102887)

    igt@kms_flip@absolute-wf_vblank-interruptible:
      shard-apl:          PASS -> FAIL (fdo#106087)

    igt@kms_flip@plain-flip-ts-check-interruptible:
      shard-hsw:          PASS -> FAIL (fdo#103928)

    igt@kms_plane_multiple@atomic-pipe-a-tiling-x:
      shard-snb:          PASS -> FAIL (fdo#103166)

    
    ==== Possible fixes ====

    igt@kms_flip@2x-dpms-vs-vblank-race:
      shard-hsw:          FAIL (fdo#103060) -> PASS

    igt@kms_flip@2x-plain-flip-ts-check-interruptible:
      shard-hsw:          FAIL (fdo#100368) -> PASS

    
  fdo#100368 https://bugs.freedesktop.org/show_bug.cgi?id=100368
  fdo#102887 https://bugs.freedesktop.org/show_bug.cgi?id=102887
  fdo#103060 https://bugs.freedesktop.org/show_bug.cgi?id=103060
  fdo#103166 https://bugs.freedesktop.org/show_bug.cgi?id=103166
  fdo#103665 https://bugs.freedesktop.org/show_bug.cgi?id=103665
  fdo#103928 https://bugs.freedesktop.org/show_bug.cgi?id=103928
  fdo#106024 https://bugs.freedesktop.org/show_bug.cgi?id=106024
  fdo#106087 https://bugs.freedesktop.org/show_bug.cgi?id=106087


== Participating hosts (5 -> 4) ==

  Missing    (1): shard-glkb 


== Build changes ==

    * IGT: IGT_4444 -> IGTPW_1290
    * Linux: CI_DRM_4076 -> CI_DRM_4078

  CI_DRM_4076: 01b171f6df7b2b55b3c1b851d40741179fa2a722 @ git://anongit.freedesktop.org/gfx-ci/linux
  CI_DRM_4078: 9391010824b34ec58217f816ba5e314e7312191d @ git://anongit.freedesktop.org/gfx-ci/linux
  IGTPW_1290: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_1290/
  IGT_4444: dcc44347494231feabc588c2a76998cbc9afdf8c @ git://anongit.freedesktop.org/xorg/app/intel-gpu-tools
  piglit_4444: a2f486679f467cd6e82578384f56d4aabaa8cf2e @ git://anongit.freedesktop.org/piglit

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_1290/shards.html
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

^ permalink raw reply	[flat|nested] 16+ messages in thread
* Re: [PATCH i-g-t 3/4] trace.pl: Fix incomplete request handling
  2018-04-23  9:52   ` [igt-dev] " Tvrtko Ursulin
@ 2018-05-07 23:58     ` John Harrison
  -1 siblings, 0 replies; 16+ messages in thread
From: John Harrison @ 2018-05-07 23:58 UTC (permalink / raw)
  To: Tvrtko Ursulin, igt-dev; +Cc: Intel-gfx

On 4/23/2018 2:52 AM, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>
> Incomplete requests (no notify, no context complete) have to be corrected
> by looking at the engine timeline, and not the sorted-by-start-time view
> as was previously used.
>
> Per-engine timelines are generated on demand and cached for later use.
>
> v2: Find end of current context on the engine timeline instead of just
>      using the next request for adjusting the incomplete start time.
>
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> Cc: John Harrison <John.C.Harrison@intel.com>
> ---
>   scripts/trace.pl | 86 ++++++++++++++++++++++++++++++++++++++++++--------------
>   1 file changed, 65 insertions(+), 21 deletions(-)
>
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index eb5a36b91a5c..b48f43225fc1 100755
> --- a/scripts/trace.pl
> +++ b/scripts/trace.pl
> @@ -26,6 +26,8 @@ use strict;
>   use warnings;
>   use 5.010;
>   
> +use List::Util;
> +
>   my $gid = 0;
>   my (%db, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait);
>   my @freqs;
> @@ -516,29 +518,71 @@ foreach my $key (keys %db) {
>   	}
>   }
>   
> -# 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 %engine_timelines;
> +
> +sub sortEngine {
> +	my $as = $db{$a}->{'global'};
> +	my $bs = $db{$b}->{'global'};
> +	my $val;
> +
> +	$val = $as <=> $bs;
> +
> +	die if $val == 0;
> +
> +	return $val;
> +}
> +
> +sub get_engine_timeline {
> +	my ($ring) = @_;
> +	my @timeline;
> +
> +	return $engine_timelines{$ring} if exists $engine_timelines{$ring};
> +
> +	@timeline = grep { $db{$_}->{'ring'} == $ring } keys %db;
> +	# FIXME seqno restart
> +	@timeline = sort sortEngine @timeline;
> +
> +	$engine_timelines{$ring} = \@timeline;
> +
> +	return \@timeline;
> +}
> +
> +# Fix up incompletes by ending them when the last request of a coalesced group
> +# ends. Start by filtering out the incomplete requests.
> +my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
> +
> +foreach my $key (@incompletes) {
> +	my $timeline;
> +	my $last_key;
>   	my $end;
> +	my $i;
>   
> -	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
> +	# Find the next request on the engine timeline.
> +	$timeline = get_engine_timeline($db{$key}->{'ring'});
> +	$i = List::Util::first { ${$timeline}[$_] eq $key } 0..$#{$timeline};
This line in particular massively slows the process down! With one of my 
longer trace files, the incomplete fix-up step took 30 seconds prior to 
this. After this patch, it took 11205 seconds! Just shy of four hours!

Caching the start point of the search greatly speeds things up but it is 
still a lot slower than previous. With the following, it is down to 4068 
seconds, or a little over one hour.
+my $lastIndex = 0;
...
-       $i = List::Util::first { ${$timeline}[$_] eq $key } 
0..$#{$timeline};
+       $i = List::Util::first { ${$timeline}[$_] eq $key } 
${lastIndex}..$#{$timeline};
+       if( !defined($i) ) {
+               $i = List::Util::first { ${$timeline}[$_] eq $key } 
0..$#{$timeline};
+               defined($i) || die "Failed to find '$key'!\n";
+       }
+       $lastIndex = $i;

If I sort the '@incompletes' array numerically by seqno rather than as a 
string sort, then I get rid of all the first level match failures 
(except when rolling from one ring to the next) and the time drops to 
1819 seconds or half an hour.

+sub sortKeys {
+       my( $aR, $aC, $aS ) = split( '/', $a );
+       my( $bR, $bC, $bS ) = split( '/', $b );
+       my $val;
+
+       $val = $aR <=> $bR;
+       return $val if $val != 0;
+
+       $val = $aC <=> $bC;
+       return $val if $val != 0;
+
+       return $aS <=> $bS;
+}
+

-my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
+my @incompletes = sort sortKeys grep { exists $db{$_}->{'incomplete'} } 
keys %db;



> +
> +	while ($i < $#{$timeline}) {
> +		my $next;
> +
> +		$i = $i + 1;
$i++; ?

> +		$next = ${$timeline}[$i];
> +
> +		next if exists $db{$next}->{'incomplete'};
>   
> -	if (exists $db{$next_key}) {
> -		$end = $db{$next_key}->{'end'};
> +		$last_key = $next;
> +		last;
> +	}
> +
> +	if (defined $last_key) {
> +		if ($db{$key}->{'ctx'} eq $db{$last_key}->{'ctx'}) {
> +			$end = $db{$last_key}->{'end'};
> +		} else {
> +			$end = $db{$last_key}->{'start'};
> +		}
>   	} else {
> -		# No info at all, fake it:
> +		# No next submission, fake it.
>   		$end = $db{$key}->{'start'} + 999;
>   	}
>   
> @@ -546,10 +590,6 @@ foreach my $key (keys %db) {
>   	$db{$key}->{'end'} = $end;
>   }
>   
> -# GPU time accounting
> -my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
> -my (%submit_avg, %execute_avg, %ctxsave_avg);
> -
>   sub sortStart {
>   	my $as = $db{$a}->{'start'};
>   	my $bs = $db{$b}->{'start'};
> @@ -597,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);
> +

This is just a prettification type change? Moving declarations to be 
more local to their usage? It doesn't seem to be related to the above 
changes or explicitly mentioned in the commit message.

>   my $last_ts = 0;
>   my $first_ts;
>   my ($min_ctx, $max_ctx);

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

^ permalink raw reply	[flat|nested] 16+ messages in thread
* Re: [igt-dev] [PATCH i-g-t 3/4] trace.pl: Fix incomplete request handling
@ 2018-05-07 23:58     ` John Harrison
  0 siblings, 0 replies; 16+ messages in thread
From: John Harrison @ 2018-05-07 23:58 UTC (permalink / raw)
  To: Tvrtko Ursulin, igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin

On 4/23/2018 2:52 AM, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>
> Incomplete requests (no notify, no context complete) have to be corrected
> by looking at the engine timeline, and not the sorted-by-start-time view
> as was previously used.
>
> Per-engine timelines are generated on demand and cached for later use.
>
> v2: Find end of current context on the engine timeline instead of just
>      using the next request for adjusting the incomplete start time.
>
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> Cc: John Harrison <John.C.Harrison@intel.com>
> ---
>   scripts/trace.pl | 86 ++++++++++++++++++++++++++++++++++++++++++--------------
>   1 file changed, 65 insertions(+), 21 deletions(-)
>
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index eb5a36b91a5c..b48f43225fc1 100755
> --- a/scripts/trace.pl
> +++ b/scripts/trace.pl
> @@ -26,6 +26,8 @@ use strict;
>   use warnings;
>   use 5.010;
>   
> +use List::Util;
> +
>   my $gid = 0;
>   my (%db, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait);
>   my @freqs;
> @@ -516,29 +518,71 @@ foreach my $key (keys %db) {
>   	}
>   }
>   
> -# 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 %engine_timelines;
> +
> +sub sortEngine {
> +	my $as = $db{$a}->{'global'};
> +	my $bs = $db{$b}->{'global'};
> +	my $val;
> +
> +	$val = $as <=> $bs;
> +
> +	die if $val == 0;
> +
> +	return $val;
> +}
> +
> +sub get_engine_timeline {
> +	my ($ring) = @_;
> +	my @timeline;
> +
> +	return $engine_timelines{$ring} if exists $engine_timelines{$ring};
> +
> +	@timeline = grep { $db{$_}->{'ring'} == $ring } keys %db;
> +	# FIXME seqno restart
> +	@timeline = sort sortEngine @timeline;
> +
> +	$engine_timelines{$ring} = \@timeline;
> +
> +	return \@timeline;
> +}
> +
> +# Fix up incompletes by ending them when the last request of a coalesced group
> +# ends. Start by filtering out the incomplete requests.
> +my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
> +
> +foreach my $key (@incompletes) {
> +	my $timeline;
> +	my $last_key;
>   	my $end;
> +	my $i;
>   
> -	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
> +	# Find the next request on the engine timeline.
> +	$timeline = get_engine_timeline($db{$key}->{'ring'});
> +	$i = List::Util::first { ${$timeline}[$_] eq $key } 0..$#{$timeline};
This line in particular massively slows the process down! With one of my 
longer trace files, the incomplete fix-up step took 30 seconds prior to 
this. After this patch, it took 11205 seconds! Just shy of four hours!

Caching the start point of the search greatly speeds things up but it is 
still a lot slower than previous. With the following, it is down to 4068 
seconds, or a little over one hour.
+my $lastIndex = 0;
...
-       $i = List::Util::first { ${$timeline}[$_] eq $key } 
0..$#{$timeline};
+       $i = List::Util::first { ${$timeline}[$_] eq $key } 
${lastIndex}..$#{$timeline};
+       if( !defined($i) ) {
+               $i = List::Util::first { ${$timeline}[$_] eq $key } 
0..$#{$timeline};
+               defined($i) || die "Failed to find '$key'!\n";
+       }
+       $lastIndex = $i;

If I sort the '@incompletes' array numerically by seqno rather than as a 
string sort, then I get rid of all the first level match failures 
(except when rolling from one ring to the next) and the time drops to 
1819 seconds or half an hour.

+sub sortKeys {
+       my( $aR, $aC, $aS ) = split( '/', $a );
+       my( $bR, $bC, $bS ) = split( '/', $b );
+       my $val;
+
+       $val = $aR <=> $bR;
+       return $val if $val != 0;
+
+       $val = $aC <=> $bC;
+       return $val if $val != 0;
+
+       return $aS <=> $bS;
+}
+

-my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
+my @incompletes = sort sortKeys grep { exists $db{$_}->{'incomplete'} } 
keys %db;



> +
> +	while ($i < $#{$timeline}) {
> +		my $next;
> +
> +		$i = $i + 1;
$i++; ?

> +		$next = ${$timeline}[$i];
> +
> +		next if exists $db{$next}->{'incomplete'};
>   
> -	if (exists $db{$next_key}) {
> -		$end = $db{$next_key}->{'end'};
> +		$last_key = $next;
> +		last;
> +	}
> +
> +	if (defined $last_key) {
> +		if ($db{$key}->{'ctx'} eq $db{$last_key}->{'ctx'}) {
> +			$end = $db{$last_key}->{'end'};
> +		} else {
> +			$end = $db{$last_key}->{'start'};
> +		}
>   	} else {
> -		# No info at all, fake it:
> +		# No next submission, fake it.
>   		$end = $db{$key}->{'start'} + 999;
>   	}
>   
> @@ -546,10 +590,6 @@ foreach my $key (keys %db) {
>   	$db{$key}->{'end'} = $end;
>   }
>   
> -# GPU time accounting
> -my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
> -my (%submit_avg, %execute_avg, %ctxsave_avg);
> -
>   sub sortStart {
>   	my $as = $db{$a}->{'start'};
>   	my $bs = $db{$b}->{'start'};
> @@ -597,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);
> +

This is just a prettification type change? Moving declarations to be 
more local to their usage? It doesn't seem to be related to the above 
changes or explicitly mentioned in the commit message.

>   my $last_ts = 0;
>   my $first_ts;
>   my ($min_ctx, $max_ctx);

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

^ permalink raw reply	[flat|nested] 16+ messages in thread
* Re: [igt-dev] [PATCH i-g-t 3/4] trace.pl: Fix incomplete request handling
  2018-05-07 23:58     ` [igt-dev] " John Harrison
@ 2018-05-08 12:07       ` Tvrtko Ursulin
  -1 siblings, 0 replies; 16+ messages in thread
From: Tvrtko Ursulin @ 2018-05-08 12:07 UTC (permalink / raw)
  To: John Harrison, Tvrtko Ursulin, igt-dev; +Cc: Intel-gfx


On 08/05/2018 00:58, John Harrison wrote:
> On 4/23/2018 2:52 AM, Tvrtko Ursulin wrote:
>> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>>
>> Incomplete requests (no notify, no context complete) have to be corrected
>> by looking at the engine timeline, and not the sorted-by-start-time view
>> as was previously used.
>>
>> Per-engine timelines are generated on demand and cached for later use.
>>
>> v2: Find end of current context on the engine timeline instead of just
>>      using the next request for adjusting the incomplete start time.
>>
>> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>> Cc: John Harrison <John.C.Harrison@intel.com>
>> ---
>>   scripts/trace.pl | 86 
>> ++++++++++++++++++++++++++++++++++++++++++--------------
>>   1 file changed, 65 insertions(+), 21 deletions(-)
>>
>> diff --git a/scripts/trace.pl b/scripts/trace.pl
>> index eb5a36b91a5c..b48f43225fc1 100755
>> --- a/scripts/trace.pl
>> +++ b/scripts/trace.pl
>> @@ -26,6 +26,8 @@ use strict;
>>   use warnings;
>>   use 5.010;
>> +use List::Util;
>> +
>>   my $gid = 0;
>>   my (%db, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait);
>>   my @freqs;
>> @@ -516,29 +518,71 @@ foreach my $key (keys %db) {
>>       }
>>   }
>> -# 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 %engine_timelines;
>> +
>> +sub sortEngine {
>> +    my $as = $db{$a}->{'global'};
>> +    my $bs = $db{$b}->{'global'};
>> +    my $val;
>> +
>> +    $val = $as <=> $bs;
>> +
>> +    die if $val == 0;
>> +
>> +    return $val;
>> +}
>> +
>> +sub get_engine_timeline {
>> +    my ($ring) = @_;
>> +    my @timeline;
>> +
>> +    return $engine_timelines{$ring} if exists $engine_timelines{$ring};
>> +
>> +    @timeline = grep { $db{$_}->{'ring'} == $ring } keys %db;
>> +    # FIXME seqno restart
>> +    @timeline = sort sortEngine @timeline;
>> +
>> +    $engine_timelines{$ring} = \@timeline;
>> +
>> +    return \@timeline;
>> +}
>> +
>> +# Fix up incompletes by ending them when the last request of a 
>> coalesced group
>> +# ends. Start by filtering out the incomplete requests.
>> +my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
>> +
>> +foreach my $key (@incompletes) {
>> +    my $timeline;
>> +    my $last_key;
>>       my $end;
>> +    my $i;
>> -    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
>> +    # Find the next request on the engine timeline.
>> +    $timeline = get_engine_timeline($db{$key}->{'ring'});
>> +    $i = List::Util::first { ${$timeline}[$_] eq $key } 
>> 0..$#{$timeline};
> This line in particular massively slows the process down! With one of my 
> longer trace files, the incomplete fix-up step took 30 seconds prior to 
> this. After this patch, it took 11205 seconds! Just shy of four hours!

Gee, awful. :(

> Caching the start point of the search greatly speeds things up but it is 
> still a lot slower than previous. With the following, it is down to 4068 
> seconds, or a little over one hour.
> +my $lastIndex = 0;
> ...
> -       $i = List::Util::first { ${$timeline}[$_] eq $key } 
> 0..$#{$timeline};
> +       $i = List::Util::first { ${$timeline}[$_] eq $key } 
> ${lastIndex}..$#{$timeline};
> +       if( !defined($i) ) {
> +               $i = List::Util::first { ${$timeline}[$_] eq $key } 
> 0..$#{$timeline};
> +               defined($i) || die "Failed to find '$key'!\n";
> +       }
> +       $lastIndex = $i;

This definitely makes sense and I'll take it.

> If I sort the '@incompletes' array numerically by seqno rather than as a 
> string sort, then I get rid of all the first level match failures 
> (except when rolling from one ring to the next) and the time drops to 
> 1819 seconds or half an hour.
> 
> +sub sortKeys {
> +       my( $aR, $aC, $aS ) = split( '/', $a );
> +       my( $bR, $bC, $bS ) = split( '/', $b );
> +       my $val;
> +
> +       $val = $aR <=> $bR;
> +       return $val if $val != 0;
> +
> +       $val = $aC <=> $bC;
> +       return $val if $val != 0;
> +
> +       return $aS <=> $bS;
> +}

For here I am thinking to try processing incompletes per-ring instead. 
That should limit the walks and enable some more numerical comparisons.

I'll also try adding cachine to the loop after the List::Util::first 
lookup to avoid repeatedly looking for the next complete, in cases when 
there are a lot of bunched up incompletes.

> +
> 
> -my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
> +my @incompletes = sort sortKeys grep { exists $db{$_}->{'incomplete'} } 
> keys %db;
> 
> 
> 
>> +
>> +    while ($i < $#{$timeline}) {
>> +        my $next;
>> +
>> +        $i = $i + 1;
> $i++; ?

Yeah.. there was a language which didn't support increments and my brain 
got confused that's Perl, when it is actually Python.. :)

> 
>> +        $next = ${$timeline}[$i];
>> +
>> +        next if exists $db{$next}->{'incomplete'};
>> -    if (exists $db{$next_key}) {
>> -        $end = $db{$next_key}->{'end'};
>> +        $last_key = $next;
>> +        last;
>> +    }
>> +
>> +    if (defined $last_key) {
>> +        if ($db{$key}->{'ctx'} eq $db{$last_key}->{'ctx'}) {
>> +            $end = $db{$last_key}->{'end'};
>> +        } else {
>> +            $end = $db{$last_key}->{'start'};
>> +        }
>>       } else {
>> -        # No info at all, fake it:
>> +        # No next submission, fake it.
>>           $end = $db{$key}->{'start'} + 999;
>>       }
>> @@ -546,10 +590,6 @@ foreach my $key (keys %db) {
>>       $db{$key}->{'end'} = $end;
>>   }
>> -# GPU time accounting
>> -my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, 
>> %batch_count);
>> -my (%submit_avg, %execute_avg, %ctxsave_avg);
>> -
>>   sub sortStart {
>>       my $as = $db{$a}->{'start'};
>>       my $bs = $db{$b}->{'start'};
>> @@ -597,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);
>> +
> 
> This is just a prettification type change? Moving declarations to be 
> more local to their usage? It doesn't seem to be related to the above 
> changes or explicitly mentioned in the commit message.

Yes, just moving closer to use site.

Regards,

Tvrtko
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

^ permalink raw reply	[flat|nested] 16+ messages in thread
* Re: [igt-dev] [PATCH i-g-t 3/4] trace.pl: Fix incomplete request handling
@ 2018-05-08 12:07       ` Tvrtko Ursulin
  0 siblings, 0 replies; 16+ messages in thread
From: Tvrtko Ursulin @ 2018-05-08 12:07 UTC (permalink / raw)
  To: John Harrison, Tvrtko Ursulin, igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin


On 08/05/2018 00:58, John Harrison wrote:
> On 4/23/2018 2:52 AM, Tvrtko Ursulin wrote:
>> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>>
>> Incomplete requests (no notify, no context complete) have to be corrected
>> by looking at the engine timeline, and not the sorted-by-start-time view
>> as was previously used.
>>
>> Per-engine timelines are generated on demand and cached for later use.
>>
>> v2: Find end of current context on the engine timeline instead of just
>>      using the next request for adjusting the incomplete start time.
>>
>> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>> Cc: John Harrison <John.C.Harrison@intel.com>
>> ---
>>   scripts/trace.pl | 86 
>> ++++++++++++++++++++++++++++++++++++++++++--------------
>>   1 file changed, 65 insertions(+), 21 deletions(-)
>>
>> diff --git a/scripts/trace.pl b/scripts/trace.pl
>> index eb5a36b91a5c..b48f43225fc1 100755
>> --- a/scripts/trace.pl
>> +++ b/scripts/trace.pl
>> @@ -26,6 +26,8 @@ use strict;
>>   use warnings;
>>   use 5.010;
>> +use List::Util;
>> +
>>   my $gid = 0;
>>   my (%db, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait);
>>   my @freqs;
>> @@ -516,29 +518,71 @@ foreach my $key (keys %db) {
>>       }
>>   }
>> -# 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 %engine_timelines;
>> +
>> +sub sortEngine {
>> +    my $as = $db{$a}->{'global'};
>> +    my $bs = $db{$b}->{'global'};
>> +    my $val;
>> +
>> +    $val = $as <=> $bs;
>> +
>> +    die if $val == 0;
>> +
>> +    return $val;
>> +}
>> +
>> +sub get_engine_timeline {
>> +    my ($ring) = @_;
>> +    my @timeline;
>> +
>> +    return $engine_timelines{$ring} if exists $engine_timelines{$ring};
>> +
>> +    @timeline = grep { $db{$_}->{'ring'} == $ring } keys %db;
>> +    # FIXME seqno restart
>> +    @timeline = sort sortEngine @timeline;
>> +
>> +    $engine_timelines{$ring} = \@timeline;
>> +
>> +    return \@timeline;
>> +}
>> +
>> +# Fix up incompletes by ending them when the last request of a 
>> coalesced group
>> +# ends. Start by filtering out the incomplete requests.
>> +my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
>> +
>> +foreach my $key (@incompletes) {
>> +    my $timeline;
>> +    my $last_key;
>>       my $end;
>> +    my $i;
>> -    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
>> +    # Find the next request on the engine timeline.
>> +    $timeline = get_engine_timeline($db{$key}->{'ring'});
>> +    $i = List::Util::first { ${$timeline}[$_] eq $key } 
>> 0..$#{$timeline};
> This line in particular massively slows the process down! With one of my 
> longer trace files, the incomplete fix-up step took 30 seconds prior to 
> this. After this patch, it took 11205 seconds! Just shy of four hours!

Gee, awful. :(

> Caching the start point of the search greatly speeds things up but it is 
> still a lot slower than previous. With the following, it is down to 4068 
> seconds, or a little over one hour.
> +my $lastIndex = 0;
> ...
> -       $i = List::Util::first { ${$timeline}[$_] eq $key } 
> 0..$#{$timeline};
> +       $i = List::Util::first { ${$timeline}[$_] eq $key } 
> ${lastIndex}..$#{$timeline};
> +       if( !defined($i) ) {
> +               $i = List::Util::first { ${$timeline}[$_] eq $key } 
> 0..$#{$timeline};
> +               defined($i) || die "Failed to find '$key'!\n";
> +       }
> +       $lastIndex = $i;

This definitely makes sense and I'll take it.

> If I sort the '@incompletes' array numerically by seqno rather than as a 
> string sort, then I get rid of all the first level match failures 
> (except when rolling from one ring to the next) and the time drops to 
> 1819 seconds or half an hour.
> 
> +sub sortKeys {
> +       my( $aR, $aC, $aS ) = split( '/', $a );
> +       my( $bR, $bC, $bS ) = split( '/', $b );
> +       my $val;
> +
> +       $val = $aR <=> $bR;
> +       return $val if $val != 0;
> +
> +       $val = $aC <=> $bC;
> +       return $val if $val != 0;
> +
> +       return $aS <=> $bS;
> +}

For here I am thinking to try processing incompletes per-ring instead. 
That should limit the walks and enable some more numerical comparisons.

I'll also try adding cachine to the loop after the List::Util::first 
lookup to avoid repeatedly looking for the next complete, in cases when 
there are a lot of bunched up incompletes.

> +
> 
> -my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
> +my @incompletes = sort sortKeys grep { exists $db{$_}->{'incomplete'} } 
> keys %db;
> 
> 
> 
>> +
>> +    while ($i < $#{$timeline}) {
>> +        my $next;
>> +
>> +        $i = $i + 1;
> $i++; ?

Yeah.. there was a language which didn't support increments and my brain 
got confused that's Perl, when it is actually Python.. :)

> 
>> +        $next = ${$timeline}[$i];
>> +
>> +        next if exists $db{$next}->{'incomplete'};
>> -    if (exists $db{$next_key}) {
>> -        $end = $db{$next_key}->{'end'};
>> +        $last_key = $next;
>> +        last;
>> +    }
>> +
>> +    if (defined $last_key) {
>> +        if ($db{$key}->{'ctx'} eq $db{$last_key}->{'ctx'}) {
>> +            $end = $db{$last_key}->{'end'};
>> +        } else {
>> +            $end = $db{$last_key}->{'start'};
>> +        }
>>       } else {
>> -        # No info at all, fake it:
>> +        # No next submission, fake it.
>>           $end = $db{$key}->{'start'} + 999;
>>       }
>> @@ -546,10 +590,6 @@ foreach my $key (keys %db) {
>>       $db{$key}->{'end'} = $end;
>>   }
>> -# GPU time accounting
>> -my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, 
>> %batch_count);
>> -my (%submit_avg, %execute_avg, %ctxsave_avg);
>> -
>>   sub sortStart {
>>       my $as = $db{$a}->{'start'};
>>       my $bs = $db{$b}->{'start'};
>> @@ -597,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);
>> +
> 
> This is just a prettification type change? Moving declarations to be 
> more local to their usage? It doesn't seem to be related to the above 
> changes or explicitly mentioned in the commit message.

Yes, just moving closer to use site.

Regards,

Tvrtko
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

^ permalink raw reply	[flat|nested] 16+ messages in thread
end of thread, other threads:[~2018-05-08 12:07 UTC | newest]

Thread overview: 16+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-04-23  9:52 [PATCH i-g-t v3 0/4] trace.pl fixes Tvrtko Ursulin
2018-04-23  9:52 ` [igt-dev] " Tvrtko Ursulin
2018-04-23  9:52 ` [PATCH i-g-t 1/4] trace.pl: Add support for colouring context execution Tvrtko Ursulin
2018-04-23  9:52   ` [igt-dev] " Tvrtko Ursulin
2018-04-23  9:52 ` [PATCH i-g-t 2/4] trace.pl: Fix engine busy accounting in split mode Tvrtko Ursulin
2018-04-23  9:52   ` [igt-dev] " Tvrtko Ursulin
2018-04-23  9:52 ` [PATCH i-g-t 3/4] trace.pl: Fix incomplete request handling Tvrtko Ursulin
2018-04-23  9:52   ` [igt-dev] " Tvrtko Ursulin
2018-05-07 23:58   ` John Harrison
2018-05-07 23:58     ` [igt-dev] " John Harrison
2018-05-08 12:07     ` Tvrtko Ursulin
2018-05-08 12:07       ` Tvrtko Ursulin
2018-04-23  9:52 ` [PATCH i-g-t 4/4] trace.pl: Fix request split mode Tvrtko Ursulin
2018-04-23  9:52   ` [igt-dev] " Tvrtko Ursulin
2018-04-23 14:46 ` [igt-dev] ✓ Fi.CI.BAT: success for trace.pl fixes (rev3) Patchwork
2018-04-23 18:20 ` [igt-dev] ✓ Fi.CI.IGT: " Patchwork

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.