Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Enormous number of sync objects #200

Open
xairy opened this issue Sep 4, 2015 · 5 comments
Open

Enormous number of sync objects #200

xairy opened this issue Sep 4, 2015 · 5 comments
Labels
bug KTSAN KTSAN-related issues wontfix

Comments

@xairy
Copy link
Collaborator

xairy commented Sep 4, 2015 

Most syncs created at (totally 2300000):
 645794 [<     inlined    >] get_page_from_freelist+0x6ca/0xe20 atomic_read ./arch/x86/include/asm/atomic.h:31
 645794 [<     inlined    >] get_page_from_freelist+0x6ca/0xe20 check_new_page mm/page_alloc.c:1299
 645794 [<     inlined    >] get_page_from_freelist+0x6ca/0xe20 prep_new_page mm/page_alloc.c:1327
 645794 [<ffffffff811d583a>] get_page_from_freelist+0x6ca/0xe20 mm/page_alloc.c:2597
 608791 [<     inlined    >] __rmqueue+0x246/0x770 __SetPageBuddy ./arch/x86/include/asm/atomic.h:47
 608791 [<     inlined    >] __rmqueue+0x246/0x770 set_page_order mm/page_alloc.c:550
 608791 [<     inlined    >] __rmqueue+0x246/0x770 expand mm/page_alloc.c:1283
 608791 [<     inlined    >] __rmqueue+0x246/0x770 __rmqueue_smallest mm/page_alloc.c:1384
 608791 [<ffffffff811d4c46>] __rmqueue+0x246/0x770 mm/page_alloc.c:1660
 334873 [<     inlined    >] vunmap_page_range+0x27c/0x320 native_ptep_get_and_clear ./arch/x86/include/asm/pgtable_64.h:76
 334873 [<     inlined    >] vunmap_page_range+0x27c/0x320 ptep_get_and_clear ./arch/x86/include/asm/pgtable.h:749
 334873 [<     inlined    >] vunmap_page_range+0x27c/0x320 vunmap_pte_range mm/vmalloc.c:65
 334873 [<     inlined    >] vunmap_page_range+0x27c/0x320 vunmap_pmd_range mm/vmalloc.c:82
 334873 [<     inlined    >] vunmap_page_range+0x27c/0x320 vunmap_pud_range mm/vmalloc.c:98
 334873 [<ffffffff8122044c>] vunmap_page_range+0x27c/0x320 mm/vmalloc.c:113
 201060 [<     inlined    >] inet_twsk_purge+0x6e/0x1f0 __read_once_size include/linux/compiler.h:241
 201060 [<ffffffff81bfd5de>] inet_twsk_purge+0x6e/0x1f0 net/ipv4/inet_timewait_sock.c:295
  60067 [<     inlined    >] _raw_spin_lock+0x50/0x70 __raw_spin_lock include/linux/spinlock_api_smp.h:158
  60067 [<ffffffff81eb10e0>] _raw_spin_lock+0x50/0x70 kernel/locking/spinlock.c:151
  30868 [<     inlined    >] get_page_from_freelist+0x69f/0xe20 page_mapcount ./arch/x86/include/asm/atomic.h:31
  30868 [<     inlined    >] get_page_from_freelist+0x69f/0xe20 check_new_page mm/page_alloc.c:1295
  30868 [<     inlined    >] get_page_from_freelist+0x69f/0xe20 prep_new_page mm/page_alloc.c:1327
  30868 [<ffffffff811d580f>] get_page_from_freelist+0x69f/0xe20 mm/page_alloc.c:2597
  30308 [<     inlined    >] __d_lookup+0x96/0x2c0 __read_once_size include/linux/compiler.h:241
  30308 [<     inlined    >] __d_lookup+0x96/0x2c0 hlist_bl_first_rcu include/linux/rculist_bl.h:23
  30308 [<ffffffff812884c6>] __d_lookup+0x96/0x2c0 fs/dcache.c:2310
  26121 [<     inlined    >] __d_instantiate+0xc9/0x210 __read_once_size include/linux/compiler.h:240
  26121 [<     inlined    >] __d_instantiate+0xc9/0x210 __d_set_inode_and_type fs/dcache.c:283
  26121 [<ffffffff81283039>] __d_instantiate+0xc9/0x210 fs/dcache.c:1765
@xairy xairy self-assigned this Sep 4, 2015
@xairy
Copy link
Collaborator Author

xairy commented Sep 7, 2015

With the following changes

  • tame release and acquire clocks
  • don't create sync object on relaxed load if it doesn't exist
  • drop the two most frequently created sync objects (~500k instances each after running Trinity for 5 minutes)

after running KTSAN and Trinity for almost an hour (surprised that the kernel managed to live that long) we get:

Most syncs created at (totally 1310321):
 317039 [<     inlined    >] release_pages+0xb2/0x300 atomic_dec_and_test ./arch/x86/include/asm/atomic.h:151
 317039 [<     inlined    >] release_pages+0xb2/0x300 put_page_testzero include/linux/mm.h:345
 317039 [<ffffffff811ded82>] release_pages+0xb2/0x300 mm/swap.c:937
 283013 [<     inlined    >] shmem_getpage_gfp+0x627/0xc00 SetPageUptodate ./arch/x86/include/asm/bitops.h:86
 283013 [<ffffffff811ef397>] shmem_getpage_gfp+0x627/0xc00 mm/shmem.c:1217
 186054 [<     inlined    >] page_remove_rmap+0x31/0x40 atomic_add_negative ./arch/x86/include/asm/atomic.h:188
 186054 [<     inlined    >] page_remove_rmap+0x31/0x40 page_remove_file_rmap mm/rmap.c:1118
 186054 [<ffffffff8121d111>] page_remove_rmap+0x31/0x40 mm/rmap.c:1148
 132281 [<     inlined    >] page_add_file_rmap+0x28/0x60 atomic_inc_and_test ./arch/x86/include/asm/atomic.h:169
 132281 [<ffffffff8121d0a8>] page_add_file_rmap+0x28/0x60 mm/rmap.c:1104
  85209 [<     inlined    >] _raw_spin_lock+0x50/0x70 __raw_spin_lock include/linux/spinlock_api_smp.h:158
  85209 [<ffffffff81eb2090>] _raw_spin_lock+0x50/0x70 kernel/locking/spinlock.c:151
  56190 [<     inlined    >] __d_rehash+0xc0/0x100 hlist_bl_set_first_rcu include/linux/rculist_bl.h:16
  56190 [<     inlined    >] __d_rehash+0xc0/0x100 hlist_bl_add_head_rcu include/linux/rculist_bl.h:112
  56190 [<ffffffff812838d0>] __d_rehash+0xc0/0x100 fs/dcache.c:2431
  26131 [<     inlined    >] __d_instantiate+0xdd/0x210 __write_once_size include/linux/compiler.h:268
  26131 [<     inlined    >] __d_instantiate+0xdd/0x210 __d_set_inode_and_type fs/dcache.c:286
  26131 [<ffffffff81283fed>] __d_instantiate+0xdd/0x210 fs/dcache.c:1765
  24278 [<ffffffff81eaf057>] mutex_lock+0x57/0x70 kernel/locking/mutex.c:108
  15986 [<ffffffff815461b6>] radix_tree_insert+0x76/0x120 lib/radix-tree.c:462
  14528 [<     inlined    >] unlock_page+0x26/0xd0 clear_bit_unlock ./arch/x86/include/asm/bitops.h:146
  14528 [<ffffffff811c8446>] unlock_page+0x26/0xd0 mm/filemap.c:772
  13124 [<     inlined    >] __add_to_page_cache_locked+0x19b/0x370 radix_tree_replace_slot include/linux/radix-tree.h:260
  13124 [<     inlined    >] __add_to_page_cache_locked+0x19b/0x370 page_cache_tree_insert mm/filemap.c:547
  13124 [<ffffffff811c918b>] __add_to_page_cache_locked+0x19b/0x370 mm/filemap.c:597
  12672 [<ffffffff81290811>] dup_fd+0x2b1/0x570 fs/file.c:340
  10879 [<     inlined    >] __skb_clone+0x237/0x2d0 atomic_set ./arch/x86/include/asm/atomic.h:47 (discriminator 4)
  10879 [<ffffffff81b44627>] __skb_clone+0x237/0x2d0 net/core/skbuff.c:835 (discriminator 4)

The number of syncs objects is more or less stable:

[    4.935786] Most syncs created at (totally 34554):
[  127.722176] Most syncs created at (totally 243104):
[  131.444438] Most syncs created at (totally 250875):
[  133.608427] Most syncs created at (totally 256264):
[  135.308545] Most syncs created at (totally 263539):
[  137.308710] Most syncs created at (totally 275041):
[  141.909295] Most syncs created at (totally 293688):
[  146.002937] Most syncs created at (totally 297967):
[  168.805459] Most syncs created at (totally 361992):
[  182.016732] Most syncs created at (totally 374232):
[  190.508499] Most syncs created at (totally 375523):
[  220.700803] Most syncs created at (totally 388294):
[  241.806779] Most syncs created at (totally 393843):
[  247.520564] Most syncs created at (totally 389601):
[  306.664419] Most syncs created at (totally 994165):
[  358.087313] Most syncs created at (totally 1349838):
[  412.711400] Most syncs created at (totally 1276255):
[  494.430167] Most syncs created at (totally 1185293):
[  586.416514] Most syncs created at (totally 1281445):
[  686.069873] Most syncs created at (totally 1286231):
[ 1001.677572] Most syncs created at (totally 1190237):
[ 1073.923882] Most syncs created at (totally 1200666):
[ 1413.897642] Most syncs created at (totally 1261882):
[ 1831.994341] Most syncs created at (totally 1273099):
[ 2573.685708] Most syncs created at (totally 1308679):
[ 3002.649049] Most syncs created at (totally 1310321):

@xairy xairy changed the title Majority of sync objects are various page flags Enormous number of sync objects Sep 8, 2015
@xairy
Copy link
Collaborator Author

xairy commented Sep 8, 2015

With newer Trinity (1.5+) the number of objects doesn't seem to stabilize:

 368839 [<     inlined    >] atomic_dec_and_test ./arch/x86/include/asm/atomic.h:151
 368839 [<     inlined    >] put_page_testzero include/linux/mm.h:345
 368839 [<ffffffff811de329>] put_page+0x39/0x80 mm/swap.c:275
 354365 [<ffffffff81544846>] radix_tree_insert+0x76/0x120 lib/radix-tree.c:462
 325074 [<     inlined    >] set_bit ./arch/x86/include/asm/bitops.h:86
 325074 [<     inlined    >] SetPageUptodate include/linux/page-flags.h:367
 325074 [<ffffffff811ec7ba>] shmem_write_end+0x8a/0x280 mm/shmem.c:1510
 297269 [<     inlined    >] atomic_add_negative ./arch/x86/include/asm/atomic.h:188
 297269 [<     inlined    >] page_remove_file_rmap mm/rmap.c:1118
 297269 [<ffffffff8121cb81>] page_remove_rmap+0x31/0x40 mm/rmap.c:1148
  87623 [<     inlined    >] atomic_dec_and_test ./arch/x86/include/asm/atomic.h:151
  87623 [<     inlined    >] put_page_testzero include/linux/mm.h:345
  87623 [<ffffffff811de832>] release_pages+0xb2/0x300 mm/swap.c:937
  78579 [<     inlined    >] radix_tree_replace_slot include/linux/radix-tree.h:260
  78579 [<     inlined    >] page_cache_tree_insert mm/filemap.c:547
  78579 [<ffffffff811c8c3b>] __add_to_page_cache_locked+0x19b/0x370 mm/filemap.c:597
  70396 [<     inlined    >] test_and_set_bit ./arch/x86/include/asm/bitops.h:231
  70396 [<     inlined    >] test_set_buffer_dirty include/linux/buffer_head.h:118
  70396 [<ffffffff812b4427>] mark_buffer_dirty+0x67/0x190 fs/buffer.c:1176
  70319 [<     inlined    >] __raw_spin_lock include/linux/spinlock_api_smp.h:158
  70319 [<ffffffff81eb0710>] _raw_spin_lock+0x50/0x70 kernel/locking/spinlock.c:151
  67498 [<     inlined    >] clear_bit_unlock ./arch/x86/include/asm/bitops.h:146
  67498 [<ffffffff811c7ef6>] unlock_page+0x26/0xd0 mm/filemap.c:772
  45991 [<     inlined    >] hlist_bl_set_first_rcu include/linux/rculist_bl.h:16
  45991 [<     inlined    >] hlist_bl_add_head_rcu include/linux/rculist_bl.h:112
  45991 [<ffffffff81281f60>] __d_rehash+0xc0/0x100 fs/dcache.c:2431
  45296 [<     inlined    >] SetPageUptodate ./arch/x86/include/asm/bitops.h:86
  45296 [<ffffffff811eee47>] shmem_getpage_gfp+0x627/0xc00 mm/shmem.c:1217

[    3.797413] Most syncs created at (totally 34589):
[   84.652327] Most syncs created at (totally 95670):
[  103.153509] Most syncs created at (totally 225628):
[  106.670249] Most syncs created at (totally 312480):
[  111.116979] Most syncs created at (totally 355045):
[  117.035732] Most syncs created at (totally 449357):
[  127.565359] Most syncs created at (totally 609161):
[  140.653323] Most syncs created at (totally 649451):
[  149.602170] Most syncs created at (totally 694245):
[  180.947961] Most syncs created at (totally 1045190):
[  186.151220] Most syncs created at (totally 1059597):
[  200.242113] Most syncs created at (totally 1129513):
[  235.131424] Most syncs created at (totally 1111757):
[  258.685047] Most syncs created at (totally 1012138):
[  290.063308] Most syncs created at (totally 1003696):
[  290.063308] Most syncs created at (totally 1026690):
[  308.303944] Most syncs created at (totally 1093524):
[  383.200329] Most syncs created at (totally 1127557):
[  429.876396] Most syncs created at (totally 1163067):
[  563.889572] Most syncs created at (totally 1353929):
[  619.819463] Most syncs created at (totally 1308813):
[  682.397344] Most syncs created at (totally 1668977):
[  688.270962] Most syncs created at (totally 1695481):
[  792.522211] Most syncs created at (totally 1639250):
[ 1139.070932] Most syncs created at (totally 1696846):
[ 1237.656199] Most syncs created at (totally 1694812):
[ 1270.293016] Most syncs created at (totally 2000000):

The most used are still different page flags and refcounters.

@dvyukov
Copy link
Collaborator

dvyukov commented Sep 8, 2015

Maybe it uses more memory (allocates more pages)?

@xairy
Copy link
Collaborator Author

xairy commented Sep 8, 2015

Maybe.

It also creates sync objects from shmem_write_end, which didn't happen before.
But it's also probably caused by Trinity making more shmem-related things.

@xairy
Copy link
Collaborator Author

xairy commented Sep 9, 2015

With xchg() in vmalloc.c and all syncs from page_structs ignored the number of syncs objects is significantly lower and more or less stable:

Most syncs created at (totally 401563):
 114524 [<ffffffff815451e6>] radix_tree_insert+0x76/0x120 lib/radix-tree.c:462
  85629 [<     inlined    >] hlist_bl_set_first_rcu include/linux/rculist_bl.h:16
  85629 [<     inlined    >] hlist_bl_add_head_rcu include/linux/rculist_bl.h:112
  85629 [<ffffffff81282900>] __d_rehash+0xc0/0x100 fs/dcache.c:2431
  58903 [<     inlined    >] __raw_spin_lock include/linux/spinlock_api_smp.h:158
  58903 [<ffffffff81eb10b0>] _raw_spin_lock+0x50/0x70 kernel/locking/spinlock.c:151
  25248 [<     inlined    >] __write_once_size include/linux/compiler.h:268
  25248 [<     inlined    >] __d_set_inode_and_type fs/dcache.c:286
  25248 [<ffffffff8128301d>] __d_instantiate+0xdd/0x210 fs/dcache.c:1765
  20910 [<ffffffff81eae097>] mutex_lock+0x57/0x70 kernel/locking/mutex.c:108
  14080 [<ffffffff8128f841>] dup_fd+0x2b1/0x570 fs/file.c:340
  13060 [<     inlined    >] atomic_set ./arch/x86/include/asm/atomic.h:47 (discriminator 4)
  13060 [<ffffffff81b43677>] __skb_clone+0x237/0x2d0 net/core/skbuff.c:835 (discriminator 4)
   9554 [<     inlined    >] radix_tree_replace_slot include/linux/radix-tree.h:260
   9554 [<     inlined    >] page_cache_tree_insert mm/filemap.c:547
   9554 [<ffffffff811c8c4b>] __add_to_page_cache_locked+0x19b/0x370 mm/filemap.c:597
   7154 [<     inlined    >] atomic_dec_and_test ./arch/x86/include/asm/atomic.h:151 (discriminator 1)
   7154 [<ffffffff81320a94>] kernfs_put+0x34/0x2c0 fs/kernfs/dir.c:398 (discriminator 1)
   4095 [<     inlined    >] hlist_add_head_rcu include/linux/rculist.h:402 (discriminator 2)
   4095 [<ffffffff810b6b89>] alloc_pid+0x669/0x770 kernel/pid.c:344 (discriminator 2)
   4075 [<     inlined    >] clear_bit_unlock ./arch/x86/include/asm/bitops.h:146
   4075 [<ffffffff812b3cb7>] unlock_buffer+0x27/0x50 fs/buffer.c:76
   3403 [<     inlined    >] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:129
   3403 [<ffffffff81eb1404>] _raw_spin_lock_irqsave+0x64/0x80 kernel/locking/spinlock.c:159
   2788 [<ffffffff811313b7>] csd_unlock+0x37/0x60 kernel/smp.c:134 (discriminator 3)
   2436 [<     inlined    >] atomic_dec ./arch/x86/include/asm/atomic.h:134
   2436 [<     inlined    >] put_bh include/linux/buffer_head.h:281
   2436 [<ffffffff812b46f6>] __brelse+0x66/0x80 fs/buffer.c:1204
   2408 [<     inlined    >] __raw_spin_lock_irq include/linux/spinlock_api_smp.h:140
   2408 [<ffffffff81eb0a8c>] _raw_spin_lock_irq+0x5c/0x80 kernel/locking/spinlock.c:167

[    3.616783] Most syncs created at (totally 34212):
[   75.079492] Most syncs created at (totally 63110):
[   92.373540] Most syncs created at (totally 198955):
[   94.090444] Most syncs created at (totally 205105):
[   97.040194] Most syncs created at (totally 220600):
[  101.803175] Most syncs created at (totally 247523):
[  105.335322] Most syncs created at (totally 265583):
[  152.335160] Most syncs created at (totally 227410):
[  181.627497] Most syncs created at (totally 230083):
[  303.207605] Most syncs created at (totally 414132):
[  304.484186] Most syncs created at (totally 413539):
[  307.688989] Most syncs created at (totally 407402):
[  310.842688] Most syncs created at (totally 379310):
[  327.711834] Most syncs created at (totally 319068):
[  361.418038] Most syncs created at (totally 502182):
[  361.418038] Most syncs created at (totally 504821):
[  420.474099] Most syncs created at (totally 407051):
[  526.915723] Most syncs created at (totally 352157):
[  639.579130] Most syncs created at (totally 420157):
[  673.918992] Most syncs created at (totally 615566):
[  746.223397] Most syncs created at (totally 469673):
[  775.780021] Most syncs created at (totally 462315):
[  827.109435] Most syncs created at (totally 318354):
[  886.554361] Most syncs created at (totally 631652):
[ 1027.710317] Most syncs created at (totally 537458):
[ 1181.742846] Most syncs created at (totally 321810):
[ 1270.383560] Most syncs created at (totally 769576):
[ 1362.749303] Most syncs created at (totally 793958):
[ 1558.722168] Most syncs created at (totally 788634):
[ 1831.881138] Most syncs created at (totally 401606):
[ 2144.727357] Most syncs created at (totally 414302):
[ 2163.109000] Most syncs created at (totally 401563):

Syncs from radix_tree_insert might keep popping up up to 500k, but they eventually go away.

@xairy xairy transferred this issue from google/ktsan Dec 23, 2021
@xairy xairy added bug KTSAN KTSAN-related issues labels Dec 23, 2021
@xairy xairy removed their assignment Dec 23, 2021
@melver melver added the wontfix label Jan 25, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug KTSAN KTSAN-related issues wontfix
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@melver @dvyukov @xairy