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:

quoted

On 05.11.2012 14:46, Shawn Guo wrote:

quoted

quoted

quoted

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

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.

quoted

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