Re: [PATCH 3/7] Add IRQ_TIME_ACCOUNTING, finer accounting of irq time -v3

[Venkatesh Pallipadi]

On Fri, Oct 1, 2010 at 4:46 AM, Peter Zijlstra <peterz@xxxxxxxxxxxxx> wrote:
> On Thu, 2010-09-30 at 13:38 -0700, Venkatesh Pallipadi wrote:
>> On Thu, Sep 30, 2010 at 9:29 AM, Venkatesh Pallipadi <venki@xxxxxxxxxx> wrote:
>> > On Thu, Sep 30, 2010 at 4:06 AM, Peter Zijlstra <peterz@xxxxxxxxxxxxx> wrote:
>> >> On Wed, 2010-09-29 at 12:21 -0700, Venkatesh Pallipadi wrote:
>> >>> +void account_system_vtime(struct task_struct *curr)
>> >>> +{
>> >>> +       unsigned long flags;
>> >>> +       int cpu;
>> >>> +       u64 now, delta;
>> >>> +
>> >>> +       if (!sched_clock_irqtime)
>> >>> +               return;
>> >>> +
>> >>> +       local_irq_save(flags);
>> >>> +
>> >>> +       now = sched_clock();
>> >>> +       cpu = smp_processor_id();
>> >>
>> >> Like said before, that really wants to read like:
>> >>
>> >>        cpu = smp_processor_id();
>> >>        now = sched_clock_cpu(cpu);
>> >>
>> >> sched_clock() is raw tsc + ns conversion and can go all over the place.
>> >
>> > sched_clock_cpu() won't really work for here, due to what looks like
>> > idle and timer tick dependencies. Using sched_clock_cpu(), I end up
>> > accounting CPU idle time to hardirq due to time captured before the
>> > handler and after the handler.
>> >
>>
>> Specifically, here is the now and delta log from my test setup with
>> using sched_clock_cpu() above (data below from a particular CPU)
>>
>>           <idle>-0     [001]  1697.910060: account_system_vtime:
>> SOFTIRQ STOP 1700897011613, delta 3555
>>           <idle>-0     [001]  1697.911047: account_system_vtime: IRQ
>> START 1700897999028
>
> Dude, linewrap hell! And what are you trying to illustrate?
>
Sorry. Retrying with shorted lines

This is the log of start, hardirq stop, softirq stop and deltas at
stop, taken in account_system_vtime on CPU 1 with sched_clock_cpu.

~5000 delta for a hardirq seems reasonable. But, as you see there are
frequent ms deltas on hardirq, specifically when in idle.

<idle>-0     []  1697.911047: START 1700897999028
<idle>-0     []  1697.911051: HARD STOP 1700898005071, delta 6043
<idle>-0     []  1697.911052: START 1700898006003
<idle>-0     []  1697.911057: SOFT STOP 1700898010685, delta 4682
<idle>-0     []  1697.911931: START 1700898884039
<idle>-0     []  1697.911935: HARD STOP 1700898890304, delta 6265
<idle>-0     []  1697.915040: START 1700899887146
<idle>-0     []  1697.915047: HARD STOP 1700902008678, delta 2121532
<idle>-0     []  1697.915048: START 1700902009617
<idle>-0     []  1697.915055: SOFT STOP 1700902015924, delta 6307
<idle>-0     []  1697.918958: START 1700903006980
<idle>-0     []  1697.918963: HARD STOP 1700905931367, delta 2924387
<idle>-0     []  1697.919553: START 1700906521486
<idle>-0     []  1697.919557: HARD STOP 1700906527006, delta 5520
<idle>-0     []  1697.933420: START 1700907524219
<idle>-0     []  1697.933428: HARD STOP 1700920424020, delta 12899801
<idle>-0     []  1697.936512: START 1700921418037
<idle>-0     []  1697.936523: HARD STOP 1700923524497, delta 2106460


This is probably because this test system is of the crazy TSC ones.
But, it does have TSC as its closcksource and there is no trace of
mark_tsc_unstable in dmesg.

Thanks,
Venki
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/