Firmware zu CUL, CUNX und Co. mit Timestamp Option ASKSIN tsculfw V0.41

[Adimarantis]

Update: Über Nacht gab es weiter in unregelmäßigen Abständen (alle ca. 10 Minuten) timeouts. Etwas häufiger vom FW1.4 Gerät.
Noch zu Bedenken dabei: Ich hab 50+ Homematic Geräte im Haus die munter dazwischenfunken. Vielleicht sind da einfach auch Kollisionen dabei. Diese Messages sind im Log ausgefiltert.

Gruß,
Jörg

[noansi]

Hallo Jörg,

ich habe mal für den 1A758E nachprüfen wollen, ob das (variable) Intervall denn passt. Dabei ist mir ein Abweichung von etwa -2.3s aufgefallen und ich dachte zuerst, der Takt vom nano sei so schlecht, weil ich die Timestamps dafür genutzt habe.
Da der Unterschied zum Host aber schon mit scF gemessen wird und der bei Dir ganz gut aussah, konnte ich beim weiteren Check der Intervallzeiten nicht recht glauben, dass auch Deine Pi Uhr gleich schlecht gehen soll.
Aber nach weiterem Check im Code denke ich nun, dass es ein Laufzeitproblem in FHEM ursächlich ist. Es wurde versucht, auf einen erfolgreichen Ack die letzte Sendezeit zum aufsynchronisieren zu nutzen, das Holen der Zeit aber laufzeitbehaftet nicht passt und damit das Intervall verkürzt wird. Das habe ich jetzt raus geworfen und mal nur auf das berechnete Intervall gesetzt. Beeinflussen lässt sich das Intervall mit den Attributen unten.

Teste bitte mal mit der angehängten 10_CUL_HM.pm.
attr cyclicMsgOffset ist nun wieder offset und per default auf 0.
attr cyclicMsgCorr ist ergänzt und kann quasi als Uhrgangunterschiedskorrektur genutzt werden, default ebenfalls 0.

Kannst Du bitte damit nochmal testen und loggen?

Gruß, Ansgar.

PS: außerdem ein HMinfo, um ein Ergebnistextersetzungsproblem von Frank zu beheben.

[Adimarantis]

Test läuft. Ich hatte das cyclicMsgOffset attribut jetzt erstmal wieder gelöscht und habe aktuell gefühlt mehr timeouts.
Jetzt habe ich CyclicMsgCorr auf -40 gesetzt , das müsste wieder meinen 160ms entsprechen, oder habe ich das jetzt falsch verstanden?

Das Testsetup ist jetzt automatisiert und stellt die Ventile per DOIF 

Code Auswählen Erweitern

([:15]) (set HMTC14_c1 valvePos 10)
DOELSEIF
([:30]) (set HMTC20_c1 valvePos 20)
DOELSEIF
([:45]) (set HMTC14_c1 valvePos 60)
DOELSEIF
([:00]) (set HMTC20_c1 valvePos 70)

[noansi]

Hallo Jörg,

nein, zuvor warst Du etwa 2280ms zu früh dran nach Rechnung relativ konstant. Das wäre wohl eher -2280 als CyclicMsgOffset, um auf ähnliches zu kommen.

Gruß, Ansgar.

[Adimarantis]

Hi Ansgar,

kann es sein das es eher -228 als -2280 hätten sein müssen? - auf jeden Fall haben die Antriebe mit diesem Wert total gestreikt und sind  dann auf Fehlerposition gefahren. Ich hab es dann nach einer Weile wieder auf 0 gesetzt.

Auf jeden Fall viel Log zu schmökern.

Gruß,
Jörg

[noansi]

Hallo Jörg,

verstehen tu ich es noch nicht, aber die 2.x Sekunden sind geblieben.
Nur der Empfangstimeout für Antworten passt dazu, auch wenn ich eigentlich keinen Zusammenhang sehe.

Bitte setz mal beim nano das Attribut hmLanQLen auf 3. Das ist per default auf 1. Mal sehen, ob das irgendeinen Unterschied macht.

Hattest Du wirklich mit den letzten Modulen gearbeitet und auch den Neustart nach einspielen nicht vergessen?

Gruß, Ansgar.

[Adimarantis]

Bin mir sehr sicher dass ich neu gestartet habe und die ...i version ist korrekt kopiert. Habe auch nochmal im fhem.save und fhem.cfg geschaut ob der Wert irgendwo "hängengeblieben" ist, obwohl ich das Attribut gelöscht habe und nichts verdächtiges gefunden.
Auf jeden Fall hmLanQLen auf 3 gesetzt und fhem auf service level mit frischen logfile neugestartet. Lass ich jetzt mal eine Weile laufen und schicke dann die Logfiles.
Läuft jetzt ca. 15 Minuten mit 3 timeouts und zwei (erfolgreichen) Ventilländerungen.

Gruß,
Jörg

[noansi]

Hallo Jörg,

nochmal 3 neue Dateien zum Testen.
Ich habe den cyclicMsgOffset wieder auf default 200 gesetzt. Die Berechnung des Intervalls habe ich mal nach meinem Verständis neu geschrieben.

Noch ein Hinweis, es macht bezüglich der Timergenauigkeit einen Unterschied, ob FHEM-Seite im Browser offen ist, weil die regelmäßig aktualisiert wird, was sich in einem größeren Jitter bemerkbar macht.
Beim virtuellen TC kannst Du verbose auf 2 stellen und bekommst dann das nächste berechnete Sendeintervall ins log geschrieben.

Gruß, Ansgar.

[Adimarantis]

Hi Ansgar,

ok. Hab die eine PM mit link zum vollständigen Log geschickt. Da dürfte zwar nichts kritisches drinstehen, möchte es aber trotzdem nicht posten. Sag Bescheid wenn ichs wieder löschen kann.

Ich denke mir im kompletten Log siehst du eventuell ob die Timeouts irgendwelche Seiteneffekte haben.

Jörg

[noansi]

Hallo Jörg,

manchmal ist man einfach nur doof.
Klar, wenn ich mit der falschen HMID rechne, dann kommt eine Differenz raus...

Mit der jeweils richtigen HMID, also der Deines jeweiligen virtuellen TCs, passsen errechnete Sendezeitpunkte. Du hast offenbar das letzte Log ohne Offset oder Corr laufen lassen.

Hier übrigens mal der link zum Thread bezüglich cyclicMsgOffset https://forum.fhem.de/index.php/topic,45735.msg572806.html#msg572806.

Meine Theorie dazu:
FHEM jittert im Sendezeitpunkt, weil je nach Auslastung Timer nicht rechtzeitig ausgeführt werden und das nicht zu knapp. Der Jitter verlängert und verkürzt das Sendeintervall. Zu früh senden ist offenbar ebenso ungeschickt, wie zu spät senden. Der Offset verzögert den Sendezeitpunkt. Sendet FHEM zu früh, weil es zuvor zu spät gesendet hat, dann hilft der Offset, trotzdem noch im Empfangsfenster zu bleiben. Übertreibt man es mit dem Offset, fliegt man raus, wenn FHEM zu spät sendet.

Der nächste Punkt ist natürlich der Gleichtakt der Uhren. Um das zumindest besser aufeinander abstimmen zu können, habe ich den cyclicMsgCorr ergänzt. Leider ist erst mal unbekannt, wie die Uhr am Empfänger tickt.

Die beiden Anteile wirken als Summe.

Für den 1A758E hab ich mir das Spiel mal intensiver angeschaut. Dein Pi war sehr brav beim Sendezeitpunkt mit einer Abwichung von max. 10ms im Log Zeitraum nach nano Zeit.

Anfangs hat er gut empfangen. Dann kam der erste Aussetzer, danach nochmal direkt empfangen, dann bei der 1. Wiederholung, dann zwei mal bei der 2. Wiederholung, Aussetzter, 2. Wiederholung, Aussetzer, 2. Wiederholung, Aussetzter, 2. Wiederholung, Aussetzer.
Da das Sendeintervall nicht korrigiert war und er wohl auf den Empfang synchronisiert, vermute ich aus den 2. Wiederholungen mal, dass Du eher am Anfang des Empfangszeitraums gesendet hast. Und da es möglich war, bei der 1. Wiederholung mit wohl unverändertem Empfangintervall zu empfangen, müßte der Empfangszeitraum mindestens 272ms sein.

Du solltest das bei dem Richtung + korrigieren.

Das spricht weiterhin dafür, dass ich den resynch für den virtTC wieder einbaue. Festes Intervall ist wohl ungünstig mit Bezug auf die Empfangschancen bei Wiederholungen.

Gruß, Ansgar.

[frank]

hi ansgar,

attr cyclicMsgOffset wurde eigentlich erst viel später wegen problemen bei externen tempfühlern ergänzt.
ich habe gerade erst gesehen, dass das auch beim virtuellen tc verfügbar ist. hm..., schon immer?
ich habe es jedenfalls nie benötigt, allerdings beim virt tc auch noch keinen cul probiert.

falls der offset grundsätzlich auch nach jedem miss erneut addiert wird, könnte auch hinderlich sein.



die theorie der kommunikationsfenster beim vd gibt es hier: https://forum.fhem.de/index.php/topic,18193.msg120907.html#msg120907

vd und tc synchronisieren sich nur bei jeder gelungenen kommunikation.

gruss frank

[noansi]

Hallo Frank,

vielen Dank für den Link. Ich lese, Du warst da auch schon schwer aktiv.

Zwei Dinge sind mir noch nicht klar bezüglich der Interpretation bei Empfangsproblemen.

1. Wie ist die Wachfolge?
250 ms nix empfangen
250 ms nix empfangen
750 ms nix empfangen
1250 ms nix empfangen
1750 ms nix empfangen
2250 ms nix empfangen
2750 ms nix empfangen
? Zumindest würde ich den zitierten Text so verstehen
oder
250 ms nix empfangen
750 ms nix empfangen
1250 ms nix empfangen
1750 ms nix empfangen
2250 ms nix empfangen
2750 ms nix empfangen
? So verstehe ich weitere Forumsbeiträge

2.
Macht der VD zwischen den verlängerten Wachzeiten die gleiche Pausenlänge nach Intervallberechnung oder wird die Pause um die Wachverlängerung verkürzt?

@Ralf:

nochmal eine neue Test CUL_HM im Anhang.

Gruß, Ansgar

[frank]

hi ansgar,

mein verständnis sieht so aus:

die geplanten zeitpunkte nenne ich mal meetings (m0, m1, .... , m6).
m0 ist das gerade durchgeführte (last) meeting.
war m0 erfolgreich, gibt es genau 6 versuche (m1 .. m6), erneut ein erfolgreiches meeting durchzuführen (keep-alive-mechanismus).
waren alle 6 meetings in folge erfolglos, schläft der vd für ca 60min ein.
anschliessend wacht der vd für längere zeit auf, so dass auf alle fälle der nächste versuch erfolgreich sein wird.

ein erfolgreiches meeting wird im vtc im reading valveCtrl mit ok angezeigt.
die misslungenen meetings werden mit "miss_1, ... , miss_5, lost" angezeigt.
wenn fhem wirklich alle messages vom vd empfängt, kann man sich darauf verlassen, dass bei valveCtrl=lost der vd wirklich eingeschlafen ist. ab dann kann man auch davon ausgehen, dass nun valvePosition=valveErrorPos gilt.

wenn m0=ok ist, sind dadurch die zeitpunkte der nächsten 6 meetings (m1 .. m6) im prinzip festgelegt.
für m4 also: m0 plus die summe der ersten 4 berechnungen.

ich bin in meinen überlegungen immer davon ausgegangen, das die jeweiligen "fenster" dann symmetrisch um die berechneten zeitpunkte liegen. das könnte aber auch anders sein. die länge der fenster ist für die berechnung eigentlich uninteressant.
wichtig ist der synchronisations zeitpunkt.


zum verständnis des codes ist es eventuell hilfreich zu wissen, dass noch ein mechanismus eingebaut ist, um den traffic der io zu reduzieren:
über das "attr param msgReduce:N" kann man N meetings nach einem erfolgreichen meeting auslassen.
ich nutze zb "msgReduce:2", wodurch in der regel m1 und m2 ausgelassen wird. erst ab m3 wird dann der keep-alive versucht.
wenn allerdings beim vtc die valvePos geändert wird, wird ab diesem moment für den anstehenden keep-alive zyklus kein meeting ausgelassen. das auslassen wird erst wieder in gang gesetzt, wenn es ein erfolgreiches meeting gegeben hat.
mit "msgReduce:2" sehe ich zusätzlich den effekt, dass es pro tag weniger miss gibt. erstens wegen weniger versuchen pro tag und zweitens wohl, weil das fenster dann natürlich auch grösser ist.


@Adimarantis
zum überwachen des readings valveCtrl nutze ich zb die fehlererkennung von hminfo.
dazu habe ich das attribut sumERROR mit "valveCtrl:restart:unknown:ok:miss_1:miss_2:miss_3:miss_4:miss_5" erweitert. dadurch wird für valveCtrl=lost die jeweilige entity in den internals angezeigt.

[noansi]

Hallo Frank,

danke für Deine Erläuterung.

Hatte ich auch im Prinzip schon aus dem verlinkten Thread rausgelesen.

das die jeweiligen "fenster" dann symmetrisch um die berechneten zeitpunkte liegen. das könnte aber auch anders sein. die länge der fenster ist für die berechnung eigentlich uninteressant.

Das Fenster will getroffen werden.
Symetrisch um die berechneten Zeitpunkte wäre sinnvoll, muss aber nicht so im VD programmiert sein. Was dafür spricht, wäre die jeweils +500ms = +2*250ms.
Wenn dem nicht so ist, dann muss das Sendeintervall verlängert werden, um das verlängerte Empfangsintervall auch sinnvoll nutzen zu können. Für irgendwas muss der reale TC ja auch das Ack anfordern (klar, Error Meldungen sind auch schön . Für Fehlermeldungen könnte man auch im Sinne von Stromverbrauch nur jedes n-te mal ein Ack anfordern.
Über die Ack Info kann aber auch das Intervall angepasst werden.

Ist eine Intervallveränderung Richtung länger mit dem realen TC mal aufgefallen, wenn bei VD z.B. die Batterien einfach mal rausgenommen werden?

Für ein asymetrisches Empfangsfenster würde der Stromverbrauch sprechen. Wenn der Anfang des Empfangsfensters getroffen wird, kann früher wieder komplett geschlafen werden, inklusive Empfänger. Ist natürlich auch eine Frage der in der Produktion erreichbaren Taktgenauigkeit für die HM devices.

Ich kann nur mit RT testen und habe dafür nun den Offset dynamisiert. Bekannt ist der Soll-Aufrufzeitpunkt des Timers. Gemessen wird schon der Ist-Zeitpunkt des Timers. Systemlast bedingt werden Timer wenn falsch, dann immer nur zu spät ausgeführt. Mit dem cyclicMsgOffset lässt sich das nutzen, um bei Systemverspätung den Offset zu veringern.
Bei krassen Verspätungen sende ich nun einfach gar nicht zum RT, damit kann der das auch nicht versehentlich empfangen.

Wenn das noch um das Sollintervall herum symetrisiert wird, dann wäre das auch auf den VD anwendbar (und sollte es auch für den RT weiter verbessern). Wäre also als eine Art Zeitpuffer im engen Rahmen des Empfangsfensters zu verstehen.

Edit:
Nebenbei führt das Anfordern das Acks zu Repeats durch das IO (macht HMLAN und auch tsculfw). Wenn der VD auf einen IO-Repeat synchronisiert ist auch schlecht. Dafür müsste Senderseitig der Ack Zeitpunkt mit einbezogen werden. Macht der reale TC so was, sprich springt das Sendeintervall schon mal?

Gruß, Ansgar.

[Adimarantis]

Ich habe heute noch ein wenig mit den Offsets rumgespielt.
Der FW2.0 Antrieb (1A758E) läuft recht gut mit 220 - beim FW 1.4 (1123B8) Antrieb hab ich nicht wirklich viel Unterschied bemerkt, außer dass zu große Abweichungen dann dazu geführt haben, dass er in den Fehlerzustand ging.
Ich bringe da zu diesen Deltas vom TC nicht wirklich eine Relation hergestellt. Anbei nochmal die Daten der letzten Stunde (Offset konstant 1A758E=220 , 1123B8=230
Wenn ich noch etwas probieren soll, dann bitte welche spezifischen Settings. Für mich funktioniert das jetzt "gut genug".

Danke,
Jörg

Code Auswählen Erweitern

2020.12.28 15:19:58.865 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8
2020.12.28 15:20:53.501 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1A758E
2020.12.28 15:24:38.325 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8
2020.12.28 15:28:36.659 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1A758E
2020.12.28 15:30:27.769 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8
2020.12.28 15:36:18.057 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1A758E
2020.12.28 15:37:23.950 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8
2020.12.28 15:59:11.038 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1A758E
2020.12.28 16:04:28.233 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1A758E
2020.12.28 16:08:47.697 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1A758E
2020.12.28 16:10:11.446 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8
2020.12.28 16:15:14.663 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8
2020.12.28 16:21:33.271 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1A758E
2020.12.28 16:25:39.827 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8
2020.12.28 16:27:56.060 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8
2020.12.28 16:35:26.248 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8
2020.12.28 16:39:56.953 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8
2020.12.28 16:42:54.680 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8
2020.12.28 16:45:37.931 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8
2020.12.28 16:48:39.950 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1A758E
2020.12.28 16:50:21.133 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8
2020.12.28 16:51:37.665 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1A758E
2020.12.28 16:53:25.101 4: TSCUL_XmitAwaitHMTo CUL_TS: timeout - 1123B8


Code Auswählen Erweitern

2020.12.28 15:59:08.683 2: CUL_HM HMTC20_c1 mc:FA->FB dt:165720ms
2020.12.28 16:00:07.415 2: CUL_HM HMTC14_c1 mc:FB->FC dt:171980ms
2020.12.28 16:01:54.414 2: CUL_HM HMTC20_c1 mc:FB->FC dt:151470ms
2020.12.28 16:02:59.397 2: CUL_HM HMTC14_c1 mc:FC->FD dt:157730ms
2020.12.28 16:04:25.880 2: CUL_HM HMTC20_c1 mc:FC->FD dt:136970ms
2020.12.28 16:05:37.126 2: CUL_HM HMTC14_c1 mc:FD->FE dt:143230ms
2020.12.28 16:06:42.845 2: CUL_HM HMTC20_c1 mc:FD->FE dt:122470ms
2020.12.28 16:08:00.361 2: CUL_HM HMTC14_c1 mc:FE->FF dt:128730ms
2020.12.28 16:08:45.342 2: CUL_HM HMTC20_c1 mc:FE->FF dt:171970ms
2020.12.28 16:10:09.086 2: CUL_HM HMTC14_c1 mc:FF->00 dt:158730ms
2020.12.28 16:11:37.298 2: CUL_HM HMTC20_c1 mc:FF->00 dt:137970ms
2020.12.28 16:12:47.826 2: CUL_HM HMTC14_c1 mc:00->01 dt:144480ms
2020.12.28 16:13:55.265 2: CUL_HM HMTC20_c1 mc:00->01 dt:123720ms
2020.12.28 16:15:12.298 2: CUL_HM HMTC14_c1 mc:01->02 dt:129980ms
2020.12.28 16:15:58.976 2: CUL_HM HMTC20_c1 mc:01->02 dt:173220ms
2020.12.28 16:17:22.276 2: CUL_HM HMTC14_c1 mc:02->03 dt:179480ms
2020.12.28 16:18:52.203 2: CUL_HM HMTC20_c1 mc:02->03 dt:158720ms
2020.12.28 16:20:21.755 2: CUL_HM HMTC14_c1 mc:03->04 dt:164980ms
2020.12.28 16:21:30.916 2: CUL_HM HMTC20_c1 mc:03->04 dt:144470ms
2020.12.28 16:23:06.737 2: CUL_HM HMTC14_c1 mc:04->05 dt:150730ms
2020.12.28 16:23:55.384 2: CUL_HM HMTC20_c1 mc:04->05 dt:129970ms
2020.12.28 16:25:37.466 2: CUL_HM HMTC14_c1 mc:05->06 dt:136230ms
2020.12.28 16:26:05.354 2: CUL_HM HMTC20_c1 mc:05->06 dt:179470ms
2020.12.28 16:27:53.706 2: CUL_HM HMTC14_c1 mc:06->07 dt:121730ms
2020.12.28 16:29:04.836 2: CUL_HM HMTC20_c1 mc:06->07 dt:164970ms
2020.12.28 16:29:55.427 2: CUL_HM HMTC14_c1 mc:07->08 dt:171480ms
2020.12.28 16:31:49.804 2: CUL_HM HMTC20_c1 mc:07->08 dt:150720ms
2020.12.28 16:32:46.906 2: CUL_HM HMTC14_c1 mc:08->09 dt:156980ms
2020.12.28 16:34:20.515 2: CUL_HM HMTC20_c1 mc:08->09 dt:136220ms
2020.12.28 16:35:23.894 2: CUL_HM HMTC14_c1 mc:09->0A dt:142480ms
2020.12.28 16:36:36.742 2: CUL_HM HMTC20_c1 mc:09->0A dt:121720ms
2020.12.28 16:37:46.372 2: CUL_HM HMTC14_c1 mc:0A->0B dt:128230ms
2020.12.28 16:38:38.465 2: CUL_HM HMTC20_c1 mc:0A->0B dt:171470ms
2020.12.28 16:39:54.598 2: CUL_HM HMTC14_c1 mc:0B->0C dt:177730ms
2020.12.28 16:41:29.925 2: CUL_HM HMTC20_c1 mc:0B->0C dt:156970ms
2020.12.28 16:42:52.326 2: CUL_HM HMTC14_c1 mc:0C->0D dt:163230ms
2020.12.28 16:44:06.894 2: CUL_HM HMTC20_c1 mc:0C->0D dt:142470ms
2020.12.28 16:45:35.576 2: CUL_HM HMTC14_c1 mc:0D->0E dt:148730ms
2020.12.28 16:46:29.375 2: CUL_HM HMTC20_c1 mc:0D->0E dt:128220ms
2020.12.28 16:48:04.291 2: CUL_HM HMTC14_c1 mc:0E->0F dt:134480ms
2020.12.28 16:48:37.595 2: CUL_HM HMTC20_c1 mc:0E->0F dt:177720ms
2020.12.28 16:50:18.775 2: CUL_HM HMTC14_c1 mc:0F->10 dt:183980ms
2020.12.28 16:51:35.310 2: CUL_HM HMTC20_c1 mc:0F->10 dt:163220ms
2020.12.28 16:53:22.745 2: CUL_HM HMTC14_c1 mc:10->11 dt:169480ms
2020.12.28 16:54:18.530 2: CUL_HM HMTC20_c1 mc:10->11 dt:148970ms
2020.12.28 16:56:12.225 2: CUL_HM HMTC14_c1 mc:11->12 dt:155230ms
2020.12.28 16:56:47.496 2: CUL_HM HMTC20_c1 mc:11->12 dt:134470ms
2020.12.28 16:58:47.456 2: CUL_HM HMTC14_c1 mc:12->13 dt:140730ms
2020.12.28 16:59:01.968 2: CUL_HM HMTC20_c1 mc:12->13 dt:183970ms
2020.12.28 17:01:08.186 2: CUL_HM HMTC14_c1 mc:13->14 dt:126230ms
2020.12.28 17:02:05.940 2: CUL_HM HMTC20_c1 mc:13->14 dt:169470ms
2020.12.28 17:03:14.415 2: CUL_HM HMTC14_c1 mc:14->15 dt:175980ms