[Intel-gfx] [PATCH i-g-t] scripts/trace.pl: Update for preempt-to-busy, heartbeats and timeslicing
Ye, Tony
tony.ye at intel.com
Fri Jan 17 20:58:08 UTC 2020
Failed on parsing the trace log:
Died at ./trace.pl line 296.
Raw data attached.
Regards,
Tony
On 1/17/2020 10:49 AM, Tvrtko Ursulin wrote:
> From: Tvrtko Ursulin <tvrtko.ursulin at intel.com>
>
> ...
>
> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin at intel.com>
> Cc: Tony Ye <tony.ye at intel.com>
> ---
> Tony could you please check if this works for you and even send me some
> raw trace files you might have so I see how it looks?
>
> P.S.
> I don't yet guarantee the results are 100% reliable and truthful. Or that
> it won't crash.
> ---
> scripts/trace.pl | 283 +++++++++++++++++++++++++----------------------
> 1 file changed, 151 insertions(+), 132 deletions(-)
>
> diff --git a/scripts/trace.pl b/scripts/trace.pl
> index 77587f24197a..8cad7e6ef65b 100755
> --- a/scripts/trace.pl
> +++ b/scripts/trace.pl
> @@ -34,11 +34,10 @@ my $cid = 0;
> my %queues;
> my @freqs;
>
> -use constant VENG => '255:254';
> +use constant VENG => '65534:65534';
>
> my $max_requests = 1000;
> my $width_us = 32000;
> -my $correct_durations = 0;
> my %ignore_ring;
> my %skip_box;
> my $html = 0;
> @@ -224,18 +223,6 @@ sub arg_zoom_width
> return @_;
> }
>
> -sub arg_split_requests
> -{
> - return unless scalar(@_);
> -
> - if ($_[0] eq '--split-requests' or $_[0] eq '-s') {
> - shift @_;
> - $correct_durations = 1;
> - }
> -
> - return @_;
> -}
> -
> sub arg_ignore_ring
> {
> my $val;
> @@ -299,7 +286,6 @@ while (@args) {
> @args = arg_trace(@args);
> @args = arg_max_requests(@args);
> @args = arg_zoom_width(@args);
> - @args = arg_split_requests(@args);
> @args = arg_ignore_ring(@args);
> @args = arg_skip_box(@args);
> @args = arg_colour_contexts(@args);
> @@ -340,7 +326,79 @@ sub is_veng
> {
> my ($class, $instance) = split ':', shift;
>
> - return $instance eq '254';
> + return 1 if $instance eq '254' or $instance eq '65534';
> +}
> +
> +my (%port_keys, %port_times);
> +
> +sub port_in
> +{
> + my ($ring, $port, $key, $time) = @_;
> + my ($port_key, $port_time);
> + my @slices;
> +
> + $db{$key}->{'slices'} = \@slices
> + unless exists $db{$key}->{'slices'};
> +
> + $db{$key}->{'in'}++;
> +
> + unless (exists $port_keys{$ring}) {
> + my (@keys, @times);
> +
> + $port_keys{$ring} = \@keys;
> + $port_times{$ring} = \@times;
> + }
> +
> + $port_key = $port_keys{$ring};
> + $port_time = $port_times{$ring};
> +
> + unless (defined $port_key->[$port] and $port_key->[$port] eq $key) {
> + $port_key->[$port] = $key;
> + $port_time->[$port] = $time;
> + }
> +}
> +
> +sub port_out
> +{
> + my ($ring, $key, $time) = @_;
> + my ($port_key, $port_time);
> + my $port;
> +
> + die unless $db{$key}->{'in'};
> + $db{$key}->{'in'}--;
> +
> + $port_key = $port_keys{$ring};
> + $port_time = $port_times{$ring};
> +
> + for (my $i = 0; $i < scalar(@{$port_key}); $i++) {
> + next unless defined $port_key->[$i];
> +
> + if ($port_key->[$i] eq $key) {
> + $port = $i;
> + last;
> + }
> + }
> +
> + return unless defined $port;
> +
> + if ($port == 0) {
> + my $s = $db{$key}->{'slices'};
> + my $next;
> +
> + push @{$s}, [$port_time->[$port], $time];
> +
> + $next = $port + 1;
> + if (defined $port_key->[$next]) {
> + $port_time->[$next] = $time;
> + shift @{$port_key};
> + shift @{$port_time};
> + }
> + }
> +
> + if ($db{$key}->{'in'} == 0) {
> + $port_key->[$port] = undef;
> + $port_time->[$port] = undef;
> + }
> }
>
> # Main input loop - parse lines and build the internal representation of the
> @@ -368,7 +426,6 @@ while (<>) {
>
> next unless $f =~ m/=/;
> ($k, $v) = ($`, $');
> - $k = 'global' if $k eq 'global_seqno';
> chop $v if substr($v, -1, 1) eq ',';
> $tp{$k} = $v;
>
> @@ -433,76 +490,89 @@ while (<>) {
> }
> } elsif ($tp_name eq 'i915:i915_request_submit:') {
> die if exists $submit{$key};
> - die unless exists $queue{$key};
> + unless (exists $queue{$key}) { # i915 internal
> + $queue{$key} = $time;
> + $ctxdb{$orig_ctx} = 1;
> + }
> die if $ring eq VENG and not exists $queues{$ctx};
>
> $submit{$key} = $time;
> } elsif ($tp_name eq 'i915:i915_request_in:') {
> + my $port = $tp{'port'};
> my ($q, $s);
> my %req;
>
> - # preemption
> - delete $db{$key} if exists $db{$key};
> -
> unless (exists $queue{$key}) {
> # Virtual engine
> my $vkey = db_key(VENG, $ctx, $seqno);
> my %req;
>
> die unless exists $queues{$ctx};
> - die unless exists $queue{$vkey};
> die unless exists $submit{$vkey};
>
> - # Create separate request record on the queue timeline
> $q = $queue{$vkey};
> $s = $submit{$vkey};
> - $req{'queue'} = $q;
> - $req{'submit'} = $s;
> +
> + unless (exists $vdb{$vkey}) {
> + # Create separate request record on the queue
> + # timeline.
> + $req{'queue'} = $q;
> + $req{'submit'} = $s;
> + $req{'start'} = $time;
> + $req{'end'} = $time;
> + $req{'ring'} = VENG;
> + $req{'phys-engine'} = $ring;
> + $req{'seqno'} = $seqno;
> + $req{'ctx'} = $ctx;
> + $req{'name'} = $ctx . '/' . $seqno;
> + $req{'port'} = $port;
> +
> + $vdb{$vkey} = \%req;
> + }
> + } else {
> + $q = $queue{$key};
> + $s = $submit{$key};
> + }
> +
> + unless (exists $db{$key}) {
> $req{'start'} = $time;
> - $req{'end'} = $time;
> - $req{'ring'} = VENG;
> + $req{'ring'} = $ring;
> $req{'seqno'} = $seqno;
> $req{'ctx'} = $ctx;
> + $ctxtimelines{$ctx . '/' . $ring} = 1;
> $req{'name'} = $ctx . '/' . $seqno;
> - $req{'global'} = $tp{'global'};
> - $req{'port'} = $tp{'port'};
> + $req{'port'} = $port;
> + $req{'queue'} = $q;
> + $req{'submit'} = $s;
> + $req{'virtual'} = 1 if exists $queues{$ctx};
> + $rings{$ring} = $gid++ unless exists $rings{$ring};
> + $ringmap{$rings{$ring}} = $ring;
> + $db{$key} = \%req;
>
> - $vdb{$vkey} = \%req;
> - } else {
> - $q = $queue{$key};
> - $s = $submit{$key};
> }
>
> - $req{'start'} = $time;
> - $req{'ring'} = $ring;
> - $req{'seqno'} = $seqno;
> - $req{'ctx'} = $ctx;
> - $ctxtimelines{$ctx . '/' . $ring} = 1;
> - $req{'name'} = $ctx . '/' . $seqno;
> - $req{'global'} = $tp{'global'};
> - $req{'port'} = $tp{'port'};
> - $req{'queue'} = $q;
> - $req{'submit'} = $s;
> - $req{'virtual'} = 1 if exists $queues{$ctx};
> - $rings{$ring} = $gid++ unless exists $rings{$ring};
> - $ringmap{$rings{$ring}} = $ring;
> - $db{$key} = \%req;
> + port_in($ring, $port, $key, $time);
> } elsif ($tp_name eq 'i915:i915_request_out:') {
> - if ($tp{'completed?'}) {
> - my $nkey;
> + my ($nkey, $completed, $prev_in);
>
> - die unless exists $db{$key};
> - die unless exists $db{$key}->{'start'};
> - die if exists $db{$key}->{'end'};
> -
> - $nkey = notify_key($ctx, $seqno);
> + if ($ring eq VENG and not exists $db{$key}) {
> + my $vkey = db_key(VENG, $ctx, $seqno);
>
> - $db{$key}->{'end'} = $time;
> - $db{$key}->{'notify'} = $notify{$nkey}
> - if exists $notify{$nkey};
> - } else {
> - delete $db{$key};
> + $ring = $vdb{$vkey}->{'phys-engine'};
> + $key = db_key($ring, $ctx, $seqno);
> }
> +
> + die unless exists $db{$key};
> + die unless exists $db{$key}->{'start'};
> +
> + $nkey = notify_key($ctx, $seqno);
> +
> + port_out($ring, $key, $time);
> +
> + $db{$key}->{'notify'} = $notify{$nkey}
> + if exists $notify{$nkey};
> + $db{$key}->{'end'} = $time;
> + $db{$key}->{'completed'} = $tp{'completed?'};
> } elsif ($tp_name eq 'dma_fence:dma_fence_signaled:') {
> my $nkey;
>
> @@ -561,6 +631,18 @@ sub sortStart {
> return $val;
> }
>
> +sub sortEnd {
> + my $as = $db{$a}->{'end'};
> + my $bs = $db{$b}->{'end'};
> + my $val;
> +
> +say $a unless defined $as;
> + $val = $as <=> $bs;
> + $val = $a cmp $b if $val == 0;
> +
> + return $val;
> +}
> +
> sub get_engine_timeline {
> my ($ring) = @_;
> my @timeline;
> @@ -568,7 +650,7 @@ sub get_engine_timeline {
> return $engine_timelines{$ring} if exists $engine_timelines{$ring};
>
> @timeline = grep { $db{$_}->{'ring'} eq $ring } keys %db;
> - @timeline = sort sortStart @timeline;
> + @timeline = sort sortEnd @timeline;
> $engine_timelines{$ring} = \@timeline;
>
> return \@timeline;
> @@ -679,73 +761,6 @@ sub get_ctx_timeline {
> return \@timeline;
> }
>
> -# Split out merged batches if requested.
> -if ($correct_durations) {
> - # Shift !port0 requests start time to after the previous context on the
> - # same timeline has finished.
> - foreach my $gid (sort keys %rings) {
> - my $ring = $ringmap{$rings{$gid}};
> - my $timeline = get_engine_timeline($ring);
> - my $complete;
> -
> - foreach my $pos (0..$#{$timeline}) {
> - my $key = @{$timeline}[$pos];
> - my $prev = $complete;
> - my $pkey;
> -
> - $complete = $key unless exists $db{$key}->{'no-end'};
> - $pkey = $complete;
> -
> - next if $db{$key}->{'port'} == 0;
> -
> - $pkey = $prev if $complete eq $key;
> -
> - die unless defined $pkey;
> -
> - $db{$key}->{'start'} = $db{$pkey}->{'end'};
> - $db{$key}->{'start'} = $db{$pkey}->{'notify'} if $db{$key}->{'start'} > $db{$key}->{'end'};
> -
> - die if $db{$key}->{'start'} > $db{$key}->{'end'};
> -
> - $re_sort = 1;
> - }
> - }
> -
> - maybe_sort_keys();
> -
> - # Batch with no-end (no request_out) means it was submitted as part of
> - # coalesced context. This means it's start time should be set to the end
> - # time of a following request on this context timeline.
> - foreach my $tkey (sort keys %ctxtimelines) {
> - my ($ctx, $ring) = split '/', $tkey;
> - my $timeline = get_ctx_timeline($ctx, $ring, $tkey);
> - my $last_complete = -1;
> - my $complete;
> -
> - foreach my $pos (0..$#{$timeline}) {
> - my $key = @{$timeline}[$pos];
> - my $next_key;
> -
> - next unless exists $db{$key}->{'no-end'};
> - last if $pos == $#{$timeline};
> -
> - # Shift following request to start after the current
> - # one, but only if that wouldn't make it zero duration,
> - # which would indicate notify arrived after context
> - # complete.
> - $next_key = ${$timeline}[$pos + 1];
> - if (exists $db{$key}->{'notify'} and
> - $db{$key}->{'notify'} < $db{$key}->{'end'}) {
> - $db{$next_key}->{'engine-start'} = $db{$next_key}->{'start'};
> - $db{$next_key}->{'start'} = $db{$key}->{'notify'};
> - $re_sort = 1;
> - }
> - }
> - }
> -}
> -
> -maybe_sort_keys();
> -
> # GPU time accounting
> my (%running, %runnable, %queued, %batch_avg, %batch_total_avg, %batch_count);
> my (%submit_avg, %execute_avg, %ctxsave_avg);
> @@ -781,8 +796,7 @@ foreach my $key (@sorted_keys) {
> $db{$key}->{'duration'} = 0;
> }
>
> - $running{$ring} += $end - $start if $correct_durations or
> - not exists $db{$key}->{'no-end'};
> + $running{$ring} += $end - $start if not exists $db{$key}->{'no-end'};
> unless (exists $db{$key}->{'virtual'}) {
> $runnable{$ring} += $db{$key}->{'execute-delay'};
> $queued{$ring} += $start - $db{$key}->{'execute-delay'} - $db{$key}->{'queue'};
> @@ -1324,9 +1338,14 @@ foreach my $key (sort sortQueue keys %db) {
> $content .= ' <small><i>++</i></small> ' if exists $db{$key}->{'no-end'};
> $content .= ' <small><i>+</i></small> ' if exists $db{$key}->{'no-notify'};
> $content .= "<br>$db{$key}->{'duration'}us <small>($db{$key}->{'context-complete-delay'}us)</small>";
> - $startend = 'start: ' . $start . ', end: ' . $notify;
> - print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n";
> - $i++;
> + foreach my $slice (@{$db{$key}->{'slices'}}) {
> + my ($s, $e) = ($start, $notify);
> + $s = @{$slice}[0] if @{$slice}[0] >= $start;
> + $e = @{$slice}[1] if @{$slice}[1] <= $notify;
> + $startend = 'start: ' . $s . ', end: ' . $e;
> + print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n";
> + $i++;
> + }
> }
>
> # user interrupt to context complete
>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: perf.data.tar.gz
Type: application/x-gzip
Size: 95585 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/intel-gfx/attachments/20200117/b3da6f51/attachment-0001.bin>
More information about the Intel-gfx
mailing list