Bug 186211 - pm_parepare_console takes more than 200ms - switch vt during suspend - (Lenovo yoga 900/Mac book pro 2015)
Summary: pm_parepare_console takes more than 200ms - switch vt during suspend - (Leno...
Status: RESOLVED DOCUMENTED
Alias: None
Product: Power Management
Classification: Unclassified
Component: Hibernation/Suspend (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Chen Yu
URL:
Keywords:
: 186231 (view as bug list)
Depends on:
Blocks: 178231
  Show dependency tree
 
Reported: 2016-11-01 07:24 UTC by Zhang Rui
Modified: 2016-12-22 03:39 UTC (History)
2 users (show)

See Also:
Kernel Version: All
Subsystem:
Regression: No
Bisected commit-id:


Attachments

Description Zhang Rui 2016-11-01 07:24:29 UTC
pm_parepare_console takes more than 200ms to finish.
Comment 1 Chen Yu 2016-11-07 08:58:13 UTC
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)
Comment 2 Chen Yu 2016-11-15 11:05:04 UTC
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
Comment 3 Chen Yu 2016-11-15 11:08:06 UTC
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
Comment 4 Chen Yu 2016-11-16 15:34:09 UTC
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)
Comment 5 Chen Yu 2016-11-16 15:50:39 UTC
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
Comment 6 Chen Yu 2016-11-17 06:24:04 UTC
Sent to Xorg mailist
https://lists.x.org/archives/xorg-devel/2016-November/051852.html
Comment 7 Chen Yu 2016-11-17 12:12:25 UTC
*** Bug 186231 has been marked as a duplicate of this bug. ***
Comment 8 Len Brown 2016-11-21 14:36:11 UTC
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?
Comment 9 Len Brown 2016-11-21 14:37:56 UTC
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.
Comment 10 Chen Yu 2016-12-01 07:30:25 UTC
(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.
Comment 11 Chen Yu 2016-12-01 07:32:17 UTC
(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.
Comment 12 Zhang Rui 2016-12-22 03:14:19 UTC
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". :)
Comment 13 Chen Yu 2016-12-22 03:39:44 UTC
Done, tracked at: 
https://bugs.freedesktop.org/show_bug.cgi?id=99173

Note You need to log in before you can comment on or make changes to this bug.