|
Hi, all I found a 300ms~600ms IRQ off when writing 1Gb data to mmc device at I.MX7d SDB board at Linux-kernel-v6.14. But I test the same case at Linux-kernel-v6.7, this longest IRQ off time is only 1ms~2ms. So the issue is introduced from v6.7~v6.14. Run this cmd to test: dd if=/dev/zero of=/dev/mmcblk2p4 bs=4096 seek=12500 count=256000 conv=fsync This issue looks from blkdev_buffered_write() function. Because when I run this cmd with “oflag=direct” to use
blkdev_direct_write(), I can not see any long time IRQ off. Then I use Ftrace irqoff tracer to trace the longest IRQ off event, I found some differences between v6.7 and v6.14: In iomap_file_buffered_write(), __folio_alloc (in v6.7) is replaced by _folio_alloc_noprof (in v6.14) by this patch. The spinlock disabled IRQ ~300ms+. It looks there are some fixes for this patch, but I still can see IRQ off 300ms+ at 6.14.0-rc7-next-20250319. Do I trigger one bug? I know little about mem so I have to report it and hope I can get some help or guide. I put my ftrace log at the mail tail to help trace and explain. commit b951aaff503502a7fe066eeed2744ba8a6413c89 Author: Suren Baghdasaryan
surenb@xxxxxxxxxx Date: Thu Mar 21 09:36:40 2024 -0700 mm: enable page allocation tagging Redefine page allocators to record allocation tags upon their invocation. Instrument post_alloc_hook and free_pages_prepare to modify current allocation tag. [surenb@xxxxxxxxxx: undo _noprof additions in the documentation] Link:
https://lkml.kernel.org/r/20240326231453.1206227-3-surenb@xxxxxxxxxx Link:
https://lkml.kernel.org/r/20240321163705.3067592-19-surenb@xxxxxxxxxx Signed-off-by: Suren Baghdasaryan
surenb@xxxxxxxxxx Co-developed-by: Kent Overstreet
kent.overstreet@xxxxxxxxx Signed-off-by: Kent Overstreet
kent.overstreet@xxxxxxxxx Reviewed-by: Kees Cook
keescook@xxxxxxxxxxxx Tested-by: Kees Cook
keescook@xxxxxxxxxxxx Cc: Alexander Viro
viro@xxxxxxxxxxxxxxxxxx Cc: Alex Gaynor
alex.gaynor@xxxxxxxxx Cc: Alice Ryhl
aliceryhl@xxxxxxxxxx Cc: Andreas Hindborg
a.hindborg@xxxxxxxxxxx Cc: Benno Lossin
benno.lossin@xxxxxxxxx Cc: "Björn Roy Baron"
bjorn3_gh@xxxxxxxxxxxxxx Cc: Boqun Feng
boqun.feng@xxxxxxxxx Cc: Christoph Lameter
cl@xxxxxxxxx Cc: Dennis Zhou
dennis@xxxxxxxxxx Cc: Gary Guo
gary@xxxxxxxxxxx Cc: Miguel Ojeda
ojeda@xxxxxxxxxx Cc: Pasha Tatashin
pasha.tatashin@xxxxxxxxxx Cc: Peter Zijlstra
peterz@xxxxxxxxxxxxx Cc: Tejun Heo
tj@xxxxxxxxxx Cc: Vlastimil Babka
vbabka@xxxxxxx Cc: Wedson Almeida Filho
wedsonaf@xxxxxxxxx Signed-off-by: Andrew Morton
akpm@xxxxxxxxxxxxxxxxxxxx Ftrace irqoff tracer shows detail: At v6.14: # tracer: irqsoff # # irqsoff latency trace v1.1.5 on 6.14.0-rc7-next-20250319 # -------------------------------------------------------------------- # latency: 279663 us, #21352/21352, CPU#0 | (M:NONE VP:0, KP:0, SP:0 HP:0 #P:2) # ----------------- # | task: dd-805 (uid:0 nice:0 policy:0 rt_prio:0) # ----------------- # => started at: __rmqueue_pcplist # => ended at: _raw_spin_unlock_irqrestore # # # _------=> CPU#
# / _-----=> irqs-off/BH-disabled # | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / _-=> migrate-disable
# ||||| / delay
# cmd pid |||||| time | caller
# \ / |||||| \ | /
dd-805 0d.... 1us : __rmqueue_pcplist dd-805 0d.... 3us : _raw_spin_trylock <-__rmqueue_pcplist dd-805 0d.... 7us : __mod_zone_page_state <-__rmqueue_pcplist dd-805 0d.... 10us : __mod_zone_page_state <-__rmqueue_pcplist dd-805 0d.... 12us : __mod_zone_page_state <-__rmqueue_pcplist dd-805 0d.... 15us : __mod_zone_page_state <-__rmqueue_pcplist dd-805 0d.... 17us : __mod_zone_page_state <-__rmqueue_pcplist dd-805 0d.... 19us : __mod_zone_page_state <-__rmqueue_pcplist … dd-805 0d.... 1535us : find_suitable_fallback <-__rmqueue_pcplist dd-805 0d.... 1538us : find_suitable_fallback <-__rmqueue_pcplist dd-805 0d.... 1539us : find_suitable_fallback <-__rmqueue_pcplist dd-805 0d.... 1542us+: try_to_claim_block <-__rmqueue_pcplist dd-805 0d.... 1597us : find_suitable_fallback <-__rmqueue_pcplist dd-805 0d.... 1599us+: try_to_claim_block <-__rmqueue_pcplist dd-805 0d.... 1674us : find_suitable_fallback <-__rmqueue_pcplist dd-805 0d.... 1676us+: try_to_claim_block <-__rmqueue_pcplist dd-805 0d.... 1716us : find_suitable_fallback <-__rmqueue_pcplist dd-805 0d.... 1718us+: try_to_claim_block <-__rmqueue_pcplist dd-805 0d.... 1801us : find_suitable_fallback <-__rmqueue_pcplist dd-805 0d.... 1803us+: try_to_claim_block <-__rmqueue_pcplist … dd-805 0d.... 279555us : find_suitable_fallback <-__rmqueue_pcplist dd-805 0d.... 279556us : find_suitable_fallback <-__rmqueue_pcplist dd-805 0d.... 279558us : find_suitable_fallback <-__rmqueue_pcplist dd-805 0d.... 279560us+: try_to_claim_block <-__rmqueue_pcplist dd-805 0d.... 279616us : find_suitable_fallback <-__rmqueue_pcplist dd-805 0d.... 279618us : __mod_zone_page_state <-__rmqueue_pcplist dd-805 0d.... 279620us : find_suitable_fallback <-__rmqueue_pcplist … dd-805 0d.... 279658us : find_suitable_fallback <-__rmqueue_pcplist dd-805 0d.... 279660us : _raw_spin_unlock_irqrestore <-__rmqueue_pcplist dd-805 0d.... 279662us : _raw_spin_unlock_irqrestore dd-805 0d.... 279666us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore dd-805 0d.... 279712us : <stack trace> => get_page_from_freelist => __alloc_frozen_pages_noprof => __folio_alloc_noprof => __filemap_get_folio => iomap_write_begin => iomap_file_buffered_write => blkdev_write_iter => vfs_write => ksys_write => ret_fast_syscall At v6.7: # tracer: irqsoff # # irqsoff latency trace v1.1.5 on 6.7.0 # -------------------------------------------------------------------- # latency: 2477 us, #146/146, CPU#0 | (M:server VP:0, KP:0, SP:0 HP:0 #P:2) # ----------------- # | task: dd-808 (uid:0 nice:0 policy:0 rt_prio:0) # ----------------- # => started at: _raw_spin_lock_irqsave # => ended at: _raw_spin_unlock_irqrestore # # # _------=> CPU#
# / _-----=> irqs-off/BH-disabled # | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / _-=> migrate-disable
# ||||| / delay
# cmd pid |||||| time | caller
# \ / |||||| \ | /
dd-808 0d.... 1us!: _raw_spin_lock_irqsave dd-808 0d.... 186us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 189us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 191us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 192us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 194us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 196us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 199us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 203us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 330us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 332us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 334us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 336us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 338us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 339us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 341us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 343us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 479us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 481us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 483us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 485us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 486us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 488us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 490us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 492us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 630us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 632us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 634us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 636us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 638us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 640us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 642us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 644us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 771us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 773us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 775us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 777us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 778us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 780us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 782us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 784us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 911us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 913us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 915us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 916us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 918us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 920us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 922us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 924us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 1055us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1058us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1059us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1061us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1063us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1065us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1066us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1068us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 1194us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1196us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1198us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1200us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1202us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1203us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1205us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1208us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 1333us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1335us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1337us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1339us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1341us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1342us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1344us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1346us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 1480us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1482us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1484us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1486us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1488us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1490us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1492us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1494us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 1621us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1623us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1625us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1627us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1629us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1630us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1632us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1634us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 1761us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1763us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1765us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1766us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1768us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1770us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1772us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1774us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 1900us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1902us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1903us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1905us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1907us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1909us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1911us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 1913us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 2038us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2040us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2042us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2044us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2046us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2047us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2049us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2051us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2053us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2055us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 2175us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2176us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2178us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2180us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2182us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2183us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2185us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2187us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2189us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2191us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2192us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2194us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2196us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 2323us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2325us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2327us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2328us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2330us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2332us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2334us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2335us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2337us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2339us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2341us : find_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2343us : steal_suitable_fallback <-__rmqueue_pcplist dd-808 0d.... 2345us!: move_freepages_block <-steal_suitable_fallback dd-808 0d.... 2470us : __mod_zone_page_state <-__rmqueue_pcplist dd-808 0d.... 2473us : _raw_spin_unlock_irqrestore <-__rmqueue_pcplist dd-808 0d.... 2476us : _raw_spin_unlock_irqrestore dd-808 0d.... 2479us+: tracer_hardirqs_on <-_raw_spin_unlock_irqrestore dd-808 0d.... 2520us : <stack trace> => get_page_from_freelist => __alloc_pages => __folio_alloc => __filemap_get_folio => iomap_write_begin => iomap_file_buffered_write => blkdev_write_iter => vfs_write => ksys_write => ret_fast_syscall Best Regard Carlos Song |
