[PATCH i-g-t 0/4] scripts/trace.pl: Re-order calculations and fixups

[PATCH i-g-t 0/4] scripts/trace.pl: Re-order calculations and fixups

[John.C.Harrison]

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

The trace.pl script calculates a bunch of statistics. It also
re-generates some timestamp values to correct issues with the log
being processed. These operations were all mixed up together thus some
were done multiple times (with different results each time). Whereas
some stats were not being re-calculated after the underlying data had
changed and thus were not actually correct at the end. Also, the
ordering of some operations was non-deterministic due to being based
on internal Perl hash ordering.

These patches rationalise all of this processing to ensure that it all
happens in the correct order and in a consistent manner.

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

 scripts/trace.pl | 118 ++++++++++++++++++++++++++++++++++---------------------
 1 file changed, 73 insertions(+), 45 deletions(-)

-- 
2.15.1

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

[PATCH i-g-t 1/4] scripts/trace.pl: More hash key optimisations

[John.C.Harrison]

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.

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index cb93900d..7b8a920e 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -508,7 +508,9 @@ foreach my $key (keys %db) {
 }
 
 # Fix up incompletes
-foreach my $key (keys %db) {
+my @keys = keys(%db);
+my $keyCount = scalar(@keys);
+foreach my $key (@keys) {
 	next unless exists $db{$key}->{'incomplete'};
 
 	# End the incomplete batch at the time next one starts
@@ -522,7 +524,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 > $keyCount);  # ugly stop hack
 
 	if (exists $db{$next_key}) {
 		$db{$key}->{'notify'} = $db{$next_key}->{'end'};
@@ -540,6 +542,7 @@ 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) == $keyCount;
 
 foreach my $key (@sorted_keys) {
 	my $ring = $db{$key}->{'ring'};
@@ -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 > $keyCount);  # ugly stop hack
 
 		# 20us tolerance
 		if (exists $db{$next_key} and $db{$next_key}->{'start'} < $start + 20) {
-- 
2.15.1

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

[PATCH i-g-t 2/4] scripts/trace.pl: Sort order

[John.C.Harrison]

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.

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

diff --git a/scripts/trace.pl b/scripts/trace.pl
index 7b8a920e..cf841b7e 100755
--- a/scripts/trace.pl
+++ b/scripts/trace.pl
@@ -540,7 +540,25 @@ 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'};
+
+	return $as <=> $bs if($as ne $bs);
+
+	return $a cmp $b;
+}
+
+sub sortQueue {
+	my $as = $db{$a}->{'queue'};
+	my $bs = $db{$b}->{'queue'};
+
+	return $as <=> $bs if($as ne $bs);
+
+	return $a cmp $b;
+}
+
+my @sorted_keys = sort sortStart keys %db;
 my $re_sort = 0;
 die "Database changed size?!" unless scalar(@sorted_keys) == $keyCount;
 
@@ -589,9 +607,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 +849,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.15.1

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

[PATCH i-g-t 3/4] scripts/trace.pl: Calculate stats only after all munging

[John.C.Harrison]

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.

Signed-off-by: John Harrison <John.C.Harrison@intel.com>
Cc: 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 cf841b7e..c5d822aa 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'};
 		}
 	}
 }
@@ -529,8 +521,6 @@ foreach my $key (@keys) {
 	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'};
 	}
 }
 
@@ -565,19 +555,14 @@ die "Database changed size?!" unless scalar(@sorted_keys) == $keyCount;
 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;
 
-	$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 $next_key;
@@ -591,24 +576,41 @@ foreach my $key (@sorted_keys) {
 		# 20us tolerance
 		if (exists $db{$next_key} and $db{$next_key}->{'start'} < $start + 20) {
 			$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.15.1

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

[PATCH i-g-t 4/4] scripts/trace.pl: Simplify 'end' & 'notify' generation

[John.C.Harrison]

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.

Signed-off-by: John Harrison <John.C.Harrison@intel.com>
Cc: 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 c5d822aa..fbf4b92e 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;
 		}
 	}
 }
@@ -511,6 +510,7 @@ foreach my $key (@keys) {
 	my $seqno = $db{$key}->{'seqno'};
 	my $next_key;
 	my $i = 1;
+	my $end;
 
 	do {
 		$next_key = db_key($ring, $ctx, $seqno + $i);
@@ -519,9 +519,14 @@ foreach my $key (@keys) {
 		 or $i > $keyCount);  # 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.15.1

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

✓ Fi.CI.BAT: success for scripts/trace.pl: Re-order calculations and fixups

[Patchwork]

== Series Details ==

Series: scripts/trace.pl: Re-order calculations and fixups
URL   : https://patchwork.freedesktop.org/series/36829/
State : success

== Summary ==

IGT patchset tested on top of latest successful build
94bd67c5d6184c435c2fed0bfb39d75b3138b7a8 tools/intel_vbt_decode: update vbt defs from kernel

with latest DRM-Tip kernel build CI_DRM_3663
85f8773e7d77 drm-tip: 2018y-01m-19d-21h-19m-11s UTC integration manifest

No testlist changes.

Test debugfs_test:
        Subgroup read_all_entries:
                pass       -> DMESG-WARN (fi-elk-e7500) fdo#103989 +1
                incomplete -> PASS       (fi-snb-2520m) fdo#103713 +1

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

fi-bdw-5557u     total:288  pass:267  dwarn:0   dfail:0   fail:0   skip:21  time:432s
fi-bdw-gvtdvm    total:288  pass:264  dwarn:0   dfail:0   fail:0   skip:24  time:435s
fi-blb-e6850     total:288  pass:223  dwarn:1   dfail:0   fail:0   skip:64  time:385s
fi-bsw-n3050     total:288  pass:242  dwarn:0   dfail:0   fail:0   skip:46  time:519s
fi-bwr-2160      total:288  pass:183  dwarn:0   dfail:0   fail:0   skip:105 time:294s
fi-bxt-dsi       total:288  pass:258  dwarn:0   dfail:0   fail:0   skip:30  time:500s
fi-bxt-j4205     total:288  pass:259  dwarn:0   dfail:0   fail:0   skip:29  time:501s
fi-byt-j1900     total:288  pass:253  dwarn:0   dfail:0   fail:0   skip:35  time:495s
fi-byt-n2820     total:288  pass:249  dwarn:0   dfail:0   fail:0   skip:39  time:484s
fi-elk-e7500     total:224  pass:168  dwarn:10  dfail:0   fail:0   skip:45 
fi-gdg-551       total:288  pass:179  dwarn:0   dfail:0   fail:1   skip:108 time:302s
fi-glk-1         total:288  pass:260  dwarn:0   dfail:0   fail:0   skip:28  time:531s
fi-hsw-4770      total:288  pass:261  dwarn:0   dfail:0   fail:0   skip:27  time:396s
fi-hsw-4770r     total:288  pass:261  dwarn:0   dfail:0   fail:0   skip:27  time:410s
fi-ilk-650       total:288  pass:228  dwarn:0   dfail:0   fail:0   skip:60  time:425s
fi-ivb-3520m     total:288  pass:259  dwarn:0   dfail:0   fail:0   skip:29  time:472s
fi-ivb-3770      total:288  pass:255  dwarn:0   dfail:0   fail:0   skip:33  time:421s
fi-kbl-7500u     total:288  pass:263  dwarn:1   dfail:0   fail:0   skip:24  time:464s
fi-kbl-7560u     total:288  pass:269  dwarn:0   dfail:0   fail:0   skip:19  time:504s
fi-kbl-7567u     total:288  pass:268  dwarn:0   dfail:0   fail:0   skip:20  time:459s
fi-kbl-r         total:288  pass:261  dwarn:0   dfail:0   fail:0   skip:27  time:508s
fi-pnv-d510      total:288  pass:222  dwarn:1   dfail:0   fail:0   skip:65  time:629s
fi-skl-6260u     total:288  pass:268  dwarn:0   dfail:0   fail:0   skip:20  time:446s
fi-skl-6600u     total:288  pass:261  dwarn:0   dfail:0   fail:0   skip:27  time:516s
fi-skl-6700hq    total:288  pass:262  dwarn:0   dfail:0   fail:0   skip:26  time:537s
fi-skl-6700k2    total:288  pass:264  dwarn:0   dfail:0   fail:0   skip:24  time:493s
fi-skl-6770hq    total:288  pass:268  dwarn:0   dfail:0   fail:0   skip:20  time:493s
fi-skl-gvtdvm    total:288  pass:265  dwarn:0   dfail:0   fail:0   skip:23  time:441s
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:402s
Blacklisted hosts:
fi-cfl-s2        total:288  pass:256  dwarn:0   dfail:0   fail:3   skip:26  time:574s
fi-skl-guc       total:288  pass:260  dwarn:0   dfail:0   fail:0   skip:28  time:428s

== Logs ==

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

✗ Fi.CI.IGT: failure for scripts/trace.pl: Re-order calculations and fixups

[Patchwork]

== Series Details ==

Series: scripts/trace.pl: Re-order calculations and fixups
URL   : https://patchwork.freedesktop.org/series/36829/
State : failure

== Summary ==

Test perf:
        Subgroup oa-exponents:
                pass       -> FAIL       (shard-apl) fdo#102254
Test kms_cursor_legacy:
        Subgroup flip-vs-cursor-atomic:
                pass       -> FAIL       (shard-apl) fdo#102670
Test kms_flip:
        Subgroup vblank-vs-dpms-suspend-interruptible:
                fail       -> PASS       (shard-hsw) fdo#103540 +1
        Subgroup vblank-vs-suspend:
                skip       -> PASS       (shard-snb) fdo#102365
Test gem_exec_schedule:
        Subgroup wide-vebox:
                pass       -> FAIL       (shard-apl) fdo#102848
Test kms_frontbuffer_tracking:
        Subgroup fbc-1p-offscren-pri-shrfb-draw-render:
                pass       -> FAIL       (shard-snb) fdo#101623
Test gem_tiled_swapping:
        Subgroup non-threaded:
                pass       -> DMESG-WARN (shard-hsw) fdo#104218
Test kms_ccs:
        Subgroup pipe-c-missing-ccs-buffer:
                skip       -> INCOMPLETE (shard-hsw)

fdo#102254 https://bugs.freedesktop.org/show_bug.cgi?id=102254
fdo#102670 https://bugs.freedesktop.org/show_bug.cgi?id=102670
fdo#103540 https://bugs.freedesktop.org/show_bug.cgi?id=103540
fdo#102365 https://bugs.freedesktop.org/show_bug.cgi?id=102365
fdo#102848 https://bugs.freedesktop.org/show_bug.cgi?id=102848
fdo#101623 https://bugs.freedesktop.org/show_bug.cgi?id=101623
fdo#104218 https://bugs.freedesktop.org/show_bug.cgi?id=104218

shard-apl        total:2780 pass:1714 dwarn:1   dfail:0   fail:25  skip:1040 time:14767s
shard-hsw        total:2707 pass:1687 dwarn:2   dfail:0   fail:11  skip:1005 time:15102s
shard-snb        total:2780 pass:1316 dwarn:1   dfail:0   fail:13  skip:1450 time:8004s
Blacklisted hosts:
shard-kbl        total:2770 pass:1830 dwarn:1   dfail:0   fail:24  skip:914 time:10678s

== Logs ==

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

Re: [PATCH i-g-t 1/4] scripts/trace.pl: More hash key optimisations

[Tvrtko Ursulin]

On 20/01/2018 00:24, John.C.Harrison@Intel.com wrote:
> From: John Harrison <John.C.Harrison@Intel.com>
> 
> Cache the key count value rather than querying the hash every time.

This actually makes a difference? Just curious, I would have assumed 
Perl would know the size of it's arrays but maybe the implementation is 
stupid...

Btw I was using Devel::NTYProf in HTML output mode to profile my 
changes. It is quite easy to use and provided all the info I needed.

> Also assert that the database does not magically change size after the
> fixups.
> 
> Signed-off-by: John Harrison <John.C.Harrison@intel.com>
> Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> ---
>   scripts/trace.pl | 9 ++++++---
>   1 file changed, 6 insertions(+), 3 deletions(-)
> 
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index cb93900d..7b8a920e 100755
> --- a/scripts/trace.pl
> +++ b/scripts/trace.pl
> @@ -508,7 +508,9 @@ foreach my $key (keys %db) {
>   }
>   
>   # Fix up incompletes
> -foreach my $key (keys %db) {
> +my @keys = keys(%db);

This array is unused except for the query below so I'd suggest to not 
have it.

> +my $keyCount = scalar(@keys);

About came case.. I won't complain too the max, since I'm happy you are 
finding the tool useful and improving it, but it would be good to stay 
within the same style of variable naming or we'll have a mish-mash of 
styles which won't help readability.

Regards,

Tvrtko

> +foreach my $key (@keys) {
>   	next unless exists $db{$key}->{'incomplete'};
>   
>   	# End the incomplete batch at the time next one starts
> @@ -522,7 +524,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 > $keyCount);  # ugly stop hack
>   
>   	if (exists $db{$next_key}) {
>   		$db{$key}->{'notify'} = $db{$next_key}->{'end'};
> @@ -540,6 +542,7 @@ 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) == $keyCount;
>   
>   foreach my $key (@sorted_keys) {
>   	my $ring = $db{$key}->{'ring'};
> @@ -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 > $keyCount);  # ugly stop hack
>   
>   		# 20us tolerance
>   		if (exists $db{$next_key} and $db{$next_key}->{'start'} < $start + 20) {
> 
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH i-g-t 2/4] scripts/trace.pl: Sort order

[Tvrtko Ursulin]

On 20/01/2018 00:24, John.C.Harrison@Intel.com wrote:
> 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.

Makes sense. I guess I never expected ns resolution time stamps to be 
different.

> As the comparison test is now more than a single equation, moved it
> out into a separate sort function.
> 
> Signed-off-by: John Harrison <John.C.Harrison@intel.com>
> Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
> ---
>   scripts/trace.pl | 26 ++++++++++++++++++++++----
>   1 file changed, 22 insertions(+), 4 deletions(-)
> 
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index 7b8a920e..cf841b7e 100755
> --- a/scripts/trace.pl
> +++ b/scripts/trace.pl
> @@ -540,7 +540,25 @@ 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'};
> +
> +	return $as <=> $bs if($as ne $bs);

In the spirit of the last round of optimising work, I would check if 
this is the most optimal way to write this. Perhaps it would be better 
with a single comparison on this line. And not mixing string and 
numerical context? Like:

	my $val = $as <=> $bs;

	$val = $a cmp $b if $val == 0;

	return $val;

?

> +
> +	return $a cmp $b;
> +}
> +
> +sub sortQueue {
> +	my $as = $db{$a}->{'queue'};
> +	my $bs = $db{$b}->{'queue'};
> +
> +	return $as <=> $bs if($as ne $bs);
> +
> +	return $a cmp $b;
> +}
> +
> +my @sorted_keys = sort sortStart keys %db;
>   my $re_sort = 0;
>   die "Database changed size?!" unless scalar(@sorted_keys) == $keyCount;
>   
> @@ -589,9 +607,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 +849,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'};
> 

Rest looks OK.

Regards,

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

Re: [PATCH i-g-t 3/4] scripts/trace.pl: Calculate stats only after all munging

[Tvrtko Ursulin]

On 20/01/2018 00:24, John.C.Harrison@Intel.com wrote:
> 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.
> 
> Signed-off-by: John Harrison <John.C.Harrison@intel.com>
> Cc: 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 cf841b7e..c5d822aa 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};

You only use the submit key to look up things two times, so you could 
use the %submit hash directly to save some lookups, but on the other 
hand maybe you were going for nicer split between data structures over 
performance.

When I look at it again, I was using the same approach for 'queue' when 
%queue was also available so never mind.. maybe an optimisation 
opportunity with both for later, if would be worth it.

>   		$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'};
>   		}
>   	}
>   }
> @@ -529,8 +521,6 @@ foreach my $key (@keys) {
>   	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'};
>   	}
>   }
>   
> @@ -565,19 +555,14 @@ die "Database changed size?!" unless scalar(@sorted_keys) == $keyCount;
>   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'};

Why did you move/put these two here since they are not used outside the 
$correct_durations block? I'd avoid hash queries if not needed.

>   
>   	$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 $next_key;
> @@ -591,24 +576,41 @@ foreach my $key (@sorted_keys) {
>   		# 20us tolerance
>   		if (exists $db{$next_key} and $db{$next_key}->{'start'} < $start + 20) {
>   			$re_sort = 1;
> -			$db{$next_key}->{'start'} = $start + $db{$key}->{'duration'};
> +			$db{$next_key}->{'start'} = $notify;

Makes sense, mine was silly!

>   			$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};
> 

A great improvement! I didn't spot that you've changed anything which 
would break the flow.

I'd move those two locals in the if block, but otherwise:

Reviewed-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>

Regards,

Tvrtko

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

Re: [PATCH i-g-t 4/4] scripts/trace.pl: Simplify 'end' & 'notify' generation

[Tvrtko Ursulin]

On 20/01/2018 00:24, John.C.Harrison@Intel.com wrote:
> 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.
> 
> Signed-off-by: John Harrison <John.C.Harrison@intel.com>
> Cc: 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 c5d822aa..fbf4b92e 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;
>   		}
>   	}
>   }
> @@ -511,6 +510,7 @@ foreach my $key (@keys) {
>   	my $seqno = $db{$key}->{'seqno'};
>   	my $next_key;
>   	my $i = 1;
> +	my $end;
>   
>   	do {
>   		$next_key = db_key($ring, $ctx, $seqno + $i);
> @@ -519,9 +519,14 @@ foreach my $key (@keys) {
>   		 or $i > $keyCount);  # 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
> 

Looks cleaner and still correct. Just please explain in the commit that 
the description applies only for requests marked as incomplete. AFICS 
those were the only ones it was setting the end and notify times 
potentially two times.

Regards,

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

Re: [PATCH i-g-t 1/4] scripts/trace.pl: More hash key optimisations

[John Harrison]

On 1/22/2018 2:14 AM, Tvrtko Ursulin wrote:
>
> On 20/01/2018 00:24, John.C.Harrison@Intel.com wrote:
>> From: John Harrison <John.C.Harrison@Intel.com>
>>
>> Cache the key count value rather than querying the hash every time.
>
> This actually makes a difference? Just curious, I would have assumed 
> Perl would know the size of it's arrays but maybe the implementation 
> is stupid...

Actually, I'm not sure it does anymore. I thought it did but I later 
decided that the change was actually just run to run noise. However, I 
already had the patch and I think it makes the code at least look 
simpler. IMHO, '$key_count' is easier to read than 'scalar(keys(%db))' 
and it is obviously trivial rather than relying on the compiler to be smart.

>
> Btw I was using Devel::NTYProf in HTML output mode to profile my 
> changes. It is quite easy to use and provided all the info I needed.
>
>> Also assert that the database does not magically change size after the
>> fixups.
>>
>> Signed-off-by: John Harrison <John.C.Harrison@intel.com>
>> Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>> ---
>>   scripts/trace.pl | 9 ++++++---
>>   1 file changed, 6 insertions(+), 3 deletions(-)
>>
>> diff --git a/scripts/trace.pl b/scripts/trace.pl
>> index cb93900d..7b8a920e 100755
>> --- a/scripts/trace.pl
>> +++ b/scripts/trace.pl
>> @@ -508,7 +508,9 @@ foreach my $key (keys %db) {
>>   }
>>     # Fix up incompletes
>> -foreach my $key (keys %db) {
>> +my @keys = keys(%db);
>
> This array is unused except for the query below so I'd suggest to not 
> have it.
>
>> +my $keyCount = scalar(@keys);
>
> About came case.. I won't complain too the max, since I'm happy you 
> are finding the tool useful and improving it, but it would be good to 
> stay within the same style of variable naming or we'll have a 
> mish-mash of styles which won't help readability.

Oops, I missed that. Habit and too many different style guides in too 
many different projects! I'll change it to $key_count instead.


>
> Regards,
>
> Tvrtko
>
>> +foreach my $key (@keys) {
>>       next unless exists $db{$key}->{'incomplete'};
>>         # End the incomplete batch at the time next one starts
>> @@ -522,7 +524,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 > $keyCount);  # ugly stop hack
>>         if (exists $db{$next_key}) {
>>           $db{$key}->{'notify'} = $db{$next_key}->{'end'};
>> @@ -540,6 +542,7 @@ 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) == $keyCount;
>>     foreach my $key (@sorted_keys) {
>>       my $ring = $db{$key}->{'ring'};
>> @@ -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 > $keyCount); # ugly 
>> stop hack
>>             # 20us tolerance
>>           if (exists $db{$next_key} and $db{$next_key}->{'start'} < 
>> $start + 20) {
>>

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

Re: [PATCH i-g-t 2/4] scripts/trace.pl: Sort order

[John Harrison]

On 1/22/2018 2:19 AM, Tvrtko Ursulin wrote:
>
> On 20/01/2018 00:24, John.C.Harrison@Intel.com wrote:
>> 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.
>
> Makes sense. I guess I never expected ns resolution time stamps to be 
> different.

Computers are fast - ns is slow!

>
>> As the comparison test is now more than a single equation, moved it
>> out into a separate sort function.
>>
>> Signed-off-by: John Harrison <John.C.Harrison@intel.com>
>> Cc: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>> ---
>>   scripts/trace.pl | 26 ++++++++++++++++++++++----
>>   1 file changed, 22 insertions(+), 4 deletions(-)
>>
>> diff --git a/scripts/trace.pl b/scripts/trace.pl
>> index 7b8a920e..cf841b7e 100755
>> --- a/scripts/trace.pl
>> +++ b/scripts/trace.pl
>> @@ -540,7 +540,25 @@ 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'};
>> +
>> +    return $as <=> $bs if($as ne $bs);
>
> In the spirit of the last round of optimising work, I would check if 
> this is the most optimal way to write this. Perhaps it would be better 
> with a single comparison on this line. And not mixing string and 
> numerical context? Like:
>
>     my $val = $as <=> $bs;
>
>     $val = $a cmp $b if $val == 0;
>
>     return $val;
>
> ?
Six of one, half a dozen of another. Again, I would assume the compiler 
would be smart enough to make both versions equal but I'm happy to go 
with your version if you feel it is better.

>
>> +
>> +    return $a cmp $b;
>> +}
>> +
>> +sub sortQueue {
>> +    my $as = $db{$a}->{'queue'};
>> +    my $bs = $db{$b}->{'queue'};
>> +
>> +    return $as <=> $bs if($as ne $bs);
>> +
>> +    return $a cmp $b;
>> +}
>> +
>> +my @sorted_keys = sort sortStart keys %db;
>>   my $re_sort = 0;
>>   die "Database changed size?!" unless scalar(@sorted_keys) == 
>> $keyCount;
>>   @@ -589,9 +607,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 +849,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'};
>>
>
> Rest looks OK.
>
> Regards,
>
> Tvrtko

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

Re: [PATCH i-g-t 3/4] scripts/trace.pl: Calculate stats only after all munging

[John Harrison]

On 1/22/2018 2:54 AM, Tvrtko Ursulin wrote:
>
> On 20/01/2018 00:24, John.C.Harrison@Intel.com wrote:
>> 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.
>>
>> Signed-off-by: John Harrison <John.C.Harrison@intel.com>
>> Cc: 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 cf841b7e..c5d822aa 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};
>
> You only use the submit key to look up things two times, so you could 
> use the %submit hash directly to save some lookups, but on the other 
> hand maybe you were going for nicer split between data structures over 
> performance.
>
> When I look at it again, I was using the same approach for 'queue' 
> when %queue was also available so never mind.. maybe an optimisation 
> opportunity with both for later, if would be worth it.
Yeah, I wasn't 100% certain the queue/submit things were safe to use 
later given that you weren't. However, I think it definitely makes the 
code easier to maintain if %db is assumed to be the one true source of 
all information. Once that is constructed, all else can be forgotten 
about and all subsequent processing only needs to operate on that one 
data structure.


>
>>           $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'};
>>           }
>>       }
>>   }
>> @@ -529,8 +521,6 @@ foreach my $key (@keys) {
>>       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'};
>>       }
>>   }
>>   @@ -565,19 +555,14 @@ die "Database changed size?!" unless 
>> scalar(@sorted_keys) == $keyCount;
>>   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'};
>
> Why did you move/put these two here since they are not used outside 
> the $correct_durations block? I'd avoid hash queries if not needed.

The code had mutated a lot before arriving at this point, yer honour. It 
all made sense at one point in time!

>
>>         $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 $next_key;
>> @@ -591,24 +576,41 @@ foreach my $key (@sorted_keys) {
>>           # 20us tolerance
>>           if (exists $db{$next_key} and $db{$next_key}->{'start'} < 
>> $start + 20) {
>>               $re_sort = 1;
>> -            $db{$next_key}->{'start'} = $start + 
>> $db{$key}->{'duration'};
>> +            $db{$next_key}->{'start'} = $notify;
>
> Makes sense, mine was silly!
>
>>               $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};
>>
>
> A great improvement! I didn't spot that you've changed anything which 
> would break the flow.
>
> I'd move those two locals in the if block, but otherwise:
>
> Reviewed-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>
> Regards,
>
> Tvrtko
>

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