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.


Log in to reply
 

Pycom on Twitter