[Intel-gfx] [PATCH i-g-t 4/4] trace.pl: Fix frequency timeline

[Tvrtko Ursulin]

On 27/07/2018 23:17, John Harrison wrote:
> On 7/19/2018 2:36 AM, Tvrtko Ursulin wrote:
>> From: Tvrtko Ursulin<tvrtko.ursulin at 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 at 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