Bug 106689

Summary: [CI] ODEBUG: free active (active state 0) object type: timer_list hint: process_timeout+0x0/0x10
Product: DRI Reporter: Martin Peres <martin.peres>
Component: DRM/IntelAssignee: Intel GFX Bugs mailing list <intel-gfx-bugs>
Status: CLOSED DUPLICATE QA Contact: Intel GFX Bugs mailing list <intel-gfx-bugs>
Severity: normal    
Priority: lowest CC: intel-gfx-bugs
Version: XOrg git   
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: BSW/CHT i915 features: display/audio

Description Martin Peres 2018-05-28 13:59:45 UTC 
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_39/fi-bsw-n3050/igt@drm_import_export@flink.html

In the boot log, we can find the following issue, coming from the realtek audio driver:

<4>[   14.837853] ------------[ cut here ]------------
<3>[   14.838298] ODEBUG: free active (active state 0) object type: timer_list hint: process_timeout+0x0/0x10
<7>[   14.838427] [drm:intel_dp_aux_xfer [i915]] dp_aux_ch timeout status 0x71450064
<4>[   14.838538] WARNING: CPU: 1 PID: 189 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100
<4>[   14.838639] Modules linked in: snd_hda_codec_realtek(+) snd_hda_codec_generic i915 snd_hda_intel snd_hda_codec intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul snd_hwdep ghash_clmulni_intel snd_hda_core snd_pcm r8169 mii lpc_ich prime_numbers pinctrl_cherryview
<4>[   14.838943] CPU: 1 PID: 189 Comm: systemd-udevd Not tainted 4.17.0-rc4-gb4c14c0809e8-drmtip_39+ #1
<4>[   14.839048] Hardware name:  /NUC5CPYB, BIOS PYBSWCEL.86A.0058.2016.1102.1842 11/02/2016
<4>[   14.839146] RIP: 0010:debug_print_object+0xd7/0x100
<4>[   14.839208] RSP: 0018:ffffaac080253b60 EFLAGS: 00010082
<4>[   14.839276] RAX: 0000000000000000 RBX: ffff8cd9b6d14d88 RCX: 0000000000000002
<4>[   14.839363] RDX: 0000000000000002 RSI: ffffffffba08634e RDI: 00000000ffffffff
<4>[   14.839449] RBP: ffffffffba247820 R08: 0000000000000000 R09: 0000000000000000
<4>[   14.839533] R10: ffffaac080253c20 R11: ffffffffba244598 R12: ffffffffba0a1a97
<4>[   14.839617] R13: ffffffffb9115d00 R14: ffffaac085865000 R15: dead000000000100
<4>[   14.839702] FS:  00007f56f154d680(0000) GS:ffff8cd9bfd00000(0000) knlGS:0000000000000000
<4>[   14.839797] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4>[   14.839867] CR2: 00007f4542c8d490 CR3: 0000000175b3e000 CR4: 00000000001006e0
<4>[   14.839952] Call Trace:
<4>[   14.839992]  ? trace_hardirqs_on_thunk+0x1a/0x1c
<4>[   14.840058]  ? lock_acquire+0xa6/0x210
<4>[   14.840110]  ? debug_check_no_obj_freed+0xa4/0x210
<4>[   14.840179]  debug_check_no_obj_freed+0x194/0x210
<4>[   14.840247]  __vunmap+0xab/0x100
<4>[   14.840294]  load_module+0x2e2/0x2b20
<4>[   14.840351]  ? vfs_read+0x122/0x140
<4>[   14.840401]  ? kernel_read+0x27/0x40
<4>[   14.840451]  ? kernel_read_file+0xee/0x180
<4>[   14.840511]  ? __se_sys_finit_module+0xd3/0xf0
<4>[   14.840569]  __se_sys_finit_module+0xd3/0xf0
<4>[   14.840634]  do_syscall_64+0x55/0x190
<4>[   14.840685]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4>[   14.840748] RIP: 0033:0x7f56f1077839
<4>[   14.840795] RSP: 002b:00007ffd6579bf58 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
<4>[   14.840888] RAX: ffffffffffffffda RBX: 00005646dd579be0 RCX: 00007f56f1077839
<4>[   14.840974] RDX: 0000000000000000 RSI: 00007f56f0d560e5 RDI: 000000000000000f
<7>[   14.841087] [drm:intel_dp_aux_xfer [i915]] dp_aux_ch timeout status 0x71450064
<4>[   14.841176] RBP: 00007f56f0d560e5 R08: 0000000000000000 R09: 00007ffd6579c070
<4>[   14.841182] R10: 000000000000000f R11: 0000000000000246 R12: 0000000000000000
<4>[   14.841367] R13: 00005646dd59c6a0 R14: 0000000000020000 R15: 00005646dd579be0
<4>[   14.841459] Code: 02 01 e8 2d 38 05 00 8b 43 10 4d 89 e9 4c 89 e6 8b 4b 14 4c 8b 45 00 48 c7 c7 08 87 0a ba 48 8b 14 c5 e0 45 e4 b9 e8 69 70 bf ff <0f> 0b 48 c7 c7 48 87 0a ba e8 64 c8 c6 ff be 02 00 00 00 48 89 
<4>[   14.841787] irq event stamp: 286790
<4>[   14.841836] hardirqs last  enabled at (286789): [<ffffffffb994878c>] _raw_spin_unlock_irqrestore+0x4c/0x60
<4>[   14.841950] hardirqs last disabled at (286790): [<ffffffffb99485fd>] _raw_spin_lock_irqsave+0xd/0x50
<4>[   14.842058] softirqs last  enabled at (285954): [<ffffffffb9c0032b>] __do_softirq+0x32b/0x4e1
<4>[   14.842160] softirqs last disabled at (285947): [<ffffffffb908f6f4>] irq_exit+0xa4/0xb0
<4>[   14.842258] WARNING: CPU: 1 PID: 189 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100
<4>[   14.842357] ---[ end trace 1e828788b9e29e10 ]---
<7>[   14.843938] [drm:intel_dp_aux_xfer [i915]] dp_aux_ch timeout status 0x71450064
<3>[   14.846194] ODEBUG: ODEBUG: debug object originally initialized at:
<4>[   14.846198]    schedule_timeout+0x76/0x540
<4>[   14.846200]    msleep+0x33/0x40
<4>[   14.846214]    alc283_init+0xf1/0x120 [snd_hda_codec_realtek]
<4>[   14.846225]    alc_init+0x1f/0x590 [snd_hda_codec_realtek]
<7>[   14.860163] [drm:intel_dp_aux_xfer [i915]] dp_aux_ch timeout status 0x71450064
<4>[   14.861873]    snd_hda_codec_build_controls+0x32/0x200 [snd_hda_codec]
<4>[   14.861881]    hda_codec_driver_probe+0xc1/0x100 [snd_hda_codec]
<4>[   14.861889]    driver_probe_device+0x306/0x480
<7>[   14.873171] [drm:intel_dp_aux_xfer [i915]] dp_aux_ch timeout status 0x71450064
<4>[   14.873742]    __driver_attach+0xb7/0xe0
<4>[   14.873747]    bus_for_each_dev+0x74/0xc0
<7>[   14.885164] [drm:intel_dp_aux_xfer [i915]] dp_aux_ch timeout status 0x71450064
<4>[   14.885711]    bus_add_driver+0x15f/0x250
<4>[   14.885717]    driver_register+0x52/0xc0
<7>[   14.895368] [drm:intel_dp_aux_xfer [i915]] dp_aux_ch timeout status 0x71450064
<4>[   14.897788]    do_one_initcall+0x58/0x370
<4>[   14.897792]    do_init_module+0x56/0x1ea
<4>[   14.897794]    load_module+0x2435/0x2b20
<4>[   14.897797]    __se_sys_finit_module+0xd3/0xf0
<4>[   14.897799]    do_syscall_64+0x55/0x190
<4>[   14.897805]    entry_SYSCALL_64_after_hwframe+0x49/0xbe
<7>[   14.911696] [drm:intel_dp_aux_xfer [i915]] dp_aux_ch timeout status 0x71450064

<4>[   14.914110] ======================================================
<4>[   14.914111] WARNING: possible circular locking dependency detected
<4>[   14.914112] 4.17.0-rc4-gb4c14c0809e8-drmtip_39+ #1 Not tainted
<4>[   14.914113] ------------------------------------------------------
<4>[   14.914114] systemd-udevd/189 is trying to acquire lock:
<4>[   14.914114]         (ptrval) ((console_sem).lock){-...}, at: down_trylock+0xa/0x30

<4>[   14.914119] but task is already holding lock:
<4>[   14.914120]         (ptrval) (&obj_hash[i].lock){-.-.}, at: debug_check_no_obj_freed+0xa4/0x210

<4>[   14.914124] which lock already depends on the new lock.


<4>[   14.914126] the existing dependency chain (in reverse order) is:

<4>[   14.914127] -> #3 (&obj_hash[i].lock){-.-.}:
<4>[   14.914131]        __debug_object_init+0x74/0x590
<4>[   14.914132]        hrtimer_init+0x1b/0x160
<4>[   14.914132]        init_dl_task_timer+0x17/0x30
<4>[   14.914133]        __sched_fork.isra.16+0xa4/0xf0
<4>[   14.914134]        init_idle+0x53/0x270
<4>[   14.914135]        sched_init+0x42c/0x49f
<4>[   14.914136]        start_kernel+0x269/0x4c2
<4>[   14.914136]        secondary_startup_64+0xa5/0xb0

<4>[   14.914138] -> #2 (&rq->lock){-.-.}:
<4>[   14.914141]        task_fork_fair+0x36/0x160
<4>[   14.914142]        sched_fork+0x123/0x280
<4>[   14.914142]        copy_process.part.7+0x5f4/0x1d30
<4>[   14.914143]        _do_fork+0xe2/0x700
<4>[   14.914144]        kernel_thread+0x20/0x30
<4>[   14.914145]        rest_init+0x1d/0x220
<4>[   14.914146]        start_kernel+0x4a2/0x4c2
<4>[   14.914146]        secondary_startup_64+0xa5/0xb0

<4>[   14.914148] -> #1 (&p->pi_lock){-.-.}:
<4>[   14.914151]        try_to_wake_up+0x37/0x650
<4>[   14.914152]        up+0x3b/0x50
<4>[   14.914152]        __up_console_sem+0x2e/0x50
<4>[   14.914153]        console_unlock+0x32f/0x640
<4>[   14.914154]        register_framebuffer+0x24c/0x350
<4>[   14.914155]        __drm_fb_helper_initial_config_and_unlock+0x22a/0x4a0
<4>[   14.914156]        intel_fbdev_initial_config+0xf/0x20 [i915]
<4>[   14.914157]        async_run_entry_fn+0x34/0x160
<4>[   14.914158]        process_one_work+0x229/0x6a0
<4>[   14.914159]        worker_thread+0x35/0x380
<4>[   14.914159]        kthread+0x119/0x130
<4>[   14.914160]        ret_from_fork+0x3a/0x50

<4>[   14.914161] -> #0 ((console_sem).lock){-...}:
<4>[   14.914165]        _raw_spin_lock_irqsave+0x33/0x50
<4>[   14.914165]        down_trylock+0xa/0x30
<4>[   14.914166]        __down_trylock_console_sem+0x20/0x80
<4>[   14.914167]        console_trylock+0xe/0x60
<4>[   14.914168]        vprintk_emit+0x22e/0x4d0
<4>[   14.914169]        printk+0x4d/0x69
<4>[   14.914169]        __warn_printk+0x46/0x90
<4>[   14.914170]        debug_print_object+0xd7/0x100
<4>[   14.914171]        debug_check_no_obj_freed+0x194/0x210
<4>[   14.914172]        __vunmap+0xab/0x100
<4>[   14.914173]        load_module+0x2e2/0x2b20
<4>[   14.914174]        __se_sys_finit_module+0xd3/0xf0
<4>[   14.914174]        do_syscall_64+0x55/0x190
<4>[   14.914175]        entry_SYSCALL_64_after_hwframe+0x49/0xbe

<4>[   14.914177] other info that might help us debug this:

<4>[   14.914178] Chain exists of:
<4>[   14.914179]   (console_sem).lock --> &rq->lock --> &obj_hash[i].lock

<4>[   14.914184]  Possible unsafe locking scenario:

<4>[   14.914185]        CPU0                    CPU1
<4>[   14.914186]        ----                    ----
<4>[   14.914187]   lock(&obj_hash[i].lock);
<4>[   14.914189]                                lock(&rq->lock);
<4>[   14.914191]                                lock(&obj_hash[i].lock);
<4>[   14.914193]   lock((console_sem).lock);

<4>[   14.914196]  *** DEADLOCK ***

<4>[   14.914197] 1 lock held by systemd-udevd/189:
<4>[   14.914198]  #0:         (ptrval) (&obj_hash[i].lock){-.-.}, at: debug_check_no_obj_freed+0xa4/0x210

<4>[   14.914202] stack backtrace:
<4>[   14.914204] CPU: 1 PID: 189 Comm: systemd-udevd Not tainted 4.17.0-rc4-gb4c14c0809e8-drmtip_39+ #1
<4>[   14.914205] Hardware name:  /NUC5CPYB, BIOS PYBSWCEL.86A.0058.2016.1102.1842 11/02/2016
<4>[   14.914205] Call Trace:
<4>[   14.914206]  dump_stack+0x67/0x9b
<4>[   14.914207]  print_circular_bug.isra.18+0x1c8/0x2b0
<4>[   14.914208]  __lock_acquire+0x1897/0x1b50
<4>[   14.914209]  ? lock_acquire+0xa6/0x210
<4>[   14.914209]  lock_acquire+0xa6/0x210
<4>[   14.914210]  ? down_trylock+0xa/0x30
<4>[   14.914211]  ? vprintk_emit+0x22e/0x4d0
<4>[   14.914212]  _raw_spin_lock_irqsave+0x33/0x50
<4>[   14.914213]  ? down_trylock+0xa/0x30
<4>[   14.914213]  down_trylock+0xa/0x30
<4>[   14.914214]  __down_trylock_console_sem+0x20/0x80
<4>[   14.914215]  console_trylock+0xe/0x60
<4>[   14.914216]  vprintk_emit+0x22e/0x4d0
<4>[   14.914217]  ? collect_expired_timers+0xa0/0xa0
<4>[   14.914217]  printk+0x4d/0x69
<4>[   14.914218]  ? collect_expired_timers+0xa0/0xa0
<4>[   14.914219]  __warn_printk+0x46/0x90
<4>[   14.914220]  ? collect_expired_timers+0xa0/0xa0
<4>[   14.914221]  debug_print_object+0xd7/0x100
<4>[   14.914222]  ? trace_hardirqs_on_thunk+0x1a/0x1c
<4>[   14.914222]  ? lock_acquire+0xa6/0x210
<4>[   14.914223]  ? debug_check_no_obj_freed+0xa4/0x210
<4>[   14.914224]  debug_check_no_obj_freed+0x194/0x210
<4>[   14.914225]  __vunmap+0xab/0x100
<4>[   14.914226]  load_module+0x2e2/0x2b20
<4>[   14.914226]  ? vfs_read+0x122/0x140
<4>[   14.914227]  ? kernel_read+0x27/0x40
<4>[   14.914228]  ? kernel_read_file+0xee/0x180
<4>[   14.914229]  ? __se_sys_finit_module+0xd3/0xf0
<4>[   14.914230]  __se_sys_finit_module+0xd3/0xf0
<4>[   14.914230]  do_syscall_64+0x55/0x190
<4>[   14.914231]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4>[   14.914232] RIP: 0033:0x7f56f1077839
<4>[   14.914233] RSP: 002b:00007ffd6579bf58 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
<4>[   14.914235] RAX: ffffffffffffffda RBX: 00005646dd579be0 RCX: 00007f56f1077839
<4>[   14.914236] RDX: 0000000000000000 RSI: 00007f56f0d560e5 RDI: 000000000000000f
<4>[   14.914237] RBP: 00007f56f0d560e5 R08: 0000000000000000 R09: 00007ffd6579c070
<4>[   14.914238] R10: 000000000000000f R11: 0000000000000246 R12: 0000000000000000
<4>[   14.914239] R13: 00005646dd59c6a0 R14: 0000000000020000 R15: 00005646dd579be0

Filing this bug first here to see if we can reproduce it, before sending it to the audio guys.
Comment 1 Martin Peres 2018-06-05 09:44:57 UTC 

*** This bug has been marked as a duplicate of bug 105616 ***
Comment 2 Jani Saarinen 2018-06-19 14:25:57 UTC 
Closing, thanks.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.