Message-ID: <20180914090151.GH7632@shao2-debian>
Date:   Fri, 14 Sep 2018 17:01:51 +0800
From:   kernel test robot <rong.a.chen@...el.com>
To:     Dmitry Safonov <dima@...sta.com>
Cc:     linux-kernel@...r.kernel.org,
        Dmitry Safonov <0x7f454c46@...il.com>,
        Dmitry Safonov <dima@...sta.com>,
        Daniel Axtens <dja@...ens.net>,
        Dmitry Vyukov <dvyukov@...gle.com>,
        Mark Rutland <mark.rutland@....com>,
        Michael Neuling <mikey@...ling.org>,
        Mikulas Patocka <mpatocka@...hat.com>,
        Nathan March <nathan@...net>,
        Pasi Kärkkäinen <pasik@....fi>,
        Peter Hurley <peter@...leysoftware.com>,
        Peter Zijlstra <peterz@...radead.org>,
        "Rong, Chen" <rong.a.chen@...el.com>,
        Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>,
        Tan Xiaojun <tanxiaojun@...wei.com>,
        Tetsuo Handa <penguin-kernel@...ove.SAKURA.ne.jp>,
        Jiri Slaby <jslaby@...e.cz>,
        syzbot+3aa9784721dfb90e984d@...kaller.appspotmail.com,
        stable@...r.kernel.org,
        Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
        Jiri Slaby <jslaby@...e.com>, lkp@...org
Subject: [LKP] [tty]  f26eb68a52: INFO:task_blocked_for_more_than#seconds

FYI, we noticed the following commit (built with gcc-4.9):

commit: f26eb68a52bb7302d220133440c1438143f2c7e1 ("[PATCHv4 2/7] tty: Hold tty_ldisc_lock() during tty_reopen()")
url: https://github.com/0day-ci/linux/commits/Dmitry-Safonov/tty-Hold-write-ldisc-sem-in-tty_reopen/20180912-182135
base: https://git.kernel.org/cgit/linux/kernel/git/gregkh/tty.git tty-testing

in testcase: locktorture
with following parameters:

	runtime: 300s
	test: cpuhotplug

test-description: This torture test consists of creating a number of kernel threads which acquire the lock and hold it for specific amount of time, thus simulating different critical region behaviors.
test-url: https://www.kernel.org/doc/Documentation/locking/locktorture.txt


on test machine: qemu-system-i386 -enable-kvm -m 256M

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


+----------------------------------------------------+------------+------------+
|                                                    | 59ce4b9e1e | f26eb68a52 |
+----------------------------------------------------+------------+------------+
| boot_successes                                     | 0          | 0          |
| boot_failures                                      | 12         | 14         |
| INFO:trying_to_register_non-static_key             | 12         | 14         |
| WARNING:at_mm/page_alloc.c:#__alloc_pages_nodemask | 12         | 14         |
| EIP:__alloc_pages_nodemask                         | 12         | 14         |
| Mem-Info                                           | 12         | 14         |
| INFO:task_blocked_for_more_than#seconds            | 0          | 8          |
| Kernel_panic-not_syncing:hung_task:blocked_tasks   | 0          | 8          |
+----------------------------------------------------+------------+------------+



[  245.080051] INFO: task lkp-setup-rootf:500 blocked for more than 120 seconds.
[  245.082850]       Tainted: G        W       T 4.19.0-rc3-00014-gf26eb68 #1
[  245.084673] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  245.086455] lkp-setup-rootf D 6516   500    498 0x00000000
[  245.087766] Call Trace:
[  245.088391]  __schedule+0x4b1/0xe80
[  245.089322]  schedule+0x25/0x60
[  245.090178]  schedule_timeout+0x275/0x4e0
[  245.091105]  ? __ldsem_down_write_nested+0x1aa/0x300
[  245.092217]  __ldsem_down_write_nested+0x1b2/0x300
[  245.093286]  ? ldsem_down_write+0x2a/0x2e
[  245.094305]  ldsem_down_write+0x2a/0x2e
[  245.095211]  tty_ldisc_lock+0x16/0x40
[  245.096104]  tty_reopen+0x3f/0xc0
[  245.096892]  tty_open+0x3cf/0x450
[  245.097718]  chrdev_open+0x9c/0x1f0
[  245.098511]  ? security_file_open+0x99/0xa0
[  245.099512]  do_dentry_open+0x3d5/0x5d0
[  245.100428]  ? inode_permission+0x95/0x180
[  245.101351]  ? cdev_put+0x30/0x30
[  245.102138]  vfs_open+0x2d/0x30
[  245.102898]  path_openat+0x9e1/0x17d0
[  245.103733]  do_filp_open+0x6a/0x120
[  245.104541]  ? _raw_spin_unlock+0x22/0x30
[  245.105439]  ? __alloc_fd+0xa5/0x170
[  245.106309]  do_sys_open+0x13a/0x250
[  245.107118]  sys_open+0x22/0x30
[  245.107980]  do_int80_syscall_32+0x94/0x1c0
[  245.108982]  entry_INT80_32+0xf3/0xf3
[  245.109865] EIP: 0x6fe9c305
[  245.110672] Code: Bad RIP value.
[  245.111607] EAX: ffffffda EBX: 0906aa54 ECX: 00008241 EDX: 000001b6
[  245.113034] ESI: 00000241 EDI: 000001b6 EBP: 778ae6f4 ESP: 778ae5ec
[  245.114594] DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 007b EFLAGS: 00000286
[  245.116119] INFO: task jshn:542 blocked for more than 120 seconds.
[  245.117633]       Tainted: G        W       T 4.19.0-rc3-00014-gf26eb68 #1
[  245.119174] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  245.120929] jshn            D 6708   542    541 0x00000000
[  245.122290] Call Trace:
[  245.122871]  ? __schedule+0x4b1/0xe80
[  245.123749]  ? schedule+0x25/0x60
[  245.124554]  ? __mutex_unlock_slowpath+0xbe/0x3b0
[  245.125670]  ? schedule_timeout+0x275/0x4e0
[  245.126623]  ? __ldsem_down_read_nested+0x137/0x2c0
[  245.127726]  ? __ldsem_down_read_nested+0x14b/0x2c0
[  245.129035]  ? ldsem_down_read+0x2a/0x30
[  245.129943]  ? uart_write+0x220/0x220
[  245.130875]  ? ldsem_down_read+0x2a/0x30
[  245.131729]  ? tty_ldisc_ref_wait+0x1e/0x40
[  245.132637]  ? tty_ioctl+0xe2/0x970
[  245.133451]  ? do_raw_spin_unlock+0xb2/0x130
[  245.134501]  ? _raw_spin_unlock+0x22/0x30
[  245.135428]  ? handle_mm_fault+0x16d1/0x1e80
[  245.136368]  ? send_break+0x110/0x110
[  245.137240]  ? do_vfs_ioctl+0x84/0x9f0
[  245.138181]  ? __do_page_fault+0x40c/0x840
[  245.139146]  ? up_read+0x67/0xd0
[  245.139870]  ? __fget_light+0x81/0x90
[  245.140672]  ? security_file_ioctl+0xe/0x50
[  245.141676]  ? ksys_ioctl+0x58/0x80
[  245.142436]  ? sys_ioctl+0x16/0x20
[  245.143195]  ? do_int80_syscall_32+0x94/0x1c0
[  245.144160]  ? entry_INT80_32+0xf3/0xf3
[  245.145021] INFO: task dnsmasq:555 blocked for more than 120 seconds.
[  245.146852]       Tainted: G        W       T 4.19.0-rc3-00014-gf26eb68 #1
[  245.148826] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  245.151131] dnsmasq         D 6772   555      1 0x00000000
[  245.152449] Call Trace:
[  245.153009]  __schedule+0x4b1/0xe80
[  245.153808]  schedule+0x25/0x60
[  245.154561]  ? __mutex_unlock_slowpath+0xbe/0x3b0
[  245.155609]  schedule_timeout+0x275/0x4e0
[  245.156560]  ? __ldsem_down_read_nested+0x137/0x2c0
[  245.157693]  __ldsem_down_read_nested+0x14b/0x2c0
[  245.159001]  ? ldsem_down_read+0x2a/0x30
[  245.159885]  ? uart_write+0x220/0x220
[  245.160702]  ldsem_down_read+0x2a/0x30
[  245.161522]  tty_ldisc_ref_wait+0x1e/0x40
[  245.162581]  tty_ioctl+0xe2/0x970
[  245.163314]  ? do_raw_spin_unlock+0xb2/0x130
[  245.164286]  ? _raw_spin_unlock+0x22/0x30
[  245.165257]  ? handle_mm_fault+0x16d1/0x1e80
[  245.166260]  ? send_break+0x110/0x110
[  245.167082]  do_vfs_ioctl+0x84/0x9f0
[  245.167876]  ? __do_page_fault+0x40c/0x840
[  245.169051]  ? up_read+0x67/0xd0
[  245.169829]  ? __fget_light+0x81/0x90
[  245.170637]  ? security_file_ioctl+0xe/0x50
[  245.171570]  ksys_ioctl+0x58/0x80
[  245.172336]  sys_ioctl+0x16/0x20
[  245.173139]  do_int80_syscall_32+0x94/0x1c0
[  245.174104]  entry_INT80_32+0xf3/0xf3
[  245.175017] EIP: 0x6ff64648
[  245.175657] Code: c0 74 1a 8d 83 ce e8 fe ff 89 44 24 04 89 3c 24 e8 21 9d ff ff 85 c0 0f 85 93 00 00 00 8b 83 68 44 00 00 85 c0 74 53 48 89 83 <68> 44 00 00 8b 93 5c 44 00 00 8b 04 82 89 04 24 e8 53 95 fd ff eb
[  245.180346] EAX: ffffffda EBX: 00000000 ECX: 00005401 EDX: 77a6c704
[  245.181929] ESI: 77a6c704 EDI: 77a6c73c EBP: 77a6c9a8 ESP: 77a6c6e4
[  245.183279] DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 007b EFLAGS: 00000246
[  245.184814] INFO: task dropbear:667 blocked for more than 120 seconds.
[  245.186388]       Tainted: G        W       T 4.19.0-rc3-00014-gf26eb68 #1
[  245.187992] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  245.189851] dropbear        D 6772   667      1 0x00000000
[  245.191265] Call Trace:
[  245.191865]  __schedule+0x4b1/0xe80
[  245.192643]  schedule+0x25/0x60
[  245.193355]  ? __mutex_unlock_slowpath+0xbe/0x3b0
[  245.194554]  schedule_timeout+0x275/0x4e0
[  245.195574]  ? __ldsem_down_read_nested+0x137/0x2c0
[  245.196694]  __ldsem_down_read_nested+0x14b/0x2c0
[  245.197744]  ? ldsem_down_read+0x2a/0x30
[  245.198686]  ? uart_write+0x220/0x220
[  245.199516]  ldsem_down_read+0x2a/0x30
[  245.200321]  tty_ldisc_ref_wait+0x1e/0x40
[  245.201219]  tty_ioctl+0xe2/0x970
[  245.202012]  ? do_raw_spin_unlock+0xb2/0x130
[  245.202937]  ? _raw_spin_unlock+0x22/0x30
[  245.203891]  ? handle_mm_fault+0x16d1/0x1e80
[  245.204884]  ? send_break+0x110/0x110
[  245.205834]  do_vfs_ioctl+0x84/0x9f0
[  245.206729]  ? __do_page_fault+0x40c/0x840
[  245.207752]  ? up_read+0x67/0xd0
[  245.208526]  ? __fget_light+0x81/0x90
[  245.209440]  ? security_file_ioctl+0xe/0x50
[  245.210531]  ksys_ioctl+0x58/0x80
[  245.211285]  sys_ioctl+0x16/0x20
[  245.212182]  do_int80_syscall_32+0x94/0x1c0
[  245.213163]  entry_INT80_32+0xf3/0xf3
[  245.214146] EIP: 0x6ff5f648
[  245.214894] Code: 39 89 3e 4a 83 c1 04 83 c6 04 eb ef 85 d2 74 09 4a 8b 34 91 89 34 90 eb f3 5e 5f c3 56 8b 44 24 08 8b 4c 24 0c 8b 54 24 10 85 <d2> 74 0d 8b 31 89 30 4a 83 c1 04 83 c0 04 eb ef 5e c3 56 8b 44 24
[  245.219039] EAX: ffffffda EBX: 00000000 ECX: 00005401 EDX: 77b3c984
[  245.220389] ESI: 77b3c984 EDI: 77b3c9bc EBP: 77b3cc28 ESP: 77b3c964
[  245.222023] DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 007b EFLAGS: 00000246
[  245.223596] INFO: lockdep is turned off.
[  245.224554] NMI backtrace for cpu 0
[  245.225318] CPU: 0 PID: 18 Comm: khungtaskd Tainted: G        W       T 4.19.0-rc3-00014-gf26eb68 #1
[  245.227454] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[  245.229272] Call Trace:
[  245.229879]  ? dump_stack+0x76/0xb6
[  245.230725]  ? nmi_cpu_backtrace+0x9e/0xa0
[  245.231630]  ? nmi_trigger_cpumask_backtrace+0xaa/0xf0
[  245.232783]  ? debug_show_all_locks+0x112/0x120
[  245.233863]  ? watchdog+0x308/0x530
[  245.234744]  ? lapic_can_unplug_cpu+0xa0/0xa0
[  245.235811]  ? arch_trigger_cpumask_backtrace+0x15/0x20
[  245.237103]  ? watchdog+0x349/0x530
[  245.237891]  ? kthread+0x10f/0x140
[  245.238634]  ? reset_hung_task_detector+0x20/0x20
[  245.239777]  ? kthread_stop+0x210/0x210
[  245.240642]  ? ret_from_fork+0x2e/0x38
[  245.241586] Kernel panic - not syncing: hung_task: blocked tasks
[  245.242902] CPU: 0 PID: 18 Comm: khungtaskd Tainted: G        W       T 4.19.0-rc3-00014-gf26eb68 #1
[  245.244941] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[  245.246929] Call Trace:
[  245.247486]  ? dump_stack+0x76/0xb6
[  245.248246]  ? panic+0x97/0x1e0
[  245.248991]  ? watchdog+0x355/0x530
[  245.249798]  ? kthread+0x10f/0x140
[  245.250598]  ? reset_hung_task_detector+0x20/0x20
[  245.251716]  ? kthread_stop+0x210/0x210
[  245.252617]  ? ret_from_fork+0x2e/0x38
[  245.253582] Kernel Offset: disabled
[  245.254385] Rebooting in 3 seconds..

Elapsed time: 240

#!/bin/bash

# To reproduce,
# 1) save job-script and this script (both are attached in 0day report email)
# 2) run this script with your compiled kernel and optional env $INSTALL_MOD_PATH

kernel=$1

initrds=(
	/osimage/openwrt/openwrt-i386-2016-03-16.cgz
	/lkp/lkp/lkp-i386.cgz
)

HTTP_PREFIX=https://download.01.org/0day-ci/lkp-qemu
wget --timestamping "${initrds[@]/#/$HTTP_PREFIX}"

{
	cat "${initrds[@]//*\//}"
	[[ $INSTALL_MOD_PATH ]] && (
		cd "$INSTALL_MOD_PATH"
		find lib | cpio -o -H newc --quiet | gzip
	)
	echo  job-script | cpio -o -H newc --quiet | gzip
} > initrd.img

qemu-img create -f qcow2 disk-vm-lkp-hsw-4ep1-openwrt-i386-14-0 256G
qemu-img create -f qcow2 disk-vm-lkp-hsw-4ep1-openwrt-i386-14-1 256G

kvm=(
	qemu-system-i386
	-enable-kvm
	-kernel $kernel
	-initrd initrd.img
	-m 256
	-smp 1
	-device e1000,netdev=net0
	-netdev user,id=net0
	-boot order=nc
	-no-reboot
	-watchdog i6300esb
	-watchdog-action debug
	-rtc base=localtime
	-drive file=disk-vm-lkp-hsw-4ep1-openwrt-i386-14-0,media=disk,if=virtio
	-drive file=disk-vm-lkp-hsw-4ep1-openwrt-i386-14-1,media=disk,if=virtio
	-serial stdio
	-display none
	-monitor null
)

append=(
	ip=::::vm-lkp-hsw-4ep1-openwrt-i386-14::dhcp
	root=/dev/ram0
	user=lkp
	job=/job-script
	ARCH=i386
	kconfig=i386-randconfig-sb0-09131136
	branch=linux-devel/devel-spot-201809131102
	commit=f26eb68a52bb7302d220133440c1438143f2c7e1
	BOOT_IMAGE=/pkg/linux/i386-randconfig-sb0-09131136/gcc-4.9/f26eb68a52bb7302d220133440c1438143f2c7e1/vmlinuz-4.19.0-rc3-00014-gf26eb68
	max_uptime=1500
	RESULT_ROOT=/result/locktorture/300s-cpuhotplug/vm-lkp-hsw-4ep1-openwrt-i386/openwrt-i386-2016-03-16.cgz/i386-randconfig-sb0-09131136/gcc-4.9/f26eb68a52bb7302d220133440c1438143f2c7e1/3
	result_service=tmpfs
	debug
	apic=debug
	sysrq_always_enabled
	rcupdate.rcu_cpu_stall_timeout=100
	net.ifnames=0
	printk.devkmsg=on


To reproduce:

        git clone https://github.com/intel/lkp-tests.git
        cd lkp-tests
        find lib/ | cpio -o -H newc --quiet | gzip > modules.cgz
	bin/lkp qemu -k <bzImage> -m modules.cgz job-script # job-script is attached in this email




Thanks,
Rong, Chen

View attachment "config-4.19.0-rc3-00014-gf26eb68" of type "text/plain" (122066 bytes)

View attachment "job-script" of type "text/plain" (4144 bytes)

Download attachment "dmesg.xz" of type "application/x-xz" (22308 bytes)

Powered by blists - more mailing lists