Session logout takes too long

[Simon Steinbeiß]

This seems to be an issue confirmed across Ubuntu-flavors in Saucy at the moment: logging out of the session takes longer than expected (that is 5+seconds even on fast machines).

It's not clear to me what exactly is going on, what component is the culprit. I started debugging xfce4-session (as I'm a Xubuntu team member) and then dug around lightdm, but without result. Maybe more able people can take a peek at this one...

[Alistair Buxton (a-j-buxton)]

I investigated this issue with bootchart. If you want to do the same, edit /etc/init/bootchart.conf and find the line where it sleeps for 45 seconds. Increase the sleep so we catch the logout as well as the login (as the comment says "delay 45 seconds to catch the login.")

On the first test, I noticed that gnome-keyring-d and xscreensaver persisted all the way until the end of the logout delay. I emoved those two programs in order to rule them out, and the delay persists. Attachment is the bootchart with those programs removed.

The section of interest is 35 seconds to 42 seconds. I press logout for the first time at 35 seconds. A lot of programs exit immediately. Some persist for a further 6 seconds. Xorg, lightdm, and the session init persist for a further 6 seconds before Xorg restarts and the greeter is displayed at 42 seconds. A total delay of 12 seconds. During this time there is apparently no CPU activity.

[Elfy (elfy)]

Commenting out xubuntu from

/etc/upstart-xsessions

leads to normal logout and login speeds

[Alistair Buxton (a-j-buxton)]

Session ending could take at worst: ( max_initial_delay + max_kill_timeout_new )

Under normal circumstances: Worst case scenario will likely be a wait of (5 + 5) seconds.

Average case scenario is expected to be approximately (0 + 1) seconds Since,
            No standard provided Session Job will start on "session-end" meaning max_kill_timeout_new and WAIT will effectively be 0.
            All standard provided Session Jobs will react to the default kill signal and end quickly.

 - https://wiki.edubuntu.org/FoundationsTeam/Specs/RaringUpstartUserSessions

[Stephen Michael Kellat (skellat)]

It would probably be appropriate to contact Steve Langasek (slangasek) and get him looped in on this.

[Alistair Buxton (a-j-buxton)]

More things I found:

I couldn't find a way to access the log from the upstart user session, so I made this shim:

#include <stdio.h>
#include <unistd.h>

int main(int argc, char *argv[]) {
    freopen("/tmp/out", "a", stdout);
    freopen("/tmp/err", "a", stderr);
    execlp("/sbin/init", "init", "--user", "--verbose", NULL);
}

Build it, put it in /sbin/ and edit /etc/X11/Xsession.d/99upstart

Edit the line with STARTUP and change "init --user" to "logshim"

Now the output will go to /tmp/out and /tmp/err (appending).

So what I found after doing this, is that the logrotate job which sleeps for 1 minute at startup is the one holding up the shutdown if you log out less than 1 minute after logging in. In this case, the delay will be ~10 seconds.

However, if you wait for 1 minute until this job stops, the delay is still ~5 seconds. This is because the calculation of the delay uses the max of all job kill timeouts and the default kill timeout, which is 5 seconds. So it can never be less than 5 seconds.

[Alistair Buxton (a-j-buxton)]

In quiesce() the jobs are not stopped if you select "log out":

 if (requester == QUIESCE_REQUESTER_SYSTEM) {
  /* We'll attempt to wait for this long, but system
   * policy may prevent it such that we just get killed
   * and job processes reparented to PID 1.
   */
  max_kill_timeout = job_class_max_kill_timeout ();

  job_process_stop_all ();
 }

In quiesce_wait_callback() the shutdown is not sent unless QUIESCE_DEFAULT_JOB_RUNTIME (5) seconds have passed:

 else if (quiesce_phase == QUIESCE_PHASE_WAIT) {

  if ((now - quiesce_phase_time) > QUIESCE_DEFAULT_JOB_RUNTIME) {
   quiesce_phase = QUIESCE_PHASE_KILL;

   /* reset for new phase */
   quiesce_phase_time = time (NULL);

   max_kill_timeout = job_class_max_kill_timeout ();
   job_process_stop_all ();
  }
 }

So when you log out, upstart will always wait 5 seconds before attempting to stop any jobs. Once the jobs are told to stop, they all stop within 1 second and shutdown completes on the next call to the callback (as long as the logrotate job has finished, which happens ~1 minute after log in. If that is still running, then upstart will wait for up to job_class_max_kill_timeout () seconds (which is always at least 5 seconds) for it to stop.)

This all appears to be by design. The quiesce period is supposed to prevent any jobs from starting after the stop signal is sent to all existing jobs. This is only necessary on "log out" because on shutdown/restart, everything is going to get killed anyway. As such I don't think this is fixable without causing other issues.

[Steve Langasek (vorlon)]

> This all appears to be by design. The quiesce period is supposed to
> prevent any jobs from starting after the stop signal is sent to all
> existing jobs. This is only necessary on "log out" because on
> shutdown/restart, everything is going to get killed anyway. As such I
> don't think this is fixable without causing other issues.

I don't agree. The expected shutdown procedure is:
 - when upstart is signaled, it sends an event indicating that shutdown has been requested and sets a timer.
 - if all upstart jobs exit in a timely manner, and there are no remaining pending events, upstart should exit *immediately*.
 - if jobs are still running when the timer is reached, upstart should try a last ditch SIGKILL of each job, then exit.

James, can you please give priority to this bug for 13.10, and make sure upstart user sessions are actually working as described above?

[Launchpad Janitor (janitor)]

This bug was fixed in the package upstart - 1.10-0ubuntu3

---------------
upstart (1.10-0ubuntu3) saucy; urgency=low

  * Cherry-pick upstream fix for test failure (LP: #1089159).
 -- James Hunt <email address hidden> Thu, 03 Oct 2013 13:25:23 +0100

[Mina (842mono)]

I'm on Ubuntu 14.04 64 bits. I have this same exact problem with a fast machine. my logout time takes minimum 30 seconds.

this also affects shutting down and restart. It's clear that there's some bug. ...actually when I press restart from the top-right menu, it then shows a little window to either select "restart" or "shutdown" then it doesn't wait for user input! it just goes on to restart immediately (which takes the 30 seconds)

...sometimes the case beeps once! (the sound you should actually hear when starting the computer). I'm so ready to debug but I need exact steps.

...btw there was one time (just ONE) that it logged off in normal time. took just a few seconds.