Der Start eines Computers bis zur Anmeldemaske dauert mehr als 4 Minuten

Hallo, Martin hier mit einem Gastbeitrag (*) .

Unser Unternehmen betreut als IT-Dienstleister etwa 700 Kunden mit zusammen 100.000 Arbeitsplätzen unter Vista SP2. Das hier analysierte Problem ist aber auch auf Windows 7 vorhanden.
Einer unserer Kunden meldete uns vor einiger Zeit ein Problem beim Computerstart. Der dauert gewöhnlich etwa 2 Minuten bis zur Anmeldemaske. Auf einigen Rechnern allerdings waren es 4 Minuten und mehr!
Ich werfe einen schnellen – und etwas unscharfen – Blick in die üblichen Eventlogs (System und Anwendung), finde aber keine Auffälligkeiten. Computerstartskripte laufen asynchron, daran kann es auch nicht liegen. Also brauche ich weitergehende Analysemöglichkeiten.

Aus der Vergangenheit weiß ich, dass das Group Policy Service Log ein wertvoller Einstiegspunkt in die Analyse des Startverhaltens ist. Also habe ich zunächst das Logging aktiviert (https://support.microsoft.com/kb/944043/de). Das produziert dann ein ASCII-File %Windir%\Debug\Usermode\gpsvc.log – allerdings etwas unübersichtlich.

Aber Dank https://www.sysprosoft.com/policyreporter.shtml ist die Analyse dann doch recht einfach – auf jeden Fall einfacher als in Notepad ;-) Besonders interessant für mich ist hier das Policy Reporter Feature, dass die seit Beginn der GPO-Verarbeitung verstrichene Zeit direkt angezeigt wird. Damit lassen sich – sofern GPO-begründet – Zeitprobleme sehr schnell finden.

Hier sehe ich sofort, dass die Security-Extension 90 Sekunden benötigt – nur wofür? Ein genauerer Blick in den entsprechenden Abschnitt der Security-Extension im GPSvc.log:

GPSVC(484.4dc) 07:48:55:861 MachinePolicyCallback: Setting status UI to Die Sicherheitsrichtlinie für das System wird konfiguriert.
GPSVC(170.bf4) 07:49:35:373 CGPNotify::RegisterForNotification: Entering with target Machine and event 0x1a4
GPSVC(170.bf4) 07:49:35:373 Client_InitialRegisterForNotification: User = machine, changenumber = 0
GPSVC(484.4e0) 07:49:35:373 Target = Machine
GPSVC(170.bf4) 07:49:35:373 Client_RegisterForNotification: User = machine, changenumber = 0
GPSVC(484.4e0) 07:49:35:373 Target = Machine, ChangeNumber 0
GPSVC(170.bf4) 07:49:35:373 CGPNotify::RegisterForNotification: Exiting with status = 0
GPSVC(414.cac) 07:50:21:143 CGPNotify::RegisterForNotification: Entering with target Machine and event 0x9cc
GPSVC(414.cac) 07:50:21:143 Client_InitialRegisterForNotification: User = machine, changenumber = 0
GPSVC(484.4e0) 07:50:21:158 Target = Machine
GPSVC(414.cac) 07:50:21:158 Client_RegisterForNotification: User = machine, changenumber = 0
GPSVC(414.cac) 07:50:21:158 CGPNotify::RegisterForNotification: Exiting with status = 0
GPSVC(484.4e0) 07:50:21:158 Target = Machine, ChangeNumber 0
GPSVC(484.4dc) 07:50:24:373 MachinePolicyCallback: Setting status UI to Computereinstellungen werden übernommen...
GPSVC(484.4dc) 07:50:24:373 ProcessGPOList: Extension Security returned 0x4e4.

Das ist also auch noch nicht das “Gelbe vom Ei” – ich sehe zwar, dass es lange dauert, aber ich sehe nicht, warum. Dann schauen wir mal im Protokoll der Security-Extension in %Windir%\Security\Logs\Winlogon.log nach. Dort finde ich zu Beginn

Dienstag, 13. Juli 2010 07:48:54
Benutzer mit Administratorenrechten hat sich angemeldet.

Und gegen Ende dann noch

Die Richtlinienpropagierung wird im blockierenden Winlogon-Thread aufgerufen. Erstellen Sie einen anderen Thread für langsame Aufgaben.
-------------------------------------------
Dienstag, 13. Juli 2010 07:50:24

Dazwischen kommt die ganze Security-Verarbeitung mit Rechten, Diensten, Sicherheitseinstellungen usw. – aber das hier sind leider die einzigen Einträge, die einen Zeitstempel haben. Also weiß ich immer noch nicht, was den Hänger von 1:30 verursacht. Aber da fällt mir ein Kommentar von Mark Russinovich auf der Teched 2009 in Berlin ein: „If you don’t know what to do – use Process Monitor.“
Also erstellen wir ein Procmon Boot-Log. In diesem Log ist die erste Analyse dann per Filter auf Winlogon.Log – ich will wissen, wo genau die Security Extension hängen bleibt.

Das reduziert das Bootlog auf 900 Events, und auch hier finde ich dann tatsächlich eine Lücke von 1:30.

Jetzt will ich nur noch wissen, welcher Eintrag im Winlogon.log da geschrieben wurde. Und das mache ich über den Offset (1.020.360) und einen Hexeditor. Den Hexeditor brauche ich, weil Winlogon.log ein Unicode-File ist, also 2 Byte pro Zeichen. Der WriteFile in 519 mit 4 Byte ist wohl ein CR/LF. Und im Hexeditor identifiziere ich dann diese Zeilen:

Konfigurieren von BITS.

(Das wird in Seq. 518 geschrieben.)

Konfiguration allgemeiner Diensteinstellungen wurde erfolgreich abgeschlossen.

(Das wird in Seq. 520 geschrieben.)

Also macht die Security Extension nach dem Konfigurieren des letzten Dienstes (hier BITS) „irgend etwas“, was 1:30 dauert. Das war dann der Zeitpunkt, bei EMEA GTSC einen Call zu eröffnen – Source Code war gefragt. Mein freundlicher Escalation Engineer findet dann auch sehr schnell heraus: Nach dem Konfigurieren der Dienste hat die Security Extension eine Schleife, in der alle Dienste mit Start=Auto einfach mal gestartet werden. Geht dabei vielleicht etwas schief? Dann schauen wir doch mal, ob es Autostart-Dienste gibt, die nicht gestartet sind:

C:\>wmic service where (startmode="Auto" and State !="Running") list brief
ExitCode Name ProcessId StartMode State Status
0 EgononAgent 0 Auto Stopped OK
0 msiserver 0 Auto Stopped OK
0 TBS 0 Auto Stopped OK
0 UTAXACCOUNTING4WORK_client 5368 Auto Start Pending OK

Hoppla - da ist also ein Autostart-Dienst, der lange nach Boot des Computers immer noch “Start Pending” hat – Bingo! Jetzt noch ein schneller Blick in die Ereignisanzeige:

06.08.2010 07:56:12 Service Control Manager UTAX ACCOUNTING4WORK client service 7022 ERROR

Datum und Uhrzeit passen nicht zu dem GPSvc.log oben, aber das ändert nichts – da protokolliert der SCM also einen 7022 – „Service hung on startup“. Und im aktuellen Winlogon.log/GPSvc.log passen die dort protokollierten Zeiten exakt zu diesem Hänger – 2 Sekunden später geht die GPO-Verarbeitung weiter. Auch im Process Monitor Log taucht ein entsprechender Eintrag auf – aber den finde ich erst jetzt, da ich weiß, wonach ich suche:

Etwas deutlicher:

Da zündet das Windows Error Reporting (wermgr.exe) und beschäftig sich genau mit dem Executable meines hängenden Dienstes. Aber in knapp 4 Millionen Einträgen kann man das schon mal übersehen ;-)

Damit war der Fall für uns glücklicherweise gelöst – alles weitere ist jetzt Aufgabe unseres Kunden: Kontaktieren des Anwendungsherstellers, Beheben dieses Dienst-Startproblems und dergleichen mehr.

* Rechtlicher Hinweis: Bei den hier als "Gastbeitrag" markierten Artikeln handelt es sich um Blogs, die von nicht-Microsoft Mitarbeitern verfasst wurden. Diese Beiträge geben ausschließlich die Meinung des jeweiligen Autors wieder und stimmen nicht unbedingt mit der Meinung von Microsoft überein. Microsoft macht sich diese Beiträge ausdrücklich nicht zu eigen. Eine Vorabkontrolle der Beiträge findet nicht statt. Dementsprechend kann Microsoft keine Verantwortung oder Gewähr für die Beiträge übernehmen.