Message-ID: <20220330110156.GA9250@axis.com>
Date:   Wed, 30 Mar 2022 13:01:56 +0200
From:   Vincent Whitchurch <vincent.whitchurch@...s.com>
To:     <johannes@...solutions.net>
CC:     <linux-um@...ts.infradead.org>, <linux-kernel@...r.kernel.org>
Subject: UML time-travel warning from __run_timers

Hello Johannes,

As requested in the roadtest thread[0], here is some information about
reproducing the warnings I'm seeing from the timekeeping code with time
travel in UML, after about 10-20 wall time seconds of idling.

[0] https://lore.kernel.org/lkml/5b39d572e619c812109af7a1b8028bfb8353efda.camel@sipsolutions.net/

The warning is the WARN_ON_ONCE(!levels && !base->next_expiry_recalc) in
__run_timers().  The log and the config generated with savedefconfig are
below.  The full .config is attached.

The kernel version is v5.17, but the splats are seen on older kernels
and on latest mainline also.

Thanks,
Vincent

$ ./vmlinux mem=64M rootfstype=hostfs rw init=/bin/sh time-travel
[    0.000000][    T0] Linux version 5.17.0 (user@...ver) (gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2) #4 Wed Mar 30 12:50:22 CEST 2022
[    0.000000][    T0] Zone ranges:
[    0.000000][    T0]   Normal   [mem 0x0000000000000000-0x0000000065e5dfff]
[    0.000000][    T0] Movable zone start for each node
[    0.000000][    T0] Early memory node ranges
[    0.000000][    T0]   node   0: [mem 0x0000000000000000-0x0000000005e5dfff]
[    0.000000][    T0] Initmem setup node 0 [mem 0x0000000000000000-0x0000000005e5dfff]
[    0.000000][    T0] Built 1 zonelists, mobility grouping on.  Total pages: 23827
[    0.000000][    T0] Kernel command line: mem=64M rootfstype=hostfs rw init=/bin/sh time-travel root=98:0 console=tty
[    0.000000][    T0] Unknown kernel command line parameters "mem=64M", will be passed to user space.
[    0.000000][    T0] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes, linear)
[    0.000000][    T0] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.000000][    T0] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000][    T0] Memory: 44216K/96632K available (4153K kernel code, 1452K rwdata, 1784K rodata, 220K init, 12103K bss, 52416K reserved, 0K cma-reserved)
[    0.000000][    T0] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000][    T0] Running RCU self tests
[    0.000000][    T0] NR_IRQS: 128
[    0.000000][    T0] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.000000][    T0] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.000000][    T0] ... MAX_LOCK_DEPTH:          48
[    0.000000][    T0] ... MAX_LOCKDEP_KEYS:        8192
[    0.000000][    T0] ... CLASSHASH_SIZE:          4096
[    0.000000][    T0] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.000000][    T0] ... MAX_LOCKDEP_CHAINS:      65536
[    0.000000][    T0] ... CHAINHASH_SIZE:          32768
[    0.000000][    T0]  memory used by lock dependency info: 6365 kB
[    0.000000][    T0]  memory used for stack traces: 4224 kB
[    0.000000][    T0]  per task-struct memory footprint: 1920 bytes
[    0.000000][    T0] clocksource: time-travel-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e205, max_idle_ns: 881590404426 ns
[    0.000000][    T0] Calibrating delay loop... 4434.32 BogoMIPS (lpj=22171648)
[    0.070000][    T0] pid_max: default: 32768 minimum: 301
[    0.070000][    T0] Mount-cache hash table entries: 512 (order: 0, 4096 bytes, linear)
[    0.070000][    T0] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes, linear)
[    0.070000][    T0] Checking that host ptys support output SIGIO...Yes
[    0.070000][    T1] devtmpfs: initialized
[    0.070000][    T1] random: get_random_bytes called from 0x6001a9d3 with crng_init=0
[    0.070000][    T1] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.070000][    T1] futex hash table entries: 256 (order: 2, 22528 bytes, linear)
[    0.070000][    T1] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[    0.070000][    T1] vgaarb: loaded
[    0.070000][    T1] pps_core: LinuxPPS API ver. 1 registered
[    0.070000][    T1] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@...ux.it>
[    0.070000][    T1] PTP clock support registered
[    0.070000][    T1] clocksource: Switched to clocksource time-travel-clock
[    0.100000][    T1] VFS: Disk quotas dquot_6.6.0
[    0.100000][    T1] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.100000][    T1] NET: Registered PF_UNIX/PF_LOCAL protocol family
[    0.100000][    T1] PCI: CLS 0 bytes, default 64
[    0.100000][    T1] printk: console [stderr0] disabled
[    0.100000][    T1] mconsole (version 2) initialized on /home/user/.uml/soRICy/mconsole
[    0.100000][    T1] Checking host MADV_REMOVE support...OK
[    0.100000][    T1] PCI host bridge to bus 0000:00
[    0.100000][    T1] pci_bus 0000:00: root bus resource [mem 0xf0000000-0xffffffff]
[    0.100000][    T1] workingset: timestamp_bits=62 max_order=14 bucket_order=0
[    0.100000][    T1] jitterentropy: Initialization failed with host not compliant with requirements: 10
[    0.100000][    T1] io scheduler mq-deadline registered
[    0.100000][    T1] io scheduler kyber registered
[    0.100000][    T1] i2c_dev: i2c /dev entries driver
[    0.100000][    T1] Initialized stdio console driver
[    0.100000][    T1] Console initialized on /dev/tty0
[    0.100000][    T1] printk: console [tty0] enabled
[    0.100000][    T1] Initializing software serial port version 1
[    0.100000][    T1] printk: console [mc-1] enabled
[    0.100000][    T1] VFS: Mounted root (hostfs filesystem) on device 0:14.
[    0.100000][    T1] devtmpfs: mounted
[    0.100000][    T1] This architecture does not have kernel memory protection.
[    0.100000][    T1] Run /bin/sh as init process
sh: cannot set terminal process group (-1): Inappropriate ioctl for device
sh: no job control in this shell
[?2004hsh-5.1# [ 1031.280000][    C0] random: fast init done
[ 1911.750000][    C0] random: crng init done
[10737482.720000][    C0] ------------[ cut here ]------------
[10737482.720000][    C0] WARNING: CPU: 0 PID: 0 at kernel/time/timer.c:1729 __run_timers+0x36d/0x380
[10737482.720000][    C0] Modules linked in:
[10737482.720000][    C0] CPU: 0 PID: 0 Comm: swapper Not tainted 5.17.0 #4
[10737482.720000][    C0] Stack:
[10737482.720000][    C0]  603f5639 00000100 00000000 00000000
[10737482.720000][    C0]  603fabe8 600b1fcd 000006c1 603f550a
[10737482.720000][    C0]  160643fc0 9604234c7 60614ec0 604234c7
[10737482.720000][    C0] Call Trace:
[10737482.720000][    C0]  [<603f5639>] ? warn_slowpath_fmt+0x0/0xda
[10737482.720000][    C0]  [<603fabe8>] ? _printk+0x0/0x9b
[10737482.720000][    C0]  [<600b1fcd>] ? __run_timers+0x36d/0x380
[10737482.720000][    C0]  [<603f550a>] ? __warn.cold+0x1f/0x14e
[10737482.720000][    C0]  [<604234c7>] ? lock_is_held_type+0x157/0x1e0
[10737482.720000][    C0]  [<603f5705>] ? warn_slowpath_fmt+0xcc/0xda
[10737482.720000][    C0]  [<60092189>] ? lock_acquire+0x209/0x340
[10737482.720000][    C0]  [<600b1c94>] ? __run_timers+0x34/0x380
[10737482.720000][    C0]  [<603f5639>] ? warn_slowpath_fmt+0x0/0xda
[10737482.720000][    C0]  [<600b1d85>] ? __run_timers+0x125/0x380
[10737482.720000][    C0]  [<600b19a0>] ? call_timer_fn+0x0/0x2c0
[10737482.720000][    C0]  [<6042d8dc>] ? _raw_spin_lock_irq+0x4c/0x80
[10737482.720000][    C0]  [<600b1c94>] ? __run_timers+0x34/0x380
[10737482.720000][    C0]  [<600b1fcd>] ? __run_timers+0x36d/0x380
[10737482.720000][    C0]  [<604234c7>] ? lock_is_held_type+0x157/0x1e0
[10737482.720000][    C0]  [<600247d0>] ? um_trace_signals_on+0x0/0x20
[10737482.720000][    C0]  [<600b1c60>] ? __run_timers+0x0/0x380
[10737482.720000][    C0]  [<600aa850>] ? rcu_read_lock_sched_held+0x0/0x40
[10737482.720000][    C0]  [<6042e4d5>] ? __do_softirq+0x115/0x576
[10737482.720000][    C0]  [<60091cbb>] ? lock_release+0x10b/0x3d0
[10737482.720000][    C0]  [<600247d0>] ? um_trace_signals_on+0x0/0x20
[10737482.720000][    C0]  [<60036560>] ? sig_handler_common+0x0/0xd0
[10737482.720000][    C0]  [<60047585>] ? __irq_exit_rcu+0x175/0x1a0
[10737482.720000][    C0]  [<6009ebe1>] ? generic_handle_irq+0x41/0x60
[10737482.720000][    C0]  [<60047770>] ? irq_exit+0x10/0x30
[10737482.720000][    C0]  [<60022adc>] ? do_IRQ+0x3c/0x50
[10737482.720000][    C0]  [<60036e20>] ? um_set_signals+0x0/0x50
[10737482.720000][    C0]  [<60025c57>] ? timer_handler+0x47/0x120
[10737482.720000][    C0]  [<60036669>] ? timer_real_alarm_handler+0x39/0x70
[10737482.720000][    C0]  [<600247f0>] ? um_trace_signals_off+0x0/0x20
[10737482.720000][    C0]  [<60036e0e>] ? unblock_signals+0x10e/0x120
[10737482.720000][    C0]  [<600aa850>] ? rcu_read_lock_sched_held+0x0/0x40
[10737482.720000][    C0]  [<60422da0>] ? lockdep_hardirqs_on+0x0/0x1c0
[10737482.720000][    C0]  [<60079960>] ? arch_cpu_idle_enter+0x0/0x10
[10737482.720000][    C0]  [<60036ce0>] ? block_signals+0x0/0x20
[10737482.720000][    C0]  [<6042d623>] ? default_idle_call+0xb3/0x1fa
[10737482.720000][    C0]  [<60079970>] ? arch_cpu_idle_exit+0x0/0x10
[10737482.720000][    C0]  [<60079960>] ? arch_cpu_idle_enter+0x0/0x10
[10737482.720000][    C0]  [<60079970>] ? arch_cpu_idle_exit+0x0/0x10
[10737482.720000][    C0]  [<60079a8d>] ? do_idle+0xdd/0x180
[10737482.720000][    C0]  [<60091bb0>] ? lock_release+0x0/0x3d0
[10737482.720000][    C0]  [<60066f40>] ? find_task_by_pid_ns+0x0/0xa0
[10737482.720000][    C0]  [<600799b0>] ? do_idle+0x0/0x180
[10737482.720000][    C0]  [<602996b0>] ? strlen+0x0/0x30
[10737482.720000][    C0]  [<60079f9b>] ? cpu_startup_entry+0x1b/0x20
[10737482.720000][    C0]  [<603fabe8>] ? _printk+0x0/0x9b
[10737482.720000][    C0]  [<60001f3e>] ? 0x60001f3e
[10737482.720000][    C0]  [<60068b00>] ? parse_args+0x0/0x4f0
[10737482.720000][    C0]  [<60036ce0>] ? block_signals+0x0/0x20
[10737482.720000][    C0]  [<60003ac3>] ? 0x60003ac3
[10737482.720000][    C0]  [<600232b2>] ? new_thread_handler+0x82/0xc0
[10737482.720000][    C0] irq event stamp: 18391811
[10737482.720000][    C0] hardirqs last  enabled at (18391810): [<000000006042dc14>] _raw_spin_unlock_irq+0x34/0x50
[10737482.720000][    C0] hardirqs last disabled at (18391811): [<000000006042d904>] _raw_spin_lock_irq+0x74/0x80
[10737482.720000][    C0] softirqs last  enabled at (18391702): [<000000006042e743>] __do_softirq+0x383/0x576
[10737482.720000][    C0] softirqs last disabled at (18391799): [<0000000060047585>] __irq_exit_rcu+0x175/0x1a0
[10737482.720000][    C0] ---[ end trace 0000000000000000 ]---


CONFIG_NO_HZ=y
CONFIG_HIGH_RES_TIMERS=y
CONFIG_LOG_BUF_SHIFT=14
CONFIG_EXPERT=y
CONFIG_HOSTFS=y
CONFIG_MAGIC_SYSRQ=y
CONFIG_UML_TIME_TRAVEL_SUPPORT=y
CONFIG_SSL=y
CONFIG_NULL_CHAN=y
CONFIG_PORT_CHAN=y
CONFIG_PTY_CHAN=y
CONFIG_TTY_CHAN=y
CONFIG_XTERM_CHAN=y
CONFIG_CON_CHAN="pts"
CONFIG_SSL_CHAN="pts"
CONFIG_VIRTIO_UML=y
CONFIG_UML_PCI_OVER_VIRTIO=y
CONFIG_UML_PCI_OVER_VIRTIO_DEVICE_ID=1234
CONFIG_GCOV_KERNEL=y
CONFIG_MODULES=y
CONFIG_MODULE_UNLOAD=y
CONFIG_BINFMT_MISC=m
# CONFIG_COMPACTION is not set
CONFIG_NET=y
CONFIG_UNIX=y
CONFIG_DEVTMPFS=y
CONFIG_DEVTMPFS_MOUNT=y
CONFIG_OF=y
# CONFIG_INPUT is not set
CONFIG_LEGACY_PTY_COUNT=32
CONFIG_HW_RANDOM=y
CONFIG_RANDOM_TRUST_BOOTLOADER=y
CONFIG_I2C=y
# CONFIG_I2C_COMPAT is not set
CONFIG_I2C_CHARDEV=y
CONFIG_I2C_VIRTIO=y
CONFIG_I2C_STUB=m
CONFIG_GPIOLIB=y
CONFIG_GPIO_VIRTIO=y
CONFIG_REGULATOR=y
CONFIG_REGULATOR_DEBUG=y
CONFIG_REGULATOR_VIRTUAL_CONSUMER=y
CONFIG_REGULATOR_TPS6286X=m
CONFIG_NEW_LEDS=y
CONFIG_LEDS_CLASS=y
CONFIG_LEDS_GPIO=y
CONFIG_LEDS_TRIGGERS=y
CONFIG_LEDS_TRIGGER_HEARTBEAT=y
CONFIG_RTC_CLASS=y
# CONFIG_RTC_HCTOSYS is not set
# CONFIG_RTC_SYSTOHC is not set
CONFIG_RTC_DEBUG=y
# CONFIG_RTC_NVMEM is not set
CONFIG_RTC_DRV_PCF8563=m
CONFIG_IIO=y
CONFIG_OPT3001=m
CONFIG_VCNL4000=m
CONFIG_QUOTA=y
CONFIG_AUTOFS4_FS=m
CONFIG_PROC_KCORE=y
CONFIG_TMPFS=y
CONFIG_NLS=y
CONFIG_CRYPTO=y
CONFIG_CRYPTO_CRC32C=y
CONFIG_CRYPTO_JITTERENTROPY=y
CONFIG_CRC16=y
CONFIG_PRINTK_TIME=y
CONFIG_PRINTK_CALLER=y
CONFIG_DYNAMIC_DEBUG=y
CONFIG_FRAME_WARN=1024
CONFIG_READABLE_ASM=y
CONFIG_DEBUG_FS=y
CONFIG_UBSAN=y
CONFIG_PAGE_EXTENSION=y
CONFIG_DEBUG_OBJECTS=y
CONFIG_DEBUG_OBJECTS_FREE=y
CONFIG_DEBUG_OBJECTS_TIMERS=y
CONFIG_DEBUG_OBJECTS_WORK=y
CONFIG_PROVE_LOCKING=y
CONFIG_ENABLE_DEFAULT_TRACERS=y

View attachment "uml-config" of type "text/plain" (71261 bytes)

Powered by blists - more mailing lists