as_GPS: issues when gps module sampling > 1Hz

[dukeduck1984]

Hi Peter,

The as_GPS driver worked great when the gps module was at 1Hz standard sampling rate, however after I had set the module to sample at 5Hz, the example code shown in "3 Basic Usage" (the one using callback) behaved like it got stuck - it might print one or two lines of satellite data, but most of the time, it printed nothing, only 'waiting for GPS data' till it returned.

I connected the gps module by USB-TTL to PC, and it did sample at 5Hz.

What could be the issue?

Thanks.
Kaiyuan

[peterhinch]

What MicroPython hardware are you using?

[dukeduck1984]

ESP32 Wrover, firmware 1.13 stable

[dukeduck1984]

Usually in the first run right after setting the module to 5Hz, it would print several lines, but in the next few runs it was like it got stuck. Is it a memory issue?

[peterhinch]

It doesn't sound like one. The ESP32 has about 110K of free RAM which should be plenty. If MicroPython does run out of RAM it usually throws an exception.

I'm rather in the dark on this one. You could experiment with the UART rxbuf arg. Try setting it to something large, say 1024.

[dukeduck1984]

I set the rxbuf to 2048 and the baudrate of the uart to 11520 (it was 9600). ESP32's CPU freq was set to 240MHz. Now it won't get stuck. But the performance was not very stable.

In the callback, I added code to print epoch, so I can count how many times the callback was run. When the GPS module is set at 5Hz, the callback was run 1-3 times per second, most of the time, it was twice. I assume the parser somehow could not keep up with the update rate of the GPS module?

Is there anyway to speed it up? In my use case, I use the GPS to measure speed only, if I have the parser to parse only that sentence, will it be faster?

Thanks a lot.
Kaiyuan

[dukeduck1984]

Below is the fragment of the epoch printed by the callback, as you can see, it was not stable.

It printed total 143 lines within 60 seconds, so merely 2.3Hz on average.
661593218 661593219 661593220 661593220 661593220 661593221 661593221 661593221 661593223 661593223 661593223 661593223 661593224 661593224 661593226 661593226 661593226 661593226 661593226 661593227 661593228 661593228 661593229 661593229 661593229 661593229 661593231 661593231 661593231 661593232 661593232 661593232 661593234 661593234 661593234 661593234 661593234 661593235 661593236 661593236 661593237 661593237 661593237 661593237 661593239 661593239 661593239 661593239 661593240 661593240 661593240 661593242

[peterhinch]

I can only agree that the CPU may be failing to keep up with the workload. One thing to try is to set FULL_CHECK False. This will save a little work. The other might be to modify the code, reducing supported sentences dict to RMC only. This saves it parsing the other data (if I remember correctly - it's a while since I worked on this).

Most of my testing was done on Pyboards. The ESP32 is a very different animal as it has an underlying OS which can cause latency. I'm sure that I tested at 10Hz on a Pyboard, the maximum speed supported by the Adafruit GPS. No UART tweaks were required.

[dukeduck1984]

Thanks for pointing the direction.

Was that Pyboard you tested with STM32F4 or STM32F7?

[peterhinch]

Development was done on a Pyboard 1.1 (STM32F405RG), and the timings in the code comments relate to that hardware.

[romeocontrol]

Hallo, With a lot of support from Peter Hinch and others I used the Pycom Lopy as GPS parser. It was the V2 uasyncio. I tried a lot to get the callback-function to work, but ist wasn’t reliable. The await-function did work up to 10Hz. I used another format to receive the data, called PUBX. It contains all position information in one line. Comes from ublox-receivers. My as_PUBRT2-class is the as_GPS without most GPX-parsing due to ram problems with the old uasyncio. Greetings RT #indentation not correct! 5Hz example import gc from time import localtime gc.collect() import as_PUBRT2 gc.collect() import uasyncio as asyncio from machine import UART gc.collect() gc.threshold(gc.mem_free() // 4 + gc.mem_alloc()) uart= UART(1, baudrate=115200, pins=('P20','P21')) uart.readline() while uart.any(): print('y', uart.readline()) sreader = asyncio.StreamReader(uart) # Create a StreamReader # Instantiate pub pub = as_PUBRT2.AS_PUBRT(sreader) async def test(): print('waiting for pubRT data') await pub.data_received(position=True, altitude=True, date=False) for _ in range(50000): #print (localtime(pub.epoch_time), pub.mstime, pub.satellites_used, pub.hAcc, pub.vAcc) print(pub.gns_date, pub.gns_time, pub.epoch_time, pub.latitude_string(as_PUBRT2.KML), pub.longitude_string(as_PUBRT2.KML), 's',pub.speed(units=as_PUBRT2.KPH)) print(pub.altitude, pub.satellites_in_use, pub.hAcc) await asyncio.sleep_ms(200) loop = asyncio.get_event_loop() loop.run_until_complete(test())

…

Am 18.12.2020 um 09:15 schrieb Peter Hinch ***@***.***>: I can only agree that the CPU may be failing to keep up with the workload. One thing to try is to set FULL_CHECK <https://github.com/peterhinch/micropython-async/blob/master/v3/docs/GPS.md#46-public-class-variable> False. This will save a little work. The other might be to modify the code, reducing supported sentences dict <https://github.com/peterhinch/micropython-async/blob/cc73e0773103e511a72d7298ed950be3586d8956/v3/as_drivers/as_GPS/as_GPS.py#L121> to RMC only. This saves it parsing the other data (if I remember correctly - it's a while since I worked on this). Most of my testing was done on Pyboards. The ESP32 is a very different animal as it has an underlying OS which can cause latency. I'm sure that I tested at 10Hz on a Pyboard, the maximum speed supported by the Adafruit GPS. No UART tweaks were required. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#52 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AEI5EA552K4HTP756JFWW4LSVMFQTANCNFSM4U76FTVA>.

[dukeduck1984]

I tried to flash the ESP32 Wrover with the firmware without psram, thinking that might make the esp32 perform a bit faster. Also changed code to FULL_CHECK = False, and reduced supported_sentences to only RMC. The speed difference is minimal, still around 2ish Hz.

[dukeduck1984]

Another issue happened when supported_sentences dict was reduced to only RMC, the callback example broke - it wouldn't stop printing even when 60 seconds had passed.

[dukeduck1984]

@romeocontrol So you think it's related to the uasyncio performance on ESP32? BTW, my firmware is 1.13 stable, so it's uasyncio V3.

[romeocontrol]

I think: Try it without callback. In my case the problem was not performance but RAM. RT As an aside, I think: forum.micropython.org would be a better place to work on these problems.

…

Am 18.12.2020 um 11:15 schrieb Kaiyuan ***@***.***>: @romeocontrol <https://github.com/romeocontrol> So you think it's related to the uasyncio performance on ESP32? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#52 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AEI5EA354PDGVP3OIUJ3AM3SVMTURANCNFSM4U76FTVA>.

[dukeduck1984]

I think you are right @romeocontrol . This time I tried without callback, rather I used another coro in which I had the time_since_fix printed every 200ms for 60 seconds, (only) 36 out of 300 time_since_fix's were greater than 200ms - not bad!

[peterhinch]

I agree that this would be worth moving to the forum where it will be seen by more people who may have ideas to contribute or experience to report.

I am certainly open to the idea of revisiting this. I initially wrote it when the Pyboard was the only platform. I recently adapted it for uasyncio V3. I checked it worked on ESP32, but only to verify compatibility; ~2Hz seems unreasonably slow.

I need to get a better handle on the issue of ESP32 performance, and how best to optimise applications.

I recently improved ESP32 support for my touch GUI for the official display - another uasyncio application. The difference in performance between ESP32 and Pyboard 1.1 is pronounced. In studying the ESP32 it's clear that it can suffer from high levels of latency responding to interrupts. But the GUI doesn't use interrupts (or serial ports). Just I2C and SPI, which work well on the ESP32. I'd been hoping for the same snappy response delivered by Pyboards.

In nano-gui I did a detailed study of the code which performs a display refresh. The performance of that critical fragment was close to that of a Pyboard. It seems that you can optimise critical routines effectively, yet overall application performance seems disproportionately poor. There have been issues raised regarding benchmarking MicroPython on ESP32. I gather it's difficult to get consistent results for reasons connected with its memory architecture.

I don't think the issues are to do with uasyncio as nano-gui is synchronous. The demo scripts make simple use of uasyncio to produce dynamic results. Some of these demos have been run on an ESP8266 with 18KB of RAM free, so an ESP32 will be wallowing in free RAM.

[dukeduck1984]

Thank you so much for detailed explanation, Peter!

I'm closing this issue and will move this to the forum for further discussion.

Thanks again!

Kaiyuan

[peterhinch]

I've been thinking about how to measure CPU hogging in an application and have come up with this.

It is undocumented but basically it runs a "do nothing" task and performs some measurements on how frequently the task gets scheduled and the max, min and average time between schedules. The code in lines 32-37 illustrates how it might be called: the idea is that your application, once started, issues this line. After that a report will be printed every 10s.

Interestingly, running it as presented, performance on an ESP32 is an order of magnitude worse than a Pyboard D. The maximum interval between calls was 368μs on a Pyboard D, and 8530μs on an ESP32. Average call frequency was 2800Hz vs 453Hz. I will do some tests tomorrow in a real application.

I'm still tied up optimising my graphics drivers, but you might like to see if it gives any insight into the GPS issue.

[romeocontrol]

Good morning from Germany! Max 3495us Min 2606us Avg 2659us No. of calls 3759 Freq 375 Max 4149us Min 2554us Avg 2634us No. of calls 3796 Freq 379 Max 3101us Min 2561us Avg 2619us No. of calls 3817 Freq 381 Max 3242us Min 2564us Avg 2623us No. of calls 3811 Freq 381 Max 3095us Min 2542us Avg 2600us No. of calls 3845 Freq 384 Max 3089us Min 2556us Avg 2614us No. of calls 3824 Freq 382 My MicroPython career started with the Wipy1. So of course ;-) I started your metrics.py on the Wipy3. The Walrus operator did not work. t = ticks_us() while ticks_diff(t, tstart) < 10_000_000: await asyncio.sleep(0) t = ticks_us() This resulted in the above data for me. They are even worse. And more worse with this code: while ticks_diff(t, tstart) < 10_000_000: t = ticks_us() await asyncio.sleep(0) Max 21624us Min 4318us Avg 4429us No. of calls 2257 Freq 225 Max 23115us Min 4317us Avg 4430us No. of calls 2257 Freq 225 Max 21753us Min 4304us Avg 4412us No. of calls 2266 Freq 226 Max 23080us Min 4298us Avg 4413us No. of calls 2266 Freq 226 Max 21943us Min 4325us Avg 4430us No. of calls 2256 Freq 225 Greetings Rainer Treichel

…

Am 21.12.2020 um 19:40 schrieb Peter Hinch ***@***.***>: I've been thinking about how to measure CPU hogging in an application and have come up with this <https://github.com/peterhinch/micropython-async/blob/master/v3/as_drivers/metrics/metrics.py>. It is undocumented but basically it runs a "do nothing" task and performs some measurements on how frequently the task gets scheduled and the max, min and average time between schedules. The code in lines 32-37 illustrates how it might be called: the idea is that your application, once started, issues this line <https://github.com/peterhinch/micropython-async/blob/0302d6d416b55f6ce7fba835d3e4126346d1dc6a/v3/as_drivers/metrics/metrics.py#L33>. After that a report will be printed every 10s. Interestingly, running it as presented, performance on an ESP32 is an order of magnitude worse than a Pyboard D. The maximum interval between calls was 368μs on a Pyboard D, and 8530μs on an ESP32. Average call frequency was 2800Hz vs 453Hz. I will do some tests tomorrow in a real application. I'm still tied up optimising my graphics drivers, but you might like to see if it gives any insight into the GPS issue. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#52 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AEI5EA4R3ITC2IBPWUKGGGTSV6JBDANCNFSM4U76FTVA>.

[peterhinch]

Hi Rainer,
thank you for testing. I raised this issue. With the GUI running the worst-case delay in scheduling the coroutine was 1.46s which is awful. The difference between a Pyboard 1.1 and an ESP32 is very visible indeed.

I will be interested to see if the ESP32 experts have a view on this.

[dukeduck1984]

I tested my ESP32 Wrover with external spiram, the result seemed to be slightly better...

Firmware 1.13 stable with spiram, IDF V4. CPU full power at 240MHz.

MicroPython v1.13 on 2020-09-02; ESP32 module (spiram) with ESP32
Type "help()" for more information.
>>> import uasyncio as asyncio
>>> import machine
>>> machine.freq(240000000)
I (44990) pm_esp32: Frequency switching config: CPU_MAX: 240, APB_MAX: 240, APB_MIN: 240, Light sleep: DISABLED
>>> from metrics import *
>>> asyncio.run(main())
Max 1658ￎﾼs Min 1590ￎﾼs Avg 1609ￎﾼs No. of calls 6214 Freq 621
mem free 4093328
Max 2511ￎﾼs Min 1568ￎﾼs Avg 1587ￎﾼs No. of calls 6298 Freq 629
mem free 4093344
Max 2938ￎﾼs Min 1617ￎﾼs Avg 1636ￎﾼs No. of calls 6112 Freq 611
mem free 4093360
Max 2560ￎﾼs Min 1616ￎﾼs Avg 1635ￎﾼs No. of calls 6115 Freq 611
mem free 4093344
Max 2510ￎﾼs Min 1617ￎﾼs Avg 1636ￎﾼs No. of calls 6112 Freq 611
mem free 4093360
Max 2555ￎﾼs Min 1616ￎﾼs Avg 1635ￎﾼs No. of calls 6115 Freq 611
mem free 4093344
Max 2538ￎﾼs Min 1617ￎﾼs Avg 1635ￎﾼs No. of calls 6112 Freq 611
mem free 4093360
Max 2539ￎﾼs Min 1616ￎﾼs Avg 1635ￎﾼs No. of calls 6115 Freq 611
mem free 4093344
Max 2544ￎﾼs Min 1617ￎﾼs Avg 1635ￎﾼs No. of calls 6112 Freq 611
mem free 4093360
Max 2563ￎﾼs Min 1616ￎﾼs Avg 1635ￎﾼs No. of calls 6115 Freq 611
mem free 4093344
Max 2525ￎﾼs Min 1617ￎﾼs Avg 1636ￎﾼs No. of calls 6112 Freq 611
mem free 4093360
Max 2537ￎﾼs Min 1616ￎﾼs Avg 1635ￎﾼs No. of calls 6115 Freq 611
mem free 4093344
Max 2528ￎﾼs Min 1617ￎﾼs Avg 1636ￎﾼs No. of calls 6112 Freq 611
mem free 4093360
Max 2539ￎﾼs Min 1616ￎﾼs Avg 1635ￎﾼs No. of calls 6115 Freq 611
mem free 4093344
Max 2545ￎﾼs Min 1617ￎﾼs Avg 1636ￎﾼs No. of calls 6112 Freq 611
mem free 4093360
Max 2579ￎﾼs Min 1616ￎﾼs Avg 1635ￎﾼs No. of calls 6115 Freq 611
mem free 4093360
Max 2510ￎﾼs Min 1617ￎﾼs Avg 1635ￎﾼs No. of calls 6113 Freq 611
mem free 4093328
Max 2530ￎﾼs Min 1616ￎﾼs Avg 1635ￎﾼs No. of calls 6115 Freq 611
mem free 4093328
Max 2553ￎﾼs Min 1616ￎﾼs Avg 1635ￎﾼs No. of calls 6114 Freq 611
mem free 4093328

[dukeduck1984]

I have a bad feeling about my another on-going ESP32 project in which the callback function is triggered by hardware interrupts, and the shortest interval between triggers is 20ms (at 50Hz). I haven't wired the hardware to actually test the sensor, but I'm really worried now...

[peterhinch]

As you probably know, ESPx interrupts are soft IRQ's. If an event happens when a GC is in progress, the ISR won't be triggered until the GC is complete. A GC on an ESP32 with SPIRAM can take 100ms. On an ESP32 without SPIRAM you can keep the latency down by regularly doing explicit gc.collect() calls. You should be able to keep it well below 20ms.

On the other hand I'm baffled by what my ESP32 was doing for up to 1.4s, so my understanding of ESP32 behaviour is evidently incomplete.

[dukeduck1984]

I compiled the firmware with IDF3 per @tve 's comments in that issue, and since I'm using the ESP32 Wrover module, I assumed it's fine to add CONFIG_SPIRAM_SPEED_80M=y in sdkconfig.board.

Below is the test result with the custom firmware, seemed better, but I'm not sure if the difference would mean anything...

Max 5833ￎﾼs Min 1364ￎﾼs Avg 1467ￎﾼs No. of calls 6816 Freq 681
mem free 4083920
Max 3693ￎﾼs Min 1379ￎﾼs Avg 1481ￎﾼs No. of calls 6750 Freq 675
mem free 4083936
Max 4221ￎﾼs Min 1381ￎﾼs Avg 1480ￎﾼs No. of calls 6752 Freq 675
mem free 4083936
Max 3663ￎﾼs Min 1392ￎﾼs Avg 1495ￎﾼs No. of calls 6686 Freq 668
mem free 4083968
Max 3985ￎﾼs Min 1381ￎﾼs Avg 1481ￎﾼs No. of calls 6748 Freq 674
mem free 4083936
Max 6244ￎﾼs Min 1395ￎﾼs Avg 1496ￎﾼs No. of calls 6683 Freq 668
mem free 4083952
Max 4086ￎﾼs Min 1375ￎﾼs Avg 1482ￎﾼs No. of calls 6744 Freq 674
mem free 4083936
Max 3773ￎﾼs Min 1387ￎﾼs Avg 1493ￎﾼs No. of calls 6697 Freq 669
mem free 4083952
Max 4919ￎﾼs Min 1376ￎﾼs Avg 1484ￎﾼs No. of calls 6735 Freq 673
mem free 4083952
Max 3724ￎﾼs Min 1391ￎﾼs Avg 1495ￎﾼs No. of calls 6687 Freq 668
mem free 4083936
Max 4017ￎﾼs Min 1375ￎﾼs Avg 1480ￎﾼs No. of calls 6753 Freq 675
mem free 4083904
Max 3862ￎﾼs Min 1395ￎﾼs Avg 1492ￎﾼs No. of calls 6698 Freq 669
mem free 4083968
Max 3652ￎﾼs Min 1380ￎﾼs Avg 1482ￎﾼs No. of calls 6747 Freq 674
mem free 4083936
Max 3925ￎﾼs Min 1394ￎﾼs Avg 1495ￎﾼs No. of calls 6685 Freq 668
mem free 4083968
Max 5657ￎﾼs Min 1381ￎﾼs Avg 1482ￎﾼs No. of calls 6745 Freq 674
mem free 4083952
Max 3806ￎﾼs Min 1389ￎﾼs Avg 1494ￎﾼs No. of calls 6692 Freq 669
mem free 4083968
Max 5032ￎﾼs Min 1370ￎﾼs Avg 1480ￎﾼs No. of calls 6755 Freq 675
mem free 4083952

[peterhinch]

One thing to bear in mind with SPIRAM boards is the time taken for a GC (garbage collect). I have measured 100ms with standard firmware. This may explain the fact that you need large recieve buffer on the UART. It might be instructive to try a non-SPIRAM build so that the board ignores the SPIRAM. This drastically reduces GC time and might improve application performance.

It would also be informative to run metrics as a task in your application. In metrics.py ensure the call to main() is commented out. In your application issue:

from metrics import metrics

and somewhere in your startup code issue

asyncio.create_task(metrics())

You may find a difference in the maximum time between calls, notably between SPIRAM and non-SPIRAM firmware.

[dukeduck1984]

Noted, thanks! I will try and report back.