From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mail-wr1-f66.google.com (mail-wr1-f66.google.com [209.85.221.66]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id E9E1C31DDB8 for ; Fri, 30 Jan 2026 16:28:15 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=209.85.221.66 ARC-Seal:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1769790497; cv=none; b=WqYWuJyylBiF8ezb4uGEHD7iGCWRfeIZmQODZriAZvyFkhfIT/04+fEahKy2QFHIR9PkvzXb23EemBj65Az0IWeSWB5uxF56hvBWikUDkag/M0KdRx750xaVh7H2GQPIZmwn0izUaf38GvlZC/wYFPPuJfiUN2boMUsuRSgoMXE= ARC-Message-Signature:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1769790497; c=relaxed/simple; bh=+MjVxxLGZXBfwbg2IowDykj7M30fLhVV2Alg02mRA1s=; h=Date:From:To:Cc:Subject:Message-ID:References:MIME-Version: Content-Type:Content-Disposition:In-Reply-To; b=GYIqQstzwi0AFHWuaaG3y+FlNOJwPCtwhzGDHV8s7wBL3EAJOvx1HBkckuyOAVuNtlAVGUgOgAzeebPcpdsUjHNMPSyb1pyGQrD/OpUN8RAp9I3PP2rrPVi3k0XDpQ9a9PS5BWwN4HZnVQfDeEX2sAuDxO66HixGQkRyidc/ZfU= ARC-Authentication-Results:i=1; smtp.subspace.kernel.org; dmarc=pass (p=quarantine dis=none) header.from=suse.com; spf=pass smtp.mailfrom=suse.com; dkim=pass (2048-bit key) header.d=suse.com header.i=@suse.com header.b=KGwyRpVG; arc=none smtp.client-ip=209.85.221.66 Authentication-Results: smtp.subspace.kernel.org; dmarc=pass (p=quarantine dis=none) header.from=suse.com Authentication-Results: smtp.subspace.kernel.org; spf=pass smtp.mailfrom=suse.com Authentication-Results: smtp.subspace.kernel.org; dkim=pass (2048-bit key) header.d=suse.com header.i=@suse.com header.b="KGwyRpVG" Received: by mail-wr1-f66.google.com with SMTP id ffacd0b85a97d-42fbc305552so2242128f8f.0 for ; Fri, 30 Jan 2026 08:28:15 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=suse.com; s=google; t=1769790494; x=1770395294; darn=vger.kernel.org; h=in-reply-to:content-disposition:mime-version:references:message-id :subject:cc:to:from:date:from:to:cc:subject:date:message-id:reply-to; bh=efaCbmeIrGni07PmJ+M5t4p6HVsvlnN2g3ubV7VwQjI=; b=KGwyRpVGEKo8OQjeKS0Rr7wIspxXm+5DTmrSmfj3JeaEOMwuyJklXIDzNLM9hmiCXD Z0ckZ6mArPF+At+rZA4LQgJ+IOxcAwO+gHE+hT/ByBNbWYIkGDEgfDZLNWOAVLJYM3dF otkhgbP3XefGDz7clUB7yv7QOnXwMdtP48A3CJSOzrV1dZaTbOi8CPIziskBt3ZPEquF t6kv6nR9aNbYdWYfkoid9XANxjinCA7IX1iQs+wpftf2ee1+MGScI9Efz3r6Z0sZDBot 0cseN7B9ayn9luSvvzxlZhc/XUO9H3J4jeOtEiCaz58dXIthEay9CgW+1K4Lbbn8S9Rt Pb4g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1769790494; x=1770395294; h=in-reply-to:content-disposition:mime-version:references:message-id :subject:cc:to:from:date:x-gm-gg:x-gm-message-state:from:to:cc :subject:date:message-id:reply-to; bh=efaCbmeIrGni07PmJ+M5t4p6HVsvlnN2g3ubV7VwQjI=; b=j6h5h/7sBJmS1I1+ufiVx2NSzMeirhlqF4bY/JvGK2GGAQ5qaN2yjHp3urfiCnfs0t tzRyb7keOnAY1x3Eyz+b767+W9m0G4JcTxR3T8j6SaTpYo+CmMc8FFajmAG8xKWJsuwF DRkc15rBMFRYl2sFhqzJA0N/flGP/+Lz97y7h4E4ra14PmoSjhnXqXS7O4+7S+HlwmQy 8ezA+e8YhE1WO3Fqj+RN4mXaiS3O/gWv5E5QjrhhAsoJIs+UmInbxs8Q9bmCF3pfZomk Ql1sFUi6afm/8p/Bp6Ay09p8aZt0rsHzeec3T9ixq5zjZcmXcNswlwO/asBdI7BYhfv/ L4fQ== X-Forwarded-Encrypted: i=1; AJvYcCW8nT/1mZbAtIWapxoMwsL9bW+YKhef2blpQv7l7VCyQ2x0210jk3pKQRZHKSb6m1BOCZdMH33XWQJ/QbY=@vger.kernel.org X-Gm-Message-State: AOJu0YwA0rlkVc/hv4165oA6E3aOp89XQ5HHaPJ1Bw62kC/EIivxCC0F 0gVuNzVGmrznmQhhHu0APH4zeY5n5BsmoItHBEJLjW6fbnnZ9tTalcRG2WlCrpdOri4= X-Gm-Gg: AZuq6aK9ZxtY6Pg6lVZCDbbryTHdsNoIPDEjgKX2kOoYJJNE3uRrn0GbOqVQY4ehEns RpD4OKi0coGqM/spfEnp4w/HkC17rKRgfq5ZdcKQhGp0anRUGZtcqaMU2Hzs78tlYTStHidbb71 WMHQhBRL6cob/RHERX/ONl5rOyVLHVecV8Agr60QFuAMivXzBZcd0BNlLgX9c8/pKmBYLtekwVh iBOxJkbmHo4uDnLpRSCv2rR0je9yI39O0JehNUca39oO8Y2HzipmG6iu9b7i6uA4tVzxTwgDk/D J4QbiT1T5xnHz7If2xqd9qnI5rC3nKXs2BTxFWvR6yZeKrRW6zmandIZHh5rQObyP34jLrpbMWm G3ap4n40uym4a7+iYlTVbXYEspWiz3qoSgCcPCvDH994LRbT6T0CZAv7fqahRXkF3UzvRhGrdAD a0fxerxuOL1vEHyg== X-Received: by 2002:adf:ffce:0:b0:435:e440:f518 with SMTP id ffacd0b85a97d-435f3abb472mr5007848f8f.54.1769790494097; Fri, 30 Jan 2026 08:28:14 -0800 (PST) Received: from pathway.suse.cz ([176.114.240.130]) by smtp.gmail.com with ESMTPSA id ffacd0b85a97d-435e131ce93sm22451742f8f.24.2026.01.30.08.28.13 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Fri, 30 Jan 2026 08:28:13 -0800 (PST) Date: Fri, 30 Jan 2026 17:28:11 +0100 From: Petr Mladek To: ysard Cc: John Ogness , linux-kernel@vger.kernel.org, senozhatsky@chromium.org Subject: Re: Regression: system freeze on resume from suspend introduced by printk per-console suspended state Message-ID: References: <87tsxhbtxo.fsf@jogness.linutronix.de> <877bts1ltv.fsf@jogness.linutronix.de> Precedence: bulk X-Mailing-List: linux-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: On Fri 2026-01-30 16:56:56, Petr Mladek wrote: > On Thu 2026-01-29 10:34:53, ysard wrote: > > Summary > > ======= > > > > The patch works only when I *uncomment* the 2 `synchronize_srcu(&console_srcu);` lines! > > > Works now!: > > $ sudo sh -c " > > mkdir -p /var/run/nvidia-sleep \ > > && echo 2 > /var/run/nvidia-sleep/Xorg.vt_number \ > > && chvt 63 \ > > && echo suspend >/proc/driver/nvidia/suspend \ > > && systemctl suspend" > > > > Logs: > > [ 338.901995] [ T3134] printk: Suspending console(s) (use no_console_suspend to debug) > > [ 338.901997] [ T3134] printk: console_suspend_all > > [ 338.932763] [ T2672] printk: console_trylock > > [ 338.948664] [ T2659] printk: console_trylock > > [ 338.948685] [ T2671] printk: console_trylock > > [ 338.950716] [ T272] printk: console_trylock > > [ 338.950747] [ T270] printk: console_trylock > > [ 338.982194] [ T3134] printk: console_trylock > > [ 339.020910] [ T3134] printk: console_trylock > > [ 339.044613] [ T158] printk: console_trylock > > [ 339.132842] [ T3134] printk: console_trylock [...] > > [ 339.614444] [ T9] printk: console_trylock > > [ 339.634304] [ T3149] printk: console_trylock > > [ 339.942244] [ T2673] printk: console_trylock > > [ 340.123772] [ T3134] printk: console_resume_all > > > > Proc comm values: > > 1127: kworker/3:2-cgroup_offline > > 158: kworker/5:1-mm_percpu_wq > > 2659: kworker/u32:17-async > > 2661: kworker/u32:19-async > > 2671: kworker/u32:29-async > > 2672: kworker/u32:30-async > > 2673: kworker/u32:31-kvfree_rcu_reclaim > > 270: scsi_eh_1 > > 272: scsi_eh_2 > > 310: kworker/2:2-events > > 3134: not exists or not readable > > 3149: kworker/u32:38-flush-253:3 > > 65: kworker/u32:2-async > > 66: kworker/u32:3-async > > 67: kworker/u32:4-async > > 9: kworker/0:0-events > > It is hard to know what is going there. I guess that many > console_trylock() calls are from printk(). But they might also > be from tty or from the nvidia driver code. > > I have tried to create a patch which would print backtraces > of the callers. The output might be interesting. I am going > to send it in a separate mail. Please, find the patch below. It can be applied on top of the preovius one which reverted the problematic commit, see https://lore.kernel.org/all/aXoWiJhcOaGGlcmk@pathway.suse.cz/ Important: You still need to explicitely uncomment the sychronize_srcu() calls. It would be nice to provide three logs with this patch: 1. console_lock() API called by echo suspend >/proc/driver/nvidia/suspend 2. console_lock() API called by the suspend test No freeze (expected): $ sudo sh -c " mkdir -p /var/run/nvidia-sleep \ && echo 2 > /var/run/nvidia-sleep/Xorg.vt_number \ && chvt 63 \ && systemctl suspend" 3. No freeze with the 1st patch and uncommented synchronize_srcu() calls.: $ sudo sh -c " mkdir -p /var/run/nvidia-sleep \ && echo 2 > /var/run/nvidia-sleep/Xorg.vt_number \ && chvt 63 \ && echo suspend >/proc/driver/nvidia/suspend \ && systemctl suspend" Feel free to do your own tests. But please do not spend too much time on it. It would be nice to find the culprit. Especially I would like to know whether the problem is in the core kernel code (printk, suspend, tty) or in the nvidia driver. But we might also just need to restore the original behavior of the console lock API during suspend. I mean the short cuts. They are a kind of optimization anyway. But as I said, it would be nice to understand the problem. There might be a race or infinite loop somewhere and the original console_lock API behavior just hides the problem. OK, here is the patch which printed backtraces of console_lock API callers around the suspend for me. >From ab9e67fc50425eb6574c016c5809865a085c4b44 Mon Sep 17 00:00:00 2001 From: Petr Mladek Date: Fri, 30 Jan 2026 16:57:25 +0100 Subject: [PATCH] printk: debug: Allow to print backtraces of console_lock API callers. This patch allows to print backtraces of console_lock API callers. The logging must be explicitely enabled by: echo 1 >/sys/module/printk/parameters/debug_console_lock I suggest to increase the internal log buffer size, for example, use on the command line: log_buf_len=1M The logging might easily go wild because the console API is called by printk() and tty code. I have explicitely disabled the logging in: + vprintk_emit() + fb_flashcursor() , see no_debug_console_lock_enter()/exit() calls. Otherwise, there was an endless loop of printed entries. Note that I run the tests in a virtualized test system (QEMU) via ssh. Some more tty API might need to get disabled when doing the tests using the tty console. But it might hide the code called during suspend. So, doing the tests via ssh sounds better to me. Also the number of printed backtraces is limited to "100". It helps to keep the system running when printing the report triggers more callers of the API and causes an infinite loop. Signed-off-by: Petr Mladek --- drivers/video/fbdev/core/fbcon.c | 9 +++- include/linux/printk.h | 2 + kernel/printk/printk.c | 91 ++++++++++++++++++++++++++++++-- 3 files changed, 98 insertions(+), 4 deletions(-) diff --git a/drivers/video/fbdev/core/fbcon.c b/drivers/video/fbdev/core/fbcon.c index 7be9e865325d..1d5d7af516ed 100644 --- a/drivers/video/fbdev/core/fbcon.c +++ b/drivers/video/fbdev/core/fbcon.c @@ -397,14 +397,19 @@ static void fb_flashcursor(struct work_struct *work) struct vc_data *vc = NULL; int c; bool enable; + int debug; int ret; + debug = no_debug_console_lock_enter(); + /* FIXME: we should sort out the unbind locking instead */ /* instead we just fail to flash the cursor if we can't get * the lock instead of blocking fbcon deinit */ ret = console_trylock(); - if (ret == 0) + if (ret == 0) { + no_debug_console_lock_exit(debug); return; + } /* protected by console_lock */ info = par->info; @@ -416,6 +421,7 @@ static void fb_flashcursor(struct work_struct *work) fbcon_info_from_console(vc->vc_num) != info || vc->vc_deccm != 1) { console_unlock(); + no_debug_console_lock_exit(debug); return; } @@ -425,6 +431,7 @@ static void fb_flashcursor(struct work_struct *work) get_fg_color(vc, info, c), get_bg_color(vc, info, c)); console_unlock(); + no_debug_console_lock_exit(debug); queue_delayed_work(system_power_efficient_wq, &par->cursor_work, par->cur_blink_jiffies); diff --git a/include/linux/printk.h b/include/linux/printk.h index 45c663124c9b..f266b20b7584 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -201,6 +201,8 @@ void __init setup_log_buf(int early); __printf(1, 2) void dump_stack_set_arch_desc(const char *fmt, ...); void dump_stack_print_info(const char *log_lvl); void show_regs_print_info(const char *log_lvl); +int no_debug_console_lock_enter(void); +void no_debug_console_lock_exit(int debug); extern asmlinkage void dump_stack_lvl(const char *log_lvl) __cold; extern asmlinkage void dump_stack(void) __cold; void printk_trigger_flush(void); diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 6e0ad926f409..c54c70d7a074 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -2383,11 +2383,52 @@ MODULE_PARM_DESC(debug_non_panic_cpus, "allow messages from non-panic CPUs in panic()"); #endif +int debug_console_lock; +module_param(debug_console_lock, int, S_IRUGO | S_IWUSR); +MODULE_PARM_DESC(debug_console_lock, + "Print some caller info when console_lock() API is called."); + +static DEFINE_PER_CPU(int, no_debug_console_lock_nesting); + +int no_debug_console_lock_enter(void) +{ + int debug; + + debug = READ_ONCE(debug_console_lock); + if (debug) { + if (this_cpu_read(no_debug_console_lock_nesting) > 256) { + debug_console_lock = 0; + pr_err("Overflow of no_debug_console_lock_nesting! Disabled console_lock debuginng.\n"); + return 0; + } + + migrate_disable(); + this_cpu_inc(no_debug_console_lock_nesting); + } + + return debug; +} + +void no_debug_console_lock_exit(int debug) +{ + if (debug) { + if (this_cpu_read(no_debug_console_lock_nesting) <= 0) { + debug_console_lock = 0; + pr_err("Underflow of no_debug_console_lock_nesting! Disabled console lock debuginng.\n"); + migrate_enable(); + return; + } + this_cpu_dec(no_debug_console_lock_nesting); + migrate_enable(); + } +} + asmlinkage int vprintk_emit(int facility, int level, const struct dev_printk_info *dev_info, const char *fmt, va_list args) { struct console_flush_type ft; + int debug_caller; int printed_len; /* Suppress unimportant messages after panic happens */ @@ -2404,6 +2445,8 @@ asmlinkage int vprintk_emit(int facility, int level, !panic_triggering_all_cpu_backtrace) return 0; + debug_caller = no_debug_console_lock_enter(); + printk_get_console_flush_type(&ft); /* If called from the scheduler, we can not call up(). */ @@ -2448,6 +2491,8 @@ asmlinkage int vprintk_emit(int facility, int level, else if (!console_irqwork_blocked) wake_up_klogd(); + no_debug_console_lock_exit(debug_caller); + return printed_len; } EXPORT_SYMBOL(vprintk_emit); @@ -2856,6 +2901,41 @@ static int console_cpu_notify(unsigned int cpu) return 0; } +static void print_console_lock_caller(const char *func_name) +{ + static int reports = 0; + char tcomm[64]; + u8 nested; + + if (!debug_console_lock) + return; + + nested = raw_cpu_read(no_debug_console_lock_nesting); + if (nested) + return; + + if (!func_name) { + pr_err_once("%s: called without func_name\n", __func__); + return; + } + + if (reports++ > 100) { + debug_console_lock = 0; + pr_warn("Too many printed console lock callers. Disabled the debugging.\n"); + } + + if (current->flags & PF_WQ_WORKER) + wq_worker_comm(tcomm, sizeof(tcomm), current); + else if (current->flags & PF_KTHREAD) + get_kthread_comm(tcomm, sizeof(tcomm), current); + else + get_task_comm(tcomm, current); + + pr_info("console lock API call [%d]: %s() by pid=%d, comm=%s\n", + reports, func_name, current->pid, tcomm); + show_stack(current, NULL, KERN_INFO); +} + /** * console_lock - block the console subsystem from printing * @@ -2868,13 +2948,14 @@ void console_lock(void) { might_sleep(); + print_console_lock_caller(__func__); + /* On panic, the console_lock must be left to the panic cpu. */ while (panic_on_other_cpu()) msleep(1000); down_console_sem(); if (console_suspended) { - printk_store(KERN_INFO "printk: %s\n", __func__); /* * Keep console locked, but do not touch * @console_locked or @console_may_schedule. @@ -2897,13 +2978,14 @@ EXPORT_SYMBOL(console_lock); */ int console_trylock(void) { + print_console_lock_caller(__func__); + /* On panic, the console_lock must be left to the panic cpu. */ if (panic_on_other_cpu()) return 0; if (down_trylock_console_sem()) return 0; if (console_suspended) { - printk_store(KERN_INFO "printk: %s\n", __func__); /* * The lock was acquired, but unlock directly and report * failure. Here console_locked=1 and console_may_schedule=1. @@ -2919,6 +3001,8 @@ EXPORT_SYMBOL(console_trylock); int is_console_locked(void) { +// /* This might produce too many entries. */ +// print_console_lock_caller(__func__); return console_locked; } EXPORT_SYMBOL(is_console_locked); @@ -3404,8 +3488,9 @@ void console_unlock(void) { struct console_flush_type ft; + print_console_lock_caller(__func__); + if (console_suspended) { - printk_store(KERN_INFO "printk: %s\n", __func__); /* * Simply unlock directly. * Here console_locked=1 and console_may_schedule=1. -- 2.52.0