Einführung

Auf einem Server 2016 hatten manche User das Problem, dass der Edge nach dem starten hängen bleibt (nachdem Microsoft Edge aktualisiert wurde).

Das Verhalten ist unterschiedlich, manchmal bleibt der Edge hängen, manchmal bleibt die ganze Seite weiß. Schauen wir uns das Problem etwas näher an.

Erstes Troubleshooting

Es lies sich relativ schnell herausfinden, dass mit einem neuen Edge Profil (löschen von C:\Users\%username%\AppData\Local\Microsoft\Edge\User Data\Default) das Problem gelöst ist.
Normalerweiße ist das kein Problem, allerdings ist der Verlust von Lesezeichen schmerzhaft.

Das gute ist, wir wissen jetzt dass das Problem irgendwie mit dem Profil zusammenhängt. Wir müssen nichts troubleshooten auf Maschinen Ebene. Das Problem ist irgendwie im Profil.

Process Monitor

Ich hab ein Trace mit Process Monitor gemacht während dem Edge starten und dann gestoppt, sobald die Titlebar anzeigt, dass der Edge eingefroren ist. Ich habe auf msedge.exe gefiltert und summiere mir das Feld Results:

Das sind eine menge Events. ACCESS DENIED ist eigentlich immer interessant für mich. Aber was wissen wir bis jetzt? Nur Aktivtät innerhalb des Verzeichnis C:\users\%username%\AppData\Local\Microsoft\Edge\User Data ist von Interesse. Daher filtern wir das Logfile weiter auf diese Eigenschaft.

Kein ACCESS DENIED und paar einige andere sind verschwunden. Zusammenfassend, schaut alles okay aus - keine weiteren Hinweise für mich zu finden.

Memory Dump

I dachte es wäre eine gute Idee ein Memory Dump von dem Prozess zu machen. Ich habe das mit procdump -ma {procid} gemacht. Wir laden dann die *.dmp Datei in WinDbg.

[!TIP] Wie findet man den richtigen Stack? Üblicherweise hat ein Prozess mehrere Threads. Wie viele? Das findet man mit ~ im WinDbg heraus. In meinem Fall hatte ich 45 Threads. Die meisten Threads sind WorkerThreads - also Threads die auf Arbeit warten. Die können wir in der Regel ignorieren. Ein typische Eigenschaft ist, dass diese WorkerThreads oft sehr “kurz” sind (~8).

Die geniale Extension PDE extension von Andrew Richards erleichtert uns die Abfrage. Wir laden die Extension mit: .load C:\path\x64\winext\PDE.dll Danach können wir !deep 15 ausführen - das Kommando zeigt alle Call Stacks an die eine Tiefe von 15 oder höher sind.

Nun möchten wir den Stack überprüfen:

0:000> k
 # Child-SP          RetAddr               Call Site
00 000000fd`b5bfd5b0 00007ffd`d1fd189b     msedge!std::Cr::__tree<std::Cr::basic_string<char16_t,std::Cr::char_traits<char16_t>,std::Cr::allocator<char16_t> >,std::Cr::less<std::Cr::basic_string<char16_t,std::Cr::char_traits<char16_t>,std::Cr::allocator<char16_t> > >,std::Cr::allocator<std::Cr::basic_string<char16_t,std::Cr::char_traits<char16_t>,std::Cr::allocator<char16_t> > > >::__find_equal<std::Cr::basic_string<char16_t,std::Cr::char_traits<char16_t>,std::Cr::allocator<char16_t> > >+0xa2
01 000000fd`b5bfd620 00007ffd`d1fd1694     msedge!std::Cr::__tree<std::Cr::basic_string<char16_t,std::Cr::char_traits<char16_t>,std::Cr::allocator<char16_t> >,std::Cr::less<std::Cr::basic_string<char16_t,std::Cr::char_traits<char16_t>,std::Cr::allocator<char16_t> > >,std::Cr::allocator<std::Cr::basic_string<char16_t,std::Cr::char_traits<char16_t>,std::Cr::allocator<char16_t> > > >::__find_equal<std::Cr::basic_string<char16_t,std::Cr::char_traits<char16_t>,std::Cr::allocator<char16_t> > >+0x17f
02 000000fd`b5bfd6a0 00007ffd`d2e44eb8     msedge!std::Cr::__tree<std::Cr::basic_string<char16_t,std::Cr::char_traits<char16_t>,std::Cr::allocator<char16_t> >,std::Cr::less<std::Cr::basic_string<char16_t,std::Cr::char_traits<char16_t>,std::Cr::allocator<char16_t> > >,std::Cr::allocator<std::Cr::basic_string<char16_t,std::Cr::char_traits<char16_t>,std::Cr::allocator<char16_t> > > >::__emplace_hint_unique_key_args<std::Cr::basic_string<char16_t,std::Cr::char_traits<char16_t>,std::Cr::allocator<char16_t> >,std::Cr::basic_string<char16_t,std::Cr::char_traits<char16_t>,std::Cr::allocator<char16_t> > const & __ptr64>+0x50
03 000000fd`b5bfd710 00007ffd`d2e44618     msedge!autofill::AutofillProfileComparator::GetNamePartVariants+0x480
04 000000fd`b5bfd8c0 00007ffd`d2e43fd8     msedge!autofill::AutofillProfileComparator::IsNameVariantOf+0xaa
05 000000fd`b5bfdae0 00007ffd`d2e43910     msedge!autofill::AutofillProfileComparator::HaveMergeableNames+0x298
06 000000fd`b5bfdc20 00007ffd`d2e3aec5     msedge!autofill::AutofillProfileComparator::AreMergeable+0x8e
07 000000fd`b5bfdc60 00007ffd`ccddac54     msedge!autofill::PersonalDataManagerCleaner::DedupeProfiles+0x1fd
08 000000fd`b5bfdd60 00007ffd`ccdd7ced     msedge!autofill::PersonalDataManagerCleaner::ApplyDedupingRoutine+0x1e8
09 000000fd`b5bfdea0 00007ffd`ccdd7c40     msedge!autofill::PersonalDataManagerCleaner::ApplyAddressFixesAndCleanups+0x15
0a 000000fd`b5bfded0 00007ffd`ccdd90c0     msedge!autofill::PersonalDataManagerCleaner::CleanupDataAndNotifyPersonalDataObservers+0x120
0b 000000fd`b5bfdf40 00007ffd`ccdd8a1c     msedge!autofill::AlternativeStateNameMapUpdater::LoadStatesData+0xcc
0c 000000fd`b5bfe070 00007ffd`ccdd7c02     msedge!autofill::AlternativeStateNameMapUpdater::PopulateAlternativeStateNameMap+0xd0
0d 000000fd`b5bfe220 00007ffd`ccdd6eec     msedge!autofill::PersonalDataManagerCleaner::CleanupDataAndNotifyPersonalDataObservers+0xe2
0e 000000fd`b5bfe290 00007ffd`cc918780     msedge!autofill::PersonalDataManager::OnWebDataServiceRequestDone+0x43c
0f 000000fd`b5bfe390 00007ffd`cdf911e7     msedge!WebDataRequestManager::RequestCompletedOnThread+0x70
10 000000fd`b5bfe3e0 00007ffd`cdfc8142     msedge!base::internal::Invoker<base::internal::BindState<void (WebDataRequestManager::*)(std::Cr::unique_ptr<WebDataRequest,std::Cr::default_delete<WebDataRequest> >, std::Cr::unique_ptr<WDTypedResult,std::Cr::default_delete<WDTypedResult> >),scoped_refptr<WebDataRequestManager>,std::Cr::unique_ptr<WebDataRequest,std::Cr::default_delete<WebDataRequest> >,std::Cr::unique_ptr<WDTypedResult,std::Cr::default_delete<WDTypedResult> > >,void ()>::RunOnce+0x47
11 000000fd`b5bfe420 00007ffd`ca23669f     msedge!base::TaskAnnotator::RunTaskImpl+0x122
12 000000fd`b5bfe560 00007ffd`ca782a81     msedge!base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWorkImpl+0x58f
13 000000fd`b5bfe870 00007ffd`cbaca689     msedge!base::MessagePumpForUI::DoRunLoop+0xcc1
14 000000fd`b5bfea40 00007ffd`cc403cfe     msedge!base::MessagePumpWin::Run+0x79
15 000000fd`b5bfeaa0 00007ffd`cc40b2ac     msedge!base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::Run+0x11e
16 000000fd`b5bfeb50 00007ffd`cc2e98f0     msedge!base::RunLoop::Run+0xfc
17 000000fd`b5bfec50 00007ffd`cc2e95cc     msedge!content::BrowserMainLoop::RunMainMessageLoop+0x9a
18 000000fd`b5bfecc0 00007ffd`cc2e8caa     msedge!content::BrowserMain+0xa4
19 000000fd`b5bfed70 00007ffd`cc2e7e42     msedge!content::RunBrowserProcessMain+0xe0
1a 000000fd`b5bfee90 00007ffd`cc2a651e     msedge!content::ContentMainRunnerImpl::RunBrowser+0x46e
1b 000000fd`b5bfeff0 00007ffd`cc1cf536     msedge!content::ContentMainRunnerImpl::Run+0x31e
1c 000000fd`b5bff140 00007ffd`cc1ce2f4     msedge!content::RunContentProcess+0x2e3
1d 000000fd`b5bff360 00007ffd`cc1cd6be     msedge!content::ContentMain+0x64
1e 000000fd`b5bff3f0 00007ff6`2ff25626     msedge!ChromeMain+0x27e
1f 000000fd`b5bff710 00007ff6`30013be2     msedge_exe!MainDllLoader::Launch+0x386
20 000000fd`b5bff9a0 00007ff6`2ffceca2     msedge_exe!wWinMain+0xf2c
21 000000fd`b5bffec0 00007ffe`4a2384d4     msedge_exe!__scrt_common_main_seh+0x106
22 000000fd`b5bfff00 00007ffe`4a9a1791     kernel32!BaseThreadInitThunk+0x14
23 000000fd`b5bfff30 00000000`00000000     ntdll!RtlUserThreadStart+0x21

Man muss den Stack von unten nach oben lesen. Die ersten Zeilen zeigen die normale “Startup”-Routine. Dieser Teil scheint interessant zu sein:

03 000000fd`b5bfd710 00007ffd`d2e44618     msedge!autofill::AutofillProfileComparator::GetNamePartVariants+0x480
04 000000fd`b5bfd8c0 00007ffd`d2e43fd8     msedge!autofill::AutofillProfileComparator::IsNameVariantOf+0xaa
05 000000fd`b5bfdae0 00007ffd`d2e43910     msedge!autofill::AutofillProfileComparator::HaveMergeableNames+0x298
06 000000fd`b5bfdc20 00007ffd`d2e3aec5     msedge!autofill::AutofillProfileComparator::AreMergeable+0x8e
07 000000fd`b5bfdc60 00007ffd`ccddac54     msedge!autofill::PersonalDataManagerCleaner::DedupeProfiles+0x1fd
08 000000fd`b5bfdd60 00007ffd`ccdd7ced     msedge!autofill::PersonalDataManagerCleaner::ApplyDedupingRoutine+0x1e8
09 000000fd`b5bfdea0 00007ffd`ccdd7c40     msedge!autofill::PersonalDataManagerCleaner::ApplyAddressFixesAndCleanups+0x15
0a 000000fd`b5bfded0 00007ffd`ccdd90c0     msedge!autofill::PersonalDataManagerCleaner::CleanupDataAndNotifyPersonalDataObservers+0x120
0b 000000fd`b5bfdf40 00007ffd`ccdd8a1c     msedge!autofill::AlternativeStateNameMapUpdater::LoadStatesData+0xcc
0c 000000fd`b5bfe070 00007ffd`ccdd7c02     msedge!autofill::AlternativeStateNameMapUpdater::PopulateAlternativeStateNameMap+0xd0
0d 000000fd`b5bfe220 00007ffd`ccdd6eec     msedge!autofill::PersonalDataManagerCleaner::CleanupDataAndNotifyPersonalDataObservers+0xe2
0e 000000fd`b5bfe290 00007ffd`cc918780     msedge!autofill::PersonalDataManager::OnWebDataServiceRequestDone+0x43c
0f 000000fd`b5bfe390 00007ffd`cdf911e7     msedge!WebDataRequestManager::RequestCompletedOnThread+0x70

Von WebDataRequestManager geht der Aufruf weiter zu autofill. Ich habe wieder einen Memory Dump von ein paar Sekunden später erzeugt und da sehen wir den gleichen Stack. Wir können die Funktionen nun googeln und finden auch ein paar Informationen zu dem Ding (ohne dem lesen von Source Code).

Okay, aber was können wir nun darüber sagen? Es scheint irgendwie mit dem autofill zusammenzuhängen. Und wir wissen auch, dass zumindestens eine Datei im Profil “korrupt” ist und ein neues Profil das Problem löst. Die nächste Suche im Internet könnte sowas etwas sein wie: “chromium autofill file location” und wir würden diesen Artikel finden: superuser.com article.
Wir lernen dass die “autofill”-Datei unter {AppData}\Microsoft\Edge\User Data\Default\Web Data ist.. interessant.

Aber um ehrlich zu sein, so lief es bei mir nicht und ich hab ein weiteres Werkzeug verwendet um das Problem weiter einzugrenzen.

Windows Performance Analyzer

Weil mir ProcMon nicht vollständig geholfen hat, dachte ich ein ETL Trace wäre eine gute Idee. Man kann dazu Windows Performance Recorder oder UIforETW verwenden.
Nachdem ich ein .ETL Trace gemacht habe, verwende ich Windows Performance Analyzer um die Datei zu öffnen. Am besten die Version über den Microsoft Store beziehen.

Wir sehen etwas was wir erwarten können. Üblicherweise wird so etwas CPU saturation genannt und in unserem Fall wird ein Core komplett ausgelastet für msedge.exe (100/16 = 6,25).

Wir sehen dass der Stack Trace auch das autofill aufzeigt - das wissen wir bereits von der Memory Dump Analyse. Aber wir möchten ja wissen, um welche Datei es genau geht.

Disk usage window

Wir können also disk usage auswählen und Utilization by Process, Path Name, Stack auswählen.

Interessant ist das unser Freund Web Data wieder da ist. Keine completion time - so ein noch ausständiger Dateizugriff.

Wenn wir diese Datei löschen, öffnet sich MS Edge ohne dass das Fenster einfriert.

Fazit

Wir konnten die problematische Datei relativ einfach finden. ProcMon hat mir nicht geholfen aber mittels WinDbg und schlussendlich auch mit WPA habe ich genau die Datei gefunden die ich gesucht habe.
Das Problem selbst ist durchaus etwas komisch. Manchmal habe ich ein altes Web Data Verzeichnis wiederhergestellt (für das Nachstellen des Problems) - aber es hat funktioniert. Ich hatte auch einmal den Fall, dass ich sehr lange gewartet habe (>1h?) und dann hat es sich von alleine repariert und dann hat es wieder funktioniert.

Happy troubleshooting.