Re: 5.14.0-rc1 KASAN use after free

Re: 5.14.0-rc1 KASAN use after free

[Oleksandr Natalenko]

+ Paolo, Jens et al.

On čtvrtek 15. července 2021 16:32:29 CEST jim.cromie@gmail.com wrote:
> hi all,
> 
> I noticed this report this morning, from 3 days ago,
> about 10 minutes after boot.
> Its easiest to ignore it, and I dont want to make a fuss,
> but it looks useful to someone
> 
> 
> [   33.663464] Bluetooth: RFCOMM ver 1.11
> [  646.343628]
> ================================================================== [ 
> 646.343649] BUG: KASAN: use-after-free in bfq_get_queue+0x47d/0x900 [ 
> 646.343680] Read of size 8 at addr ffff88810d864a00 by task
> journal-offline/1639
> 
> [  646.343708] CPU: 2 PID: 1639 Comm: journal-offline Not tainted
> 5.14.0-rc1-lm1 #66
> [  646.343730] Hardware name: TOSHIBA Satellite L55-C/06F4
>                , BIOS 1.20 10/08/2015
> [  646.343745] Call Trace:
> [  646.343757]  dump_stack_lvl+0x46/0x5a
> [  646.343781]  print_address_description.constprop.0+0x1f/0x140
> [  646.343808]  ? bfq_get_queue+0x47d/0x900
> [  646.343829]  kasan_report.cold+0x7f/0x11b
> [  646.343854]  ? bfq_init_bfqq+0x2a0/0x330
> [  646.343873]  ? bfq_get_queue+0x47d/0x900
> [  646.343895]  bfq_get_queue+0x47d/0x900
> [  646.343918]  ? bfq_merge_bfqqs+0x7a0/0x7a0
> [  646.343939]  ? _raw_write_unlock_bh+0x30/0x30
> [  646.343965]  bfq_get_bfqq_handle_split+0xa1/0x240
> [  646.343991]  bfq_init_rq+0x1e0/0x15e0
> [  646.344013]  ? submit_bio_noacct+0x7f0/0x7f0
> [  646.344036]  ? percpu_counter_add_batch+0x1f/0x90
> [  646.344059]  ? bfq_get_bfqq_handle_split+0x240/0x240
> [  646.344082]  ? btrfs_map_bio+0x404/0x830
> [  646.344100]  ? elv_rqhash_find+0x42/0x180
> [  646.344121]  ? _raw_spin_lock_irq+0x71/0xb0
> [  646.344142]  ? _raw_write_lock_irq+0xb0/0xb0
> [  646.344164]  bfq_insert_requests+0xe2/0x2a10
> [  646.344190]  ? btrfs_submit_data_bio+0x186/0x340
> [  646.344215]  ? submit_one_bio+0x81/0xc0
> [  646.344235]  ? bfq_request_merged+0x110/0x110
> [  646.344256]  ? blk_status_to_errno+0x20/0x30
> [  646.344279]  ? extent_write_locked_range+0x360/0x360
> [  646.344302]  ? btrfs_use_block_rsv+0x320/0x320
> [  646.344324]  blk_mq_sched_insert_requests+0xa6/0x1a0
> [  646.344347]  blk_mq_flush_plug_list+0x1fa/0x2f0
> [  646.344374]  ? blk_mq_insert_requests+0x1a0/0x1a0
> [  646.344399]  ? __filemap_fdatawrite_range+0x176/0x1c0
> [  646.344423]  blk_flush_plug_list+0x1d4/0x200
> [  646.344449]  ? blk_insert_cloned_request+0x170/0x170
> [  646.344476]  blk_finish_plug+0x3c/0x60
> [  646.344500]  start_ordered_ops.constprop.0+0xc3/0xf0
> [  646.344525]  ? btrfs_file_write_iter+0x5b0/0x5b0
> [  646.344554]  btrfs_sync_file+0x135/0x880
> [  646.344578]  ? rwsem_mark_wake+0x460/0x460
> [  646.344601]  ? start_ordered_ops.constprop.0+0xf0/0xf0
> [  646.344628]  ? vfs_fsync_range+0x86/0x100
> [  646.344650]  __x64_sys_fsync+0x3f/0x70
> [  646.344672]  do_syscall_64+0x3b/0x90
> [  646.344696]  entry_SYSCALL_64_after_hwframe+0x44/0xae
> [  646.344720] RIP: 0033:0x7f6eedeecebb
> [  646.344738] Code: 4a 00 00 00 0f 05 48 3d 00 f0 ff ff 77 41 c3 48
> 83 ec 18 89 7c 24 0c e8 53 f7 ff ff 8b 7c 24 0c 41 89 c0 b8 4a 00 00
> 00 0f 05 <48> 3d 00 f0 ff ff 77 35 44 89 c7 89 44 24 0c e8 b1 f7 ff ff
> 8b 44
> [  646.344760] RSP: 002b:00007f6ee919ca10 EFLAGS: 00000293 ORIG_RAX:
> 000000000000004a
> [  646.344784] RAX: ffffffffffffffda RBX: 00005614c6093620 RCX:
> 00007f6eedeecebb [  646.344801] RDX: 0000000000000002 RSI: 00007f6eee1cb9e2
> RDI: 0000000000000017 [  646.344815] RBP: 00007f6eee1cd610 R08:
> 0000000000000000 R09: 00007f6ee919d640 [  646.344830] R10: 0000000000000002
> R11: 0000000000000293 R12: 0000000000000002 [  646.344843] R13:
> 00007ffec2aede3f R14: 0000000000000000 R15: 00007f6ee919d640
> 
> [  646.344874] Allocated by task 1626:
> [  646.344886]  kasan_save_stack+0x1b/0x40
> [  646.344906]  __kasan_slab_alloc+0x61/0x80
> [  646.344924]  kmem_cache_alloc_node+0x151/0x2d0
> [  646.344942]  bfq_get_queue+0x209/0x900
> [  646.344961]  bfq_get_bfqq_handle_split+0xa1/0x240
> [  646.344982]  bfq_init_rq+0x1e0/0x15e0
> [  646.345001]  bfq_insert_requests+0xe2/0x2a10
> [  646.345020]  blk_mq_sched_insert_requests+0xa6/0x1a0
> [  646.345039]  blk_mq_flush_plug_list+0x1fa/0x2f0
> [  646.345060]  blk_flush_plug_list+0x1d4/0x200
> [  646.345082]  blk_finish_plug+0x3c/0x60
> [  646.345103]  start_ordered_ops.constprop.0+0xc3/0xf0
> [  646.345124]  btrfs_sync_file+0x135/0x880
> [  646.345144]  __x64_sys_fsync+0x3f/0x70
> [  646.345163]  do_syscall_64+0x3b/0x90
> [  646.345183]  entry_SYSCALL_64_after_hwframe+0x44/0xae
> 
> [  646.345212] The buggy address belongs to the object at ffff88810d864810
>                 which belongs to the cache bfq_queue of size 560
> [  646.345229] The buggy address is located 496 bytes inside of
>                 560-byte region [ffff88810d864810, ffff88810d864a40)
> [  646.345248] The buggy address belongs to the page:
> [  646.345258] page:0000000040e75441 refcount:1 mapcount:0
> mapping:0000000000000000 index:0xffff88810d864810 pfn:0x10d864
> [  646.345280] head:0000000040e75441 order:2 compound_mapcount:0
> compound_pincount:0
> [  646.345296] flags:
> 0x17ffffc0010200(slab|head|node=0|zone=2|lastcpupid=0x1fffff)
> [  646.345326] raw: 0017ffffc0010200 0000000000000000 dead000000000122
> ffff88810145b400
> [  646.345345] raw: ffff88810d864810 000000008017000f 00000001ffffffff
> 0000000000000000
> [  646.345357] page dumped because: kasan: bad access detected
> 
> [  646.345375] Memory state around the buggy address:
> [  646.345387]  ffff88810d864900: fb fb fb fb fb fb fb fb fb fb fb fb
> fb fb fb fb
> [  646.345403]  ffff88810d864980: fb fb fb fb fb fb fb fb fb fb fb fb
> fb fb fb fb
> [  646.345417] >ffff88810d864a00: fb fb fb fb fb fb fb fb fc fc fc fc
> fc fc fc fc
> [  646.345428]                    ^
> [  646.345441]  ffff88810d864a80: fc fc fc fc fc fc fc fc fb fb fb fb
> fb fb fb fb
> [  646.345455]  ffff88810d864b00: fb fb fb fb fb fb fb fb fb fb fb fb
> fb fb fb fb
> [  646.345467]
> ================================================================== [ 
> 646.345476] Disabling lock debugging due to kernel taint
> [20632.749805] rfkill: input handler enabled
> [20636.319701] rfkill: input handler disabled
> [22201.638710] perf: interrupt took too long (2514 > 2500), lowering
> kernel.perf_event_max_sample_rate to 79000
> [22539.009414] perf: interrupt took too long (3145 > 3142), lowering
> kernel.perf_event_max_sample_rate to 63000
> [23091.879235] perf: interrupt took too long (3960 > 3931), lowering
> kernel.perf_event_max_sample_rate to 50000
> [24206.193740] perf: interrupt took too long (4972 > 4950), lowering
> kernel.perf_event_max_sample_rate to 40000
> [25306.264832] L1TF CPU bug present and SMT on, data leak possible.
> See CVE-2018-3646 and
> https://www.kernel.org/doc/html/latest/admin-guide/hw-vuln/l1tf.html
> for details.
> [38172.611967] nf_conntrack: default automatic helper assignment has
> been turned off for security reasons and CT-based firewall rule not
> found. Use the iptables CT target to attach helpers instead.
> [123082.553154] psmouse serio2: bad data from KBC - timeout
> [211716.941601] ------------[ cut here ]------------
> [211716.941610] cfs_rq->avg.load_avg || cfs_rq->avg.util_avg ||
> cfs_rq->avg.runnable_avg
> [211716.941619] WARNING: CPU: 4 PID: 33 at kernel/sched/fair.c:3307
> update_blocked_averages+0xb7c/0xbf0
> [211716.941641] Modules linked in: uinput rfcomm xt_CHECKSUM
> xt_MASQUERADE xt_conntrack ipt_REJECT nf_nat_tftp nf_conntrack_tftp
> bridge stp llc ccm nft_objref nf_conntrack_netbios_ns
> nf_conntrack_broadcast nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib
> nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct
> nft_chain_nat ip6table_nat ip6table_mangle ip6table_raw
> ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6
> nf_defrag_ipv4 iptable_mangle iptable_raw iptable_security ip_set
> nf_tables nfnetlink ip6table_filter ip6_tables iptable_filter cmac
> bnep sunrpc vfat iwlmvm fat snd_hda_codec_hdmi intel_rapl_msr mac80211
> snd_hda_codec_conexant at24 snd_hda_codec_generic ledtrig_audio
> iTCO_wdt intel_pmc_bxt mei_hdcp iTCO_vendor_support libarc4
> intel_wmi_thunderbolt wmi_bmof uvcvideo btusb snd_hda_intel btrtl
> btbcm snd_intel_dspcfg videobuf2_vmalloc videobuf2_memops btintel
> videobuf2_v4l2 videobuf2_common intel_rapl_common snd_hda_codec
> x86_pkg_temp_thermal iwlwifi
> [211716.941813]  intel_powerclamp videodev coretemp snd_hwdep rapl
> snd_hda_core bluetooth intel_cstate snd_seq mc intel_uncore joydev
> snd_seq_device ecdh_generic cfg80211 ecc pcspkr snd_pcm snd_timer
> mei_me snd toshiba_acpi i2c_i801 mei sparse_keymap soundcore
> industrialio i2c_smbus toshiba_bluetooth rfkill wmi acpi_pad ip_tables
> rtsx_pci_sdmmc mmc_core crct10dif_pclmul crc32_pclmul i915
> crc32c_intel i2c_algo_bit ttm ghash_clmulni_intel serio_raw r8169
> drm_kms_helper cec rtsx_pci drm video fuse
> [211716.941897] CPU: 4 PID: 33 Comm: ksoftirqd/4 Tainted: G    B
>       5.14.0-rc1-lm1 #66
> [211716.941903] Hardware name: TOSHIBA Satellite L55-C/06F4
>                 , BIOS 1.20 10/08/2015
> [211716.941907] RIP: 0010:update_blocked_averages+0xb7c/0xbf0
> [211716.941916] Code: c0 5e ab 90 c6 05 98 15 a7 02 01 e8 21 48 14 01
> 0f 0b e9 13 f6 ff ff 48 c7 c7 20 5f ab 90 c6 05 7a 15 a7 02 01 e8 07
> 48 14 01 <0f> 0b 48 8b 7c 24 20 e8 38 61 31 00 45 8b af 38 01 00 00 e9
> e3 f9
> [211716.941921] RSP: 0018:ffff888100fefc58 EFLAGS: 00010082
> [211716.941926] RAX: 0000000000000000 RBX: ffff88821bb334c0 RCX:
> 0000000000000000
> [211716.941930] RDX: 0000000000000027 RSI: 0000000000000004 RDI:
> ffffed10201fdf81
> [211716.941934] RBP: ffff88821bb32de0 R08: ffffffff8f3f445e R09:
> ffff88821bb20a8b
> [211716.941937] R10: ffffed1043764151 R11: 0000000000000001 R12:
> ffffffff927d77c0
> [211716.941941] R13: 0000000000000001 R14: ffff88821bb33728 R15:
> ffff88821bb32d40
> [211716.941945] FS:  0000000000000000(0000) GS:ffff88821bb00000(0000)
> knlGS:0000000000000000
> [211716.941949] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [211716.941952] CR2: 0000556174b0d040 CR3: 0000000140414001 CR4:
> 00000000003726e0
> [211716.941956] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
> 0000000000000000
> [211716.941959] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
> 0000000000000400
> [211716.941963] Call Trace:
> [211716.941968]  newidle_balance+0x34d/0x6b0
> [211716.941974]  ? update_cfs_group+0x1e/0x150
> [211716.941980]  ? load_balance+0x1290/0x1290
> [211716.941985]  ? update_min_vruntime+0x44/0xc0
> [211716.941991]  pick_next_task_fair+0x59/0x660
> [211716.941997]  __schedule+0x225/0xeb0
> [211716.942005]  ? io_schedule_timeout+0xb0/0xb0
> [211716.942011]  ? __do_softirq+0x209/0x373
> [211716.942017]  schedule+0x6d/0x120
> [211716.942023]  smpboot_thread_fn+0x1b7/0x250
> [211716.942030]  ? smpboot_register_percpu_thread+0x190/0x190
> [211716.942036]  kthread+0x1d2/0x200
> [211716.942041]  ? set_kthread_struct+0x80/0x80
> [211716.942046]  ret_from_fork+0x22/0x30
> [211716.942055] ---[ end trace ee8f02e72a76fda7 ]---
> [256577.295169] show_signal_msg: 4 callbacks suppressed
> [256577.295176] gnome-shell[2236]: segfault at 18 ip 00007f16ab0563ee
> sp 00007ffcd6601570 error 4 in libgjs.so.0.0.0[7f16ab025000+92000]
> [256577.295205] Code: ec 30 64 48 8b 04 25 28 00 00 00 48 89 44 24 28
> 31 c0 e8 05 32 00 00 48 89 c3 e8 8d 36 fd ff 48 89 c7 e8 c5 30 fd ff
> 48 89 c5 <48> 8b 43 18 48 85 c0 0f 84 85 00 00 00 48 8b 50 18 48 8d 45
> 18 49
> [256588.051436] rfkill: input handler enabled


-- 
Oleksandr Natalenko (post-factum)

Re: 5.14.0-rc1 KASAN use after free

[Jens Axboe]

[-- Attachment #1: Type: text/plain, Size: 867 bytes --]

On 7/18/21 3:08 PM, Oleksandr Natalenko wrote:
> + Paolo, Jens et al.
> 
> On čtvrtek 15. července 2021 16:32:29 CEST jim.cromie@gmail.com wrote:
>> hi all,
>>
>> I noticed this report this morning, from 3 days ago,
>> about 10 minutes after boot.
>> Its easiest to ignore it, and I dont want to make a fuss,
>> but it looks useful to someone
>>
>>
>> [   33.663464] Bluetooth: RFCOMM ver 1.11
>> [  646.343628]
>> ================================================================== [ 
>> 646.343649] BUG: KASAN: use-after-free in bfq_get_queue+0x47d/0x900 [ 
>> 646.343680] Read of size 8 at addr ffff88810d864a00 by task
>> journal-offline/1639

There are only a few commits between 5.13 and master in this area, see
attached. I'd just start reverting from the top, one by one, and see
which one is causing the issue. Jim, would that be feasible?

-- 
Jens Axboe


[-- Attachment #2: bfq-commit-list.txt --]
[-- Type: text/plain, Size: 13584 bytes --]

commit fd2ef39cc9a6b9c4c41864ac506906c52f94b06a
Author: Jan Kara <jack@suse.cz>
Date:   Wed Jun 23 11:36:34 2021 +0200

    blk: Fix lock inversion between ioc lock and bfqd lock
    
    Lockdep complains about lock inversion between ioc->lock and bfqd->lock:
    
    bfqd -> ioc:
     put_io_context+0x33/0x90 -> ioc->lock grabbed
     blk_mq_free_request+0x51/0x140
     blk_put_request+0xe/0x10
     blk_attempt_req_merge+0x1d/0x30
     elv_attempt_insert_merge+0x56/0xa0
     blk_mq_sched_try_insert_merge+0x4b/0x60
     bfq_insert_requests+0x9e/0x18c0 -> bfqd->lock grabbed
     blk_mq_sched_insert_requests+0xd6/0x2b0
     blk_mq_flush_plug_list+0x154/0x280
     blk_finish_plug+0x40/0x60
     ext4_writepages+0x696/0x1320
     do_writepages+0x1c/0x80
     __filemap_fdatawrite_range+0xd7/0x120
     sync_file_range+0xac/0xf0
    
    ioc->bfqd:
     bfq_exit_icq+0xa3/0xe0 -> bfqd->lock grabbed
     put_io_context_active+0x78/0xb0 -> ioc->lock grabbed
     exit_io_context+0x48/0x50
     do_exit+0x7e9/0xdd0
     do_group_exit+0x54/0xc0
    
    To avoid this inversion we change blk_mq_sched_try_insert_merge() to not
    free the merged request but rather leave that upto the caller similarly
    to blk_mq_sched_try_merge(). And in bfq_insert_requests() we make sure
    to free all the merged requests after dropping bfqd->lock.
    
    Fixes: aee69d78dec0 ("block, bfq: introduce the BFQ-v0 I/O scheduler as an extra scheduler")
    Reviewed-by: Ming Lei <ming.lei@redhat.com>
    Acked-by: Paolo Valente <paolo.valente@linaro.org>
    Signed-off-by: Jan Kara <jack@suse.cz>
    Link: https://lore.kernel.org/r/20210623093634.27879-3-jack@suse.cz
    Signed-off-by: Jens Axboe <axboe@kernel.dk>

commit a921c655f2033dd1ce1379128efe881dda23ea37
Author: Jan Kara <jack@suse.cz>
Date:   Wed Jun 23 11:36:33 2021 +0200

    bfq: Remove merged request already in bfq_requests_merged()
    
    Currently, bfq does very little in bfq_requests_merged() and handles all
    the request cleanup in bfq_finish_requeue_request() called from
    blk_mq_free_request(). That is currently safe only because
    blk_mq_free_request() is called shortly after bfq_requests_merged()
    while bfqd->lock is still held. However to fix a lock inversion between
    bfqd->lock and ioc->lock, we need to call blk_mq_free_request() after
    dropping bfqd->lock. That would mean that already merged request could
    be seen by other processes inside bfq queues and possibly dispatched to
    the device which is wrong. So move cleanup of the request from
    bfq_finish_requeue_request() to bfq_requests_merged().
    
    Acked-by: Paolo Valente <paolo.valente@linaro.org>
    Signed-off-by: Jan Kara <jack@suse.cz>
    Link: https://lore.kernel.org/r/20210623093634.27879-2-jack@suse.cz
    Signed-off-by: Jens Axboe <axboe@kernel.dk>

commit 9a2ac41b13c573703d6689f51f3e27dd658324be
Author: Paolo Valente <paolo.valente@linaro.org>
Date:   Sat Jun 19 16:09:48 2021 +0200

    block, bfq: reset waker pointer with shared queues
    
    Commit 85686d0dc194 ("block, bfq: keep shared queues out of the waker
    mechanism") leaves shared bfq_queues out of the waker-detection
    mechanism. It attains this goal by not updating the pointer
    last_completed_rq_bfqq, if the last request completed belongs to a
    shared bfq_queue (so that the pointer will not point to the shared
    bfq_queue).
    
    Yet this has a side effect: the pointer last_completed_rq_bfqq keeps
    pointing, deceptively, to a bfq_queue that actually is not the last
    one to have had a request completed. As a consequence, such a
    bfq_queue may deceptively be considered as a waker of some bfq_queue,
    even of some shared bfq_queue.
    
    To address this issue, reset last_completed_rq_bfqq if the last
    request completed belongs to a shared queue.
    
    Fixes: 85686d0dc194 ("block, bfq: keep shared queues out of the waker mechanism")
    Signed-off-by: Paolo Valente <paolo.valente@linaro.org>
    Link: https://lore.kernel.org/r/20210619140948.98712-8-paolo.valente@linaro.org
    Signed-off-by: Jens Axboe <axboe@kernel.dk>

commit efc72524b3a9e4e7bc7c07f756528736409ec1b7
Author: Paolo Valente <paolo.valente@linaro.org>
Date:   Sat Jun 19 16:09:47 2021 +0200

    block, bfq: check waker only for queues with no in-flight I/O
    
    Consider two bfq_queues, say Q1 and Q2, with Q2 empty. If a request of
    Q1 gets completed shortly before a new request arrives for Q2, then
    BFQ flags Q1 as a candidate waker for Q2. Yet, the arrival of this new
    request may have a different cause, in the following case. If also Q2
    has requests in flight while waiting for the arrival of a new request,
    then the completion of its own requests may be the actual cause of the
    awakening of the process that sends I/O to Q2. So Q1 may be flagged
    wrongly as a candidate waker.
    
    This commit avoids this deceptive flagging, by disabling
    candidate-waker flagging for Q2, if Q2 has in-flight I/O.
    
    Signed-off-by: Paolo Valente <paolo.valente@linaro.org>
    Link: https://lore.kernel.org/r/20210619140948.98712-7-paolo.valente@linaro.org
    Signed-off-by: Jens Axboe <axboe@kernel.dk>

commit bd3664b362381c4c1473753ebedf0ab242a60d1d
Author: Paolo Valente <paolo.valente@linaro.org>
Date:   Sat Jun 19 16:09:46 2021 +0200

    block, bfq: avoid delayed merge of async queues
    
    Since commit 430a67f9d616 ("block, bfq: merge bursts of newly-created
    queues"), BFQ may schedule a merge between a newly created sync
    bfq_queue, say Q2, and the last sync bfq_queue created, say Q1. To this
    goal, BFQ stores the address of Q1 in the field bic->stable_merge_bfqq
    of the bic associated with Q2. So, when the time for the possible merge
    arrives, BFQ knows which bfq_queue to merge Q2 with. In particular,
    BFQ checks for possible merges on request arrivals.
    
    Yet the same bic may also be associated with an async bfq_queue, say
    Q3. So, if a request for Q3 arrives, then the above check may happen
    to be executed while the bfq_queue at hand is Q3, instead of Q2. In
    this case, Q1 happens to be merged with an async bfq_queue. This is
    not only a conceptual mistake, because async queues are to be kept out
    of queue merging, but also a bug that leads to inconsistent states.
    
    This commits simply filters async queues out of delayed merges.
    
    Fixes: 430a67f9d616 ("block, bfq: merge bursts of newly-created queues")
    Tested-by: Holger Hoffstätte <holger@applied-asynchrony.com>
    Signed-off-by: Paolo Valente <paolo.valente@linaro.org>
    Link: https://lore.kernel.org/r/20210619140948.98712-6-paolo.valente@linaro.org
    Signed-off-by: Jens Axboe <axboe@kernel.dk>

commit 7812472f973047a886e4ed9a91d98d6627dd746f
Author: Pietro Pedroni <pedroni.pietro.96@gmail.com>
Date:   Sat Jun 19 16:09:45 2021 +0200

    block, bfq: boost throughput by extending queue-merging times
    
    One of the methods with which bfq boosts throughput is by merging queues.
    One of the merging variants in bfq is the stable merge.
    This mechanism is activated between two queues only if they are created
    within a certain maximum time T1 from each other.
    Merging can happen soon or be delayed. In the second case, before
    merging, bfq needs to evaluate a throughput-boost parameter that
    indicates whether the queue generates a high throughput is served alone.
    Merging occurs when this throughput-boost is not high enough.
    In particular, this parameter is evaluated and late merging may occur
    only after at least a time T2 from the creation of the queue.
    
    Currently T1 and T2 are set to 180ms and 200ms, respectively.
    In this way the merging mechanism rarely occurs because time is not
    enough. This results in a noticeable lowering of the overall throughput
    with some workloads (see the example below).
    
    This commit introduces two constants bfq_activation_stable_merging and
    bfq_late_stable_merging in order to increase the duration of T1 and T2.
    Both the stable merging activation time and the late merging
    time are set to 600ms. This value has been experimentally evaluated
    using sqlite benchmark in the Phoronix Test Suite on a HDD.
    The duration of the benchmark before this fix was 111.02s, while now
    it has reached 97.02s, a better result than that of all the other
    schedulers.
    
    Signed-off-by: Pietro Pedroni <pedroni.pietro.96@gmail.com>
    Signed-off-by: Paolo Valente <paolo.valente@linaro.org>
    Link: https://lore.kernel.org/r/20210619140948.98712-5-paolo.valente@linaro.org
    Signed-off-by: Jens Axboe <axboe@kernel.dk>

commit d4f49983fa3944416c28379c35fbe10c68455ea4
Author: Paolo Valente <paolo.valente@linaro.org>
Date:   Sat Jun 19 16:09:44 2021 +0200

    block, bfq: consider also creation time in delayed stable merge
    
    Since commit 430a67f9d616 ("block, bfq: merge bursts of newly-created
    queues"), BFQ may schedule a merge between a newly created sync
    bfq_queue and the last sync bfq_queue created. Such a merging is not
    performed immediately, because BFQ needs first to find out whether the
    newly created queue actually reaches a higher throughput if not merged
    at all (and in that case BFQ will not perform any stable merging). To
    check that, a little time must be waited after the creation of the new
    queue, so that some I/O can flow in the queue, and statistics on such
    I/O can be computed.
    
    Yet, to evaluate the above waiting time, the last split time is
    considered as start time, instead of the creation time of the
    queue. This is a mistake, because considering the split time is
    correct only in the following scenario.
    
    The queue undergoes a non-stable merges on the arrival of its very
    first I/O request, due to close I/O with some other queue. While the
    queue is merged for close I/O, stable merging is not considered. Yet
    the queue may then happen to be split, if the close I/O finishes (or
    happens to be a false positive). From this time on, the queue can
    again be considered for stable merging. But, again, a little time must
    elapse, to let some new I/O flow in the queue and to get updated
    statistics. To wait for this time, the split time is to be taken into
    account.
    
    Yet, if the queue does not undergo a non-stable merge on the arrival
    of its very first request, then BFQ immediately checks whether the
    stable merge is to be performed. It happens because the split time for
    a queue is initialized to minus infinity when the queue is created.
    
    This commit fixes this mistake by adding the missing condition. Now
    the check for delayed stable-merge is performed after a little time is
    elapsed not only from the last queue split time, but also from the
    creation time of the queue.
    
    Fixes: 430a67f9d616 ("block, bfq: merge bursts of newly-created queues")
    Signed-off-by: Paolo Valente <paolo.valente@linaro.org>
    Link: https://lore.kernel.org/r/20210619140948.98712-4-paolo.valente@linaro.org
    Signed-off-by: Jens Axboe <axboe@kernel.dk>

commit e03f2ab78a4a673e4af23c3b855591c48b9de4d7
Author: Luca Mariotti <mariottiluca1@hotmail.it>
Date:   Sat Jun 19 16:09:43 2021 +0200

    block, bfq: fix delayed stable merge check
    
    When attempting to schedule a merge of a given bfq_queue with the currently
    in-service bfq_queue or with a cooperating bfq_queue among the scheduled
    bfq_queues, delayed stable merge is checked for rotational or non-queueing
    devs. For this stable merge to be performed, some conditions must be met.
    If the current bfq_queue underwent some split from some merged bfq_queue,
    one of these conditions is that two hundred milliseconds must elapse from
    split, otherwise this condition is always met.
    
    Unfortunately, by mistake, time_is_after_jiffies() was written instead of
    time_is_before_jiffies() for this check, verifying that less than two
    hundred milliseconds have elapsed instead of verifying that at least two
    hundred milliseconds have elapsed.
    
    Fix this issue by replacing time_is_after_jiffies() with
    time_is_before_jiffies().
    
    Signed-off-by: Luca Mariotti <mariottiluca1@hotmail.it>
    Signed-off-by: Paolo Valente <paolo.valente@unimore.it>
    Signed-off-by: Pietro Pedroni <pedroni.pietro.96@gmail.com>
    Link: https://lore.kernel.org/r/20210619140948.98712-3-paolo.valente@linaro.org
    Signed-off-by: Jens Axboe <axboe@kernel.dk>

commit 511a2699237611b062df7798476bf3a1392910b9
Author: Paolo Valente <paolo.valente@linaro.org>
Date:   Sat Jun 19 16:09:42 2021 +0200

    block, bfq: let also stably merged queues enjoy weight raising
    
    Merged bfq_queues are kept out of weight-raising (low-latency)
    mechanisms. The reason is that these queues are usually created for
    non-interactive and non-soft-real-time tasks. Yet this is not the case
    for stably-merged queues. These queues are merged just because they
    are created shortly after each other. So they may easily serve the I/O
    of an interactive or soft-real time application, if the application
    happens to spawn multiple processes.
    
    To address this issue, this commits lets also stably-merged queued
    enjoy weight raising.
    
    Signed-off-by: Paolo Valente <paolo.valente@linaro.org>
    Link: https://lore.kernel.org/r/20210619140948.98712-2-paolo.valente@linaro.org
    Signed-off-by: Jens Axboe <axboe@kernel.dk>

Re: 5.14.0-rc1 KASAN use after free

[jim.cromie]

On Sun, Jul 18, 2021 at 5:58 PM Jens Axboe <axboe@kernel.dk> wrote:
>
> On 7/18/21 3:08 PM, Oleksandr Natalenko wrote:
> > + Paolo, Jens et al.
> >
> > On čtvrtek 15. července 2021 16:32:29 CEST jim.cromie@gmail.com wrote:
> >> hi all,
> >>
> >> I noticed this report this morning, from 3 days ago,
> >> about 10 minutes after boot.
> >> Its easiest to ignore it, and I dont want to make a fuss,
> >> but it looks useful to someone
> >>
> >>
> >> [   33.663464] Bluetooth: RFCOMM ver 1.11
> >> [  646.343628]
> >> ================================================================== [
> >> 646.343649] BUG: KASAN: use-after-free in bfq_get_queue+0x47d/0x900 [
> >> 646.343680] Read of size 8 at addr ffff88810d864a00 by task
> >> journal-offline/1639
>
> There are only a few commits between 5.13 and master in this area, see
> attached. I'd just start reverting from the top, one by one, and see
> which one is causing the issue. Jim, would that be feasible?
>

oops, didn't see this earlier.
It hasnt happened since, I can try to recreate mid-next-week


> --
> Jens Axboe
>

Re: 5.14.0-rc1 KASAN use after free

[Paolo Valente]

> Il giorno 23 lug 2021, alle ore 15:08, jim.cromie@gmail.com ha scritto:
> 
> On Sun, Jul 18, 2021 at 5:58 PM Jens Axboe <axboe@kernel.dk> wrote:
>> 
>> On 7/18/21 3:08 PM, Oleksandr Natalenko wrote:
>>> + Paolo, Jens et al.
>>> 
>>> On čtvrtek 15. července 2021 16:32:29 CEST jim.cromie@gmail.com wrote:
>>>> hi all,
>>>> 
>>>> I noticed this report this morning, from 3 days ago,
>>>> about 10 minutes after boot.
>>>> Its easiest to ignore it, and I dont want to make a fuss,
>>>> but it looks useful to someone
>>>> 
>>>> 
>>>> [   33.663464] Bluetooth: RFCOMM ver 1.11
>>>> [  646.343628]
>>>> ================================================================== [
>>>> 646.343649] BUG: KASAN: use-after-free in bfq_get_queue+0x47d/0x900 [
>>>> 646.343680] Read of size 8 at addr ffff88810d864a00 by task
>>>> journal-offline/1639
>> 
>> There are only a few commits between 5.13 and master in this area, see
>> attached. I'd just start reverting from the top, one by one, and see
>> which one is causing the issue. Jim, would that be feasible?
>> 
> 
> oops, didn't see this earlier.
> It hasnt happened since, I can try to recreate mid-next-week
> 

Still nothing?

Thanks,
Paolo

> 
>> --
>> Jens Axboe

Re: 5.14.0-rc1 KASAN use after free

[jim.cromie]

On Mon, Aug 2, 2021 at 8:21 AM Paolo Valente <paolo.valente@linaro.org> wrote:
>
>
>
> > Il giorno 23 lug 2021, alle ore 15:08, jim.cromie@gmail.com ha scritto:
> >
> > On Sun, Jul 18, 2021 at 5:58 PM Jens Axboe <axboe@kernel.dk> wrote:
> >>
> >> On 7/18/21 3:08 PM, Oleksandr Natalenko wrote:
> >>> + Paolo, Jens et al.
> >>>
> >>> On čtvrtek 15. července 2021 16:32:29 CEST jim.cromie@gmail.com wrote:
> >>>> hi all,
> >>>>
> >>>> I noticed this report this morning, from 3 days ago,
> >>>> about 10 minutes after boot.
> >>>> Its easiest to ignore it, and I dont want to make a fuss,
> >>>> but it looks useful to someone
> >>>>
> >>>>
> >>>> [   33.663464] Bluetooth: RFCOMM ver 1.11
> >>>> [  646.343628]
> >>>> ================================================================== [
> >>>> 646.343649] BUG: KASAN: use-after-free in bfq_get_queue+0x47d/0x900 [
> >>>> 646.343680] Read of size 8 at addr ffff88810d864a00 by task
> >>>> journal-offline/1639
> >>
> >> There are only a few commits between 5.13 and master in this area, see
> >> attached. I'd just start reverting from the top, one by one, and see
> >> which one is causing the issue. Jim, would that be feasible?
> >>
> >
> > oops, didn't see this earlier.
> > It hasnt happened since, I can try to recreate mid-next-week
> >
>
> Still nothing?
>

Nada.

up to an hour ago, I was still running that installed kernel.
I just rebooted to it and ran a virtme session on it
(because of a possible 9p related trigger)
no sign of kasan err.

Im gonna boot rc4 built in the same build-dir,
I dont think Ive messed with the config,
but its a long-shot anyway to reproduce,
since same kernel image didnt do it 2nd time.


> Thanks,
> Paolo
>
> >
> >> --
> >> Jens Axboe
>