Message-ID: <20141122184506.GC29361@wfg-t540p.sh.intel.com>
Date:	Sat, 22 Nov 2014 10:45:06 -0800
From:	Fengguang Wu <fengguang.wu@...el.com>
To:	"pang.xunlei" <pang.xunlei@...aro.org>
Cc:	John Stultz <john.stultz@...aro.org>, LKP <lkp@...org>,
	linux-kernel@...r.kernel.org
Subject: [time] WARNING: CPU: 0 PID: 1 at kernel/time/timekeeping.c:1337
 update_wall_time()

Greetings,

0day kernel testing robot got the below dmesg and the first bad commit is

https://git.linaro.org/people/john.stultz/linux.git fortglx/3.19/time

commit 59fa38d60ca4bc7a2efffae1b40aa7960374ef9d
Author:     pang.xunlei <pang.xunlei@...aro.org>
AuthorDate: Wed Oct 8 15:03:34 2014 +0800
Commit:     John Stultz <john.stultz@...aro.org>
CommitDate: Thu Oct 23 21:26:24 2014 -0700

    time: Avoid possible NTP adjustment mult overflow.
    
    Ideally, __clocksource_updatefreq_scale, selects the largest shift
    value possible for a clocksource. This results in the mult memember of
    struct clocksource being particularly large, although not so large
    that NTP would adjust the clock to cause it to overflow.
    
    That said, nothing actually prohibits an overflow from occuring, its
    just that it "shouldn't" occur.
    
    So while very unlikely, and so far never observed, the value of
    (cs->mult+cs->maxadj) may have a chance to reach very near 0xFFFFFFFF,
    so there is a possibility it may overflow when doing NTP positive
    adjustment
    
    See the following detail: When NTP slewes the clock, kernel goes
    through update_wall_time()->...->timekeeping_apply_adjustment():
    	tk->tkr.mult += mult_adj;
    
    Since there is no guard against it, its possible tk->tkr.mult may
    overflow during this operation.
    
    This patch avoids any possible mult overflow by judging the overflow
    case before adding mult_adj to mult, also adds the WARNING message
    when capturing such case.
    
    Signed-off-by: pang.xunlei <pang.xunlei@...aro.org>
    [jstultz: Reworded commit message]
    Signed-off-by: John Stultz <john.stultz@...aro.org>

+---------------------------------------------------------+------------+------------+------------+
|                                                         | 3953d54968 | 59fa38d60c | 2ad4af7852 |
+---------------------------------------------------------+------------+------------+------------+
| boot_successes                                          | 83         | 0          | 0          |
| boot_failures                                           | 0          | 11         | 11         |
| WARNING:at_kernel/time/timekeeping.c:update_wall_time() | 0          | 11         | 11         |
| backtrace:acpi_get_devices                              | 0          | 8          | 10         |
| backtrace:pnpacpi_init                                  | 0          | 8          | 11         |
| backtrace:kernel_init_freeable                          | 0          | 11         | 11         |
| backtrace:apic_timer_interrupt                          | 0          | 1          |            |
| backtrace:pci_apply_final_quirks                        | 0          | 1          |            |
| backtrace:__udelay                                      | 0          | 1          |            |
| backtrace:init_acpi_pm_clocksource                      | 0          | 1          |            |
| backtrace:printk                                        | 0          | 0          | 1          |
+---------------------------------------------------------+------------+------------+------------+

[    0.241516] IOAPIC[0]: Set routing entry (0-7 -> 0x37 -> IRQ 7 Mode:0 Active:0 Dest:1)
[    0.243122] pnp 00:04: Plug and Play ACPI device, IDs PNP0400 (active)
[    0.243383] ------------[ cut here ]------------
[    0.243383] WARNING: CPU: 0 PID: 1 at kernel/time/timekeeping.c:1337 update_wall_time+0x4c4/0x604()
[    0.243383] Modules linked in:
[    0.243383] CPU: 0 PID: 1 Comm: swapper Not tainted 3.18.0-rc1-00274-g59fa38d #910
[    0.243383]  00000000 00000000 80017b2c 8138aefc 80017b48 81036c2a 00000539 81066a6e
[    0.243383]  00000000 002aaaaa 00000000 80017b58 81036ca5 00000009 00000000 80017b84
[    0.243383]  81066a6e 00000086 0032dcd5 00000000 00000009 0014ec06 00000000 00000000
[    0.243383] Call Trace:
[    0.243383]  [<8138aefc>] dump_stack+0x16/0x18
[    0.243383]  [<81036c2a>] warn_slowpath_common+0x5c/0x73
[    0.243383]  [<81066a6e>] ? update_wall_time+0x4c4/0x604
[    0.243383]  [<81036ca5>] warn_slowpath_null+0xf/0x13
[    0.243383]  [<81066a6e>] update_wall_time+0x4c4/0x604
[    0.243383]  [<8106b908>] tick_sched_timer+0x13f/0x1a2
[    0.243383]  [<81061bee>] __run_hrtimer+0x4b/0xb3
[    0.243383]  [<8106b7c9>] ? write_seqcount_begin+0x25/0x25
[    0.243383]  [<81061dbd>] hrtimer_interrupt+0xe6/0x20a
[    0.243383]  [<810234d3>] local_apic_timer_interrupt+0x3c/0x3e
[    0.243383]  [<81023842>] smp_apic_timer_interrupt+0x1e/0x2c
[    0.243383]  [<81390c39>] apic_timer_interrupt+0x39/0x40
[    0.243383]  [<811b96d7>] ? serial8250_console_write+0x117/0x11f
[    0.243383]  [<811b007b>] ? tty_port_open+0x43/0x99
[    0.243383]  [<81050000>] ? graph_unlock+0x51/0x6e
[    0.243383]  [<81056ac1>] ? arch_local_irq_restore+0x5/0xb
[    0.243383]  [<81058120>] console_unlock+0x31d/0x3c3
[    0.243383]  [<81058555>] vprintk_emit+0x38f/0x39b
[    0.243383]  [<811c645c>] dev_vprintk_emit+0x1a5/0x1be
[    0.243383]  [<81051920>] ? mark_held_locks+0x58/0x6e
[    0.243383]  [<810535db>] ? lock_acquire+0x74/0x7f
[    0.243383]  [<8113144f>] ? string+0x2d/0x97
[    0.243383]  [<811c648a>] dev_printk_emit+0x15/0x17
[    0.243383]  [<811c64d9>] __dev_printk+0x4d/0x58
[    0.243383]  [<811c650a>] dev_printk+0x26/0x28
[    0.243383]  [<81190bab>] pnp_add_device+0xab/0xc9
[    0.243383]  [<810ae1c4>] ? slab_free_hook+0x52/0x57
[    0.243383]  [<810af57a>] ? kfree+0x4d/0x9f
[    0.243383]  [<811874cf>] ? acpi_walk_resources+0x69/0x78
[    0.243383]  [<8164972f>] pnpacpi_add_device_handler+0x1a8/0x1d8
[    0.243383]  [<811837eb>] acpi_ns_get_device_callback+0x113/0x11c
[    0.243383]  [<811834fb>] acpi_ns_walk_namespace+0xad/0x166
[    0.243383]  [<81649520>] ? ispnpidacpi+0x9f/0x9f
[    0.243383]  [<81183622>] acpi_get_devices+0x42/0x60
[    0.243383]  [<811836d8>] ? acpi_walk_namespace+0x98/0x98
[    0.243383]  [<81649587>] ? pnpacpi_init+0x67/0x67
[    0.243383]  [<81649520>] ? ispnpidacpi+0x9f/0x9f
[    0.243383]  [<81649566>] pnpacpi_init+0x46/0x67
[    0.243383]  [<810021c0>] do_one_initcall+0x15e/0x16d
[    0.243383]  [<8162b400>] ? do_early_param+0x14/0x73
[    0.243383]  [<81047257>] ? parse_args+0x197/0x272
[    0.243383]  [<8162bb76>] kernel_init_freeable+0xd6/0x14e
[    0.243383]  [<81388009>] kernel_init+0x8/0xb3
[    0.243383]  [<81390420>] ret_from_kernel_thread+0x20/0x30
[    0.243383]  [<81388001>] ? rest_init+0xa2/0xa2
[    0.243383] ---[ end trace e467c44e628492f6 ]---
[    0.310086] IOAPIC[0]: Set routing entry (0-4 -> 0x34 -> IRQ 4 Mode:0 Active:0 Dest:1)

git bisect start 2ad4af7852fa94e5829a723546cce0d73d44c526 816fb4175c29b16948fb24a92053bea1e79908cc --
git bisect good 3953d54968793e0db56c8a7ffbdedc2ba9cb6d82  # 14:35     20+      0  time: Rename udelay_test.c to test_udelay.c
git bisect  bad 59fa38d60ca4bc7a2efffae1b40aa7960374ef9d  # 14:35      0-     11  time: Avoid possible NTP adjustment mult overflow.
# first bad commit: [59fa38d60ca4bc7a2efffae1b40aa7960374ef9d] time: Avoid possible NTP adjustment mult overflow.
git bisect good 3953d54968793e0db56c8a7ffbdedc2ba9cb6d82  # 14:39     60+      0  time: Rename udelay_test.c to test_udelay.c
git bisect  bad b6adbbd9a2171aa4764ea8a56c4c1a5f63f2cca6  # 14:39      0-      4  Merge commit '039348d8c131329742e80e37122f11d230fd270b' into fortglx/3.19/time
git bisect good fc14f9c1272f62c3e8d01300f52467c0d9af50f9  # 14:43     60+     23  Linux 3.18-rc5
git bisect good 5b83d7ad910674ab8c059f3a5ff9c2b0c0a4b685  # 14:45     60+      0  Add linux-next specific files for 20141120


This script may reproduce the error.

----------------------------------------------------------------------------
#!/bin/bash

kernel=$1
initrd=yocto-minimal-i386.cgz

wget --no-clobber https://github.com/fengguang/reproduce-kernel-bug/raw/master/initrd/$initrd

kvm=(
	qemu-system-x86_64
	-enable-kvm
	-cpu Haswell,+smep,+smap
	-kernel $kernel
	-initrd $initrd
	-m 320
	-smp 1
	-net nic,vlan=1,model=e1000
	-net user,vlan=1
	-boot order=nc
	-no-reboot
	-watchdog i6300esb
	-rtc base=localtime
	-serial stdio
	-display none
	-monitor null 
)

append=(
	hung_task_panic=1
	earlyprintk=ttyS0,115200
	debug
	apic=debug
	sysrq_always_enabled
	rcupdate.rcu_cpu_stall_timeout=100
	panic=-1
	softlockup_panic=1
	nmi_watchdog=panic
	oops=panic
	load_ramdisk=2
	prompt_ramdisk=0
	console=ttyS0,115200
	console=tty0
	vga=normal
	root=/dev/ram0
	rw
	drbd.minor_count=8
)

"${kvm[@]}" --append "${append[*]}"
----------------------------------------------------------------------------

Thanks,
Fengguang

View attachment "dmesg-yocto-kbuild-6:20141121140934:i386-randconfig-ha3-1109:3.18.0-rc1-00274-g59fa38d:910" of type "text/plain" (52749 bytes)

View attachment "config-3.18.0-rc1-00274-g59fa38d" of type "text/plain" (90292 bytes)

_______________________________________________
LKP mailing list
LKP@...ux.intel.com

Powered by blists - more mailing lists