Execution time of callback function

edit

I have a callback function that takes a laser scan, transforms it into cartesian coordinates and saves it to a class variable.

def rear_scan_cb(self, msg):
    internal_time = time.time()
    self.rear_scan_data = msg
    self.rear_scan_cart = CalibUtils.homogeneous(
        np.asarray(CalibUtils.polar_scan_to_cart(self.rear_scan_data, self.min_range, self.max_range)))
    print "elapsed ", time.time() - self.time
    print "elapsed internal ", time.time() - internal_time
    self.time = time.time()

self.time is a class variable that stores the last time the function finished executing. The output of my function shows the time elapsed since the last call of the function and the elapsed time from the beginning until the end of the function call (elapsed internal).

The problem is that the numbers do not add up. With an average frequency of 20 Hz for the laser scan (0.05s for each new scan) I get the following output:

elapsed internal  0.00101113319397
elapsed  0.138864994049
elapsed internal  0.00641489028931
elapsed  0.0383219718933
elapsed internal  0.00250887870789
elapsed  0.129732847214
elapsed internal  0.00207710266113
elapsed  0.0546798706055
elapsed internal  0.00196719169617
elapsed  0.0963840484619
elapsed internal  0.00415015220642
elapsed  0.0352799892426
elapsed internal  0.0046238899231
elapsed  0.0817019939423
elapsed internal  0.00347518920898
elapsed  0.138021945953
elapsed internal  0.0033700466156
elapsed  0.174504995346
elapsed internal  0.00218296051025

This doesn't make sense, and it also causes my laser scans to get buffered and processed slower than real life. What can be the cause here? (I am running on Gazebo)