Priorities not working?

[George-JL]

I am trying to test the ArduinoProcessScheduler and it seems to me that process priorities are not working properly. The TestSchedule.ino.txt code is expected to run three identical processes with the same period of one second and three different priorities.
The output
Process: 1 at 1000.492 ms runNo=1 Priority=0
Process: 2 at 1001.564 ms runNo=1 Priority=1
Process: 3 at 1002.844 ms runNo=1 Priority=2
Process: 1 at 2000.932 ms runNo=2 Priority=0
Process: 2 at 2002.004 ms runNo=2 Priority=1
Process: 3 at 2003.284 ms runNo=2 Priority=2
Process: 2 at 3000.352 ms runNo=3 Priority=1
Process: 3 at 3001.420 ms runNo=3 Priority=2
Process: 1 at 3002.708 ms runNo=3 Priority=0
Process: 3 at 4000.800 ms runNo=4 Priority=2
Process: 1 at 4001.864 ms runNo=4 Priority=0
Process: 2 at 4003.152 ms runNo=4 Priority=1
Process: 1 at 5000.216 ms runNo=5 Priority=0
Process: 2 at 5001.348 ms runNo=5 Priority=1
Process: 3 at 5002.628 ms runNo=5 Priority=2
is rather unexpected. I believe the processes should always run in the same order.

Where is the problem?
What am I doing wrong?
Is it an interference with the Serial output delays?
Or did I miss something with the non-preemptive multitasking?

Thanks for response.

[wizard97]

This was actually intentional to prevent resource starvation for new users to the library. If somewhen made a high priority service constantly process, it will prevent all the lower ones from ever running.

In the current 1.0 branch, priorities only determine how often the process is given an opportunity to run, it gives no guarantee about the order.

However, I'm starting to change my mind about this decision. In fact, I just made a strict-priorities branch, that should implement what you are asking. It is completely untested, as I am away from home. Please test it and let me know.

[George-JL]

@wizard97:
I made some basic tests of your strict-priorities branch. Unfortunately, it didn't change anything in Scheduler behaviour, except it ignores iterations argument.
I made another experiment (with the master 1.0 branch): When I added resetTimeStamps() call at the end of the service() method, the Scheduler started to keep the expected order.
I also suspect a bug:

  myProc1.add(true);    //  myProc1(sched, HIGH_PRIORITY,   1000, 10);
  myProc2.add(true);    //  myProc2(sched, MEDIUM_PRIORITY, 1000, 10);
  myProc3.add(true);    //  myProc3(sched, LOW_PRIORITY,    1000, 10);

which works fine.
When I comment out the MEDIUM_PRIORITY process, the Scheduler produces chaotic order of processes.

[wizard97]

Thanks for your testing!

I think I found the issues in the strict-priorities branch that you were experiencing, it was basically just a couple of lines in the wrong place.

If you don't mind could you give it another shot and let me know?

[wizard97]

Any luck? I am interested in merging this into the dev branch

[George-JL]

Aaron, I am sorry, but I am out for a long term travel having limited access to Internet and no access to my development/testing equipment. I'll be back at mid of August. George

[wizard97]

Thanks, just wanted to check in. It would be awesome if you could test this on the same program when you get back so I can close this issue.

Aaron

[George-JL]

Aaron,

back at my test site. The strict-priorities branch seems to work properly. Its only issue, I have detected, is that the Process parameter iterations is still ignored and the processes run forever.

George

[George-JL]

Sorry, I had a typo in my test prog. iterations also work fine!

[wizard97]

Awesome, glad to here! Thanks for the testing. Would you be willing to include your test program as an example? Might be helpful to others to understand how everything works.

[George-JL]

Here is my test program ProcessPrioritiesTest.ino.txt
I still discovered a strange behavior: When I comment out the return statement on line 65, I get a garbage.

[George-JL]

This tester gives better output: ProcessPrioritiesTest.ino.txt

[wizard97]

So if line 69 is commented out, you get garbage?

[George-JL]

Yes.
If I try to "Serial.print()" from onEnable() callback, the whole scheduling procedure breaks down. I suspect some timing interaction with the serial line.
Tested on Adruino Nano v3 clone with CH340 serial chip.

[wizard97]

Thanks for this awesome bug find, it turned out to be a weird race condition that in some cases would cause a uint32_t to overflow in the reverse direction depending on how slow you were to start calling run.

It has been fixed and priorities and timing appear to be working properly:

Process 1 enabled with priority HIGH  
Process 2 enabled with priority MEDIUM
Process 3 enabled with priority LOW   
Process 1: priority HIGH   at   200.744 ms | getCurrTS()=  200 ms | runNo=1  | getIterations()=10 | getActualRunTS()=200   | getScheduledTS()=200   | timeToNextRun()=192 
Process 2: priority MEDIUM at   209.924 ms | getCurrTS()=  214 ms | runNo=1  | getIterations()=10 | getActualRunTS()=208   | getScheduledTS()=200   | timeToNextRun()=177 
Process 3: priority LOW    at   224.552 ms | getCurrTS()=  228 ms | runNo=1  | getIterations()=12 | getActualRunTS()=224   | getScheduledTS()=202   | timeToNextRun()=164 
=======================
Process 1: priority HIGH   at   400.432 ms | getCurrTS()=  400 ms | runNo=2  | getIterations()=9  | getActualRunTS()=400   | getScheduledTS()=400   | timeToNextRun()=192 
Process 2: priority MEDIUM at   409.612 ms | getCurrTS()=  413 ms | runNo=2  | getIterations()=9  | getActualRunTS()=408   | getScheduledTS()=400   | timeToNextRun()=178 
Process 3: priority LOW    at   424.236 ms | getCurrTS()=  428 ms | runNo=2  | getIterations()=11 | getActualRunTS()=423   | getScheduledTS()=402   | timeToNextRun()=164 
=======================
Process 1: priority HIGH   at   600.116 ms | getCurrTS()=  600 ms | runNo=3  | getIterations()=8  | getActualRunTS()=600   | getScheduledTS()=600   | timeToNextRun()=192 
Process 2: priority MEDIUM at   609.296 ms | getCurrTS()=  613 ms | runNo=3  | getIterations()=8  | getActualRunTS()=609   | getScheduledTS()=600   | timeToNextRun()=178 
Process 3: priority LOW    at   623.920 ms | getCurrTS()=  627 ms | runNo=3  | getIterations()=10 | getActualRunTS()=623   | getScheduledTS()=602   | timeToNextRun()=165 
=======================
Process 1: priority HIGH   at   800.808 ms | getCurrTS()=  800 ms | runNo=4  | getIterations()=7  | getActualRunTS()=800   | getScheduledTS()=800   | timeToNextRun()=192 
Process 2: priority MEDIUM at   809.992 ms | getCurrTS()=  814 ms | runNo=4  | getIterations()=7  | getActualRunTS()=808   | getScheduledTS()=800   | timeToNextRun()=177 
Process 3: priority LOW    at   824.616 ms | getCurrTS()=  828 ms | runNo=4  | getIterations()=9  | getActualRunTS()=824   | getScheduledTS()=802   | timeToNextRun()=164 
=======================
Process 1: priority HIGH   at  1000.496 ms | getCurrTS()= 1000 ms | runNo=5  | getIterations()=6  | getActualRunTS()=1000  | getScheduledTS()=1000  | timeToNextRun()=192 
Process 2: priority MEDIUM at  1009.676 ms | getCurrTS()= 1013 ms | runNo=5  | getIterations()=6  | getActualRunTS()=1008  | getScheduledTS()=1000  | timeToNextRun()=178 
Process 3: priority LOW    at  1024.300 ms | getCurrTS()= 1028 ms | runNo=5  | getIterations()=8  | getActualRunTS()=1024  | getScheduledTS()=1002  | timeToNextRun()=164 
=======================
Process 1: priority HIGH   at  1200.180 ms | getCurrTS()= 1200 ms | runNo=6  | getIterations()=5  | getActualRunTS()=1200  | getScheduledTS()=1200  | timeToNextRun()=192 
Process 2: priority MEDIUM at  1209.360 ms | getCurrTS()= 1213 ms | runNo=6  | getIterations()=5  | getActualRunTS()=1209  | getScheduledTS()=1200  | timeToNextRun()=178 
Process 3: priority LOW    at  1223.988 ms | getCurrTS()= 1227 ms | runNo=6  | getIterations()=7  | getActualRunTS()=1223  | getScheduledTS()=1202  | timeToNextRun()=164 
=======================
Process 1: priority HIGH   at  1400.876 ms | getCurrTS()= 1400 ms | runNo=7  | getIterations()=4  | getActualRunTS()=1400  | getScheduledTS()=1400  | timeToNextRun()=191 
Process 2: priority MEDIUM at  1410.056 ms | getCurrTS()= 1414 ms | runNo=7  | getIterations()=4  | getActualRunTS()=1409  | getScheduledTS()=1400  | timeToNextRun()=177 
Process 3: priority LOW    at  1424.680 ms | getCurrTS()= 1428 ms | runNo=7  | getIterations()=6  | getActualRunTS()=1424  | getScheduledTS()=1402  | timeToNextRun()=164 
=======================
Process 1: priority HIGH   at  1600.560 ms | getCurrTS()= 1600 ms | runNo=8  | getIterations()=3  | getActualRunTS()=1600  | getScheduledTS()=1600  | timeToNextRun()=192 
Process 2: priority MEDIUM at  1609.740 ms | getCurrTS()= 1613 ms | runNo=8  | getIterations()=3  | getActualRunTS()=1609  | getScheduledTS()=1600  | timeToNextRun()=177 
Process 3: priority LOW    at  1624.368 ms | getCurrTS()= 1628 ms | runNo=8  | getIterations()=5  | getActualRunTS()=1624  | getScheduledTS()=1602  | timeToNextRun()=164 
=======================
Process 1: priority HIGH   at  1800.244 ms | getCurrTS()= 1800 ms | runNo=9  | getIterations()=2  | getActualRunTS()=1800  | getScheduledTS()=1800  | timeToNextRun()=192 
Process 2: priority MEDIUM at  1809.424 ms | getCurrTS()= 1813 ms | runNo=9  | getIterations()=2  | getActualRunTS()=1809  | getScheduledTS()=1800  | timeToNextRun()=178 
Process 3: priority LOW    at  1824.052 ms | getCurrTS()= 1827 ms | runNo=9  | getIterations()=4  | getActualRunTS()=1823  | getScheduledTS()=1802  | timeToNextRun()=164 
=======================
Process 1: priority HIGH   at  2000.940 ms | getCurrTS()= 2000 ms | runNo=10 | getIterations()=1  | getActualRunTS()=2000  | getScheduledTS()=2000  | timeToNextRun()=191 
Process 1 disabled
Process 2: priority MEDIUM at  2011.808 ms | getCurrTS()= 2016 ms | runNo=10 | getIterations()=1  | getActualRunTS()=2011  | getScheduledTS()=2000  | timeToNextRun()=175 
Process 2 disabled
Process 3: priority LOW    at  2028.136 ms | getCurrTS()= 2032 ms | runNo=10 | getIterations()=3  | getActualRunTS()=2027  | getScheduledTS()=2002  | timeToNextRun()=161 
=======================
Process 3: priority LOW    at  2202.696 ms | getCurrTS()= 2202 ms | runNo=11 | getIterations()=2  | getActualRunTS()=2202  | getScheduledTS()=2202  | timeToNextRun()=192 
=======================
Process 3: priority LOW    at  2402.380 ms | getCurrTS()= 2402 ms | runNo=12 | getIterations()=1  | getActualRunTS()=2402  | getScheduledTS()=2402  | timeToNextRun()=192 
=======================
Process 3 disabled

Thanks so much!

[George-JL]

Yes.
If I try to "Serial.print()" from onEnable

[George-JL]

Everything works fine after your most recent patch.
Yet another issue: #define _MICROS_PRECISION causes chaotic behavior even when period is multiplied by 1000. Changing wrong type of getPeriod() [Process.h line 71] to uint32_t didn't help.