Wakeup latency measured with SCHED_TRACER depends on HZ

PATCH New Stanislav Meduna 3 participants 22 messages Oct 31, 2012 – Nov 12, 2012

Subsystems (3)

Arm (32-bit) Arm sub-architectures Arm i.MX and Layerscape

lore

Share & tools

lore

Stanislav Meduna

author

2012-10-31 21:41 UTC #0 lore raw

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

Signature · 1 line

                                    Stano

Stanislav Meduna

author

2012-11-02 14:30 UTC #1 lore raw

Quoted 3 lines · Stanislav Meduna

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

Signature · 1 line

                                      Stano

Quoted 1 line

From ddeed3c83d48e8ce33b36bd964572756354e7feb Mon Sep 17 00:00:00 2001

From: Stanislav Meduna <[email protected]>
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(-)

arch/arm/mach-mxs/timer.c +19 -0

index 564a632..0ab86a2 100644
@@ -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);
 }

Signature · 1 line

1.7.0.4

Shawn Guo

2012-11-05 02:32 UTC #2 lore raw

Quoted 6 lines · Stanislav Meduna

Quoted 3 lines · Stanislav Meduna
on an embedded platform using a Freescale i.MX28 ARM processor I am experiencing a strange phenomenon - the latencies reported are dependent of HZ

Quoted 8 lines

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.

Quoted 2 lines

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

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

Quoted 12 lines

(only to linux-rt-users).

Regards

Signature · 7 lines

                                      Stano


From ddeed3c83d48e8ce33b36bd964572756354e7feb Mon Sep 17 00:00:00 2001
From: Stanislav Meduna <[email protected]>
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.

Quoted 35 lines

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

arch/arm/mach-mxs/timer.c +11 -0

index 564a632..0ab86a2 100644
@@ -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);

arch/arm/mach-mxs/timer.c void __init mxs_timer_init(struct clk *timer_clk, int irq) · line 306

Quoted 10 lines

arch/arm/mach-mxs/timer.c +8 -0

 	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

Quoted 6 lines

arch/arm/mach-mxs/timer.c +0 -0
 	/* Make irqs happen */
 	setup_irq(irq, &mxs_timer_irq);
 }
Signature · 1 line
1.7.0.4

Stanislav Meduna

author

2012-11-05 09:14 UTC #3 lore raw

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

Quoted 6 lines · Shawn Guo

Quoted 3 lines
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

Signature · 1 line

                                         Stano

Shawn Guo

2012-11-05 13:21 UTC #4 lore raw

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

Quoted 9 lines · Stanislav Meduna

Quoted 6 lines · Shawn Guo
Quoted 3 lines
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.

Quoted 1 line

Hmm, does it wrap after 2 seconds?

Yes, it does wrap after ~2 seconds.

Quoted 9 lines

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

Stanislav Meduna

author

2012-11-05 16:09 UTC #5 lore raw

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

Quoted 9 lines · Shawn Guo

Quoted 3 lines
Quoted 2 lines
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.
Quoted 1 line
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

Signature · 1 line

                                            Stano

Russell King - ARM Linux

2012-11-05 22:28 UTC #6 lore raw

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

Quoted 10 lines · Stanislav Meduna

Quoted 8 lines · Shawn Guo
Quoted 3 lines
Quoted 2 lines
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.
Quoted 1 line
Hmm, does it wrap after 2 seconds?

Quoted 7 lines

Quoted 1 line
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.

Quoted 3 lines

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.

Shawn Guo

2012-11-06 02:15 UTC #7 lore raw

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

Quoted 22 lines · Russell King - ARM Linux

Quoted 10 lines · Stanislav Meduna
Quoted 8 lines · Shawn Guo
Quoted 3 lines
Quoted 2 lines
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.
Quoted 1 line
Hmm, does it wrap after 2 seconds?
Quoted 7 lines
Quoted 1 line
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.

Quoted 7 lines

Quoted 3 lines
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

Russell King - ARM Linux

2012-11-06 10:12 UTC #8 lore raw

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

Quoted 43 lines · Shawn Guo

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 at 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

Quoted 1 line

47ms

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

Shawn Guo

2012-11-06 13:24 UTC #9 lore raw

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

Quoted 5 lines · Russell King - ARM Linux

Quoted 2 lines
[    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

Russell King - ARM Linux

2012-11-06 20:04 UTC #10 lore raw

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

Quoted 9 lines · Shawn Guo

Quoted 5 lines · Russell King - ARM Linux
Quoted 2 lines
[    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.

Stanislav Meduna

author

2012-11-06 08:34 UTC #11 lore raw

scheduler clock for MXS

In reply to Russell King - ARM Linux

Quoted 2 lines · Russell King - ARM Linux

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

Signature · 1 line

                                    Stano

Russell King - ARM Linux

2012-11-06 09:45 UTC #12 lore raw

scheduler clock for MXS

Quoted 10 lines · Stanislav Meduna

Quoted 2 lines · Russell King - ARM Linux
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().

Shawn Guo

2012-11-06 13:21 UTC #13 lore raw

scheduler clock for MXS

In reply to Stanislav Meduna

Quoted 6 lines · Stanislav Meduna

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

Russell King - ARM Linux

2012-11-06 20:20 UTC #14 lore raw

scheduler clock for MXS

Quoted 8 lines · Shawn Guo

Quoted 6 lines · Stanislav Meduna
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...)

Stanislav Meduna

author

2012-11-06 22:30 UTC #15 lore raw

scheduler clock for MXS

Quoted 6 lines · Russell King - ARM Linux

Quoted 1 line
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.

Quoted 2 lines

Well. I just tried an experiment with OMAP4:
[    0.000000] sched_clock: 16 bits at 32kHz, resolution 30517ns,

wraps every 1999ms

Quoted 2 lines

...

[    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

Signature · 1 line

                                    Stano

Russell King - ARM Linux

2012-11-06 22:46 UTC #16 lore raw

scheduler clock for MXS

Quoted 17 lines · Stanislav Meduna

Quoted 2 lines · Russell King - ARM Linux
Well. I just tried an experiment with OMAP4:
[    0.000000] sched_clock: 16 bits at 32kHz, resolution 30517ns,
wraps every 1999ms
Quoted 2 lines
...
[    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).

Quoted 5 lines

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?

Shawn Guo

2012-11-07 06:47 UTC #17 lore raw

scheduler clock for MXS

Quoted 34 lines · Russell King - ARM Linux

Quoted 17 lines · Stanislav Meduna
Quoted 2 lines · Russell King - ARM Linux
Well. I just tried an experiment with OMAP4:
[    0.000000] sched_clock: 16 bits at 32kHz, resolution 30517ns,
wraps every 1999ms
Quoted 2 lines
...
[    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).
Quoted 5 lines
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...

Quoted 5 lines

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

Quoted 19 lines

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?

Stanislav Meduna

author

2012-11-08 21:27 UTC #18 lore raw

scheduler clock for MXS

In reply to Russell King - ARM Linux

Quoted 6 lines · Russell King - ARM Linux

* 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

Quoted 3 lines

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@0...

Regards

Signature · 1 line

                                       Stano

Russell King - ARM Linux

2012-11-08 22:11 UTC #19 lore raw

scheduler clock for MXS

Quoted 8 lines · Stanislav Meduna

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.

Quoted 7 lines

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.

Stanislav Meduna

author

2012-11-08 22:45 UTC #20 lore raw

PATCH 1/1 ARM: mxs: Setup scheduler clock

In reply to Shawn Guo

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

Signature · 3 lines

                                    Stano

-------------- next part --------------

Quoted 1 line

From 74092cc0217a5bab6f80ee07aa188a54f5792634 Mon Sep 17 00:00:00 2001

From: Stanislav Meduna <[email protected]>
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 <[email protected]>

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

arch/arm/mach-mxs/timer.c +9 -1

index 564a632..4b6e36c 100644
@@ -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;
 }

Signature · 1 line

1.7.0.4

Shawn Guo

2012-11-12 01:28 UTC #21 lore raw

PATCH 1/1 ARM: mxs: Setup scheduler clock

Quoted 19 lines · Stanislav Meduna

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

Signature · 10 lines

                                    Stano

From 74092cc0217a5bab6f80ee07aa188a54f5792634 Mon Sep 17 00:00:00 2001
From: Stanislav Meduna <[email protected]>
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

Quoted 48 lines

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 <[email protected]>

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

arch/arm/mach-mxs/timer.c +9 -1

index 564a632..4b6e36c 100644
@@ -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;
 }

Signature · 1 line

1.7.0.4