Fix long delay at session termination on certain systems

This resolves Bug 760
Add shutdown profiling code and disable at compile time

1 files changed, 62 insertions, 17 deletions

diff --git a/ksmserver/shutdown.cpp b/ksmserver/shutdown.cpp
index 87b9836b1..05bfd0af2 100644
--- a/ksmserver/shutdown.cpp
+++ b/ksmserver/shutdown.cpp
@@ -95,6 +95,14 @@ CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
 #include "shutdowndlg.h"
 #include "client.h"
 
+// #define PROFILE_SHUTDOWN 1
+
+#ifdef PROFILE_SHUTDOWN
+	#define SHUTDOWN_MARKER(x) printf("[ksmserver] '%s' [%s]\n\r", x, TQTime::currentTime().toString("hh:mm:ss:zzz").ascii()); fflush(stdout);
+#else // PROFILE_SHUTDOWN
+	#define SHUTDOWN_MARKER(x)
+#endif // PROFILE_SHUTDOWN
+
 void KSMServer::logout( int confirm, int sdtype, int sdmode )
 {
     shutdown( (TDEApplication::ShutdownConfirm)confirm,
@@ -221,7 +229,7 @@ void KSMServer::shutdownInternal( TDEApplication::ShutdownConfirm confirm,
     }
 
     if ( logoutConfirmed ) {
-
+	SHUTDOWN_MARKER("Shutdown initiated");
 	shutdownType = sdtype;
 	shutdownMode = sdmode;
 	bootOption = bopt;
@@ -230,8 +238,9 @@ void KSMServer::shutdownInternal( TDEApplication::ShutdownConfirm confirm,
         // shall we save the session on logout?
         saveSession = ( config->readEntry( "loginMode", "restorePreviousLogout" ) == "restorePreviousLogout" );
 
-        if ( saveSession )
+        if ( saveSession ) {
             sessionGroup = TQString("Session: ") + SESSION_PREVIOUS_LOGOUT;
+        }
 
         // Set the real desktop background to black so that exit looks
         // clean regardless of what was on "our" desktop.
@@ -242,6 +251,7 @@ void KSMServer::shutdownInternal( TDEApplication::ShutdownConfirm confirm,
         wmPhase1WaitingCount = 0;
         saveType = saveSession?SmSaveBoth:SmSaveGlobal;
 	performLegacySessionSave();
+	SHUTDOWN_MARKER("Legacy save complete");
         startProtection();
         for ( KSMClient* c = clients.first(); c; c = clients.next() ) {
             c->resetState();
@@ -271,8 +281,9 @@ void KSMServer::shutdownInternal( TDEApplication::ShutdownConfirm confirm,
                 SmsSaveYourself( c->connection(), saveType,
                              true, SmInteractStyleAny, false );
         }
-        if ( clients.isEmpty() )
+        if ( clients.isEmpty() ) {
             completeShutdownOrCheckpoint();
+        }
     }
     else {
        if (showLogoutStatusDlg) {
@@ -505,12 +516,15 @@ void KSMServer::protectionTimeout()
 
 void KSMServer::completeShutdownOrCheckpoint()
 {
-    if ( state != Shutdown && state != Checkpoint )
+    SHUTDOWN_MARKER("completeShutdownOrCheckpoint");
+    if ( state != Shutdown && state != Checkpoint ) {
         return;
+    }
 
     for ( KSMClient* c = clients.first(); c; c = clients.next() ) {
-        if ( !c->saveYourselfDone && !c->waitForPhase2 )
+        if ( !c->saveYourselfDone && !c->waitForPhase2 ) {
             return; // not done yet
+        }
     }
 
     // do phase 2
@@ -522,8 +536,10 @@ void KSMServer::completeShutdownOrCheckpoint()
             waitForPhase2 = true;
         }
     }
-    if ( waitForPhase2 )
+    if ( waitForPhase2 ) {
         return;
+    }
+    SHUTDOWN_MARKER("Phase 2 complete");
 
     bool showLogoutStatusDlg = TDEConfigGroup(TDEGlobal::config(), "Logout").readBoolEntry("showLogoutStatusDlg", true);
     if (showLogoutStatusDlg && state != Checkpoint) {
@@ -544,10 +560,14 @@ void KSMServer::completeShutdownOrCheckpoint()
         static_cast<KSMShutdownIPDlg*>(shutdownNotifierIPDlg)->setStatusMessage(i18n("Saving your settings..."));
     }
 
-    if ( saveSession )
+    if ( saveSession ) {
         storeSession();
-    else
+        SHUTDOWN_MARKER("Session stored");
+    }
+    else {
         discardSession();
+        SHUTDOWN_MARKER("Session discarded");
+    }
 
     if ( state == Shutdown ) {
         bool waitForKNotify = true;
@@ -563,8 +583,9 @@ void KSMServer::completeShutdownOrCheckpoint()
         }
         // event() can return -1 if KNotifyClient short-circuits and avoids KNotify
         logoutSoundEvent = KNotifyClient::event( 0, "exitkde" ); // KDE says good bye
-        if( logoutSoundEvent <= 0 )
+        if( logoutSoundEvent <= 0 ) {
             waitForKNotify = false;
+        }
         if( waitForKNotify ) {
             state = WaitingForKNotify;
             knotifyTimeoutTimer.start( 20000, true );
@@ -577,15 +598,17 @@ void KSMServer::completeShutdownOrCheckpoint()
         }
         state = Idle;
     }
+    SHUTDOWN_MARKER("Fully shutdown");
 }
 
 void KSMServer::startKilling()
 {
+    SHUTDOWN_MARKER("startKilling");
     knotifyTimeoutTimer.stop();
     // kill all clients
     state = Killing;
     for ( KSMClient* c = clients.first(); c; c = clients.next() ) {
-        if( isWM( c ) || isCM( c ) ) // kill the WM and CM as the last one in order to reduce flicker
+        if( isWM( c ) || isCM( c ) || isNotifier( c ) ) // kill the WM and CM as the last one in order to reduce flicker.  Also wait to kill knotify to avoid logout delays
             continue;
         kdDebug( 1218 ) << "completeShutdown: client " << c->program() << "(" << c->clientId() << ")" << endl;
         SmsDie( c->connection() );
@@ -599,12 +622,13 @@ void KSMServer::startKilling()
 
 void KSMServer::completeKilling()
 {
+    SHUTDOWN_MARKER("completeKilling");
     kdDebug( 1218 ) << "KSMServer::completeKilling clients.count()=" <<
         clients.count() << endl;
     if( state == Killing ) {
         bool wait = false;
         for( KSMClient* c = clients.first(); c; c = clients.next()) {
-            if( isWM( c ) || isCM( c ) )
+            if( isWM( c ) || isCM( c ) || isNotifier( c ) )
                 continue;
             wait = true; // still waiting for clients to go away
         }
@@ -616,6 +640,7 @@ void KSMServer::completeKilling()
 
 void KSMServer::killWM()
 {
+    SHUTDOWN_MARKER("killWM");
     state = KillingWM;
     bool iswm = false;
     if (shutdownNotifierIPDlg) {
@@ -631,6 +656,9 @@ void KSMServer::killWM()
         if( isCM( c )) {
             SmsDie( c->connection() );
         }
+        if( isNotifier( c )) {
+            SmsDie( c->connection() );
+        }
     }
     if( iswm ) {
         completeKillingWM();
@@ -642,6 +670,7 @@ void KSMServer::killWM()
 
 void KSMServer::completeKillingWM()
 {
+    SHUTDOWN_MARKER("completeKillingWM");
     kdDebug( 1218 ) << "KSMServer::completeKillingWM clients.count()=" <<
         clients.count() << endl;
     if( state == KillingWM ) {
@@ -653,18 +682,26 @@ void KSMServer::completeKillingWM()
 // shutdown is fully complete
 void KSMServer::killingCompleted()
 {
+    SHUTDOWN_MARKER("killingCompleted");
     kapp->quit();
 }
 
 // called when KNotify performs notification for logout (not when sound is finished though)
 void KSMServer::notifySlot(TQString event ,TQString app,TQString,TQString,TQString,int present,int,int,int)
 {
-    if( state != WaitingForKNotify )
+    SHUTDOWN_MARKER("notifySlot");
+    if( state != WaitingForKNotify ) {
+        SHUTDOWN_MARKER("notifySlot state != WaitingForKNotify");
         return;
-    if( event != "exitkde" || app != "ksmserver" )
+    }
+    if( event != "exitkde" || app != "ksmserver" ) {
+        SHUTDOWN_MARKER("notifySlot event != \"exitkde\" || app != \"ksmserver\"");
         return;
-    if( present & KNotifyClient::Sound ) // logoutSoundFinished() will be called
+    }
+    if( present & KNotifyClient::Sound ) { // logoutSoundFinished() will be called
+        SHUTDOWN_MARKER("notifySlot present & KNotifyClient::Sound");
         return;
+    }
     startKilling();
 }
 
@@ -672,23 +709,30 @@ void KSMServer::notifySlot(TQString event ,TQString app,TQString,TQString,TQStri
 // emitted in KNotify only after the sound is finished playing.
 void KSMServer::logoutSoundFinished( int event, int )
 {
-    if( state != WaitingForKNotify )
+    SHUTDOWN_MARKER("logoutSoundFinished");
+    if( state != WaitingForKNotify ) {
         return;
-    if( event != logoutSoundEvent )
+    }
+    if( event != logoutSoundEvent ) {
         return;
+    }
     startKilling();
 }
 
 void KSMServer::knotifyTimeout()
 {
-    if( state != WaitingForKNotify )
+    SHUTDOWN_MARKER("knotifyTimeout");
+    if( state != WaitingForKNotify ) {
         return;
+    }
     startKilling();
 }
 
 void KSMServer::timeoutQuit()
 {
+    SHUTDOWN_MARKER("timeoutQuit");
     for (KSMClient *c = clients.first(); c; c = clients.next()) {
+        SHUTDOWN_MARKER(TQString("SmsDie timeout, client %1 (%2)").arg(c->program()).arg(c->clientId()).ascii());
         kdWarning( 1218 ) << "SmsDie timeout, client " << c->program() << "(" << c->clientId() << ")" << endl;
     }
     killWM();
@@ -696,6 +740,7 @@ void KSMServer::timeoutQuit()
 
 void KSMServer::timeoutWMQuit()
 {
+    SHUTDOWN_MARKER("timeoutWMQuit");
     if( state == KillingWM ) {
         kdWarning( 1218 ) << "SmsDie WM timeout" << endl;
     }