lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Message-ID: <1434424558.18774.198.camel@intel.com>
Date:	Tue, 16 Jun 2015 11:15:58 +0800
From:	Huang Ying <ying.huang@...el.com>
To:	John Stultz <john.stultz@...aro.org>
Cc:	LKML <linux-kernel@...r.kernel.org>, LKP ML <lkp@...org>,
	Huang Ying <ying.huang@...el.com>
Subject: [lkp] [time] 78a0b9a793a: INFO: possible recursive locking detected
 ]

FYI, we noticed the below changes on

https://git.linaro.org/people/john.stultz/linux.git wip
commit 78a0b9a793a36f73a9a3330dec00859e15d9ad6d ("time: Do leapsecond adjustment in gettime fastpaths")


+------------------------------------------+------------+------------+
|                                          | 4ae9e1e25d | 78a0b9a793 |
+------------------------------------------+------------+------------+
| boot_successes                           | 900        | 263        |
| boot_failures                            | 0          | 37         |
| INFO:possible_recursive_locking_detected | 0          | 37         |
| BUG:spinlock_lockup_suspected_on_CPU     | 0          | 15         |
| EIP_is_at_native_apic_mem_write          | 0          | 15         |
| EIP_is_at_read_seqcount_begin            | 0          | 15         |
| backtrace:SYSC_adjtimex                  | 0          | 32         |
| backtrace:SyS_adjtimex                   | 0          | 32         |
| backtrace:vfs_write                      | 0          | 7          |
| backtrace:SyS_write                      | 0          | 7          |
| BUG:kernel_test_hang                     | 0          | 22         |
| backtrace:SYSC_clock_adjtime             | 0          | 5          |
| backtrace:SyS_clock_adjtime              | 0          | 5          |
| backtrace:lru_add_drain_all              | 0          | 1          |
| backtrace:SyS_mlock                      | 0          | 2          |
| backtrace:do_group_exit                  | 0          | 1          |
| backtrace:SyS_exit_group                 | 0          | 1          |
| backtrace:cpu_startup_entry              | 0          | 3          |
| backtrace:__mm_populate                  | 0          | 1          |
| backtrace:link_path_walk                 | 0          | 1          |
| backtrace:path_init                      | 0          | 1          |
| backtrace:do_sys_open                    | 0          | 1          |
| backtrace:SyS_open                       | 0          | 1          |
+------------------------------------------+------------+------------+


[   23.011400] VFS: Warning: trinity-c1 using old stat() call. Recompile your binary.
[   23.012387] 
[   23.012580] =============================================
[   23.013218] [ INFO: possible recursive locking detected ]
[   23.013841] 4.1.0-rc5-01505-gd6201b6 #2 Not tainted
[   23.014419] ---------------------------------------------
[   23.015051] trinity-c1/22948 is trying to acquire lock:
[   23.015657]  (tk_core){----..}, at: [<4107d71c>] timekeeping_get_ns+0x10/0xe8
[   23.016564] 
[   23.016564] but task is already holding lock:
[   23.017241]  (tk_core){----..}, at: [<4107f150>] do_adjtimex+0x58/0xc2
[   23.017380] 
[   23.017380] other info that might help us debug this:
[   23.017380]  Possible unsafe locking scenario:
[   23.017380] 
[   23.017380]        CPU0
[   23.017380]        ----
[   23.017380]   lock(tk_core);
[   23.017380]   lock(tk_core);
[   23.017380] 
[   23.017380]  *** DEADLOCK ***
[   23.017380] 
[   23.017380]  May be due to missing lock nesting notation
[   23.017380] 
[   23.017380] 2 locks held by trinity-c1/22948:
[   23.017380]  #0:  (timekeeper_lock){-.-...}, at: [<4107f144>] do_adjtimex+0x4c/0xc2
[   23.017380]  #1:  (tk_core){----..}, at: [<4107f150>] do_adjtimex+0x58/0xc2
[   23.017380] 
[   23.017380] stack backtrace:
[   23.017380] CPU: 1 PID: 22948 Comm: trinity-c1 Not tainted 4.1.0-rc5-01505-gd6201b6 #2
[   23.017380] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014
[   23.017380]  00000000 00000000 50211ddc 413ce68a 41c6a910 50211e50 410646c2 41551379
[   23.017380]  41551d81 4155126c 00000000 4fc09210 41c6a910 00001f02 00000000 7803e01f
[   23.017380]  00000000 4fc09210 00000000 00000002 4fc09238 4fc08d40 41c506f0 4fc09208
[   23.017380] Call Trace:
[   23.017380]  [<413ce68a>] dump_stack+0x49/0x73
[   23.017380]  [<410646c2>] __lock_acquire+0xb78/0xcd3
[   23.017380]  [<4106414b>] ? __lock_acquire+0x601/0xcd3
[   23.017380]  [<41064ad9>] lock_acquire+0x5b/0x7d
[   23.017380]  [<4107d71c>] ? timekeeping_get_ns+0x10/0xe8
[   23.017380]  [<4107d5f1>] read_seqcount_begin+0x2e/0x74
[   23.017380]  [<4107d71c>] ? timekeeping_get_ns+0x10/0xe8
[   23.017380]  [<4107d71c>] timekeeping_get_ns+0x10/0xe8
[   23.017380]  [<4107f150>] ? do_adjtimex+0x58/0xc2
[   23.017380]  [<4107dabf>] __getnstimeofday64_preleap+0x29/0x5d
[   23.017380]  [<4107f158>] do_adjtimex+0x60/0xc2
[   23.017380]  [<4107aa8e>] posix_clock_realtime_adj+0xa/0xc
[   23.017380]  [<4107af8a>] SYSC_clock_adjtime+0x60/0x92
[   23.017380]  [<4107b732>] SyS_clock_adjtime+0xe/0x10
[   23.017380]  [<413d3aab>] syscall_call+0x7/0x7
[   23.017380]  [<413d0000>] ? do_wait_for_common+0x69/0xe4
[   23.015623] BUG: spinlock lockup suspected on CPU#0, trinity-c0/22947
[   23.015623]  lock: timekeeper_lock+0x0/0x40, .magic: dead4ead, .owner: trinity-c1/22948, .owner_cpu: 1
[   23.015623] CPU: 0 PID: 22947 Comm: trinity-c0 Not tainted 4.1.0-rc5-01505-gd6201b6 #2
[   23.015623] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014
[   23.015623]  00000000 00000000 501f1d54 413ce68a 4fc09040 501f1d80 410674b5 41552af6
[   23.015623]  416204c0 dead4ead 4fc09040 000059a4 00000001 416204c0 a08baba0 00000000
[   23.015623]  501f1dac 4106760a a08baba0 00000000 4162cecd 416204c0 416204d0 501f1dc0
[   23.015623] Call Trace:
[   23.015623]  [<413ce68a>] dump_stack+0x49/0x73
[   23.015623]  [<410674b5>] spin_dump+0x7b/0x86
[   23.015623]  [<4106760a>] do_raw_spin_lock+0xda/0x121
[   23.015623]  [<413d2fd9>] _raw_spin_lock_irqsave+0x54/0x68
[   23.015623]  [<4107e884>] update_wall_time+0x13/0x70f
[   23.015623]  [<41064eb5>] ? lock_release+0x173/0x18a
[   23.015623]  [<41082df4>] tick_periodic+0x7a/0x99
[   23.015623]  [<41082f1e>] ? tick_handle_periodic+0x1c/0x5b
[   23.015623]  [<41082f1e>] tick_handle_periodic+0x1c/0x5b
[   23.015623]  [<41021ff0>] local_apic_timer_interrupt+0x40/0x45
[   23.015623]  [<41022519>] smp_apic_timer_interrupt+0x20/0x2f
[   23.015623]  [<413d448f>] apic_timer_interrupt+0x2f/0x34
[   23.015623]  [<4107d630>] ? read_seqcount_begin+0x6d/0x74
[   23.015623]  [<4107d642>] current_kernel_time+0xb/0x3f
[   23.015623]  [<410789b7>] current_fs_time+0xb/0x19
[   23.015623]  [<410ee0c7>] file_update_time+0x20/0x9b
[   23.015623]  [<410a6c22>] __generic_file_write_iter+0x4b/0x15f
[   23.015623]  [<410a6d7a>] generic_file_write_iter+0x44/0xc5
[   23.015623]  [<410db739>] __vfs_write+0x66/0x8f
[   23.015623]  [<410dbf25>] vfs_write+0x74/0x93
[   23.015623]  [<410dc3f6>] SyS_write+0x4a/0x77
[   23.015623]  [<413d3aab>] syscall_call+0x7/0x7
[   23.015623]  [<413d0000>] ? do_wait_for_common+0x69/0xe4
[   23.015623] sending NMI to all CPUs:
[   23.015623] NMI backtrace for cpu 0
[   23.015623] CPU: 0 PID: 22947 Comm: trinity-c0 Not tainted 4.1.0-rc5-01505-gd6201b6 #2
[   23.015623] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014
[   23.015623] task: 4fc0dcc0 ti: 501f0000 task.ti: 501f0000
[   23.015623] EIP: 0060:[<410230d6>] EFLAGS: 00000046 CPU: 0
[   23.015623] EIP is at native_apic_mem_write+0x12/0x14
[   23.015623] EAX: ffffb300 EBX: 00000c00 ECX: fffff000 EDX: 00000c00
[   23.015623] ESI: 00000002 EDI: 03000000 EBP: 501f1d34 ESP: 501f1d34
[   23.015623]  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
[   23.015623] CR0: 8005003b CR2: 080d3000 CR3: 1016c000 CR4: 00000690
[   23.015623] Stack:
[   23.015623]  501f1d48 41023152 00000006 00000003 00000002 501f1d5c 41023408 416e0880
[   23.015623]  00000001 00000000 501f1d80 41023ead 4154a50e 415701d3 000059a4 00000001
[   23.015623]  416204c0 a08baba0 00000000 501f1dac 41067614 a08baba0 00000000 4162cecd
[   23.015623] Call Trace:
[   23.015623]  [<41023152>] __default_send_IPI_dest_field+0x49/0x4e
[   23.015623]  [<41023408>] default_send_IPI_mask_logical+0x4c/0x70
[   23.015623]  [<41023ead>] arch_trigger_all_cpu_backtrace+0xdf/0x1c5
[   23.015623]  [<41067614>] do_raw_spin_lock+0xe4/0x121
[   23.015623]  [<413d2fd9>] _raw_spin_lock_irqsave+0x54/0x68
[   23.015623]  [<4107e884>] update_wall_time+0x13/0x70f
[   23.015623]  [<41064eb5>] ? lock_release+0x173/0x18a
[   23.015623]  [<41082df4>] tick_periodic+0x7a/0x99
[   23.015623]  [<41082f1e>] ? tick_handle_periodic+0x1c/0x5b
[   23.015623]  [<41082f1e>] tick_handle_periodic+0x1c/0x5b
[   23.015623]  [<41021ff0>] local_apic_timer_interrupt+0x40/0x45
[   23.015623]  [<41022519>] smp_apic_timer_interrupt+0x20/0x2f
[   23.015623]  [<413d448f>] apic_timer_interrupt+0x2f/0x34
[   23.015623]  [<4107d630>] ? read_seqcount_begin+0x6d/0x74
[   23.015623]  [<4107d642>] current_kernel_time+0xb/0x3f
[   23.015623]  [<410789b7>] current_fs_time+0xb/0x19
[   23.015623]  [<410ee0c7>] file_update_time+0x20/0x9b
[   23.015623]  [<410a6c22>] __generic_file_write_iter+0x4b/0x15f
[   23.015623]  [<410a6d7a>] generic_file_write_iter+0x44/0xc5
[   23.015623]  [<410db739>] __vfs_write+0x66/0x8f
[   23.015623]  [<410dbf25>] vfs_write+0x74/0x93
[   23.015623]  [<410dc3f6>] SyS_write+0x4a/0x77
[   23.015623]  [<413d3aab>] syscall_call+0x7/0x7
[   23.015623]  [<413d0000>] ? do_wait_for_common+0x69/0xe4
[   23.015623] Code: 00 5d c3 55 89 e5 50 9d 8d 74 26 00 5d c3 55 89 e5 fa 90 8d 74 26 00 5d c3 8b 0d 38 8c 61 41 55 89 e5 8d 84 08 00 c0 ff ff 89 10 <5d> c3 55 8d 48 01 89 e5 53 89 d3 89 d8 ba 08 00 00 00 e8 c7 dd
[   23.015623] NMI backtrace for cpu 1
[   23.015623] CPU: 1 PID: 22948 Comm: trinity-c1 Not tainted 4.1.0-rc5-01505-gd6201b6 #2
[   23.015623] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014
[   23.015623] task: 4fc08d40 ti: 50210000 task.ti: 50210000
[   23.015623] EIP: 0060:[<4107d630>] EFLAGS: 00000002 CPU: 1
[   23.015623] EIP is at read_seqcount_begin+0x6d/0x74
[   23.015623] EAX: 0000112d EBX: 00000012 ECX: 00000046 EDX: 00000001
[   23.015623] ESI: 4200b600 EDI: 00000246 EBP: 50211e9c ESP: 50211e98
[   23.015623]  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
[   23.015623] CR0: 8005003b CR2: 37560fff CR3: 0ff45000 CR4: 00000690
[   23.015623] Stack:
[   23.015623]  4200c35c 50211ecc 4107d71c 00000001 00000001 00000000 4107f150 00000000
[   23.015623]  00000000 50211f18 50211eec 4200b600 00000246 50211ee0 4107dabf 50211f18
[   23.015623]  4200b600 00000246 50211f04 4107f158 00000080 00000000 00000000 00000000
[   23.015623] Call Trace:
[   23.015623]  [<4107d71c>] timekeeping_get_ns+0x10/0xe8
[   23.015623]  [<4107f150>] ? do_adjtimex+0x58/0xc2
[   23.015623]  [<4107dabf>] __getnstimeofday64_preleap+0x29/0x5d
[   23.015623]  [<4107f158>] do_adjtimex+0x60/0xc2
[   23.015623]  [<4107aa8e>] posix_clock_realtime_adj+0xa/0xc
[   23.015623]  [<4107af8a>] SYSC_clock_adjtime+0x60/0x92
[   23.015623]  [<4107b732>] SyS_clock_adjtime+0xe/0x10
[   23.015623]  [<413d3aab>] syscall_call+0x7/0x7
[   23.015623]  [<413d0000>] ? do_wait_for_common+0x69/0xe4
[   23.015623] Code: 10 f6 c7 02 75 0e 89 d8 e8 0c f9 ff ff e8 ee 42 fe ff eb 0c e8 d4 62 fe ff 89 d8 e8 f9 f8 ff ff a1 40 c3 00 42 a8 01 74 04 f3 90 <eb> f3 8b 5d fc c9 c3 55 89 e5 57 56 53 e8 81 ff ff ff 8b 1d bc

Elapsed time: 220
qemu-system-i386 -enable-kvm -kernel /pkg/linux/i386-randconfig-ib1-05310241/gcc-4.9/d6201b60b90be3c9c344f2387073dbfb84a08d31/vmlinuz-4.1.0-rc5-01505-gd6201b6 -append 'root=/dev/ram0 user=lkp job=/lkp/scheduled/vm-kbuild-yocto-i386-58/rand_boot-1-yocto-minimal-i386.cgz-i386-randconfig-ib1-05310241-d6201b60b90be3c9c344f2387073dbfb84a08d31-1-20150531-98583-1ppz9ur.yaml ARCH=i386 kconfig=i386-randconfig-ib1-05310241 branch=linux-devel/devel-hourly-2015053102 commit=d6201b60b90be3c9c344f2387073dbfb84a08d31 BOOT_IMAGE=/pkg/linux/i386-randconfig-ib1-05310241/gcc-4.9/d6201b60b90be3c9c344f2387073dbfb84a08d31/vmlinuz-4.1.0-rc5-01505-gd6201b6 max_uptime=600 RESULT_ROOT=/result/boot/1/vm-kbuild-yocto-i386/yocto-minimal-i386.cgz/i386-randconfig-ib1-05310241/gcc-4.9/d6201b60b90be3c9c344f2387073dbfb84a08d31/0 LKP_SERVER=inn earlyprintk=ttyS0,115200 systemd.log_level=err 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 rw ip=::::vm-kbuild-yocto-i386-58::dhcp drbd.minor_count=8'  -initrd /fs/sda1/initrd-vm-kbuild-yocto-i386-58 -m 320 -smp 2 -device e1000,netdev=net0 -netdev user,id=net0 -boot order=nc -no-reboot -watchdog i6300esb -rtc base=localtime -drive file=/fs/sda1/disk0-vm-kbuild-yocto-i386-58,media=disk,if=virtio -pidfile /dev/shm/kboot/pid-vm-kbuild-yocto-i386-58 -serial file:/dev/shm/kboot/serial-vm-kbuild-yocto-i386-58 -daemonize -display none -monitor null 



Thanks,
Ying Huang
-------------------------------------
lkp@...ists.intel.com
https://eclists.intel.com/sympa/info/lkp
Unsubscribe by sending email to sympa@...ists.intel.com with subject "Unsubscribe lkp"


View attachment "config-4.1.0-rc4-00015-g78a0b9a" of type "text/plain" (78041 bytes)

View attachment ".dmesg" of type "text/plain" (88612 bytes)

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ