From patchwork Wed May 8 12:10:40 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Tvrtko Ursulin X-Patchwork-Id: 10935555 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 1ECA61575 for ; Wed, 8 May 2019 12:11:11 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 0CF5F289B0 for ; Wed, 8 May 2019 12:11:11 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 019FB289C0; Wed, 8 May 2019 12:11:10 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-5.2 required=2.0 tests=BAYES_00,MAILING_LIST_MULTI, RCVD_IN_DNSWL_MED autolearn=ham version=3.3.1 Received: from gabe.freedesktop.org (gabe.freedesktop.org [131.252.210.177]) (using TLSv1.2 with cipher DHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.wl.linuxfoundation.org (Postfix) with ESMTPS id 166DF289B9 for ; Wed, 8 May 2019 12:11:10 +0000 (UTC) Received: from gabe.freedesktop.org (localhost [127.0.0.1]) by gabe.freedesktop.org (Postfix) with ESMTP id 76C808989F; Wed, 8 May 2019 12:11:08 +0000 (UTC) X-Original-To: Intel-gfx@lists.freedesktop.org Delivered-To: Intel-gfx@lists.freedesktop.org Received: from mga17.intel.com (mga17.intel.com [192.55.52.151]) by gabe.freedesktop.org (Postfix) with ESMTPS id 7D9B68989C; Wed, 8 May 2019 12:11:07 +0000 (UTC) X-Amp-Result: SKIPPED(no attachment in message) X-Amp-File-Uploaded: False Received: from fmsmga008.fm.intel.com ([10.253.24.58]) by fmsmga107.fm.intel.com with ESMTP/TLS/DHE-RSA-AES256-GCM-SHA384; 08 May 2019 05:11:07 -0700 X-ExtLoop1: 1 Received: from jzapadkx-mobl1.ger.corp.intel.com (HELO localhost.localdomain) ([10.252.0.159]) by fmsmga008.fm.intel.com with ESMTP; 08 May 2019 05:11:06 -0700 From: Tvrtko Ursulin To: igt-dev@lists.freedesktop.org Date: Wed, 8 May 2019 13:10:40 +0100 Message-Id: <20190508121058.27038-4-tvrtko.ursulin@linux.intel.com> X-Mailer: git-send-email 2.19.1 In-Reply-To: <20190508121058.27038-1-tvrtko.ursulin@linux.intel.com> References: <20190508121058.27038-1-tvrtko.ursulin@linux.intel.com> MIME-Version: 1.0 Subject: [Intel-gfx] [PATCH i-g-t 03/21] trace.pl: Virtual engine support X-BeenThere: intel-gfx@lists.freedesktop.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Intel graphics driver community testing & development List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: Intel-gfx@lists.freedesktop.org Errors-To: intel-gfx-bounces@lists.freedesktop.org Sender: "Intel-gfx" X-Virus-Scanned: ClamAV using ClamSMTP From: Tvrtko Ursulin Add virtual/queue timelines to both stdout and HTML output. A new timeline is created for each queue/virtual engine to display associated requests in queued and runnable states. Once requests are submitted to a real engine for executing they show up on the physical engine timeline. Signed-off-by: Tvrtko Ursulin Cc: Chris Wilson --- scripts/trace.pl | 238 +++++++++++++++++++++++++++++++++++++++++------ 1 file changed, 208 insertions(+), 30 deletions(-) diff --git a/scripts/trace.pl b/scripts/trace.pl index 95dc3a645e8e..6cc332bb6e2a 100755 --- a/scripts/trace.pl +++ b/scripts/trace.pl @@ -27,11 +27,16 @@ use warnings; use 5.010; my $gid = 0; -my (%db, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait, +my (%db, %vdb, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait, %ctxtimelines, %ctxengines); +my (%cids, %ctxmap); +my $cid = 0; +my %queues; my @freqs; -my $max_items = 3000; +use constant VENG => '255:254'; + +my $max_requests = 1000; my $width_us = 32000; my $correct_durations = 0; my %ignore_ring; @@ -181,21 +186,21 @@ sub arg_trace return @_; } -sub arg_max_items +sub arg_max_requests { my $val; return unless scalar(@_); - if ($_[0] eq '--max-items' or $_[0] eq '-m') { + if ($_[0] eq '--max-requests' or $_[0] eq '-m') { shift @_; $val = shift @_; - } elsif ($_[0] =~ /--max-items=(\d+)/) { + } elsif ($_[0] =~ /--max-requests=(\d+)/) { shift @_; $val = $1; } - $max_items = int($val) if defined $val; + $max_requests = int($val) if defined $val; return @_; } @@ -292,7 +297,7 @@ while (@args) { @args = arg_avg_delay_stats(@args); @args = arg_gpu_timeline(@args); @args = arg_trace(@args); - @args = arg_max_items(@args); + @args = arg_max_requests(@args); @args = arg_zoom_width(@args); @args = arg_split_requests(@args); @args = arg_ignore_ring(@args); @@ -324,6 +329,13 @@ sub sanitize_ctx } } +sub is_veng +{ + my ($class, $instance) = split ':', shift; + + return $instance eq '254'; +} + # Main input loop - parse lines and build the internal representation of the # trace using a hash of requests and some auxilliary data structures. my $prev_freq = 0; @@ -366,6 +378,7 @@ while (<>) { $ctx = $tp{'ctx'}; $orig_ctx = $ctx; $ctx = sanitize_ctx($ctx, $ring); + $ring = VENG if is_veng($ring); $key = db_key($ring, $ctx, $seqno); } } @@ -374,6 +387,7 @@ while (<>) { my %rw; next if exists $reqwait{$key}; + die if $ring eq VENG and not exists $queues{$ctx}; $rw{'key'} = $key; $rw{'ring'} = $ring; @@ -382,9 +396,19 @@ while (<>) { $rw{'start'} = $time; $reqwait{$key} = \%rw; } elsif ($tp_name eq 'i915:i915_request_wait_end:') { - next unless exists $reqwait{$key}; + die if $ring eq VENG and not exists $queues{$ctx}; - $reqwait{$key}->{'end'} = $time; + if (exists $reqwait{$key}) { + $reqwait{$key}->{'end'} = $time; + } else { # Virtual engine + my $vkey = db_key(VENG, $ctx, $seqno); + + die unless exists $reqwait{$vkey}; + + # If the wait started on the virtual engine, attribute + # it to it completely. + $reqwait{$vkey}->{'end'} = $time; + } } elsif ($tp_name eq 'i915:i915_request_add:') { if (exists $queue{$key}) { $ctxdb{$orig_ctx}++; @@ -395,19 +419,52 @@ while (<>) { } $queue{$key} = $time; + if ($ring eq VENG and not exists $queues{$ctx}) { + $queues{$ctx} = 1 ; + $cids{$ctx} = $cid++; + $ctxmap{$cids{$ctx}} = $ctx; + } } elsif ($tp_name eq 'i915:i915_request_submit:') { die if exists $submit{$key}; die unless exists $queue{$key}; + die if $ring eq VENG and not exists $queues{$ctx}; $submit{$key} = $time; } elsif ($tp_name eq 'i915:i915_request_in:') { + my ($q, $s); my %req; # preemption delete $db{$key} if exists $db{$key}; - die unless exists $queue{$key}; - die unless exists $submit{$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; + $req{'start'} = $time; + $req{'end'} = $time; + $req{'ring'} = VENG; + $req{'seqno'} = $seqno; + $req{'ctx'} = $ctx; + $req{'name'} = $ctx . '/' . $seqno; + $req{'global'} = $tp{'global'}; + $req{'port'} = $tp{'port'}; + + $vdb{$vkey} = \%req; + } else { + $q = $queue{$key}; + $s = $submit{$key}; + } $req{'start'} = $time; $req{'ring'} = $ring; @@ -419,8 +476,9 @@ while (<>) { $req{'name'} = $ctx . '/' . $seqno; $req{'global'} = $tp{'global'}; $req{'port'} = $tp{'port'}; - $req{'queue'} = $queue{$key}; - $req{'submit'} = $submit{$key}; + $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; @@ -720,8 +778,10 @@ foreach my $key (@sorted_keys) { $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'}; + unless (exists $db{$key}->{'virtual'}) { + $runnable{$ring} += $db{$key}->{'execute-delay'}; + $queued{$ring} += $start - $db{$key}->{'execute-delay'} - $db{$key}->{'queue'}; + } $batch_count{$ring}++; @@ -840,6 +900,12 @@ foreach my $key (keys %reqwait) { $reqw{$reqwait{$key}->{'ring'}} += $reqwait{$key}->{'end'} - $reqwait{$key}->{'start'}; } +# Add up all request waits per virtual engine +my %vreqw; +foreach my $key (keys %reqwait) { + $vreqw{$reqwait{$key}->{'ctx'}} += $reqwait{$key}->{'end'} - $reqwait{$key}->{'start'}; +} + say sprintf('GPU: %.2f%% idle, %.2f%% busy', $flat_busy{'gpu-idle'}, $flat_busy{'gpu-busy'}) unless $html; @@ -961,18 +1027,24 @@ ENDHTML sub html_stats { my ($stats, $group, $id) = @_; + my $veng = exists $stats->{'virtual'} ? 1 : 0; my $name; - $name = 'Ring' . $group; + $name = $veng ? 'Virtual' : 'Ring'; + $name .= $group; $name .= '

'; - $name .= sprintf('%.2f', $stats->{'idle'}) . '% idle

'; - $name .= sprintf('%.2f', $stats->{'busy'}) . '% busy
'; + unless ($veng) { + $name .= sprintf('%.2f', $stats->{'idle'}) . '% idle

'; + $name .= sprintf('%.2f', $stats->{'busy'}) . '% busy
'; + } $name .= sprintf('%.2f', $stats->{'runnable'}) . '% runnable
'; $name .= sprintf('%.2f', $stats->{'queued'}) . '% queued

'; $name .= sprintf('%.2f', $stats->{'wait'}) . '% wait

'; $name .= $stats->{'count'} . ' batches
'; - $name .= sprintf('%.2f', $stats->{'avg'}) . 'us avg batch
'; - $name .= sprintf('%.2f', $stats->{'total-avg'}) . 'us avg engine batch
'; + unless ($veng) { + $name .= sprintf('%.2f', $stats->{'avg'}) . 'us avg batch
'; + $name .= sprintf('%.2f', $stats->{'total-avg'}) . 'us avg engine batch
'; + } $name .= ''; print "\t{id: $id, content: '$name'},\n"; @@ -981,17 +1053,24 @@ sub html_stats sub stdio_stats { my ($stats, $group, $id) = @_; + my $veng = exists $stats->{'virtual'} ? 1 : 0; my $str; - $str = 'Ring' . $group . ': '; + $str = $veng ? 'Virtual' : 'Ring'; + $str .= $group . ': '; $str .= $stats->{'count'} . ' batches, '; - $str .= sprintf('%.2f (%.2f) avg batch us, ', $stats->{'avg'}, $stats->{'total-avg'}); - $str .= sprintf('%.2f', $stats->{'idle'}) . '% idle, '; - $str .= sprintf('%.2f', $stats->{'busy'}) . '% busy, '; + unless ($veng) { + $str .= sprintf('%.2f (%.2f) avg batch us, ', + $stats->{'avg'}, $stats->{'total-avg'}); + $str .= sprintf('%.2f', $stats->{'idle'}) . '% idle, '; + $str .= sprintf('%.2f', $stats->{'busy'}) . '% busy, '; + } + $str .= sprintf('%.2f', $stats->{'runnable'}) . '% runnable, '; $str .= sprintf('%.2f', $stats->{'queued'}) . '% queued, '; $str .= sprintf('%.2f', $stats->{'wait'}) . '% wait'; - if ($avg_delay_stats) { + + if ($avg_delay_stats and not $veng) { $str .= ', submit/execute/save-avg=('; $str .= sprintf('%.2f/%.2f/%.2f)', $stats->{'submit'}, $stats->{'execute'}, $stats->{'save'}); } @@ -1013,8 +1092,16 @@ foreach my $group (sort keys %rings) { $stats{'idle'} = (1.0 - $flat_busy{$ring} / $elapsed) * 100.0; $stats{'busy'} = $running{$ring} / $elapsed * 100.0; - $stats{'runnable'} = $runnable{$ring} / $elapsed * 100.0; - $stats{'queued'} = $queued{$ring} / $elapsed * 100.0; + if (exists $runnable{$ring}) { + $stats{'runnable'} = $runnable{$ring} / $elapsed * 100.0; + } else { + $stats{'runnable'} = 0; + } + if (exists $queued{$ring}) { + $stats{'queued'} = $queued{$ring} / $elapsed * 100.0; + } else { + $stats{'queued'} = 0; + } $reqw{$ring} = 0 unless exists $reqw{$ring}; $stats{'wait'} = $reqw{$ring} / $elapsed * 100.0; $stats{'count'} = $batch_count{$ring}; @@ -1031,6 +1118,59 @@ foreach my $group (sort keys %rings) { } } +sub sortVQueue { + my $as = $vdb{$a}->{'queue'}; + my $bs = $vdb{$b}->{'queue'}; + my $val; + + $val = $as <=> $bs; + $val = $a cmp $b if $val == 0; + + return $val; +} + +my @sorted_vkeys = sort sortVQueue keys %vdb; +my (%vqueued, %vrunnable); + +foreach my $key (@sorted_vkeys) { + my $ctx = $vdb{$key}->{'ctx'}; + + $vdb{$key}->{'submit-delay'} = $vdb{$key}->{'submit'} - $vdb{$key}->{'queue'}; + $vdb{$key}->{'execute-delay'} = $vdb{$key}->{'start'} - $vdb{$key}->{'submit'}; + + $vqueued{$ctx} += $vdb{$key}->{'submit-delay'}; + $vrunnable{$ctx} += $vdb{$key}->{'execute-delay'}; +} + +my $veng_id = $engine_start_id + scalar(keys %rings); + +foreach my $cid (sort keys %ctxmap) { + my $ctx = $ctxmap{$cid}; + my $elapsed = $last_ts - $first_ts; + my %stats; + + $stats{'virtual'} = 1; + if (exists $vrunnable{$ctx}) { + $stats{'runnable'} = $vrunnable{$ctx} / $elapsed * 100.0; + } else { + $stats{'runnable'} = 0; + } + if (exists $vqueued{$ctx}) { + $stats{'queued'} = $vqueued{$ctx} / $elapsed * 100.0; + } else { + $stats{'queued'} = 0; + } + $vreqw{$ctx} = 0 unless exists $vreqw{$ctx}; + $stats{'wait'} = $vreqw{$ctx} / $elapsed * 100.0; + $stats{'count'} = scalar(grep {$ctx == $vdb{$_}->{'ctx'}} keys %vdb); + + if ($html) { + html_stats(\%stats, $cid, $veng_id++); + } else { + stdio_stats(\%stats, $cid, $veng_id++); + } +} + exit 0 unless $html; print <{'name'}, $db{$key}->{'ctx'}, $db{$key}->{'seqno'}); my ($queue, $start, $notify, $end) = ($db{$key}->{'queue'}, $db{$key}->{'start'}, $db{$key}->{'notify'}, $db{$key}->{'end'}); @@ -1147,7 +1288,7 @@ foreach my $key (sort sortQueue keys %db) { my $skey; # submit to execute - unless (exists $skip_box{'queue'}) { + unless (exists $skip_box{'queue'} or exists $db{$key}->{'virtual'}) { $skey = 2 * $max_seqno * $ctx + 2 * $seqno; $style = box_style($ctx, 'queue'); $content = "$name
$db{$key}->{'submit-delay'}us ($db{$key}->{'execute-delay'}us)"; @@ -1158,7 +1299,7 @@ foreach my $key (sort sortQueue keys %db) { # execute to start $engine_start = $db{$key}->{'start'} unless defined $engine_start; - unless (exists $skip_box{'ready'}) { + unless (exists $skip_box{'ready'} or exists $db{$key}->{'virtual'}) { $skey = 2 * $max_seqno * $ctx + 2 * $seqno + 1; $style = box_style($ctx, 'ready'); $content = "$name
$db{$key}->{'execute-delay'}us"; @@ -1199,7 +1340,7 @@ foreach my $key (sort sortQueue keys %db) { $last_ts = $end; - last if $i > $max_items; + last if ++$req > $max_requests; } push @freqs, [$prev_freq_ts, $last_ts, $prev_freq] if $prev_freq; @@ -1232,6 +1373,43 @@ if ($gpu_timeline) { } } +$req = 0; +$veng_id = $engine_start_id + scalar(keys %rings); +foreach my $key (@sorted_vkeys) { + my ($name, $ctx, $seqno) = ($vdb{$key}->{'name'}, $vdb{$key}->{'ctx'}, $vdb{$key}->{'seqno'}); + my $queue = $vdb{$key}->{'queue'}; + my $submit = $vdb{$key}->{'submit'}; + my $engine_start = $db{$key}->{'engine-start'}; + my ($content, $style, $startend, $skey); + my $group = $veng_id + $cids{$ctx}; + my $subgroup = $ctx - $min_ctx; + my $type = ' type: \'range\','; + my $duration; + + # submit to execute + unless (exists $skip_box{'queue'}) { + $skey = 2 * $max_seqno * $ctx + 2 * $seqno; + $style = box_style($ctx, 'queue'); + $content = "$name
$vdb{$key}->{'submit-delay'}us ($vdb{$key}->{'execute-delay'}us)"; + $startend = 'start: ' . $queue . ', end: ' . $submit; + print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n"; + $i++; + } + + # execute to start + $engine_start = $vdb{$key}->{'start'} unless defined $engine_start; + unless (exists $skip_box{'ready'}) { + $skey = 2 * $max_seqno * $ctx + 2 * $seqno + 1; + $style = box_style($ctx, 'ready'); + $content = "$name
$vdb{$key}->{'execute-delay'}us"; + $startend = 'start: ' . $submit . ', end: ' . $engine_start; + print "\t{id: $i, key: $skey, $type group: $group, subgroup: $subgroup, subgroupOrder: $subgroup, content: '$content', $startend, style: \'$style\'},\n"; + $i++; + } + + last if ++$req > $max_requests; +} + my $end_ts = $first_ts + $width_us; $first_ts = $first_ts;