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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <AANLkTi=b2NaXOS05tT69hdmddxPPc5OxxnZ0qG0ZZZYe@mail.gmail.com>
Date:	Fri, 1 Oct 2010 10:29:06 -0700
From:	Venkatesh Pallipadi <venki@...gle.com>
To:	Peter Zijlstra <peterz@...radead.org>
Cc:	Ingo Molnar <mingo@...e.hu>, "H. Peter Anvin" <hpa@...or.com>,
	Thomas Gleixner <tglx@...utronix.de>,
	Balbir Singh <balbir@...ux.vnet.ibm.com>,
	Martin Schwidefsky <schwidefsky@...ibm.com>,
	linux-kernel@...r.kernel.org, Paul Turner <pjt@...gle.com>,
	Eric Dumazet <eric.dumazet@...il.com>
Subject: Re: [PATCH 3/7] Add IRQ_TIME_ACCOUNTING, finer accounting of irq time -v3

On Fri, Oct 1, 2010 at 9:51 AM, Venkatesh Pallipadi <venki@...gle.com> wrote:
> On Fri, Oct 1, 2010 at 4:46 AM, Peter Zijlstra <peterz@...radead.org> 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@...gle.com> wrote:
>>> > On Thu, Sep 30, 2010 at 4:06 AM, Peter Zijlstra <peterz@...radead.org> 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.
>

Digging a bit deeper into sched_clock stuff, I see sched_clock_stable
is only set in
arch/x86/kernel/cpu/intel.c when
    if (c->x86_power & (1 << 8)) {

So, on x86, sched_clock_stable is not set on all other kind of CPUs
and my test system happens to be one of them. So, sched_clock_cpu()
falls back to tick based even when TSC is not marked unstable and
clocksource is using TSC for timing.
First, is this limited use of sched_clock_stable by design? Shouldn't
it be rather based on tsc_unstable value in tsc.c?
If this is by design, I will have to limit the irq accounting to this
limited set of CPUs as well. As, for irq accounting, I cannot use tick
based sched_clock_cpu() as it will have jumps while handling interrupt
when the clock gets readjusted.

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