From patchwork Thu Oct 18 15:28:00 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Tvrtko Ursulin X-Patchwork-Id: 10647499 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 ECC7F112B for ; Thu, 18 Oct 2018 15:28:39 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id DDEAA28C20 for ; Thu, 18 Oct 2018 15:28:39 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id D205628D0A; Thu, 18 Oct 2018 15:28:39 +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 0D99228C20 for ; Thu, 18 Oct 2018 15:28:39 +0000 (UTC) Received: from gabe.freedesktop.org (localhost [127.0.0.1]) by gabe.freedesktop.org (Postfix) with ESMTP id AC57D6E03B; Thu, 18 Oct 2018 15:28:36 +0000 (UTC) X-Original-To: Intel-gfx@lists.freedesktop.org Delivered-To: Intel-gfx@lists.freedesktop.org Received: from mail-wm1-x342.google.com (mail-wm1-x342.google.com [IPv6:2a00:1450:4864:20::342]) by gabe.freedesktop.org (Postfix) with ESMTPS id B0C6E897FD for ; Thu, 18 Oct 2018 15:28:26 +0000 (UTC) Received: by mail-wm1-x342.google.com with SMTP id i8-v6so711982wmg.0 for ; Thu, 18 Oct 2018 08:28:26 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references; bh=5RbdrFjlDPY+960EFBzZBGdHAbO8lIGKnzy2CaYcybc=; b=BPKgryQHh2m1L5ME8zVAWMIPLDLIUvRsoU2iVg/i9xEC0SSLho80loj/6ndDwG7Zhj KytHxLsRcL46MVgsVgAiUD5FRKkcDSwoEsvOXzUSZ56U8AftB/yuD9mIkxQqUeIrEAmv hswTPuGVi+Fi6S8MjlmyBv03X4qFa0/kf8uaysAucEJ3OtCjkzW4Vp0TE+CAt7QbVAmN acCjNRcfCj8sMc+cE4ZGWiwp0IizXeKd6LxAtPZyx/DoY7kzIwN9qKgUg2UR9EUwcL0d HYmd6ix0obRMD0p4y7H7QDpQqvB5XMGhAHzYHsWJswdVyX7kGfhbO6V01C/TTo6BRUO7 YMpg== X-Gm-Message-State: ABuFfoj2FsojmMIgII3/LpGAvml/yEp3wObmEeic62Lnrw4XoYniZl1m Vls0I4YwfQhBW1S1i7vgFF9Ahg== X-Google-Smtp-Source: ACcGV60GDTSJKXqyMBtyMOZ5aJEq2fqDog2uLqYZoD0Nv2HTXADEFTqjPHMwB/YVl7EWS8CsswylfA== X-Received: by 2002:a1c:b605:: with SMTP id g5-v6mr762262wmf.97.1539876505084; Thu, 18 Oct 2018 08:28:25 -0700 (PDT) Received: from localhost.localdomain ([91.110.193.16]) by smtp.gmail.com with ESMTPSA id i6-v6sm19530387wrq.4.2018.10.18.08.28.24 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Thu, 18 Oct 2018 08:28:24 -0700 (PDT) From: Tvrtko Ursulin X-Google-Original-From: Tvrtko Ursulin To: igt-dev@lists.freedesktop.org Date: Thu, 18 Oct 2018 16:28:00 +0100 Message-Id: <20181018152815.31816-3-tvrtko.ursulin@linux.intel.com> X-Mailer: git-send-email 2.17.1 In-Reply-To: <20181018152815.31816-1-tvrtko.ursulin@linux.intel.com> References: <20181018152815.31816-1-tvrtko.ursulin@linux.intel.com> Subject: [Intel-gfx] [PATCH i-g-t 02/17] 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 MIME-Version: 1.0 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 | 230 ++++++++++++++++++++++++++++++++++++++++------- 1 file changed, 200 insertions(+), 30 deletions(-) diff --git a/scripts/trace.pl b/scripts/trace.pl index 18f9f3b18396..72747b046202 100755 --- a/scripts/trace.pl +++ b/scripts/trace.pl @@ -27,10 +27,15 @@ use warnings; use 5.010; my $gid = 0; -my (%db, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait, %ctxtimelines); +my (%db, %vdb, %queue, %submit, %notify, %rings, %ctxdb, %ringmap, %reqwait, %ctxtimelines); +my (%cids, %ctxmap); +my $cid = 0; +my %queues; my @freqs; -my $max_items = 3000; +use constant VENG => '255:0'; + +my $max_requests = 1000; my $width_us = 32000; my $correct_durations = 0; my %ignore_ring; @@ -180,21 +185,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 @_; } @@ -291,7 +296,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); @@ -380,6 +385,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; @@ -388,9 +394,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}; + + if (exists $reqwait{$key}) { + $reqwait{$key}->{'end'} = $time; + } else { # Virtual engine + my $vkey = db_key(VENG, $ctx, $seqno); + + die unless exists $reqwait{$vkey}; - $reqwait{$key}->{'end'} = $time; + # 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}++; @@ -401,19 +417,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; @@ -423,8 +472,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 +770,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 +892,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 +1019,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 +1045,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 +1084,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 +1110,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 +1280,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 +1291,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 +1332,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 +1365,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;