lkml.org 
[lkml]   [2019]   [Jul]   [27]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
Subjectsched: Unexpected reschedule of offline CPU#2!
Hi,

I see the following traceback (or similar tracebacks) once in a while
during my boot tests. In this specific case it is with mainline
(v5.3-rc1-195-g3ea54d9b0d65), but I have seen it with other branches
as well. This isn't a new problem; I have seen it for quite some time.
There is no specific action required to make it appear; just running
reboot loops is sufficient. The problem doesn't happen a lot;
non-scientifically I would say I see it maybe once every few hundred
boots.

No specific action requested or asked for; this is just informational.

A complete log is at:
https://kerneltests.org/builders/qemu-x86-master/builds/1285/steps/qemubuildcommand/logs/stdio

Guenter

---
[ 61.248329] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 61.268277] e1000e: EEE TX LPI TIMER: 00000000
[ 61.311435] reboot: Restarting system
[ 61.312321] reboot: machine restart
[ 61.342193] ------------[ cut here ]------------
[ 61.342660] sched: Unexpected reschedule of offline CPU#2!
ILLOPC: ce241f83: 0f 0b
[ 61.344323] WARNING: CPU: 1 PID: 15 at arch/x86/kernel/smp.c:126 native_smp_send_reschedule+0x33/0x40
[ 61.344836] Modules linked in:
[ 61.345694] CPU: 1 PID: 15 Comm: ksoftirqd/1 Not tainted 5.3.0-rc1+ #1
[ 61.345998] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 04/01/2014
[ 61.346569] EIP: native_smp_send_reschedule+0x33/0x40
[ 61.347099] Code: cf 73 1c 8b 15 60 54 2b cf 8b 4a 18 ba fd 00 00 00 e8 05 65 c7 00 c9 c3 8d b4 26 00 00 00 00 50 68 04 ca 1a cf e8 fe e3 01 00 <0f> 0b 58 5a c9 c3 8d b4 26 00 00 00 00 55 89 e5 56 53 83 ec 0c 65
[ 61.347726] EAX: 0000002e EBX: 00000002 ECX: 00000000 EDX: cdd64140
[ 61.347977] ESI: 00000002 EDI: 00000000 EBP: cdd73c88 ESP: cdd73c80
[ 61.348234] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00000096
[ 61.348514] CR0: 80050033 CR2: b7ee7048 CR3: 0c28f000 CR4: 000006d0
[ 61.348866] Call Trace:
[ 61.349392] kick_ilb+0x90/0xa0
[ 61.349629] trigger_load_balance+0xf0/0x5c0
[ 61.349859] ? check_preempt_wakeup+0x1b0/0x1b0
[ 61.350057] scheduler_tick+0xa7/0xd0
[ 61.350266] update_process_times+0x4a/0x60
[ 61.350467] tick_sched_handle+0x3e/0x50
[ 61.350650] tick_sched_timer+0x37/0x90
[ 61.350847] __hrtimer_run_queues+0xf7/0x440
[ 61.351056] ? tick_sched_do_timer+0x70/0x70
[ 61.351281] hrtimer_interrupt+0x10e/0x260
[ 61.351541] smp_apic_timer_interrupt+0x68/0x210
[ 61.351750] apic_timer_interrupt+0x106/0x10c
[ 61.352040] EIP: _raw_spin_unlock_irqrestore+0x47/0x50
[ 61.352254] Code: 66 40 ff f6 c7 02 75 1b 53 9d e8 c4 67 49 ff 64 ff 0d 84 27 50 cf 5b 5e 5d c3 8d b4 26 00 00 00 00 66 90 e8 ab 69 49 ff 53 9d <eb> e3 8d b4 26 00 00 00 00 55 64 ff 05 84 27 50 cf 89 e5 53 89 c3
[ 61.352810] EAX: cdd64140 EBX: 00000282 ECX: 00000003 EDX: 00000002
[ 61.353041] ESI: cdc01940 EDI: 00000001 EBP: cdd73e08 ESP: cdd73e00
[ 61.353273] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00000282
[ 61.353705] ? _raw_spin_unlock_irqrestore+0x47/0x50
[ 61.362142] free_debug_processing+0x199/0x220
[ 61.362413] __slab_free+0x220/0x3b0
[ 61.362599] ? irq_kobj_release+0x1c/0x20
[ 61.362845] ? kfree+0x1ad/0x270
[ 61.363002] ? kfree+0x1ad/0x270
[ 61.363162] kfree+0x264/0x270
[ 61.363305] ? kfree+0x264/0x270
[ 61.363458] ? irq_kobj_release+0x1c/0x20
[ 61.363624] ? irq_kobj_release+0x1c/0x20
[ 61.363824] irq_kobj_release+0x1c/0x20
[ 61.364018] kobject_put+0x58/0xc0
[ 61.364211] ? hwirq_show+0x50/0x50
[ 61.364439] delayed_free_desc+0xb/0x10
[ 61.364621] rcu_core+0x288/0xb50
[ 61.364805] ? __do_softirq+0x7e/0x3bb
[ 61.365042] rcu_core_si+0x8/0x10
[ 61.365209] __do_softirq+0xa9/0x3bb
[ 61.365445] run_ksoftirqd+0x25/0x50
[ 61.365615] smpboot_thread_fn+0xef/0x1d0
[ 61.365834] kthread+0xf2/0x110
[ 61.365986] ? sort_range+0x20/0x20
[ 61.366156] ? kthread_create_on_node+0x20/0x20
[ 61.366360] ret_from_fork+0x2e/0x38
[ 61.366818] irq event stamp: 1267
[ 61.367115] hardirqs last enabled at (1266): [<ceeb37f5>] _raw_spin_unlock_irqrestore+0x45/0x50
[ 61.367448] hardirqs last disabled at (1267): [<ce20178a>] trace_hardirqs_off_thunk+0xc/0x12
[ 61.367769] softirqs last enabled at (1232): [<ceeb7a45>] __do_softirq+0x2c5/0x3bb
[ 61.368057] softirqs last disabled at (1237): [<ce267605>] run_ksoftirqd+0x25/0x50
[ 61.368389] ---[ end trace 3465d631a21844b8 ]---

\
 
 \ /
  Last update: 2019-07-27 18:49    [W:0.055 / U:2.800 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site