Accuracy / resolution of ROS time

edit

I was doing some quick profiling of the execution time of a piece of code, and noticed that I was getting different answers depending on what method I use to get the current time.

EDIT: original test removed, added test as per Eric's suggestion.

I am running on: Ubuntu, 3.0.0-17-generic

The following code is inserted in a callback function, which is called asynchronously.

struct timeval s_get, e_get;
timespec s_crt, e_crt;
ros::Time s_ros, e_ros;

gettimeofday(&s_get, NULL);
clock_gettime(CLOCK_REALTIME,  &s_crt);
s_ros = ros::Time::now();

// **** do something here... ****

gettimeofday(&e_get, NULL);
clock_gettime(CLOCK_REALTIME,  &e_crt);
e_ros = ros::Time::now();

// print results
double dur_get = ((e_get.tv_sec * 10e6 + e_get.tv_usec) -
                  (s_get.tv_sec * 10e6 + s_get.tv_usec)) * 1e-3;
double dur_crt = ((e_crt.tv_sec * 10e9 + e_crt.tv_nsec) - 
                  (s_crt.tv_sec * 10e9 + s_crt.tv_nsec)) * 1e-6;
double dur_ros = (e_ros - s_ros).toNSec() * 1e-6;

printf("Dur [ms]: %.1f \t %.1f \t %.1f \n", dur_get, dur_crt, dur_ros);

Output:

Dur [ms]: 8.5     8.5      0.0 
Dur [ms]: 6.7     6.7     10.1 
Dur [ms]: 15.9     15.9     10.1 
Dur [ms]: 6.2     6.2      0.0 
Dur [ms]: 13.6  13.6     10.1 
Dur [ms]: 15.2  15.2     20.2 
Dur [ms]: 13.0  13.0     20.2 
Dur [ms]: 10.5  10.5     10.1 
Dur [ms]: 14.2  14.2     20.2 
Dur [ms]: 11.2  11.2     10.1 
Dur [ms]: 10.5  10.5     10.2 
Dur [ms]: 10.4  10.4     10.1 
Dur [ms]: 16.4  16.4     20.1 
Dur [ms]: 11.0  11.0     10.1 
Dur [ms]: 17.6  17.6     20.2 
Dur [ms]: 12.6  12.6     20.1 
Dur [ms]: 18.5  18.5     20.1 
Dur [ms]: 18.1  18.1     20.1 
Dur [ms]: 14.8  14.8     10.1 
Dur [ms]: 5.5     5.5      0.0 
Dur [ms]: 8.5     8.5     10.1 
Dur [ms]: 11.4  11.4     10.1 
Dur [ms]: 18.4  18.4     20.2 
Dur [ms]: 14.3  14.3     10.1 
Dur [ms]: 10.8  10.8     10.1 
Dur [ms]: 7.9     7.8      0.0 
Dur [ms]: 17.2  17.2     20.2

Consclusion

gettimeofday and clock_gettime result in similar durations, but ros::Time::now() durations are different.

I noticed that if I insert the example above in a loop at startup (instead of asynchronously inside a function), and tell it to sleep a certain time each iteration, I get 0.0 ms reported duration by ROS, and the correct duration with the other 2 methods. My only explanation is that ros::spinOnce() hasn't been called, and this is interfering with ros::Time::now().

This has very little impact on my profiling. However, I sometimes use the ros time to calculate velocities or other quantities in the form x/dt. In this case, poor temporal resolution like this would make a huge difference.

Could anyone comment on this? Am I doing something wrong?

EDIT 2

I was running using ... (more)