| Message ID | 20180719093601.11788-5-tvrtko.ursulin@linux.intel.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
On 7/19/2018 2:36 AM, Tvrtko Ursulin wrote: > From: Tvrtko Ursulin <tvrtko.ursulin@intel.com> > > Frequency timeline needs to be finished with an entry spanning to the end > of known time so that the last known frequency is displayed. > > Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com> > --- > scripts/trace.pl | 2 ++ > 1 file changed, 2 insertions(+) > > diff --git a/scripts/trace.pl b/scripts/trace.pl > index 1924333e12b6..2976cfdf585a 100755 > --- a/scripts/trace.pl > +++ b/scripts/trace.pl > @@ -1201,6 +1201,8 @@ foreach my $key (sort sortQueue keys %db) { > last if $i > $max_items; > } > > +push @freqs, [$prev_freq_ts, $last_ts, $prev_freq] if $prev_freq; > + > foreach my $item (@freqs) { > my ($start, $end, $freq) = @$item; > my $startend; This does not appear to do anything for me. At least not with any of my trace files. I get exactly the same output with or without the change. What situation is it meant to fix? Note that I get the frequency line abbreviated to the size of the request trace. Not sure if that is intentional or not. E.g. with the following trace data the frequency bar starts with 300 at a time of 728us not 706us. Likewise, it ends at 389838us not 392227us: gem_exec_trace 1316 [002] 856981.389706: i915:intel_gpu_freq_change: new_freq=300 gem_exec_trace 1316 [002] 856981.389728: i915:i915_request_add: dev=0, engine=0:0, hw_id=2, ctx=847, seqno=1, global=0 gem_exec_trace 1316 [002] 856981.389732: i915:i915_request_submit: dev=0, engine=0:0, hw_id=2, ctx=847, seqno=1, global=0 gem_exec_trace 1316 [002] 856981.389739: i915:i915_request_in: dev=0, engine=0:0, hw_id=2, ctx=847, seqno=1, prio=0, global=1, port=0 swapper 0 [002] 856981.389838: i915:i915_request_out: dev=0, engine=0:0, hw_id=2, ctx=847, seqno=1, global=1, completed?=1 kworker/u8:1 1246 [001] 856981.392227: i915:intel_gpu_freq_change: new_freq=300 <html> <head> <meta http-equiv="Content-Type" content="text/html; charset=utf-8"> </head> <body text="#000000" bgcolor="#FFFFFF"> On 7/19/2018 2:36 AM, Tvrtko Ursulin wrote:<br> <blockquote type="cite" cite="mid:20180719093601.11788-5-tvrtko.ursulin@linux.intel.com"> <pre wrap="">From: Tvrtko Ursulin <a class="moz-txt-link-rfc2396E" href="mailto:tvrtko.ursulin@intel.com"><tvrtko.ursulin@intel.com></a> Frequency timeline needs to be finished with an entry spanning to the end of known time so that the last known frequency is displayed. Signed-off-by: Tvrtko Ursulin <a class="moz-txt-link-rfc2396E" href="mailto:tvrtko.ursulin@intel.com"><tvrtko.ursulin@intel.com></a> --- scripts/trace.pl | 2 ++ 1 file changed, 2 insertions(+) diff --git a/scripts/trace.pl b/scripts/trace.pl index 1924333e12b6..2976cfdf585a 100755 --- a/scripts/trace.pl +++ b/scripts/trace.pl @@ -1201,6 +1201,8 @@ foreach my $key (sort sortQueue keys %db) { last if $i > $max_items; } +push @freqs, [$prev_freq_ts, $last_ts, $prev_freq] if $prev_freq; + foreach my $item (@freqs) { my ($start, $end, $freq) = @$item; my $startend; </pre> </blockquote> <br> This does not appear to do anything for me. At least not with any of my trace files. I get exactly the same output with or without the change. What situation is it meant to fix?<br> <br> Note that I get the frequency line abbreviated to the size of the request trace. Not sure if that is intentional or not. E.g. with the following trace data the frequency bar starts with 300 at a time of 728us not 706us. Likewise, it ends at 389838us not 392227us:<br> <pre style="color: rgb(0, 0, 0); font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: 400; letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform: none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style: initial; text-decoration-color: initial; word-wrap: break-word; white-space: pre-wrap;"> gem_exec_trace 1316 [002] 856981.389706: i915:intel_gpu_freq_change: new_freq=300 gem_exec_trace 1316 [002] 856981.389728: i915:i915_request_add: dev=0, engine=0:0, hw_id=2, ctx=847, seqno=1, global=0 gem_exec_trace 1316 [002] 856981.389732: i915:i915_request_submit: dev=0, engine=0:0, hw_id=2, ctx=847, seqno=1, global=0 gem_exec_trace 1316 [002] 856981.389739: i915:i915_request_in: dev=0, engine=0:0, hw_id=2, ctx=847, seqno=1, prio=0, global=1, port=0 swapper 0 [002] 856981.389838: i915:i915_request_out: dev=0, engine=0:0, hw_id=2, ctx=847, seqno=1, global=1, completed?=1 kworker/u8:1 1246 [001] 856981.392227: i915:intel_gpu_freq_change: new_freq=300 </pre> </body> </html>
On 27/07/2018 23:17, John Harrison wrote: > On 7/19/2018 2:36 AM, Tvrtko Ursulin wrote: >> From: Tvrtko Ursulin<tvrtko.ursulin@intel.com> >> >> Frequency timeline needs to be finished with an entry spanning to the end >> of known time so that the last known frequency is displayed. >> >> Signed-off-by: Tvrtko Ursulin<tvrtko.ursulin@intel.com> >> --- >> scripts/trace.pl | 2 ++ >> 1 file changed, 2 insertions(+) >> >> diff --git a/scripts/trace.pl b/scripts/trace.pl >> index 1924333e12b6..2976cfdf585a 100755 >> --- a/scripts/trace.pl >> +++ b/scripts/trace.pl >> @@ -1201,6 +1201,8 @@ foreach my $key (sort sortQueue keys %db) { >> last if $i > $max_items; >> } >> >> +push @freqs, [$prev_freq_ts, $last_ts, $prev_freq] if $prev_freq; >> + >> foreach my $item (@freqs) { >> my ($start, $end, $freq) = @$item; >> my $startend; > > This does not appear to do anything for me. At least not with any of my > trace files. I get exactly the same output with or without the change. > What situation is it meant to fix? It fixes the frequency box ending at the last intel_gpu_freq_change timestamp instead of at the end of the displayed timeline. > Note that I get the frequency line abbreviated to the size of the > request trace. Not sure if that is intentional or not. E.g. with the > following trace data the frequency bar starts with 300 at a time of > 728us not 706us. Likewise, it ends at 389838us not 392227us: > > gem_exec_trace 1316 [002] 856981.389706: i915:intel_gpu_freq_change: new_freq=300 > gem_exec_trace 1316 [002] 856981.389728: i915:i915_request_add: dev=0, engine=0:0, hw_id=2, ctx=847, seqno=1, global=0 > gem_exec_trace 1316 [002] 856981.389732: i915:i915_request_submit: dev=0, engine=0:0, hw_id=2, ctx=847, seqno=1, global=0 > gem_exec_trace 1316 [002] 856981.389739: i915:i915_request_in: dev=0, engine=0:0, hw_id=2, ctx=847, seqno=1, prio=0, global=1, port=0 > swapper 0 [002] 856981.389838: i915:i915_request_out: dev=0, engine=0:0, hw_id=2, ctx=847, seqno=1, global=1, completed?=1 > kworker/u8:1 1246 [001] 856981.392227: i915:intel_gpu_freq_change: new_freq=300 For this I have no explanation. All processing is happening inside the freq change tracepoint so I don't understand how it could get one belonging to a different event. Regards, Tvrtko
diff --git a/scripts/trace.pl b/scripts/trace.pl index 1924333e12b6..2976cfdf585a 100755 --- a/scripts/trace.pl +++ b/scripts/trace.pl @@ -1201,6 +1201,8 @@ foreach my $key (sort sortQueue keys %db) { last if $i > $max_items; } +push @freqs, [$prev_freq_ts, $last_ts, $prev_freq] if $prev_freq; + foreach my $item (@freqs) { my ($start, $end, $freq) = @$item; my $startend;