Demigrator - rausfinden was der gerade macht

[stardvd]

Hallo Leute,

zum Thema demigrator habe ich hier im Forum etliche Threads gefunden. Leider keinen der mir weitergeholfen hat.

Vor ein paar Wochen habe ich so ca. 1 TB Daten auf den WHS kopiert. Der WHS dient quasi nur als Fileserver: es werden keine Clients darauf gesichert, es ist keine Ordnerduplizierung eingeschaltet.

Ich habe immer nur so 200 GB kopiert und dann einen Tag gewartet.

Wenn ich den WHS nun benutze geht er anschließend nicht mehr von selbst in den Ruhezustand, da immer noch der demigrator läuft. (so um die 50 - 70% CPU Auslastung und man hört das was auf den Festplatten geschieht). Kann man rausfinden warum der läuft? M.E. dürfte der doch nichts zu tun haben?!

NS: ich habe zwei WHS beim 1. WHS der auch die Clients sichert ist dieses Verhalten nicht - der läuft nach wie vor problemlos.

[Nobby1805]

Schau in den LogFile des Migrators "DEutil......log"
Wenn dir der Inhalt nicht reicht kannst du in der Registry das LogLevel bis auf Verbose (=Plaudertasche) hochsetzten

[stardvd]

Danke. Der Tipp steht ja mehrmals zum Thema im Forum. Das aktuelle LOG ist leer:

Hier der Inhalt des DEutil...log

[10.01.2010 11:00:00]

Das aktuellsste ist das whsarch.011010.log

[10.01.2010 11:39:00]

also ebenfalls leer..

Davor noch ein chkdsk...log das auch nur sagt das alles OK ist..

Weitere Vorschläge/Ideen.

NS: alle Updates sind installiert usw.

[Nobby1805]

von DEutil gibt es immer pro Stunde ZWEI Logfiles die sich nur durch die ProzessID unterscheiden ... auch bei mir ist einer in der Regel leer und der andere ist etwas bis deutlich größer

10.01.2010 09:00 26.356 DEUtil.011010.080000.1592.log
10.01.2010 09:00 350 DEUtil.011010.080000.2908.log

[stardvd]

Gleicher Inhalt bei dem zweiten.

Es gibt noch welche von 11:00 Uhr - beide kpl. leer.

Bei denen von heute 10:27 Uhr vorher ist das eine komplett leer, das zweite ist ca. 80 Zeilen lang und sagt auch nur aus das alles OK ist. Hier mal der Schluss davon:

[09.01.2010 22:06:35 cf0] **Starting Migration Pass***
[09.01.2010 22:06:35 d10] Initializing DEUtils
[09.01.2010 22:06:35 d10] Refreshing filter configuration.
[09.01.2010 22:06:35 d10] Refreshed filter configuration successfully.
[09.01.2010 22:06:35 d10] MigrationDisabled = 0
[09.01.2010 22:06:35 d10] Audit Grace Period is set to: 1440
[09.01.2010 22:06:35 d10] ***Starting Primary Pass

Was mir da auffällt ist eigentlich das die Einträge von gestern sind, das Logfile von heute 10:27 Uhr?!

[Nobby1805]

JEDE Stunde werden 2 Logs erzeugt also 48 am Tag, es kann sein dass der aktuelle leer ist, wenn seit dem Wechsel des Log-Files (Stundenwechsel) noch nichts passiert ist

Hast du mal im Explorer nach Creation-Date sortiert ? Stimmt bei dir auf dem WHS die Uhrzeit ? (es gibt da einen Micrososft Installation Bug )

[stardvd]

Uhrzeit stimmt. Von 12 Uhr habe ich jetzt 4 Logs.

Die ersten drei:

[10.01.2010 12:00:00]

Aber im vierten steht nun was:

[10.01.2010 11:00:00]
[10.01.2010 11:11:50 d10] Primary Pass: (duplication) 47114064,9177ms
[10.01.2010 11:11:50 d10] ***Starting Secondary Pass
[10.01.2010 11:11:50 d10] Volume information -
Volume - Id = 67efa80d-8fb3-424c-b563-e78c49729ee9 Size = 911 GB Free = 926865 MB
Volume - Id = ac956de5-5fce-490f-9d1f-6a1e1099d9f6 Size = 931 GB Free = 797593 MB
Volume - Id = 47472a92-31cd-4018-b929-1b27c2019dd2 Size = 931 GB Free = 449938 MB
Volume - Id = 2834a7ba-e457-4b92-83fd-165a39007c42 Size = 931 GB Free = 20410 MB
[10.01.2010 11:12:01 d10] ***ERROR: DEfileFromShadow(c:\fs\V\DE\shares\Daten\Daten_P\Sicherungen_PC\Daten_P_Verbatim\Daten_P_10_2008\Urlaub2008.pics\IMG_3920.jpg,67efa80d-8fb3-424c-b563-e78c49729ee9) took too long. 3441,213ms
>>in der Form ca. 20 Einträge
[10.01.2010 11:42:46 d10] Secondary Pass: (balancing) 1856545,8232ms
[10.01.2010 11:42:46 d10] Full Primary and Secondary Pass 48970626,308ms

Was sagt mir das jetzt?

[Nobby1805]

Schau mal in den davor , bzw in der sortierten Reihenfolge 2 dahinter

[10.01.2010 11:11:50 d10] Primary Pass: (duplication) 47114064,9177ms
[10.01.2010 11:11:50 d10] ***Starting Secondary Pass

47114 Sekunden für den primary pass = 13,08 Stunden kann nicht sein ´... da musst du dir mal alle davor mit gleicher Prozess-ID ansehen ob irgend etwas darin steht spätestens in dem von Gestern 22 Uhr müsstest du dann den Start des primary passes finden .. ok den hast du ja schon gepostet

Jetzt hilft nur noch den Log-Level zu erhöhen., dafür musst du in der Registry einen Wert verändert

Code: Alles auswählen

[HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows Home Server\DEUtil]
"TraceFile"="C:\\Dokumente und Einstellungen\\All Users\\Anwendungsdaten\\Microsoft\\Windows Home Server\\logs\\DEUtil.%d.%t.%p.log"
"TraceMask"=dword:00000003

Tracemask auf 7 oder F setzen und dann den WHS booten

[stardvd]

Ich habe mir noch mal ein paar der Log's angesehen, da finden sich immer wieder mal solche Meldungen:

***ERROR: DEfileFromShadow...

aber es tauchen da nie zweimal die gleichen Dateinamen auf.

Ich erhöhe jetzt mal den Log-Level und melde mich dann wieder.

[Nobby1805]

Ich habe mir noch mal ein paar der Log's angesehen, da finden sich immer wieder mal solche Meldungen:

***ERROR: DEfileFromShadow...

das wichtige steht in der Meldung hinten ... "took to long" ist unkritisch, weist auf schlechte Performance (in dem Moment) hin

[stardvd]

So, die ersten Logs schreibt er ja offenbar direkt nach dem Neustart.

Das erste DEUtil ist das hier (komplett):

[10.01.2010 15:46:03 91c] ********************************************************************************
[10.01.2010 15:46:03 91c] DEUTil is initializing
[10.01.2010 15:46:03 91c] OpenedFile::Open: Opened D:\folders\{378AE094-F4CA-4D9B-BDA5-649D6F738276}\whs.reg as handle 00000180
[10.01.2010 15:46:03 91c] OpenedFile::Open: Opened {47472A92-31CD-4018-B929-1B27C2019DD2},32000000045fbc as handle 00000178
[10.01.2010 15:46:03 91c] OpenedFile::Open: Opened D:\folders\{378AE094-F4CA-4D9B-BDA5-649D6F738276}\whs.reg as handle 00000180
[10.01.2010 15:46:03 91c] OpenedFile::Open: Opened {47472A92-31CD-4018-B929-1B27C2019DD2},32000000045fbc as handle 00000184
[10.01.2010 15:46:03 91c] OpenedFile::Open: Opened {67EFA80D-8FB3-424C-B563-E78C49729EE9},\DE\folders\{378AE094-F4CA-4D9B-BDA5-649D6F738276}\whs.reg as handle 00000160
[10.01.2010 15:47:04 91c] OpenedFile::Open: Opened D:\folders\{378AE094-F4CA-4D9B-BDA5-649D6F738276}\whs.reg as handle 00000108
[10.01.2010 15:47:04 91c] OpenedFile::Open: Opened {47472A92-31CD-4018-B929-1B27C2019DD2},33000000045fbc as handle 00000188
[10.01.2010 15:47:04 91c] OpenedFile::Open: Opened D:\folders\{378AE094-F4CA-4D9B-BDA5-649D6F738276}\whs.reg as handle 00000108
[10.01.2010 15:47:04 91c] OpenedFile::Open: Opened {47472A92-31CD-4018-B929-1B27C2019DD2},33000000045fbc as handle 0000018C
[10.01.2010 15:47:04 91c] OpenedFile::Open: Opened {67EFA80D-8FB3-424C-B563-E78C49729EE9},\DE\folders\{378AE094-F4CA-4D9B-BDA5-649D6F738276}\whs.reg as handle 00000164
[10.01.2010 15:54:50 91c] OpenedFile::Open: Opened D:\folders\{378AE094-F4CA-4D9B-BDA5-649D6F738276}\whs.reg as handle 00000168
[10.01.2010 15:54:50 91c] OpenedFile::Open: Opened {47472A92-31CD-4018-B929-1B27C2019DD2},34000000045fbc as handle 0000018C
[10.01.2010 15:54:50 91c] OpenedFile::Open: Opened D:\folders\{378AE094-F4CA-4D9B-BDA5-649D6F738276}\whs.reg as handle 00000168
[10.01.2010 15:54:50 91c] OpenedFile::Open: Opened {47472A92-31CD-4018-B929-1B27C2019DD2},34000000045fbc as handle 00000140
[10.01.2010 15:54:50 91c] OpenedFile::Open: Opened {67EFA80D-8FB3-424C-B563-E78C49729EE9},\DE\folders\{378AE094-F4CA-4D9B-BDA5-649D6F738276}\whs.reg as handle 00000190
[10.01.2010 15:55:51 91c] OpenedFile::Open: Opened D:\folders\{378AE094-F4CA-4D9B-BDA5-649D6F738276}\whs.reg as handle 00000184
[10.01.2010 15:55:51 91c] OpenedFile::Open: Opened {47472A92-31CD-4018-B929-1B27C2019DD2},35000000045fbc as handle 00000178
[10.01.2010 15:55:51 91c] OpenedFile::Open: Opened D:\folders\{378AE094-F4CA-4D9B-BDA5-649D6F738276}\whs.reg as handle 00000184
[10.01.2010 15:55:51 91c] OpenedFile::Open: Opened {47472A92-31CD-4018-B929-1B27C2019DD2},35000000045fbc as handle 00000164
[10.01.2010 15:55:51 91c] OpenedFile::Open: Opened {67EFA80D-8FB3-424C-B563-E78C49729EE9},\DE\folders\{378AE094-F4CA-4D9B-BDA5-649D6F738276}\whs.reg as handle 00000190

Das zweite ist > 260 MB

und hat jede Menge dieser Einträge:

[10.01.2010 15:55:41 d20] OpenedFile::Open: Opened D:\shares\Daten\Daten_P\Sicherungen_P von PC\Daten_P_Verbatim\IMG-100.jpg as handle 000003A0
[10.01.2010 15:55:41 d20] OpenedFile::Open: Opened {AC956DE5-5FCE-490F-9D1F-6A1E1099D9F6},1000000015ecd as handle 0000043C

Dann gibt es jetzt neu ein: qsm.011010.log - ist das was wichtiges?

[Nobby1805]

QSM ist der Storage Manager .. also sehr wichtig

Wohin hast du denn den Log_level gesetzt ? Diese Meldungen habe ich bei mir nicht gesehen , habe aber den Level nach PP3 auch noch nicht wieder hoch gesetzt .. probiere ich gleich mal aus

[stardvd]

Ich habe den Loglevel auf 7 gesetzt. Werde den jetzt aber wieder ändern, denn die aktuellen log's vom DEUtil sind bis 1,2 GB gross.

Zudem gibt es jetzt von 17 Uhr wieder 4 Log's.

[Nobby1805]

Wieso 4 ? Läuft der DEmigrator evt. 2 mal ?

[stardvd]

Nein, läuft nur einmal. In zwei der Log's stand nur Datum und Uhrzeit und jetzt nach dem Neustarten sind die komischerweise auch weg?!