[vz-users] vzlogger s0 protocol + aggtime funktioniertsporadisch nicht wie erwartet

Sun Dec 18 21:38:10 CET 2016

Hallo Zusammen,

hier eine kurzer Auszug aus dem LogFile, der das Verhalten belegt und auch erklärt. Ich bin mir nur nicht sicher ob es ein Bug oder doch en Feature ist. Zur Erinnerung: aggtime ist auf 180 Sekunden konfiguriert.

$ cat vzlogger.log | grep RESULT
[Dec 18 16:18:18][SUM]  RESULT 1.000000 @ 1482074297367
[Dec 18 16:26:24][SUM]  RESULT 1.000000 @ 1482074784160
[Dec 18 16:34:30][SUM]  RESULT 1.000000 @ 1482075269620
[Dec 18 16:42:44][SUM]  RESULT 1.000000 @ 1482075763855
[Dec 18 16:50:54][SUM]  RESULT 1.000000 @ 1482076253440
[Dec 18 16:59:04][SUM]  RESULT 1.000000 @ 1482076743708
[Dec 18 17:07:11][SUM]  RESULT 1.000000 @ 1482077230993
[Dec 18 17:15:14][SUM]  RESULT 1.000000 @ 1482077713184
[Dec 18 17:23:16][SUM]  RESULT 1.000000 @ 1482078195362
[Dec 18 17:30:23][SUM]  RESULT 1.000000 @ 1482078623062
[Dec 18 17:31:23][SUM]  RESULT 1.000000 @ 1482078682365
[Dec 18 17:32:12][SUM]  RESULT 1.000000 @ 1482078731995
[Dec 18 17:33:38][SUM]  RESULT 1.000000 @ 1482078817905
[Dec 18 17:35:01][SUM]  RESULT 1.000000 @ 1482078901141
[Dec 18 17:35:57][SUM]  RESULT 1.000000 @ 1482078957060
[Dec 18 17:36:36][SUM]  RESULT 1.000000 @ 1482078995379
[Dec 18 17:37:07][SUM]  RESULT 1.000000 @ 1482079026684
[Dec 18 17:38:05][SUM]  RESULT 1.000000 @ 1482079084316
[Dec 18 17:38:55][SUM]  RESULT 1.000000 @ 1482079134720
[Dec 18 17:39:44][SUM]  RESULT 1.000000 @ 1482079183307
[Dec 18 17:40:27][SUM]  RESULT 1.000000 @ 1482079226809
[Dec 18 17:41:11][SUM]  RESULT 1.000000 @ 1482079271028
[Dec 18 17:41:53][SUM]  RESULT 1.000000 @ 1482079312363
[Dec 18 17:42:31][SUM]  RESULT 1.000000 @ 1482079351137
[Dec 18 17:43:10][SUM]  RESULT 1.000000 @ 1482079389844
[Dec 18 17:43:50][SUM]  RESULT 1.000000 @ 1482079430045
[Dec 18 17:44:30][SUM]  RESULT 1.000000 @ 1482079470132
[Dec 18 17:45:10][SUM]  RESULT 1.000000 @ 1482079509486
[Dec 18 17:45:49][SUM]  RESULT 1.000000 @ 1482079548973
[Dec 18 17:46:29][SUM]  RESULT 1.000000 @ 1482079588680
[Dec 18 17:47:09][SUM]  RESULT 1.000000 @ 1482079628743
[Dec 18 17:47:50][SUM]  RESULT 1.000000 @ 1482079669334
[Dec 18 17:48:34][SUM]  RESULT 1.000000 @ 1482079713419
[Dec 18 17:49:19][SUM]  RESULT 1.000000 @ 1482079758291
[Dec 18 17:50:02][SUM]  RESULT 1.000000 @ 1482079801734
[Dec 18 17:50:45][SUM]  RESULT 1.000000 @ 1482079844569
[Dec 18 17:51:28][SUM]  RESULT 1.000000 @ 1482079887909
[Dec 18 17:52:11][SUM]  RESULT 1.000000 @ 1482079931165
[Dec 18 17:52:54][SUM]  RESULT 1.000000 @ 1482079973669
[Dec 18 17:53:38][SUM]  RESULT 1.000000 @ 1482080017676
[Dec 18 17:56:18][SUM]  RESULT 3.000000 @ 1482080177836
[Dec 18 17:59:27][SUM]  RESULT 3.000000 @ 1482080366835
[Dec 18 18:02:54][SUM]  RESULT 3.000000 @ 1482080573948
[Dec 18 18:05:13][SUM]  RESULT 2.000000 @ 1482080712362
[Dec 18 18:08:41][SUM]  RESULT 3.000000 @ 1482080920902

Aus dem Log wird ersichtlich, dass die gehäuften Logeinträge immer dann Zustande kommen, wenn die Last von weniger als ein S0 Impuls innerhalb von 180 s auf mind. 1 S0 Impuls innerhalb von 180 s steigt.

Nach einem Blick in die Sourcen von vzlogger, insb. threads.cpp ist das Verhalten auch erklärbar. Ob das so gewollt ist, kann der Entwickler beurteilen. Für mich kam es erst einmal überraschend.

Die verantwortliche Stelle im Code stammt aus der Funktion reading_thread().

        aggIntEnd = time(NULL);
        do { /* start thread main loop */
            aggIntEnd += mtr->aggtime(); /* end of this aggregation period */
            do { /* aggregate loop */
                /* fetch readings from meter and calculate delta */
                n = mtr->read(rds, details->max_readings); // blocking call bei S0 Protokol

                // nicht relevanter Code gelöscht

            } while((mtr->aggtime() > 0) && (time(NULL) < aggIntEnd)); /* default aggtime is -1 */

Ein Blick in mein angehängtes Logfile zeigt, dass mtr->read in Situation mit sehr wenig Last deutlich länger als die konfigurierte aggtime blockiert (teilweise bis zu 15 Minuten).
Das führt nun dazu, dass aggIntEnd sehr weit in der Vergangenheit liegt. Die nächste Berechnung von aggIntEnd += mtr->aggtime() führt zu einem Wert, der immer noch weit in der Vergangenheit liegt, womit die Abbruchbedingung der Aggregation loop weiterhin erfüllt ist.

Ist dieses Verhalten absichtlich so implementiert? Immerhin hat man dadurch über den kompletten Messzeitraum durchschnittlich immer einen Wert innerhalt von aggtime.

Ich hätte jetzt ehrlich gesagt eher sowas in der Art erwartet:

do {
   aggIntEnd += mtr->aggtime(); /* end of this aggregation period */
} while(aggIntEnd <= time(NULL)); /* aggIntEnd has to be in the future */

Viele Grüße,
Claus

Von: Claus Beckenbauer
Gesendet: Sonntag, 18. Dezember 2016 11:15
An: volkszaehler.org - users; Jens; volkszaehler-users
Betreff: Re: [vz-users] vzlogger s0 protocol + aggtime funktioniertsporadisch nicht wie erwartet

Das mit dem Lastwechsel würde ich eher auf kurze Lastspitzen reduzieren.
Bei mir läuft das ganze auf nem RaspberryPi.
Ich generiere jetzt mal ein Log File und poste es hier.

Am 18. Dezember 2016 10:40:10 MEZ, schrieb Jens <panterglas at web.de>:
Hallo Claus,

das Problem habe ich auch. Es tritt bei mir nur bei S0 Zähler auf und am Anfang eines Lastwechsels, z.B. wenn die Wärmepumpe einschaltet. Nach eine weile arbeitet blogger dann wie er soll.

Würde gerne helfen, das Problem zu lösen, weiß aber nicht so recht was ich machen soll um den Experten zu helfen.

Viele Grüße Jens

Am 18.12.2016 um 09:38 schrieb Daniel Lauckner <vz at jahp.de>:

Hallo Claus,

am Samstag, 17. Dezember 2016 um 19:39 hast du geschrieben:

Ich hätte jetzt erwartet, dass vzlogger maximal alle 180 Sekunden
einen Wert in die DB einträgt. Meistens funktioniert das auch. 
[...]

Sporadisch kommt es jedoch vor, dass Werte häufiger eingetragen
werden.

Kann sich das jemand erklären?

Erklärung hab ich keine. Ein Logfile mit verbosity 15 und eine grobe
Richtung wie oft das auftritt wäre hilfreich.

mfg Daniel

-- 
Diese Nachricht wurde von meinem Android-Mobiltelefon mit K-9 Mail gesendet.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://demo.volkszaehler.org/pipermail/volkszaehler-users/attachments/20161218/af5ff8cd/attachment.html>