Skip to content

[lts 8.6] oops all breaks - #75

Closed
PlaidCat wants to merge 2 commits into
ctrliq:{jmaple}_ciqlts8_6from
PlaidCat:{jmaple}_test_ciqlts8_6
Closed

PlaidCat wants to merge 2 commits into
ctrliq:{jmaple}_ciqlts8_6from
PlaidCat:{jmaple}_test_ciqlts8_6

Conversation

@PlaidCat

Copy link
Copy Markdown
Collaborator

No description provided.

@PlaidCat
PlaidCat force-pushed the {jmaple}_test_ciqlts8_6 branch from 0e8e8ce to ee2ce43 Compare January 17, 2025 00:01
@PlaidCat PlaidCat self-assigned this Jan 17, 2025
@PlaidCat PlaidCat closed this Jan 22, 2025
github-actions Bot pushed a commit that referenced this pull request Jun 4, 2025
Specify the threshold for dumping offcpu samples with --off-cpu-thresh,
the unit is milliseconds. Default value is 500ms.

Example:

  perf record --off-cpu --off-cpu-thresh 824

The example above collects direct off-cpu samples where the off-cpu time
is longer than 824ms.

Committer testing:

After commenting out the end off-cpu dump to have just the ones that are
added right after the task is scheduled back, and using a threshould of
1000ms, we see some periods (the 5th column, just before "offcpu-time"
in the 'perf script' output) that are over 1000.000.000 nanoseconds:

  root@number:~# perf record --off-cpu --off-cpu-thresh 10000
  ^C[ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 3.902 MB perf.data (34335 samples) ]
  root@number:~# perf script
<SNIP>
  Isolated Web Co   59932 [028] 63839.594437: 1000049427 offcpu-time:
             7fe63c7976c2 __syscall_cancel_arch_end+0x0 (/usr/lib64/libc.so.6)
             7fe63c78c04c __futex_abstimed_wait_common+0x7c (/usr/lib64/libc.so.6)
             7fe63c78e928 pthread_cond_timedwait@@GLIBC_2.3.2+0x178 (/usr/lib64/libc.so.6)
             5599974a9fe7 mozilla::detail::ConditionVariableImpl::wait_for(mozilla::detail::MutexImpl&, mozilla::BaseTimeDuration<mozilla::TimeDurationValueCalculator> const&)+0xe7 (/usr/lib64/fir>
                100000000 [unknown] ([unknown])

          swapper       0 [025] 63839.594459:     195724    cycles:P:  ffffffffac328270 read_tsc+0x0 ([kernel.kallsyms])
  Isolated Web Co   59932 [010] 63839.594466: 1000055278 offcpu-time:
             7fe63c7976c2 __syscall_cancel_arch_end+0x0 (/usr/lib64/libc.so.6)
             7fe63c78ba24 __syscall_cancel+0x14 (/usr/lib64/libc.so.6)
             7fe63c804c4e __poll+0x1e (/usr/lib64/libc.so.6)
             7fe633b0d1b8 PollWrapper(_GPollFD*, unsigned int, int) [clone .lto_priv.0]+0xf8 (/usr/lib64/firefox/libxul.so)
                10000002c [unknown] ([unknown])

          swapper       0 [027] 63839.594475:     134433    cycles:P:  ffffffffad4c45d9 irqentry_enter+0x19 ([kernel.kallsyms])
          swapper       0 [028] 63839.594499:     215838    cycles:P:  ffffffffac39199a switch_mm_irqs_off+0x10a ([kernel.kallsyms])
  MediaPD~oder #1 1407676 [027] 63839.594514:     134433    cycles:P:      7f982ef5e69f dct_IV(int*, int, int*)+0x24f (/usr/lib64/libfdk-aac.so.2.0.0)
          swapper       0 [024] 63839.594524:     267411    cycles:P:  ffffffffad4c6ee6 poll_idle+0x56 ([kernel.kallsyms])
  MediaSu~sor #75 1093827 [026] 63839.594555:     332652    cycles:P:      55be753ad030 moz_xmalloc+0x200 (/usr/lib64/firefox/firefox)
          swapper       0 [027] 63839.594616:     160548    cycles:P:  ffffffffad144840 menu_select+0x570 ([kernel.kallsyms])
  Isolated Web Co   14019 [027] 63839.595120: 1000050178 offcpu-time:
             7fc9537cc6c2 __syscall_cancel_arch_end+0x0 (/usr/lib64/libc.so.6)
             7fc9537c104c __futex_abstimed_wait_common+0x7c (/usr/lib64/libc.so.6)
             7fc9537c3928 pthread_cond_timedwait@@GLIBC_2.3.2+0x178 (/usr/lib64/libc.so.6)
             7fc95372a3c8 pt_TimedWait+0xb8 (/usr/lib64/libnspr4.so)
             7fc95372a8d8 PR_WaitCondVar+0x68 (/usr/lib64/libnspr4.so)
             7fc94afb1f7c WatchdogMain(void*)+0xac (/usr/lib64/firefox/libxul.so)
             7fc947498660 [unknown] ([unknown])
             7fc9535fce88 [unknown] ([unknown])
             7fc94b620e60 WatchdogManager::~WatchdogManager()+0x0 (/usr/lib64/firefox/libxul.so)
          fff8548387f8b48 [unknown] ([unknown])

          swapper       0 [003] 63839.595712:     212948    cycles:P:  ffffffffacd5b865 acpi_os_read_port+0x55 ([kernel.kallsyms])
<SNIP>

Suggested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Suggested-by: Ian Rogers <irogers@google.com>
Suggested-by: Namhyung Kim <namhyung@kernel.org>
Reviewed-by: Ian Rogers <irogers@google.com>
Signed-off-by: Howard Chu <howardchu95@gmail.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Tested-by: Gautam Menghani <gautam@linux.ibm.com>
Tested-by: Ian Rogers <irogers@google.com>
Acked-by: Namhyung Kim <namhyung@kernel.org>
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: James Clark <james.clark@linaro.org>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Kan Liang <kan.liang@linux.intel.com>
Cc: Mark Rutland <mark.rutland@arm.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: https://lore.kernel.org/r/20241108204137.2444151-2-howardchu95@gmail.com
Link: https://lore.kernel.org/r/20250501022809.449767-10-howardchu95@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
github-actions Bot pushed a commit that referenced this pull request Sep 27, 2025
JIRA: https://issues.redhat.com/browse/RHEL-78198

upstream
========
commit 9557c00
Author: Howard Chu <howardchu95@gmail.com>
Date: Wed Apr 30 19:28:07 2025 -0700

description
===========
Specify the threshold for dumping offcpu samples with --off-cpu-thresh,
the unit is milliseconds. Default value is 500ms.

Example:

  perf record --off-cpu --off-cpu-thresh 824

The example above collects direct off-cpu samples where the off-cpu time
is longer than 824ms.

Committer testing:

After commenting out the end off-cpu dump to have just the ones that are
added right after the task is scheduled back, and using a threshould of
1000ms, we see some periods (the 5th column, just before "offcpu-time"
in the 'perf script' output) that are over 1000.000.000 nanoseconds:

  root@number:~# perf record --off-cpu --off-cpu-thresh 10000
  ^C[ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 3.902 MB perf.data (34335 samples) ]
  root@number:~# perf script
<SNIP>
  Isolated Web Co   59932 [028] 63839.594437: 1000049427 offcpu-time:
             7fe63c7976c2 __syscall_cancel_arch_end+0x0 (/usr/lib64/libc.so.6)
             7fe63c78c04c __futex_abstimed_wait_common+0x7c (/usr/lib64/libc.so.6)
             7fe63c78e928 pthread_cond_timedwait@@GLIBC_2.3.2+0x178 (/usr/lib64/libc.so.6)
             5599974a9fe7 mozilla::detail::ConditionVariableImpl::wait_for(mozilla::detail::MutexImpl&, mozilla::BaseTimeDuration<mozilla::TimeDurationValueCalculator> const&)+0xe7 (/usr/lib64/fir>
                100000000 [unknown] ([unknown])

          swapper       0 [025] 63839.594459:     195724    cycles:P:  ffffffffac328270 read_tsc+0x0 ([kernel.kallsyms])
  Isolated Web Co   59932 [010] 63839.594466: 1000055278 offcpu-time:
             7fe63c7976c2 __syscall_cancel_arch_end+0x0 (/usr/lib64/libc.so.6)
             7fe63c78ba24 __syscall_cancel+0x14 (/usr/lib64/libc.so.6)
             7fe63c804c4e __poll+0x1e (/usr/lib64/libc.so.6)
             7fe633b0d1b8 PollWrapper(_GPollFD*, unsigned int, int) [clone .lto_priv.0]+0xf8 (/usr/lib64/firefox/libxul.so)
                10000002c [unknown] ([unknown])

          swapper       0 [027] 63839.594475:     134433    cycles:P:  ffffffffad4c45d9 irqentry_enter+0x19 ([kernel.kallsyms])
          swapper       0 [028] 63839.594499:     215838    cycles:P:  ffffffffac39199a switch_mm_irqs_off+0x10a ([kernel.kallsyms])
  MediaPD~oder #1 1407676 [027] 63839.594514:     134433    cycles:P:      7f982ef5e69f dct_IV(int*, int, int*)+0x24f (/usr/lib64/libfdk-aac.so.2.0.0)
          swapper       0 [024] 63839.594524:     267411    cycles:P:  ffffffffad4c6ee6 poll_idle+0x56 ([kernel.kallsyms])
  MediaSu~sor #75 1093827 [026] 63839.594555:     332652    cycles:P:      55be753ad030 moz_xmalloc+0x200 (/usr/lib64/firefox/firefox)
          swapper       0 [027] 63839.594616:     160548    cycles:P:  ffffffffad144840 menu_select+0x570 ([kernel.kallsyms])
  Isolated Web Co   14019 [027] 63839.595120: 1000050178 offcpu-time:
             7fc9537cc6c2 __syscall_cancel_arch_end+0x0 (/usr/lib64/libc.so.6)
             7fc9537c104c __futex_abstimed_wait_common+0x7c (/usr/lib64/libc.so.6)
             7fc9537c3928 pthread_cond_timedwait@@GLIBC_2.3.2+0x178 (/usr/lib64/libc.so.6)
             7fc95372a3c8 pt_TimedWait+0xb8 (/usr/lib64/libnspr4.so)
             7fc95372a8d8 PR_WaitCondVar+0x68 (/usr/lib64/libnspr4.so)
             7fc94afb1f7c WatchdogMain(void*)+0xac (/usr/lib64/firefox/libxul.so)
             7fc947498660 [unknown] ([unknown])
             7fc9535fce88 [unknown] ([unknown])
             7fc94b620e60 WatchdogManager::~WatchdogManager()+0x0 (/usr/lib64/firefox/libxul.so)
          fff8548387f8b48 [unknown] ([unknown])

          swapper       0 [003] 63839.595712:     212948    cycles:P:  ffffffffacd5b865 acpi_os_read_port+0x55 ([kernel.kallsyms])
<SNIP>

    Suggested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
    Suggested-by: Ian Rogers <irogers@google.com>
    Suggested-by: Namhyung Kim <namhyung@kernel.org>
    Reviewed-by: Ian Rogers <irogers@google.com>
    Signed-off-by: Howard Chu <howardchu95@gmail.com>
    Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
    Tested-by: Gautam Menghani <gautam@linux.ibm.com>
    Tested-by: Ian Rogers <irogers@google.com>
    Acked-by: Namhyung Kim <namhyung@kernel.org>
    Cc: Adrian Hunter <adrian.hunter@intel.com>
    Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
    Cc: Ingo Molnar <mingo@redhat.com>
    Cc: James Clark <james.clark@linaro.org>
    Cc: Jiri Olsa <jolsa@kernel.org>
    Cc: Kan Liang <kan.liang@linux.intel.com>
    Cc: Mark Rutland <mark.rutland@arm.com>
    Cc: Peter Zijlstra <peterz@infradead.org>
    Link: https://lore.kernel.org/r/20241108204137.2444151-2-howardchu95@gmail.com
    Link: https://lore.kernel.org/r/20250501022809.449767-10-howardchu95@gmail.com
    Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

Signed-off-by: Michael Petlan <mpetlan@redhat.com>
github-actions Bot pushed a commit that referenced this pull request Aug 24, 2026
__smbdirect_socket_schedule_cleanup() and smbdirect_socket_cleanup_work()
take sc->listen.lock and walk the listener's pending list, recursing
into smbdirect_socket_schedule_cleanup() for each child, and every
child takes its own listen.lock inside that walk.

This cannot deadlock for real: the nesting is strictly listener into
child, a child never listens, so the outer and the inner lock are
always different instances.  lockdep only tracks lock classes, though;
it sees the same class acquired twice and reports a possible recursive
locking deadlock.  This change therefore works around a lockdep
limitation rather than fixing a real hang, but the report is still
worth avoiding: lockdep disables itself after the first splat and then
hides real locking bugs for the rest of the run.

Only a socket that was a listener owns a populated listen.ready/pending
list; a child has empty lists and nothing to do in these blocks.  Guard
both of them with sc->listen.backlog != -1, the "was a listener" marker
that smbdirect_socket_destroy() already uses: listen.backlog leaves its
initial -1 exactly once, when smbdirect_socket_listen() succeeds.  The
alternative !sc->accept.listener test reads as "not a listener" while
meaning the opposite, and it is also true for an accepted child, whose
accept.listener has been cleared on hand-over.  With the guard the walk
only runs for a listener and never nests a child's listen.lock under
it; a pending child stays on its listener's list for the free path
(smbdirect_socket_destroy) to reap.

[  741.705044] WARNING: possible recursive locking detected
[  741.705403] 7.1.0-next-20260623+ #75 Not tainted
[  741.705695] --------------------------------------------
[  741.706022] ksmbd.control/18502 is trying to acquire lock:
[  741.706379] ffff888108d612f8 (&sc->listen.lock){....}-{3:3}, at: __smbdirect_socket_schedule_cleanup+0x719/0xd70
[  741.707008]
[  741.707008] but task is already holding lock:
[  741.707396] ffff8881087642f8 (&sc->listen.lock){....}-{3:3}, at: __smbdirect_socket_schedule_cleanup+0x719/0xd70
[  741.708025]
[  741.708025] other info that might help us debug this:
[  741.708448]  Possible unsafe locking scenario:
[  741.708448]
[  741.708845]        CPU0
[  741.709016]        ----
[  741.709186]   lock(&sc->listen.lock);
[  741.709453]   lock(&sc->listen.lock);
[  741.709705]
[  741.709705]  *** DEADLOCK ***
[  741.709705]
[  741.710095]  May be due to missing lock nesting notation
[  741.710095]
[  741.710663] 6 locks held by ksmbd.control/18502:
[  741.710975]  #0: ffff888109e51420 (sb_writers#7){.+.+}-{0:0}, at: vfs_write+0x1e7/0xc70
[  741.711561]  #1: ffff888126ec3880 (&of->mutex){+.+.}-{4:4}, at: kernfs_fop_write_iter+0x1be/0x4d0
[  741.712147]  #2: ffff888102af17b0 (kn->active#45){.+.+}-{0:0}, at: kernfs_fop_write_iter+0x205/0x4d0
[  741.712803]  #3: ffffffff85ad1e00 (ctrl_lock){+.+.}-{4:4}, at: kill_server_store+0x1e0/0x2b0
[  741.713381]  #4: ffffffff85ad41a0 (init_lock){+.+.}-{4:4}, at: ksmbd_conn_transport_destroy+0x5b/0x3c0
[  741.713995]  #5: ffff8881087642f8 (&sc->listen.lock){....}-{3:3}, at: __smbdirect_socket_schedule_cleanup+0x719/0xd70
[  741.714736]
[  741.714736] stack backtrace:
[  741.715038] CPU: 4 UID: 0 PID: 18502 Comm: ksmbd.control Not tainted 7.1.0-next-20260623+ #75 PREEMPT(lazy)
[  741.715043] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-debian-1.17.0-1 04/01/2014
[  741.715046] Call Trace:
[  741.715049]  <TASK>
[  741.715052]  dump_stack_lvl+0x77/0xa0
[  741.715058]  print_deadlock_bug+0x279/0x290
[  741.715065]  __lock_acquire+0x272a/0x2e30
[  741.715070]  ? stack_trace_save+0xae/0x100
[  741.715075]  ? smb_direct_logging_vaprintf+0x1a0/0x230
[  741.715079]  ? __pfx_smb_direct_logging_vaprintf+0x10/0x10
[  741.715082]  ? __timer_delete+0x58/0x320
[  741.715087]  lock_acquire+0xd3/0x270
[  741.715091]  ? __smbdirect_socket_schedule_cleanup+0x719/0xd70
[  741.715095]  ? entry_SYSCALL_64_after_hwframe+0x77/0x7f
[  741.715099]  _raw_spin_lock_irqsave+0x42/0x60
[  741.715105]  ? __smbdirect_socket_schedule_cleanup+0x719/0xd70

Note the two addresses above: ffff888108d612f8 is the child's lock,
ffff8881087642f8 the listener's, always distinct objects.

Found with ksmbdzzer [2], a KSMBD fuzzer that drives libFuzzer with a
kcov-dataflow [1] coverage vector: it folds each instrumented
comparison/argument's runtime operand value together with its PC (the
default arm mixes them as pc⊕val) so that a new operand value at a known
site counts as new coverage.

[1] https://lwn.net/Articles/1077606/
[2] https://github.com/yskzalloc/kcov-dataflow

Fixes: dc691b9 ("smb: smbdirect: introduce smbdirect_socket_{listen,accept}()")
Signed-off-by: Yunseong Kim <yunseong.kim@est.tech>
Reviewed-by: Stefan Metzmacher <metze@samba.org>
Signed-off-by: Namjae Jeon <linkinjeon@kernel.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Development

Successfully merging this pull request may close these issues.

1 participant