From: Tvrtko Ursulin <tvrtko.ursulin@xxxxxxxxx> 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 <tvrtko.ursulin@xxxxxxxxx> Cc: Chris Wilson <chris@xxxxxxxxxxxxxxxxxx> --- 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 .= '<br><small><br>'; - $name .= sprintf('%.2f', $stats->{'idle'}) . '% idle<br><br>'; - $name .= sprintf('%.2f', $stats->{'busy'}) . '% busy<br>'; + unless ($veng) { + $name .= sprintf('%.2f', $stats->{'idle'}) . '% idle<br><br>'; + $name .= sprintf('%.2f', $stats->{'busy'}) . '% busy<br>'; + } $name .= sprintf('%.2f', $stats->{'runnable'}) . '% runnable<br>'; $name .= sprintf('%.2f', $stats->{'queued'}) . '% queued<br><br>'; $name .= sprintf('%.2f', $stats->{'wait'}) . '% wait<br><br>'; $name .= $stats->{'count'} . ' batches<br>'; - $name .= sprintf('%.2f', $stats->{'avg'}) . 'us avg batch<br>'; - $name .= sprintf('%.2f', $stats->{'total-avg'}) . 'us avg engine batch<br>'; + unless ($veng) { + $name .= sprintf('%.2f', $stats->{'avg'}) . 'us avg batch<br>'; + $name .= sprintf('%.2f', $stats->{'total-avg'}) . 'us avg engine batch<br>'; + } $name .= '</small>'; 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 <<ENDHTML; @@ -1134,6 +1266,7 @@ sub box_style } my $i = 0; +my $req = 0; 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'}); @@ -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<br>$db{$key}->{'submit-delay'}us <small>($db{$key}->{'execute-delay'}us)</small>"; @@ -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 = "<small>$name<br>$db{$key}->{'execute-delay'}us</small>"; @@ -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<br>$vdb{$key}->{'submit-delay'}us <small>($vdb{$key}->{'execute-delay'}us)</small>"; + $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 = "<small>$name<br>$vdb{$key}->{'execute-delay'}us</small>"; + $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; -- 2.17.1 _______________________________________________ Intel-gfx mailing list Intel-gfx@xxxxxxxxxxxxxxxxxxxxx https://lists.freedesktop.org/mailman/listinfo/intel-gfx