All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH i-g-t v2 00/11] trace.pl fixes
@ 2018-03-06 12:43 ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

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

Collection of fixes on top of John's recent work.

Problems were mostly in the request split logic which had several issues both
in my original version, and also after John's improvements.

Handling of "incomplete" requests (the ones which received neither notify nor
context complete) was also a bit incorrect.

After this series it seems to work fine, famous last words. Anyway with my test
data it correctly draws the timeline with no overalaps considering both merged
requests and submission to port 1.

I also added context colouring mode so it is easier to follow the timeline and
started using hw_id for context id's for additional readability.

v2:

 * Update for tracepoint renames. (new in series)
 * Remove hw_id change. (droppped from series)

 * Fix incomplete handling in split mode (-s).

   This did not work well for workloads which generate very few
   intel_engine_notify events. I am not that confident it is 100% correct now,
   but at least it doesn't crash the script and output for one other workload I
   had lying around looks correct.

   I guess the moral of the story here is split mode is not easy to get right if
   it is considered just a side project and more time needs to be set aside to
   triple-check it.

John Harrison (4):
  scripts/trace.pl: More hash key optimisations
  scripts/trace.pl: Sort order
  scripts/trace.pl: Calculate stats only after all munging
  scripts/trace.pl: Simplify 'end' & 'notify' generation

Tvrtko Ursulin (7):
  trace.pl: Catch-up with tracepoint renames
  trace.pl: Move sortQueue near its user
  trace.pl: Move min/max timestamp lookup to last loop
  trace.pl: Fix engine busy accounting in split mode
  trace.pl: Add support for colouring context execution
  trace.pl: Fix incomplete request handling
  trace.pl: Fix request split mode

 scripts/trace.pl | 372 +++++++++++++++++++++++++++++++++++++++++--------------
 1 file changed, 278 insertions(+), 94 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] 34+ messages in thread

* [Intel-gfx] [PATCH i-g-t v2 00/11] trace.pl fixes
@ 2018-03-06 12:43 ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

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

Collection of fixes on top of John's recent work.

Problems were mostly in the request split logic which had several issues both
in my original version, and also after John's improvements.

Handling of "incomplete" requests (the ones which received neither notify nor
context complete) was also a bit incorrect.

After this series it seems to work fine, famous last words. Anyway with my test
data it correctly draws the timeline with no overalaps considering both merged
requests and submission to port 1.

I also added context colouring mode so it is easier to follow the timeline and
started using hw_id for context id's for additional readability.

v2:

 * Update for tracepoint renames. (new in series)
 * Remove hw_id change. (droppped from series)

 * Fix incomplete handling in split mode (-s).

   This did not work well for workloads which generate very few
   intel_engine_notify events. I am not that confident it is 100% correct now,
   but at least it doesn't crash the script and output for one other workload I
   had lying around looks correct.

   I guess the moral of the story here is split mode is not easy to get right if
   it is considered just a side project and more time needs to be set aside to
   triple-check it.

John Harrison (4):
  scripts/trace.pl: More hash key optimisations
  scripts/trace.pl: Sort order
  scripts/trace.pl: Calculate stats only after all munging
  scripts/trace.pl: Simplify 'end' & 'notify' generation

Tvrtko Ursulin (7):
  trace.pl: Catch-up with tracepoint renames
  trace.pl: Move sortQueue near its user
  trace.pl: Move min/max timestamp lookup to last loop
  trace.pl: Fix engine busy accounting in split mode
  trace.pl: Add support for colouring context execution
  trace.pl: Fix incomplete request handling
  trace.pl: Fix request split mode

 scripts/trace.pl | 372 +++++++++++++++++++++++++++++++++++++++++--------------
 1 file changed, 278 insertions(+), 94 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] 34+ messages in thread

* [PATCH i-g-t 01/11] trace.pl: Catch-up with tracepoint renames
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

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

i915 renamed the request related tracepoints so catch up with that.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
 scripts/trace.pl | 36 ++++++++++++++++++------------------
 1 file changed, 18 insertions(+), 18 deletions(-)

diff --git a/scripts/trace.pl b/scripts/trace.pl
index cb93900dd620..d6686833b3e9 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -62,13 +62,13 @@ Notes:
    The above will invoke perf record, or alternatively it can be done directly:
 
 	perf record -a -c 1 -e i915:intel_gpu_freq_change, \
-			       i915:i915_gem_request_add, \
-			       i915:i915_gem_request_submit, \
-			       i915:i915_gem_request_in, \
-			       i915:i915_gem_request_out, \
+			       i915:i915_request_add, \
+			       i915:i915_request_submit, \
+			       i915:i915_request_in, \
+			       i915:i915_request_out, \
 			       i915:intel_engine_notify, \
-			       i915:i915_gem_request_wait_begin, \
-			       i915:i915_gem_request_wait_end \
+			       i915:i915_request_wait_begin, \
+			       i915:i915_request_wait_end \
 			       [command-to-be-profiled]
 
    Then create the log file with:
@@ -169,13 +169,13 @@ sub arg_gpu_timeline
 sub arg_trace
 {
 	my @events = ( 'i915:intel_gpu_freq_change',
-		       'i915:i915_gem_request_add',
-		       'i915:i915_gem_request_submit',
-		       'i915:i915_gem_request_in',
-		       'i915:i915_gem_request_out',
+		       'i915:i915_request_add',
+		       'i915:i915_request_submit',
+		       'i915:i915_request_in',
+		       'i915:i915_request_out',
 		       'i915:intel_engine_notify',
-		       'i915:i915_gem_request_wait_begin',
-		       'i915:i915_gem_request_wait_end' );
+		       'i915:i915_request_wait_begin',
+		       'i915:i915_request_wait_end' );
 
 	return unless scalar(@_);
 
@@ -394,7 +394,7 @@ while (<>) {
 		}
 	}
 
-	if ($tp_name eq 'i915:i915_gem_request_wait_begin:') {
+	if ($tp_name eq 'i915:i915_request_wait_begin:') {
 		my %rw;
 
 		next if exists $reqwait{$key};
@@ -405,11 +405,11 @@ while (<>) {
 		$rw{'ctx'} = $ctx;
 		$rw{'start'} = $time;
 		$reqwait{$key} = \%rw;
-	} elsif ($tp_name eq 'i915:i915_gem_request_wait_end:') {
+	} elsif ($tp_name eq 'i915:i915_request_wait_end:') {
 		next unless exists $reqwait{$key};
 
 		$reqwait{$key}->{'end'} = $time;
-	} elsif ($tp_name eq 'i915:i915_gem_request_add:') {
+	} elsif ($tp_name eq 'i915:i915_request_add:') {
 		if (exists $queue{$key}) {
 			$ctxdb{$orig_ctx}++;
 			$ctx = sanitize_ctx($orig_ctx, $ring);
@@ -417,12 +417,12 @@ while (<>) {
 		}
 
 		$queue{$key} = $time;
-	} elsif ($tp_name eq 'i915:i915_gem_request_submit:') {
+	} elsif ($tp_name eq 'i915:i915_request_submit:') {
 		die if exists $submit{$key};
 		die unless exists $queue{$key};
 
 		$submit{$key} = $time;
-	} elsif ($tp_name eq 'i915:i915_gem_request_in:') {
+	} elsif ($tp_name eq 'i915:i915_request_in:') {
 		my %req;
 
 		die if exists $db{$key};
@@ -442,7 +442,7 @@ while (<>) {
 		$rings{$ring} = $gid++ unless exists $rings{$ring};
 		$ringmap{$rings{$ring}} = $ring;
 		$db{$key} = \%req;
-	} elsif ($tp_name eq 'i915:i915_gem_request_out:') {
+	} elsif ($tp_name eq 'i915:i915_request_out:') {
 		my $gkey = global_key($ring, $tp{'global'});
 
 		die unless exists $db{$key};
-- 
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] 34+ messages in thread

* [Intel-gfx] [PATCH i-g-t 01/11] trace.pl: Catch-up with tracepoint renames
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

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

i915 renamed the request related tracepoints so catch up with that.

Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
---
 scripts/trace.pl | 36 ++++++++++++++++++------------------
 1 file changed, 18 insertions(+), 18 deletions(-)

diff --git a/scripts/trace.pl b/scripts/trace.pl
index cb93900dd620..d6686833b3e9 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -62,13 +62,13 @@ Notes:
    The above will invoke perf record, or alternatively it can be done directly:
 
 	perf record -a -c 1 -e i915:intel_gpu_freq_change, \
-			       i915:i915_gem_request_add, \
-			       i915:i915_gem_request_submit, \
-			       i915:i915_gem_request_in, \
-			       i915:i915_gem_request_out, \
+			       i915:i915_request_add, \
+			       i915:i915_request_submit, \
+			       i915:i915_request_in, \
+			       i915:i915_request_out, \
 			       i915:intel_engine_notify, \
-			       i915:i915_gem_request_wait_begin, \
-			       i915:i915_gem_request_wait_end \
+			       i915:i915_request_wait_begin, \
+			       i915:i915_request_wait_end \
 			       [command-to-be-profiled]
 
    Then create the log file with:
@@ -169,13 +169,13 @@ sub arg_gpu_timeline
 sub arg_trace
 {
 	my @events = ( 'i915:intel_gpu_freq_change',
-		       'i915:i915_gem_request_add',
-		       'i915:i915_gem_request_submit',
-		       'i915:i915_gem_request_in',
-		       'i915:i915_gem_request_out',
+		       'i915:i915_request_add',
+		       'i915:i915_request_submit',
+		       'i915:i915_request_in',
+		       'i915:i915_request_out',
 		       'i915:intel_engine_notify',
-		       'i915:i915_gem_request_wait_begin',
-		       'i915:i915_gem_request_wait_end' );
+		       'i915:i915_request_wait_begin',
+		       'i915:i915_request_wait_end' );
 
 	return unless scalar(@_);
 
@@ -394,7 +394,7 @@ while (<>) {
 		}
 	}
 
-	if ($tp_name eq 'i915:i915_gem_request_wait_begin:') {
+	if ($tp_name eq 'i915:i915_request_wait_begin:') {
 		my %rw;
 
 		next if exists $reqwait{$key};
@@ -405,11 +405,11 @@ while (<>) {
 		$rw{'ctx'} = $ctx;
 		$rw{'start'} = $time;
 		$reqwait{$key} = \%rw;
-	} elsif ($tp_name eq 'i915:i915_gem_request_wait_end:') {
+	} elsif ($tp_name eq 'i915:i915_request_wait_end:') {
 		next unless exists $reqwait{$key};
 
 		$reqwait{$key}->{'end'} = $time;
-	} elsif ($tp_name eq 'i915:i915_gem_request_add:') {
+	} elsif ($tp_name eq 'i915:i915_request_add:') {
 		if (exists $queue{$key}) {
 			$ctxdb{$orig_ctx}++;
 			$ctx = sanitize_ctx($orig_ctx, $ring);
@@ -417,12 +417,12 @@ while (<>) {
 		}
 
 		$queue{$key} = $time;
-	} elsif ($tp_name eq 'i915:i915_gem_request_submit:') {
+	} elsif ($tp_name eq 'i915:i915_request_submit:') {
 		die if exists $submit{$key};
 		die unless exists $queue{$key};
 
 		$submit{$key} = $time;
-	} elsif ($tp_name eq 'i915:i915_gem_request_in:') {
+	} elsif ($tp_name eq 'i915:i915_request_in:') {
 		my %req;
 
 		die if exists $db{$key};
@@ -442,7 +442,7 @@ while (<>) {
 		$rings{$ring} = $gid++ unless exists $rings{$ring};
 		$ringmap{$rings{$ring}} = $ring;
 		$db{$key} = \%req;
-	} elsif ($tp_name eq 'i915:i915_gem_request_out:') {
+	} elsif ($tp_name eq 'i915:i915_request_out:') {
 		my $gkey = global_key($ring, $tp{'global'});
 
 		die unless exists $db{$key};
-- 
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] 34+ messages in thread

* [PATCH i-g-t 02/11] scripts/trace.pl: More hash key optimisations
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

From: John Harrison <John.C.Harrison@Intel.com>

Cache the key count value rather than querying the hash every time.
Also assert that the database does not magically change size after the
fixups.

v2: Rename variable according to style guide [Tvrtko]

v3: Reverted accidental style change and added a blank line. [Tvrtko]

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index d6686833b3e9..6b784ac6ab1f 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -508,6 +508,7 @@ 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'};
 
@@ -522,7 +523,7 @@ foreach my $key (keys %db) {
 		$next_key = db_key($ring, $ctx, $seqno + $i);
 		$i++;
 	} until ((exists $db{$next_key} and not exists $db{$next_key}->{'incomplete'})
-		 or $i > scalar(keys(%db)));  # ugly stop hack
+		 or $i > $key_count);  # ugly stop hack
 
 	if (exists $db{$next_key}) {
 		$db{$key}->{'notify'} = $db{$next_key}->{'end'};
@@ -541,6 +542,8 @@ my $first_ts;
 my @sorted_keys = sort {$db{$a}->{'start'} <=> $db{$b}->{'start'}} keys %db;
 my $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'};
@@ -565,7 +568,7 @@ foreach my $key (@sorted_keys) {
 		do {
 			$next_key = db_key($ring, $ctx, $seqno + $i);
 			$i++;
-		} until (exists $db{$next_key} or $i > scalar(keys(%db)));  # ugly stop hack
+		} 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) {
-- 
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] 34+ messages in thread

* [igt-dev] [PATCH i-g-t 02/11] scripts/trace.pl: More hash key optimisations
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin

From: John Harrison <John.C.Harrison@Intel.com>

Cache the key count value rather than querying the hash every time.
Also assert that the database does not magically change size after the
fixups.

v2: Rename variable according to style guide [Tvrtko]

v3: Reverted accidental style change and added a blank line. [Tvrtko]

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index d6686833b3e9..6b784ac6ab1f 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -508,6 +508,7 @@ 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'};
 
@@ -522,7 +523,7 @@ foreach my $key (keys %db) {
 		$next_key = db_key($ring, $ctx, $seqno + $i);
 		$i++;
 	} until ((exists $db{$next_key} and not exists $db{$next_key}->{'incomplete'})
-		 or $i > scalar(keys(%db)));  # ugly stop hack
+		 or $i > $key_count);  # ugly stop hack
 
 	if (exists $db{$next_key}) {
 		$db{$key}->{'notify'} = $db{$next_key}->{'end'};
@@ -541,6 +542,8 @@ my $first_ts;
 my @sorted_keys = sort {$db{$a}->{'start'} <=> $db{$b}->{'start'}} keys %db;
 my $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'};
@@ -565,7 +568,7 @@ foreach my $key (@sorted_keys) {
 		do {
 			$next_key = db_key($ring, $ctx, $seqno + $i);
 			$i++;
-		} until (exists $db{$next_key} or $i > scalar(keys(%db)));  # ugly stop hack
+		} 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) {
-- 
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] 34+ messages in thread

* [PATCH i-g-t 03/11] scripts/trace.pl: Sort order
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

From: John Harrison <John.C.Harrison@Intel.com>

Add an extra level to the databse key sort so that the ordering is
deterministic. If the time stamp matches, it now compares the key
itself as well (context/seqno). This makes it much easier to determine
if a change has actually broken anything. Previously back to back runs
with no changes could still produce different output, especially when
adding extra debug output during the calculations.

As the comparison test is now more than a single equation, moved it
out into a separate sort function.

v2: Re-work sort func for readability/performance [Tvrtko]

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index 6b784ac6ab1f..d571a870fca2 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -539,7 +539,29 @@ my (%submit_avg, %execute_avg, %ctxsave_avg);
 my $last_ts = 0;
 my $first_ts;
 
-my @sorted_keys = sort {$db{$a}->{'start'} <=> $db{$b}->{'start'}} keys %db;
+sub sortStart {
+	my $as = $db{$a}->{'start'};
+	my $bs = $db{$b}->{'start'};
+	my $val;
+
+	$val = $as <=> $bs;
+	$val = $a cmp $b if $val == 0;
+
+	return $val;
+}
+
+sub sortQueue {
+	my $as = $db{$a}->{'queue'};
+	my $bs = $db{$b}->{'queue'};
+	my $val;
+
+	$val = $as <=> $bs;
+	$val = $a cmp $b if $val == 0;
+
+	return $val;
+}
+
+my @sorted_keys = sort sortStart keys %db;
 my $re_sort = 0;
 
 die "Database changed size?!" unless scalar(@sorted_keys) == $key_count;
@@ -589,9 +611,9 @@ foreach my $key (@sorted_keys) {
 	$ctxsave_avg{$ring} += $db{$key}->{'end'} - $db{$key}->{'notify'};
 }
 
-@sorted_keys = sort {$db{$a}->{'start'} <=> $db{$b}->{'start'}} keys %db if $re_sort;
+@sorted_keys = sort sortStart keys %db if $re_sort;
 
-foreach my $ring (keys %batch_avg) {
+foreach my $ring (sort keys %batch_avg) {
 	$batch_avg{$ring} /= $batch_count{$ring};
 	$batch_total_avg{$ring} /= $batch_count{$ring};
 	$submit_avg{$ring} /= $batch_count{$ring};
@@ -831,7 +853,7 @@ print <<ENDHTML;
 ENDHTML
 
 my $i = 0;
-foreach my $key (sort {$db{$a}->{'queue'} <=> $db{$b}->{'queue'}} keys %db) {
+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 $submit = $queue + $db{$key}->{'submit-delay'};
-- 
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] 34+ messages in thread

* [igt-dev] [PATCH i-g-t 03/11] scripts/trace.pl: Sort order
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin

From: John Harrison <John.C.Harrison@Intel.com>

Add an extra level to the databse key sort so that the ordering is
deterministic. If the time stamp matches, it now compares the key
itself as well (context/seqno). This makes it much easier to determine
if a change has actually broken anything. Previously back to back runs
with no changes could still produce different output, especially when
adding extra debug output during the calculations.

As the comparison test is now more than a single equation, moved it
out into a separate sort function.

v2: Re-work sort func for readability/performance [Tvrtko]

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index 6b784ac6ab1f..d571a870fca2 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -539,7 +539,29 @@ my (%submit_avg, %execute_avg, %ctxsave_avg);
 my $last_ts = 0;
 my $first_ts;
 
-my @sorted_keys = sort {$db{$a}->{'start'} <=> $db{$b}->{'start'}} keys %db;
+sub sortStart {
+	my $as = $db{$a}->{'start'};
+	my $bs = $db{$b}->{'start'};
+	my $val;
+
+	$val = $as <=> $bs;
+	$val = $a cmp $b if $val == 0;
+
+	return $val;
+}
+
+sub sortQueue {
+	my $as = $db{$a}->{'queue'};
+	my $bs = $db{$b}->{'queue'};
+	my $val;
+
+	$val = $as <=> $bs;
+	$val = $a cmp $b if $val == 0;
+
+	return $val;
+}
+
+my @sorted_keys = sort sortStart keys %db;
 my $re_sort = 0;
 
 die "Database changed size?!" unless scalar(@sorted_keys) == $key_count;
@@ -589,9 +611,9 @@ foreach my $key (@sorted_keys) {
 	$ctxsave_avg{$ring} += $db{$key}->{'end'} - $db{$key}->{'notify'};
 }
 
-@sorted_keys = sort {$db{$a}->{'start'} <=> $db{$b}->{'start'}} keys %db if $re_sort;
+@sorted_keys = sort sortStart keys %db if $re_sort;
 
-foreach my $ring (keys %batch_avg) {
+foreach my $ring (sort keys %batch_avg) {
 	$batch_avg{$ring} /= $batch_count{$ring};
 	$batch_total_avg{$ring} /= $batch_count{$ring};
 	$submit_avg{$ring} /= $batch_count{$ring};
@@ -831,7 +853,7 @@ print <<ENDHTML;
 ENDHTML
 
 my $i = 0;
-foreach my $key (sort {$db{$a}->{'queue'} <=> $db{$b}->{'queue'}} keys %db) {
+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 $submit = $queue + $db{$key}->{'submit-delay'};
-- 
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] 34+ messages in thread

* [PATCH i-g-t 04/11] scripts/trace.pl: Calculate stats only after all munging
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

From: John Harrison <John.C.Harrison@Intel.com>

There are various statistics being calculated multiple times in
multiple places while the log file is being read in. Some of these are
then re-calculated when the database is munged to correct various
issues with the logs. This patch consolidates the calculations into a
separate pass after all the reading and munging has been done.

Note that this actually produces a different final output as the
'execute-delay' values were not previously being re-calculated after
all the fixups. Thus were based on an incorrect calculation.

v2: Reduce scope of some local variables [Tvrtko]

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index d571a870fca2..d880a733bff8 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -437,8 +437,7 @@ while (<>) {
 		$req{'global'} = $tp{'global'};
 		$req{'port'} = $tp{'port'};
 		$req{'queue'} = $queue{$key};
-		$req{'submit-delay'} = $submit{$key} - $queue{$key};
-		$req{'execute-delay'} = $req{'start'} - $submit{$key};
+		$req{'submit'} = $submit{$key};
 		$rings{$ring} = $gid++ unless exists $rings{$ring};
 		$ringmap{$rings{$ring}} = $ring;
 		$db{$key} = \%req;
@@ -458,8 +457,6 @@ while (<>) {
 			$db{$key}->{'notify'} = $db{$key}->{'end'};
 			$db{$key}->{'no-notify'} = 1;
 		}
-		$db{$key}->{'duration'} = $db{$key}->{'notify'} - $db{$key}->{'start'};
-		$db{$key}->{'context-complete-delay'} = $db{$key}->{'end'} - $db{$key}->{'notify'};
 	} elsif ($tp_name eq 'i915:intel_engine_notify:') {
 		$notify{global_key($ring, $seqno)} = $time;
 	} elsif ($tp_name eq 'i915:intel_gpu_freq_change:') {
@@ -493,16 +490,11 @@ foreach my $key (keys %db) {
 			$db{$key}->{'notify'} = $db{$key}->{'end'};
 			$db{$key}->{'incomplete'} = 1;
 		}
-
-		$db{$key}->{'duration'} = $db{$key}->{'notify'} - $db{$key}->{'start'};
-		$db{$key}->{'context-complete-delay'} = $db{$key}->{'end'} - $db{$key}->{'notify'};
 	} else {
 		# Notify arrived after context complete.
 		if (exists $db{$key}->{'no-notify'} and exists $notify{$gkey}) {
 			delete $db{$key}->{'no-notify'};
 			$db{$key}->{'notify'} = $notify{$gkey};
-			$db{$key}->{'duration'} = $db{$key}->{'notify'} - $db{$key}->{'start'};
-			$db{$key}->{'context-complete-delay'} = $db{$key}->{'end'} - $db{$key}->{'notify'};
 		}
 	}
 }
@@ -528,8 +520,6 @@ foreach my $key (keys %db) {
 	if (exists $db{$next_key}) {
 		$db{$key}->{'notify'} = $db{$next_key}->{'end'};
 		$db{$key}->{'end'} = $db{$key}->{'notify'};
-		$db{$key}->{'duration'} = $db{$key}->{'notify'} - $db{$key}->{'start'};
-		$db{$key}->{'context-complete-delay'} = $db{$key}->{'end'} - $db{$key}->{'notify'};
 	}
 }
 
@@ -573,17 +563,11 @@ foreach my $key (@sorted_keys) {
 	$first_ts = $db{$key}->{'queue'} if not defined $first_ts or $db{$key}->{'queue'} < $first_ts;
 	$last_ts = $end if $end > $last_ts;
 
-	$running{$ring} += $end - $db{$key}->{'start'} unless exists $db{$key}->{'no-end'};
-	$runnable{$ring} += $db{$key}->{'execute-delay'};
-	$queued{$ring} += $db{$key}->{'start'} - $db{$key}->{'execute-delay'} - $db{$key}->{'queue'};
-
-	$batch_count{$ring}++;
-
 	# correct duration of merged batches
 	if ($correct_durations and exists $db{$key}->{'no-end'}) {
-		my $start = $db{$key}->{'start'};
 		my $ctx = $db{$key}->{'ctx'};
 		my $seqno = $db{$key}->{'seqno'};
+		my $start = $db{$key}->{'start'};
 		my $next_key;
 		my $i = 1;
 
@@ -594,25 +578,43 @@ foreach my $key (@sorted_keys) {
 
 		# 20us tolerance
 		if (exists $db{$next_key} and $db{$next_key}->{'start'} < $start + 20) {
+			my $notify = $db{$key}->{'notify'};
 			$re_sort = 1;
-			$db{$next_key}->{'start'} = $start + $db{$key}->{'duration'};
+			$db{$next_key}->{'start'} = $notify;
 			$db{$next_key}->{'start'} = $db{$next_key}->{'end'} if $db{$next_key}->{'start'} > $db{$next_key}->{'end'};
-			$db{$next_key}->{'duration'} = $db{$next_key}->{'notify'} - $db{$next_key}->{'start'};
-			$end = $db{$key}->{'notify'};
 			die if $db{$next_key}->{'start'} > $db{$next_key}->{'end'};
 		}
-		die if $db{$key}->{'start'} > $db{$key}->{'end'};
+		die if $start > $end;
 	}
+}
+
+@sorted_keys = sort sortStart keys %db if $re_sort;
+
+foreach my $key (@sorted_keys) {
+	my $ring = $db{$key}->{'ring'};
+	my $end = $db{$key}->{'end'};
+	my $start = $db{$key}->{'start'};
+	my $notify = $db{$key}->{'notify'};
+
+	$db{$key}->{'context-complete-delay'} = $end - $notify;
+	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
+	$db{$key}->{'submit-delay'} = $db{$key}->{'submit'} - $db{$key}->{'queue'};
+	$db{$key}->{'duration'} = $notify - $start;
+
+	$running{$ring} += $end - $start unless exists $db{$key}->{'no-end'};
+	$runnable{$ring} += $db{$key}->{'execute-delay'};
+	$queued{$ring} += $start - $db{$key}->{'execute-delay'} - $db{$key}->{'queue'};
+
+	$batch_count{$ring}++;
+
 	$batch_avg{$ring} += $db{$key}->{'duration'};
-	$batch_total_avg{$ring} += $end - $db{$key}->{'start'};
+	$batch_total_avg{$ring} += $end - $start;
 
 	$submit_avg{$ring} += $db{$key}->{'submit-delay'};
 	$execute_avg{$ring} += $db{$key}->{'execute-delay'};
-	$ctxsave_avg{$ring} += $db{$key}->{'end'} - $db{$key}->{'notify'};
+	$ctxsave_avg{$ring} += $end - $notify;
 }
 
-@sorted_keys = sort sortStart keys %db if $re_sort;
-
 foreach my $ring (sort keys %batch_avg) {
 	$batch_avg{$ring} /= $batch_count{$ring};
 	$batch_total_avg{$ring} /= $batch_count{$ring};
-- 
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] 34+ messages in thread

* [igt-dev] [PATCH i-g-t 04/11] scripts/trace.pl: Calculate stats only after all munging
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin

From: John Harrison <John.C.Harrison@Intel.com>

There are various statistics being calculated multiple times in
multiple places while the log file is being read in. Some of these are
then re-calculated when the database is munged to correct various
issues with the logs. This patch consolidates the calculations into a
separate pass after all the reading and munging has been done.

Note that this actually produces a different final output as the
'execute-delay' values were not previously being re-calculated after
all the fixups. Thus were based on an incorrect calculation.

v2: Reduce scope of some local variables [Tvrtko]

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index d571a870fca2..d880a733bff8 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -437,8 +437,7 @@ while (<>) {
 		$req{'global'} = $tp{'global'};
 		$req{'port'} = $tp{'port'};
 		$req{'queue'} = $queue{$key};
-		$req{'submit-delay'} = $submit{$key} - $queue{$key};
-		$req{'execute-delay'} = $req{'start'} - $submit{$key};
+		$req{'submit'} = $submit{$key};
 		$rings{$ring} = $gid++ unless exists $rings{$ring};
 		$ringmap{$rings{$ring}} = $ring;
 		$db{$key} = \%req;
@@ -458,8 +457,6 @@ while (<>) {
 			$db{$key}->{'notify'} = $db{$key}->{'end'};
 			$db{$key}->{'no-notify'} = 1;
 		}
-		$db{$key}->{'duration'} = $db{$key}->{'notify'} - $db{$key}->{'start'};
-		$db{$key}->{'context-complete-delay'} = $db{$key}->{'end'} - $db{$key}->{'notify'};
 	} elsif ($tp_name eq 'i915:intel_engine_notify:') {
 		$notify{global_key($ring, $seqno)} = $time;
 	} elsif ($tp_name eq 'i915:intel_gpu_freq_change:') {
@@ -493,16 +490,11 @@ foreach my $key (keys %db) {
 			$db{$key}->{'notify'} = $db{$key}->{'end'};
 			$db{$key}->{'incomplete'} = 1;
 		}
-
-		$db{$key}->{'duration'} = $db{$key}->{'notify'} - $db{$key}->{'start'};
-		$db{$key}->{'context-complete-delay'} = $db{$key}->{'end'} - $db{$key}->{'notify'};
 	} else {
 		# Notify arrived after context complete.
 		if (exists $db{$key}->{'no-notify'} and exists $notify{$gkey}) {
 			delete $db{$key}->{'no-notify'};
 			$db{$key}->{'notify'} = $notify{$gkey};
-			$db{$key}->{'duration'} = $db{$key}->{'notify'} - $db{$key}->{'start'};
-			$db{$key}->{'context-complete-delay'} = $db{$key}->{'end'} - $db{$key}->{'notify'};
 		}
 	}
 }
@@ -528,8 +520,6 @@ foreach my $key (keys %db) {
 	if (exists $db{$next_key}) {
 		$db{$key}->{'notify'} = $db{$next_key}->{'end'};
 		$db{$key}->{'end'} = $db{$key}->{'notify'};
-		$db{$key}->{'duration'} = $db{$key}->{'notify'} - $db{$key}->{'start'};
-		$db{$key}->{'context-complete-delay'} = $db{$key}->{'end'} - $db{$key}->{'notify'};
 	}
 }
 
@@ -573,17 +563,11 @@ foreach my $key (@sorted_keys) {
 	$first_ts = $db{$key}->{'queue'} if not defined $first_ts or $db{$key}->{'queue'} < $first_ts;
 	$last_ts = $end if $end > $last_ts;
 
-	$running{$ring} += $end - $db{$key}->{'start'} unless exists $db{$key}->{'no-end'};
-	$runnable{$ring} += $db{$key}->{'execute-delay'};
-	$queued{$ring} += $db{$key}->{'start'} - $db{$key}->{'execute-delay'} - $db{$key}->{'queue'};
-
-	$batch_count{$ring}++;
-
 	# correct duration of merged batches
 	if ($correct_durations and exists $db{$key}->{'no-end'}) {
-		my $start = $db{$key}->{'start'};
 		my $ctx = $db{$key}->{'ctx'};
 		my $seqno = $db{$key}->{'seqno'};
+		my $start = $db{$key}->{'start'};
 		my $next_key;
 		my $i = 1;
 
@@ -594,25 +578,43 @@ foreach my $key (@sorted_keys) {
 
 		# 20us tolerance
 		if (exists $db{$next_key} and $db{$next_key}->{'start'} < $start + 20) {
+			my $notify = $db{$key}->{'notify'};
 			$re_sort = 1;
-			$db{$next_key}->{'start'} = $start + $db{$key}->{'duration'};
+			$db{$next_key}->{'start'} = $notify;
 			$db{$next_key}->{'start'} = $db{$next_key}->{'end'} if $db{$next_key}->{'start'} > $db{$next_key}->{'end'};
-			$db{$next_key}->{'duration'} = $db{$next_key}->{'notify'} - $db{$next_key}->{'start'};
-			$end = $db{$key}->{'notify'};
 			die if $db{$next_key}->{'start'} > $db{$next_key}->{'end'};
 		}
-		die if $db{$key}->{'start'} > $db{$key}->{'end'};
+		die if $start > $end;
 	}
+}
+
+@sorted_keys = sort sortStart keys %db if $re_sort;
+
+foreach my $key (@sorted_keys) {
+	my $ring = $db{$key}->{'ring'};
+	my $end = $db{$key}->{'end'};
+	my $start = $db{$key}->{'start'};
+	my $notify = $db{$key}->{'notify'};
+
+	$db{$key}->{'context-complete-delay'} = $end - $notify;
+	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
+	$db{$key}->{'submit-delay'} = $db{$key}->{'submit'} - $db{$key}->{'queue'};
+	$db{$key}->{'duration'} = $notify - $start;
+
+	$running{$ring} += $end - $start unless exists $db{$key}->{'no-end'};
+	$runnable{$ring} += $db{$key}->{'execute-delay'};
+	$queued{$ring} += $start - $db{$key}->{'execute-delay'} - $db{$key}->{'queue'};
+
+	$batch_count{$ring}++;
+
 	$batch_avg{$ring} += $db{$key}->{'duration'};
-	$batch_total_avg{$ring} += $end - $db{$key}->{'start'};
+	$batch_total_avg{$ring} += $end - $start;
 
 	$submit_avg{$ring} += $db{$key}->{'submit-delay'};
 	$execute_avg{$ring} += $db{$key}->{'execute-delay'};
-	$ctxsave_avg{$ring} += $db{$key}->{'end'} - $db{$key}->{'notify'};
+	$ctxsave_avg{$ring} += $end - $notify;
 }
 
-@sorted_keys = sort sortStart keys %db if $re_sort;
-
 foreach my $ring (sort keys %batch_avg) {
 	$batch_avg{$ring} /= $batch_count{$ring};
 	$batch_total_avg{$ring} /= $batch_count{$ring};
-- 
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] 34+ messages in thread

* [PATCH i-g-t 05/11] scripts/trace.pl: Simplify 'end' & 'notify' generation
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

From: John Harrison <John.C.Harrison@Intel.com>

Delay the auto-generation of end/notify values until the point where
everything is known. As opposed to potentially generating them
multiple times with differing values (in the case of 'incomplete'
entries).

v2: More complete description. [Tvrtko]

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index d880a733bff8..509df6c0dd8b 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -467,10 +467,11 @@ while (<>) {
 }
 
 # Sanitation pass to fixup up out of order notify and context complete, and to
-# fine the largest seqno to be used for timeline sorting purposes.
+# find the largest seqno to be used for timeline sorting purposes.
 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'};
 
@@ -478,23 +479,21 @@ foreach my $key (keys %db) {
 
 	unless (exists $db{$key}->{'end'}) {
 		# Context complete not received.
-		if (exists $notify{$gkey}) {
+		$db{$key}->{'no-end'} = 1;
+
+		if (defined($notify)) {
 			# No context complete due req merging - use notify.
-			$db{$key}->{'notify'} = $notify{$gkey};
-			$db{$key}->{'end'} = $db{$key}->{'notify'};
-			$db{$key}->{'no-end'} = 1;
+			$db{$key}->{'notify'} = $notify;
+			$db{$key}->{'end'} = $notify;
 		} else {
-			# No notify and no context complete - mark it.
-			$db{$key}->{'no-end'} = 1;
-			$db{$key}->{'end'} = $db{$key}->{'start'} + 999;
-			$db{$key}->{'notify'} = $db{$key}->{'end'};
+			# 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 exists $notify{$gkey}) {
+		if (exists $db{$key}->{'no-notify'} and defined($notify)) {
 			delete $db{$key}->{'no-notify'};
-			$db{$key}->{'notify'} = $notify{$gkey};
+			$db{$key}->{'notify'} = $notify;
 		}
 	}
 }
@@ -510,6 +509,7 @@ foreach my $key (keys %db) {
 	my $seqno = $db{$key}->{'seqno'};
 	my $next_key;
 	my $i = 1;
+	my $end;
 
 	do {
 		$next_key = db_key($ring, $ctx, $seqno + $i);
@@ -518,9 +518,14 @@ foreach my $key (keys %db) {
 		 or $i > $key_count);  # ugly stop hack
 
 	if (exists $db{$next_key}) {
-		$db{$key}->{'notify'} = $db{$next_key}->{'end'};
-		$db{$key}->{'end'} = $db{$key}->{'notify'};
+		$end = $db{$next_key}->{'end'};
+	} else {
+		# No info at all, fake it:
+		$end = $db{$key}->{'start'} + 999;
 	}
+
+	$db{$key}->{'notify'} = $end;
+	$db{$key}->{'end'} = $end;
 }
 
 # GPU time accounting
-- 
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] 34+ messages in thread

* [igt-dev] [PATCH i-g-t 05/11] scripts/trace.pl: Simplify 'end' & 'notify' generation
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin

From: John Harrison <John.C.Harrison@Intel.com>

Delay the auto-generation of end/notify values until the point where
everything is known. As opposed to potentially generating them
multiple times with differing values (in the case of 'incomplete'
entries).

v2: More complete description. [Tvrtko]

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index d880a733bff8..509df6c0dd8b 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -467,10 +467,11 @@ while (<>) {
 }
 
 # Sanitation pass to fixup up out of order notify and context complete, and to
-# fine the largest seqno to be used for timeline sorting purposes.
+# find the largest seqno to be used for timeline sorting purposes.
 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'};
 
@@ -478,23 +479,21 @@ foreach my $key (keys %db) {
 
 	unless (exists $db{$key}->{'end'}) {
 		# Context complete not received.
-		if (exists $notify{$gkey}) {
+		$db{$key}->{'no-end'} = 1;
+
+		if (defined($notify)) {
 			# No context complete due req merging - use notify.
-			$db{$key}->{'notify'} = $notify{$gkey};
-			$db{$key}->{'end'} = $db{$key}->{'notify'};
-			$db{$key}->{'no-end'} = 1;
+			$db{$key}->{'notify'} = $notify;
+			$db{$key}->{'end'} = $notify;
 		} else {
-			# No notify and no context complete - mark it.
-			$db{$key}->{'no-end'} = 1;
-			$db{$key}->{'end'} = $db{$key}->{'start'} + 999;
-			$db{$key}->{'notify'} = $db{$key}->{'end'};
+			# 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 exists $notify{$gkey}) {
+		if (exists $db{$key}->{'no-notify'} and defined($notify)) {
 			delete $db{$key}->{'no-notify'};
-			$db{$key}->{'notify'} = $notify{$gkey};
+			$db{$key}->{'notify'} = $notify;
 		}
 	}
 }
@@ -510,6 +509,7 @@ foreach my $key (keys %db) {
 	my $seqno = $db{$key}->{'seqno'};
 	my $next_key;
 	my $i = 1;
+	my $end;
 
 	do {
 		$next_key = db_key($ring, $ctx, $seqno + $i);
@@ -518,9 +518,14 @@ foreach my $key (keys %db) {
 		 or $i > $key_count);  # ugly stop hack
 
 	if (exists $db{$next_key}) {
-		$db{$key}->{'notify'} = $db{$next_key}->{'end'};
-		$db{$key}->{'end'} = $db{$key}->{'notify'};
+		$end = $db{$next_key}->{'end'};
+	} else {
+		# No info at all, fake it:
+		$end = $db{$key}->{'start'} + 999;
 	}
+
+	$db{$key}->{'notify'} = $end;
+	$db{$key}->{'end'} = $end;
 }
 
 # GPU time accounting
-- 
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] 34+ messages in thread

* [PATCH i-g-t 06/11] trace.pl: Move sortQueue near its user
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

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

Just to clear up some space for incoming code refactoring.

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index 509df6c0dd8b..d49d25d6c1ca 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -545,17 +545,6 @@ sub sortStart {
 	return $val;
 }
 
-sub sortQueue {
-	my $as = $db{$a}->{'queue'};
-	my $bs = $db{$b}->{'queue'};
-	my $val;
-
-	$val = $as <=> $bs;
-	$val = $a cmp $b if $val == 0;
-
-	return $val;
-}
-
 my @sorted_keys = sort sortStart keys %db;
 my $re_sort = 0;
 
@@ -859,6 +848,17 @@ print <<ENDHTML;
   var items = new vis.DataSet([
 ENDHTML
 
+sub sortQueue {
+	my $as = $db{$a}->{'queue'};
+	my $bs = $db{$b}->{'queue'};
+	my $val;
+
+	$val = $as <=> $bs;
+	$val = $a cmp $b if $val == 0;
+
+	return $val;
+}
+
 my $i = 0;
 foreach my $key (sort sortQueue keys %db) {
 	my ($name, $ctx, $seqno) = ($db{$key}->{'name'}, $db{$key}->{'ctx'}, $db{$key}->{'seqno'});
-- 
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] 34+ messages in thread

* [igt-dev] [PATCH i-g-t 06/11] trace.pl: Move sortQueue near its user
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin

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

Just to clear up some space for incoming code refactoring.

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index 509df6c0dd8b..d49d25d6c1ca 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -545,17 +545,6 @@ sub sortStart {
 	return $val;
 }
 
-sub sortQueue {
-	my $as = $db{$a}->{'queue'};
-	my $bs = $db{$b}->{'queue'};
-	my $val;
-
-	$val = $as <=> $bs;
-	$val = $a cmp $b if $val == 0;
-
-	return $val;
-}
-
 my @sorted_keys = sort sortStart keys %db;
 my $re_sort = 0;
 
@@ -859,6 +848,17 @@ print <<ENDHTML;
   var items = new vis.DataSet([
 ENDHTML
 
+sub sortQueue {
+	my $as = $db{$a}->{'queue'};
+	my $bs = $db{$b}->{'queue'};
+	my $val;
+
+	$val = $as <=> $bs;
+	$val = $a cmp $b if $val == 0;
+
+	return $val;
+}
+
 my $i = 0;
 foreach my $key (sort sortQueue keys %db) {
 	my ($name, $ctx, $seqno) = ($db{$key}->{'name'}, $db{$key}->{'ctx'}, $db{$key}->{'seqno'});
-- 
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] 34+ messages in thread

* [PATCH i-g-t 07/11] trace.pl: Move min/max timestamp lookup to last loop
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx

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

It makes sense to fetch the min and max timestamp only after the
last sort of the array.

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index d49d25d6c1ca..27b39efcebbd 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -531,8 +531,6 @@ foreach my $key (keys %db) {
 # 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;
 
 sub sortStart {
 	my $as = $db{$a}->{'start'};
@@ -554,9 +552,6 @@ foreach my $key (@sorted_keys) {
 	my $ring = $db{$key}->{'ring'};
 	my $end = $db{$key}->{'end'};
 
-	$first_ts = $db{$key}->{'queue'} if not defined $first_ts or $db{$key}->{'queue'} < $first_ts;
-	$last_ts = $end if $end > $last_ts;
-
 	# correct duration of merged batches
 	if ($correct_durations and exists $db{$key}->{'no-end'}) {
 		my $ctx = $db{$key}->{'ctx'};
@@ -584,12 +579,18 @@ foreach my $key (@sorted_keys) {
 
 @sorted_keys = sort sortStart keys %db if $re_sort;
 
+my $last_ts = 0;
+my $first_ts;
+
 foreach my $key (@sorted_keys) {
 	my $ring = $db{$key}->{'ring'};
 	my $end = $db{$key}->{'end'};
 	my $start = $db{$key}->{'start'};
 	my $notify = $db{$key}->{'notify'};
 
+	$first_ts = $db{$key}->{'queue'} if not defined $first_ts or $db{$key}->{'queue'} < $first_ts;
+	$last_ts = $end if $end > $last_ts;
+
 	$db{$key}->{'context-complete-delay'} = $end - $notify;
 	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
 	$db{$key}->{'submit-delay'} = $db{$key}->{'submit'} - $db{$key}->{'queue'};
-- 
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] 34+ messages in thread

* [igt-dev] [PATCH i-g-t 07/11] trace.pl: Move min/max timestamp lookup to last loop
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 UTC (permalink / raw)
  To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin

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

It makes sense to fetch the min and max timestamp only after the
last sort of the array.

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index d49d25d6c1ca..27b39efcebbd 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -531,8 +531,6 @@ foreach my $key (keys %db) {
 # 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;
 
 sub sortStart {
 	my $as = $db{$a}->{'start'};
@@ -554,9 +552,6 @@ foreach my $key (@sorted_keys) {
 	my $ring = $db{$key}->{'ring'};
 	my $end = $db{$key}->{'end'};
 
-	$first_ts = $db{$key}->{'queue'} if not defined $first_ts or $db{$key}->{'queue'} < $first_ts;
-	$last_ts = $end if $end > $last_ts;
-
 	# correct duration of merged batches
 	if ($correct_durations and exists $db{$key}->{'no-end'}) {
 		my $ctx = $db{$key}->{'ctx'};
@@ -584,12 +579,18 @@ foreach my $key (@sorted_keys) {
 
 @sorted_keys = sort sortStart keys %db if $re_sort;
 
+my $last_ts = 0;
+my $first_ts;
+
 foreach my $key (@sorted_keys) {
 	my $ring = $db{$key}->{'ring'};
 	my $end = $db{$key}->{'end'};
 	my $start = $db{$key}->{'start'};
 	my $notify = $db{$key}->{'notify'};
 
+	$first_ts = $db{$key}->{'queue'} if not defined $first_ts or $db{$key}->{'queue'} < $first_ts;
+	$last_ts = $end if $end > $last_ts;
+
 	$db{$key}->{'context-complete-delay'} = $end - $notify;
 	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
 	$db{$key}->{'submit-delay'} = $db{$key}->{'submit'} - $db{$key}->{'queue'};
-- 
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] 34+ messages in thread

* [PATCH i-g-t 08/11] trace.pl: Fix engine busy accounting in split mode
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 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 27b39efcebbd..e7ce273ef26a 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -596,7 +596,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] 34+ messages in thread

* [igt-dev] [PATCH i-g-t 08/11] trace.pl: Fix engine busy accounting in split mode
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 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 27b39efcebbd..e7ce273ef26a 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -596,7 +596,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] 34+ messages in thread

* [PATCH i-g-t 09/11] trace.pl: Add support for colouring context execution
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 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.

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index e7ce273ef26a..ff61dea0768d 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;
 
 foreach my $key (@sorted_keys) {
 	my $ring = $db{$key}->{'ring'};
@@ -590,6 +609,8 @@ 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;
 
 	$db{$key}->{'context-complete-delay'} = $end - $notify;
 	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
@@ -721,6 +742,8 @@ foreach my $key (keys %reqwait) {
 say sprintf('GPU: %.2f%% idle, %.2f%% busy',
 	     $flat_busy{'gpu-idle'}, $flat_busy{'gpu-busy'}) unless $html;
 
+my $execute_colour = $colour_contexts ? 'multi-colour' : 'pink';
+
 print <<ENDHTML if $html;
 <!DOCTYPE HTML>
 <html>
@@ -741,7 +764,7 @@ print <<ENDHTML if $html;
 <button onclick="toggleStackSubgroups()">Toggle stacking</button>
 
 <p>
-pink = requests executing on the GPU<br>
+$execute_colour = 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>
 </p>
@@ -861,6 +884,19 @@ sub sortQueue {
 	return $val;
 }
 
+my @html_colours = ( 'Pink', 'Green', 'Purple', 'Gold', 'Cyan', 'Brown',
+		     'DeepPink', 'LightGreen', 'Plum', 'Orange', 'Teal', 'Peru',
+		     'Indigo', 'Khaki', 'Coral', 'Olive' );
+
+sub ctx_colour
+{
+       my ($ctx) = (@_);
+
+       return 'Pink' unless $colour_contexts;
+
+       return $html_colours[($ctx - $min_ctx) % scalar(@html_colours)];
+}
+
 my $i = 0;
 foreach my $key (sort sortQueue keys %db) {
 	my ($name, $ctx, $seqno) = ($db{$key}->{'name'}, $db{$key}->{'ctx'}, $db{$key}->{'seqno'});
@@ -898,7 +934,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) . ';';
 		}
 		$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] 34+ messages in thread

* [igt-dev] [PATCH i-g-t 09/11] trace.pl: Add support for colouring context execution
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 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.

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index e7ce273ef26a..ff61dea0768d 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;
 
 foreach my $key (@sorted_keys) {
 	my $ring = $db{$key}->{'ring'};
@@ -590,6 +609,8 @@ 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;
 
 	$db{$key}->{'context-complete-delay'} = $end - $notify;
 	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
@@ -721,6 +742,8 @@ foreach my $key (keys %reqwait) {
 say sprintf('GPU: %.2f%% idle, %.2f%% busy',
 	     $flat_busy{'gpu-idle'}, $flat_busy{'gpu-busy'}) unless $html;
 
+my $execute_colour = $colour_contexts ? 'multi-colour' : 'pink';
+
 print <<ENDHTML if $html;
 <!DOCTYPE HTML>
 <html>
@@ -741,7 +764,7 @@ print <<ENDHTML if $html;
 <button onclick="toggleStackSubgroups()">Toggle stacking</button>
 
 <p>
-pink = requests executing on the GPU<br>
+$execute_colour = 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>
 </p>
@@ -861,6 +884,19 @@ sub sortQueue {
 	return $val;
 }
 
+my @html_colours = ( 'Pink', 'Green', 'Purple', 'Gold', 'Cyan', 'Brown',
+		     'DeepPink', 'LightGreen', 'Plum', 'Orange', 'Teal', 'Peru',
+		     'Indigo', 'Khaki', 'Coral', 'Olive' );
+
+sub ctx_colour
+{
+       my ($ctx) = (@_);
+
+       return 'Pink' unless $colour_contexts;
+
+       return $html_colours[($ctx - $min_ctx) % scalar(@html_colours)];
+}
+
 my $i = 0;
 foreach my $key (sort sortQueue keys %db) {
 	my ($name, $ctx, $seqno) = ($db{$key}->{'name'}, $db{$key}->{'ctx'}, $db{$key}->{'seqno'});
@@ -898,7 +934,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) . ';';
 		}
 		$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] 34+ messages in thread

* [PATCH i-g-t 10/11] trace.pl: Fix incomplete request handling
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 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 ff61dea0768d..4d1da98daa0d 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;
-- 
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] 34+ messages in thread

* [Intel-gfx] [PATCH i-g-t 10/11] trace.pl: Fix incomplete request handling
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 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 ff61dea0768d..4d1da98daa0d 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;
-- 
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] 34+ messages in thread

* [PATCH i-g-t 11/11] trace.pl: Fix request split mode
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 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 4d1da98daa0d..de02bb1018f2 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] 34+ messages in thread

* [igt-dev] [PATCH i-g-t 11/11] trace.pl: Fix request split mode
@ 2018-03-06 12:43   ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-03-06 12:43 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 4d1da98daa0d..de02bb1018f2 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] 34+ messages in thread

* [igt-dev] ✓ Fi.CI.BAT: success for trace.pl fixes (rev2)
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
                   ` (11 preceding siblings ...)
  (?)
@ 2018-03-06 14:18 ` Patchwork
  -1 siblings, 0 replies; 34+ messages in thread
From: Patchwork @ 2018-03-06 14:18 UTC (permalink / raw)
  To: Tvrtko Ursulin; +Cc: igt-dev

== Series Details ==

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

== Summary ==

IGT patchset tested on top of latest successful build
b4689dce36d0fbd9aec70d5a4b077c43a6b9c254 igt: Remove gen7_forcewake_mt

with latest DRM-Tip kernel build CI_DRM_3880
3d35bb0a8966 drm-tip: 2018y-03m-06d-12h-23m-04s UTC integration manifest

No testlist changes.

---- Known issues:

Test kms_pipe_crc_basic:
        Subgroup suspend-read-crc-pipe-b:
                pass       -> INCOMPLETE (fi-snb-2520m) fdo#103713
Test prime_vgem:
        Subgroup basic-fence-flip:
                pass       -> FAIL       (fi-ilk-650) fdo#104008

fdo#103713 https://bugs.freedesktop.org/show_bug.cgi?id=103713
fdo#104008 https://bugs.freedesktop.org/show_bug.cgi?id=104008

fi-bdw-5557u     total:288  pass:267  dwarn:0   dfail:0   fail:0   skip:21  time:425s
fi-bdw-gvtdvm    total:288  pass:264  dwarn:0   dfail:0   fail:0   skip:24  time:424s
fi-blb-e6850     total:288  pass:223  dwarn:1   dfail:0   fail:0   skip:64  time:379s
fi-bsw-n3050     total:288  pass:242  dwarn:0   dfail:0   fail:0   skip:46  time:512s
fi-bwr-2160      total:288  pass:183  dwarn:0   dfail:0   fail:0   skip:105 time:279s
fi-bxt-dsi       total:288  pass:258  dwarn:0   dfail:0   fail:0   skip:30  time:490s
fi-bxt-j4205     total:288  pass:259  dwarn:0   dfail:0   fail:0   skip:29  time:495s
fi-byt-j1900     total:288  pass:253  dwarn:0   dfail:0   fail:0   skip:35  time:482s
fi-byt-n2820     total:288  pass:249  dwarn:0   dfail:0   fail:0   skip:39  time:474s
fi-cfl-8700k     total:288  pass:260  dwarn:0   dfail:0   fail:0   skip:28  time:403s
fi-cfl-s2        total:288  pass:262  dwarn:0   dfail:0   fail:0   skip:26  time:568s
fi-cnl-y3        total:288  pass:262  dwarn:0   dfail:0   fail:0   skip:26  time:589s
fi-elk-e7500     total:288  pass:229  dwarn:0   dfail:0   fail:0   skip:59  time:415s
fi-gdg-551       total:288  pass:179  dwarn:0   dfail:0   fail:1   skip:108 time:286s
fi-glk-1         total:288  pass:260  dwarn:0   dfail:0   fail:0   skip:28  time:521s
fi-hsw-4770      total:288  pass:261  dwarn:0   dfail:0   fail:0   skip:27  time:397s
fi-ilk-650       total:288  pass:227  dwarn:0   dfail:0   fail:1   skip:60  time:414s
fi-ivb-3520m     total:288  pass:259  dwarn:0   dfail:0   fail:0   skip:29  time:473s
fi-ivb-3770      total:288  pass:255  dwarn:0   dfail:0   fail:0   skip:33  time:419s
fi-kbl-7500u     total:288  pass:263  dwarn:1   dfail:0   fail:0   skip:24  time:474s
fi-kbl-7560u     total:108  pass:104  dwarn:0   dfail:0   fail:0   skip:3  
fi-kbl-7567u     total:288  pass:268  dwarn:0   dfail:0   fail:0   skip:20  time:462s
fi-kbl-r         total:288  pass:261  dwarn:0   dfail:0   fail:0   skip:27  time:507s
fi-pnv-d510      total:288  pass:222  dwarn:1   dfail:0   fail:0   skip:65  time:589s
fi-skl-6260u     total:288  pass:268  dwarn:0   dfail:0   fail:0   skip:20  time:442s
fi-skl-6600u     total:288  pass:261  dwarn:0   dfail:0   fail:0   skip:27  time:517s
fi-skl-6700hq    total:288  pass:262  dwarn:0   dfail:0   fail:0   skip:26  time:536s
fi-skl-6700k2    total:288  pass:264  dwarn:0   dfail:0   fail:0   skip:24  time:500s
fi-skl-6770hq    total:288  pass:268  dwarn:0   dfail:0   fail:0   skip:20  time:484s
fi-skl-guc       total:288  pass:260  dwarn:0   dfail:0   fail:0   skip:28  time:421s
fi-snb-2520m     total:245  pass:211  dwarn:0   dfail:0   fail:0   skip:33 
fi-snb-2600      total:288  pass:248  dwarn:0   dfail:0   fail:0   skip:40  time:401s

== Logs ==

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

^ permalink raw reply	[flat|nested] 34+ messages in thread

* [igt-dev] ✓ Fi.CI.IGT: success for trace.pl fixes (rev2)
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
                   ` (12 preceding siblings ...)
  (?)
@ 2018-03-06 19:29 ` Patchwork
  -1 siblings, 0 replies; 34+ messages in thread
From: Patchwork @ 2018-03-06 19:29 UTC (permalink / raw)
  To: Tvrtko Ursulin; +Cc: igt-dev

== Series Details ==

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

== Summary ==

---- Known issues:

Test gem_eio:
        Subgroup in-flight-contexts:
                incomplete -> PASS       (shard-apl) fdo#105341 +1
Test gem_softpin:
        Subgroup noreloc-s3:
                skip       -> PASS       (shard-snb) fdo#103375
Test kms_chv_cursor_fail:
        Subgroup pipe-b-64x64-top-edge:
                pass       -> DMESG-WARN (shard-snb) fdo#105185 +3
Test kms_flip:
        Subgroup flip-vs-expired-vblank:
                fail       -> PASS       (shard-hsw) fdo#102887
Test kms_frontbuffer_tracking:
        Subgroup fbc-suspend:
                fail       -> PASS       (shard-apl) fdo#101623 +1
Test kms_plane:
        Subgroup plane-panning-bottom-right-suspend-pipe-b-planes:
                incomplete -> PASS       (shard-hsw) fdo#103540
Test kms_rotation_crc:
        Subgroup primary-rotation-180:
                fail       -> PASS       (shard-snb) fdo#103925
        Subgroup sprite-rotation-90-pos-100-0:
                dmesg-warn -> PASS       (shard-apl) fdo#103356

fdo#105341 https://bugs.freedesktop.org/show_bug.cgi?id=105341
fdo#103375 https://bugs.freedesktop.org/show_bug.cgi?id=103375
fdo#105185 https://bugs.freedesktop.org/show_bug.cgi?id=105185
fdo#102887 https://bugs.freedesktop.org/show_bug.cgi?id=102887
fdo#101623 https://bugs.freedesktop.org/show_bug.cgi?id=101623
fdo#103540 https://bugs.freedesktop.org/show_bug.cgi?id=103540
fdo#103925 https://bugs.freedesktop.org/show_bug.cgi?id=103925
fdo#103356 https://bugs.freedesktop.org/show_bug.cgi?id=103356

shard-apl        total:3467 pass:1826 dwarn:1   dfail:0   fail:7   skip:1632 time:12427s
shard-hsw        total:3467 pass:1772 dwarn:2   dfail:0   fail:1   skip:1691 time:11915s
shard-snb        total:3467 pass:1362 dwarn:3   dfail:0   fail:2   skip:2100 time:7121s
Blacklisted hosts:
shard-kbl        total:3433 pass:1934 dwarn:1   dfail:0   fail:7   skip:1490 time:9260s

== Logs ==

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

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: [igt-dev] [PATCH i-g-t v2 00/11] trace.pl fixes
  2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
@ 2018-04-18 14:52   ` Tvrtko Ursulin
  -1 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-04-18 14:52 UTC (permalink / raw)
  To: Tvrtko Ursulin, igt-dev, John Harrison; +Cc: Intel-gfx


On 06/03/2018 12:43, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> 
> Collection of fixes on top of John's recent work.
> 
> Problems were mostly in the request split logic which had several issues both
> in my original version, and also after John's improvements.
> 
> Handling of "incomplete" requests (the ones which received neither notify nor
> context complete) was also a bit incorrect.
> 
> After this series it seems to work fine, famous last words. Anyway with my test
> data it correctly draws the timeline with no overalaps considering both merged
> requests and submission to port 1.
> 
> I also added context colouring mode so it is easier to follow the timeline and
> started using hw_id for context id's for additional readability.
> 
> v2:
> 
>   * Update for tracepoint renames. (new in series)
>   * Remove hw_id change. (droppped from series)
> 
>   * Fix incomplete handling in split mode (-s).
> 
>     This did not work well for workloads which generate very few
>     intel_engine_notify events. I am not that confident it is 100% correct now,
>     but at least it doesn't crash the script and output for one other workload I
>     had lying around looks correct.
> 
>     I guess the moral of the story here is split mode is not easy to get right if
>     it is considered just a side project and more time needs to be set aside to
>     triple-check it.
> 
> John Harrison (4):
>    scripts/trace.pl: More hash key optimisations
>    scripts/trace.pl: Sort order
>    scripts/trace.pl: Calculate stats only after all munging
>    scripts/trace.pl: Simplify 'end' & 'notify' generation
> 
> Tvrtko Ursulin (7):
>    trace.pl: Catch-up with tracepoint renames

 From here vvvvv...

>    trace.pl: Move sortQueue near its user
>    trace.pl: Move min/max timestamp lookup to last loop
>    trace.pl: Fix engine busy accounting in split mode
>    trace.pl: Add support for colouring context execution
>    trace.pl: Fix incomplete request handling
>    trace.pl: Fix request split mode

... to here ^^^^^.

Only six patches to review and four even don't need much thinking!

Regards,

Tvrtko


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

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: [igt-dev] [PATCH i-g-t v2 00/11] trace.pl fixes
@ 2018-04-18 14:52   ` Tvrtko Ursulin
  0 siblings, 0 replies; 34+ messages in thread
From: Tvrtko Ursulin @ 2018-04-18 14:52 UTC (permalink / raw)
  To: Tvrtko Ursulin, igt-dev, John Harrison; +Cc: Intel-gfx, Tvrtko Ursulin


On 06/03/2018 12:43, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> 
> Collection of fixes on top of John's recent work.
> 
> Problems were mostly in the request split logic which had several issues both
> in my original version, and also after John's improvements.
> 
> Handling of "incomplete" requests (the ones which received neither notify nor
> context complete) was also a bit incorrect.
> 
> After this series it seems to work fine, famous last words. Anyway with my test
> data it correctly draws the timeline with no overalaps considering both merged
> requests and submission to port 1.
> 
> I also added context colouring mode so it is easier to follow the timeline and
> started using hw_id for context id's for additional readability.
> 
> v2:
> 
>   * Update for tracepoint renames. (new in series)
>   * Remove hw_id change. (droppped from series)
> 
>   * Fix incomplete handling in split mode (-s).
> 
>     This did not work well for workloads which generate very few
>     intel_engine_notify events. I am not that confident it is 100% correct now,
>     but at least it doesn't crash the script and output for one other workload I
>     had lying around looks correct.
> 
>     I guess the moral of the story here is split mode is not easy to get right if
>     it is considered just a side project and more time needs to be set aside to
>     triple-check it.
> 
> John Harrison (4):
>    scripts/trace.pl: More hash key optimisations
>    scripts/trace.pl: Sort order
>    scripts/trace.pl: Calculate stats only after all munging
>    scripts/trace.pl: Simplify 'end' & 'notify' generation
> 
> Tvrtko Ursulin (7):
>    trace.pl: Catch-up with tracepoint renames

 From here vvvvv...

>    trace.pl: Move sortQueue near its user
>    trace.pl: Move min/max timestamp lookup to last loop
>    trace.pl: Fix engine busy accounting in split mode
>    trace.pl: Add support for colouring context execution
>    trace.pl: Fix incomplete request handling
>    trace.pl: Fix request split mode

... to here ^^^^^.

Only six patches to review and four even don't need much thinking!

Regards,

Tvrtko


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

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: [igt-dev] [PATCH i-g-t 06/11] trace.pl: Move sortQueue near its user
  2018-03-06 12:43   ` [igt-dev] " Tvrtko Ursulin
@ 2018-04-18 16:56     ` Lionel Landwerlin
  -1 siblings, 0 replies; 34+ messages in thread
From: Lionel Landwerlin @ 2018-04-18 16:56 UTC (permalink / raw)
  To: Tvrtko Ursulin, igt-dev; +Cc: Intel-gfx

Reviewed-by: Lionel Landwerlin <lionel.g.landwerlin@intel.com>

On 06/03/18 04:43, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>
> Just to clear up some space for incoming code refactoring.
>
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> Cc: John Harrison <John.C.Harrison@intel.com>
> ---
>   scripts/trace.pl | 22 +++++++++++-----------
>   1 file changed, 11 insertions(+), 11 deletions(-)
>
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index 509df6c0dd8b..d49d25d6c1ca 100755
> --- a/scripts/trace.pl
> +++ b/scripts/trace.pl
> @@ -545,17 +545,6 @@ sub sortStart {
>   	return $val;
>   }
>   
> -sub sortQueue {
> -	my $as = $db{$a}->{'queue'};
> -	my $bs = $db{$b}->{'queue'};
> -	my $val;
> -
> -	$val = $as <=> $bs;
> -	$val = $a cmp $b if $val == 0;
> -
> -	return $val;
> -}
> -
>   my @sorted_keys = sort sortStart keys %db;
>   my $re_sort = 0;
>   
> @@ -859,6 +848,17 @@ print <<ENDHTML;
>     var items = new vis.DataSet([
>   ENDHTML
>   
> +sub sortQueue {
> +	my $as = $db{$a}->{'queue'};
> +	my $bs = $db{$b}->{'queue'};
> +	my $val;
> +
> +	$val = $as <=> $bs;
> +	$val = $a cmp $b if $val == 0;
> +
> +	return $val;
> +}
> +
>   my $i = 0;
>   foreach my $key (sort sortQueue keys %db) {
>   	my ($name, $ctx, $seqno) = ($db{$key}->{'name'}, $db{$key}->{'ctx'}, $db{$key}->{'seqno'});


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

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: [Intel-gfx] [igt-dev] [PATCH i-g-t 06/11] trace.pl: Move sortQueue near its user
@ 2018-04-18 16:56     ` Lionel Landwerlin
  0 siblings, 0 replies; 34+ messages in thread
From: Lionel Landwerlin @ 2018-04-18 16:56 UTC (permalink / raw)
  To: Tvrtko Ursulin, igt-dev; +Cc: Intel-gfx

Reviewed-by: Lionel Landwerlin <lionel.g.landwerlin@intel.com>

On 06/03/18 04:43, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>
> Just to clear up some space for incoming code refactoring.
>
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> Cc: John Harrison <John.C.Harrison@intel.com>
> ---
>   scripts/trace.pl | 22 +++++++++++-----------
>   1 file changed, 11 insertions(+), 11 deletions(-)
>
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index 509df6c0dd8b..d49d25d6c1ca 100755
> --- a/scripts/trace.pl
> +++ b/scripts/trace.pl
> @@ -545,17 +545,6 @@ sub sortStart {
>   	return $val;
>   }
>   
> -sub sortQueue {
> -	my $as = $db{$a}->{'queue'};
> -	my $bs = $db{$b}->{'queue'};
> -	my $val;
> -
> -	$val = $as <=> $bs;
> -	$val = $a cmp $b if $val == 0;
> -
> -	return $val;
> -}
> -
>   my @sorted_keys = sort sortStart keys %db;
>   my $re_sort = 0;
>   
> @@ -859,6 +848,17 @@ print <<ENDHTML;
>     var items = new vis.DataSet([
>   ENDHTML
>   
> +sub sortQueue {
> +	my $as = $db{$a}->{'queue'};
> +	my $bs = $db{$b}->{'queue'};
> +	my $val;
> +
> +	$val = $as <=> $bs;
> +	$val = $a cmp $b if $val == 0;
> +
> +	return $val;
> +}
> +
>   my $i = 0;
>   foreach my $key (sort sortQueue keys %db) {
>   	my ($name, $ctx, $seqno) = ($db{$key}->{'name'}, $db{$key}->{'ctx'}, $db{$key}->{'seqno'});


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

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: [igt-dev] [PATCH i-g-t 07/11] trace.pl: Move min/max timestamp lookup to last loop
  2018-03-06 12:43   ` [igt-dev] " Tvrtko Ursulin
@ 2018-04-18 16:56     ` Lionel Landwerlin
  -1 siblings, 0 replies; 34+ messages in thread
From: Lionel Landwerlin @ 2018-04-18 16:56 UTC (permalink / raw)
  To: Tvrtko Ursulin, igt-dev; +Cc: Intel-gfx

Reviewed-by: Lionel Landwerlin <lionel.g.landwerlin@intel.com>

On 06/03/18 04:43, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>
> It makes sense to fetch the min and max timestamp only after the
> last sort of the array.
>
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> Cc: John Harrison <John.C.Harrison@intel.com>
> ---
>   scripts/trace.pl | 11 ++++++-----
>   1 file changed, 6 insertions(+), 5 deletions(-)
>
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index d49d25d6c1ca..27b39efcebbd 100755
> --- a/scripts/trace.pl
> +++ b/scripts/trace.pl
> @@ -531,8 +531,6 @@ foreach my $key (keys %db) {
>   # 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;
>   
>   sub sortStart {
>   	my $as = $db{$a}->{'start'};
> @@ -554,9 +552,6 @@ foreach my $key (@sorted_keys) {
>   	my $ring = $db{$key}->{'ring'};
>   	my $end = $db{$key}->{'end'};
>   
> -	$first_ts = $db{$key}->{'queue'} if not defined $first_ts or $db{$key}->{'queue'} < $first_ts;
> -	$last_ts = $end if $end > $last_ts;
> -
>   	# correct duration of merged batches
>   	if ($correct_durations and exists $db{$key}->{'no-end'}) {
>   		my $ctx = $db{$key}->{'ctx'};
> @@ -584,12 +579,18 @@ foreach my $key (@sorted_keys) {
>   
>   @sorted_keys = sort sortStart keys %db if $re_sort;
>   
> +my $last_ts = 0;
> +my $first_ts;
> +
>   foreach my $key (@sorted_keys) {
>   	my $ring = $db{$key}->{'ring'};
>   	my $end = $db{$key}->{'end'};
>   	my $start = $db{$key}->{'start'};
>   	my $notify = $db{$key}->{'notify'};
>   
> +	$first_ts = $db{$key}->{'queue'} if not defined $first_ts or $db{$key}->{'queue'} < $first_ts;
> +	$last_ts = $end if $end > $last_ts;
> +
>   	$db{$key}->{'context-complete-delay'} = $end - $notify;
>   	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
>   	$db{$key}->{'submit-delay'} = $db{$key}->{'submit'} - $db{$key}->{'queue'};


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

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: [igt-dev] [PATCH i-g-t 07/11] trace.pl: Move min/max timestamp lookup to last loop
@ 2018-04-18 16:56     ` Lionel Landwerlin
  0 siblings, 0 replies; 34+ messages in thread
From: Lionel Landwerlin @ 2018-04-18 16:56 UTC (permalink / raw)
  To: Tvrtko Ursulin, igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin

Reviewed-by: Lionel Landwerlin <lionel.g.landwerlin@intel.com>

On 06/03/18 04:43, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>
> It makes sense to fetch the min and max timestamp only after the
> last sort of the array.
>
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> Cc: John Harrison <John.C.Harrison@intel.com>
> ---
>   scripts/trace.pl | 11 ++++++-----
>   1 file changed, 6 insertions(+), 5 deletions(-)
>
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index d49d25d6c1ca..27b39efcebbd 100755
> --- a/scripts/trace.pl
> +++ b/scripts/trace.pl
> @@ -531,8 +531,6 @@ foreach my $key (keys %db) {
>   # 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;
>   
>   sub sortStart {
>   	my $as = $db{$a}->{'start'};
> @@ -554,9 +552,6 @@ foreach my $key (@sorted_keys) {
>   	my $ring = $db{$key}->{'ring'};
>   	my $end = $db{$key}->{'end'};
>   
> -	$first_ts = $db{$key}->{'queue'} if not defined $first_ts or $db{$key}->{'queue'} < $first_ts;
> -	$last_ts = $end if $end > $last_ts;
> -
>   	# correct duration of merged batches
>   	if ($correct_durations and exists $db{$key}->{'no-end'}) {
>   		my $ctx = $db{$key}->{'ctx'};
> @@ -584,12 +579,18 @@ foreach my $key (@sorted_keys) {
>   
>   @sorted_keys = sort sortStart keys %db if $re_sort;
>   
> +my $last_ts = 0;
> +my $first_ts;
> +
>   foreach my $key (@sorted_keys) {
>   	my $ring = $db{$key}->{'ring'};
>   	my $end = $db{$key}->{'end'};
>   	my $start = $db{$key}->{'start'};
>   	my $notify = $db{$key}->{'notify'};
>   
> +	$first_ts = $db{$key}->{'queue'} if not defined $first_ts or $db{$key}->{'queue'} < $first_ts;
> +	$last_ts = $end if $end > $last_ts;
> +
>   	$db{$key}->{'context-complete-delay'} = $end - $notify;
>   	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
>   	$db{$key}->{'submit-delay'} = $db{$key}->{'submit'} - $db{$key}->{'queue'};


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

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: [PATCH i-g-t 09/11] trace.pl: Add support for colouring context execution
  2018-03-06 12:43   ` [igt-dev] " Tvrtko Ursulin
@ 2018-04-18 17:02     ` Lionel Landwerlin
  -1 siblings, 0 replies; 34+ messages in thread
From: Lionel Landwerlin @ 2018-04-18 17:02 UTC (permalink / raw)
  To: Tvrtko Ursulin, igt-dev; +Cc: Intel-gfx

One suggestion below, otherwise :

Reviewed-by: Lionel Landwerlin <lionel.g.landwerlin@intel.com>

On 06/03/18 04:43, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>
> Add the command line switch which uses different colours for different
> context execution boxes.
>
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> Cc: John Harrison <John.C.Harrison@intel.com>
> ---
>   scripts/trace.pl | 41 +++++++++++++++++++++++++++++++++++++++--
>   1 file changed, 39 insertions(+), 2 deletions(-)
>
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index e7ce273ef26a..ff61dea0768d 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;
>   
>   foreach my $key (@sorted_keys) {
>   	my $ring = $db{$key}->{'ring'};
> @@ -590,6 +609,8 @@ 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;
>   
>   	$db{$key}->{'context-complete-delay'} = $end - $notify;
>   	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
> @@ -721,6 +742,8 @@ foreach my $key (keys %reqwait) {
>   say sprintf('GPU: %.2f%% idle, %.2f%% busy',
>   	     $flat_busy{'gpu-idle'}, $flat_busy{'gpu-busy'}) unless $html;
>   
> +my $execute_colour = $colour_contexts ? 'multi-colour' : 'pink';
> +
>   print <<ENDHTML if $html;
>   <!DOCTYPE HTML>
>   <html>
> @@ -741,7 +764,7 @@ print <<ENDHTML if $html;
>   <button onclick="toggleStackSubgroups()">Toggle stacking</button>
>   
>   <p>
> -pink = requests executing on the GPU<br>
> +$execute_colour = 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>
>   </p>
> @@ -861,6 +884,19 @@ sub sortQueue {
>   	return $val;
>   }
>   
> +my @html_colours = ( 'Pink', 'Green', 'Purple', 'Gold', 'Cyan', 'Brown',
> +		     'DeepPink', 'LightGreen', 'Plum', 'Orange', 'Teal', 'Peru',
> +		     'Indigo', 'Khaki', 'Coral', 'Olive' );

One way to generate as many colors as you need is to use hsv and divide 
the hue range into as many colors you need.
Then the color for element X is X * 360 / n_colors (http://colorizer.org/)

Just a suggestion :)

> +
> +sub ctx_colour
> +{
> +       my ($ctx) = (@_);
> +
> +       return 'Pink' unless $colour_contexts;
> +
> +       return $html_colours[($ctx - $min_ctx) % scalar(@html_colours)];
> +}
> +
>   my $i = 0;
>   foreach my $key (sort sortQueue keys %db) {
>   	my ($name, $ctx, $seqno) = ($db{$key}->{'name'}, $db{$key}->{'ctx'}, $db{$key}->{'seqno'});
> @@ -898,7 +934,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) . ';';
>   		}
>   		$content = "$name <small>$db{$key}->{'port'}</small>";
>   		$content .= ' <small><i>???</i></small> ' if exists $db{$key}->{'incomplete'};


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

^ permalink raw reply	[flat|nested] 34+ messages in thread

* Re: [igt-dev] [Intel-gfx] [PATCH i-g-t 09/11] trace.pl: Add support for colouring context execution
@ 2018-04-18 17:02     ` Lionel Landwerlin
  0 siblings, 0 replies; 34+ messages in thread
From: Lionel Landwerlin @ 2018-04-18 17:02 UTC (permalink / raw)
  To: Tvrtko Ursulin, igt-dev; +Cc: Intel-gfx

One suggestion below, otherwise :

Reviewed-by: Lionel Landwerlin <lionel.g.landwerlin@intel.com>

On 06/03/18 04:43, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>
> Add the command line switch which uses different colours for different
> context execution boxes.
>
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> Cc: John Harrison <John.C.Harrison@intel.com>
> ---
>   scripts/trace.pl | 41 +++++++++++++++++++++++++++++++++++++++--
>   1 file changed, 39 insertions(+), 2 deletions(-)
>
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index e7ce273ef26a..ff61dea0768d 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;
>   
>   foreach my $key (@sorted_keys) {
>   	my $ring = $db{$key}->{'ring'};
> @@ -590,6 +609,8 @@ 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;
>   
>   	$db{$key}->{'context-complete-delay'} = $end - $notify;
>   	$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
> @@ -721,6 +742,8 @@ foreach my $key (keys %reqwait) {
>   say sprintf('GPU: %.2f%% idle, %.2f%% busy',
>   	     $flat_busy{'gpu-idle'}, $flat_busy{'gpu-busy'}) unless $html;
>   
> +my $execute_colour = $colour_contexts ? 'multi-colour' : 'pink';
> +
>   print <<ENDHTML if $html;
>   <!DOCTYPE HTML>
>   <html>
> @@ -741,7 +764,7 @@ print <<ENDHTML if $html;
>   <button onclick="toggleStackSubgroups()">Toggle stacking</button>
>   
>   <p>
> -pink = requests executing on the GPU<br>
> +$execute_colour = 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>
>   </p>
> @@ -861,6 +884,19 @@ sub sortQueue {
>   	return $val;
>   }
>   
> +my @html_colours = ( 'Pink', 'Green', 'Purple', 'Gold', 'Cyan', 'Brown',
> +		     'DeepPink', 'LightGreen', 'Plum', 'Orange', 'Teal', 'Peru',
> +		     'Indigo', 'Khaki', 'Coral', 'Olive' );

One way to generate as many colors as you need is to use hsv and divide 
the hue range into as many colors you need.
Then the color for element X is X * 360 / n_colors (http://colorizer.org/)

Just a suggestion :)

> +
> +sub ctx_colour
> +{
> +       my ($ctx) = (@_);
> +
> +       return 'Pink' unless $colour_contexts;
> +
> +       return $html_colours[($ctx - $min_ctx) % scalar(@html_colours)];
> +}
> +
>   my $i = 0;
>   foreach my $key (sort sortQueue keys %db) {
>   	my ($name, $ctx, $seqno) = ($db{$key}->{'name'}, $db{$key}->{'ctx'}, $db{$key}->{'seqno'});
> @@ -898,7 +934,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) . ';';
>   		}
>   		$content = "$name <small>$db{$key}->{'port'}</small>";
>   		$content .= ' <small><i>???</i></small> ' if exists $db{$key}->{'incomplete'};


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

^ permalink raw reply	[flat|nested] 34+ messages in thread

end of thread, other threads:[~2018-04-18 17:02 UTC | newest]

Thread overview: 34+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-03-06 12:43 [PATCH i-g-t v2 00/11] trace.pl fixes Tvrtko Ursulin
2018-03-06 12:43 ` [Intel-gfx] " Tvrtko Ursulin
2018-03-06 12:43 ` [PATCH i-g-t 01/11] trace.pl: Catch-up with tracepoint renames Tvrtko Ursulin
2018-03-06 12:43   ` [Intel-gfx] " Tvrtko Ursulin
2018-03-06 12:43 ` [PATCH i-g-t 02/11] scripts/trace.pl: More hash key optimisations Tvrtko Ursulin
2018-03-06 12:43   ` [igt-dev] " Tvrtko Ursulin
2018-03-06 12:43 ` [PATCH i-g-t 03/11] scripts/trace.pl: Sort order Tvrtko Ursulin
2018-03-06 12:43   ` [igt-dev] " Tvrtko Ursulin
2018-03-06 12:43 ` [PATCH i-g-t 04/11] scripts/trace.pl: Calculate stats only after all munging Tvrtko Ursulin
2018-03-06 12:43   ` [igt-dev] " Tvrtko Ursulin
2018-03-06 12:43 ` [PATCH i-g-t 05/11] scripts/trace.pl: Simplify 'end' & 'notify' generation Tvrtko Ursulin
2018-03-06 12:43   ` [igt-dev] " Tvrtko Ursulin
2018-03-06 12:43 ` [PATCH i-g-t 06/11] trace.pl: Move sortQueue near its user Tvrtko Ursulin
2018-03-06 12:43   ` [igt-dev] " Tvrtko Ursulin
2018-04-18 16:56   ` Lionel Landwerlin
2018-04-18 16:56     ` [Intel-gfx] " Lionel Landwerlin
2018-03-06 12:43 ` [PATCH i-g-t 07/11] trace.pl: Move min/max timestamp lookup to last loop Tvrtko Ursulin
2018-03-06 12:43   ` [igt-dev] " Tvrtko Ursulin
2018-04-18 16:56   ` Lionel Landwerlin
2018-04-18 16:56     ` Lionel Landwerlin
2018-03-06 12:43 ` [PATCH i-g-t 08/11] trace.pl: Fix engine busy accounting in split mode Tvrtko Ursulin
2018-03-06 12:43   ` [igt-dev] " Tvrtko Ursulin
2018-03-06 12:43 ` [PATCH i-g-t 09/11] trace.pl: Add support for colouring context execution Tvrtko Ursulin
2018-03-06 12:43   ` [igt-dev] " Tvrtko Ursulin
2018-04-18 17:02   ` Lionel Landwerlin
2018-04-18 17:02     ` [igt-dev] [Intel-gfx] " Lionel Landwerlin
2018-03-06 12:43 ` [PATCH i-g-t 10/11] trace.pl: Fix incomplete request handling Tvrtko Ursulin
2018-03-06 12:43   ` [Intel-gfx] " Tvrtko Ursulin
2018-03-06 12:43 ` [PATCH i-g-t 11/11] trace.pl: Fix request split mode Tvrtko Ursulin
2018-03-06 12:43   ` [igt-dev] " Tvrtko Ursulin
2018-03-06 14:18 ` [igt-dev] ✓ Fi.CI.BAT: success for trace.pl fixes (rev2) Patchwork
2018-03-06 19:29 ` [igt-dev] ✓ Fi.CI.IGT: " Patchwork
2018-04-18 14:52 ` [igt-dev] [PATCH i-g-t v2 00/11] trace.pl fixes Tvrtko Ursulin
2018-04-18 14:52   ` Tvrtko Ursulin

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.