On Thu, Mar 20, 2025 at 11:07:41AM +0000, Carlos Song wrote: > 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. Did you track down which spinlock? > > commit b951aaff503502a7fe066eeed2744ba8a6413c89 > Author: Suren Baghdasaryan surenb@xxxxxxxxxx<mailto: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<mailto:surenb@xxxxxxxxxx> > Co-developed-by: Kent Overstreet kent.overstreet@xxxxxxxxx<mailto:kent.overstreet@xxxxxxxxx> > Signed-off-by: Kent Overstreet kent.overstreet@xxxxxxxxx<mailto:kent.overstreet@xxxxxxxxx> > Reviewed-by: Kees Cook keescook@xxxxxxxxxxxx<mailto:keescook@xxxxxxxxxxxx> > Tested-by: Kees Cook keescook@xxxxxxxxxxxx<mailto:keescook@xxxxxxxxxxxx> > Cc: Alexander Viro viro@xxxxxxxxxxxxxxxxxx<mailto:viro@xxxxxxxxxxxxxxxxxx> > Cc: Alex Gaynor alex.gaynor@xxxxxxxxx<mailto:alex.gaynor@xxxxxxxxx> > Cc: Alice Ryhl aliceryhl@xxxxxxxxxx<mailto:aliceryhl@xxxxxxxxxx> > Cc: Andreas Hindborg a.hindborg@xxxxxxxxxxx<mailto:a.hindborg@xxxxxxxxxxx> > Cc: Benno Lossin benno.lossin@xxxxxxxxx<mailto:benno.lossin@xxxxxxxxx> > Cc: "Björn Roy Baron" bjorn3_gh@xxxxxxxxxxxxxx<mailto:bjorn3_gh@xxxxxxxxxxxxxx> > Cc: Boqun Feng boqun.feng@xxxxxxxxx<mailto:boqun.feng@xxxxxxxxx> > Cc: Christoph Lameter cl@xxxxxxxxx<mailto:cl@xxxxxxxxx> > Cc: Dennis Zhou dennis@xxxxxxxxxx<mailto:dennis@xxxxxxxxxx> > Cc: Gary Guo gary@xxxxxxxxxxx<mailto:gary@xxxxxxxxxxx> > Cc: Miguel Ojeda ojeda@xxxxxxxxxx<mailto:ojeda@xxxxxxxxxx> > Cc: Pasha Tatashin pasha.tatashin@xxxxxxxxxx<mailto:pasha.tatashin@xxxxxxxxxx> > Cc: Peter Zijlstra peterz@xxxxxxxxxxxxx<mailto:peterz@xxxxxxxxxxxxx> > Cc: Tejun Heo tj@xxxxxxxxxx<mailto:tj@xxxxxxxxxx> > Cc: Vlastimil Babka vbabka@xxxxxxx<mailto:vbabka@xxxxxxx> > Cc: Wedson Almeida Filho wedsonaf@xxxxxxxxx<mailto:wedsonaf@xxxxxxxxx> > Signed-off-by: Andrew Morton akpm@xxxxxxxxxxxxxxxxxxxx<mailto: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 >
