Huge CPU load with 2.0.1

Question

Huge CPU load with 2.0.1

Matt77CHE opened this issue 2 years ago · 61 comments

Hi
When I updated history adapter from 1.11.1 to 2.0.1 I recognized every time a huge CPU load (up to 99% / normaly load about 10%) when I was loading page in VIS with a Flot Chart.

It didn't happen with 1.11.1 and when I made a downgrade again from 2.0.2 to 1.11.1 it disappeared again.

Also the RAM indicator in Instance-View showed with 2.0.1 up to 900MB / with 1.11.1 it's about 70BM.

admin: 5.4.9
Js-controller: 4.0.23

Is there something in my settings I have to change, or is 2.0.1 somewhere buggy?

Answer 1 · 2022-05-14T13:53:06.000Z

Can you please provide a debug log from borh versions with "the same chart request"?

Answer 2 · 2022-05-14T14:50:25.000Z

History 1.11.1 on debug:

history.0
2022-05-14 16:42:47.286	debug	Send: 519 of: 17761 in: 102ms

history.0
2022-05-14 16:42:47.235	debug	got 3 datapoints for BFS 7

history.0
2022-05-14 16:42:47.184	debug	use parallel requests

history.0
2022-05-14 16:42:47.145	debug	Send: 607 of: 20905 in: 111ms

history.0
2022-05-14 16:42:47.086	debug	got 3 datapoints for BFS 8

history.0
2022-05-14 16:42:47.034	debug	use parallel requests

history.0
2022-05-14 16:42:46.999	debug	Send: 606 of: 20902 in: 120ms

history.0
2022-05-14 16:42:46.935	debug	got 3 datapoints for BFS 6

history.0
2022-05-14 16:42:46.879	debug	use parallel requests

history.0
2022-05-14 16:42:46.833	debug	Send: 606 of: 20901 in: 128ms

history.0
2022-05-14 16:42:46.759	debug	got 3 datapoints for BFS 5

history.0
2022-05-14 16:42:46.705	debug	use parallel requests

history.0
2022-05-14 16:42:46.669	debug	Send: 606 of: 20900 in: 111ms

history.0
2022-05-14 16:42:46.614	debug	got 3 datapoints for BFS 4

history.0
2022-05-14 16:42:46.558	debug	use parallel requests

history.0
2022-05-14 16:42:46.512	debug	Send: 551 of: 17276 in: 111ms

history.0
2022-05-14 16:42:46.451	debug	got 3 datapoints for BFS 3

history.0
2022-05-14 16:42:46.401	debug	use parallel requests

history.0
2022-05-14 16:42:46.362	debug	Send: 608 of: 20895 in: 99ms

history.0
2022-05-14 16:42:46.312	debug	got 3 datapoints for BFS 2

history.0
2022-05-14 16:42:46.263	debug	use parallel requests

history.0
2022-05-14 16:42:46.236	debug	Send: 322 of: 10441 in: 85ms

history.0
2022-05-14 16:42:46.200	debug	got 3 datapoints for BFS 1

history.0
2022-05-14 16:42:46.151	debug	use parallel requests

history.0
2022-05-14 16:42:43.959	debug	Send: 1005 of: 20908 in: 105ms

history.0
2022-05-14 16:42:43.902	debug	got 1 datapoints for Regen letzte h

history.0
2022-05-14 16:42:43.854	debug	use parallel requests

history.0
2022-05-14 16:42:43.801	debug	Send: 1005 of: 20908 in: 109ms

history.0
2022-05-14 16:42:43.743	debug	got 1 datapoints for Regen ganzer Tag

history.0
2022-05-14 16:42:43.692	debug	use parallel requests

History 2.0.1 on debug:

`history.0
2022-05-14 16:45:57.957 debug 0_userdata.0.MeinWetter.Regen_Stunde16525394746450.3217834768140251 Send: 19028 of: 19027 in: 83312ms

history.0
2022-05-14 16:45:53.719 debug 0_userdata.0.MeinWetter.DP100.2.Bodenfeuchtigkeit16525394746140.6732358205955207 Send: 18982 of: 19016 in: 79105ms

history.0
2022-05-14 16:45:51.716 debug 0_userdata.0.MeinWetter.Regen_Stunde16525394736690.4691697703114912 Send: 19030 of: 19029 in: 78047ms

history.0
2022-05-14 16:45:44.112 debug 0_userdata.0.MeinWetter.DP100.7.Bodenfeuchtigkeit16525395436130.1287146287253591 Send: 519 of: 15913 in: 499ms

history.0
2022-05-14 16:45:43.967 debug getOneCachedData: got 0 datapoints for BFS 7

history.0
2022-05-14 16:45:43.614 debug 0_userdata.0.MeinWetter.DP100.7.Bodenfeuchtigkeit16525395436130.1287146287253591 use parallel requests for getHistory

history.0
2022-05-14 16:45:43.613 debug 0_userdata.0.MeinWetter.DP100.7.Bodenfeuchtigkeit16525395436130.1287146287253591 getHistory call: {"id":"0_userdata.0.MeinWetter.DP100.7.Bodenfeuchtigkeit","path":"/opt/iobroker/iobroker-data/history/","start":1651934725745,"end":1652539525745,"step":null,"count":600,"from":false,"ack":false,"q":false,"ignoreNull":"true","aggregate":"minmax","limit":600,"addId":false,"sessionId":2,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.DP100.7.Bodenfeuchtigkeit16525395436130.1287146287253591","round":null}

history.0
2022-05-14 16:45:43.371 debug 0_userdata.0.MeinWetter.DP100.8.Bodenfeuchtigkeit16525395426500.47889192560539784 Send: 607 of: 19056 in: 721ms

history.0
2022-05-14 16:45:43.058 debug getOneCachedData: got 3 datapoints for BFS 8

history.0
2022-05-14 16:45:42.651 debug 0_userdata.0.MeinWetter.DP100.8.Bodenfeuchtigkeit16525395426500.47889192560539784 use parallel requests for getHistory

history.0
2022-05-14 16:45:42.650 debug 0_userdata.0.MeinWetter.DP100.8.Bodenfeuchtigkeit16525395426500.47889192560539784 getHistory call: {"id":"0_userdata.0.MeinWetter.DP100.8.Bodenfeuchtigkeit","path":"/opt/iobroker/iobroker-data/history/","start":1651934725745,"end":1652539525745,"step":null,"count":600,"from":false,"ack":false,"q":false,"ignoreNull":"true","aggregate":"minmax","limit":600,"addId":false,"sessionId":2,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.DP100.8.Bodenfeuchtigkeit16525395426500.47889192560539784","round":null}

history.0
2022-05-14 16:45:42.111 debug 0_userdata.0.MeinWetter.DP100.6.Bodenfeuchtigkeit16525395416200.7894546776835749 Send: 607 of: 19053 in: 491ms

history.0
2022-05-14 16:45:41.977 debug getOneCachedData: got 3 datapoints for BFS 6

history.0
2022-05-14 16:45:41.620 debug 0_userdata.0.MeinWetter.DP100.6.Bodenfeuchtigkeit16525395416200.7894546776835749 use parallel requests for getHistory

history.0
2022-05-14 16:45:41.620 debug 0_userdata.0.MeinWetter.DP100.6.Bodenfeuchtigkeit16525395416200.7894546776835749 getHistory call: {"id":"0_userdata.0.MeinWetter.DP100.6.Bodenfeuchtigkeit","path":"/opt/iobroker/iobroker-data/history/","start":1651934725745,"end":1652539525745,"step":null,"count":600,"from":false,"ack":false,"q":false,"ignoreNull":"true","aggregate":"minmax","limit":600,"addId":false,"sessionId":2,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.DP100.6.Bodenfeuchtigkeit16525395416200.7894546776835749","round":null}

history.0
2022-05-14 16:45:41.154 debug 0_userdata.0.MeinWetter.DP100.5.Bodenfeuchtigkeit16525395406510.07771112803355362 Send: 607 of: 19052 in: 503ms

history.0
2022-05-14 16:45:40.904 debug getOneCachedData: got 3 datapoints for BFS 5

history.0
2022-05-14 16:45:40.652 debug 0_userdata.0.MeinWetter.DP100.5.Bodenfeuchtigkeit16525395406510.07771112803355362 use parallel requests for getHistory

history.0
2022-05-14 16:45:40.651 debug 0_userdata.0.MeinWetter.DP100.5.Bodenfeuchtigkeit16525395406510.07771112803355362 getHistory call: {"id":"0_userdata.0.MeinWetter.DP100.5.Bodenfeuchtigkeit","path":"/opt/iobroker/iobroker-data/history/","start":1651934725745,"end":1652539525745,"step":null,"count":600,"from":false,"ack":false,"q":false,"ignoreNull":"true","aggregate":"minmax","limit":600,"addId":false,"sessionId":2,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.DP100.5.Bodenfeuchtigkeit16525395406510.07771112803355362","round":null}

history.0
2022-05-14 16:45:40.278 debug 0_userdata.0.MeinWetter.DP100.4.Bodenfeuchtigkeit16525395396750.04230880906652801 Send: 607 of: 19051 in: 603ms

history.0
2022-05-14 16:45:40.023 debug getOneCachedData: got 3 datapoints for BFS 4

history.0
2022-05-14 16:45:39.675 debug 0_userdata.0.MeinWetter.DP100.4.Bodenfeuchtigkeit16525395396750.04230880906652801 use parallel requests for getHistory

history.0
2022-05-14 16:45:39.675 debug 0_userdata.0.MeinWetter.DP100.4.Bodenfeuchtigkeit16525395396750.04230880906652801 getHistory call: {"id":"0_userdata.0.MeinWetter.DP100.4.Bodenfeuchtigkeit","path":"/opt/iobroker/iobroker-data/history/","start":1651934725745,"end":1652539525745,"step":null,"count":600,"from":false,"ack":false,"q":false,"ignoreNull":"true","aggregate":"minmax","limit":600,"addId":false,"sessionId":2,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.DP100.4.Bodenfeuchtigkeit16525395396750.04230880906652801","round":null}

history.0
2022-05-14 16:45:39.186 debug 0_userdata.0.MeinWetter.DP100.3.Bodenfeuchtigkeit16525395386360.16223218337762169 Send: 551 of: 17284 in: 550ms

history.0
2022-05-14 16:45:39.015 debug getOneCachedData: got 3 datapoints for BFS 3

history.0
2022-05-14 16:45:38.636 debug 0_userdata.0.MeinWetter.DP100.3.Bodenfeuchtigkeit16525395386360.16223218337762169 use parallel requests for getHistory

history.0
2022-05-14 16:45:38.636 debug 0_userdata.0.MeinWetter.DP100.3.Bodenfeuchtigkeit16525395386360.16223218337762169 getHistory call: {"id":"0_userdata.0.MeinWetter.DP100.3.Bodenfeuchtigkeit","path":"/opt/iobroker/iobroker-data/history/","start":1651934725745,"end":1652539525745,"step":null,"count":600,"from":false,"ack":false,"q":false,"ignoreNull":"true","aggregate":"minmax","limit":600,"addId":false,"sessionId":2,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.DP100.3.Bodenfeuchtigkeit16525395386360.16223218337762169","round":null}

history.0
2022-05-14 16:45:38.263 debug 0_userdata.0.MeinWetter.DP100.2.Bodenfeuchtigkeit16525395376230.12890294817228254 Send: 608 of: 19046 in: 640ms

history.0
2022-05-14 16:45:37.997 debug getOneCachedData: got 3 datapoints for BFS 2

history.0
2022-05-14 16:45:37.623 debug 0_userdata.0.MeinWetter.DP100.2.Bodenfeuchtigkeit16525395376230.12890294817228254 use parallel requests for getHistory

history.0
2022-05-14 16:45:37.623 debug 0_userdata.0.MeinWetter.DP100.2.Bodenfeuchtigkeit16525395376230.12890294817228254 getHistory call: {"id":"0_userdata.0.MeinWetter.DP100.2.Bodenfeuchtigkeit","path":"/opt/iobroker/iobroker-data/history/","start":1651934725745,"end":1652539525745,"step":null,"count":600,"from":false,"ack":false,"q":false,"ignoreNull":"true","aggregate":"minmax","limit":600,"addId":false,"sessionId":2,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.DP100.2.Bodenfeuchtigkeit16525395376230.12890294817228254","round":null}

history.0
2022-05-14 16:45:37.413 debug 0_userdata.0.MeinWetter.DP100.1.Bodenfeuchtigkeit16525395294070.22479815559459237 Send: 320 of: 9696 in: 8006ms

history.0
2022-05-14 16:45:37.344 debug getOneCachedData: got 3 datapoints for BFS 1

history.0
2022-05-14 16:45:37.319 debug getOneCachedData: got 3 datapoints for BFS 1

history.0
2022-05-14 16:45:29.564 debug 0_userdata.0.MeinWetter.DP100.1.Bodenfeuchtigkeit16525394736330.5244507489462606 Send: 9633 of: 9667 in: 55931ms

history.0
2022-05-14 16:45:29.407 debug 0_userdata.0.MeinWetter.DP100.1.Bodenfeuchtigkeit16525395294070.22479815559459237 use parallel requests for getHistory

history.0
2022-05-14 16:45:29.407 debug 0_userdata.0.MeinWetter.DP100.1.Bodenfeuchtigkeit16525395294070.22479815559459237 getHistory call: {"id":"0_userdata.0.MeinWetter.DP100.1.Bodenfeuchtigkeit","path":"/opt/iobroker/iobroker-data/history/","start":1651934725745,"end":1652539525745,"step":null,"count":600,"from":false,"ack":false,"q":false,"ignoreNull":"true","aggregate":"minmax","limit":600,"addId":false,"sessionId":2,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.DP100.1.Bodenfeuchtigkeit16525395294070.22479815559459237","round":null}

history.0
2022-05-14 16:45:29.290 debug getOneCachedData: got 3 datapoints for BFS 3

history.0
2022-05-14 16:45:20.847 debug getOneCachedData: got 3 datapoints for BFS 2

history.0
2022-05-14 16:45:08.381 debug 0_userdata.0.MeinWetter.Regen_Stunde16525395074310.32840952208744234 Send: 1004 of: 19046 in: 950ms

history.0
2022-05-14 16:45:07.951 debug getOneCachedData: got 0 datapoints for Regen letzte h

history.0
2022-05-14 16:45:07.432 debug 0_userdata.0.MeinWetter.Regen_Stunde16525395074310.32840952208744234 use parallel requests for getHistory

history.0
2022-05-14 16:45:07.431 debug 0_userdata.0.MeinWetter.Regen_Stunde16525395074310.32840952208744234 getHistory call: {"id":"0_userdata.0.MeinWetter.Regen_Stunde","path":"/opt/iobroker/iobroker-data/history/","start":1651934708027,"end":1652539508027,"step":null,"count":1000,"from":false,"ack":false,"q":false,"ignoreNull":"true","aggregate":"minmax","limit":1000,"addId":false,"sessionId":2,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.Regen_Stunde16525395074310.32840952208744234","round":null}

history.0
2022-05-14 16:45:07.383 debug 0_userdata.0.MeinWetter.Regen_Tag16525395067090.9634364943676639 Send: 1004 of: 19046 in: 674ms

history.0
2022-05-14 16:45:07.011 debug getOneCachedData: got 0 datapoints for Regen ganzer Tag

history.0
2022-05-14 16:45:06.709 debug 0_userdata.0.MeinWetter.Regen_Tag16525395067090.9634364943676639 use parallel requests for getHistory

history.0
2022-05-14 16:45:06.709 debug 0_userdata.0.MeinWetter.Regen_Tag16525395067090.9634364943676639 getHistory call: {"id":"0_userdata.0.MeinWetter.Regen_Tag","path":"/opt/iobroker/iobroker-data/history/","start":1651934708027,"end":1652539508027,"step":null,"count":1000,"from":false,"ack":false,"q":false,"ignoreNull":"true","aggregate":"minmax","limit":1000,"addId":false,"sessionId":2,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.Regen_Tag16525395067090.9634364943676639","round":null}

history.0
2022-05-14 16:45:06.583 debug 0_userdata.0.MeinWetter.DP100.1.Bodenfeuchtigkeit16525395065830.11021175387038085 use parallel requests for getHistory

history.0
2022-05-14 16:45:06.583 debug 0_userdata.0.MeinWetter.DP100.1.Bodenfeuchtigkeit16525395065830.11021175387038085 getHistory call: {"id":"0_userdata.0.MeinWetter.DP100.1.Bodenfeuchtigkeit","path":"/opt/iobroker/iobroker-data/history/","start":1651934708020,"end":1652539508020,"step":null,"count":1000000,"from":false,"ack":false,"q":false,"ignoreNull":"true","aggregate":"minmax","limit":1000000,"addId":false,"sessionId":2,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.DP100.1.Bodenfeuchtigkeit16525395065830.11021175387038085","round":null}

history.0
2022-05-14 16:45:06.464 debug 0_userdata.0.MeinWetter.DP100.3.Bodenfeuchtigkeit16525395064640.996568618851478 use parallel requests for getHistory

history.0
2022-05-14 16:45:06.464 debug 0_userdata.0.MeinWetter.DP100.3.Bodenfeuchtigkeit16525395064640.996568618851478 getHistory call: {"id":"0_userdata.0.MeinWetter.DP100.3.Bodenfeuchtigkeit","path":"/opt/iobroker/iobroker-data/history/","start":1651934707997,"end":1652539507997,"step":null,"count":1000000,"from":false,"ack":false,"q":false,"ignoreNull":"true","aggregate":"minmax","limit":1000000,"addId":false,"sessionId":2,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.DP100.3.Bodenfeuchtigkeit16525395064640.996568618851478","round":null}

history.0
2022-05-14 16:45:06.373 debug 0_userdata.0.MeinWetter.DP100.2.Bodenfeuchtigkeit16525395063720.8140996762487953 use parallel requests for getHistory

history.0
2022-05-14 16:45:06.372 debug 0_userdata.0.MeinWetter.DP100.2.Bodenfeuchtigkeit16525395063720.8140996762487953 getHistory call: {"id":"0_userdata.0.MeinWetter.DP100.2.Bodenfeuchtigkeit","path":"/opt/iobroker/iobroker-data/history/","start":1651934707970,"end":1652539507970,"step":null,"count":1000000,"from":false,"ack":false,"q":false,"ignoreNull":"true","aggregate":"minmax","limit":1000000,"addId":false,"sessionId":2,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.DP100.2.Bodenfeuchtigkeit16525395063720.8140996762487953","round":null}

history.0
2022-05-14 16:44:55.446 debug getOneCachedData: got 2 datapoints for BFS 2

history.0
2022-05-14 16:44:49.858 debug getOneCachedData: got 2 datapoints for BFS 1

history.0
2022-05-14 16:44:45.979 debug getOneCachedData: got 0 datapoints for Regen letzte h```

Answer 3 · 2022-05-14T21:41:27.000Z

Interessant ... Also ja diese "Daten von 1 Woche mit minmax" aggregiert die neue Version um einiges Langsamer als die alte. mist.

Kannst Du mir mal 1-2 Wochen deiner Datenfiles einfach in ein Zip packen und per E-mail an iobroker@fischer-ka.de senden? Muss das glaube it so einem szenario nachstellen. Danke

Answer 4 · 2022-05-15T10:32:56.000Z

Also welche Datenfiles möchtest du - die Log Files?- nur vom History-Adapter, oder die gesamte?
Mit dem 2.0.1 oder mit der 1.11.1? - mit 2.0.1 müsste ich schauen, was noch da ist, sollten jedoch ein paar Tage da sein.

Da ich jedoch nicht mehrfach täglich auf die Charts in der VIS zugreife, dürfte da nicht allzu viel vorhanden sein.....
Aber klar kannst du sie haben.

Answer 5 · 2022-05-15T10:50:52.000Z

Ich hab mal noch kurz die Log Files durchgeschaut; da History erst seit gestern auf Debug läuft, ist da natürlich fast nichts drin.
Ich könnte ihn jedoch auf Debug belassen; dann wäre nur noch die Frage, ob ich die 2.0.1 wieder installieren soll (denke ja)?

Answer 6 · 2022-05-15T11:59:11.000Z

Nein ich meine die Datenfiles ... also die Files die die 20 000 Daten von 7 Tagen entahletne. In dem Verzeichnis was du beim adsapter angibst bzw /opt/iobroker/iobroker.data/history oder ist pro Tag einnVerzeichnis und prp Datenpunkt ein File. Ich brauche die Rohdaten ... SOnst müsste ich mor jetzt irgendwie sinnvoll ein paar zehntausend Testdatensätze basteln

Answer 7 · 2022-05-15T12:41:04.000Z

Ich habe Dir die Daten per Mail gesendet.....

Answer 8 · 2022-05-27T16:03:34.000Z

Still on my agenda! (not adressed in 2.1.0 coming soon ... needed to get out other stuff first

Answer 9 · 2022-06-05T19:42:30.000Z

Hi, komme gerade nicht so recht weiter damit bei mir ... Bitte installiere mal GitHub Adapter version, schalte die Instanz auf Debug log und dann NUR für einen betroffenen Datenpunkt mal das Debug log in den Settings ein ... Dann bitte das log von so einer History Abfrage oder ein paar ... Danke. Dann können wir mal sehen wo genau die Zeit drauf geht.

Am besten aber als Textfile hier hochladen/attachen

Answer 10 · 2022-06-06T12:05:15.000Z

Hi
Ich bin dran.... versuche gerade die Version von Github herunterzuladen - dauert aber irgendwie verdammt lange.....

Answer 11 · 2022-06-06T12:59:37.000Z

Also - ich habe die Version mittels Katze und dann von Github heruntergeladen; mittels URL kam ne Fehlermeldung.

Ich habe danach History auf debug gestellt; danach ist mir im Log folgendes aufgefallen:

history.0	2022-06-06 14:29:14.369	debug	0_userdata.0.MeinWetter.Regen_Stunde16545185115640.263664686476917 Send: 19010 of: 19010 in: 42805ms
history.0	2022-06-06 14:29:08.394	debug	0_userdata.0.MeinWetter.Regen_Stunde16545185029810.6480794367840266 Send: 19010 of: 19010 in: 45413ms
history.0	2022-06-06 14:28:59.603	debug	0_userdata.0.MeinWetter.Regen_Stunde16545184915730.6666321360116938 Send: 19010 of: 19010 in: 48029ms
history.0	2022-06-06 14:28:39.017	debug	getOneCachedData: got 1 datapoints for Regen letzte h

history.0	2022-06-06 14:28:22.676	debug	0_userdata.0.MeinWetter.DP100.2.Bodenfeuchtigkeit16545184538010.12343283975710095 Send: 18988 of: 19010 in: 48875ms

history.0	2022-06-06 14:28:29.533	debug	0_userdata.0.MeinWetter.DP100.3.Bodenfeuchtigkeit16545184538130.2957974671028558 Send: 18988 of: 19010 in: 55720ms

history.0	2022-06-06 14:35:37.570	debug	0_userdata.0.Läuft_Bewässerung16545189375700.6215022276579167 getHistory call: {"id":"0_userdata.0.Läuft_Bewässerung","path":"/opt/iobroker/iobroker-data/history/","start":1653914103790,"end":1654518903790,"step":null,"count":300,"from":false,"ack":false,"q":false,"aggregate":"onchange","limit":300,"addId":false,"sessionId":28,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.Läuft_Bewässerung16545189375700.6215022276579167","round":null}
history.0	2022-06-06 14:35:06.496	debug	0_userdata.0.MeinWetter.Regen_Stunde16545188515940.548087462285942 Send: 19010 of: 19010 in: 54902ms
history.0	2022-06-06 14:35:03.585	debug	0_userdata.0.Läuft_Bewässerung16545189035800.6103964445803716 Send: 23 values in: 5ms

history.0	2022-06-06 14:39:20.083	debug	getOneCachedData: got 0 datapoints for Regen letzte h
history.0	2022-06-06 14:39:11.920	debug	0_userdata.0.MeinWetter.Regen_Stunde16545191477150.3431104355552088 Send: 1005 of: 19010 in: 4205ms
history.0	2022-06-06 14:39:11.857	debug	0_userdata.0.MeinWetter.Regen_Stunde16545191518570.5647514076181754 use parallel requests for getHistory

History Adapter.txt

Da dauerten die Abfragen recht lange....
Da kommt manchmal auch was mit "use parallel requests for getHistory".....

Answer 12 · 2022-06-06T13:10:02.000Z

Danke,

Ja GitHub installs mit npm 6 dauern aktuell laaaange (10+mins keine Seltenheit). Liegt an nem, Bug in npm selbst. EInfach abwarten.

Hast Du auch das "zusatz Logging" aktiviert? geh mal auf einen oder paar dieser Datenpunkte in die einstellungen, da ist ein "erweiteres debug log" ... schalt das mal ein dann kommt meeeehr log ... (alternativ mach dasd in den default settings der instanz an das kommts ggf für alles)

Am Ende muss wenn so ein " use parallel requests for getHistory" kommt danach einige Logzeilen kommen mit "GetHistory fork" drin. genau die fehlen und das sind die interessanten :-)

Answer 13 · 2022-06-06T13:19:55.000Z

Was aber auf jeden Fall schonmal klar ist (und da ist die Frage wo das herkommt) Da fragt jemand nach aggregierten Daten über "minmax" aggregatlogik für 7 Tage, aber will 1.000.000 datenpunkte haben ... und das sind gerade die die soooo ewig dauern. Am Ende bekommt er "nur" ca. 19.000 Datensätze aber stell dir dioch mal vort was das für Logik und verarbeitungszeit bedeutet:

Er initialisiert im RAM eine Struktur um 1 Mio Datenpunkte zu verarbeiten
Er liesst 7 Tage Daten ein, sagen wir mal 20.000 Datensätze (das volle Debug log sollte das genauer zeigen). Dann ordnet er diese Daten in diese Datenstruktur ein
Danach berechnet er da dinge auf 1 Mio Datensätzen (ich denke das selten zwei Datensäätze in einer Zeitscheibe sind weil jede zeitscheibe ist nur 604ms lang bei 7 Tage in MS durch 1Mio
Dann sortiert er das aus und entfernt "leere" zeitscheiben - mein Tipp geht darauf das das der Punkt ist wo viel Zeit verloren geht weil er immer wieder daten im RAM neu strukturieren muss. das sollte seeeehr teuer sein
Dann kommen 19k ergebnisse raus die dann zurückgegeben werden

Also mach mal bitte Log mit genau dem, will mal meine vermutung bestätigen und lass auch die Abfrage so das wir sehen können wegen Optimierungen, aber schau mal wo diese Abfragen herkommen weil die Visu die das so macht die sollte dringend die Limits anpassen :-)

Answer 14 · 2022-06-06T13:20:17.000Z

nein, das zusatz Logging habe ich noch nicht, da ich dieses "erweiterte debug log " nirgends finden kann....

Wenn ich einen Datenpunk in den Objekten nehme der gelogt wird, finde ich diese Einstellung nirgends.... - auch bei der History Instanz finde ich nirgends so was - Bin ich Blind...?

Answer 15 · 2022-06-06T13:23:25.000Z

Ich glaube das ist das Skript von der WLan Wetterstation; evtl könnte da ein Update das Skriptes von der helfen - werde das dann mal ausprobieren...

Answer 16 · 2022-06-06T13:24:03.000Z

Das unterste

Answer 17 · 2022-06-06T13:42:35.000Z

Ich frage mich aber immer noch, wieso das mit 1.11.1 kein Problem war - aber jetzt mit der neuen schon...

Answer 18 · 2022-06-06T13:44:34.000Z

Da steht aber history 1..11.1 ???? Das ist nicht die github version.
Bitte ggf nochmal "iob upload history" ausführen.

naja es gab einige größere Umstellungen intern ... da kann das schon sein das irgendwas "unperformanter" wird bei sowas wie hier mit 1 Mio abfragewerten :-)

Answer 19 · 2022-06-06T13:45:15.000Z

das erweiterte Log habe ich gefunden....

Answer 20 · 2022-06-06T13:45:15.000Z

Aahhh ... Admin 5 UI bitte ... nicht Admin 4 UI nutzen!!

Answer 21 · 2022-06-06T13:45:38.000Z

ja, habs -

Answer 22 · 2022-06-06T13:56:15.000Z

Hier die Neue - mit erweitertem Log:

History Adapter.txt

Answer 23 · 2022-06-06T14:06:08.000Z

Ok, ich habe mal MeinWetter.Regen_Stunde16545234634630.48424264669268746 genau angeschaut.

Das macht keinen sinn ... ag mal ... wie geht es dem system eigentlich? zweig mal screenshot von top ... das dauer alles viel zu lang., das muss unter einer mega load stehen das system ... Das zieht alles nochmal in die länge.

Also am besten: zeig mal top wie es jetzt ist.
Dann mach mal alles aus was getHistory Anfragen sendet ... kannst ja im log schauen das NICHTS mehr ankommt. Dann am besten mal EIN chart aufrufen, am allerbesten auch nur EIN Datenpunkt und davon das log aber auch vor her ein "top" bitte.

Answer 24 · 2022-06-06T14:08:38.000Z

Meinst du mit Top das hier:

Answer 25 · 2022-06-06T14:10:36.000Z

Hier noch vom Proxmox, die Spiten sind seit dem update vom History Adapter:

Answer 26 · 2022-06-06T14:12:41.000Z

Matt77CHE commented 2 years ago

Answer 27 · 2022-06-06T14:16:00.000Z

Matt77CHE commented 2 years ago

Answer 28 · 2022-06-06T14:16:43.000Z

Matt77CHE commented 2 years ago

Answer 29 · 2022-06-06T14:20:09.000Z

Zeig mal die Settings ... wieviele Cores hat denn die VM zugewiesen auf proxmox seite bitte? Was ist das für ein Proxmox Host?

Wenn ich Bodenfeuchtigkeit16545234634700.3769635928168418 ansehe sieht es etwas besser aus:

107ms um einen neuen nodejs Prozess zu starten (nicht gerade kurz)
1.998ms um die 1 Mio Datensätze im RAM zu initialisieren ... viiiel zu lange
5.061ms macht er quasi nichts (er sagt dem Haupt prozess an sich nur das er cache daten will)
285ms Verarbeiten der File daten
3.660ms warten auf die cache daten vom HauptProzess
quasi instance fertig und start der Ergebnisaufbereitung
68.934ms Umgestalten der Ergebnisse und runterdampfen der 1Mio zeitscheiben auf 19k

Krass

Answer 30 · 2022-06-06T14:22:00.000Z

Matt77CHE commented 2 years ago

Answer 31 · 2022-06-06T14:23:36.000Z

Matt77CHE commented 2 years ago

Answer 32 · 2022-06-06T14:24:34.000Z

Matt77CHE commented 2 years ago

Answer 33 · 2022-06-06T14:25:44.000Z

Ok, mal aus interesse ... weleche UI macht denn diese Anfragen mit count 1Mio? Kannst das mal auf zb 20.000 ZEitsxheiben verringern und schauen was dann rauskommt?

Answer 34 · 2022-06-06T14:27:00.000Z

PS: Weil zbn MeinWetter.Aussentemperatur16545235510830.07349148805507144 angesehen ....
ANfrage von 200 Datensätzen ... 129ms

Answer 35 · 2022-06-06T14:28:36.000Z

das ist das WLan-Wetterstation-Script von SBorg.....

Answer 36 · 2022-06-06T14:29:22.000Z

aber eben - ich glaube da gibt es wieder neuere Versionen - evtl löst das das Problem....

Answer 37 · 2022-06-06T14:29:32.000Z

Was will das denn mit 1 Mio Ergebnissen ... haste mal link dazu?

Answer 38 · 2022-06-06T14:31:27.000Z

Und kannst bitte mal alles ausschalten was getHitsory macht und mal wirklich auf einem "beruhigten" system nur einen call laufen lassen?

Answer 39 · 2022-06-06T14:31:38.000Z

Klaro:

https://github.com/SBorg2014/WLAN-Wetterstation

Answer 40 · 2022-06-06T14:36:08.000Z

Ehrlich??? Das Skript macht keinerlei "getHistory"-Anfragen, das redet sogar primär mit InfluxDB. Ist es das wirklich?

2022-06-06 15:51:03.463 debug 0_userdata.0.MeinWetter.Regen_Stunde16545234634630.48424264669268746 getHistory call: {"id":"0_userdata.0.MeinWetter.Regen_Stunde","path":"/opt/iobroker/iobroker-data/history/","start":1653918603789,"end":1654523403789,"step":null,"count":1000000,"from":false,"ack":false,"q":false,"aggregate":"minmax","limit":1000000,"addId":false,"sessionId":13,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.MeinWetter.Regen_Stunde16545234634630.48424264669268746","round":null}

2022-06-06 15:51:03.458 debug sonoff.0.GV_03.POWER16545234634580.8281327426185476 getHistory call: {"id":"sonoff.0.GV_03.POWER","path":"/opt/iobroker/iobroker-data/history/","start":1653918603789,"end":1654523403789,"step":null,"count":1000000,"from":false,"ack":false,"q":false,"aggregate":"onchange","limit":1000000,"addId":false,"sessionId":13,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"sonoff.0.GV_03.POWER16545234634580.8281327426185476","round":null}

Answer 41 · 2022-06-06T14:39:27.000Z

ich habe keine Influx-DB
Was ich brauche, logge ich mit History.

Hier das Skript:
Wetterstation.txt

Answer 42 · 2022-06-06T14:41:35.000Z

Also dieses Skript legt ausschliesslich States und Objekte an ... da ist keine Datenlogik drin, nichts was Daten setzt und auch nichts was Daten abfragt. Sicher das nicht irgendwo Flot oder ne Viso läuft die dir diese Datenounkte anzeigt als Charts?? Also dieses Skript ists nicht

Answer 43 · 2022-06-06T14:44:28.000Z

Also ich nutze History - dann weden die Daten mit Flot in Diagramme gewandelt - diese lasse ich mir in div VIS anzeigen

Answer 44 · 2022-06-06T14:45:26.000Z

Das Skript von der Wlan-Wetterstation musste ich in Proxmox in der VM des IoBrokers installieren...
Richtig - das von mir angehängte Script erstellt die Datenpunkte.

Answer 45 · 2022-06-06T14:46:47.000Z

diese lasse ich mir in div VIS anzeigen

Und wie sind die konfoguriert?? Kommen da vllt die "1 mio datenpunkte " her?

Answer 46 · 2022-06-06T14:59:47.000Z

Wäre da die "Anzahl" verantwortlich dafür in Flot?

...Das dient doch nur zur Darstellung?

Answer 47 · 2022-06-06T15:05:31.000Z

Was ich habe, sind 3 Tablets mit verschiedenen VIS - In den VIS diverse FLOT-Diagramme...

Answer 48 · 2022-06-06T15:07:34.000Z

Dann such mal ... irgendwo muss da 1000000 stehen bei "anzahl" ... Es gibt einige Abfragen mit 200 oder 600 und so die sind denke ich alle sok ... aber dann gibts die mit 1000000 die dir komplett aus der reihe tanzen

Answer 49 · 2022-06-06T15:09:44.000Z

Ja, das habe ich tatsächlich gefunden und diese nun auf 300 runter gesetzt.

Ich werde mal mein System diese Tage aufräumen, anpassen und ein paar Updates und Upgrades machen - Mal schauen wies es dann aussieht.

Answer 50 · 2022-06-06T15:24:14.000Z

Wäre hochinteressant. Ich teste gerade noch ein paar optimierungen bei den Array operationen die mir aufgefallen sind - aber halt vor allem zum Tragen kommen bei solchen "irrsinnigen" Anfragen wie bei Dir :-)

Wenn Du nochmal log hättest mit "weniger" wäre das echt cool

Answer 51 · 2022-06-06T15:36:33.000Z

Log kommt gleich....

Answer 52 · 2022-06-06T15:59:31.000Z

Hier ist es:
Ich musste natürlich in der VIS die URL noch anpassen - Vorher hatte er immer noch die 1000000 drin.... jetzt habe ich auf die Schnelle keine gefunden.

History Adapter.txt

Answer 53 · 2022-06-06T16:06:39.000Z

Jetzt ist alles so im 100-200ms bereich und die VM sollte sich deutlich beruhigt haben, oder!?

Die zeiten sind auch jetzt sinnvoller: zb Bodenfeuchtigkeit16545309750900.6642422033349569

44ms für start nodejs prozess
1ms Datenstrukturen initialisieren
82 ms Daten lesen und verarbeiten (inkl. cache daten)
2ms finalisierung der aggregation und Datens enden

Fertig nach 131ms

Ich suche immer noch nach "der Änderung" in History 2 die die Ursache sein könnte, aber finde keine. ggf ne Kleinigkeit die dein system dann "ünber ein Limit" gevbracht hat mit diesen 1 Mio zeitscheiben abfragen

Answer 54 · 2022-06-06T20:07:53.000Z

@Matt77CHE DO you like to check/test something for ? ;-)))

I tried some restructuring and now in my testcase such an "1 mio data case with just 60 datapoints" runs in 136ms instead of 5+seconds ...

It would be great to:

A: See it in your 1 Mio requested case
B: See it in your "changed to 300" case

Would you be willing to test that for me and send me log of that with the most current GitHub version?

And also maybe save a screenshot of such a graph before you install new version and after and compare that it looks the same :-)

Answer 55 · 2022-06-08T11:43:28.000Z

version gets released ... log would be still great to "see" the effects

Answer 56 · 2022-06-08T11:48:36.000Z

Ich werde es diese Woche mal noch einmal mit den erhöhten Anfragen ausprobieren und dir das Log hier einstellen.....

Answer 57 · 2022-06-08T14:46:08.000Z

Also;
Ich habe mal den IoBroker geupdated (admin 6.0.1) und alle Adapter; Node.js v14.19.3; NPM 6.14.17.

Ich habe den History adapter mit der Version 2.1.3 am laufen; habe ihn auf Debug gestellt und den Datenpunkt auf erweitertes Debug gestellt - Regen Stunde habe ich im Flot wieder auf 100000 gestellt, in der Vis die Adresse wieder aktualisiert.
Anschliessend die Abfrage gestartet - Absolut keine grössere Verzögerung wie gegenüber der 300er Abfrage in der Vis.
Soweit also gut;

Hier noch das Log:

History Adapter.txt

Answer 58 · 2022-06-08T15:42:00.000Z

Super, Danke!

Answer 59 · 2022-06-08T15:42:16.000Z

Wievielel millisekunden stehen bei den 300/600ern so?

Answer 60 · 2022-06-08T15:56:47.000Z

was ich gerade so fand war um die 60ms

Answer 61 · 2022-06-08T16:19:46.000Z

Also auch ca. doppelt so schnell wie vorher :-)