Template based data retrieval gets exponentially slower with many fields

[briis]

Hi,
I am building an integration of Meteobridge in to Home Assistant, and I use template.cgi to retrieve the needed fields.
I have all that running fine, but I have run in to the problem that it takes a very long time to get the result back from the Meteobridge Device. I have both a Nano SD and a Pro and it does not make a difference which one I use.

Here is the link to the code that does the actual communication with the Meteobridge Device: https://github.com/briis/pymeteobridge

A few numbers:

• If I process 62 fields in the template string it takes 7.6 seconds from the GET request until the results are returned. Size of the Request is 2467 Bytes.

• If I process 25 fields in the template string it takes 1.6 seconds from the GET request until the results are returned. Size of the Request is 1034 Bytes.

• If I process 12 fields in the template string it takes 0.4 seconds from the GET request until the results are returned. Size of the Request is 564 Bytes.

If we take the last result and multiply that by 5, it should take around 2 seconds to process 60 fields, but as you can see from above it takes a lot longer. There is code that does the actual formatting of the GET string, but it takes micro seconds more to process 60 fields instead of 12, so that is not the issue.

There is no network issues and the Nano device runs with 0% Buffers.

The GET request is not complicated, and follows the guide from the Wiki.

I have a few service calls defined that adds a lot more fields, and they are way faster in processing, so am I doing anything wrong or could this be speeded up in any other way?

[admin]

Presumably some of the requested data makes Meteobridge to work a bit. Could you please share the request?

[briis]

Here are the fields that I use for the test, in the same order as above, so first the one that takes the longest time. I did try and remove some of the calculated fields like dmax and dmin, but I do see a big difference. So maybe stating the obvious, but the below fields are added to the end of this http://ip-of-meteobridge/cgi-bin/template.cgi?template=

Number 1:

Code: Select all

{'timestamp':+[epoch],+'temperature':+[th0temp-act:None],+'pressure':+[thb0seapress-act:None],+'air_pm_10':+[air0pm-act:None],+'air_pm_25':+[air1pm-act:None],+'air_pm_1':+[air2pm-act:None],+'heatindex':+[th0heatindex-act:None],+'humidity':+[th0hum-act:None],+'windspeedavg':+[wind0avgwind-act:None],+'windgust':+[wind0wind-max1:None],+'windspeed':+[wind0wind-act:None],+'windbearing':+[wind0dir-avg5.0:None],+'raintoday':+[rain0total-daysum:None],+'rainrate':+[rain0rate-act:None],+'dewpoint':+[th0dew-act:None],+'windchill':+[wind0chill-act:None],+'is_lowbat':+[th0lowbat-act.0:None],+'in_temperature':+[thb0temp-act:None],+'in_humidity':+[thb0hum-act.0:None],+'temphigh':+[th0temp-dmax:None],+'templow':+[th0temp-dmin:None],+'uvindex':+[uv0index-act:None],+'solarrad':+[sol0rad-act:None],+'temp_month_min':+[th0temp-mmin.1:None],+'temp_month_max':+[th0temp-mmax.1:None],+'temp_year_min':+[th0temp-ymin.1:None],+'temp_year_max':+[th0temp-ymax.1:None],+'wind_month_max':+[wind0wind-mmax.1:None],+'wind_year_max':+[wind0wind-ymax.1:None],+'rain_month_max':+[rain0total-mmax.1:None],+'rain_year_max':+[rain0total-ymax.1:None],+'rainrate_month_max':+[rain0rate-mmax.1:None],+'rainrate_year_max':+[rain0rate-ymax.1:None],+'lightning_count':+[lgt0total-act.0:None],+'lightning_energy':+[lgt0energy-act.0:None],+'lightning_distance':+[lgt0dist-act.0:None],+'bft_value':+[wind0wind-act=bft.0:None],+'trend_temperature':+[th0temp-delta10:None],+'trend_pressure':+[thb0seapress-delta10:None],+'absolute_pressure':+[thb0press-act:None],+'forecast':+'[forecast-text:None]',+'temperature_2':+[th1temp-act:None],+'humidity_2':+[th1hum-act:None],+'heatindex_2':+[th1heatindex-act.1:None],+'temperature_3':+[th2temp-act:None],+'humidity_3':+[th2hum-act:None],+'heatindex_3':+[th2heatindex-act.1:None],+'temperature_4':+[th3temp-act:None],+'humidity_4':+[th3hum-act:None],+'heatindex_4':+[th3heatindex-act.1:None],+'temperature_5':+[th4temp-act:None],+'humidity_5':+[th4hum-act:None],+'heatindex_5':+[th4heatindex-act.1:None],+'temperature_6':+[th5temp-act:None],+'humidity_6':+[th5hum-act:None],+'heatindex_6':+[th5heatindex-act.1:None],+'temperature_7':+[th6temp-act:None],+'humidity_7':+[th6hum-act:None],+'heatindex_7':+[th6heatindex-act.1:None],+'temperature_8':+[th7temp-act:None],+'humidity_8':+[th7hum-act:None],+'heatindex_8':+[th7heatindex-act.1:None]}+&contenttype=text/plain;charset=iso-8859-1

Number 2:

Code: Select all

{'timestamp':+[epoch],+'temperature':+[th0temp-act:None],+'pressure':+[thb0seapress-act:None],+'air_pm_10':+[air0pm-act:None],+'air_pm_25':+[air1pm-act:None],+'air_pm_1':+[air2pm-act:None],+'heatindex':+[th0heatindex-act:None],+'humidity':+[th0hum-act:None],+'windspeedavg':+[wind0avgwind-act:None],+'windgust':+[wind0wind-max1:None],+'windbearing':+[wind0dir-avg5.0:None],+'raintoday':+[rain0total-daysum:None],+'rainrate':+[rain0rate-act:None],+'dewpoint':+[th0dew-act:None],+'windchill':+[wind0chill-act:None],+'is_lowbat':+[th0lowbat-act.0:None],+'uvindex':+[uv0index-act:None],+'solarrad':+[sol0rad-act:None],+'lightning_count':+[lgt0total-act.0:None],+'lightning_energy':+[lgt0energy-act.0:None],+'lightning_distance':+[lgt0dist-act.0:None],+'trend_temperature':+[th0temp-delta10:None],+'trend_pressure':+[thb0seapress-delta10:None],+'absolute_pressure':+[thb0press-act:None],+'forecast':+'[forecast-text:None]'}+&contenttype=text/plain;charset=iso-8859-1

Number 3:

Code: Select all

{'temperature_2':+[th1temp-act:None],+'humidity_2':+[th1hum-act:None],+'heatindex_2':+[th1heatindex-act.1:None],+'temperature_3':+[th2temp-act:None],+'humidity_3':+[th2hum-act:None],+'heatindex_3':+[th2heatindex-act.1:None],+'temperature_4':+[th3temp-act:None],+'humidity_4':+[th3hum-act:None],+'heatindex_4':+[th3heatindex-act.1:None],+'temperature_5':+[th4temp-act:None],+'humidity_5':+[th4hum-act:None],+'heatindex_5':+[th4heatindex-act.1:None]}+&contenttype=text/plain;charset=iso-8859-1

[admin]

To better understand where the time is spent I added a switch that allows inspection of runtimes when doing template evaluation. This can be activated by placing "[mbsystem-debugtime:]" at the beginning of the template string. Doing so evaluation time of each template variable is added behind the evaluated variable, like "(35ns)". It also shows sum of all evaluations and total evaluation time, like "(sum:3ms, total:5ms)". Updated release has just been published.

Please give it a try on your machine. I tried with mine, but as many variables you use are not there, I do not have any interesting findings.

[briis]

Thanks. Just upgraded the NANO to this release and will start experimenting. I will post the findings when I have them.

[briis]

This debug flag was very helpful, as it clearly showed that it is NOT the processing of the values that takes time. Max time for many fields was a bit over 40ms. It turned out to be the string length returned and send that is really making a BIG difference in time.

I rewrote my request routine, so that I now only get and send the values of the fields, and then I post process these values in my program, and that brings the reply time down to a reasonable value even with many fields.