qemu sparc64 runtime crashes in -next

qemu sparc64 runtime crashes in -next

[Guenter Roeck]

Hi,

my sparc qemu tests started failing with next-20170613.
Log output is not very helpful:

Unhandled Exception 0x0000000000000028
PC = 0x00000000004620f4 NPC = 0x00000000004620f8
Stopping execution

It looks like 0x00000000004620f4 is in init_tick_ops().

Bisect points to commit 'sparc64: improve modularity tick options'.
Bisect log is attached.

No idea if this is a qemu problem. If you think it is, anything to help
tracking it down would be appreciated.

Thanks,
Guenter

---
# bad: [b14746170b0684005bab3e07893e6b91baf7dbf6] Add linux-next specific files for 20170614
# good: [32c1431eea4881a6b17bd7c639315010aeefa452] Linux 4.12-rc5
git bisect start 'HEAD' 'v4.12-rc5'
# bad: [0500b956eedb4686b0420308ae01a74b00f9ab64] Merge remote-tracking branch 'crypto/master'
git bisect bad 0500b956eedb4686b0420308ae01a74b00f9ab64
# bad: [411b0d31eb697ad647513baf4d109bfec102d88d] Merge remote-tracking branch 'jc_docs/docs-next'
git bisect bad 411b0d31eb697ad647513baf4d109bfec102d88d
# good: [17ea634b46f1ed3e6e7910ed9de81bdc27c472a1] Merge remote-tracking branch 'sunxi/sunxi/for-next'
git bisect good 17ea634b46f1ed3e6e7910ed9de81bdc27c472a1
# bad: [2a0cc43ce1f9d76cf438855fd0e526cdb277a5a9] Merge remote-tracking branch 'btrfs-kdave/for-next'
git bisect bad 2a0cc43ce1f9d76cf438855fd0e526cdb277a5a9
# good: [09c98ed29a43211c59b986ac6190695aaacfa220] Merge remote-tracking branch 'powerpc/next'
git bisect good 09c98ed29a43211c59b986ac6190695aaacfa220
# good: [34e4c9c048aa3ed9b13f357bc15ad4870fc6f2ae] Merge branch 'ext/syue/dir-item-checks-wip' into for-next-next-v4.13-20170605
git bisect good 34e4c9c048aa3ed9b13f357bc15ad4870fc6f2ae
# good: [bb3cc9791ff3a10bb214585cbe9a6d8713e1ba7d] Merge remote-tracking branch 's390/features'
git bisect good bb3cc9791ff3a10bb214585cbe9a6d8713e1ba7d
# bad: [169ca4894ea4b491d95d9cfe7350eceb08f72243] Merge remote-tracking branch 'tile/master'
git bisect bad 169ca4894ea4b491d95d9cfe7350eceb08f72243
# good: [0abdfaf4a95435c0197603a262149019ca2f448d] Merge branch 'sparc64-LDC-changes-for-porting-VCC-driver-into-upstream-kernel'
git bisect good 0abdfaf4a95435c0197603a262149019ca2f448d
# bad: [4929c83a6ce6584cb64381bf1407c487f67d588a] sparc64: add hot-patched and inlined get_tick()
git bisect bad 4929c83a6ce6584cb64381bf1407c487f67d588a
# good: [b5dd4d807f0fe7da67c5cc67b2ec681b60e4994b] sparc64: show time stamps from zero
git bisect good b5dd4d807f0fe7da67c5cc67b2ec681b60e4994b
# bad: [89108c3423e8047cd0da73182ea09b9da190b57e] sparc64: improve modularity tick options
git bisect bad 89108c3423e8047cd0da73182ea09b9da190b57e
# good: [178bf2b9a20e866677bbca5cb521b09a8498c1d7] sparc64: optimize loads in clock_sched()
git bisect good 178bf2b9a20e866677bbca5cb521b09a8498c1d7
# first bad commit: [89108c3423e8047cd0da73182ea09b9da190b57e] sparc64: improve modularity tick options

Re: qemu sparc64 runtime crashes in -next

[David Miller]

From: Guenter Roeck <linux@roeck-us.net>
Date: Wed, 14 Jun 2017 03:13:54 -0700

> Hi,
> 
> my sparc qemu tests started failing with next-20170613.
> Log output is not very helpful:
> 
> Unhandled Exception 0x0000000000000028
> PC = 0x00000000004620f4 NPC = 0x00000000004620f8
> Stopping execution
> 
> It looks like 0x00000000004620f4 is in init_tick_ops().
> 
> Bisect points to commit 'sparc64: improve modularity tick options'.
> Bisect log is attached.
> 
> No idea if this is a qemu problem. If you think it is, anything to
> help
> tracking it down would be appreciated.

Pavel, please look into this.

It looks weird that the commit it bisects to would cause a problem.
Maybe the change from __read_mostly to __cachelin_aligned causes the
issue?

Really weird...

Re: qemu sparc64 runtime crashes in -next

[Guenter Roeck]

On Wed, Jun 14, 2017 at 03:31:08PM -0400, David Miller wrote:
> From: Guenter Roeck <linux@roeck-us.net>
> Date: Wed, 14 Jun 2017 03:13:54 -0700
> 
> > Hi,
> > 
> > my sparc qemu tests started failing with next-20170613.
> > Log output is not very helpful:
> > 
> > Unhandled Exception 0x0000000000000028
> > PC = 0x00000000004620f4 NPC = 0x00000000004620f8
> > Stopping execution
> > 
> > It looks like 0x00000000004620f4 is in init_tick_ops().
> > 
> > Bisect points to commit 'sparc64: improve modularity tick options'.
> > Bisect log is attached.
> > 
> > No idea if this is a qemu problem. If you think it is, anything to
> > help
> > tracking it down would be appreciated.
> 
> Pavel, please look into this.
> 
> It looks weird that the commit it bisects to would cause a problem.
> Maybe the change from __read_mostly to __cachelin_aligned causes the
> issue?
> 
> Really weird...

Turns out tick_get_frequency() returns 0. The value is used as divisor
in clocksource_hz2mult().

Looking into it further, clock_tick is initialized much later.

[    0.000000] clock_tick is 0
	-> tick_get_frequency()
[    0.039361] PROMLIB: Sun IEEE Boot Prom 'OBP 3.10.24 1999/01/01 01:01'
[    0.041646] PROMLIB: Root node compatible: sun4u
[    0.060500] Linux version 4.12.0-rc5-next-20170614+ (groeck@mars) (gcc version 4.6.3 (GCC) ) #5 SMP Wed Jun 14 13:40:01 PDT 2017
[    0.893475] bootconsole [earlyprom0] enabled
[    0.958658] ARCH: SUN4U
[    1.265007] Ethernet address: 52:54:00:12:34:56
[    1.340458] MM: PAGE_OFFSET is 0xfffff80000000000 (max_phys_bits == 40)
[    1.405302] MM: VMALLOC [0x0000000100000000 --> 0x0000060000000000]
[    1.468992] MM: VMEMMAP [0x0000060000000000 --> 0x00000c0000000000]
[    3.349070] Kernel: Using 5 locked TLB entries for main kernel image.
[    3.422093] Remapping the kernel... 
[    4.342159] done.
[  136.231664] OF stdout device is: /pci@1fe,0/ebus@3/su
[  136.298896] PROM: Built device tree with 60466 bytes of memory.
[  136.458520] Top of RAM: 0x1fe80000, Total RAM: 0x1fe80000
[  136.520487] Memory hole size: 0MB
[  143.705871] Allocated 16384 bytes for kernel page tables.
[  143.972916] Zone ranges:
[  144.039046]   Normal   [mem 0x0000000000000000-0x000000001fe7ffff]
[  144.118654] Movable zone start for each node
[  144.180797] Early memory node ranges
[  144.240870]   node   0: [mem 0x0000000000000000-0x000000001fe7ffff]
[  144.333686] Initmem setup node 0 [mem 0x0000000000000000-0x000000001fe7ffff]
[  144.943918] Booting Linux...
[  145.010966] CPU CAPS: [flush,stbar,swap,muldiv,v9,mul32,div32,v8plus]
[  145.082225] CPU CAPS: [vis]
[  145.581394] percpu: Embedded 12 pages/cpu @fffff8001f800000 s57024 r8192 d33088 u4194304
[  145.949412] ###################### fill_in_one_cpu(): CPU 0 clock tick set to 100000000

That doesn't really take 145 seconds, though :-).

Guenter

Re: qemu sparc64 runtime crashes in -next

[Pasha Tatashin]

I think I know the problem, and working on a fix. Will send it out soon.

Thank you,
Pasha

On 06/14/2017 04:42 PM, Guenter Roeck wrote:
> On Wed, Jun 14, 2017 at 03:31:08PM -0400, David Miller wrote:
>> From: Guenter Roeck <linux@roeck-us.net>
>> Date: Wed, 14 Jun 2017 03:13:54 -0700
>>
>>> Hi,
>>>
>>> my sparc qemu tests started failing with next-20170613.
>>> Log output is not very helpful:
>>>
>>> Unhandled Exception 0x0000000000000028
>>> PC = 0x00000000004620f4 NPC = 0x00000000004620f8
>>> Stopping execution
>>>
>>> It looks like 0x00000000004620f4 is in init_tick_ops().
>>>
>>> Bisect points to commit 'sparc64: improve modularity tick options'.
>>> Bisect log is attached.
>>>
>>> No idea if this is a qemu problem. If you think it is, anything to
>>> help
>>> tracking it down would be appreciated.
>>
>> Pavel, please look into this.
>>
>> It looks weird that the commit it bisects to would cause a problem.
>> Maybe the change from __read_mostly to __cachelin_aligned causes the
>> issue?
>>
>> Really weird...
> 
> Turns out tick_get_frequency() returns 0. The value is used as divisor
> in clocksource_hz2mult().
> 
> Looking into it further, clock_tick is initialized much later.
> 
> [    0.000000] clock_tick is 0
> 	-> tick_get_frequency()
> [    0.039361] PROMLIB: Sun IEEE Boot Prom 'OBP 3.10.24 1999/01/01 01:01'
> [    0.041646] PROMLIB: Root node compatible: sun4u
> [    0.060500] Linux version 4.12.0-rc5-next-20170614+ (groeck@mars) (gcc version 4.6.3 (GCC) ) #5 SMP Wed Jun 14 13:40:01 PDT 2017
> [    0.893475] bootconsole [earlyprom0] enabled
> [    0.958658] ARCH: SUN4U
> [    1.265007] Ethernet address: 52:54:00:12:34:56
> [    1.340458] MM: PAGE_OFFSET is 0xfffff80000000000 (max_phys_bits == 40)
> [    1.405302] MM: VMALLOC [0x0000000100000000 --> 0x0000060000000000]
> [    1.468992] MM: VMEMMAP [0x0000060000000000 --> 0x00000c0000000000]
> [    3.349070] Kernel: Using 5 locked TLB entries for main kernel image.
> [    3.422093] Remapping the kernel...
> [    4.342159] done.
> [  136.231664] OF stdout device is: /pci@1fe,0/ebus@3/su
> [  136.298896] PROM: Built device tree with 60466 bytes of memory.
> [  136.458520] Top of RAM: 0x1fe80000, Total RAM: 0x1fe80000
> [  136.520487] Memory hole size: 0MB
> [  143.705871] Allocated 16384 bytes for kernel page tables.
> [  143.972916] Zone ranges:
> [  144.039046]   Normal   [mem 0x0000000000000000-0x000000001fe7ffff]
> [  144.118654] Movable zone start for each node
> [  144.180797] Early memory node ranges
> [  144.240870]   node   0: [mem 0x0000000000000000-0x000000001fe7ffff]
> [  144.333686] Initmem setup node 0 [mem 0x0000000000000000-0x000000001fe7ffff]
> [  144.943918] Booting Linux...
> [  145.010966] CPU CAPS: [flush,stbar,swap,muldiv,v9,mul32,div32,v8plus]
> [  145.082225] CPU CAPS: [vis]
> [  145.581394] percpu: Embedded 12 pages/cpu @fffff8001f800000 s57024 r8192 d33088 u4194304
> [  145.949412] ###################### fill_in_one_cpu(): CPU 0 clock tick set to 100000000
> 
> That doesn't really take 145 seconds, though :-).
> 
> Guenter
>