On 4/8/20 11:08 PM, Tetsuo Handa wrote:
Hello.
I'm hitting WARN_ON() at try_get_page() from try_grab_page() due to page_ref_count(page) == -1021
(which is "3 - GUP_PIN_COUNTING_BIAS") if I use loadable kernel module version of TOMOYO security
module. Since I don't see recent changes in security/tomoyo regarding get_user_pages_remote(),
I'm wondering what is happening.
Hi Tetsuo,
Yes, commit 3faa52c03f440d1b ("mm/gup: track FOLL_PIN pages") is the one that turns everything on,
so if any problems with the whole FOLL_PIN scheme are to be found, it's natural that git bisect
would point to that commit.
Thanks for all the details here. One of the first questions I normally have is: is anything in the
system even using FOLL_PIN? And the way to answer that is to monitor the two new *foll_pin* entries
in /proc/vmstat, approximately like this:
$ cat /proc/vmstat |grep foll_pin
nr_foll_pin_acquired 0
nr_foll_pin_released 0
If you could do that before, during and after (ideally...or whatever you can get) the problem, I'd
love to see that data.
Also, if you happen to know if anything is calling pin_user_page*() and/or unpin_user_page*(), that
is extra credit. :)
I don't see anything here that jumps out at me, yet. The call stack below is as expected, and the WARN
often picks up problems that happened in some other calling path (something else leaked a FOLL_PIN
page for example, etc).
quick question below:
[ 10.427414][ T1] ------------[ cut here ]------------
[ 10.427425][ T1] WARNING: CPU: 3 PID: 1 at ./include/linux/mm.h:1009 try_grab_page+0x77/0x80
[ 10.427426][ T1] Modules linked in: caitsith(O) akari(O) xfs libcrc32c crc32c_generic sd_mod ata_generic pata_acpi mptspi scsi_transport_spi vmwgfx mptscsih drm_kms_helper mptbase cfbfillrect syscopyarea cfbimgblt sysfillrect sysimgblt fb_sys_fops cfbcopyarea fb ahci fbdev libahci ttm ata_piix nvme drm drm_panel_orientation_quirks libata nvme_core t10_pi agpgart e1000 i2c_core scsi_mod serio_raw atkbd libps2 i8042 serio unix
[ 10.427451][ T1] CPU: 3 PID: 1 Comm: akari-init Tainted: G O 5.6.0-05654-g3faa52c03f44 #984
[ 10.427452][ T1] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/29/2019
[ 10.427454][ T1] RIP: 0010:try_grab_page+0x77/0x80
[ 10.427456][ T1] Code: 34 85 c0 7e 25 f0 ff 47 34 b8 01 00 00 00 5d c3 0f 0b eb b1 48 8d 78 ff eb c6 0f 0b 31 c0 5d 0f 1f 40 00 c3 48 8d 78 ff eb d4 <0f> 0b 31 c0 5d c3 0f 1f 00 55 48 89 e5 41 57 49 89 cf 41 56 49 89
[ 10.427457][ T1] RSP: 0018:ffffa859c0013ac0 EFLAGS: 00010286
[ 10.427459][ T1] RAX: 00000000fffffc03 RBX: ffffcb6208c71dc0 RCX: 8000000231c77067
[ 10.427460][ T1] RDX: 8000000231c77067 RSI: 0000000000002016 RDI: ffffcb6208c71dc0
[ 10.427461][ T1] RBP: ffffa859c0013ac0 R08: 0000000000000001 R09: 0000000000000000
[ 10.427462][ T1] R10: 0000000000000001 R11: ffff95d91c615340 R12: 0000000000002016
[ 10.427463][ T1] R13: ffff95d91c615328 R14: 0000000000000ff0 R15: ffff95d91e0c0ff0
[ 10.427465][ T1] FS: 00007fbfc3772740(0000) GS:ffff95d927a00000(0000) knlGS:0000000000000000
[ 10.427479][ T1] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 10.427483][ T1] CR2: 0000000000ac5190 CR3: 000000022090a002 CR4: 00000000003606e0
[ 10.427491][ T1] Call Trace:
[ 10.427494][ T1] follow_page_pte+0x329/0x443
[ 10.427503][ T1] follow_p4d_mask+0x756/0x7c1
[ 10.427511][ T1] follow_page_mask+0x6a/0x70
[ 10.427516][ T1] __get_user_pages+0x110/0x880
[ 10.427518][ T1] ? ___slab_alloc.constprop.95+0x929/0x980
[ 10.427532][ T1] __get_user_pages_remote+0xce/0x230
[ 10.427540][ T1] get_user_pages_remote+0x27/0x40
[ 10.427545][ T1] ccs_dump_page+0x6a/0x140 [akari]
[ 10.427552][ T1] ccs_start_execve+0x28c/0x490 [akari]
[ 10.427555][ T1] ? ccs_start_execve+0x90/0x490 [akari]
[ 10.427561][ T1] ? ccs_load_policy+0xee/0x150 [akari]
[ 10.427568][ T1] ccs_bprm_check_security+0x4e/0x70 [akari]
...say, I can't find the ccs_*() routines in my tree, can you point me to them? Probably not
important but I'm curious now.
thanks,
--
John Hubbard
NVIDIA
[ 10.427572][ T1] security_bprm_check+0x26/0x40
[ 10.427576][ T1] search_binary_handler+0x22/0x1c0
[ 10.427580][ T1] __do_execve_file.isra.41+0x723/0xac0
[ 10.427581][ T1] ? __do_execve_file.isra.41+0x665/0xac0
[ 10.427590][ T1] __x64_sys_execve+0x44/0x50
[ 10.427614][ T1] do_syscall_64+0x4a/0x1e0
[ 10.427618][ T1] entry_SYSCALL_64_after_hwframe+0x49/0xb3
[ 10.427649][ T1] RIP: 0033:0x7fbfc2e36c37
[ 10.427651][ T1] Code: ff ff 76 df 89 c6 f7 de 64 41 89 32 eb d5 89 c6 f7 de 64 41 89 32 eb db 66 2e 0f 1f 84 00 00 00 00 00 90 b8 3b 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 02 f3 c3 48 8b 15 08 12 30 00 f7 d8 64 89 02
[ 10.427652][ T1] RSP: 002b:00007fff25f9c0f8 EFLAGS: 00000202 ORIG_RAX: 000000000000003b
[ 10.427654][ T1] RAX: ffffffffffffffda RBX: 0000000000ac64f0 RCX: 00007fbfc2e36c37
[ 10.427672][ T1] RDX: 0000000000ac6be0 RSI: 0000000000ac6ac0 RDI: 0000000000ac64f0
[ 10.427673][ T1] RBP: 0000000000000000 R08: 00007fff25f9c0e0 R09: 0000000000000000
[ 10.427674][ T1] R10: 00007fff25f9bb60 R11: 0000000000000202 R12: 0000000000ac6be0
[ 10.427675][ T1] R13: 0000000000ac6ac0 R14: 0000000000ac6be0 R15: 0000000000ac6820
[ 10.427701][ T1] irq event stamp: 10135190
[ 10.427704][ T1] hardirqs last enabled at (10135189): [<ffffffffb223092a>] __slab_alloc.constprop.94+0x48/0x5e
[ 10.427706][ T1] hardirqs last disabled at (10135190): [<ffffffffb2001eb7>] trace_hardirqs_off_thunk+0x1a/0x1c
[ 10.427707][ T1] softirqs last enabled at (10135114): [<ffffffffb2a0032b>] __do_softirq+0x32b/0x455
[ 10.427710][ T1] softirqs last disabled at (10135107): [<ffffffffb2072985>] irq_exit+0xa5/0xb0
[ 10.427711][ T1] ---[ end trace 984e9bd0ce5a1e09 ]---
+bool __must_check try_grab_page(struct page *page, unsigned int flags)
+{
+ WARN_ON_ONCE((flags & (FOLL_GET | FOLL_PIN)) == (FOLL_GET | FOLL_PIN));
+
+ if (flags & FOLL_GET)
+ return try_get_page(page);
+ else if (flags & FOLL_PIN) {
+ page = compound_head(page);
+
+ if (WARN_ON_ONCE(page_ref_count(page) <= 0))
+ return false;
+
+ page_ref_add(page, GUP_PIN_COUNTING_BIAS);
+ }
+
+ return true;
+}
Bisection says 3faa52c03f440d1b ("mm/gup: track FOLL_PIN pages") is the bad commit.
$ git bisect log
# bad: [3faa52c03f440d1b9ddef18c4f189f4790d52d7e] mm/gup: track FOLL_PIN pages
# good: [7111951b8d4973bda27ff663f2cf18b663d15b48] Linux 5.6
# good: [d5226fa6dbae0569ee43ecfc08bdcd6770fc4755] Linux 5.5
# good: [219d54332a09e8d8741c1e1982f5eae56099de85] Linux 5.4
# good: [4d856f72c10ecb060868ed10ff1b1453943fc6c8] Linux 5.3
# good: [0ecfebd2b52404ae0c54a878c872bb93363ada36] Linux 5.2
# good: [e93c9c99a629c61837d5a7fc2120cd2b6c70dbdd] Linux 5.1
# good: [1c163f4c7b3f621efff9b28a47abb36f7378d783] Linux 5.0
# good: [86dfbed49f88fd87ce8a12d2314b1f93266da7a7] mm/gup: pass a flags arg to __gup_device_* functions
# good: [83daf837884cc44c3cc0e4f8a096c5d1461cbcc2] mm/filemap.c: unexport find_get_entry
# good: [cc7b8f6245f0042a232c7f6807dc130d87233164] mm/page-writeback.c: write_cache_pages(): deduplicate identical checks
# good: [29d9f30d4ce6c7a38745a54a8cddface10013490] Merge git://git.kernel.org/pub/scm/linux/kernel/git/netdev/net-next
# good: [4afdb733b1606c6cb86e7833f9335f4870cf7ddd] io-uring: drop completion when removing file
git bisect start '3faa52c03f440d1b9ddef18c4f189f4790d52d7e' 'v5.6' 'v5.5' 'v5.4' 'v5.3' 'v5.2' 'v5.1' 'v5.0' '86dfbed49f88fd87ce8a12d2314b1f93266da7a7' '83daf837884cc44c3cc0e4f8a096c5d1461cbcc2' 'cc7b8f6245f0042a232c7f6807dc130d87233164' '29d9f30d4ce6c7a38745a54a8cddface10013490' '4afdb733b1606c6cb86e7833f9335f4870cf7ddd'
# good: [3b78d8347d31a050bb4f378a5f42cf495d873796] mm/gup: pass gup flags to two more routines
git bisect good 3b78d8347d31a050bb4f378a5f42cf495d873796
# good: [94202f126f698691f8865906ad6a68203e5dde8c] mm/gup: require FOLL_GET for get_user_pages_fast()
git bisect good 94202f126f698691f8865906ad6a68203e5dde8c
# first bad commit: [3faa52c03f440d1b9ddef18c4f189f4790d52d7e] mm/gup: track FOLL_PIN pages
