Timer.Alarm does not immediately update free timer count after alarm.callback(None)

[rkeiii]

Please include the following information when submitting a bug report:

• The Pycom board you are using: WiPy 2.0
• The firmware version you are using: custom build of 1.11.0.b1

Version Information:  (sysname='WiPy', nodename='WiPy', release='1.11.0.b1', version='68057a7 on 2017-12-22', machine='WiPy with ESP32')

• Exact steps to cause this issue
  1. Create 16 Timer.Alarm objects
  2. Call alarm.callback(None) on several of them in rapid succession
• What you expected
  • I expected to no longer receive "MemoryError: maximum number of 16 alarms already reached" after calling alarm.callback(None) on a Timer.Alarm object
• What happened instead
  • I received "MemoryError: maximum number of 16 alarms already reached" for some number of seconds before the Timer.Alarm code finally realized there were some free timers.

Here's the "timer code" that I'm using the instantiate the Timer.Alarm's and also to free them with alarm.callback(None).

import config
import util
import _thread
import time
import msg
import gc

from machine import Timer
from exception import TimersSoftLimitException, TimersHardLimitException
from uasyncio.queues import Queue
from uasyncio.queues import QueueEmpty

# TODO: This looks like insanity because it is.
# The first time you load datetime it errors with
# AttributeError: type object 'tzinfo' has no attribute '__new__'
# Upon the second load it load fine!?
try:
    from datetime import datetime
except AttributeError:
    pass
from datetime import datetime

timers = []
timers_lock = _thread.allocate_lock()
task_queue = Queue(maxsize=config.queued_tasks_limit)

class BaseTimer:
    """Base timer class"""

    def __init__(self, wakeup_callback, sleep_us, is_periodic):
        try:
            with timers_lock:
                if len(timers) < config.timers_hard_limit:
                    gc.collect()
                    self._alarm = Timer.Alarm(wakeup_callback, ms=sleep_us, arg=None, periodic=is_periodic)
                    timers.append(self)
                    print("timers in use:", len(timers))
                else:
                   raise TimersHardLimitException()
        except MemoryError as e:
            print("Probably spurious MemoryError suppressed: ", e)


class EtaTaskCallTimer(BaseTimer):
    """Timer to supprt ETA type Celery Task calls"""

    def __init__(self, task):
        # calculate how to long to sleep based on Task ETA
        now = datetime(*config.rtc.now())
        tdiff = task.eta - now
        # TODO: No day handling. This is fucked just as soon as we try to time something longer than "minutes" wtf that means
        sleep_us = (tdiff.seconds * 1000) + (tdiff.microseconds / 1000)

        super().__init__(self._wakeup_callback, int(sleep_us), False)
        self._task = task

    def _wakeup_callback(self, arg):
        try:
            config.relays[self._task.args[0]].toggle()
            print(config.rtc.now(), " task", self._task.id, "completed successfully with", datetime(*config.rtc.now()) - self._task.eta, "deviation")
            config.mqtt_client.publish(config.celery_event_exchange, msg.task_succeeded(self._task, "succeeded", 0, config.hostname, config.rtc.now(), 0))
        finally:
            with timers_lock:
                timers.remove(self)
                self._alarm.callback(None) # free up the timer we were using

Here's an example run of my code. You can see from the logging my code has it's own list it uses to track active timers which does not match up with how many the Timer.Alarm code things are free.

W.E. Grow Micro Bot
===================
Starting up...
Version Information:  (sysname='WiPy', nodename='WiPy', release='1.11.0.b1', version='68057a7 on 2017-12-22', machine='WiPy with ESP32')
Current Date/Time:  (2017, 12, 22, 23, 24, 47, 471086, None)
Startup complete, resuming normal operations
===================
timers in use: 1
timers in use: 2
timers in use: 3
MicroPython 68057a7 on 2017-12-22; WiPy with ESP32
Type "help()" for more information.
>>> timers in use: 4
timers in use: 5
timers in use: 6
timers in use: 7
timers in use: 8
timers in use: 9
timers in use: 10
timers in use: 11
timers in use: 12
timers in use: 13
timers in use: 14
timers in use: 15
timers in use: 16
(2017, 12, 22, 23, 25, 50, 823658, None)  task 2a717a65-b64f-42b5-b944-89fc1261140a completed successfully with 0:00:00.012638 deviation
(2017, 12, 22, 23, 25, 50, 923616, None)  task f39f84ca-f90b-4a5b-82c3-37d256bace13 completed successfully with 0:00:00.012600 deviation
(2017, 12, 22, 23, 25, 51, 23605, None)  task fcd1c82c-5462-43f7-ae75-7f0206aba915 completed successfully with 0:00:00.012592 deviation
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
(2017, 12, 22, 23, 25, 51, 122636, None)  task b84b356f-baf3-4c8b-9505-67f00d51db28 completed successfully with 0:00:00.011618 deviation
(2017, 12, 22, 23, 25, 51, 221641, None)  task 307077f2-db80-4507-bbd4-25770c627730 completed successfully with 0:00:00.010621 deviation
(2017, 12, 22, 23, 25, 51, 323616, None)  task 356e8e82-b07d-4295-8e06-f533e1878ad3 completed successfully with 0:00:00.012600 deviation
(2017, 12, 22, 23, 25, 51, 423619, None)  task 279f8a1b-10c7-4545-84a8-41e3792033ac completed successfully with 0:00:00.012604 deviation
(2017, 12, 22, 23, 25, 51, 523605, None)  task 42299c79-20d6-4c63-9393-9b9249c3b7d9 completed successfully with 0:00:00.012591 deviation
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
(2017, 12, 22, 23, 25, 51, 623582, None)  task 334ab03b-7731-4a4b-8db1-5d6b15688deb completed successfully with 0:00:00.012561 deviation
(2017, 12, 22, 23, 25, 51, 722607, None)  task 64ea8c44-ad27-4cb5-8a9b-9c2d0b832e3b completed successfully with 0:00:00.011589 deviation
(2017, 12, 22, 23, 25, 51, 823605, None)  task 1247ba21-33b9-45d4-8f47-bc5663c6cbc5 completed successfully with 0:00:00.012599 deviation
(2017, 12, 22, 23, 25, 51, 924054, None)  task f28c4eb9-c3cc-4517-8154-d5019926e423 completed successfully with 0:00:00.013063 deviation
(2017, 12, 22, 23, 25, 52, 22600, None)  task 92e121de-21ba-4fb0-99e9-fbb3d6bd95c0 completed successfully with 0:00:00.011621 deviation
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
timers in use: 4
timers in use: 5
timers in use: 6
timers in use: 7
timers in use: 8
timers in use: 9
timers in use: 10
timers in use: 11
timers in use: 12
timers in use: 13
timers in use: 14
timers in use: 15
timers in use: 16
task queue is full
task queue is full
task queue is full
task queue is full
task queue is full
task queue is full
task queue is full
(2017, 12, 22, 23, 26, 41, 954684, None)  task 69ed9f27-f298-4994-9729-88fb57c794f4 completed successfully with 0:00:00.011692 deviation
(2017, 12, 22, 23, 26, 42, 51625, None)  task 794a92f8-971e-40d9-b9b0-39be88d95dc8 completed successfully with 0:00:00.008654 deviation
task queue is full
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
(2017, 12, 22, 23, 26, 42, 155579, None)  task 25c187c7-043e-4830-9e67-7696d8f866cb completed successfully with 0:00:00.012586 deviation
(2017, 12, 22, 23, 26, 42, 251659, None)  task 69410e47-ebc6-43e4-9aeb-c99d7b20465c completed successfully with 0:00:00.008680 deviation
(2017, 12, 22, 23, 26, 42, 352638, None)  task aa04e34f-5ce5-4ea5-bc0a-6004a64341e2 completed successfully with 0:00:00.009678 deviation
(2017, 12, 22, 23, 26, 42, 455621, None)  task 97d3f8d4-c6a7-4fb8-a8f3-5763bc8b25e7 completed successfully with 0:00:00.012633 deviation
(2017, 12, 22, 23, 26, 42, 552617, None)  task 0443d8a1-006b-4640-8066-2f14a1d2f392 completed successfully with 0:00:00.009632 deviation
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
(2017, 12, 22, 23, 26, 42, 655610, None)  task 0ed33b33-e4ab-420f-aa05-4b1fd845a99e completed successfully with 0:00:00.012632 deviation
(2017, 12, 22, 23, 26, 42, 756610, None)  task 653c2e0a-918e-4841-a368-93ffe83ceaff completed successfully with 0:00:00.013637 deviation
(2017, 12, 22, 23, 26, 42, 855612, None)  task 90f58dec-6c55-4793-bb71-784987894d0d completed successfully with 0:00:00.012647 deviation
(2017, 12, 22, 23, 26, 42, 955627, None)  task 0f41de6c-16dc-4d26-80fa-ef16d2c3ac52 completed successfully with 0:00:00.012674 deviation
(2017, 12, 22, 23, 26, 43, 52599, None)  task 6218b69f-3a67-4204-bf26-e4a1229540e0 completed successfully with 0:00:00.009660 deviation
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
(2017, 12, 22, 23, 26, 43, 152563, None)  task 3f881c96-4012-4fc4-b876-8b49ca15a308 completed successfully with 0:00:00.009580 deviation
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
Probably spurious MemoryError suppressed:  maximum number of 16 alarms already reached
...........................................

[rkeiii]

I realized after doing some more testing with a friend that I needed to be calling Timer.Alarm.cancel() instead of Timer.Alarm.callback(None).

This page in the documentation seems unclear about how to properly disregard a Timer you're no longer interested in. Am I missing something?

Could I submit a documentation patch somehow?

[rkeiii]

Sorry, here's the docs page I was talking about: https://docs.pycom.io/chapter/tutorials/all/timers.html

[robert-hh]

@rkeiii That's right. It used to be, that Timer.Alarm.callback(None) would remove the alarm. But now it just re-enables the alarm. The section of interest is int mods/machtimer_alarm.c, line 237. replacing line 238 by

alarm_delete(self_in); // that is the function serving alarm.cancel()
return;

could do the trick. Or the documentation can be updated.

[rkeiii]

@robert-hh I'm quite new to Micropython as a whole so I'd be open to suggestion on whichever approach would be better. My gut tells me completely cancelling the Timer.Alarm as a result of calling Timer.Alarm.callback(None) might be somewhat non-intuitive behavior. What if I want to re-use the Timer.Alarm with a new callback? So I think I would probably lean toward improving the documentation but like I say I'm no authority on the matter.

Would you happen to know if it's possible/where to submit a documentation patch?

[robert-hh]

@rkeiii Since the timer has only the noticeable reaction of calling a callback, Timer.Alarm.callback(None) is practically the same as Timer.Alarm.cancel(). There is not need to let the timer running if there is nothing to do.
The place for the documentation is here: https://github.com/pycom/pycom-documentation
You could place a Pull-request there or an issue, although Pycom is not very active in dealing with pull requests. They typically take what's suggested there and copy it into their private repository. Maybe they it's because git is not a very user-friendly tool.

[danicampora]

Hello,

Thanks for reporting this. Timer.Alarm.callback(None) should cancel the alarm as well. The documentation is correct, there's a bug in the code.

Cheers,
Daniel

[danicampora]

The fix is actually to change line 259 of machtimer_alarm.c to:

    } else if (self->handler != mp_const_none) {

This is done in master now. Will be available with the next release.

[rkeiii]

@danicampora Thank you for the fix.