pm_parepare_console takes more than 200ms to finish.
The following code path took more than 300ms to finish, looks like the vt switching is waiting for framebuffer to finish its work: pm_prepare_console->vt_move_to_console->vt_waitactive->__vt_event_wait.isra.3.part.4->schedule(300ms later scheduled in again)
According to ftrace result on vt_waitactive/console_callback/complete_change_console across suspend/resume, the reason why vt switch takes so much time is because of the Xorg daemon that, the kernel has to wait for Xorg to release the vt and issues a ioctrl to complete the switching. If X is disabled, this issue disappears. rtcwake-886 [001] .... 2519.641849: vt_waitactive <-vt_move_to_console kworker/1:2-262 [001] .... 2519.641851: console_callback <-process_one_work Xorg-818 [002] .... 2519.835715: complete_change_console <-vt_ioctl rtcwake-886 [000] .... 2550.656509: vt_waitactive <-vt_move_to_console kworker/0:0-22796 [000] .... 2550.656511: console_callback <-process_one_work kworker/0:0-22796 [000] .... 2550.656515: complete_change_console <-change_console
According to above result, the Xorg issues a vt_ioctl to finish the console switch, which takes 2519.835715 - 2519.641851 = 200ms. While during resumed, there is no need to wait for Xorg thus the switch operatin is done in one worker thread, which takes only 2550.656515 - 2550.656511
The problem is root caused to be the implementation of Xorg: This issue can be simply reproduced by switching between Graphic mode and text mode console: press alt + ctl + F1 to text mode. Since the Xorg(Graphic) is working in VT_PROCESS mode(set by ioctl), the kernel has to handshake with Xorg, it means, if kernel wants to switch to suspend console, the kernel needs to wait for the Xorg to finish its work and sets the finish flag by issuing ioctl(VT_RELDISP). The problem is, although the Xorg has received the switch request from kernel on time, it waits for 200ms in user space(maybe doing some cleanup) and issue the VT_RELDISP to notify the finish to kernel. Currently it seems there is no good solution for this, it might not be applicable if the switching process is deferred, as the kernel must switch to the suspend console before freezing the processes, otherwise the Xorg will be freezed and the switching to suspend console will never be achieved(kernel never gets a ACK)
Ftrace result: Graphic mode vt switch to suspend-console's vt <...>-3802 [000] .... 12443.331885: change_console <-console_callback /* Since the current vt is working in VT_PROCESS, the kernel send the switch request to Xorg. */ <...>-3802 [000] .... 12443.331887: kill_pid <-change_console /* Signal sent. */ <...>-3802 [000] d... 12443.331902: signal_generate: sig=10 errno=0 code=128 comm=Xorg pid=833 grp=1 res=0 /* The Xorg has react to this request, and is about to invoke the signal handler*/ Xorg-833 [003] d... 12443.332044: signal_deliver: sig=10 errno=0 code=128 sa_handler=5616ac7ef860 sa_flags=14000000 /* However it takes 200ms for the Xorg to finish the signal handler, and finally it set the finish flag and info the kernel */ Xorg-833 [003] .... 12443.722808: complete_change_console <-vt_ioctl suspend-console's vt switch bakc to Graphic mode vt since the suspend-console is not working in VT_PROCESS mode, the kernel switch back to Graphic mode immediately: kworker/0:3-4540 [000] .... 12464.280929: change_console <-console_callback kworker/0:3-4540 [000] .... 12464.280932: complete_change_console <-change_console kworker/0:3-4540 [000] .N.. 12464.280961: kill_pid <-complete_change_console kworker/0:3-4540 [000] dN.. 12464.280970: signal_generate: sig=10 errno=0 code=128 comm=Xorg pid=833 grp=1 res=0 Xorg-833 [003] d... 12464.280980: signal_deliver: sig=10 errno=0 code=128 sa_handler=5616ac7ef860 sa_flags=14000000
Sent to Xorg mailist https://lists.x.org/archives/xorg-devel/2016-November/051852.html
*** Bug 186231 has been marked as a duplicate of this bug. ***
Dumb question: What if the suspend process skipped the VT switch? What bad things would happen? It seems that the kernel is asking Xorg to do this -- what if the kernel stopped asking?
Also: it sounds like this issue now has a known workaround -- though not a user-friendly workaround -- if we suspend from TEXT MODE, then this delay will not appear in the results.
(In reply to Len Brown from comment #8) > Dumb question: What if the suspend process skipped the VT switch? What bad > things would happen? It seems that the kernel is asking Xorg to do this -- > what if the kernel stopped asking? Because if no_console_suspend is enabled, the kernel needs to switch from Graphic mode to a temporary suspend-use-only-console vt, thus the kernel can record any output during suspend/resume. Since the Xorg is using the graphic vt, any it might not work during suspend, so kernel might need to switch to a safe vt instead.
(In reply to Len Brown from comment #9) > Also: it sounds like this issue now has a known workaround -- though not a > user-friendly workaround -- if we suspend from TEXT MODE, then this delay > will not appear in the results. Yes, if currently the system is using Graphic as current vt, any switch to other VTs will take much time to finish. And another workaround is not to append 'no_console_suspend' in the grub.
hmmm, actually, this is a graphics issue. We should open a ticket at freedesktop and track the status there. And mark this bug as Documented "Duplicate". :)
Done, tracked at: https://bugs.freedesktop.org/show_bug.cgi?id=99173