[vz-dev] Fragen zum Protokoll "s0" in vzlogger

Thu May 5 20:27:12 CEST 2016

Moin,

> Am 05.05.2016 um 12:28 schrieb Andreas Goetz <cpuidle at gmail.com>:
> 
> Servus (ich muss endlich in den Garten ;)

…war ich schon :D

> 2016-05-05 12:12 GMT+02:00 Justin Otherguy <justin at justinotherguy.org>:
> 
> > Am 05.05.2016 um 11:57 schrieb Andreas Goetz <cpuidle at gmail.com>:
> >
>>  2016-05-05 8:18 GMT+02:00 Justin Otherguy <justin at justinotherguy.org>:
>> 
>> >> Hier ist meine vzlogger.conf:
>> >> http://pastie.org/10824437
>> >>
>> >> Ich hatte das Thema als Github-Issue #249 eröffnet - dann zeigte sich aber, dass das auf der ML besser aufgehoben ist.
>> >> Hier schon mal ein paar Zwischenergebnisse und neue Fragen:
>> >>
>> >> 1. bei der Verwendung von s0 in Kombination mit "interval": 1 werden lt. Matthias für 1 s keine Daten gezählt
>> >> das verstehe ich nicht; weder leuchtet mir ein, wieso oder wozu das so sein soll noch deckt es sich mit meiner Beobachtung - habe ich das falsch verstanden?
>> >>
>> > Das soll gar nicht sein. S0 reagiert auf Impulse (!), interval pollt. Die beiden Settings schließen sich logisch eigentlich aus und sollten nicht zusammen verwendet werden.
>> 
>> ok - richtig wäre also, interval nicht zu setzen, wenn ich s0 nutze, korrekt?
>> 
> M.E. ja!

done! s. [3] 

sieht besser aus…seither ist der Abstand zwischen den Übertragungen konstant und der höchste „value“ war 101.
-> damit scheint mir bestätigt, dass die Verwendung von „interval“ hier reingespuckt hat - sehr schön, etwas Klarheit :)

Bleibt die Frage, wie aggtime sich hier auswirken sollte.
- bei aggtime = 1 würde ich erwarten, dass die Impulse für 1 Sekunde gesammelt und dann in einem Request übertragen werden (value= (ca.) 100)
- bei aggtime = 10 würde ich erwarten, dass die Impulse für 10 Sekunden gesammelt und dann in einem Request übertragen werden (value= (ca.) 1000)

Habe ich hier die falsche Vorstellung?

>> Das probiere ich mal aus. Falls ich das richtig verstanden habe: haben wir eine Chance, das beim Parsen der Config entweder
>> - als Fehler auszugeben -> vzlogger beendet sich oder
>> - als Warning auf der Konsole und im Logfile?
>> 
> Mach bitte ein Issue auf.

done! s. [4]

> >> Ausschnitt aus vzlogger.conf:
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >> [May 05 08:11:31][s0]   Reading S0 - returning 4 readings (n=100 n_neg = 0)
> >> [May 05 08:11:31][mtr0] Got 4 new readings from meter:
> >> [May 05 08:11:31][mtr0] Reading: id=Power/StringIdentifier: value=359281.40 ts=1462428691862
> >> [May 05 08:11:31][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462428691862
> >> [May 05 08:11:31][mtr0] Reading: id=Power_neg/StringIdentifier: value=0.00 ts=1462428691862
> >> [May 05 08:11:31][mtr0] Reading: id=Impulse_neg/StringIdentifier: value=0.00 ts=1462428691862
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >> [May 05 08:11:31][S0]   MeterS0:HWIF_GPIO:first poll returned 1
> >>
> >> Ich gebe 50 Hz auf den Eingang - und das sieht so aus, als würden die auch (zum Grossteil) verarbeitet.
> 
> Mal für die Doofen wie mich: Du erwartest aufgrund der 50 Hz also einen konstanten Wert im Log, richtig?

ex-akt.
Das ist die Simulation für den Zustand „Pelletförderschnecke läuft“; der andere Zustand („…läuft nicht“) liefert eben 0 Hz und ist mit „send_zero“ erschlagen.

> >> 2. aggtime ist die Zeit, über die aggregiert wird
> >>
> >> das scheint mir nicht immer zu funktionieren - noch ein Auszug, jetzt gegrept nach "Impulse/StringIdentifier“:
> >>
> >> [May 05 08:12:36][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462428756878
> >> [May 05 08:12:37][mtr0] Reading: id=Impulse/StringIdentifier: value=99.00 ts=1462428757871
> >> [May 05 08:12:38][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462428758874
> >> [May 05 08:12:48][mtr0] Reading: id=Impulse/StringIdentifier: value=998.00 ts=1462428768879
> >> [May 05 08:12:49][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462428769882
> >> [May 05 08:12:50][mtr0] Reading: id=Impulse/StringIdentifier: value=99.00 ts=1462428770874
> >> [May 05 08:12:51][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462428771877
> >>
> >> -> in der Liste hat’s ein Mal geklappt: „value=998“, sonst immer ca. 100.
> 
> Was heißt "geklappt"? Ich verstehe Deine Erwartungshaltung nicht. Siehe oben- ich würde jeweils den gleichen Wert erwarten und mir erscheint die 998 spanisch. 

geklappt im Sinne der Definition von oben.
998 ist aus meiner Sicht nahe genug an 1000 - wenn der Pi 0,2% der Impulse verschluckt, halte ich das für unproblematisch (s. Udos berechtigten Einwand: wozu überhaupt die hohe Auflösung von 50 Hz?).

Wir sind einen Schritt weiter :)

>> >> Wie kann ich das genauer eingrenzen?
>> >>
>> > Ich kann nicht erkennen wo/was da nicht  funktioniert insofern schwer zu beantworten.
>> 
>> bei 1. ging’s mir um „Interval=1 bewirkt, dass jeweils 1 Sekunde keine Impulse verarbeitet werden
>> der Auszug zeigt mehrere Einträge innerhalb einer Sekunde - direkt vor und nach dem Loggen eines Wertes
>> 
> Lass uns den Punkt mal bitte vergessen. Betrachten wir Interval bei S0 mal als undefiniert. Bleibt aggtime auf Deinem 2. Log.

jepp!

>> > Wir haben seit ewigen Zeiten aber vmtl. diesen Fehler offen: https://github.com/volkszaehler/vzlogger/issues/231 Könnte das die Ursache sein?
>> 
>> das ist ein guter Punkt - vielleicht können wir das nun gleich mit klären.
>> 
>> Ich habe send_zero nun auskommentiert [1] - Auszug aus dem Log (wieder gegrept nach Impulse/StringItentifier):
> 
> Das ist schon Fehlersuche aus dem Issue- noch wissen wir nicht obs bei Dir vorher einen anderen Fehler gibt der den überlagert. 
> Könntest Du bitte erstmal testen ob aggtime wie erwartet funktioniert wenn Du aggfixedinterval ebenfalls setzt? Dann wissen wir ob das Logging wie erwartet läuft und können dann in send_zero aus dem Issue einsteigen.

jepp.

Habe aggfixedinterval aktiviert (s. [3]) und es werden weiterhin jede Sekunde die Werte geloggt:

[May 05 20:26:28][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462472788615
[May 05 20:26:29][mtr0] Reading: id=Impulse/StringIdentifier: value=99.00 ts=1462472789607
[May 05 20:26:30][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462472790610
[May 05 20:26:31][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462472791612
[May 05 20:26:32][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462472792615
[May 05 20:26:33][mtr0] Reading: id=Impulse/StringIdentifier: value=99.00 ts=1462472793608
[May 05 20:26:34][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462472794610
[May 05 20:26:35][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462472795613
[May 05 20:26:36][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462472796615
[May 05 20:26:37][mtr0] Reading: id=Impulse/StringIdentifier: value=99.00 ts=1462472797608
[May 05 20:26:38][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462472798611
[May 05 20:26:39][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462472799613
[May 05 20:26:40][mtr0] Reading: id=Impulse/StringIdentifier: value=100.00 ts=1462472800616
[May 05 20:26:41][mtr0] Reading: id=Impulse/StringIdentifier: value=99.00 ts=1462472801608

>> > Bevor wir weiter an Symptomen rumdoktorn würde mich aber eigentlich interessieren wie konkret Deine Meßeinrichtung aussieht- dann finden wir auch die richtige Konfiguration dazu.
>> 
>> ich verwende Udos whm [2] „produktiv“ und im Test hier gerade einen Arduino, der 50 Hz auf den GPIO17 des RPi ausgibt.
>> Brauchst Du weitere Details?
> 
> D.h. Du erwartest einfach konstate Readings solange der whm getaktet wird, richtig?

genau.

Neue Ideen?

Gruß, J.

[3] http://pastie.org/10825951
[4] https://github.com/volkszaehler/vzlogger/issues/253