* [igt-dev] [PATCH i-g-t 1/4] trace.pl: Add support for colouring context execution
2018-04-23 9:52 [igt-dev] [PATCH i-g-t v3 0/4] trace.pl fixes Tvrtko Ursulin
@ 2018-04-23 9:52 ` Tvrtko Ursulin
2018-04-23 9:52 ` [igt-dev] [PATCH i-g-t 2/4] trace.pl: Fix engine busy accounting in split mode Tvrtko Ursulin
` (4 subsequent siblings)
5 siblings, 0 replies; 9+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23 9:52 UTC (permalink / raw)
To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin
From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Add the command line switch which uses different colours for different
context execution boxes.
v2:
* Use HSL to simplify color generation. (Lionel)
* Colour other boxes in the same colour but different shade so it is
easier to follow the timeline.
Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: John Harrison <John.C.Harrison@intel.com>
Reviewed-by: Lionel Landwerlin <lionel.g.landwerlin@intel.com> # v1
---
scripts/trace.pl | 54 ++++++++++++++++++++++++++++++++++++++++++++++++------
1 file changed, 48 insertions(+), 6 deletions(-)
diff --git a/scripts/trace.pl b/scripts/trace.pl
index 27b39efcebbd..c8182a8ea86d 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -40,6 +40,7 @@ my $trace = 0;
my $avg_delay_stats = 0;
my $squash_context_id = 0;
my $gpu_timeline = 0;
+my $colour_contexts = 0;
my @args;
@@ -110,6 +111,8 @@ Usage:
--squash-ctx-id Squash context id by substracting engine
id from ctx id.
--gpu-timeline Draw overall GPU busy timeline.
+ --colour-contexts / -c Use different colours for different
+ context execution boxes.
ENDHELP
exit 0;
@@ -279,6 +282,20 @@ sub arg_skip_box
return @_;
}
+sub arg_colour_contexts
+{
+ return unless scalar(@_);
+
+ if ($_[0] eq '--colour-contexts' or
+ $_[0] eq '--color-contexts' or
+ $_[0] eq '-c') {
+ shift @_;
+ $colour_contexts = 1;
+ }
+
+ return @_;
+}
+
@args = @ARGV;
while (@args) {
my $left = scalar(@args);
@@ -294,6 +311,7 @@ while (@args) {
@args = arg_split_requests(@args);
@args = arg_ignore_ring(@args);
@args = arg_skip_box(@args);
+ @args = arg_colour_contexts(@args);
last if $left == scalar(@args);
}
@@ -581,6 +599,7 @@ foreach my $key (@sorted_keys) {
my $last_ts = 0;
my $first_ts;
+my ($min_ctx, $max_ctx);
foreach my $key (@sorted_keys) {
my $ring = $db{$key}->{'ring'};
@@ -590,6 +609,10 @@ foreach my $key (@sorted_keys) {
$first_ts = $db{$key}->{'queue'} if not defined $first_ts or $db{$key}->{'queue'} < $first_ts;
$last_ts = $end if $end > $last_ts;
+ $min_ctx = $db{$key}->{'ctx'} if not defined $min_ctx or
+ $db{$key}->{'ctx'} < $min_ctx;
+ $max_ctx = $db{$key}->{'ctx'} if not defined $max_ctx or
+ $db{$key}->{'ctx'} > $max_ctx;
$db{$key}->{'context-complete-delay'} = $end - $notify;
$db{$key}->{'execute-delay'} = $start - $db{$key}->{'submit'};
@@ -720,6 +743,10 @@ foreach my $key (keys %reqwait) {
say sprintf('GPU: %.2f%% idle, %.2f%% busy',
$flat_busy{'gpu-idle'}, $flat_busy{'gpu-busy'}) unless $html;
+my $queued_colour = $colour_contexts ? 'multi-colour light' : 'blue';
+my $runnable_colour = $colour_contexts ? 'multi-colour dark' : 'grey';
+my $execute_colour = $colour_contexts ? 'multi-colour' : 'pink';
+
print <<ENDHTML if $html;
<!DOCTYPE HTML>
<html>
@@ -740,9 +767,9 @@ print <<ENDHTML if $html;
<button onclick="toggleStackSubgroups()">Toggle stacking</button>
<p>
-pink = requests executing on the GPU<br>
-grey = runnable requests waiting for a slot on GPU<br>
-blue = requests waiting on fences and dependencies before they are runnable<br>
+$execute_colour = requests executing on the GPU<br>
+$runnable_colour = runnable requests waiting for a slot on GPU<br>
+$queued_colour = requests waiting on fences and dependencies before they are runnable<br>
</p>
<p>
Boxes are in format 'ctx-id/seqno'.
@@ -860,6 +887,18 @@ sub sortQueue {
return $val;
}
+sub ctx_colour
+{
+ my ($ctx, $s, $l) = (@_);
+ my $val;
+
+ return 'Pink;' unless $colour_contexts;
+
+ $val = int(360 / ($max_ctx - $min_ctx + 1)) * ($ctx - $min_ctx);
+
+ return "hsl($val, $s%, $l%);";
+}
+
my $i = 0;
foreach my $key (sort sortQueue keys %db) {
my ($name, $ctx, $seqno) = ($db{$key}->{'name'}, $db{$key}->{'ctx'}, $db{$key}->{'seqno'});
@@ -874,7 +913,8 @@ foreach my $key (sort sortQueue keys %db) {
# submit to execute
unless (exists $skip_box{'queue'}) {
$skey = 2 * $max_seqno * $ctx + 2 * $seqno;
- $style = 'color: black; background-color: lightblue;';
+ $style = 'color: black; background-color: ' .
+ ctx_colour($ctx, 35, 85);
$content = "$name<br>$db{$key}->{'submit-delay'}us <small>($db{$key}->{'execute-delay'}us)</small>";
$startend = 'start: \'' . ts($queue) . '\', end: \'' . ts($submit) . '\'';
print "\t{id: $i, key: $skey, $type group: $group, subgroup: 1, subgroupOrder: 1, content: '$content', $startend, style: \'$style\'},\n";
@@ -884,7 +924,8 @@ foreach my $key (sort sortQueue keys %db) {
# execute to start
unless (exists $skip_box{'ready'}) {
$skey = 2 * $max_seqno * $ctx + 2 * $seqno + 1;
- $style = 'color: black; background-color: lightgrey;';
+ $style = 'color: black; background-color: ' .
+ ctx_colour($ctx, 35, 45);
$content = "<small>$name<br>$db{$key}->{'execute-delay'}us</small>";
$startend = 'start: \'' . ts($submit) . '\', end: \'' . ts($start) . '\'';
print "\t{id: $i, key: $skey, $type group: $group, subgroup: 1, subgroupOrder: 2, content: '$content', $startend, style: \'$style\'},\n";
@@ -897,7 +938,8 @@ foreach my $key (sort sortQueue keys %db) {
if (exists $db{$key}->{'incomplete'}) {
$style = 'color: white; background-color: red;';
} else {
- $style = 'color: black; background-color: pink;';
+ $style = 'color: black; background-color: ' .
+ ctx_colour($ctx, 80, 65);
}
$content = "$name <small>$db{$key}->{'port'}</small>";
$content .= ' <small><i>???</i></small> ' if exists $db{$key}->{'incomplete'};
--
2.14.1
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev
^ permalink raw reply related [flat|nested] 9+ messages in thread* [igt-dev] [PATCH i-g-t 2/4] trace.pl: Fix engine busy accounting in split mode
2018-04-23 9:52 [igt-dev] [PATCH i-g-t v3 0/4] trace.pl fixes Tvrtko Ursulin
2018-04-23 9:52 ` [igt-dev] [PATCH i-g-t 1/4] trace.pl: Add support for colouring context execution Tvrtko Ursulin
@ 2018-04-23 9:52 ` Tvrtko Ursulin
2018-04-23 9:52 ` [igt-dev] [PATCH i-g-t 3/4] trace.pl: Fix incomplete request handling Tvrtko Ursulin
` (3 subsequent siblings)
5 siblings, 0 replies; 9+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23 9:52 UTC (permalink / raw)
To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin
From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
In split mode all requests have to be added up since they were previously
re-arranged so there is no overlap.
Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: John Harrison <John.C.Harrison@intel.com>
---
scripts/trace.pl | 3 ++-
1 file changed, 2 insertions(+), 1 deletion(-)
diff --git a/scripts/trace.pl b/scripts/trace.pl
index c8182a8ea86d..eb5a36b91a5c 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -619,7 +619,8 @@ foreach my $key (@sorted_keys) {
$db{$key}->{'submit-delay'} = $db{$key}->{'submit'} - $db{$key}->{'queue'};
$db{$key}->{'duration'} = $notify - $start;
- $running{$ring} += $end - $start unless exists $db{$key}->{'no-end'};
+ $running{$ring} += $end - $start if $correct_durations or
+ not exists $db{$key}->{'no-end'};
$runnable{$ring} += $db{$key}->{'execute-delay'};
$queued{$ring} += $start - $db{$key}->{'execute-delay'} - $db{$key}->{'queue'};
--
2.14.1
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev
^ permalink raw reply related [flat|nested] 9+ messages in thread* [igt-dev] [PATCH i-g-t 3/4] trace.pl: Fix incomplete request handling
2018-04-23 9:52 [igt-dev] [PATCH i-g-t v3 0/4] trace.pl fixes Tvrtko Ursulin
2018-04-23 9:52 ` [igt-dev] [PATCH i-g-t 1/4] trace.pl: Add support for colouring context execution Tvrtko Ursulin
2018-04-23 9:52 ` [igt-dev] [PATCH i-g-t 2/4] trace.pl: Fix engine busy accounting in split mode Tvrtko Ursulin
@ 2018-04-23 9:52 ` Tvrtko Ursulin
2018-05-07 23:58 ` John Harrison
2018-04-23 9:52 ` [igt-dev] [PATCH i-g-t 4/4] trace.pl: Fix request split mode Tvrtko Ursulin
` (2 subsequent siblings)
5 siblings, 1 reply; 9+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23 9:52 UTC (permalink / raw)
To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin
From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Incomplete requests (no notify, no context complete) have to be corrected
by looking at the engine timeline, and not the sorted-by-start-time view
as was previously used.
Per-engine timelines are generated on demand and cached for later use.
v2: Find end of current context on the engine timeline instead of just
using the next request for adjusting the incomplete start time.
Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: John Harrison <John.C.Harrison@intel.com>
---
scripts/trace.pl | 86 ++++++++++++++++++++++++++++++++++++++++++--------------
1 file changed, 65 insertions(+), 21 deletions(-)
diff --git a/scripts/trace.pl b/scripts/trace.pl
index eb5a36b91a5c..b48f43225fc1 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -26,6 +26,8 @@ use strict;
use warnings;
use 5.010;
+use List::Util;
+
my $gid = 0;
my (%db, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait);
my @freqs;
@@ -516,29 +518,71 @@ foreach my $key (keys %db) {
}
}
-# Fix up incompletes
my $key_count = scalar(keys %db);
-foreach my $key (keys %db) {
- next unless exists $db{$key}->{'incomplete'};
- # End the incomplete batch at the time next one starts
- my $ring = $db{$key}->{'ring'};
- my $ctx = $db{$key}->{'ctx'};
- my $seqno = $db{$key}->{'seqno'};
- my $next_key;
- my $i = 1;
+my %engine_timelines;
+
+sub sortEngine {
+ my $as = $db{$a}->{'global'};
+ my $bs = $db{$b}->{'global'};
+ my $val;
+
+ $val = $as <=> $bs;
+
+ die if $val == 0;
+
+ return $val;
+}
+
+sub get_engine_timeline {
+ my ($ring) = @_;
+ my @timeline;
+
+ return $engine_timelines{$ring} if exists $engine_timelines{$ring};
+
+ @timeline = grep { $db{$_}->{'ring'} == $ring } keys %db;
+ # FIXME seqno restart
+ @timeline = sort sortEngine @timeline;
+
+ $engine_timelines{$ring} = \@timeline;
+
+ return \@timeline;
+}
+
+# Fix up incompletes by ending them when the last request of a coalesced group
+# ends. Start by filtering out the incomplete requests.
+my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
+
+foreach my $key (@incompletes) {
+ my $timeline;
+ my $last_key;
my $end;
+ my $i;
- do {
- $next_key = db_key($ring, $ctx, $seqno + $i);
- $i++;
- } until ((exists $db{$next_key} and not exists $db{$next_key}->{'incomplete'})
- or $i > $key_count); # ugly stop hack
+ # Find the next request on the engine timeline.
+ $timeline = get_engine_timeline($db{$key}->{'ring'});
+ $i = List::Util::first { ${$timeline}[$_] eq $key } 0..$#{$timeline};
+
+ while ($i < $#{$timeline}) {
+ my $next;
+
+ $i = $i + 1;
+ $next = ${$timeline}[$i];
+
+ next if exists $db{$next}->{'incomplete'};
- if (exists $db{$next_key}) {
- $end = $db{$next_key}->{'end'};
+ $last_key = $next;
+ last;
+ }
+
+ if (defined $last_key) {
+ if ($db{$key}->{'ctx'} eq $db{$last_key}->{'ctx'}) {
+ $end = $db{$last_key}->{'end'};
+ } else {
+ $end = $db{$last_key}->{'start'};
+ }
} else {
- # No info at all, fake it:
+ # No next submission, fake it.
$end = $db{$key}->{'start'} + 999;
}
@@ -546,10 +590,6 @@ foreach my $key (keys %db) {
$db{$key}->{'end'} = $end;
}
-# GPU time accounting
-my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
-my (%submit_avg, %execute_avg, %ctxsave_avg);
-
sub sortStart {
my $as = $db{$a}->{'start'};
my $bs = $db{$b}->{'start'};
@@ -597,6 +637,10 @@ foreach my $key (@sorted_keys) {
@sorted_keys = sort sortStart keys %db if $re_sort;
+# GPU time accounting
+my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
+my (%submit_avg, %execute_avg, %ctxsave_avg);
+
my $last_ts = 0;
my $first_ts;
my ($min_ctx, $max_ctx);
--
2.14.1
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev
^ permalink raw reply related [flat|nested] 9+ messages in thread* Re: [igt-dev] [PATCH i-g-t 3/4] trace.pl: Fix incomplete request handling
2018-04-23 9:52 ` [igt-dev] [PATCH i-g-t 3/4] trace.pl: Fix incomplete request handling Tvrtko Ursulin
@ 2018-05-07 23:58 ` John Harrison
2018-05-08 12:07 ` Tvrtko Ursulin
0 siblings, 1 reply; 9+ messages in thread
From: John Harrison @ 2018-05-07 23:58 UTC (permalink / raw)
To: Tvrtko Ursulin, igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin
On 4/23/2018 2:52 AM, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>
> Incomplete requests (no notify, no context complete) have to be corrected
> by looking at the engine timeline, and not the sorted-by-start-time view
> as was previously used.
>
> Per-engine timelines are generated on demand and cached for later use.
>
> v2: Find end of current context on the engine timeline instead of just
> using the next request for adjusting the incomplete start time.
>
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> Cc: John Harrison <John.C.Harrison@intel.com>
> ---
> scripts/trace.pl | 86 ++++++++++++++++++++++++++++++++++++++++++--------------
> 1 file changed, 65 insertions(+), 21 deletions(-)
>
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index eb5a36b91a5c..b48f43225fc1 100755
> --- a/scripts/trace.pl
> +++ b/scripts/trace.pl
> @@ -26,6 +26,8 @@ use strict;
> use warnings;
> use 5.010;
>
> +use List::Util;
> +
> my $gid = 0;
> my (%db, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait);
> my @freqs;
> @@ -516,29 +518,71 @@ foreach my $key (keys %db) {
> }
> }
>
> -# Fix up incompletes
> my $key_count = scalar(keys %db);
> -foreach my $key (keys %db) {
> - next unless exists $db{$key}->{'incomplete'};
>
> - # End the incomplete batch at the time next one starts
> - my $ring = $db{$key}->{'ring'};
> - my $ctx = $db{$key}->{'ctx'};
> - my $seqno = $db{$key}->{'seqno'};
> - my $next_key;
> - my $i = 1;
> +my %engine_timelines;
> +
> +sub sortEngine {
> + my $as = $db{$a}->{'global'};
> + my $bs = $db{$b}->{'global'};
> + my $val;
> +
> + $val = $as <=> $bs;
> +
> + die if $val == 0;
> +
> + return $val;
> +}
> +
> +sub get_engine_timeline {
> + my ($ring) = @_;
> + my @timeline;
> +
> + return $engine_timelines{$ring} if exists $engine_timelines{$ring};
> +
> + @timeline = grep { $db{$_}->{'ring'} == $ring } keys %db;
> + # FIXME seqno restart
> + @timeline = sort sortEngine @timeline;
> +
> + $engine_timelines{$ring} = \@timeline;
> +
> + return \@timeline;
> +}
> +
> +# Fix up incompletes by ending them when the last request of a coalesced group
> +# ends. Start by filtering out the incomplete requests.
> +my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
> +
> +foreach my $key (@incompletes) {
> + my $timeline;
> + my $last_key;
> my $end;
> + my $i;
>
> - do {
> - $next_key = db_key($ring, $ctx, $seqno + $i);
> - $i++;
> - } until ((exists $db{$next_key} and not exists $db{$next_key}->{'incomplete'})
> - or $i > $key_count); # ugly stop hack
> + # Find the next request on the engine timeline.
> + $timeline = get_engine_timeline($db{$key}->{'ring'});
> + $i = List::Util::first { ${$timeline}[$_] eq $key } 0..$#{$timeline};
This line in particular massively slows the process down! With one of my
longer trace files, the incomplete fix-up step took 30 seconds prior to
this. After this patch, it took 11205 seconds! Just shy of four hours!
Caching the start point of the search greatly speeds things up but it is
still a lot slower than previous. With the following, it is down to 4068
seconds, or a little over one hour.
+my $lastIndex = 0;
...
- $i = List::Util::first { ${$timeline}[$_] eq $key }
0..$#{$timeline};
+ $i = List::Util::first { ${$timeline}[$_] eq $key }
${lastIndex}..$#{$timeline};
+ if( !defined($i) ) {
+ $i = List::Util::first { ${$timeline}[$_] eq $key }
0..$#{$timeline};
+ defined($i) || die "Failed to find '$key'!\n";
+ }
+ $lastIndex = $i;
If I sort the '@incompletes' array numerically by seqno rather than as a
string sort, then I get rid of all the first level match failures
(except when rolling from one ring to the next) and the time drops to
1819 seconds or half an hour.
+sub sortKeys {
+ my( $aR, $aC, $aS ) = split( '/', $a );
+ my( $bR, $bC, $bS ) = split( '/', $b );
+ my $val;
+
+ $val = $aR <=> $bR;
+ return $val if $val != 0;
+
+ $val = $aC <=> $bC;
+ return $val if $val != 0;
+
+ return $aS <=> $bS;
+}
+
-my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
+my @incompletes = sort sortKeys grep { exists $db{$_}->{'incomplete'} }
keys %db;
> +
> + while ($i < $#{$timeline}) {
> + my $next;
> +
> + $i = $i + 1;
$i++; ?
> + $next = ${$timeline}[$i];
> +
> + next if exists $db{$next}->{'incomplete'};
>
> - if (exists $db{$next_key}) {
> - $end = $db{$next_key}->{'end'};
> + $last_key = $next;
> + last;
> + }
> +
> + if (defined $last_key) {
> + if ($db{$key}->{'ctx'} eq $db{$last_key}->{'ctx'}) {
> + $end = $db{$last_key}->{'end'};
> + } else {
> + $end = $db{$last_key}->{'start'};
> + }
> } else {
> - # No info at all, fake it:
> + # No next submission, fake it.
> $end = $db{$key}->{'start'} + 999;
> }
>
> @@ -546,10 +590,6 @@ foreach my $key (keys %db) {
> $db{$key}->{'end'} = $end;
> }
>
> -# GPU time accounting
> -my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
> -my (%submit_avg, %execute_avg, %ctxsave_avg);
> -
> sub sortStart {
> my $as = $db{$a}->{'start'};
> my $bs = $db{$b}->{'start'};
> @@ -597,6 +637,10 @@ foreach my $key (@sorted_keys) {
>
> @sorted_keys = sort sortStart keys %db if $re_sort;
>
> +# GPU time accounting
> +my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
> +my (%submit_avg, %execute_avg, %ctxsave_avg);
> +
This is just a prettification type change? Moving declarations to be
more local to their usage? It doesn't seem to be related to the above
changes or explicitly mentioned in the commit message.
> my $last_ts = 0;
> my $first_ts;
> my ($min_ctx, $max_ctx);
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev
^ permalink raw reply [flat|nested] 9+ messages in thread* Re: [igt-dev] [PATCH i-g-t 3/4] trace.pl: Fix incomplete request handling
2018-05-07 23:58 ` John Harrison
@ 2018-05-08 12:07 ` Tvrtko Ursulin
0 siblings, 0 replies; 9+ messages in thread
From: Tvrtko Ursulin @ 2018-05-08 12:07 UTC (permalink / raw)
To: John Harrison, Tvrtko Ursulin, igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin
On 08/05/2018 00:58, John Harrison wrote:
> On 4/23/2018 2:52 AM, Tvrtko Ursulin wrote:
>> From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>>
>> Incomplete requests (no notify, no context complete) have to be corrected
>> by looking at the engine timeline, and not the sorted-by-start-time view
>> as was previously used.
>>
>> Per-engine timelines are generated on demand and cached for later use.
>>
>> v2: Find end of current context on the engine timeline instead of just
>> using the next request for adjusting the incomplete start time.
>>
>> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>> Cc: John Harrison <John.C.Harrison@intel.com>
>> ---
>> scripts/trace.pl | 86
>> ++++++++++++++++++++++++++++++++++++++++++--------------
>> 1 file changed, 65 insertions(+), 21 deletions(-)
>>
>> diff --git a/scripts/trace.pl b/scripts/trace.pl
>> index eb5a36b91a5c..b48f43225fc1 100755
>> --- a/scripts/trace.pl
>> +++ b/scripts/trace.pl
>> @@ -26,6 +26,8 @@ use strict;
>> use warnings;
>> use 5.010;
>> +use List::Util;
>> +
>> my $gid = 0;
>> my (%db, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait);
>> my @freqs;
>> @@ -516,29 +518,71 @@ foreach my $key (keys %db) {
>> }
>> }
>> -# Fix up incompletes
>> my $key_count = scalar(keys %db);
>> -foreach my $key (keys %db) {
>> - next unless exists $db{$key}->{'incomplete'};
>> - # End the incomplete batch at the time next one starts
>> - my $ring = $db{$key}->{'ring'};
>> - my $ctx = $db{$key}->{'ctx'};
>> - my $seqno = $db{$key}->{'seqno'};
>> - my $next_key;
>> - my $i = 1;
>> +my %engine_timelines;
>> +
>> +sub sortEngine {
>> + my $as = $db{$a}->{'global'};
>> + my $bs = $db{$b}->{'global'};
>> + my $val;
>> +
>> + $val = $as <=> $bs;
>> +
>> + die if $val == 0;
>> +
>> + return $val;
>> +}
>> +
>> +sub get_engine_timeline {
>> + my ($ring) = @_;
>> + my @timeline;
>> +
>> + return $engine_timelines{$ring} if exists $engine_timelines{$ring};
>> +
>> + @timeline = grep { $db{$_}->{'ring'} == $ring } keys %db;
>> + # FIXME seqno restart
>> + @timeline = sort sortEngine @timeline;
>> +
>> + $engine_timelines{$ring} = \@timeline;
>> +
>> + return \@timeline;
>> +}
>> +
>> +# Fix up incompletes by ending them when the last request of a
>> coalesced group
>> +# ends. Start by filtering out the incomplete requests.
>> +my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
>> +
>> +foreach my $key (@incompletes) {
>> + my $timeline;
>> + my $last_key;
>> my $end;
>> + my $i;
>> - do {
>> - $next_key = db_key($ring, $ctx, $seqno + $i);
>> - $i++;
>> - } until ((exists $db{$next_key} and not exists
>> $db{$next_key}->{'incomplete'})
>> - or $i > $key_count); # ugly stop hack
>> + # Find the next request on the engine timeline.
>> + $timeline = get_engine_timeline($db{$key}->{'ring'});
>> + $i = List::Util::first { ${$timeline}[$_] eq $key }
>> 0..$#{$timeline};
> This line in particular massively slows the process down! With one of my
> longer trace files, the incomplete fix-up step took 30 seconds prior to
> this. After this patch, it took 11205 seconds! Just shy of four hours!
Gee, awful. :(
> Caching the start point of the search greatly speeds things up but it is
> still a lot slower than previous. With the following, it is down to 4068
> seconds, or a little over one hour.
> +my $lastIndex = 0;
> ...
> - $i = List::Util::first { ${$timeline}[$_] eq $key }
> 0..$#{$timeline};
> + $i = List::Util::first { ${$timeline}[$_] eq $key }
> ${lastIndex}..$#{$timeline};
> + if( !defined($i) ) {
> + $i = List::Util::first { ${$timeline}[$_] eq $key }
> 0..$#{$timeline};
> + defined($i) || die "Failed to find '$key'!\n";
> + }
> + $lastIndex = $i;
This definitely makes sense and I'll take it.
> If I sort the '@incompletes' array numerically by seqno rather than as a
> string sort, then I get rid of all the first level match failures
> (except when rolling from one ring to the next) and the time drops to
> 1819 seconds or half an hour.
>
> +sub sortKeys {
> + my( $aR, $aC, $aS ) = split( '/', $a );
> + my( $bR, $bC, $bS ) = split( '/', $b );
> + my $val;
> +
> + $val = $aR <=> $bR;
> + return $val if $val != 0;
> +
> + $val = $aC <=> $bC;
> + return $val if $val != 0;
> +
> + return $aS <=> $bS;
> +}
For here I am thinking to try processing incompletes per-ring instead.
That should limit the walks and enable some more numerical comparisons.
I'll also try adding cachine to the loop after the List::Util::first
lookup to avoid repeatedly looking for the next complete, in cases when
there are a lot of bunched up incompletes.
> +
>
> -my @incompletes = sort grep { exists $db{$_}->{'incomplete'} } keys %db;
> +my @incompletes = sort sortKeys grep { exists $db{$_}->{'incomplete'} }
> keys %db;
>
>
>
>> +
>> + while ($i < $#{$timeline}) {
>> + my $next;
>> +
>> + $i = $i + 1;
> $i++; ?
Yeah.. there was a language which didn't support increments and my brain
got confused that's Perl, when it is actually Python.. :)
>
>> + $next = ${$timeline}[$i];
>> +
>> + next if exists $db{$next}->{'incomplete'};
>> - if (exists $db{$next_key}) {
>> - $end = $db{$next_key}->{'end'};
>> + $last_key = $next;
>> + last;
>> + }
>> +
>> + if (defined $last_key) {
>> + if ($db{$key}->{'ctx'} eq $db{$last_key}->{'ctx'}) {
>> + $end = $db{$last_key}->{'end'};
>> + } else {
>> + $end = $db{$last_key}->{'start'};
>> + }
>> } else {
>> - # No info at all, fake it:
>> + # No next submission, fake it.
>> $end = $db{$key}->{'start'} + 999;
>> }
>> @@ -546,10 +590,6 @@ foreach my $key (keys %db) {
>> $db{$key}->{'end'} = $end;
>> }
>> -# GPU time accounting
>> -my (%running, %runnable, %queued, %batch_avg, %batch_total_avg,
>> %batch_count);
>> -my (%submit_avg, %execute_avg, %ctxsave_avg);
>> -
>> sub sortStart {
>> my $as = $db{$a}->{'start'};
>> my $bs = $db{$b}->{'start'};
>> @@ -597,6 +637,10 @@ foreach my $key (@sorted_keys) {
>> @sorted_keys = sort sortStart keys %db if $re_sort;
>> +# GPU time accounting
>> +my (%running, %runnable, %queued, %batch_avg, %batch_total_avg,
>> %batch_count);
>> +my (%submit_avg, %execute_avg, %ctxsave_avg);
>> +
>
> This is just a prettification type change? Moving declarations to be
> more local to their usage? It doesn't seem to be related to the above
> changes or explicitly mentioned in the commit message.
Yes, just moving closer to use site.
Regards,
Tvrtko
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev
^ permalink raw reply [flat|nested] 9+ messages in thread
* [igt-dev] [PATCH i-g-t 4/4] trace.pl: Fix request split mode
2018-04-23 9:52 [igt-dev] [PATCH i-g-t v3 0/4] trace.pl fixes Tvrtko Ursulin
` (2 preceding siblings ...)
2018-04-23 9:52 ` [igt-dev] [PATCH i-g-t 3/4] trace.pl: Fix incomplete request handling Tvrtko Ursulin
@ 2018-04-23 9:52 ` Tvrtko Ursulin
2018-04-23 14:46 ` [igt-dev] ✓ Fi.CI.BAT: success for trace.pl fixes (rev3) Patchwork
2018-04-23 18:20 ` [igt-dev] ✓ Fi.CI.IGT: " Patchwork
5 siblings, 0 replies; 9+ messages in thread
From: Tvrtko Ursulin @ 2018-04-23 9:52 UTC (permalink / raw)
To: igt-dev; +Cc: Intel-gfx, Tvrtko Ursulin
From: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Request split mode had several bugs, both in the original version and also
after the recent refactorings.
One big one was that it wasn't considering different submit ports as a
reason to split execution, and also that it was too time based instead of
looking at relevant timelines.
In this refactoring we address the former by using the engine timelines
introduced in the previous patch. Secondary port submissions are moved
to follow the preceding submission as a first step in the correction
process.
In the second step, we add context timelines and use then in a similar
fashion to separate start and end time of coalesced requests. For each
coalesced request we know its boundaries by looking at the engine
timeline (via global seqnos), and we know the previous request it should
only start after, by looking at the context timeline.
v2:
* Remove some dead code.
* Fix !port0 shifting logic.
Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
Cc: John Harrison <John.C.Harrison@intel.com>
---
scripts/trace.pl | 121 +++++++++++++++++++++++++++++++++++++++++++------------
1 file changed, 95 insertions(+), 26 deletions(-)
diff --git a/scripts/trace.pl b/scripts/trace.pl
index b48f43225fc1..88aa667df2d4 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -601,41 +601,110 @@ sub sortStart {
return $val;
}
-my @sorted_keys = sort sortStart keys %db;
-my $re_sort = 0;
+my $re_sort = 1;
+my @sorted_keys;
-die "Database changed size?!" unless scalar(@sorted_keys) == $key_count;
+sub maybe_sort_keys
+{
+ if ($re_sort) {
+ @sorted_keys = sort sortStart keys %db;
+ $re_sort = 0;
+ die "Database changed size?!" unless scalar(@sorted_keys) ==
+ $key_count;
+ }
+}
-foreach my $key (@sorted_keys) {
- my $ring = $db{$key}->{'ring'};
- my $end = $db{$key}->{'end'};
+maybe_sort_keys();
+
+my %ctx_timelines;
+
+sub sortContext {
+ my $as = $db{$a}->{'seqno'};
+ my $bs = $db{$b}->{'seqno'};
+ my $val;
+
+ $val = $as <=> $bs;
+
+ die if $val == 0;
+
+ return $val;
+}
+
+sub get_ctx_timeline {
+ my ($ctx, $ring, $key) = @_;
+ my @timeline;
- # correct duration of merged batches
- if ($correct_durations and exists $db{$key}->{'no-end'}) {
+ return $ctx_timelines{$key} if exists $ctx_timelines{$key};
+
+ @timeline = grep { $db{$_}->{'ring'} == $ring and
+ $db{$_}->{'ctx'} == $ctx } @sorted_keys;
+ # FIXME seqno restart
+ @timeline = sort sortContext @timeline;
+
+ $ctx_timelines{$key} = \@timeline;
+
+ return \@timeline;
+}
+
+# Split out merged batches if requested.
+if ($correct_durations) {
+ my @port1;
+ my @no_end;
+
+ # Shift !port0 requests start time to after the previous context on the
+ # same timeline has finished.
+ @port1 = grep { $db{$_}->{'port'} != 0 } @sorted_keys;
+ foreach my $key (@port1) {
+ my $timeline = get_engine_timeline($db{$key}->{'ring'});
+ my $i = List::Util::first { ${$timeline}[$_] eq $key } 0..$#{$timeline};
+ my $prev_key;
+ my $start;
+
+ while ($i > 0) {
+ my $prev;
+
+ $i = $i - 1;
+ $prev = ${$timeline}[$i];
+
+ next if exists $db{$prev}->{'no-end'};
+
+ $prev_key = $prev;
+ last;
+ }
+
+ $start = $db{$prev_key}->{'end'};
+ $db{$key}->{'start'} = $start;
+ die if $start > $db{$key}->{'end'};
+
+ $re_sort = 1;
+ }
+
+ maybe_sort_keys();
+
+ # Batch with no-end (no request_out) means it was submitted as part of
+ # colaesced context. This means it's start time should be set to the end
+ # time of a precedeing request on this timeline.
+ @no_end = grep { exists $db{$_}->{'no-end'} } @sorted_keys;
+ foreach my $key (@no_end) {
my $ctx = $db{$key}->{'ctx'};
- my $seqno = $db{$key}->{'seqno'};
- my $start = $db{$key}->{'start'};
- my $next_key;
- my $i = 1;
-
- do {
- $next_key = db_key($ring, $ctx, $seqno + $i);
- $i++;
- } until (exists $db{$next_key} or $i > $key_count); # ugly stop hack
-
- # 20us tolerance
- if (exists $db{$next_key} and $db{$next_key}->{'start'} < $start + 20) {
- my $notify = $db{$key}->{'notify'};
+ my $ring = $db{$key}->{'ring'};
+ my $tkey = $ctx . '/' . $ring;
+ my $timeline = get_ctx_timeline($ctx, $ring, $tkey);
+ my $i;
+
+ $i = List::Util::first { ${$timeline}[$_] eq $key } 0..$#{$timeline};
+
+ # Shift following request to start after the current one.
+ if ($i < $#{$timeline}) {
+ my $next_key = ${$timeline}[$i + 1];
+
+ $db{$next_key}->{'start'} = $db{$key}->{'notify'};
$re_sort = 1;
- $db{$next_key}->{'start'} = $notify;
- $db{$next_key}->{'start'} = $db{$next_key}->{'end'} if $db{$next_key}->{'start'} > $db{$next_key}->{'end'};
- die if $db{$next_key}->{'start'} > $db{$next_key}->{'end'};
}
- die if $start > $end;
}
}
-@sorted_keys = sort sortStart keys %db if $re_sort;
+maybe_sort_keys();
# GPU time accounting
my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
--
2.14.1
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev
^ permalink raw reply related [flat|nested] 9+ messages in thread* [igt-dev] ✓ Fi.CI.BAT: success for trace.pl fixes (rev3)
2018-04-23 9:52 [igt-dev] [PATCH i-g-t v3 0/4] trace.pl fixes Tvrtko Ursulin
` (3 preceding siblings ...)
2018-04-23 9:52 ` [igt-dev] [PATCH i-g-t 4/4] trace.pl: Fix request split mode Tvrtko Ursulin
@ 2018-04-23 14:46 ` Patchwork
2018-04-23 18:20 ` [igt-dev] ✓ Fi.CI.IGT: " Patchwork
5 siblings, 0 replies; 9+ messages in thread
From: Patchwork @ 2018-04-23 14:46 UTC (permalink / raw)
To: Tvrtko Ursulin; +Cc: igt-dev
== Series Details ==
Series: trace.pl fixes (rev3)
URL : https://patchwork.freedesktop.org/series/37330/
State : success
== Summary ==
= CI Bug Log - changes from CI_DRM_4078 -> IGTPW_1290 =
== Summary - SUCCESS ==
No regressions found.
External URL: https://patchwork.freedesktop.org/api/1.0/series/37330/revisions/3/mbox/
== Known issues ==
Here are the changes found in IGTPW_1290 that come from known issues:
=== IGT changes ===
==== Issues hit ====
igt@kms_pipe_crc_basic@nonblocking-crc-pipe-a-frame-sequence:
fi-elk-e7500: PASS -> INCOMPLETE (fdo#103989)
igt@kms_pipe_crc_basic@read-crc-pipe-b-frame-sequence:
fi-glk-j4005: PASS -> DMESG-WARN (fdo#106097) +2
igt@kms_pipe_crc_basic@suspend-read-crc-pipe-b:
fi-cnl-psr: PASS -> DMESG-WARN (fdo#104951) +1
==== Possible fixes ====
igt@kms_pipe_crc_basic@suspend-read-crc-pipe-c:
fi-ivb-3520m: DMESG-WARN (fdo#106084) -> PASS
fdo#103989 https://bugs.freedesktop.org/show_bug.cgi?id=103989
fdo#104951 https://bugs.freedesktop.org/show_bug.cgi?id=104951
fdo#106084 https://bugs.freedesktop.org/show_bug.cgi?id=106084
fdo#106097 https://bugs.freedesktop.org/show_bug.cgi?id=106097
== Participating hosts (36 -> 32) ==
Missing (4): fi-byt-j1900 fi-ctg-p8600 fi-ilk-m540 fi-skl-6700hq
== Build changes ==
* IGT: IGT_4444 -> IGTPW_1290
CI_DRM_4078: 9391010824b34ec58217f816ba5e314e7312191d @ git://anongit.freedesktop.org/gfx-ci/linux
IGTPW_1290: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_1290/
IGT_4444: dcc44347494231feabc588c2a76998cbc9afdf8c @ git://anongit.freedesktop.org/xorg/app/intel-gpu-tools
piglit_4444: a2f486679f467cd6e82578384f56d4aabaa8cf2e @ git://anongit.freedesktop.org/piglit
== Logs ==
For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_1290/issues.html
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev
^ permalink raw reply [flat|nested] 9+ messages in thread* [igt-dev] ✓ Fi.CI.IGT: success for trace.pl fixes (rev3)
2018-04-23 9:52 [igt-dev] [PATCH i-g-t v3 0/4] trace.pl fixes Tvrtko Ursulin
` (4 preceding siblings ...)
2018-04-23 14:46 ` [igt-dev] ✓ Fi.CI.BAT: success for trace.pl fixes (rev3) Patchwork
@ 2018-04-23 18:20 ` Patchwork
5 siblings, 0 replies; 9+ messages in thread
From: Patchwork @ 2018-04-23 18:20 UTC (permalink / raw)
To: Tvrtko Ursulin; +Cc: igt-dev
== Series Details ==
Series: trace.pl fixes (rev3)
URL : https://patchwork.freedesktop.org/series/37330/
State : success
== Summary ==
= CI Bug Log - changes from IGT_4444_full -> IGTPW_1290_full =
== Summary - WARNING ==
Minor unknown changes coming with IGTPW_1290_full need to be verified
manually.
If you think the reported changes have nothing to do with the changes
introduced in IGTPW_1290_full, please notify your bug team to allow them
to document this new failure mode, which will reduce false positives in CI.
External URL: https://patchwork.freedesktop.org/api/1.0/series/37330/revisions/3/mbox/
== Possible new issues ==
Here are the unknown changes that may have been introduced in IGTPW_1290_full:
=== IGT changes ===
==== Warnings ====
igt@gem_exec_schedule@deep-blt:
shard-kbl: PASS -> SKIP +1
igt@gem_mocs_settings@mocs-rc6-blt:
shard-kbl: SKIP -> PASS +1
== Known issues ==
Here are the changes found in IGTPW_1290_full that come from known issues:
=== IGT changes ===
==== Issues hit ====
igt@kms_cursor_crc@cursor-128x128-suspend:
shard-kbl: PASS -> INCOMPLETE (fdo#103665, fdo#106024)
igt@kms_flip@2x-flip-vs-expired-vblank-interruptible:
shard-hsw: PASS -> FAIL (fdo#102887)
igt@kms_flip@absolute-wf_vblank-interruptible:
shard-apl: PASS -> FAIL (fdo#106087)
igt@kms_flip@plain-flip-ts-check-interruptible:
shard-hsw: PASS -> FAIL (fdo#103928)
igt@kms_plane_multiple@atomic-pipe-a-tiling-x:
shard-snb: PASS -> FAIL (fdo#103166)
==== Possible fixes ====
igt@kms_flip@2x-dpms-vs-vblank-race:
shard-hsw: FAIL (fdo#103060) -> PASS
igt@kms_flip@2x-plain-flip-ts-check-interruptible:
shard-hsw: FAIL (fdo#100368) -> PASS
fdo#100368 https://bugs.freedesktop.org/show_bug.cgi?id=100368
fdo#102887 https://bugs.freedesktop.org/show_bug.cgi?id=102887
fdo#103060 https://bugs.freedesktop.org/show_bug.cgi?id=103060
fdo#103166 https://bugs.freedesktop.org/show_bug.cgi?id=103166
fdo#103665 https://bugs.freedesktop.org/show_bug.cgi?id=103665
fdo#103928 https://bugs.freedesktop.org/show_bug.cgi?id=103928
fdo#106024 https://bugs.freedesktop.org/show_bug.cgi?id=106024
fdo#106087 https://bugs.freedesktop.org/show_bug.cgi?id=106087
== Participating hosts (5 -> 4) ==
Missing (1): shard-glkb
== Build changes ==
* IGT: IGT_4444 -> IGTPW_1290
* Linux: CI_DRM_4076 -> CI_DRM_4078
CI_DRM_4076: 01b171f6df7b2b55b3c1b851d40741179fa2a722 @ git://anongit.freedesktop.org/gfx-ci/linux
CI_DRM_4078: 9391010824b34ec58217f816ba5e314e7312191d @ git://anongit.freedesktop.org/gfx-ci/linux
IGTPW_1290: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_1290/
IGT_4444: dcc44347494231feabc588c2a76998cbc9afdf8c @ git://anongit.freedesktop.org/xorg/app/intel-gpu-tools
piglit_4444: a2f486679f467cd6e82578384f56d4aabaa8cf2e @ git://anongit.freedesktop.org/piglit
== Logs ==
For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_1290/shards.html
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev
^ permalink raw reply [flat|nested] 9+ messages in thread