Netzwerkzugriff nur mit Verzögerung und langer Wartezeit

[cMaster]

Hi,

wenn ich auf meinen HomeServer zugreife, habe ich sehr häufige - für mich undefinierbare - Wartezeiten.
Wenn ich auf einen auf dem WHS freigegebenen Ordner zugreife (mittels des Windows-Explorers), dauert es zwischen 10 und 30 Sekunden, bis der Ordnerinhalt angezeigt wird, also bis der Explorer eine Antwort vom WHS erhält. Dieses Problem ist bei sämtlichen Zugriffen auf den Server, wenn ich z. B. eine Datei öffnen möchte (oder der Player das nächste Lied beginnen möchte zu spielen), dann hängt erstmal die ganze Anwendung, aller frühestens 10 sek. nach dem Zugriffsversuch kommt dann eine Antwort vom Server, und der Zugriff ist problemlos möglich. Dasselbe auch, wenn ich eine Access-DB geöffnet habe, eine andere Tabelle anklicke, und Access auf die mdb-Datei zugreifen möchte - Access hängt erstmal - einige Wartezeit später (die genannten 10 bis 30 sek.) - werden die Daten dann angezeigt.

Dieses Problem tritt nicht immer bei jedem Zugriff auf, allerdings sehr häufig. Es kann also sein, 15 Min lang kann ich ohne jegliches Warten zugreifen, dann kann es innerhalb 15 Min aber auch 3 oder 10 mal so sein, also nicht wirklich definierbar.

Was ich allerdings schon beobachten habe: Beim Zugriff auf den WHS "schläft" dieser genau solang, bis die "demigrator.exe" eine CPU-Last von 100% für 2 bis 3 sek. verursacht, dann erfolgt der Zugriff auf den Ordner oder die Datei problemlos.

Was macht die "demigrator.exe" eigentlich überhaupt genau? Ich habe über diese Datei schon einige Sachen gelesen, aber mir ist nicht ganz klar, in wie fern mein Problem mit dieser Datei zu tun haben soll.

Dieses Problem beobachte ich, seitdem ich meinen WHS vom PowerPack 1 auf PP 3 aktualisiert habe. Zur selben Zeit wurden vom Windows-Updater ca. 80 weitere Sicherheitsupdates installiert.

Der Zugriff auf den WHS erfolgt von einem Windows XP System aus.
Auf dem WHS läuft der F-Secure Viren-Scanner, allerdings lief dieser auch schon zu PowerPack-1-Zeiten.

Weiß irgend jemand eine Lösung für dieses Problem? Denn so kann man absolut nicht arbeiten und ich weiß wirklich nicht weiter.

Im Voraus schon mal: Vielen Dank!

Gruß Stefan

[Nobby1805]

"Normalerweise" läuft der DEmigrator nur einmal pro Stunde und führt Duplizierung, Datenausgleich und Konsistenzprüfung durch.

Wenn du diese Abhängigkeit beobachtest schau mal in der DEutils-Logfile auf dem WSH ob dort etwas angezeigt wird, du kannst auch das Loglevel des DEmigrators auf Verboise hochsetzten um mehr zu sehen

[cMaster]

Hi,

wenn die demigrator.exe für Duplizierung und Datenausgleich zuständig ist, ist das aber noch merkwürdiger, denn ich habe nur eine einzelne Festplatte eingebaut. Somit gibt es ja eigentlich nichts zum duplizieren.

Was heißt "Konsistenzprüfung" genau bzw. was macht der dabei?

Ich kann in den Logfiles nichts nützliches finden, zumal nach 11:00 Uhr nur eine einzelne Logdatei mit Logs von 17:23 bis 17:26 existiert.

Wo kann ich das Log-Level der DEmigrator ändern?

Gruß Stefan

[Nobby1805]

Was heißt "Konsistenzprüfung" genau bzw. was macht der dabei?

Tja, wenn MS das dokumentiert hätte ... nach meinen Beobachtungen wird die Konsistenz zwischen Tombstones und Datenfiles geprüft

Ich kann in den Logfiles nichts nützliches finden, zumal nach 11:00 Uhr nur eine einzelne Logdatei mit Logs von 17:23 bis 17:26 existiert.

Wo kann ich das Log-Level der DEmigrator ändern?

Gruß Stefan

Schaust du im richtigen Logfile ? Es werden jede Stunden (bei mir) 2 Logfiles angelegt, davon ist einer i.D.R. leer
Das Loglevel kannst du hier erhöhen .. Tracemask auf 7, F, 1F, ...

deutil trace.png (12.89 KiB) 1898 mal betrachtet

[cMaster]

Oh, Entschuldigung!
Bei mir werden die Dateien auch Stündlich angelegt, hab mich verguckt, is aber eigenartig... Ich hab ne Log-Datei vom DEutil vom 07.03.2010 von 17:36 Uhr !? und nochmal eine um 17:24 ???
Deshalb hab ich das erst nicht geblickt

Hab das log-level jetzt mal auf F gesetzt, aber was ist da eig. die Obergrenze?

Hab hier mal 2 log-files, eine von gestern Abend (als ich das Problem sehr häufig hatte), und eine von heute Mittag. Ich kann damit nicht so wahnsinnig viel mit anfangen, was der mir damit genau sagen will.


06.03.2010 19:00 - DEUtil.030610.190000.4984.log

Code: Alles auswählen

[06.03.2010 19:00:00]
[06.03.2010 19:54:34 13d0] Sleeping between passes 3600717,9624ms
[06.03.2010 19:54:34 13d0] MigrationDisabled = 0
[06.03.2010 19:54:34 13d0] Audit Grace Period is set to: 1440
[06.03.2010 19:54:34 13d0] ***Starting Primary Pass
[06.03.2010 19:58:04 13d0] Primary Pass: (duplication) 210750,109ms
[06.03.2010 19:58:04 13d0] ***Starting Secondary Pass
[06.03.2010 19:58:04 13d0] Volume information - 
Volume - Id = abaebf54-a5d2-47bb-a0b5-150696267881 Size = 1377 GB Free = 1279802 MB
[06.03.2010 19:58:09 13d0] ***ERROR: DEfileFromShadow(D:\DE\shares\Benutzer\Stefan\...[Pfad zur Datei]...\190_0.jpg,abaebf54-a5d2-47bb-a0b5-150696267881) took too long. 2781,1498ms
[06.03.2010 19:58:16 13d0] ***ERROR: DEfileFromShadow(D:\DE\shares\Benutzer\Stefan\...[Pfad zur Datei]...\address.png,abaebf54-a5d2-47bb-a0b5-150696267881) took too long. 2184,4133ms
[06.03.2010 19:58:35 13d0] ***ERROR: DEfileFromShadow(D:\DE\shares\Benutzer\Stefan\...[Pfad zur Datei]...\ddm.js,abaebf54-a5d2-47bb-a0b5-150696267881) took too long. 13372,0905ms
[06.03.2010 19:59:22 13d0] ***ERROR: DEfileFromShadow(D:\DE\shares\Benutzer\Stefan\...[Pfad zur Datei]....TTF,abaebf54-a5d2-47bb-a0b5-150696267881) took too long. 39492,1759ms
[06.03.2010 19:59:52 13d0] ***ERROR: DEfileFromShadow(D:\DE\shares\Musik\...[Pfad zur Datei]....mp3,abaebf54-a5d2-47bb-a0b5-150696267881) took too long. 28711,8365ms
[06.03.2010 19:59:54 13d0] OpenedFile::Lock: Error 300 from SendToFilter(BatchOplock) on D:\DE\shares\Öffentlich\...[Pfad zur Datei]...\BRDGMBH.avi
[06.03.2010 19:59:54 13d0] nonfatal - DEFileFromShadow(D:\DE\shares\Öffentlich\...[Pfad zur Datei]...\BRDGMBH.avi,abaebf54-a5d2-47bb-a0b5-150696267881) threw - err=170
[06.03.2010 19:59:54 13d0] Nonfatal exception in Secondary Pass on D:\DE\shares\Öffentlich\...[Pfad zur Datei]...\BRDGMBH.avi: error =170
[06.03.2010 19:59:55 13d0] Secondary Pass: (balancing) 110162,8162ms
[06.03.2010 19:59:55 13d0] Full Primary and Secondary Pass 320958,7997ms

07.03.2010 12:00 - DEUtil.030710.120000.5004.log

Code: Alles auswählen

[07.03.2010 12:00:00]
TraceCleanup: discarding log C:\Dokumente und Einstellungen\All Users\Anwendungsdaten\Microsoft\Windows Home Server\logs\DEUtil.022810.100000.3204.log
TraceCleanup: discarding log C:\Dokumente und Einstellungen\All Users\Anwendungsdaten\Microsoft\Windows Home Server\logs\DEUtil.022810.100000.4976.log
[07.03.2010 12:08:52 13e4] Sleeping between passes 3600672,9782ms
[07.03.2010 12:08:52 13e4] MigrationDisabled = 0
[07.03.2010 12:08:52 13e4] Audit Grace Period is set to: 1440
[07.03.2010 12:08:52 13e4] ***Starting Primary Pass
[07.03.2010 12:12:36 13e4] Primary Pass: (duplication) 224527,593ms
[07.03.2010 12:12:36 13e4] ***Starting Secondary Pass
[07.03.2010 12:12:36 13e4] Volume information - 
Volume - Id = abaebf54-a5d2-47bb-a0b5-150696267881 Size = 1377 GB Free = 1278991 MB
[07.03.2010 12:12:41 13e4] ***ERROR: DEfileFromShadow(D:\DE\shares\Benutzer\Stefan\...[Pfad zur Datei]....php,abaebf54-a5d2-47bb-a0b5-150696267881) took too long. 2301,2947ms
[07.03.2010 12:13:27 13e4] ***ERROR: DEfileFromShadow(D:\DE\shares\Benutzer\Stefan\...[Pfad zur Datei]...\47.JPG,abaebf54-a5d2-47bb-a0b5-150696267881) took too long. 6063,9511ms
[07.03.2010 12:14:20 13e4] ***ERROR: DEfileFromShadow(D:\DE\shares\Benutzer\Stefan\...[Pfad zur Datei]....dll,abaebf54-a5d2-47bb-a0b5-150696267881) took too long. 47921,1271ms
[07.03.2010 12:14:22 13e4] OpenedFile::Lock: Error 300 from SendToFilter(BatchOplock) on D:\DE\shares\Musik\Musik\lied1.mp3
[07.03.2010 12:14:22 13e4] nonfatal - DEFileFromShadow(D:\DE\shares\Musik\Musik\lied1.mp3,abaebf54-a5d2-47bb-a0b5-150696267881) threw - err=170
[07.03.2010 12:14:22 13e4] Nonfatal exception in Secondary Pass on D:\DE\shares\Musik\Musik\lied1.mp3: error =170
[07.03.2010 12:14:29 13e4] ***ERROR: DEfileFromShadow(D:\DE\shares\Software\...[Pfad zur Datei]....gif,abaebf54-a5d2-47bb-a0b5-150696267881) took too long. 7749,3863ms
[07.03.2010 12:14:31 13e4] Secondary Pass: (balancing) 114509,508ms
[07.03.2010 12:14:31 13e4] Full Primary and Secondary Pass 339070,4312ms

[Nobby1805]

Man bräuchte schon ein Log das mit F oder 1F geschrieben wurde (ob 3F oder 7F oder FF noch mehr Infos schreiben weiß nur Microsoft wenn das Problem auftritt, und dazu die exakte Uhrzeit ... mir ist übrigens nicht klar wann die Änderung der Registry sofort wirkt und wann erst nach einem Restart ... da sieht man das anscheinend jeder Programmierer bei MS es anders realisiert

Wie du aber den beiden Logs ansehen kannst läuft der DEmigrator jede Stunde "nur" ca. 5 Minuten

[06.03.2010 19:59:55 13d0] Full Primary and Secondary Pass 320958,7997ms

[cMaster]

Also, ich hab die Einstellung jetzt mal auf FF gesetzt und einen Neustart gemacht. Werde das jetzt mal beobachten und posten, sobald ich eine neue log-Datei habe.

Was mir jetzt gerade auch noch aufgefallen ist, die Wartezeit ist nicht nur bei sämtlichen Dateizugriffen übers Netzwerk, sondern auch wenn ich via IMAP auf meine Mails zugreife (auf dem WHS läuft der hMailServer).

[cMaster]

Hi,

ich hatte ja das Log-Level auf FF gesetzt, jetzt hat der mir da stündlich log-files mit 95 MB erstellt (sind ca. 300.000 Zeilen pro Datei)

Hier mal der Beginn einer Log-Datei:

Code: Alles auswählen

[08.03.2010 20:00:00]
TraceCleanup: discarding log C:\Dokumente und Einstellungen\All Users\Anwendungsdaten\Microsoft\Windows Home Server\logs\DEUtil.030110.180000.3216.log
TraceCleanup: discarding log C:\Dokumente und Einstellungen\All Users\Anwendungsdaten\Microsoft\Windows Home Server\logs\DEUtil.030110.180000.4964.log
[08.03.2010 20:23:05 13f8] Sleeping between passes 3600692,1223ms
[08.03.2010 20:23:05 13f8] MigrationDisabled = 0
[08.03.2010 20:23:05 13f8] Audit Grace Period is set to: 1440
[08.03.2010 20:23:05 13f8] ***Starting Primary Pass
[08.03.2010 20:23:05 13f8] PerformPrimaryPassOnDirectory(D:\)
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\QSM_VolumeID as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\QSM_VolumeID as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389 as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Error 2 opening {ABAEBF54-A5D2-47BB-A0B5-150696267881},\DE\432548661df40efcef629389
[08.03.2010 20:23:05 13f8] PerformPrimaryPassOnDirectory(D:\432548661df40efcef629389)
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64 as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Error 3 opening {ABAEBF54-A5D2-47BB-A0B5-150696267881},\DE\432548661df40efcef629389\amd64
[08.03.2010 20:23:05 13f8] PerformPrimaryPassOnDirectory(D:\432548661df40efcef629389\amd64)
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\filterpipelineprintproc.dll as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\filterpipelineprintproc.dll as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\msxpsdrv.cat as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\msxpsdrv.cat as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\msxpsdrv.inf as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\msxpsdrv.inf as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\msxpsinc.gpd as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\msxpsinc.gpd as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\msxpsinc.ppd as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\msxpsinc.ppd as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\mxdwdrv.dll as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\mxdwdrv.dll as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\xpssvcs.dll as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\amd64\xpssvcs.dll as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Opened D:\432548661df40efcef629389\i386 as handle 000005B8
[08.03.2010 20:23:05 13f8] OpenedFile::Open: Error 3 opening {ABAEBF54-A5D2-47BB-A0B5-150696267881},\DE\432548661df40efcef629389\i386
[08.03.2010 20:23:05 13f8] PerformPrimaryPassOnDirectory(D:\432548661df40efcef629389\i386)

So setzt sich das die restlichen 300.000 Zeilen fort. Ich hab das Log-Level jetzt auf F gesetzt, und schaue mir das morgen nochmal an.
Ach ja, die Einstellung wird scheints erst nach einem Neustart wirksam

Nur was ich mich frage: Was hat die DEmigrator mit diesen ganzen Dateien zu tun? Also immer mit dem "OpenedFile::Open: Opened"?
Weil da stehen auch tonnenweise Dateien aus dem shares-Ordner drin, auf die aber mit 100%iger Sicherheit von keinem User zugegriffen wurde. Auch sämtliche Dateien des hMail-Servers finden sich in diesem Log wieder !?

Gruß Stefan

[Nobby1805]

im Prinzip musst du das 1 Stunden Ruheintervall des DEmigrators abwarten und dann in der Zeit deinen Zugriff versuchen ... wenn es dann lange dauert im Log nach sehen was der DEmigrator dort gemacht hat ... der Rest des Logs ist leider unvermeidlich

Der DEmigrator öffnet alle Files in den Shares um die Konsistenz zu prüfen und das siehst du in dem LOG

[cMaster]

Hi,

ich hab jetzt grad mal so eine 95-MB-log-Datei nen bisschen bearbeitet.

Ich hab alle Log-Zeilen mit "OpenedFile" und mit "PerformPrimaryPassOnDirectory" aus dem Log entfernt.
Übrig geblieben sind folgende wenige Zeilen: (die Zahl am Anfang ist die Zeilen-Nummer in der Komplett-log-file)

Code: Alles auswählen

4:      [09.03.2010 22:40:35 13fc]     Sleeping between passes 3600331,7111ms
5:      [09.03.2010 22:40:35 13fc]     MigrationDisabled = 0
6:      [09.03.2010 22:40:35 13fc]     Audit Grace Period is set to: 1440
7:      [09.03.2010 22:40:35 13fc]     ***Starting Primary Pass
221896: [09.03.2010 22:49:19 13fc]     Primary Pass: (duplication) 524095,9797ms
221897: [09.03.2010 22:49:19 13fc]     ***Starting Secondary Pass
221898: [09.03.2010 22:49:19 13fc]     Volume information -
... ["***ERROR:" Datensätze entfernt]
227786: [09.03.2010 22:50:00 13fc]     ***ERROR: DEfileFromShadow(D:\DE\shares\Benutzer\Stefan\...\Bild.jpg,abaebf54-a5d2-47bb-a0b5-150696267881) took too long. 22642,3173ms
254439: [09.03.2010 22:50:29 13fc]     nonfatal - DEFileFromShadow(D:\DE\shares\Benutzer\Stefan\...\Datei.xls,abaebf54-a5d2-47bb-a0b5-150696267881) threw - err=170
254440: [09.03.2010 22:50:29 13fc]     Nonfatal exception in Secondary Pass on D:\DE\shares\Benutzer\Stefan\...\Datei.xls: error =170
... ["***ERROR:" Datensätze entfernt]
301318: [09.03.2010 22:51:51 13fc]     nonfatal - DEFileFromShadow(D:\DE\shares\Musik\...\Lied.mp3,abaebf54-a5d2-47bb-a0b5-150696267881) threw - err=170
301319: [09.03.2010 22:51:51 13fc]     Nonfatal exception in Secondary Pass on D:\DE\shares\Musik\...\Lied.mp3: error =170
... ["***ERROR:" Datensätze entfernt]
308698: [09.03.2010 22:52:28 13fc]     Secondary Pass: (balancing) 189413,0949ms
308699: [09.03.2010 22:52:28 13fc]     Full Primary and Secondary Pass 713542,6002ms

Die beiden Dateien im Log mit "Nonfatal" waren gerade geöffnet, als DEmigrator lief.

Als DEmigrator gerade lief, hatte ich wieder das Problem, dass der Zugriff auf sämtliche Sachen nur verzögert möglich war. Allerdings kann ich nichts sehen, was auf irgend ein Problem hinweisen könnte

Oder sehe ich das falsch?

Viele Grüße

Stefan

[Nobby1805]

In dem Log sieht man, dass von 22:40 bis 22:52 der DEmigrator lief ... da du sagst du hast Wartezeiten von 10 Sekunden hättest du jetzt in der folgenden Stunde 22:53 bis 23:52 versuchen müssen die Wartezeit zu erahlten und dann schauen ob im Log dazu etwas steht ... ich bezweifle übrigens dass diese Wartezeiten vom DEmigrator ausgelöst werden, aber du schriebst ja dass du zeitgleich 2-3 Sekunden 100% demigrator beobachten konntest

[cMaster]

Hi,

nach vielem vielem lesen, bin ich auf folgendes gestoßen: Starker Einbruch der Schreibraten nach Austausch der Platten
Ich habe eine solche WD...EARS-Platte, kann das auch damit zusammenhängen?

Gruß Stefan

[JoachimL]

nach vielem vielem lesen, bin ich auf folgendes gestoßen: Starker Einbruch der Schreibraten nach Austausch der Platten
Ich habe eine solche WD...EARS-Platte, kann das auch damit zusammenhängen?

Hallo Stefan,
hast Du den Jumper 7-8 drauf? falls nicht würde ich ihn empfehlen. Da die Daten beim Jumpern verloren gehen: Platte erst aus dem Pool entfernen, Jumper drauf, wieder hinzufügen.
Mit Jumper glaube ich nicht dass das Problem von der Festplatte kommt.
Gruß Joachim

[cMaster]

Hi,
ich kann ja Jumper 7-8 nicht setzen, da auf dieser Platte das System läuft.

Aber kann das überhaupt damit zu tun haben, dass er da zu solchen Wartezeiten kommt, oder läuft mit dieser Platte das ganze einfach grundsätzlich nur etwas langsamer?

Gruß Stefan

[Nobby1805]

Laut Beschreibung läuft die Platte nicht nur etwas langsamer, sondern die Performance kann drastisch einbrechen (c't schreibt so weit ich mich erinnere von Faktor 3 und mehr)

Aus meiner Sicht passt es trotzdem nicht ganz zu deinem Problem (auszuschließen ist natürlich nichts) ... könntest du bitte deine WHS Konfiguration beschreiben (am Besten in der Signatur)