Wakeup latency measured with SCHED_TRACER depends on HZ

Wakeup latency measured with SCHED_TRACER depends on HZ

[Stanislav Meduna]

Hi,

on an embedded platform using a Freescale i.MX28 ARM processor
I am experiencing a strange phenomenon - the latencies reported
are dependent of HZ in the way such as:

# cat timerandwakeup/max_latency-CPU0

HZ 500:
459 15 2499 (499) myApp <- 284 -6 mmcqd/1 273.436000

HZ 100:
459 15 10453 (453) myApp <- 284 -6 mmcqd/1 273.436000


The wakeup/max_latency is always exactly one HZ tick

# cat wakeup/max_latency-CPU0
233 50 2000 (0) irq/101-imx28-f <- 0 -21 swapper 121.764000


All the timestamps in e.g. dmesg output also exhibit the HZ
granularity (this is definitely not the case on an x86),
so I'd say the interpolation somehow does not work.
The hardware counter itself increments at 32 kHz (at least
clocksource_mmio_init is called with 32000 in hz parameter).

Date +%N (show nanosecond part of current time) does not
exhibit the same rounding.


Anyone has an idea where to start the search? I understand
that as I am probably the first one experimenting with RT
on this platform I am basically on my own here, I'd just
appreciate pointers to relevant information on the timing
infrastructure.

I am using 3.4.15-rt24 with some patches ported from an older
non-RT kernel provided by the platform vendor. However, none
of those patches touches clock/time handling, so these are from
mainline (arch/arm/mach-mxs/timer.c etc).

Thanks
-- 
                                    Stano

Re: Wakeup latency measured with SCHED_TRACER depends on HZ

[Stanislav Meduna]

[-- Attachment #1: Type: text/plain, Size: 651 bytes --]

On 31.10.2012 22:41, Stanislav Meduna wrote:

> on an embedded platform using a Freescale i.MX28 ARM processor
> I am experiencing a strange phenomenon - the latencies reported
> are dependent of HZ

OK, the problem is that the MXS platform does not setup
the scheduler clock so the scheduler only sees the HZ one.

The patch in attach fixes this. I can only test the MX28 part -
I don't have any timrot_is_v1() (MX23) hardware and I don't
know whether a source that wraps after ~2 seconds is OK at all.

Please Cc: when replying, I am not subscribed to linux-kernel
(only to linux-rt-users).

Regards
-- 
                                      Stano


[-- Attachment #2: 0001-Setup-scheduler-clock-for-MXS.patch --]
[-- Type: text/plain, Size: 1511 bytes --]

>From ddeed3c83d48e8ce33b36bd964572756354e7feb Mon Sep 17 00:00:00 2001
From: Stanislav Meduna <stano@meduna.org>
Date: Fri, 2 Nov 2012 15:00:44 +0100
Subject: [PATCH] Setup scheduler clock for MXS

---
 arch/arm/mach-mxs/timer.c |   19 +++++++++++++++++++
 1 files changed, 19 insertions(+), 0 deletions(-)

diff --git a/arch/arm/mach-mxs/timer.c b/arch/arm/mach-mxs/timer.c
index 564a632..0ab86a2 100644
--- a/arch/arm/mach-mxs/timer.c
+++ b/arch/arm/mach-mxs/timer.c
@@ -26,6 +26,7 @@
 #include <linux/clk.h>
 
 #include <asm/mach/time.h>
+#include <asm/sched_clock.h>
 #include <mach/mxs.h>
 #include <mach/common.h>
 
@@ -243,6 +244,16 @@ static int __init mxs_clocksource_init(struct clk *timer_clk)
 	return 0;
 }
 
+static u32 notrace mxs_read_sched_clock_v1(void)
+{
+	return timrotv1_get_cycles(&clocksource_mxs);
+}
+
+static u32 notrace mxs_read_sched_clock_v2(void)
+{
+	return ~readl_relaxed(mxs_timrot_base + HW_TIMROT_RUNNING_COUNTn(1));
+}
+
 void __init mxs_timer_init(struct clk *timer_clk, int irq)
 {
 	clk_prepare_enable(timer_clk);
@@ -285,6 +296,14 @@ void __init mxs_timer_init(struct clk *timer_clk, int irq)
 	mxs_clocksource_init(timer_clk);
 	mxs_clockevent_init(timer_clk);
 
+	/* Register scheduler clocksource */
+	if (timrot_is_v1())
+		setup_sched_clock(mxs_read_sched_clock_v1,
+			16, clk_get_rate(timer_clk));
+	else
+		setup_sched_clock(mxs_read_sched_clock_v2,
+			32, clk_get_rate(timer_clk));
+
 	/* Make irqs happen */
 	setup_irq(irq, &mxs_timer_irq);
 }
-- 
1.7.0.4

Re: Wakeup latency measured with SCHED_TRACER depends on HZ

[Shawn Guo]

On Fri, Nov 02, 2012 at 03:29:50PM +0100, Stanislav Meduna wrote:
> On 31.10.2012 22:41, Stanislav Meduna wrote:
> 
> > on an embedded platform using a Freescale i.MX28 ARM processor
> > I am experiencing a strange phenomenon - the latencies reported
> > are dependent of HZ
> 
> OK, the problem is that the MXS platform does not setup
> the scheduler clock so the scheduler only sees the HZ one.
> 
> The patch in attach fixes this. I can only test the MX28 part -
> I don't have any timrot_is_v1() (MX23) hardware and I don't
> know whether a source that wraps after ~2 seconds is OK at all.

>From my quick testing on imx23 with printk timestamp, it's not OK,
so we may need to leave imx23 out there.

> 
> Please Cc: when replying, I am not subscribed to linux-kernel

linux-arm-kernel is better than linux-kernel for this patch.

> (only to linux-rt-users).
> 
> Regards
> -- 
>                                       Stano
> 

> From ddeed3c83d48e8ce33b36bd964572756354e7feb Mon Sep 17 00:00:00 2001
> From: Stanislav Meduna <stano@meduna.org>
> Date: Fri, 2 Nov 2012 15:00:44 +0100
> Subject: [PATCH] Setup scheduler clock for MXS
> 

Generally, empty commit log is not welcomed.  Also, please add prefix
"ARM: mxs: " to patch subject.

> ---
>  arch/arm/mach-mxs/timer.c |   19 +++++++++++++++++++
>  1 files changed, 19 insertions(+), 0 deletions(-)
> 
> diff --git a/arch/arm/mach-mxs/timer.c b/arch/arm/mach-mxs/timer.c
> index 564a632..0ab86a2 100644
> --- a/arch/arm/mach-mxs/timer.c
> +++ b/arch/arm/mach-mxs/timer.c
> @@ -26,6 +26,7 @@
>  #include <linux/clk.h>
>  
>  #include <asm/mach/time.h>
> +#include <asm/sched_clock.h>
>  #include <mach/mxs.h>
>  #include <mach/common.h>
>  
> @@ -243,6 +244,16 @@ static int __init mxs_clocksource_init(struct clk *timer_clk)
>  	return 0;
>  }
>  
> +static u32 notrace mxs_read_sched_clock_v1(void)
> +{
> +	return timrotv1_get_cycles(&clocksource_mxs);
> +}
> +
> +static u32 notrace mxs_read_sched_clock_v2(void)
> +{
> +	return ~readl_relaxed(mxs_timrot_base + HW_TIMROT_RUNNING_COUNTn(1));
> +}
> +
>  void __init mxs_timer_init(struct clk *timer_clk, int irq)
>  {
>  	clk_prepare_enable(timer_clk);
> @@ -285,6 +296,14 @@ void __init mxs_timer_init(struct clk *timer_clk, int irq)
>  	mxs_clocksource_init(timer_clk);
>  	mxs_clockevent_init(timer_clk);
>  
> +	/* Register scheduler clocksource */
> +	if (timrot_is_v1())
> +		setup_sched_clock(mxs_read_sched_clock_v1,
> +			16, clk_get_rate(timer_clk));
> +	else
> +		setup_sched_clock(mxs_read_sched_clock_v2,
> +			32, clk_get_rate(timer_clk));
> +

It should better be done in mxs_clocksource_init().

Shawn

>  	/* Make irqs happen */
>  	setup_irq(irq, &mxs_timer_irq);
>  }
> -- 
> 1.7.0.4
> 

scheduler clock for MXS [Was: Re: Wakeup latency measured with SCHED_TRACER depends on HZ]

[Stanislav Meduna]

On 05.11.2012 03:57, Shawn Guo wrote:

>> The patch in attach fixes this. I can only test the MX28 part -
>> I don't have any timrot_is_v1() (MX23) hardware and I don't
>> know whether a source that wraps after ~2 seconds is OK at all.
> 
> From my quick testing on imx23 with printk timestamp, it's not OK,
> so we may need to leave imx23 out there.

Hmm, does it wrap after 2 seconds? From my grepping and googling
the code should now adapt itself, the hardcoded limit is gone...
What does the dmesg line such as

  sched_clock: 32 bits at 32kHz, resolution 31250ns,
    wraps every 134217727ms

output on that hardware?

Thanks for the comments, I will resubmit the corrected patch after
waiting ~1,5 days to verify correct wrapping with MX28.

Regards
-- 
                                         Stano

Re: scheduler clock for MXS [Was: Re: Wakeup latency measured with SCHED_TRACER depends on HZ]

[Shawn Guo]

On Mon, Nov 05, 2012 at 10:14:24AM +0100, Stanislav Meduna wrote:
> On 05.11.2012 03:57, Shawn Guo wrote:
> 
> >> The patch in attach fixes this. I can only test the MX28 part -
> >> I don't have any timrot_is_v1() (MX23) hardware and I don't
> >> know whether a source that wraps after ~2 seconds is OK at all.
> > 
> > From my quick testing on imx23 with printk timestamp, it's not OK,
> > so we may need to leave imx23 out there.
> 
I should say it's practically not OK since it wraps in such a short
period.  But it actually works as expected.

> Hmm, does it wrap after 2 seconds?

Yes, it does wrap after ~2 seconds.

> From my grepping and googling
> the code should now adapt itself, the hardcoded limit is gone...
> What does the dmesg line such as
> 
>   sched_clock: 32 bits at 32kHz, resolution 31250ns,
>     wraps every 134217727ms
> 
> output on that hardware?
> 
Yes, something like:

  sched_clock: 16 bits at 32kHz, resolution 31250ns, wraps every 2047ms

Shawn

Re: scheduler clock for MXS [Was: Re: Wakeup latency measured with SCHED_TRACER depends on HZ]

[Stanislav Meduna]

On 05.11.2012 14:46, Shawn Guo wrote:

>>> From my quick testing on imx23 with printk timestamp, it's not OK,
>>> so we may need to leave imx23 out there.
>>
> I should say it's practically not OK since it wraps in such a short
> period.  But it actually works as expected.
> 
>> Hmm, does it wrap after 2 seconds?
> 
> Yes, it does wrap after ~2 seconds.

This is weird. AFAIK the printk should be using sched_clock(),
which is a weak symbol overridden in arch/arm/kernel/sched_clock.c
and it should take care of the extension to never-ever-wrapping
64-bit timestamp. Looks that it does not and if it does not,
I think there is more to be worried of than just printk timestamps.

I don't see anything wrong with the code; bumping the 64-bit
part so that it is no more than wrap time away should take
place in sched_clock_timer which is called at 90% of the
time interval.

BTW this patch deserves IMHO looking at
  https://patchwork.kernel.org/patch/1193631/
but it is probably not the problem here.

In case it matters I'm working with the current 3.4 with
RT patches (none of them touches arch/arm/mach-mxs) - sorry
not to mention it earlier, I forgot to write it again after
I included additional mailing lists to the discussion.


Regards
-- 
                                            Stano

Re: scheduler clock for MXS [Was: Re: Wakeup latency measured with SCHED_TRACER depends on HZ]

[Russell King - ARM Linux]

On Mon, Nov 05, 2012 at 05:09:13PM +0100, Stanislav Meduna wrote:
> On 05.11.2012 14:46, Shawn Guo wrote:
> 
> >>> From my quick testing on imx23 with printk timestamp, it's not OK,
> >>> so we may need to leave imx23 out there.
> >>
> > I should say it's practically not OK since it wraps in such a short
> > period.  But it actually works as expected.
> > 
> >> Hmm, does it wrap after 2 seconds?
> > 
> > Yes, it does wrap after ~2 seconds.
> 
> This is weird. AFAIK the printk should be using sched_clock(),
> which is a weak symbol overridden in arch/arm/kernel/sched_clock.c
> and it should take care of the extension to never-ever-wrapping
> 64-bit timestamp. Looks that it does not and if it does not,
> I think there is more to be worried of than just printk timestamps.

It most certainly does handle the wrapping correctly - it was designed
to from the very start.

> BTW this patch deserves IMHO looking at
>   https://patchwork.kernel.org/patch/1193631/
> but it is probably not the problem here.

Yes, that patch is probably required... if an update to the sched_clock
epoch happens on a different CPU, then the epoch cycles can be in advance
of the read clock cycle value.  That needs to get into my patch system.

Re: scheduler clock for MXS [Was: Re: Wakeup latency measured with SCHED_TRACER depends on HZ]

[Shawn Guo]

On Mon, Nov 05, 2012 at 10:28:59PM +0000, Russell King - ARM Linux wrote:
> On Mon, Nov 05, 2012 at 05:09:13PM +0100, Stanislav Meduna wrote:
> > On 05.11.2012 14:46, Shawn Guo wrote:
> > 
> > >>> From my quick testing on imx23 with printk timestamp, it's not OK,
> > >>> so we may need to leave imx23 out there.
> > >>
> > > I should say it's practically not OK since it wraps in such a short
> > > period.  But it actually works as expected.
> > > 
> > >> Hmm, does it wrap after 2 seconds?
> > > 
> > > Yes, it does wrap after ~2 seconds.
> > 
> > This is weird. AFAIK the printk should be using sched_clock(),
> > which is a weak symbol overridden in arch/arm/kernel/sched_clock.c
> > and it should take care of the extension to never-ever-wrapping
> > 64-bit timestamp. Looks that it does not and if it does not,
> > I think there is more to be worried of than just printk timestamps.
> 
> It most certainly does handle the wrapping correctly - it was designed
> to from the very start.
> 
> > BTW this patch deserves IMHO looking at
> >   https://patchwork.kernel.org/patch/1193631/
> > but it is probably not the problem here.
> 
> Yes, that patch is probably required... if an update to the sched_clock
> epoch happens on a different CPU, then the epoch cycles can be in advance
> of the read clock cycle value.  That needs to get into my patch system.

Here is the boot log on my imx23 board after applying both Stanislav's
and Katsuki's patches.

[    0.000000] Booting Linux on physical CPU 0
[    0.000000] Linux version 3.7.0-rc1-00012-ga31941d (r65073@S2101-09) (gcc ver
sion 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5) ) #756 Tue Nov 6 10:04:30 CST 2012
[    0.000000] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177
[    0.000000] CPU: VIVT data cache, VIVT instruction cache
[    0.000000] Machine: Freescale i.MX23 (Device Tree), model: Freescale i.MX23
Evaluation Kit
[    0.000000] Memory policy: ECC disabled, Data cache writeback
[    0.000000] On node 0 totalpages: 32768
[    0.000000] free_area_init_node: node 0, pgdat c051ada8, node_mem_map c0a7000
0
[    0.000000]   Normal zone: 256 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 32512 pages, LIFO batch:7
[    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[    0.000000] pcpu-alloc: [0] 0
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pag
es: 32512
[    0.000000] Kernel command line: console=ttyAMA0,115200 debug earlyprintk roo
t=/dev/mmcblk0p3 rw rootwait no_console_suspend
[    0.000000] PID hash table entries: 512 (order: -1, 2048 bytes)
[    0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
[    0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
[    0.000000] Memory: 128MB = 128MB total
[    0.000000] Memory: 119200k/119200k available, 11872k reserved, 0K highmem
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xfff00000 - 0xfffe0000   ( 896 kB)
[    0.000000]     vmalloc : 0xc8800000 - 0xff000000   ( 872 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xc8000000   ( 128 MB)
[    0.000000]     modules : 0xbf000000 - 0xc0000000   (  16 MB)
[    0.000000]       .text : 0xc0008000 - 0xc04bf150   (4829 kB)
[    0.000000]       .init : 0xc04c0000 - 0xc04e29cc   ( 139 kB)
[    0.000000]       .data : 0xc04e4000 - 0xc051d5c0   ( 230 kB)
[    0.000000]        .bss : 0xc051d5e4 - 0xc0a6ce38   (5439 kB)
[    0.000000] SLUB: Genslabs=13, HWalign=32, Order=0-3, MinObjects=0, CPUs=1, N
odes=1
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] of_irq_init: children remain, but no parents
[    0.000000] sched_clock: 16 bits at 32kHz, resolution 31250ns, wraps every 20
47ms
[    0.000000] Console: colour dummy device 80x30
[    0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo
 Molnar
[    0.000000] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.000000] ... MAX_LOCK_DEPTH:          48
[    0.000000] ... MAX_LOCKDEP_KEYS:        8191
[    0.000000] ... CLASSHASH_SIZE:          4096
[    0.000000] ... MAX_LOCKDEP_ENTRIES:     16384
[    0.000000] ... MAX_LOCKDEP_CHAINS:      32768
[    0.000000] ... CHAINHASH_SIZE:          16384
[    0.000000]  memory used by lock dependency info: 3695 kB
[    0.000000]  per task-struct memory footprint: 1152 bytes
[    0.002593] Calibrating delay loop... 113.04 BogoMIPS (lpj=565248)
[    0.091312] pid_max: default: 32768 minimum: 301
[    0.092812] Mount-cache hash table entries: 512
[    0.109875] CPU: Testing write buffer coherency: ok
[    0.114000] Setting up static identity map for 0x4035d718 - 0x4035d770
[    0.135625] devtmpfs: initialized
[    0.147843] pinctrl core: initialized pinctrl subsystem
[    0.159093] regulator-dummy: no parameters
[    0.165000] NET: Registered protocol family 16
[    0.168000] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.204156] gpiochip_add: registered GPIOs 0 to 31 on device: gpio.0
[    0.210968] gpiochip_add: registered GPIOs 32 to 63 on device: gpio.1
[    0.217812] gpiochip_add: registered GPIOs 64 to 95 on device: gpio.2
[    0.240750] Serial: AMBA PL011 UART driver
[    0.244781] 80070000.serial: ttyAMA0 at MMIO 0x80070000 (irq = 129) is a PL01
1 rev2
[    0.592281] console [ttyAMA0] enabled
[    0.656187] bio: create slab <bio-0> at 0
[    0.681406] mxs-dma 80004000.dma-apbh: initialized
[    0.700843] mxs-dma 80024000.dma-apbx: initialized
[    0.707500] of_get_named_gpio_flags exited with status 61
[    0.714750] vddio-sd0: 3300 mV
[    0.722156] SCSI subsystem initialized
[    0.729187] usbcore: registered new interface driver usbfs
[    0.735468] usbcore: registered new interface driver hub
[    0.742250] usbcore: registered new device driver usb
[    0.755250] Advanced Linux Sound Architecture Driver Initialized.
[    0.771875] Switching to clocksource mxs_timer
[    1.108937] NET: Registered protocol family 2
[    1.119687] TCP established hash table entries: 4096 (order: 3, 32768 bytes)
[    1.128125] TCP bind hash table entries: 4096 (order: 5, 147456 bytes)
[    1.143437] TCP: Hash tables configured (established 4096 bind 4096)
[    1.151031] TCP: reno registered
[    1.154437] UDP hash table entries: 256 (order: 2, 20480 bytes)
[    1.161843] UDP-Lite hash table entries: 256 (order: 2, 20480 bytes)
[    1.172031] NET: Registered protocol family 1
[    1.183812] RPC: Registered named UNIX socket transport module.
[    1.190093] RPC: Registered udp transport module.
[    1.194906] RPC: Registered tcp transport module.
[    1.200656] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    1.211156] NetWinder Floating Point Emulator V0.97 (double precision)
[    1.360156] NFS: Registering the id_resolver key type
[    1.367843] Key type id_resolver registered
[    1.372156] Key type id_legacy registered
[    1.377000] msgmni has been set to 232
[    1.392187] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 2
52)
[    1.400312] io scheduler noop registered (default)
[    1.415281] of_get_named_gpio_flags exited with status 50
[    1.451406] Console: switching to colour frame buffer device 60x17
[    1.468312] mxsfb 80030000.lcdif: initialized
[    1.475156] uart-pl011 80070000.serial: no DMA platform data
[    1.483500] 8006c000.serial: ttyAPP0 at MMIO 0x8006c000 (irq = 126) is a 8006
c000.serial
[    1.494343] mxs-auart 8006c000.serial: Found APPUART 3.0.0
[    1.514343] gpmi-nand 8000c000.gpmi-nand: driver registration failed: -12
[    1.521781] gpmi-nand: probe of 8000c000.gpmi-nand failed with error -12
[    1.531500] Initializing USB Mass Storage driver...
[    1.537593] usbcore: registered new interface driver usb-storage
[    1.543687] USB Mass Storage support registered.
[    1.554500] mousedev: PS/2 mouse device common for all mice
[    1.567562] stmp3xxx-rtc 8005c000.rtc: rtc core: registered 8005c000.rtc as r
tc0
[    1.575875] i2c /dev entries driver
[    1.586375] of_get_named_gpio_flags exited with status 62
[    1.627437] mxs-mmc 80010000.ssp: initialized
[    1.647250] usbcore: registered new interface driver usbhid
[    1.653125] usbhid: USB HID core driver
[    1.675562] TCP: cubic registered
[    1.679500] NET: Registered protocol family 17
[    1.688500] Key type dns_resolver registered
[    1.707781] registered taskstats version 1
[    1.714531] stmp3xxx-rtc 8005c000.rtc: setting system clock to 1970-01-01 00:
02:53 UTC (173)
[    1.767593] ALSA device list:
[    1.770625]   No soundcards found.
[    1.790343] Waiting for root device /dev/mmcblk0p3...
[    1.798468] mmc0: new SD card at address d555
[    1.809625] mmcblk0: mmc0:d555 SD02G 1.89 GiB
[    1.834218]  mmcblk0: p1 p2 p3
[    0.458156] kjournald starting.  Commit interval 5 seconds
[    0.465187] EXT3-fs (mmcblk0p3): warning: maximal mount count reached, runnin
g e2fsck is recommended
[    0.607000] EXT3-fs (mmcblk0p3): using internal journal
[    0.620187] EXT3-fs (mmcblk0p3): recovery complete
[    0.625093] EXT3-fs (mmcblk0p3): mounted filesystem with ordered data mode
[    0.632781] VFS: Mounted root (ext3 filesystem) on device 179:3.
[    0.640718] Freeing init memory: 136K

Re: scheduler clock for MXS [Was: Re: Wakeup latency measured with SCHED_TRACER depends on HZ]

[Russell King - ARM Linux]

On Tue, Nov 06, 2012 at 10:40:54AM +0800, Shawn Guo wrote:
> Here is the boot log on my imx23 board after applying both Stanislav's
> and Katsuki's patches.
> 
> [    0.000000] Booting Linux on physical CPU 0
> [    0.000000] Linux version 3.7.0-rc1-00012-ga31941d (r65073@S2101-09) (gcc ver
> sion 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5) ) #756 Tue Nov 6 10:04:30 CST 2012
> [    0.000000] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177
> [    0.000000] CPU: VIVT data cache, VIVT instruction cache
> [    0.000000] Machine: Freescale i.MX23 (Device Tree), model: Freescale i.MX23
> Evaluation Kit
> [    0.000000] Memory policy: ECC disabled, Data cache writeback
> [    0.000000] On node 0 totalpages: 32768
> [    0.000000] free_area_init_node: node 0, pgdat c051ada8, node_mem_map c0a7000
> 0
> [    0.000000]   Normal zone: 256 pages used for memmap
> [    0.000000]   Normal zone: 0 pages reserved
> [    0.000000]   Normal zone: 32512 pages, LIFO batch:7
> [    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
> [    0.000000] pcpu-alloc: [0] 0
> [    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pag
> es: 32512
> [    0.000000] Kernel command line: console=ttyAMA0,115200 debug earlyprintk roo
> t=/dev/mmcblk0p3 rw rootwait no_console_suspend
> [    0.000000] PID hash table entries: 512 (order: -1, 2048 bytes)
> [    0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
> [    0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
> [    0.000000] Memory: 128MB = 128MB total
> [    0.000000] Memory: 119200k/119200k available, 11872k reserved, 0K highmem
> [    0.000000] Virtual kernel memory layout:
> [    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
> [    0.000000]     fixmap  : 0xfff00000 - 0xfffe0000   ( 896 kB)
> [    0.000000]     vmalloc : 0xc8800000 - 0xff000000   ( 872 MB)
> [    0.000000]     lowmem  : 0xc0000000 - 0xc8000000   ( 128 MB)
> [    0.000000]     modules : 0xbf000000 - 0xc0000000   (  16 MB)
> [    0.000000]       .text : 0xc0008000 - 0xc04bf150   (4829 kB)
> [    0.000000]       .init : 0xc04c0000 - 0xc04e29cc   ( 139 kB)
> [    0.000000]       .data : 0xc04e4000 - 0xc051d5c0   ( 230 kB)
> [    0.000000]        .bss : 0xc051d5e4 - 0xc0a6ce38   (5439 kB)
> [    0.000000] SLUB: Genslabs=13, HWalign=32, Order=0-3, MinObjects=0, CPUs=1, N
> odes=1
> [    0.000000] NR_IRQS:16 nr_irqs:16 16
> [    0.000000] of_irq_init: children remain, but no parents
> [    0.000000] sched_clock: 16 bits at 32kHz, resolution 31250ns, wraps every 20
> 47ms

So where are you setting this up?  My guess is it's after time_init()
has done its stuff.

Re: scheduler clock for MXS [Was: Re: Wakeup latency measured with SCHED_TRACER depends on HZ]

[Shawn Guo]

On Tue, Nov 06, 2012 at 10:12:29AM +0000, Russell King - ARM Linux wrote:
> > [    0.000000] sched_clock: 16 bits at 32kHz, resolution 31250ns, wraps every 20
> > 47ms
> 
> So where are you setting this up?  My guess is it's after time_init()
> has done its stuff.

It gets set up in machine_desc->timer->init() which is called right
in time_init() just before sched_clock_postinit().

Shawn

Re: scheduler clock for MXS [Was: Re: Wakeup latency measured with SCHED_TRACER depends on HZ]

[Russell King - ARM Linux]

On Tue, Nov 06, 2012 at 09:49:50PM +0800, Shawn Guo wrote:
> On Tue, Nov 06, 2012 at 10:12:29AM +0000, Russell King - ARM Linux wrote:
> > > [    0.000000] sched_clock: 16 bits at 32kHz, resolution 31250ns, wraps every 20
> > > 47ms
> > 
> > So where are you setting this up?  My guess is it's after time_init()
> > has done its stuff.
> 
> It gets set up in machine_desc->timer->init() which is called right
> in time_init() just before sched_clock_postinit().

Well.  I just tried an experiment with OMAP4:

[    0.000000] sched_clock: 16 bits at 32kHz, resolution 30517ns, wraps every 1999ms                                                                            

So, this is similar to yours, and there I get:

[    1.945281] ALSA device list:
[    1.948394]   #0: SDP4430
[    1.951324] Waiting 2sec before mounting root device...
[    2.926910] kjournald starting.  Commit interval 5 seconds
[    2.927001] EXT3-fs (mmcblk1p2): warning: maximal mount count reached, running e2fsck is recommended
[    3.041503] EXT3-fs (mmcblk1p2): using internal journal
[    3.051422] EXT3-fs (mmcblk1p2): recovery complete
[    3.056427] EXT3-fs (mmcblk1p2): mounted filesystem with writeback data mode
[    3.063842] VFS: Mounted root (ext3 filesystem) on device 179:26.
[    3.070404] Freeing init memory: 192K

So it appears to be working as designed.

Re: scheduler clock for MXS

[Stanislav Meduna]

On 05.11.2012 23:28, Russell King - ARM Linux wrote:

> It most certainly does handle the wrapping correctly - it was designed
> to from the very start.

I'm not an expert on Linux kernel and its core infrastructure,
but how is the sched_clock_timer armed for the first time
after calling setup_sched_clock?

The explicitely called update_sched_clock() does _not_ arm it.

Shawn: could you try change the
  update_sched_clock();
to
  sched_clock_poll(sched_clock_timer.data);
right after update_sched_clock call in setup_sched_clock?

Regards
-- 
                                    Stano

Re: scheduler clock for MXS

[Russell King - ARM Linux]

On Tue, Nov 06, 2012 at 09:34:39AM +0100, Stanislav Meduna wrote:
> On 05.11.2012 23:28, Russell King - ARM Linux wrote:
> 
> > It most certainly does handle the wrapping correctly - it was designed
> > to from the very start.
> 
> I'm not an expert on Linux kernel and its core infrastructure,
> but how is the sched_clock_timer armed for the first time
> after calling setup_sched_clock?
> 
> The explicitely called update_sched_clock() does _not_ arm it.

Correct, but sched_clock_postinit() does, which is called from time_init().

Re: scheduler clock for MXS

[Shawn Guo]

On Tue, Nov 06, 2012 at 09:34:39AM +0100, Stanislav Meduna wrote:
> Shawn: could you try change the
>   update_sched_clock();
> to
>   sched_clock_poll(sched_clock_timer.data);
> right after update_sched_clock call in setup_sched_clock?
> 
With the change, it still wraps at 2 seconds.

Shawn

Re: scheduler clock for MXS

[Russell King - ARM Linux]

On Tue, Nov 06, 2012 at 09:46:31PM +0800, Shawn Guo wrote:
> On Tue, Nov 06, 2012 at 09:34:39AM +0100, Stanislav Meduna wrote:
> > Shawn: could you try change the
> >   update_sched_clock();
> > to
> >   sched_clock_poll(sched_clock_timer.data);
> > right after update_sched_clock call in setup_sched_clock?
> > 
> With the change, it still wraps at 2 seconds.

And there's no way that such a change could ever go into mainline; it
can mean that the timer is registered into the timer subsystem before
the timer subsystem has been initialised.  That's why we postpone that
part to time_init().

(And it has _always_ been intended that this sched_clock() implementation
would be usable by the time setup_arch() completes...)

Re: scheduler clock for MXS

[Stanislav Meduna]

On 06.11.2012 21:20, Russell King - ARM Linux wrote:

>> With the change, it still wraps at 2 seconds.
> 
> And there's no way that such a change could ever go into mainline; it
> can mean that the timer is registered into the timer subsystem before
> the timer subsystem has been initialised.  That's why we postpone that
> part to time_init().

Sure, I just wanted to quick-check whether it helps or not, this was
not meant as a solution for anything.

This gets interesting. The same code on slightly different hardware
(but using same source files), just 32-bits so it wraps around after
~1,5 days:

sched_clock: 32 bits at 32kHz, resolution 31250ns,
  wraps every 134217727ms

works without problem here:
  [134919.008468] PHY: imx28-fec-1:00 - Link is Up - 100/Full

(134919 > 134217).

The only difference is 32 bits instead of 16 and a different
function to read the hardware.

> Well.  I just tried an experiment with OMAP4:
> [    0.000000] sched_clock: 16 bits at 32kHz, resolution 30517ns,
wraps every 1999ms
> ...
> [    3.070404] Freeing init memory: 192K


OK, so it is not a 16-bit problem either. So where is the
difference? Could it be that HZ / NO_HZ is playing some
tricks here and need to be taken into consideration?

I'll try to artificially limit the counter-reading function
on my hardware to 16 bits and look whether I can also
reproduce this - probably on Thursday or Friday earliest
(busy with other tasks now).

If it works I'll resubmit for only the iMX.28 and someone
who actually has the iMX.23 hardware to experiment with has
to look at it; the best start is probably to start with
comparing it to the working OMAP4. If it does not I'll
try to find the culprit.

Thanks
-- 
                                    Stano

Re: scheduler clock for MXS

[Russell King - ARM Linux]

On Tue, Nov 06, 2012 at 11:30:44PM +0100, Stanislav Meduna wrote:
> On 06.11.2012 21:20, Russell King - ARM Linux wrote:
> > Well.  I just tried an experiment with OMAP4:
> > [    0.000000] sched_clock: 16 bits at 32kHz, resolution 30517ns,
> wraps every 1999ms
> > ...
> > [    3.070404] Freeing init memory: 192K
> 
> 
> OK, so it is not a 16-bit problem either. So where is the
> difference? Could it be that HZ / NO_HZ is playing some
> tricks here and need to be taken into consideration?
> 
> I'll try to artificially limit the counter-reading function
> on my hardware to 16 bits and look whether I can also
> reproduce this - probably on Thursday or Friday earliest
> (busy with other tasks now).
> 
> If it works I'll resubmit for only the iMX.28 and someone
> who actually has the iMX.23 hardware to experiment with has
> to look at it; the best start is probably to start with
> comparing it to the working OMAP4. If it does not I'll
> try to find the culprit.

I wonder if the NO_HZ slack is preventing the sched_clock epoch update
from happening in time.  Hmm.

 * round_jiffies - function to round jiffies to a full second

This is probably it.  With mine, it's a 32.768kHz clock, so limiting
it to 16-bit gives a wrap period of 2 seconds exactly.  We take 10%
off, so the timer would be asked to fire every 1.8s, which would be
rounded up to 2 seconds.  That's a little too close for comfort...

Yours on the other hand:

sched_clock: 16 bits at 32kHz, resolution 31250ns, wraps every 2047ms

says that this timer runs at _exactly_ 32kHz (are you sure?  If this is
generated from a separate 32k crystal oscilator, it's most likely
32.768kHz because that's the standard crystal frequency.  In any case,
this would give a wrap period of just over 2 seconds.

But remember, we take of 10%, so this would give 1843ms.  Jiffy
conversion would give 185 jiffies, and rounded up to a second gives
200 jiffies, so again 2 seconds.

I suspect that your timer _does_ run at approximately 32768kHz, meaning
that it _does_ roll over at 2 second intervals.  But maybe it's trimmed
to be slightly fast or maybe your kernel's idea of time is slightly
slow - either one of which would then give you this effect.

However, either way, rounding 1.8s up to 2s for a 16-bit 32768kHz
counter isn't going to give reliable results.

I think in this case, we need a version of round_jiffies() which _always_
rounds down.  Unfortunately, it doesn't exist.  Thomas?  What are the
options here?

Re: scheduler clock for MXS

[Shawn Guo]

On Tue, Nov 06, 2012 at 10:46:24PM +0000, Russell King - ARM Linux wrote:
> On Tue, Nov 06, 2012 at 11:30:44PM +0100, Stanislav Meduna wrote:
> > On 06.11.2012 21:20, Russell King - ARM Linux wrote:
> > > Well.  I just tried an experiment with OMAP4:
> > > [    0.000000] sched_clock: 16 bits at 32kHz, resolution 30517ns,
> > wraps every 1999ms
> > > ...
> > > [    3.070404] Freeing init memory: 192K
> > 
> > 
> > OK, so it is not a 16-bit problem either. So where is the
> > difference? Could it be that HZ / NO_HZ is playing some
> > tricks here and need to be taken into consideration?
> > 
> > I'll try to artificially limit the counter-reading function
> > on my hardware to 16 bits and look whether I can also
> > reproduce this - probably on Thursday or Friday earliest
> > (busy with other tasks now).
> > 
> > If it works I'll resubmit for only the iMX.28 and someone
> > who actually has the iMX.23 hardware to experiment with has
> > to look at it; the best start is probably to start with
> > comparing it to the working OMAP4. If it does not I'll
> > try to find the culprit.
> 
> I wonder if the NO_HZ slack is preventing the sched_clock epoch update
> from happening in time.  Hmm.
> 
>  * round_jiffies - function to round jiffies to a full second
> 
> This is probably it.  With mine, it's a 32.768kHz clock, so limiting
> it to 16-bit gives a wrap period of 2 seconds exactly.  We take 10%
> off, so the timer would be asked to fire every 1.8s, which would be
> rounded up to 2 seconds.  That's a little too close for comfort...
> 
> Yours on the other hand:
> 
> sched_clock: 16 bits at 32kHz, resolution 31250ns, wraps every 2047ms
> 
> says that this timer runs at _exactly_ 32kHz (are you sure?  If this is

It sources from 24 MHz crystal with a fixed divider 750, so it's
24000000 / 750 = 32000.

Shawn

> generated from a separate 32k crystal oscilator, it's most likely
> 32.768kHz because that's the standard crystal frequency.  In any case,
> this would give a wrap period of just over 2 seconds.
> 
> But remember, we take of 10%, so this would give 1843ms.  Jiffy
> conversion would give 185 jiffies, and rounded up to a second gives
> 200 jiffies, so again 2 seconds.
> 
> I suspect that your timer _does_ run at approximately 32768kHz, meaning
> that it _does_ roll over at 2 second intervals.  But maybe it's trimmed
> to be slightly fast or maybe your kernel's idea of time is slightly
> slow - either one of which would then give you this effect.
> 
> However, either way, rounding 1.8s up to 2s for a 16-bit 32768kHz
> counter isn't going to give reliable results.
> 
> I think in this case, we need a version of round_jiffies() which _always_
> rounds down.  Unfortunately, it doesn't exist.  Thomas?  What are the
> options here?

Re: scheduler clock for MXS

[Stanislav Meduna]

On 06.11.2012 23:46, Russell King - ARM Linux wrote:

>  * round_jiffies - function to round jiffies to a full second
> 
> This is probably it.  With mine, it's a 32.768kHz clock, so limiting
> it to 16-bit gives a wrap period of 2 seconds exactly.  We take 10%
> off, so the timer would be asked to fire every 1.8s, which would be
> rounded up to 2 seconds.  That's a little too close for comfort...

Confirmed.

- if I artificially change my timer code to act as a 16-bit one,
  I get wrap-arounds. Not always, but there are definitely some
  during the bootup (where maybe the tick is sometimes delayed
  a tad more)

- if I then remove the round_jiffies and only leave jiffies +
  wrap_ticks, the wrap-arounds go away

> I think in this case, we need a version of round_jiffies() which _always_
> rounds down.  Unfortunately, it doesn't exist.  Thomas?  What are the
> options here?

What is actually the reason of round_jiffies there? The
http://kernel.org/doc/htmldocs/device-drivers/API-round-jiffies.html
mentions saving power, is it the only one?

I'd probably just leave the round_jiffies out at least for
wrap_ticks < around 16*HZ. Above that the error by possibly
rounding up can be ignored.

There is also a round_jiffies_up - unless I am too tired, as long as
we tick no faster than once per second, subtracting (HZ-1) and rounding
up should be the same as rounding down.

But: is the round_jiffies* safe at all for sub-second precision
at jiffies around 0xffffffff? From quick looking it does a modulo,
0xffffffff % say 250 is 45, the next jiffy is at 0...

Regards
-- 
                                       Stano

Re: scheduler clock for MXS

[Russell King - ARM Linux]

On Thu, Nov 08, 2012 at 10:27:59PM +0100, Stanislav Meduna wrote:
> What is actually the reason of round_jiffies there? The
> http://kernel.org/doc/htmldocs/device-drivers/API-round-jiffies.html
> mentions saving power, is it the only one?
> 
> I'd probably just leave the round_jiffies out at least for
> wrap_ticks < around 16*HZ. Above that the error by possibly
> rounding up can be ignored.
> 
> There is also a round_jiffies_up - unless I am too tired, as long as
> we tick no faster than once per second, subtracting (HZ-1) and rounding
> up should be the same as rounding down.
> 
> But: is the round_jiffies* safe at all for sub-second precision
> at jiffies around 0xffffffff? From quick looking it does a modulo,
> 0xffffffff % say 250 is 45, the next jiffy is at 0...

Well, the idea is to avoid having yet another random thing causing yet
another wakeup from the idle modes.  If you've ever watched a LED
indicating when the kernel is in the idle loop and when it isn't,
you'll know exactly what I'm talking about; your normal Linux system
sits there constantly being kicked out of idle several times a second
while... idle to service various kernel tasks.

We really don't want to add to that; if we get enough of these events
happening at random intervals, we will end up with things like cpu idle
being completely thwarted by stuff like this.

As I have said, what we want is a version of round_jiffies() which
rounds down to something, not up.

[PATCH] ARM: mxs: Setup scheduler clock

[Stanislav Meduna]

[-- Attachment #1: Type: text/plain, Size: 190 bytes --]

Hi,

OK, as the problem with 16-bit fast ticking timer looks to
be more complicated, I'd like to submit the patch for the 32-bit
ones.

Thanks
-- 
                                    Stano


[-- Attachment #2: 0001-ARM-mxs-Setup-scheduler-clock-for-MXS.patch --]
[-- Type: text/plain, Size: 1661 bytes --]

>From 74092cc0217a5bab6f80ee07aa188a54f5792634 Mon Sep 17 00:00:00 2001
From: Stanislav Meduna <stano@meduna.org>
Date: Mon, 8 Nov 2012 23:39:14 +0100
Subject: [PATCH] ARM: mxs: Setup scheduler clock

Setup scheduler clock on ARM MXS platforms with a 32-bit timrot
such as MX.28. This allows the scheduler to use sub-jiffy resolution.

The corresponding change for 16-bit v1 timrots is not possible
at the moment due to rounding issues with clock values wrapping
faster than once per several seconds in the common ARM platform code.

Signed-off-by: Stanislav Meduna <stano@meduna.org>
---
 arch/arm/mach-mxs/timer.c |   10 +++++++++-
 1 files changed, 9 insertions(+), 1 deletions(-)

diff --git a/arch/arm/mach-mxs/timer.c b/arch/arm/mach-mxs/timer.c
index 564a632..4b6e36c 100644
--- a/arch/arm/mach-mxs/timer.c
+++ b/arch/arm/mach-mxs/timer.c
@@ -26,6 +26,7 @@
 #include <linux/clk.h>
 
 #include <asm/mach/time.h>
+#include <asm/sched_clock.h>
 #include <mach/mxs.h>
 #include <mach/common.h>
 
@@ -230,15 +231,22 @@ static struct clocksource clocksource_mxs = {
 	.flags		= CLOCK_SOURCE_IS_CONTINUOUS,
 };
 
+static u32 notrace mxs_read_sched_clock_v2(void)
+{
+	return ~readl_relaxed(mxs_timrot_base + HW_TIMROT_RUNNING_COUNTn(1));
+}
+
 static int __init mxs_clocksource_init(struct clk *timer_clk)
 {
 	unsigned int c = clk_get_rate(timer_clk);
 
 	if (timrot_is_v1())
 		clocksource_register_hz(&clocksource_mxs, c);
-	else
+	else {
 		clocksource_mmio_init(mxs_timrot_base + HW_TIMROT_RUNNING_COUNTn(1),
 			"mxs_timer", c, 200, 32, clocksource_mmio_readl_down);
+		setup_sched_clock(mxs_read_sched_clock_v2, 32, c);
+	}
 
 	return 0;
 }
-- 
1.7.0.4

Re: [PATCH] ARM: mxs: Setup scheduler clock

[Shawn Guo]

On Thu, Nov 08, 2012 at 11:45:45PM +0100, Stanislav Meduna wrote:
> Hi,
> 
> OK, as the problem with 16-bit fast ticking timer looks to
> be more complicated, I'd like to submit the patch for the 32-bit
> ones.
> 
> Thanks
> -- 
>                                     Stano
> 

> From 74092cc0217a5bab6f80ee07aa188a54f5792634 Mon Sep 17 00:00:00 2001
> From: Stanislav Meduna <stano@meduna.org>
> Date: Mon, 8 Nov 2012 23:39:14 +0100
> Subject: [PATCH] ARM: mxs: Setup scheduler clock
> 
> Setup scheduler clock on ARM MXS platforms with a 32-bit timrot
> such as MX.28. This allows the scheduler to use sub-jiffy resolution.
> 
s/MX.28/i.MX28

I fixed it up and applied the patch.  Thanks.

Shawn

> The corresponding change for 16-bit v1 timrots is not possible
> at the moment due to rounding issues with clock values wrapping
> faster than once per several seconds in the common ARM platform code.
> 
> Signed-off-by: Stanislav Meduna <stano@meduna.org>
> ---
>  arch/arm/mach-mxs/timer.c |   10 +++++++++-
>  1 files changed, 9 insertions(+), 1 deletions(-)
> 
> diff --git a/arch/arm/mach-mxs/timer.c b/arch/arm/mach-mxs/timer.c
> index 564a632..4b6e36c 100644
> --- a/arch/arm/mach-mxs/timer.c
> +++ b/arch/arm/mach-mxs/timer.c
> @@ -26,6 +26,7 @@
>  #include <linux/clk.h>
>  
>  #include <asm/mach/time.h>
> +#include <asm/sched_clock.h>
>  #include <mach/mxs.h>
>  #include <mach/common.h>
>  
> @@ -230,15 +231,22 @@ static struct clocksource clocksource_mxs = {
>  	.flags		= CLOCK_SOURCE_IS_CONTINUOUS,
>  };
>  
> +static u32 notrace mxs_read_sched_clock_v2(void)
> +{
> +	return ~readl_relaxed(mxs_timrot_base + HW_TIMROT_RUNNING_COUNTn(1));
> +}
> +
>  static int __init mxs_clocksource_init(struct clk *timer_clk)
>  {
>  	unsigned int c = clk_get_rate(timer_clk);
>  
>  	if (timrot_is_v1())
>  		clocksource_register_hz(&clocksource_mxs, c);
> -	else
> +	else {
>  		clocksource_mmio_init(mxs_timrot_base + HW_TIMROT_RUNNING_COUNTn(1),
>  			"mxs_timer", c, 200, 32, clocksource_mmio_readl_down);
> +		setup_sched_clock(mxs_read_sched_clock_v2, 32, c);
> +	}
>  
>  	return 0;
>  }
> -- 
> 1.7.0.4
>