Significant runtime difference between CERES and GTSAM on same BAL problem

[dvorak0]

Description:

I noticed a large performance discrepancy between the bundle_adjuster binary and the SFMExample_bal example when running on the same BAL dataset.

Dataset:

problem-16-22106-pre.txt from https://grail.cs.washington.edu/projects/bal/dubrovnik.html
(Problem size: 16 22106 83718)

Version

96e5355

Build command:

cmake -DCMAKE_BUILD_TYPE=Release ..
make -j

Timing

ceres

root@nixos:/tinynav/output/ceres-solver/build# time ./bin/bundle_adjuster --input /tinynav/problem-16-22106-pre.txt -num_threads=1 -linear_solver=dense_schur
iter      cost      cost_change  |gradient|   |step|    tr_ratio  tr_radius  ls_iter  iter_time  total_time
   0  4.185660e+06    0.00e+00    2.16e+07   0.00e+00   0.00e+00  1.00e+04        0    4.42e-02    7.22e-02
   1  1.980525e+05    3.99e+06    5.34e+06   0.00e+00   9.60e-01  3.00e+04        1    8.01e-02    1.52e-01
   2  5.086543e+04    1.47e+05    2.11e+06   1.01e+03   8.22e-01  4.09e+04        1    7.46e-02    2.27e-01
   3  1.859667e+04    3.23e+04    2.87e+05   2.64e+02   9.85e-01  1.23e+05        1    7.48e-02    3.02e-01
   4  1.803857e+04    5.58e+02    2.69e+04   8.66e+01   9.93e-01  3.69e+05        1    7.44e-02    3.76e-01
   5  1.803391e+04    4.66e+00    3.11e+02   1.02e+01   1.00e+00  1.11e+06        1    7.31e-02    4.49e-01

Solver Summary (v 2.2.0-eigen-(3.4.0)-lapack-suitesparse-(5.10.1)-eigensparse-cuda-(12020))

                                     Original                  Reduced
Parameter blocks                        22122                    22122
Parameters                              66462                    66462
Residual blocks                         83718                    83718
Residuals                              167436                   167436

Minimizer                        TRUST_REGION

Dense linear algebra library            EIGEN 
Trust region strategy     LEVENBERG_MARQUARDT
                                        Given                     Used
Linear solver                     DENSE_SCHUR              DENSE_SCHUR
Threads                                     1                        1
Linear solver ordering               22106,16                 22106,16
Schur structure                         2,3,9                    2,3,9

Cost:
Initial                          4.185660e+06
Final                            1.803391e+04
Change                           4.167626e+06

Minimizer iterations                        6
Successful steps                            6
Unsuccessful steps                          0

Time (in seconds):
Preprocessor                         0.028064

  Residual only evaluation           0.034154 (5)
  Jacobian & residual evaluation     0.210194 (6)
  Linear solver                      0.131609 (5)
Minimizer                            0.422234

Postprocessor                        0.002126
Total                                0.452424

Termination:                   NO_CONVERGENCE (Maximum number of iterations reached. Number of iterations: 5.)


real	0m0.589s
user	0m0.527s
sys	0m0.060s

gtsam

root@nixos:/tinynav/output/gtsam/build# time ./examples/SFMExample_bal /tinynav/problem-16-22106-pr
e.txt 
read 22106 tracks on 16 cameras
Initial error: 4.18566e+06
newError: 2.84007e+06
errorThreshold: 2.84007e+06 > 0
absoluteDecrease: 1345595.21265 >= 1e-05
relativeDecrease: 0.321477369734 >= 1e-05
newError: 428396.143992
errorThreshold: 428396.143992 > 0
absoluteDecrease: 2411669.40624 >= 1e-05
relativeDecrease: 0.84915976888 >= 1e-05
newError: 82756.334431
errorThreshold: 82756.334431 > 0
absoluteDecrease: 345639.809561 >= 1e-05
relativeDecrease: 0.806822877396 >= 1e-05
newError: 28524.7237205
errorThreshold: 28524.7237205 > 0
absoluteDecrease: 54231.6107104 >= 1e-05
relativeDecrease: 0.655316732953 >= 1e-05
newError: 21028.9020562
errorThreshold: 21028.9020562 > 0
absoluteDecrease: 7495.82166434 >= 1e-05
relativeDecrease: 0.262783322207 >= 1e-05
newError: 20482.7928745
errorThreshold: 20482.7928745 > 0
absoluteDecrease: 546.109181693 >= 1e-05
relativeDecrease: 0.0259694576651 >= 1e-05
newError: 20475.2556405
errorThreshold: 20475.2556405 > 0
absoluteDecrease: 7.53723400232 >= 1e-05
relativeDecrease: 0.000367978822444 >= 1e-05
newError: 20475.2532671
errorThreshold: 20475.2532671 > 0
absoluteDecrease: 0.00237339307205 >= 1e-05
relativeDecrease: 1.15915186297e-07 < 1e-05
converged
errorThreshold: 20475.2532671 <? 0
absoluteDecrease: 0.00237339307205 <? 1e-05
relativeDecrease: 1.15915186297e-07 <? 1e-05
iterations: 8 >? 100
final error: 20475.2532671

real	0m3.145s
user	0m13.053s
sys	0m1.102s

Expected behavior:

Since both programs seem to solve the same BAL problem, I expected similar runtime performance, especially since both were built in Release mode.

perf result

[dellaert]

What’s your conclusion from looking at a flame graph?
I can’t really read what’s happening from the image.

[dvorak0]

What’s your conclusion from looking at a flame graph? I can’t really read what’s happening from the image.

I tried to find the bottleneck but couldn’t. I’ve concluded that:

1. There is no single key that can solve this issue.

2. Memory allocation needs to be handled carefully.

3. Different subfunctions need to be tuned to see how much we can improve.

We implemented VIO using GTSAM, in our navigation stack (https://github.com/UniflexAI/tinynav), but we haven’t been able to make it run fast. I’ll investigate the issue further when I have time.

[ProfFan]

Hi @dvorak0 , Is this with TBB enabled?

[dvorak0]

Hi @dvorak0 , Is this with TBB enabled?

I tried both. Both give almost the same results. At first, I compiled with the default, it's slow. And then I found a lot blocks about TBB in the flame graph and then disabled TBB and test again. it's the same.

Could you reproduce the result from your side?

[dellaert]

I'v been playing with a new batch factor idea in #2306 , still very much WIP, but testSFMBAL on my (paltry M1) Mac is much faster than 13 seconds. 5 seconds with multifrontal, and 3 seconds with sequential. Both use the "ceres-style" Schur complement ordering: points first, then cameras. Is that the ordering you are also using? Ordering can have a huge effect.

[dvorak0]

I'v been playing with a new batch factor idea in #2306 , still very much WIP, but testSFMBAL on my (paltry M1) Mac is much faster than 13 seconds. 5 seconds with multifrontal, and 3 seconds with sequential. Both use the "ceres-style" Schur complement ordering: points first, then cameras. Is that the ordering you are also using? Ordering can have a huge effect.

@dellaert I agree that the ordering matters a lot. In my previous test, I did not change the code (https://github.com/borglab/gtsam/blob/develop/examples/SFMExample_bal.cpp), so should I expect the GTSAM solver to use any heuristic ordering algorithm inside the solver? I'm sure ceres-solver find the optimal ordering from its log:
Linear solver ordering 22106,16 22106,16.

Talking about the time measuring:

real	0m3.145s
user	0m13.053s
sys	0m1.102s

I believe we should take the 3.145s as the result, which is similar to that of 3-5s in your M1. The user counts for multiple threads. I rerun the test with TBB disabled and got:

real	0m4.894s
user	0m4.674s
sys	0m0.208s

which matches what you got from the M1. But it also shows TBB only improves the wall time a little bit (4.894 -> 3.145).

I further test SFMExample_bal_COLAMD_METIS, because I believe it tries to get the optimal ordering:

root@nixos:/tinynav/output/gtsam/build# time ./examples/SFMExample_bal_COLAMD_METIS /tinynav/problem-16-22106-pre.txt 
read 22106 tracks on 16 cameras
Initial error: 4.18566e+06
newError: 2.84007e+06
errorThreshold: 2.84007e+06 > 0
absoluteDecrease: 1345595.20952 >= 1e-05
relativeDecrease: 0.321477368985 >= 1e-05
newError: 428396.145787
errorThreshold: 428396.145787 > 0
absoluteDecrease: 2411669.40758 >= 1e-05
relativeDecrease: 0.849159768415 >= 1e-05
newError: 82756.3346956
errorThreshold: 82756.3346956 > 0
absoluteDecrease: 345639.811092 >= 1e-05
relativeDecrease: 0.806822877588 >= 1e-05
newError: 28524.7237457
errorThreshold: 28524.7237457 > 0
absoluteDecrease: 54231.6109499 >= 1e-05
relativeDecrease: 0.65531673375 >= 1e-05
newError: 21028.9020568
errorThreshold: 21028.9020568 > 0
absoluteDecrease: 7495.82168893 >= 1e-05
relativeDecrease: 0.262783322838 >= 1e-05
newError: 20482.7928745
errorThreshold: 20482.7928745 > 0
absoluteDecrease: 546.109182299 >= 1e-05
relativeDecrease: 0.0259694576932 >= 1e-05
newError: 20475.2556405
errorThreshold: 20475.2556405 > 0
absoluteDecrease: 7.53723398115 >= 1e-05
relativeDecrease: 0.000367978821411 >= 1e-05
newError: 20475.2532671
errorThreshold: 20475.2532671 > 0
absoluteDecrease: 0.00237339309388 >= 1e-05
relativeDecrease: 1.15915187363e-07 < 1e-05
converged
errorThreshold: 20475.2532671 <? 0
absoluteDecrease: 0.00237339309388 <? 1e-05
relativeDecrease: 1.15915187363e-07 <? 1e-05
iterations: 8 >? 100
Initial error: 4185660.76289
newError: 2840065.55023
errorThreshold: 2840065.55023 > 0
absoluteDecrease: 1345595.21265 >= 1e-05
relativeDecrease: 0.321477369734 >= 1e-05
newError: 428396.143992
errorThreshold: 428396.143992 > 0
absoluteDecrease: 2411669.40624 >= 1e-05
relativeDecrease: 0.84915976888 >= 1e-05
newError: 82756.334431
errorThreshold: 82756.334431 > 0
absoluteDecrease: 345639.809561 >= 1e-05
relativeDecrease: 0.806822877396 >= 1e-05
newError: 28524.7237205
errorThreshold: 28524.7237205 > 0
absoluteDecrease: 54231.6107104 >= 1e-05
relativeDecrease: 0.655316732953 >= 1e-05
newError: 21028.9020562
errorThreshold: 21028.9020562 > 0
absoluteDecrease: 7495.82166434 >= 1e-05
relativeDecrease: 0.262783322207 >= 1e-05
newError: 20482.7928745
errorThreshold: 20482.7928745 > 0
absoluteDecrease: 546.109181693 >= 1e-05
relativeDecrease: 0.0259694576651 >= 1e-05
newError: 20475.2556405
errorThreshold: 20475.2556405 > 0
absoluteDecrease: 7.53723400232 >= 1e-05
relativeDecrease: 0.000367978822444 >= 1e-05
newError: 20475.2532671
errorThreshold: 20475.2532671 > 0
absoluteDecrease: 0.00237339307205 >= 1e-05
relativeDecrease: 1.15915186297e-07 < 1e-05
converged
errorThreshold: 20475.2532671 <? 0
absoluteDecrease: 0.00237339307205 <? 1e-05
relativeDecrease: 1.15915186297e-07 <? 1e-05
iterations: 8 >? 100
COLAMD final error: 20475.2532671
METIS final error: 20475.2532671


Time comparison by solving /tinynav/problem-16-22106-pre.txt results:
22106 point tracks and 16 cameras
-Total: 0 CPU (0 times, 0 wall, 7.44 children, min: 0 max: 0)
|   -METIS ORDERING: 0.06 CPU (1 times, 0.063194 wall, 0.06 children, min: 0 max: 0)
|   -COLAMD ORDERING: 0.57 CPU (1 times, 0.574361 wall, 0.57 children, min: 0 max: 0)
|   -OPTIMIZE WITH METIS: 3.4 CPU (1 times, 3.397544 wall, 3.4 children, min: 0 max: 0)
|   -OPTIMIZE WITH COLAMD: 3.41 CPU (1 times, 3.423832 wall, 3.41 children, min: 0 max: 0)

real	0m7.575s
user	0m7.407s
sys	0m0.151s

It helps, but still far from my expectation (4.894 -> 3.39/3.42).

I'm not very familiar with the internals of GTSAM, and I have a few questions:

1. How good is the ordering found by METIS/COLAMD? Should we expect them to find an “optimal ordering”?
2. If not, could you share code showing how to manually specify a point-first ordering for this problem?
3. Will the batch factor idea get us from 3s down to about 0.5s, to get closer to Ceres’ speed?

Thanks!