It appears that Tango is dropping image frames when I try to get depth data, image data, and pose data at the same time.
I am trying to capture depth and image frames and synchronize them with pose data. Using the C point-cloud-jni-example I added code to dump point cloud data to memory buffers and then to files. I added a callback for onFrameAvailable() and copied image data to buffers and then to files. Since the image data is at 30 Hz and the depth data is at ~5 Hz I naively expected the latest image to match fairly closely with the latest depth frame. The timestamps were not very close. In some cases they were different by more than 100 milliseconds. So I started to investigate the timing on the onXYZijAvailable(), onFrameAvailable(), and onPoseAvailable() callbacks and the corresponding data timestamps.
I added logcat dumps to each callback and printed out system time (std::chrono::system_clock::now()) and the TangoSystem timestamp of the returned data, whether depth, image, or pose. Some of this was described in exactly how do we compute timestamp differentials?.
Here is some pose timing. The sys time is the current clock time when the callback is executed. The pose timestamp is from the actual pose struct.
sys time pose timestamp
TM CLK Pose 10.008419 245.976464
TM CLK Pose 10.025983 246.009791
TM CLK Pose 10.124470 246.043119
TM CLK Pose 10.133542 246.076447
TM CLK Pose 10.147136 246.109774
TM CLK Pose 10.192470 246.143102
TM CLK Pose 10.200370 246.176430
TM CLK Pose 10.225367 246.209757
TM CLK Pose 10.300509 246.243085
TM CLK Pose 10.311827 246.276413
TM CLK Pose 10.335946 246.309740
TM CLK Pose 10.399209 246.343068
TM CLK Pose 10.407704 246.376396
TM CLK Pose 10.426889 246.409723
TM CLK Pose 10.504403 246.443051
The corresponding differences from pose to pose are shown here. The pose timing is rock solid at 33 msec based on the recorded timestamps. The callback times vary quite a bit, presumably due to the load of the application.
time: 0.017564 pose: 0.033327
time: 0.098487 pose: 0.033328
time: 0.009072 pose: 0.033328
time: 0.013594 pose: 0.033327
time: 0.045334 pose: 0.033328
time: 0.007900 pose: 0.033328
time: 0.024997 pose: 0.033327
time: 0.075142 pose: 0.033328
time: 0.011318 pose: 0.033328
time: 0.024119 pose: 0.033327
time: 0.063263 pose: 0.033328
time: 0.008495 pose: 0.033328
time: 0.019185 pose: 0.033327
time: 0.077514 pose: 0.033328
time: 0.011892 pose: 0.033328
Here is some depth timing and corresponding differences. The timestamps are very stable at about 0.2 seconds.
sys time : xyz timestamp
TM CLK XYZ 10.161695 246.017013
TM CLK XYZ 10.363448 246.216639
TM CLK XYZ 10.595306 246.438693
TM CLK XYZ 10.828368 246.668223
TM CLK XYZ 11.025787 246.890277
TM CLK XYZ 11.233364 247.097379
TM CLK XYZ 11.433941 247.297005
TM CLK XYZ 11.633176 247.496631
TM CLK XYZ 11.830650 247.696257
time: 0.201753 depth: 0.199626
time: 0.231858 depth: 0.222054
time: 0.233062 depth: 0.229530
time: 0.197419 depth: 0.222054
time: 0.207577 depth: 0.207102
time: 0.200577 depth: 0.199626
time: 0.199235 depth: 0.199626
time: 0.197474 depth: 0.199626
time: 0.196935 depth: 0.199626
Here is some image timing. The lines marked "---" are problem frames.
sys time : img timestamp
TM CLK Img 10.041056 246.005896
TM CLK Img 10.074105 246.105709 -----
TM CLK Img 10.106492 246.105709
TM CLK Img 10.142581 246.138980
TM CLK Img 10.176176 246.172251
TM CLK Img 10.241146 246.205522
TM CLK Img 10.274909 246.305335 -----
TM CLK Img 10.317819 246.305335
TM CLK Img 10.361682 246.345225
TM CLK Img 10.397533 246.390139
TM CLK Img 10.472859 246.430886
TM CLK Img 10.514923 246.538175 -----
TM CLK Img 10.551663 246.545651
TM CLK Img 10.585960 246.586398
TM CLK Img 10.626671 246.620526
TM CLK Img 10.705709 246.656249
TM CLK Img 10.734324 246.767705 -----
TM CLK Img 10.774233 246.768562
TM CLK Img 10.808848 246.804285
TM CLK Img 10.847230 246.842580
TM CLK Img 10.927872 246.878303
TM CLK Img 10.957309 246.989759 -----
TM CLK Img 10.991136 246.990616
Here is the corresponding time differences for the above list.
time: 0.033049 image: 0.099813
time: 0.032387 image: 0.000000
time: 0.036089 image: 0.033271
time: 0.033595 image: 0.033271
time: 0.064970 image: 0.033271
time: 0.033763 image: 0.099813
time: 0.042910 image: 0.000000
time: 0.043863 image: 0.039890
time: 0.035851 image: 0.044914
time: 0.075326 image: 0.040747
time: 0.042064 image: 0.107289
time: 0.036740 image: 0.007476
time: 0.034297 image: 0.040747
time: 0.040711 image: 0.034128
time: 0.079038 image: 0.035723
time: 0.028615 image: 0.111456
time: 0.039909 image: 0.000857
time: 0.034615 image: 0.035723
time: 0.038382 image: 0.038295
time: 0.080642 image: 0.035723
time: 0.029437 image: 0.111456
time: 0.033827 image: 0.000857
Notice that every 4 frames there is a big delay in the image time, roughly 100 msec. This is followed by two frames with the same or nearly the same timestamp. Even in cases where the timestamp on two successive images is identical the callback still fires to indicate a new frame. The result is that I am missing every fifth frame of video. That stinks for an application trying to match depth and image data.
I have stripped any extra processing out of the code. In the callbacks the only thing that happens is the data gets copied out to static buffers. The rendering of the point cloud is still being done in the normal rendering thread.
So, what gives? Can the Tango device not handle depth, image, and pose callbacks all running at the same time? Do I need to use UpdateTexture() instead of onFrameAvailable()?
