Bug#793394: NMI handler & perf interrupts take too long
Package: src:linux
Version: 3.16.7-ckt11-1+deb8u2
Severity: normal
File: /boot/vmlinuz-3.16.0-4-amd64
Hello,
I am regularly getting messages of the following form from the kernel:
| Jul 23 06:46:30 ebox kernel: [ 1.432009] perf interrupt took too long (3688 > 2500), lowering kernel.perf_event_max_sample_rate to 50000
| Jul 23 07:01:11 ebox kernel: [ 883.330989] NMI handler (perf_event_nmi_handler) took too long to run: xxx msecs
where xxx is typically multiple msecs.
I am not using perf, and this happens even right after boot (see the
timestamp above).
This looks as if it is related to
http://linux-kernel.2935.n7.nabble.com/scheduling-while-atomic-amp-hang-td679062i20.html.
Best,
-Nikolaus
-- Package-specific info:
** Version:
Linux version 3.16.0-4-amd64 (debian-kernel@lists.debian.org) (gcc version 4.8.4 (Debian 4.8.4-1) ) #1 SMP Debian 3.16.7-ckt11-1+deb8u2 (2015-07-17)
** Command line:
BOOT_IMAGE=/root/boot/vmlinuz-3.16.0-4-amd64 root=/dev/sda ro rootflags=subvol=root console=ttyS0,19200n8
** Not tainted
** Kernel log:
[ 1.376821] systemd[1]: Inserted module 'autofs4'
[ 1.377948] systemd[1]: Set hostname to <ebox>.
[ 1.432009] perf interrupt took too long (3688 > 2500), lowering kernel.perf_event_max_sample_rate to 50000
[ 1.438130] systemd[1]: Cannot add dependency job for unit display-manager.service, ignoring: Unit display-manager.service failed to load: No such file or directory.
[ 1.441345] systemd[1]: Expecting device dev-ttyS0.device...
[ 1.443868] systemd[1]: Starting Forward Password Requests to Wall Directory Watch.
[ 1.445187] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[ 1.446518] systemd[1]: Starting Remote File Systems (Pre).
[ 1.448749] systemd[1]: Reached target Remote File Systems (Pre).
[ 1.449796] systemd[1]: Starting Arbitrary Executable File Formats File System Automount Point.
[ 1.453026] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[ 1.455141] systemd[1]: Starting Encrypted Volumes.
[ 1.457297] systemd[1]: Reached target Encrypted Volumes.
[ 1.458288] systemd[1]: Starting Dispatch Password Requests to Console Directory Watch.
[ 1.459711] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[ 1.460998] systemd[1]: Starting Paths.
[ 1.462654] systemd[1]: Reached target Paths.
[ 1.463391] systemd[1]: Expecting device dev-sdb.device...
[ 1.465424] systemd[1]: Expecting device dev-sda.device...
[ 1.467370] systemd[1]: Starting Root Slice.
[ 1.469176] systemd[1]: Created slice Root Slice.
[ 1.469957] systemd[1]: Starting User and Session Slice.
[ 1.472220] systemd[1]: Created slice User and Session Slice.
[ 1.473229] systemd[1]: Starting Delayed Shutdown Socket.
[ 1.475477] systemd[1]: Listening on Delayed Shutdown Socket.
[ 1.476481] systemd[1]: Starting /dev/initctl Compatibility Named Pipe.
[ 1.479219] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[ 1.480493] systemd[1]: Starting Journal Socket (/dev/log).
[ 1.482755] systemd[1]: Listening on Journal Socket (/dev/log).
[ 1.483823] systemd[1]: Starting udev Kernel Socket.
[ 1.485828] systemd[1]: Listening on udev Kernel Socket.
[ 1.486724] systemd[1]: Starting udev Control Socket.
[ 1.488792] systemd[1]: Listening on udev Control Socket.
[ 1.489686] systemd[1]: Starting Journal Socket.
[ 1.491529] systemd[1]: Listening on Journal Socket.
[ 1.492424] systemd[1]: Starting System Slice.
[ 1.494513] systemd[1]: Created slice System Slice.
[ 1.495329] systemd[1]: Started File System Check on Root Device.
[ 1.496339] systemd[1]: Starting system-systemd\x2dfsck.slice.
[ 1.498750] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[ 1.499872] systemd[1]: Starting system-serial\x2dgetty.slice.
[ 1.502153] systemd[1]: Created slice system-serial\x2dgetty.slice.
[ 1.503216] systemd[1]: Starting Increase datagram queue length...
[ 1.507085] systemd[1]: Starting Load Kernel Modules...
[ 1.509518] systemd[1]: Starting Create list of required static device nodes for the current kernel...
[ 1.513371] systemd[1]: Starting udev Coldplug all Devices...
[ 1.518738] systemd[1]: Mounting Huge Pages File System...
[ 1.520698] tsc: Refined TSC clocksource calibration: 2800.076 MHz
[ 1.524858] fuse init (API version 7.23)
[ 1.529101] systemd[1]: Started Set Up Additional Binary Formats.
[ 1.530156] systemd[1]: Mounting POSIX Message Queue File System...
[ 1.533151] systemd[1]: Mounting Debug File System...
[ 1.535665] systemd[1]: Starting Slices.
[ 1.539506] systemd[1]: Reached target Slices.
[ 1.542982] systemd[1]: Starting Remount Root and Kernel File Systems...
[ 1.550397] systemd[1]: Started Increase datagram queue length.
[ 1.553028] systemd[1]: Started Load Kernel Modules.
[ 1.556443] systemd[1]: Started Create list of required static device nodes for the current kernel.
[ 1.564616] systemd[1]: Starting Create Static Device Nodes in /dev...
[ 1.572570] BTRFS info (device sda): disk space caching is enabled
[ 1.575423] systemd[1]: Mounted Configuration File System.
[ 1.579904] systemd[1]: Mounting FUSE Control File System...
[ 1.586042] systemd[1]: Starting Apply Kernel Variables...
[ 1.591751] systemd[1]: Starting Syslog Socket.
[ 1.596204] systemd[1]: Listening on Syslog Socket.
[ 1.598167] systemd[1]: Starting Journal Service...
[ 1.601993] systemd[1]: Started Journal Service.
[ 1.652649] systemd-udevd[178]: starting version 215
[ 1.712918] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input2
[ 1.714457] ACPI: Power Button [PWRF]
[ 1.726485] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0
[ 1.731859] [drm] Initialized drm 1.1.0 20060810
[ 1.737006] input: PC Speaker as /devices/platform/pcspkr/input/input3
[ 1.785301] AVX version of gcm_enc/dec engaged.
[ 1.807396] Adding 262140k swap on /dev/sdb. Priority:-1 extents:1 across:262140k FS
[ 1.817676] ppdev: user-space parallel port driver
[ 1.819850] alg: No test for __gcm-aes-aesni (__driver-gcm-aes-aesni)
[ 1.828955] random: nonblocking pool is initialized
[ 1.856274] alg: No test for crc32 (crc32-pclmul)
[ 1.937561] systemd-journald[177]: Received request to flush runtime journal from PID 1
[ 2.409036] ip_tables: (C) 2000-2006 Netfilter Core Team
[ 2.471744] nf_conntrack version 0.5.0 (8002 buckets, 32008 max)
[ 2.482590] tun: Universal TUN/TAP device driver, 1.6
[ 2.483417] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
[ 2.582265] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input4
[ 2.628009] perf interrupt took too long (7140 > 5000), lowering kernel.perf_event_max_sample_rate to 25000
[ 3.561638] perf interrupt took too long (10299 > 10000), lowering kernel.perf_event_max_sample_rate to 12500
[ 6.804009] perf interrupt took too long (22551 > 20000), lowering kernel.perf_event_max_sample_rate to 6250
[ 883.330989] perf interrupt took too long (40417 > 38461), lowering kernel.perf_event_max_sample_rate to 3250
[ 3335.619344] perf interrupt took too long (77281 > 71428), lowering kernel.perf_event_max_sample_rate to 1750
[ 5318.728154] perf interrupt took too long (143697 > 125000), lowering kernel.perf_event_max_sample_rate to 1000
[ 5718.600013] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 1.213 msecs
[10577.262551] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 1.234 msecs
[11242.180440] perf interrupt took too long (254126 > 250000), lowering kernel.perf_event_max_sample_rate to 500
[13235.256007] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 143.779 msecs
[13235.256007] perf interrupt took too long (1399797 > 500000), lowering kernel.perf_event_max_sample_rate to 250
[14477.800068] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 199.616 msecs
[15361.013057] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 201.356 msecs
[21339.824010] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 229.600 msecs
[22534.624019] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 319.880 msecs
** Model information
sys_vendor: QEMU
product_name: Standard PC (i440FX + PIIX, 1996)
product_version: pc-i440fx-2.3
chassis_vendor: QEMU
chassis_version: pc-i440fx-2.3
bios_vendor: SeaBIOS
bios_version: rel-1.8.1-0-g4adadbd-20150316_085822-nilsson.home.kraxel.org
** Loaded modules:
xt_nat
xt_LOG
xt_limit
xt_conntrack
ipt_REJECT
iptable_filter
xt_REDIRECT
xt_tcpudp
xt_recent
iptable_nat
nf_conntrack_ipv4
nf_defrag_ipv4
nf_nat_ipv4
nf_nat
tun
nf_conntrack
ip_tables
x_tables
crc32_pclmul
ghash_clmulni_intel
ppdev
aesni_intel
aes_x86_64
lrw
gf128mul
glue_helper
ttm
ablk_helper
drm_kms_helper
cryptd
evdev
psmouse
serio_raw
pcspkr
drm
i2c_piix4
i2c_core
parport_pc
processor
parport
thermal_sys
button
fuse
autofs4
btrfs
xor
raid6_pq
sg
sd_mod
crc_t10dif
crct10dif_generic
sr_mod
cdrom
ata_generic
virtio_scsi
virtio_net
crct10dif_pclmul
crct10dif_common
crc32c_intel
ata_piix
floppy
libata
scsi_mod
virtio_pci
virtio_ring
virtio
** PCI devices:
not available
** USB devices:
not available
-- System Information:
Debian Release: 8.1
APT prefers stable-updates
APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: amd64 (x86_64)
Kernel: Linux 3.16.0-4-amd64 (SMP w/1 CPU core)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
Versions of packages linux-image-3.16.0-4-amd64 depends on:
ii debconf [debconf-2.0] 1.5.56
ii initramfs-tools [linux-initramfs-tool] 0.120
ii kmod 18-3
ii linux-base 3.5
Versions of packages linux-image-3.16.0-4-amd64 recommends:
ii firmware-linux-free 3.3
ii irqbalance 1.0.6-3
Versions of packages linux-image-3.16.0-4-amd64 suggests:
pn debian-kernel-handbook <none>
ii grub-pc 2.02~beta2-22
pn linux-doc-3.16 <none>
Versions of packages linux-image-3.16.0-4-amd64 is related to:
pn firmware-atheros <none>
pn firmware-bnx2 <none>
pn firmware-bnx2x <none>
pn firmware-brcm80211 <none>
pn firmware-intelwimax <none>
pn firmware-ipw2x00 <none>
pn firmware-ivtv <none>
pn firmware-iwlwifi <none>
pn firmware-libertas <none>
pn firmware-linux <none>
pn firmware-linux-nonfree <none>
pn firmware-myricom <none>
pn firmware-netxen <none>
pn firmware-qlogic <none>
pn firmware-ralink <none>
pn firmware-realtek <none>
pn xen-hypervisor <none>
-- debconf information:
linux-image-3.16.0-4-amd64/prerm/removing-running-kernel-3.16.0-4-amd64: true
linux-image-3.16.0-4-amd64/postinst/depmod-error-initrd-3.16.0-4-amd64: false
linux-image-3.16.0-4-amd64/postinst/mips-initrd-3.16.0-4-amd64:
Reply to: