Profile raspberry timings
fnoop opened this issue · 5 comments
fnoop commented
Threads=-1
Time(hafc |thres ):1.41938ms 1.41938ms
Time(hafc |find-cont ):21.9357ms 23.3551ms
Time(hafc |total ):2.53662ms 25.8917ms
Time(parallel)= 28.1511ms
Time(hafc |thres ):1.77948ms 1.77948ms
Time(hafc |find-cont ):7.72038ms 9.49987ms
Time(hafc |total ):0.62521ms 10.1251ms
Time(parallel)= 12.3152ms
Time(hafc |thres ):1.86016ms 1.86016ms
Time(hafc |find-cont ):13.239ms 15.0991ms
Time(hafc |total ):1.28802ms 16.3872ms
Time(parallel)= 18.5881ms
Time(detect|ConvertGrey ):3.70053ms 3.70053ms
Time(detect|CreateImageToTheshold ):0.023073ms 3.7236ms
Time(detect|BuildPyramid ):2.26235ms 5.98595ms
Time(detect|Threshold and Detect rectangles ):28.3578ms 34.3438ms
Time(detect|prefilterCandidates ):0.041198ms 34.385ms
Time(detect|Marker classification. ):0.004635ms 34.3896ms
Time(detect|Threshold and Detect rectangles ):12.4607ms 46.8503ms
Time(detect|prefilterCandidates ):0.013177ms 46.8635ms
Time(detect|Marker classification. ):0.017552ms 46.881ms
Time(detect|Threshold and Detect rectangles ):18.7504ms 65.6315ms
Time(detect|prefilterCandidates ):0.014271ms 65.6457ms
Time(detect|Marker classification. ):0.003959ms 65.6497ms
Time(detect|Corner Refinement ):0.146615ms 65.7963ms
Time(detect|total ):0.00526ms 65.8016ms
debug:detecttime~66.6519:threads~-1
Time(hafc |thres ):1.73896ms 1.73896ms
Time(hafc |find-cont ):7.18632ms 8.92528ms
Time(hafc |total ):0.623022ms 9.5483ms
Time(parallel)= 10.447ms
Time(hafc |thres ):2.06381ms 2.06381ms
Time(hafc |find-cont ):7.98611ms 10.0499ms
Time(hafc |total ):0.647397ms 10.6973ms
Time(parallel)= 11.3218ms
Time(hafc |thres ):2.71011ms 2.71011ms
Time(hafc |find-cont ):7.24679ms 9.9569ms
Time(hafc |total ):0.037344ms 9.99424ms
Time(parallel)= 10.592ms
Time(detect|ConvertGrey ):1.90318ms 1.90318ms
Time(detect|CreateImageToTheshold ):0.024114ms 1.9273ms
Time(detect|BuildPyramid ):2.39256ms 4.31985ms
Time(detect|Threshold and Detect rectangles ):10.7017ms 15.0216ms
Time(detect|prefilterCandidates ):0.024375ms 15.046ms
Time(detect|Marker classification. ):0.004166ms 15.0501ms
Time(detect|Threshold and Detect rectangles ):11.881ms 26.9312ms
Time(detect|prefilterCandidates ):0.017605ms 26.9488ms
Time(detect|Marker classification. ):0.030312ms 26.9791ms
Time(detect|Threshold and Detect rectangles ):11.0166ms 37.9957ms
Time(detect|prefilterCandidates ):0.010729ms 38.0064ms
Time(detect|Marker classification. ):0.008073ms 38.0145ms
Time(detect|Corner Refinement ):0.145678ms 38.1602ms
Time(detect|total ):0.005ms 38.1652ms
debug:detecttime~47.1737:threads~-1
Time(hafc |thres ):2.48537ms 2.48537ms
Time(hafc |find-cont ):32.4733ms 34.9586ms
Time(hafc |total ):3.18584ms 38.1445ms
Time(parallel)= 40.9734ms
Time(hafc |thres ):2.10756ms 2.10756ms
Time(hafc |find-cont ):11.023ms 13.1306ms
Time(hafc |total ):0.54021ms 13.6708ms
Time(parallel)= 14.852ms
Time(hafc |thres ):2.92324ms 2.92324ms
Time(hafc |find-cont ):8.40658ms 11.3298ms
Time(hafc |total ):0.64547ms 11.9753ms
Time(parallel)= 12.6278ms
Time(detect|ConvertGrey ):2.93949ms 2.93949ms
Time(detect|CreateImageToTheshold ):0.039323ms 2.97881ms
Time(detect|BuildPyramid ):3.71199ms 6.6908ms
Time(detect|Threshold and Detect rectangles ):41.0676ms 47.7584ms
Time(detect|prefilterCandidates ):0.031354ms 47.7897ms
Time(detect|Marker classification. ):0.005209ms 47.795ms
Time(detect|Threshold and Detect rectangles ):14.9349ms 62.7299ms
Time(detect|prefilterCandidates ):0.011928ms 62.7418ms
Time(detect|Marker classification. ):0.031198ms 62.773ms
Time(detect|Threshold and Detect rectangles ):12.825ms 75.598ms
Time(detect|prefilterCandidates ):0.019584ms 75.6176ms
Time(detect|Marker classification. ):0.006041ms 75.6236ms
Time(detect|Corner Refinement ):0.147605ms 75.7712ms
Time(detect|total ):0.007864ms 75.7791ms
debug:detecttime~77.9994:threads~-1
Note 3 x Threshold and Detect rectangles
fnoop commented
Threads=1
Time(hafc |thres ):0.980416ms 0.980416ms
Time(hafc |find-cont ):7.4278ms 8.40822ms
Time(hafc |total ):0.023125ms 8.43135ms
Time(non-parallel)= 8.71431ms
Time(hafc |thres ):1.08776ms 1.08776ms
Time(hafc |find-cont ):8.1765ms 9.26426ms
Time(hafc |total ):0.034791ms 9.29905ms
Time(non-parallel)= 9.59582ms
Time(hafc |thres ):1.29531ms 1.29531ms
Time(hafc |find-cont ):9.9215ms 11.2168ms
Time(hafc |total ):0.238854ms 11.4557ms
Time(non-parallel)= 11.793ms
Time(detect|ConvertGrey ):2.13094ms 2.13094ms
Time(detect|CreateImageToTheshold ):0.022656ms 2.15359ms
Time(detect|BuildPyramid ):2.41718ms 4.57078ms
Time(detect|Threshold and Detect rectangles ):8.76937ms 13.3401ms
Time(detect|prefilterCandidates ):0.014114ms 13.3543ms
Time(detect|Marker classification. ):0.004375ms 13.3586ms
Time(detect|Threshold and Detect rectangles ):9.64926ms 23.0079ms
Time(detect|prefilterCandidates ):0.008177ms 23.0161ms
Time(detect|Marker classification. ):0.014323ms 23.0304ms
Time(detect|Threshold and Detect rectangles ):11.8563ms 34.8867ms
Time(detect|prefilterCandidates ):0.008177ms 34.8949ms
Time(detect|Marker classification. ):0.006354ms 34.9012ms
Time(detect|Corner Refinement ):0.147709ms 35.0489ms
Time(detect|total ):0.003021ms 35.0519ms
debug:detecttime~35.8035:threads~1
Time(hafc |thres ):0.96177ms 0.96177ms
Time(hafc |find-cont ):16.6501ms 17.6119ms
Time(hafc |total ):1.91745ms 19.5293ms
Time(non-parallel)= 20.1561ms
Time(hafc |thres ):1.40328ms 1.40328ms
Time(hafc |find-cont ):9.13905ms 10.5423ms
Time(hafc |total ):0.616145ms 11.1585ms
Time(non-parallel)= 11.9742ms
Time(hafc |thres ):1.31969ms 1.31969ms
Time(hafc |find-cont ):15.3657ms 16.6854ms
Time(hafc |total ):1.21932ms 17.9047ms
Time(non-parallel)= 18.748ms
Time(detect|ConvertGrey ):2.03729ms 2.03729ms
Time(detect|CreateImageToTheshold ):0.023178ms 2.06047ms
Time(detect|BuildPyramid ):2.3537ms 4.41416ms
Time(detect|Threshold and Detect rectangles ):20.2167ms 24.6309ms
Time(detect|prefilterCandidates ):0.0325ms 24.6634ms
Time(detect|Marker classification. ):0.006667ms 24.67ms
Time(detect|Threshold and Detect rectangles ):12.2585ms 36.9285ms
Time(detect|prefilterCandidates ):0.026146ms 36.9547ms
Time(detect|Marker classification. ):0.017291ms 36.9719ms
Time(detect|Threshold and Detect rectangles ):18.9116ms 55.8835ms
Time(detect|prefilterCandidates ):0.007291ms 55.8908ms
Time(detect|Marker classification. ):0.053854ms 55.9447ms
Time(detect|Corner Refinement ):0.158073ms 56.1028ms
Time(detect|total ):0.007188ms 56.1099ms
debug:detecttime~58.743:threads~1
fnoop commented
Most of the time in long detection time is spent copying the image:
2018-07-18 23:21:18,902 DEBUG track_targets: Debug['detecttime~9.85062', 'threads~-1']
2018-07-18 23:21:18,903 DEBUG track_targets: Debug['inactive_marker', 'center~[663.809, 446.019]', 'area~71589.2', 'marker~16=(533.402,306.749) (808.261,319.968) (787.476,604.24) (526.098,553.118) Txyz=-999999 -999999 -999999 Rxyz=-999999 -999999 -999999 ', 'Ti~0.02', 'ThresHold~100', 'Markers~2', 'processtime~249.186']
2018-07-18 23:21:18,905 DEBUG track_targets: Debug['Time(detectloop|CopyImage )', '238.85ms 238.85ms']
2018-07-18 23:21:18,906 DEBUG track_targets: Debug['Time(detectloop|MarkerDetect )', '9.97822ms 248.828ms']
2018-07-18 23:21:18,910 DEBUG track_targets: Debug['Time(detectloop|MarkerLock )', '0.177656ms 249.006ms']
2018-07-18 23:21:18,915 DEBUG track_targets: Debug['Time(detectloop|PoseEstimation )', '0.165938ms 249.172ms']
2018-07-18 23:21:18,918 DEBUG track_targets: Debug['Time(detectloop|total )', '0.343229ms 249.515ms']
fnoop commented
2018-07-19 09:48:11,481 DEBUG track_targets: Debug['detecttime~22.3879', 'threads~-1']
2018-07-19 09:48:11,484 DEBUG track_targets: Debug['active_marker', '19', 'center~[451.493, 487.476]', 'area~32704.8', 'marker~19=(540.056,399.875) (531.611,598.735) (366.446,569.411) (367.86,381.882) Txyz=-0.0376434 -0.088547 0.603173 Rxyz=-1.7572 -1.98263 0.166654 ', 'vectornorm~0.610799', 'Ti~0.0994568', 'ThresHold~62', 'Markers~1', 'processtime~43.1282']
2018-07-19 09:48:11,489 DEBUG Sending mavlink landing_target:-0.156726 0.111097 0.610799
2018-07-19 09:48:11,490 INFO Fctime:5287441017003, Fps: 17.0971794552, Alt:0.0, Rangefinder:None, Marker:19, Distance:0.610799, xOffset:-0.156726, yOffset:0.111097, processTime:43.1282
2018-07-19 09:48:11,492 DEBUG track_targets: Debug['Time(detectloop|GrabImage )', '6.43434ms 6.43434ms']
2018-07-19 09:48:11,494 DEBUG track_targets: Debug['Time(detectloop|DecodeImage )', '11.602ms 18.0363ms']
2018-07-19 09:48:11,497 DEBUG track_targets: Debug['Time(detectloop|MarkerDetect )', '22.6277ms 40.6641ms']
2018-07-19 09:48:11,501 DEBUG track_targets: Debug['Time(detectloop|MarkerLock )', '0.135572ms 40.7996ms']
2018-07-19 09:48:11,502 DEBUG track_targets: Debug['Time(detectloop|PoseEstimation )', '2.31488ms 43.1145ms']
2018-07-19 09:48:11,504 DEBUG track_targets: Debug['Time(detectloop|SendMessage )', '1.14562ms 44.2601ms']
2018-07-19 09:48:11,506 DEBUG track_targets: Debug['Time(detectloop|DrawGreenAR )', '2.0965ms 46.3566ms']
2018-07-19 09:48:11,508 DEBUG track_targets: Debug['Time(detectloop|OutputImage )', '35.5989ms 81.9555ms']
2018-07-19 09:48:11,510 DEBUG track_targets: Debug['Time(detectloop|EndofLoop )', '0.097708ms 82.0533ms']
2018-07-19 09:48:11,527 DEBUG track_targets: Debug['Time(detectloop|total )', '0.040104ms 82.0934ms']
fnoop commented
So the 3 x iteration of Threshold and Detect rectangles is because the threshold method is set to THRES_AUTO_FIXED, not THRES_ADAPTIVE. In this mode, it iterates NAttemptsAutoThresFix times. This parameter can be set to 1 to prevent this, but why is the method THRES_AUTO_FIXED? It should be THRES_ADAPTIVE by default.
Ah, it's because DM_VIDEO_FAST sets it:
else if(detectMode==DM_VIDEO_FAST){
setThresholdMethod(THRES_AUTO_FIXED);
setAutoSizeSpeedUp(true,0.3);
}
fnoop commented
If no detected markers are found, it sets random thresholds NAttemptsAutoThresFix times and tries again. If we haven't found any markers, this is a good thing - a lower framerate but a better chance of finding markers.