Re: [BUG 6.3-rc1] Bad lock in ttm_bo_delayed_delete()

From: Steven Rostedt
Date: Wed Mar 15 2023 - 13:55:10 EST

On Wed, 15 Mar 2023 11:57:12 -0400
Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:

> The WARN_ON triggered:
>
> [ 21.481449] mpls_gso: MPLS GSO support
> [ 21.488795] IPI shorthand broadcast: enabled
> [ 21.488873] ------------[ cut here ]------------
> [ 21.490101] ------------[ cut here ]------------
>
> [ 21.491693] WARNING: CPU: 1 PID: 38 at drivers/gpu/drm/ttm/ttm_bo.c:332 ttm_bo_release+0x2ac/0x2fc <<<---- Line of the added WARN_ON()
>
> [ 21.492940] refcount_t: underflow; use-after-free.
> [ 21.492965] WARNING: CPU: 0 PID: 84 at lib/refcount.c:28 refcount_warn_saturate+0xb6/0xfc
> [ 21.496116] Modules linked in:
> [ 21.497197] Modules linked in:
> [ 21.500105] CPU: 1 PID: 38 Comm: kworker/1:1 Not tainted 6.3.0-rc2-test-00047-g6015b1aca1a2-dirty #993
> [ 21.500789] CPU: 0 PID: 84 Comm: kworker/0:1H Not tainted 6.3.0-rc2-test-00047-g6015b1aca1a2-dirty #993
> [ 21.501882] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.0-debian-1.16.0-5 04/01/2014
> [ 21.503533] sched_clock: Marking stable (20788024762, 714243692)->(22140778105, -638509651)
> [ 21.504080] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.0-debian-1.16.0-5 04/01/2014
> [ 21.504089] Workqueue: ttm ttm_bo_delayed_delete
> [ 21.507196] Workqueue: events drm_fb_helper_damage_work
> [ 21.509235]
> [ 21.510291] registered taskstats version 1
> [ 21.510302] Running ring buffer tests...
> [ 21.511792]
> [ 21.513870] EIP: refcount_warn_saturate+0xb6/0xfc
> [ 21.515261] EIP: ttm_bo_release+0x2ac/0x2fc
> [ 21.516566] Code: 68 00 27 0c d8 e8 36 3b aa ff 0f 0b 58 c9 c3 90 80 3d 41 c2 37 d8 00 75 8a c6 05 41 c2 37 d8 01 68 2c 27 0c d8 e8 16 3b aa ff <0f> 0b 59 c9 c3 80 3d 3f c2 37 d8 00 0f 85 67 ff ff ff c6 05 3f c2
> [ 21.516998] Code: ff 8d b4 26 00 00 00 00 66 90 0f 0b 8b 43 10 85 c0 0f 84 a1 fd ff ff 8d 76 00 0f 0b 8b 43 28 85 c0 0f 84 9c fd ff ff 8d 76 00 <0f> 0b e9 92 fd ff ff 8d b4 26 00 00 00 00 66 90 c7 43 18 00 00 00
> [ 21.517905] EAX: 00000026 EBX: c129d150 ECX: 00000040 EDX: 00000002
> [ 21.518987] EAX: d78c8550 EBX: c129d134 ECX: c129d134 EDX: 00000001
> [ 21.519337] ESI: c129d0bc EDI: f6f91200 EBP: c2b8bf18 ESP: c2b8bf14
> [ 21.520617] ESI: c129d000 EDI: c126a7a0 EBP: c1839c24 ESP: c1839bec
> [ 21.521546] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00010286
> [ 21.526154] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00010286
> [ 21.526162] CR0: 80050033 CR2: 00000000 CR3: 18506000 CR4: 00150ef0
> [ 21.526166] Call Trace:
> [ 21.526189] ? ww_mutex_unlock+0x3a/0x94
> [ 21.530300] CR0: 80050033 CR2: ff9ff000 CR3: 18506000 CR4: 00150ef0
> [ 21.531722] ? ttm_bo_cleanup_refs+0xc4/0x1e0
> [ 21.533114] Call Trace:
> [ 21.534516] ttm_mem_evict_first+0x3d3/0x568
> [ 21.535901] ttm_bo_delayed_delete+0x9c/0xa4
> [ 21.537391] ? kfree+0x6b/0xdc
> [ 21.538901] process_one_work+0x21a/0x484
> [ 21.540279] ? ttm_range_man_alloc+0xe0/0xec
> [ 21.540854] worker_thread+0x14a/0x39c
> [ 21.541714] ? ttm_range_man_fini_nocheck+0xe8/0xe8
> [ 21.543332] kthread+0xea/0x10c

So I triggered it again, and the same backtrace is there.

> [ 21.544301] ttm_bo_mem_space+0x1d0/0x1e4

It looks like the object is being reserved before it's fully removed. And
it's somewhere in this tty_bo_mem_space() (which comes from the
qxl_bo_create()).

I don't know this code at all, nor do I have any idea of what it's trying
to do. All I know is that this is triggering often (not always), and it has
to do with some race.

Now my config has lots of debugging enabled, which slows down the system
quite a bit. This also happens to open up race windows. Just because your
testing doesn't trigger it, doesn't mean that the race doesn't exist. It's
just likely to be very hard to hit.

> [ 21.544942] ? process_one_work+0x484/0x484
> [ 21.545887] ttm_bo_validate+0xc5/0x19c
> [ 21.546986] ? kthread_complete_and_exit+0x1c/0x1c
> [ 21.547680] ttm_bo_init_reserved+0x15e/0x1fc
> [ 21.548716] ret_from_fork+0x1c/0x28
> [ 21.549650] qxl_bo_create+0x145/0x20c

Here's the latest backtrace:

[ 170.817449] ------------[ cut here ]------------
[ 170.817455] ------------[ cut here ]------------
[ 170.818210] refcount_t: underflow; use-after-free.
[ 170.818228] WARNING: CPU: 0 PID: 267 at lib/refcount.c:28 refcount_warn_saturate+0xb6/0xfc
[ 170.819352] WARNING: CPU: 3 PID: 2382 at drivers/gpu/drm/ttm/ttm_bo.c:332 ttm_bo_release+0x278/0x2c8
[ 170.820124] Modules linked in:
[ 170.822127] Modules linked in:
[ 170.823829]
[ 170.823832] CPU: 0 PID: 267 Comm: kworker/0:10H Not tainted 6.3.0-rc2-test-00047-g6015b1aca1a2-dirty #998
[ 170.824610]
[ 170.825121] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.0-debian-1.16.0-5 04/01/2014
[ 170.825124] Workqueue: ttm ttm_bo_delayed_delete
[ 170.825498] CPU: 3 PID: 2382 Comm: kworker/3:3 Not tainted 6.3.0-rc2-test-00047-g6015b1aca1a2-dirty #998
[ 170.826996]
[ 170.827367] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.0-debian-1.16.0-5 04/01/2014
[ 170.828839] EIP: refcount_warn_saturate+0xb6/0xfc
[ 170.829842] Workqueue: events drm_fb_helper_damage_work
[ 170.831325] Code: 68 50 ab ef d3 e8 76 ce b2 ff 0f 0b 58 c9 c3 90 80 3d 4e e0 18 d4 00 75 8a c6 05 4e e0 18 d4 01 68 7c ab ef d3 e8 56 ce b2 ff <0f> 0b 59 c9 c3 80 3d 4c e0 18 d4 00 0f 85 67 ff ff ff c6 05 4c e0
[ 170.831670]
[ 170.833138] EAX: 00000026 EBX: c2aa6ef4 ECX: 00000002 EDX: 80000002
[ 170.834080] EIP: ttm_bo_release+0x278/0x2c8
[ 170.834910] ESI: c27744e0 EDI: f758eaa8 EBP: c3083f34 ESP: c3083f30
[ 170.838453] Code: 00 90 89 f8 e9 91 fe ff ff 90 0f 0b 8b 43 10 85 c0 0f 84 d5 fd ff ff 8d 76 00 0f 0b 8b 43 28 85 c0 0f 84 d0 fd ff ff 8d 76 00 <0f> 0b e9 c6 fd ff ff 8d b4 26 00 00 00 00 66 90 c7 43 18 00 00 00
[ 170.838714] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00010286
[ 170.839872] EAX: d3835cf0 EBX: c2aa6ed8 ECX: c2aa6ed8 EDX: 00000001
[ 170.840546] CR0: 80050033 CR2: 005ce01c CR3: 03afa000 CR4: 00150ef0
[ 170.841669] ESI: c2aa6e00 EDI: c11333d8 EBP: c3b15ca0 ESP: c3b15c68
[ 170.844583] Call Trace:
[ 170.845738] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00010286
[ 170.846732] ttm_bo_delayed_delete+0x7c/0x84
[ 170.847766] CR0: 80050033 CR2: 005b59b1 CR3: 03b12000 CR4: 00150ef0
[ 170.848761] process_one_work+0x18a/0x350
[ 170.849177] Call Trace:
[ 170.850250] worker_thread+0x136/0x378
[ 170.850942] ? ttm_resource_free+0x57/0x6c
[ 170.851928] ? _raw_spin_unlock_irqrestore+0x25/0x40
[ 170.852583] ? ttm_bo_cleanup_memtype_use+0x5f/0x64
[ 170.853002] kthread+0xda/0xfc
[ 170.853608] ? ttm_bo_cleanup_refs+0xbb/0x1c8
[ 170.854266] ? rescuer_thread+0x340/0x340
[ 170.855058] ttm_mem_evict_first+0x324/0x3a0
[ 170.855840] ? kthread_complete_and_exit+0x1c/0x1c
[ 170.856341] ttm_bo_mem_space+0x1d8/0x1ec
[ 170.857056] ret_from_fork+0x1c/0x28
[ 170.857702] ttm_bo_validate+0xb3/0x13c
[ 170.858393] ---[ end trace 0000000000000000 ]---
[ 170.859167] ttm_bo_init_reserved+0x12e/0x1cc
[ 170.863261] systemd[1]: Starting Create System Users...
[ 170.863964] qxl_bo_create+0x14a/0x1f8
[ 170.892037] ? qxl_ttm_debugfs_init+0x48/0x48
[ 170.892043] qxl_alloc_bo_reserved+0x39/0x98
Starting ESC[0;1;39mCreat[ 170.892047] ? kmalloc_trace+0x22/0x84
e System UsersESC[0m...
[ 170.895826] qxl_image_alloc_objects+0x91/0xfc
[ 170.897122] qxl_draw_dirty_fb+0x159/0x440
[ 170.898207] systemd[1]: Finished Set the console keyboard layout.
[ 170.898329] qxl_framebuffer_surface_dirty+0xfb/0x1cc
[ 170.901528] ? qxl_create_plane+0xc4/0xc4
[ 170.901533] drm_fbdev_fb_dirty+0x129/0x1ac
[ESC[0;32m OK ESC[0m] Finished ESC[0[ 170.901537] drm_fb_helper_damage_work+0x8f/0x158
;1;39mSet the console keyboard layoutESC[0m.
[ 170.905435] process_one_work+0x18a/0x350
[ 170.906578] worker_thread+0x136/0x378
[ 170.906832] systemd[1]: Finished Load/Save Random Seed.
[ 170.907195] ? _raw_spin_unlock_irqrestore+0x25/0x40
[ 170.910267] kthread+0xda/0xfc
[ 170.910271] ? rescuer_thread+0x340/0x340
[ 170.910275] ? kthread_complete_and_exit+0x1c/0x1c
[ 170.910278] ret_from_fork+0x1c/0x28
[ 170.910282] ---[ end trace 0000000000000000 ]---

-- Steve