Memory consumptions increases after some time
-
I wrote some code to monitor the resources used by my program. I saw some strange thing I wrote a small example to show the phenomena.
Running WiPy 3 (and W01) on latest stable firmware (1.18.0).
First everything looks fine, memory usage is slowly increasing until the garbage collector kicks in. After approximately 20 minutes memory consumption starts to increase much faster, from less than 4% (of total memory) per 10 seconds, to more than 25% per 10 seconds. Also more time spends on “Do work A” and “Do work B”. Is this expected?
Johan
import utime import machine import gc TimeA = 0 TimeB = 0 TimeSleep = 0 TimeStart = utime.ticks_cpu() TimeStartIteration = utime.ticks_cpu() Iterations = 0 while(True): Iterations = Iterations + 1 TimeStartA = utime.ticks_cpu() #Do work A if [0,0,0] != [0,0,0]: machine.idle() TimeA = TimeA + utime.ticks_cpu() - TimeStartA TimeStartB = utime.ticks_cpu() #Do work B while len([]) > 0: machine.idle() TimeB = TimeB + utime.ticks_cpu() - TimeStartB TimeToSleep = TimeStartIteration + 10000 - utime.ticks_cpu() TimeStartSleep = utime.ticks_cpu() if TimeToSleep > 0: utime.sleep_us(TimeToSleep) TimeSleep = TimeSleep + utime.ticks_cpu() - TimeStartSleep TimeStartIteration = utime.ticks_cpu() if utime.ticks_cpu() - TimeStart > 10000000: Total = TimeA + TimeB + TimeSleep print("Iterations: " + str(Iterations) + " A%: " + str(100 * TimeA / Total) + " B%: " + str(100 * TimeB / Total) + " Sleep%: " + str(100 * TimeSleep / Total) + " Mem%: " + str(100 * gc.mem_alloc() / (gc.mem_alloc() + gc.mem_free()))) Iterations = 0 TimeA = 0 TimeB = 0 TimeSleep = 0 TimeStart = utime.ticks_cpu()Output from example:
Iterations: 1000 A%: 0.4268612 B%: 0.5559645 Sleep%: 99.01717 Mem%: 3.921066
Iterations: 1001 A%: 0.4354027 B%: 0.671601 Sleep%: 98.89299 Mem%: 7.705955
Iterations: 1002 A%: 0.4229757 B%: 0.6348732 Sleep%: 98.94216 Mem%: 11.49459
Iterations: 1002 A%: 0.4356846 B%: 0.659466 Sleep%: 98.90485 Mem%: 15.28323
Iterations: 1002 A%: 0.4235979 B%: 0.5002282 Sleep%: 99.07619 Mem%: 19.07186
Iterations: 1002 A%: 0.4343731 B%: 0.6243152 Sleep%: 98.94131 Mem%: 22.8605
Iterations: 1001 A%: 0.4211722 B%: 0.5028228 Sleep%: 99.076 Mem%: 26.64539
Iterations: 1002 A%: 0.442259 B%: 0.6153745 Sleep%: 98.94237 Mem%: 30.43402
Iterations: 1001 A%: 0.4532487 B%: 0.6818373 Sleep%: 98.86492 Mem%: 34.21891
Iterations: 1002 A%: 0.4649492 B%: 0.5036765 Sleep%: 99.03137 Mem%: 38.00755
Iterations: 1002 A%: 0.4595881 B%: 0.6802377 Sleep%: 98.86017 Mem%: 41.79618
Iterations: 1001 A%: 0.4609941 B%: 0.6802779 Sleep%: 98.85874 Mem%: 45.58107
Iterations: 1001 A%: 0.4618564 B%: 0.5005609 Sleep%: 99.03758 Mem%: 49.36596
Iterations: 1001 A%: 0.4622408 B%: 0.5007946 Sleep%: 99.03697 Mem%: 53.15084
Iterations: 1002 A%: 0.460346 B%: 0.5034671 Sleep%: 99.03619 Mem%: 56.93948
Iterations: 1002 A%: 0.4665888 B%: 0.5017617 Sleep%: 99.03165 Mem%: 60.72812
Iterations: 1001 A%: 0.4593462 B%: 0.682362 Sleep%: 98.85829 Mem%: 64.51301
Iterations: 1001 A%: 0.4599463 B%: 0.6766708 Sleep%: 98.86339 Mem%: 68.2979
Iterations: 1001 A%: 0.4607622 B%: 0.5017198 Sleep%: 99.03752 Mem%: 72.08278
Iterations: 1002 A%: 0.4607821 B%: 0.6863434 Sleep%: 98.85287 Mem%: 75.87142
Iterations: 1001 A%: 0.4541265 B%: 0.6801013 Sleep%: 98.86578 Mem%: 79.65631
Iterations: 1001 A%: 0.4665302 B%: 0.5036448 Sleep%: 99.02983 Mem%: 83.44119
Iterations: 1002 A%: 0.4598397 B%: 0.6861994 Sleep%: 98.85396 Mem%: 87.22983
Iterations: 1002 A%: 0.4597982 B%: 0.6849636 Sleep%: 98.85524 Mem%: 91.01847
Iterations: 1001 A%: 0.4630634 B%: 0.499958 Sleep%: 99.03698 Mem%: 94.80335
Iterations: 1001 A%: 0.4630154 B%: 0.6812444 Sleep%: 98.85573 Mem%: 98.58825
Iterations: 995 A%: 1.172224 B%: 0.549645 Sleep%: 98.27813 Mem%: 2.49619
Iterations: 1002 A%: 0.4391395 B%: 0.6772727 Sleep%: 98.88359 Mem%: 6.284825
Iterations: 1002 A%: 0.447359 B%: 0.6563093 Sleep%: 98.89633 Mem%: 10.07346
Iterations: 1002 A%: 0.4351855 B%: 0.6787983 Sleep%: 98.88602 Mem%: 13.8621
Iterations: 1001 A%: 0.456946 B%: 0.4873504 Sleep%: 99.0557 Mem%: 17.64699
Iterations: 1002 A%: 0.4349287 B%: 0.6762905 Sleep%: 98.88878 Mem%: 21.43562
Iterations: 1001 A%: 0.4468958 B%: 0.6674683 Sleep%: 98.88564 Mem%: 25.22051
Iterations: 1001 A%: 0.4374196 B%: 0.6114847 Sleep%: 98.9511 Mem%: 29.0054
Iterations: 1002 A%: 0.4625351 B%: 0.6849326 Sleep%: 98.85253 Mem%: 32.79403
Iterations: 1001 A%: 0.4613871 B%: 0.5032744 Sleep%: 99.03534 Mem%: 36.57892
Iterations: 1002 A%: 0.4624583 B%: 0.6797733 Sleep%: 98.85777 Mem%: 40.36756
Iterations: 1001 A%: 0.4642513 B%: 0.4965862 Sleep%: 99.03916 Mem%: 44.15245
Iterations: 1001 A%: 0.4595655 B%: 0.6827622 Sleep%: 98.85768 Mem%: 47.93733
Iterations: 1002 A%: 0.4581546 B%: 0.5018201 Sleep%: 99.04002 Mem%: 51.72597
Iterations: 1001 A%: 0.4592986 B%: 0.6379637 Sleep%: 98.90274 Mem%: 55.51086
Iterations: 1001 A%: 0.4593429 B%: 0.5041218 Sleep%: 99.03654 Mem%: 59.29574
Iterations: 1002 A%: 0.4635245 B%: 0.6309409 Sleep%: 98.90553 Mem%: 63.08438
Iterations: 1001 A%: 0.4535498 B%: 0.6787199 Sleep%: 98.86773 Mem%: 66.86927
Iterations: 1002 A%: 0.4617514 B%: 0.6710783 Sleep%: 98.86718 Mem%: 70.65791
Iterations: 1001 A%: 0.46189 B%: 0.4980686 Sleep%: 99.04005 Mem%: 74.4428
Iterations: 1002 A%: 0.4661546 B%: 0.5024181 Sleep%: 99.03143 Mem%: 78.23143
Iterations: 1001 A%: 0.4594512 B%: 0.6777713 Sleep%: 98.86278 Mem%: 82.01632
Iterations: 1002 A%: 0.4664502 B%: 0.5080239 Sleep%: 99.02553 Mem%: 85.80496
Iterations: 1002 A%: 0.4623048 B%: 0.5098886 Sleep%: 99.02781 Mem%: 89.59359
Iterations: 1001 A%: 0.4635204 B%: 0.5039531 Sleep%: 99.03254 Mem%: 93.37848
Iterations: 1002 A%: 0.4562716 B%: 0.6786108 Sleep%: 98.86512 Mem%: 97.16712
Iterations: 995 A%: 1.183154 B%: 0.6716971 Sleep%: 98.14515 Mem%: 1.078184
Iterations: 1002 A%: 0.4370455 B%: 0.6704541 Sleep%: 98.89251 Mem%: 4.86682
Iterations: 1002 A%: 0.4544007 B%: 0.4852212 Sleep%: 99.06038 Mem%: 8.655456
Iterations: 1001 A%: 0.441255 B%: 0.5002399 Sleep%: 99.05851 Mem%: 12.44034
Iterations: 1001 A%: 0.4487531 B%: 0.6603787 Sleep%: 98.89087 Mem%: 16.22523
Iterations: 1002 A%: 0.4411409 B%: 0.6817798 Sleep%: 98.87709 Mem%: 20.01387
Iterations: 1002 A%: 0.4495594 B%: 0.4871961 Sleep%: 99.06324 Mem%: 23.8025
Iterations: 1001 A%: 0.4382364 B%: 0.6668084 Sleep%: 98.89495 Mem%: 27.58739
Iterations: 1002 A%: 0.4582736 B%: 0.4933847 Sleep%: 99.04834 Mem%: 31.37603
Iterations: 1001 A%: 0.4604439 B%: 0.6834167 Sleep%: 98.85614 Mem%: 35.16092
Iterations: 1001 A%: 0.4601249 B%: 0.5022945 Sleep%: 99.03758 Mem%: 38.94581
Iterations: 1002 A%: 0.4618449 B%: 0.6857985 Sleep%: 98.85236 Mem%: 42.73444
Iterations: 1002 A%: 0.4607586 B%: 0.6753018 Sleep%: 98.86394 Mem%: 46.52308
Iterations: 1001 A%: 0.4641504 B%: 0.5756869 Sleep%: 98.96016 Mem%: 50.30797
Iterations: 1002 A%: 0.4576754 B%: 0.5061383 Sleep%: 99.03619 Mem%: 54.0966
Iterations: 1001 A%: 0.4620677 B%: 0.6890267 Sleep%: 98.84891 Mem%: 57.88149
Iterations: 1001 A%: 0.4608346 B%: 0.4971122 Sleep%: 99.04205 Mem%: 61.66637
Iterations: 1002 A%: 0.4607254 B%: 0.6822025 Sleep%: 98.85707 Mem%: 65.45501
Iterations: 1002 A%: 0.4578527 B%: 0.6797138 Sleep%: 98.86244 Mem%: 69.24365
Iterations: 1002 A%: 0.4675521 B%: 0.5086909 Sleep%: 99.02376 Mem%: 73.03228
Iterations: 1001 A%: 0.4587769 B%: 0.6055673 Sleep%: 98.93565 Mem%: 76.81717
Iterations: 1001 A%: 0.4623471 B%: 0.6836704 Sleep%: 98.85399 Mem%: 80.60206
Iterations: 1001 A%: 0.4660496 B%: 0.5016578 Sleep%: 99.03229 Mem%: 84.38695
Iterations: 1001 A%: 0.4644586 B%: 0.5009272 Sleep%: 99.03461 Mem%: 88.17183
Iterations: 1002 A%: 0.4596296 B%: 0.5014362 Sleep%: 99.03893 Mem%: 91.96048
Iterations: 1001 A%: 0.4568774 B%: 0.6786588 Sleep%: 98.86447 Mem%: 95.74536
Iterations: 1001 A%: 0.4608125 B%: 0.6850336 Sleep%: 98.85416 Mem%: 99.53025
Iterations: 995 A%: 0.4409168 B%: 1.349475 Sleep%: 98.20961 Mem%: 3.439444
Iterations: 1001 A%: 0.422402 B%: 0.6760397 Sleep%: 98.90156 Mem%: 7.224332
Iterations: 1001 A%: 0.4385731 B%: 0.4868137 Sleep%: 99.07462 Mem%: 11.00922
Iterations: 1001 A%: 0.4192822 B%: 0.6722896 Sleep%: 98.90842 Mem%: 14.79411
Iterations: 1001 A%: 0.4429562 B%: 0.4857871 Sleep%: 99.07125 Mem%: 18.579
Iterations: 1001 A%: 0.4244375 B%: 0.5012155 Sleep%: 99.07435 Mem%: 22.36388
Iterations: 1001 A%: 0.4326176 B%: 0.489068 Sleep%: 99.07832 Mem%: 26.14877
Iterations: 1001 A%: 0.4275609 B%: 0.6737838 Sleep%: 98.89866 Mem%: 29.93366
Iterations: 1002 A%: 0.464468 B%: 0.5050519 Sleep%: 99.03049 Mem%: 33.7223
Iterations: 1001 A%: 0.4595566 B%: 0.61113 Sleep%: 98.92932 Mem%: 37.50718
Iterations: 1002 A%: 0.4633672 B%: 0.562344 Sleep%: 98.97429 Mem%: 41.29582
Iterations: 1001 A%: 0.4608629 B%: 0.6827141 Sleep%: 98.85642 Mem%: 45.08071
Iterations: 1001 A%: 0.4647478 B%: 0.5016531 Sleep%: 99.03359 Mem%: 48.8656
Iterations: 1001 A%: 0.4613954 B%: 0.498632 Sleep%: 99.03997 Mem%: 52.65049
Iterations: 1001 A%: 0.4650342 B%: 0.5081857 Sleep%: 99.02678 Mem%: 56.43537
Iterations: 1002 A%: 0.4630762 B%: 0.5006837 Sleep%: 99.03625 Mem%: 60.22401
Iterations: 1002 A%: 0.4652658 B%: 0.5032251 Sleep%: 99.03152 Mem%: 64.01264
Iterations: 1001 A%: 0.4605877 B%: 0.5052648 Sleep%: 99.03415 Mem%: 67.79753
Iterations: 1001 A%: 0.4607079 B%: 0.6833119 Sleep%: 98.85598 Mem%: 71.58242
Iterations: 1002 A%: 0.4614534 B%: 0.5066818 Sleep%: 99.03187 Mem%: 75.37106
Iterations: 1001 A%: 0.4649589 B%: 0.5042901 Sleep%: 99.03075 Mem%: 79.15595
Iterations: 1002 A%: 0.4608251 B%: 0.6383237 Sleep%: 98.90085 Mem%: 82.94458
Iterations: 1002 A%: 0.466936 B%: 0.5068336 Sleep%: 99.02623 Mem%: 86.73322
Iterations: 1001 A%: 0.4569125 B%: 0.5035105 Sleep%: 99.03957 Mem%: 90.5181
Iterations: 1001 A%: 0.4610049 B%: 0.6845375 Sleep%: 98.85447 Mem%: 94.303
Iterations: 996 A%: 0.5111161 B%: 0.4888666 Sleep%: 99.00002 Mem%: 0.196147
Iterations: 1001 A%: 0.6227642 B%: 0.6662519 Sleep%: 98.71099 Mem%: 26.49921
Iterations: 1001 A%: 0.6420079 B%: 0.7212959 Sleep%: 98.63669 Mem%: 52.80228
Iterations: 1001 A%: 0.6463263 B%: 0.7222025 Sleep%: 98.63147 Mem%: 79.10535
Iterations: 995 A%: 0.6447483 B%: 0.7096395 Sleep%: 98.64562 Mem%: 5.408411
Iterations: 1001 A%: 0.6144424 B%: 0.6709721 Sleep%: 98.71459 Mem%: 31.71148
Iterations: 1001 A%: 0.656776 B%: 0.7096343 Sleep%: 98.63359 Mem%: 58.01454
Iterations: 1001 A%: 0.6591135 B%: 0.7220587 Sleep%: 98.61883 Mem%: 84.31762
Iterations: 995 A%: 0.6374999 B%: 0.6995121 Sleep%: 98.66299 Mem%: 10.62192
Iterations: 1002 A%: 0.6172365 B%: 0.6903603 Sleep%: 98.6924 Mem%: 36.95122
Iterations: 1001 A%: 0.6442969 B%: 0.7053012 Sleep%: 98.6504 Mem%: 63.25429
Iterations: 1001 A%: 0.6457716 B%: 0.7256569 Sleep%: 98.62857 Mem%: 89.55736
Iterations: 994 A%: 0.6267256 B%: 0.7097465 Sleep%: 98.66353 Mem%: 15.83544
Iterations: 1001 A%: 0.6319512 B%: 0.690721 Sleep%: 98.67732 Mem%: 42.1385
Iterations: 1001 A%: 0.640235 B%: 0.7212887 Sleep%: 98.63849 Mem%: 68.44157
Iterations: 1001 A%: 0.6406407 B%: 0.7232131 Sleep%: 98.63615 Mem%: 94.74463
Iterations: 995 A%: 1.352324 B%: 0.6863445 Sleep%: 97.96133 Mem%: 21.04832
Iterations: 1001 A%: 0.639236 B%: 0.7106342 Sleep%: 98.65013 Mem%: 47.35139
Iterations: 1001 A%: 0.6441297 B%: 0.7102788 Sleep%: 98.64559 Mem%: 73.65446
Iterations: 1001 A%: 0.6383808 B%: 0.7286881 Sleep%: 98.63294 Mem%: 99.95752
Iterations: 995 A%: 0.5976663 B%: 1.387575 Sleep%: 98.01476 Mem%: 26.26121
Iterations: 1001 A%: 0.6413681 B%: 0.6985755 Sleep%: 98.66006 Mem%: 52.56428
Iterations: 1001 A%: 0.6456332 B%: 0.7274104 Sleep%: 98.62697 Mem%: 78.86735
Iterations: 995 A%: 0.6378927 B%: 0.6978904 Sleep%: 98.66423 Mem%: 5.172285
Iterations: 1001 A%: 0.628281 B%: 0.651394 Sleep%: 98.72033 Mem%: 31.47535
Iterations: 1001 A%: 0.6449507 B%: 0.7263447 Sleep%: 98.6287 Mem%: 57.77842
Iterations: 1001 A%: 0.6414248 B%: 0.7222632 Sleep%: 98.63631 Mem%: 84.08149
Iterations: 995 A%: 0.6246953 B%: 0.7137373 Sleep%: 98.66157 Mem%: 10.3858
Iterations: 1001 A%: 0.6223046 B%: 0.6730704 Sleep%: 98.70463 Mem%: 36.68886
Iterations: 1001 A%: 0.6452858 B%: 0.7157889 Sleep%: 98.63893 Mem%: 62.99193
Iterations: 1001 A%: 0.6428116 B%: 0.7260916 Sleep%: 98.6311 Mem%: 89.295
Iterations: 994 A%: 0.6390259 B%: 0.6779115 Sleep%: 98.68306 Mem%: 15.57307
Iterations: 1001 A%: 0.6221085 B%: 0.6951346 Sleep%: 98.68276 Mem%: 41.87614
Iterations: 1001 A%: 0.6426847 B%: 0.714779 Sleep%: 98.64254 Mem%: 68.17921
Iterations: 1001 A%: 0.6467374 B%: 0.7253106 Sleep%: 98.62796 Mem%: 94.48227
Iterations: 995 A%: 1.363284 B%: 0.6800532 Sleep%: 97.95667 Mem%: 20.78534
Iterations: 1002 A%: 0.6367118 B%: 0.7082514 Sleep%: 98.65504 Mem%: 47.11464
Iterations: 1001 A%: 0.6432954 B%: 0.6980611 Sleep%: 98.65864 Mem%: 73.41771
Iterations: 1001 A%: 0.643342 B%: 0.7237793 Sleep%: 98.63288 Mem%: 99.72077
Iterations: 995 A%: 0.6030384 B%: 0.6501427 Sleep%: 98.74682 Mem%: 26.02446
Iterations: 1001 A%: 0.643426 B%: 0.7190869 Sleep%: 98.6375 Mem%: 52.32753
Iterations: 1001 A%: 0.6394644 B%: 0.7194495 Sleep%: 98.64108 Mem%: 78.6306
Iterations: 995 A%: 0.6423079 B%: 0.7113922 Sleep%: 98.64631 Mem%: 4.934909
Iterations: 1001 A%: 0.6100903 B%: 0.6706996 Sleep%: 98.71921 Mem%: 31.23797
Iterations: 1001 A%: 0.6447051 B%: 0.709834 Sleep%: 98.64547 Mem%: 57.54104
Iterations: 1001 A%: 0.6410086 B%: 0.7251416 Sleep%: 98.63385 Mem%: 83.84411
Iterations: 995 A%: 0.6312382 B%: 0.6989837 Sleep%: 98.66978 Mem%: 10.1478
-
@egimbernat
I fully understand that GC need to kick in and that it is a resource intensive task.The question remains, why does Work A and Work B start to take more time after appr 18 minutes runtime?
I added a gc.collect() to run every 10 iteration in the loop (appr every 10 ms). But no change, after 18 minutes it slows down.
-
@johand del and gc.collect() will pay a little time extra penalty because Microphyton enviroment need to first look references of a variable on the memory, force an unlink and release the memory for garbage collecting. Garbage collecting is a masive scan on the memory and will share some RAM and CPU with the main process while collecting.
In the case of work B there are more step to made in order to consider that sentence evaluated, that is because it takes more time.
Take a look at http://docs.micropython.org/en/v1.9.3/pyboard/reference/speed_python.html there are some fixes that you can apply to your code for being more efficient.
You may want to try calling gc.collect more times and see what's happen.
import utime import machine import gc SystemStart = utime.ticks_ms() TimeA = 0 TimeB = 0 TimeSleep = 0 TimeStart = utime.ticks_cpu() TimeStartIteration = utime.ticks_cpu() Iterations = 0 while(True): gc.collect() Iterations = Iterations + 1 TimeStartA = utime.ticks_cpu() #Do work A if [0,0,0] != [0,0,0]: machine.idle() TimeA = TimeA + utime.ticks_cpu() - TimeStartA del TimeStartA gc.collect() TimeStartB = utime.ticks_cpu() #Do work B while len([]) > 0: machine.idle() TimeB = TimeB + utime.ticks_cpu() - TimeStartB del TimeStartB gc.collect() TimeToSleep = TimeStartIteration + 10000 - utime.ticks_cpu() TimeStartSleep = utime.ticks_cpu() if TimeToSleep > 0: utime.sleep_us(TimeToSleep) TimeSleep = TimeSleep + utime.ticks_cpu() - TimeStartSleep del TimeStartSleep del TimeToSleep gc.collect() TimeStartIteration = utime.ticks_cpu() if utime.ticks_cpu() - TimeStart > 10000000: Total = TimeA + TimeB + TimeSleep gc.collect() print("Time: {:.2f} min Iterations: {} A: {:.2f}% B: {:.2f}% Sleep: {:.2f}% Mem: {:.1f}%".format((utime.ticks_ms() - SystemStart) / 60000, Iterations, 100 * TimeA / Total, 100 * TimeB / Total, 100 * TimeSleep / Total, 100 * gc.mem_alloc() / (gc.mem_alloc() + gc.mem_free()))) Iterations = 0 TimeA = 0 TimeB = 0 TimeSleep = 0 TimeStart = utime.ticks_cpu()
-
Did some more tests.
Added a gc.collect() first in every 10 second iteration. Same behavior, after appr 18 minutes memory usage 10 seconds after gc.collect() increase and time spent also increase.
Code:
import utime import machine import gc SystemStart = utime.ticks_ms() TimeA = 0 TimeB = 0 TimeSleep = 0 TimeStart = utime.ticks_cpu() TimeStartIteration = utime.ticks_cpu() Iterations = 0 while(True): Iterations = Iterations + 1 TimeStartA = utime.ticks_cpu() #Do work A if [0,0,0] != [0,0,0]: machine.idle() TimeA = TimeA + utime.ticks_cpu() - TimeStartA del TimeStartA TimeStartB = utime.ticks_cpu() #Do work B while len([]) > 0: machine.idle() TimeB = TimeB + utime.ticks_cpu() - TimeStartB del TimeStartB TimeToSleep = TimeStartIteration + 10000 - utime.ticks_cpu() TimeStartSleep = utime.ticks_cpu() if TimeToSleep > 0: utime.sleep_us(TimeToSleep) TimeSleep = TimeSleep + utime.ticks_cpu() - TimeStartSleep del TimeStartSleep del TimeToSleep TimeStartIteration = utime.ticks_cpu() if utime.ticks_cpu() - TimeStart > 10000000: Total = TimeA + TimeB + TimeSleep print("Time: {:.2f} min Iterations: {} A: {:.2f}% B: {:.2f}% Sleep: {:.2f}% Mem: {:.1f}%".format((utime.ticks_ms() - SystemStart) / 60000, Iterations, 100 * TimeA / Total, 100 * TimeB / Total, 100 * TimeSleep / Total, 100 * gc.mem_alloc() / (gc.mem_alloc() + gc.mem_free()))) Iterations = 0 TimeA = 0 TimeB = 0 TimeSleep = 0 gc.collect() TimeStart = utime.ticks_cpu()Result:
Time: 16.55 min Iterations: 1001 A: 0.44% B: 0.59% Sleep: 98.97% Mem: 3.9%
Time: 16.72 min Iterations: 1001 A: 0.45% B: 0.59% Sleep: 98.96% Mem: 3.9%
Time: 16.89 min Iterations: 1001 A: 0.44% B: 0.60% Sleep: 98.96% Mem: 3.9%
Time: 17.06 min Iterations: 1001 A: 0.45% B: 0.56% Sleep: 98.99% Mem: 3.9%
Time: 17.23 min Iterations: 1002 A: 0.44% B: 0.52% Sleep: 99.04% Mem: 3.9%
Time: 17.40 min Iterations: 1001 A: 0.45% B: 0.57% Sleep: 98.97% Mem: 3.9%
Time: 17.57 min Iterations: 1001 A: 0.44% B: 0.58% Sleep: 98.98% Mem: 3.9%
Time: 17.74 min Iterations: 1001 A: 0.46% B: 0.58% Sleep: 98.96% Mem: 4.1%
Time: 17.91 min Iterations: 1002 A: 0.49% B: 0.72% Sleep: 98.79% Mem: 10.2%
Time: 18.08 min Iterations: 1001 A: 0.63% B: 0.62% Sleep: 98.75% Mem: 26.4%
Time: 18.25 min Iterations: 1001 A: 0.60% B: 0.62% Sleep: 98.77% Mem: 26.4%
Time: 18.42 min Iterations: 1001 A: 0.63% B: 0.61% Sleep: 98.75% Mem: 26.4%
Time: 18.59 min Iterations: 1001 A: 0.60% B: 0.63% Sleep: 98.77% Mem: 26.4%Next try, gc.collect() immediately before reading memory usage. True usage is constant, but time spent doing work increase.
import utime import machine import gc SystemStart = utime.ticks_ms() TimeA = 0 TimeB = 0 TimeSleep = 0 TimeStart = utime.ticks_cpu() TimeStartIteration = utime.ticks_cpu() Iterations = 0 while(True): Iterations = Iterations + 1 TimeStartA = utime.ticks_cpu() #Do work A if [0,0,0] != [0,0,0]: machine.idle() TimeA = TimeA + utime.ticks_cpu() - TimeStartA del TimeStartA TimeStartB = utime.ticks_cpu() #Do work B while len([]) > 0: machine.idle() TimeB = TimeB + utime.ticks_cpu() - TimeStartB del TimeStartB TimeToSleep = TimeStartIteration + 10000 - utime.ticks_cpu() TimeStartSleep = utime.ticks_cpu() if TimeToSleep > 0: utime.sleep_us(TimeToSleep) TimeSleep = TimeSleep + utime.ticks_cpu() - TimeStartSleep del TimeStartSleep del TimeToSleep TimeStartIteration = utime.ticks_cpu() if utime.ticks_cpu() - TimeStart > 10000000: Total = TimeA + TimeB + TimeSleep gc.collect() print("Time: {:.2f} min Iterations: {} A: {:.2f}% B: {:.2f}% Sleep: {:.2f}% Mem: {:.1f}%".format((utime.ticks_ms() - SystemStart) / 60000, Iterations, 100 * TimeA / Total, 100 * TimeB / Total, 100 * TimeSleep / Total, 100 * gc.mem_alloc() / (gc.mem_alloc() + gc.mem_free()))) Iterations = 0 TimeA = 0 TimeB = 0 TimeSleep = 0 TimeStart = utime.ticks_cpu()Result:
Time: 16.72 min Iterations: 1001 A: 0.45% B: 0.56% Sleep: 98.98% Mem: 0.2%
Time: 16.89 min Iterations: 1002 A: 0.44% B: 0.57% Sleep: 98.99% Mem: 0.2%
Time: 17.06 min Iterations: 1001 A: 0.45% B: 0.52% Sleep: 99.03% Mem: 0.2%
Time: 17.23 min Iterations: 1002 A: 0.45% B: 0.48% Sleep: 99.08% Mem: 0.2%
Time: 17.40 min Iterations: 1001 A: 0.45% B: 0.55% Sleep: 99.00% Mem: 0.2%
Time: 17.57 min Iterations: 1002 A: 0.44% B: 0.57% Sleep: 98.99% Mem: 0.2%
Time: 17.74 min Iterations: 1001 A: 0.46% B: 0.56% Sleep: 98.98% Mem: 0.2%
Time: 17.91 min Iterations: 1001 A: 0.51% B: 0.50% Sleep: 98.99% Mem: 0.2%
Time: 18.08 min Iterations: 1001 A: 0.64% B: 0.61% Sleep: 98.75% Mem: 0.2%
Time: 18.25 min Iterations: 1002 A: 0.61% B: 0.67% Sleep: 98.73% Mem: 0.2%
Time: 18.42 min Iterations: 1001 A: 0.64% B: 0.61% Sleep: 98.75% Mem: 0.2%
Time: 18.59 min Iterations: 1001 A: 0.60% B: 0.63% Sleep: 98.77% Mem: 0.2%
Time: 18.77 min Iterations: 1001 A: 0.64% B: 0.62% Sleep: 98.74% Mem: 0.2%
-
Thank you for your answer, but I´m not sure I fully understand what you write...
I attached a new output from my test program. The only difference is the output formatting and information about total run time.
I understand that GC need to work. The question is why the memory consumption start to increase at a much faster rate after 18 minutes of runtime. At the same time more time are spent on “Do work A” and “Do work B”.
Johan
Time: 0.17 min Iterations: 1000 A: 0.44% B: 0.59% Sleep: 98.97% Mem: 3.9%
Time: 0.34 min Iterations: 1001 A: 0.45% B: 0.46% Sleep: 99.09% Mem: 7.7%
Time: 0.51 min Iterations: 1001 A: 0.44% B: 0.60% Sleep: 98.96% Mem: 11.4%
Time: 0.68 min Iterations: 1002 A: 0.45% B: 0.45% Sleep: 99.09% Mem: 15.2%
Time: 0.85 min Iterations: 1002 A: 0.44% B: 0.53% Sleep: 99.03% Mem: 19.0%
Time: 1.02 min Iterations: 1001 A: 0.45% B: 0.46% Sleep: 99.09% Mem: 22.7%
Time: 1.19 min Iterations: 1002 A: 0.44% B: 0.57% Sleep: 98.99% Mem: 26.5%
Time: 1.36 min Iterations: 1002 A: 0.46% B: 0.57% Sleep: 98.97% Mem: 30.2%
Time: 1.53 min Iterations: 1001 A: 0.48% B: 0.56% Sleep: 98.95% Mem: 34.0%
Time: 1.70 min Iterations: 1001 A: 0.49% B: 0.59% Sleep: 98.93% Mem: 37.8%
Time: 1.87 min Iterations: 1002 A: 0.48% B: 0.58% Sleep: 98.94% Mem: 41.5%
Time: 2.04 min Iterations: 1002 A: 0.49% B: 0.58% Sleep: 98.93% Mem: 45.3%
Time: 2.21 min Iterations: 1001 A: 0.48% B: 0.60% Sleep: 98.92% Mem: 49.0%
Time: 2.38 min Iterations: 1002 A: 0.48% B: 0.59% Sleep: 98.93% Mem: 52.8%
Time: 2.55 min Iterations: 1001 A: 0.49% B: 0.48% Sleep: 99.03% Mem: 56.6%
Time: 2.72 min Iterations: 1002 A: 0.49% B: 0.58% Sleep: 98.93% Mem: 60.3%
Time: 2.89 min Iterations: 1001 A: 0.48% B: 0.59% Sleep: 98.93% Mem: 64.1%
Time: 3.06 min Iterations: 1001 A: 0.49% B: 0.48% Sleep: 99.03% Mem: 67.9%
Time: 3.23 min Iterations: 1001 A: 0.48% B: 0.58% Sleep: 98.94% Mem: 71.6%
Time: 3.40 min Iterations: 1002 A: 0.49% B: 0.59% Sleep: 98.92% Mem: 75.4%
Time: 3.57 min Iterations: 1002 A: 0.49% B: 0.48% Sleep: 99.04% Mem: 79.1%
Time: 3.74 min Iterations: 1001 A: 0.49% B: 0.57% Sleep: 98.95% Mem: 82.9%
Time: 3.91 min Iterations: 1001 A: 0.48% B: 0.58% Sleep: 98.94% Mem: 86.7%
Time: 4.08 min Iterations: 1001 A: 0.49% B: 0.47% Sleep: 99.04% Mem: 90.4%
Time: 4.25 min Iterations: 1001 A: 0.48% B: 0.60% Sleep: 98.92% Mem: 94.2%
Time: 4.42 min Iterations: 1002 A: 0.49% B: 0.59% Sleep: 98.92% Mem: 97.9%
Time: 4.59 min Iterations: 995 A: 0.47% B: 1.19% Sleep: 98.34% Mem: 1.8%
Time: 4.76 min Iterations: 1002 A: 0.46% B: 0.56% Sleep: 98.98% Mem: 5.6%
Time: 4.93 min Iterations: 1001 A: 0.45% B: 0.47% Sleep: 99.08% Mem: 9.4%
Time: 5.10 min Iterations: 1001 A: 0.46% B: 0.56% Sleep: 98.98% Mem: 13.1%
Time: 5.27 min Iterations: 1001 A: 0.45% B: 0.53% Sleep: 99.02% Mem: 16.9%
Time: 5.44 min Iterations: 1001 A: 0.46% B: 0.46% Sleep: 99.08% Mem: 20.6%
Time: 5.61 min Iterations: 1002 A: 0.45% B: 0.58% Sleep: 98.97% Mem: 24.4%
Time: 5.78 min Iterations: 1002 A: 0.46% B: 0.56% Sleep: 98.98% Mem: 28.2%
Time: 5.95 min Iterations: 1001 A: 0.48% B: 0.48% Sleep: 99.04% Mem: 31.9%
Time: 6.12 min Iterations: 1001 A: 0.49% B: 0.48% Sleep: 99.03% Mem: 35.7%
Time: 6.29 min Iterations: 1001 A: 0.48% B: 0.59% Sleep: 98.92% Mem: 39.4%
Time: 6.46 min Iterations: 1001 A: 0.48% B: 0.57% Sleep: 98.94% Mem: 43.2%
Time: 6.63 min Iterations: 1002 A: 0.48% B: 0.55% Sleep: 98.96% Mem: 47.0%
Time: 6.80 min Iterations: 1001 A: 0.49% B: 0.58% Sleep: 98.93% Mem: 50.7%
Time: 6.97 min Iterations: 1002 A: 0.48% B: 0.59% Sleep: 98.93% Mem: 54.5%
Time: 7.14 min Iterations: 1001 A: 0.49% B: 0.48% Sleep: 99.03% Mem: 58.3%
Time: 7.31 min Iterations: 1001 A: 0.48% B: 0.58% Sleep: 98.93% Mem: 62.0%
Time: 7.48 min Iterations: 1001 A: 0.49% B: 0.58% Sleep: 98.93% Mem: 65.8%
Time: 7.65 min Iterations: 1002 A: 0.48% B: 0.48% Sleep: 99.04% Mem: 69.5%
Time: 7.83 min Iterations: 1001 A: 0.49% B: 0.47% Sleep: 99.04% Mem: 73.3%
Time: 8.00 min Iterations: 1002 A: 0.48% B: 0.54% Sleep: 98.98% Mem: 77.1%
Time: 8.17 min Iterations: 1001 A: 0.49% B: 0.48% Sleep: 99.03% Mem: 80.8%
Time: 8.34 min Iterations: 1001 A: 0.49% B: 0.57% Sleep: 98.94% Mem: 84.6%
Time: 8.51 min Iterations: 1001 A: 0.49% B: 0.48% Sleep: 99.03% Mem: 88.3%
Time: 8.68 min Iterations: 1002 A: 0.48% B: 0.58% Sleep: 98.94% Mem: 92.1%
Time: 8.85 min Iterations: 1001 A: 0.49% B: 0.60% Sleep: 98.91% Mem: 95.9%
Time: 9.02 min Iterations: 1002 A: 0.48% B: 0.48% Sleep: 99.04% Mem: 99.6%
Time: 9.19 min Iterations: 995 A: 0.45% B: 1.29% Sleep: 98.26% Mem: 3.5%
Time: 9.36 min Iterations: 1001 A: 0.46% B: 0.46% Sleep: 99.08% Mem: 7.3%
Time: 9.53 min Iterations: 1002 A: 0.45% B: 0.47% Sleep: 99.08% Mem: 11.0%
Time: 9.70 min Iterations: 1001 A: 0.46% B: 0.45% Sleep: 99.08% Mem: 14.8%
Time: 9.87 min Iterations: 1002 A: 0.45% B: 0.47% Sleep: 99.08% Mem: 18.6%
Time: 10.04 min Iterations: 1001 A: 0.46% B: 0.54% Sleep: 99.00% Mem: 22.3%
Time: 10.21 min Iterations: 1001 A: 0.45% B: 0.58% Sleep: 98.97% Mem: 26.1%
Time: 10.38 min Iterations: 1002 A: 0.46% B: 0.58% Sleep: 98.96% Mem: 29.9%
Time: 10.55 min Iterations: 1001 A: 0.49% B: 0.48% Sleep: 99.03% Mem: 33.6%
Time: 10.72 min Iterations: 1001 A: 0.48% B: 0.48% Sleep: 99.04% Mem: 37.4%
Time: 10.89 min Iterations: 1001 A: 0.49% B: 0.58% Sleep: 98.93% Mem: 41.1%
Time: 11.06 min Iterations: 1001 A: 0.49% B: 0.49% Sleep: 99.02% Mem: 44.9%
Time: 11.23 min Iterations: 1001 A: 0.48% B: 0.59% Sleep: 98.92% Mem: 48.7%
Time: 11.40 min Iterations: 1002 A: 0.48% B: 0.58% Sleep: 98.94% Mem: 52.4%
Time: 11.57 min Iterations: 1001 A: 0.49% B: 0.48% Sleep: 99.03% Mem: 56.2%
Time: 11.74 min Iterations: 1002 A: 0.48% B: 0.59% Sleep: 98.93% Mem: 59.9%
Time: 11.91 min Iterations: 1001 A: 0.49% B: 0.60% Sleep: 98.91% Mem: 63.7%
Time: 12.08 min Iterations: 1001 A: 0.48% B: 0.59% Sleep: 98.92% Mem: 67.5%
Time: 12.25 min Iterations: 1002 A: 0.49% B: 0.47% Sleep: 99.04% Mem: 71.2%
Time: 12.42 min Iterations: 1001 A: 0.49% B: 0.48% Sleep: 99.04% Mem: 75.0%
Time: 12.59 min Iterations: 1001 A: 0.49% B: 0.58% Sleep: 98.93% Mem: 78.7%
Time: 12.76 min Iterations: 1001 A: 0.48% B: 0.58% Sleep: 98.94% Mem: 82.5%
Time: 12.93 min Iterations: 1002 A: 0.49% B: 0.60% Sleep: 98.92% Mem: 86.3%
Time: 13.10 min Iterations: 1001 A: 0.48% B: 0.47% Sleep: 99.05% Mem: 90.0%
Time: 13.27 min Iterations: 1002 A: 0.49% B: 0.48% Sleep: 99.03% Mem: 93.8%
Time: 13.44 min Iterations: 1002 A: 0.48% B: 0.48% Sleep: 99.04% Mem: 97.6%
Time: 13.61 min Iterations: 995 A: 0.48% B: 1.21% Sleep: 98.31% Mem: 1.4%
Time: 13.78 min Iterations: 1002 A: 0.45% B: 0.51% Sleep: 99.04% Mem: 5.2%
Time: 13.95 min Iterations: 1002 A: 0.46% B: 0.57% Sleep: 98.97% Mem: 9.0%
Time: 14.12 min Iterations: 1001 A: 0.45% B: 0.49% Sleep: 99.06% Mem: 12.7%
Time: 14.29 min Iterations: 1001 A: 0.46% B: 0.60% Sleep: 98.94% Mem: 16.5%
Time: 14.46 min Iterations: 1002 A: 0.46% B: 0.58% Sleep: 98.96% Mem: 20.3%
Time: 14.63 min Iterations: 1002 A: 0.47% B: 0.46% Sleep: 99.08% Mem: 24.0%
Time: 14.80 min Iterations: 1002 A: 0.45% B: 0.47% Sleep: 99.07% Mem: 27.8%
Time: 14.97 min Iterations: 1001 A: 0.48% B: 0.58% Sleep: 98.94% Mem: 31.5%
Time: 15.14 min Iterations: 1002 A: 0.48% B: 0.58% Sleep: 98.94% Mem: 35.3%
Time: 15.31 min Iterations: 1001 A: 0.49% B: 0.58% Sleep: 98.93% Mem: 39.1%
Time: 15.48 min Iterations: 1001 A: 0.48% B: 0.48% Sleep: 99.04% Mem: 42.8%
Time: 15.65 min Iterations: 1001 A: 0.49% B: 0.47% Sleep: 99.04% Mem: 46.6%
Time: 15.82 min Iterations: 1001 A: 0.48% B: 0.57% Sleep: 98.95% Mem: 50.3%
Time: 16.00 min Iterations: 1002 A: 0.48% B: 0.60% Sleep: 98.91% Mem: 54.1%
Time: 16.17 min Iterations: 1001 A: 0.48% B: 0.47% Sleep: 99.05% Mem: 57.9%
Time: 16.34 min Iterations: 1002 A: 0.49% B: 0.58% Sleep: 98.93% Mem: 61.6%
Time: 16.51 min Iterations: 1002 A: 0.49% B: 0.52% Sleep: 99.00% Mem: 65.4%
Time: 16.68 min Iterations: 1001 A: 0.49% B: 0.48% Sleep: 99.03% Mem: 69.2%
Time: 16.85 min Iterations: 1001 A: 0.49% B: 0.47% Sleep: 99.04% Mem: 72.9%
Time: 17.02 min Iterations: 1001 A: 0.49% B: 0.61% Sleep: 98.91% Mem: 76.7%
Time: 17.19 min Iterations: 1001 A: 0.48% B: 0.48% Sleep: 99.04% Mem: 80.4%
Time: 17.36 min Iterations: 1001 A: 0.49% B: 0.48% Sleep: 99.04% Mem: 84.2%
Time: 17.53 min Iterations: 1002 A: 0.48% B: 0.46% Sleep: 99.05% Mem: 88.0%
Time: 17.70 min Iterations: 1001 A: 0.49% B: 0.48% Sleep: 99.04% Mem: 91.7%
Time: 17.87 min Iterations: 1001 A: 0.51% B: 0.54% Sleep: 98.95% Mem: 96.7%
Time: 18.04 min Iterations: 994 A: 0.64% B: 0.67% Sleep: 98.69% Mem: 23.0%
Time: 18.21 min Iterations: 1001 A: 0.64% B: 0.69% Sleep: 98.67% Mem: 49.2%
Time: 18.38 min Iterations: 1001 A: 0.65% B: 0.72% Sleep: 98.63% Mem: 75.5%
Time: 18.55 min Iterations: 995 A: 0.65% B: 0.70% Sleep: 98.65% Mem: 1.8%
Time: 18.72 min Iterations: 1001 A: 0.62% B: 0.64% Sleep: 98.74% Mem: 28.1%
Time: 18.89 min Iterations: 1001 A: 0.65% B: 0.69% Sleep: 98.65% Mem: 54.4%
Time: 19.06 min Iterations: 1001 A: 0.67% B: 0.69% Sleep: 98.64% Mem: 80.6%
Time: 19.23 min Iterations: 995 A: 1.40% B: 0.67% Sleep: 97.93% Mem: 6.9%
Time: 19.40 min Iterations: 1001 A: 0.63% B: 0.68% Sleep: 98.69% Mem: 33.2%
Time: 19.57 min Iterations: 1001 A: 0.65% B: 0.70% Sleep: 98.65% Mem: 59.5%
Time: 19.74 min Iterations: 1001 A: 0.65% B: 0.69% Sleep: 98.66% Mem: 85.7%
Time: 19.91 min Iterations: 995 A: 0.64% B: 0.67% Sleep: 98.70% Mem: 12.0%
Time: 20.08 min Iterations: 1001 A: 0.63% B: 0.65% Sleep: 98.72% Mem: 38.3%
-
Is totally expected since in your code they are two situations:
1- Only importing GC doesn't create side effect of any type on the code, hence the problem (And is related with number two) is that the code is creating full pressure on GC and is forcing it to run to prevent stack overflow. Normally in MicroPython you need to include gc.collect() at least one time on the loop.
2- You are reusing the variables so that makes more difficult to GC to collect the replaced value because a strong reference exists. In Python get worse because values outside of a function or a loop are considered global for their current context and importer.
Is normal that WorkA take a little less time than WorkB since the first is only an equality comparison, the second, contains at least 5 more assembler instructions because it needs to evaluate [], then their length and finally equality to 0 on a loop.