IntelRealSense / librealsense

Intel® RealSense™ SDK
https://www.intelrealsense.com/
Apache License 2.0
7.45k stars 4.81k forks source link

Number of frames in .bag file does not correspond to expected number of frames #8949

Closed pasandal closed 2 years ago

pasandal commented 3 years ago

Required Info
Camera Model D435I
Firmware Version 05.12.12.100
Operating System & Version Win 10
Platform PC
SDK Version 2.44.0.3073
Language python
Segment others

Issue Description

After upgrading from pyrealsense2==2.35.0.1791 to pyrealsense2==2.44.0.3073, the number of frames in the recorded bag file does not correspond the the expected number of frames in the bag file.

Here is an example code to illustrate the issue:

import time
import pyrealsense2 as rs2

camera_framerate = 30
row = 480
col = 848

def enable_all_streams(config):
    config.enable_stream(
        stream_type=rs2.stream.depth,
        width=col,
        height=row,
        format=rs2.format.z16,
        framerate=camera_framerate,
    )
    config.enable_stream(
        stream_type=rs2.stream.color,
        width=col,
        height=row,
        format=rs2.format.bgr8,
        framerate=camera_framerate,
    )

#Make recording
duration = 5
bag_path = r"c:\temp\recording.bag"
config = rs2.config()
pipeline = rs2.pipeline()
ctx = rs2.context()
devices = ctx.query_devices()
serial_number = devices[0].get_info(rs2.camera_info.serial_number)
config.enable_device(serial_number)
enable_all_streams(config)
config.enable_record_to_file(bag_path)

pipeline.start(config)
#Wait for 5 seconds
time.sleep(duration)
pipeline.stop()

#Read bag file
config = rs2.config()
pipeline = rs2.pipeline()
config.enable_device_from_file(bag_path, repeat_playback=False)
enable_all_streams(config)
pipeline_profile = pipeline.start(config)
playback = pipeline_profile.get_device().as_playback()
playback.set_real_time(False)

success = True
frame_number = 0
while success:
    success, frameSet = pipeline.try_wait_for_frames(1000)
    frame_number += 1

print(f"Numbers of frames read from the bag file: {frame_number} | Expected number of frames: {camera_framerate*duration}")

When using pyrealsense2==2.35.0.1791 the result is: Numbers of frames read from the bag file: 136 | Expected number of frames: 150 with pyrealsense2==2.44.0.3073 the result is: Numbers of frames read from the bag file: 270 | Expected number of frames: 150

The number of frames read from the bag file is doubled when using the 2.44.0.3073 version. Have you changed something in the SDK that I should be aware of, or is this a bug?

Regards, Paul

MartyG-RealSense commented 3 years ago

Hi @pasandal I am not aware of a change between these SDK versions that would radically alter your results.

I would not recommend placing confidence in calculating an expected number of frames by multiplying framerate by duration. This may provide an 'ideal' figure to use as a guideline. In practice though there are real-world factors that will affect the actual total number of frames in the bag, such as dropped frames during recording.

The code of your frame-counter frame_number looks okay to me, and you are correctly preventing bag looping and setting set_real_time to false.

It looks as though the script uses a sleep period to set a 5 second duration from the start of the script before the pipeline is stopped. I wonder if it may work better to put a timer check into the frame count mechanism, so if the value of frame_number is greater than *camera_framerateduration** (your expected maximum bag length) then the pipeline is stopped.

I also note that you are recording depth and color together. It may therefore be worth enforcing a constant frame rate when recording to prevent a frame-rate dip. The link below provides details of Python code for how to do so when auto-exposure is enabled by disabling a setting called Auto-Exposure Priority.

https://github.com/IntelRealSense/librealsense/issues/8205#issuecomment-764860412

pasandal commented 3 years ago

Thanks for feedback @MartyG-RealSense .

Yes, replacing camera_framerate*duration with int(camera_framerate*playback.get_duration().total_seconds()) will provide a more accurate result. The actual duration turns out to be 4.898734 seconds This means that I received 270 frames from a bag file with duration of 4.898734 seconds which gives a fps value of 270.0 / 4.898734 = 55 fps As seen in the code above, I enabled the stream using 30 fps on both depth and color.

If I run the same code with pyrealsense2==2.35.0.1791 I get in total 135 frames within 4.83415 seconds which results in 135 / 4.83415 = 27.9 fps

If I remove either color or depth stream I get the expected FPS (around 30) with both SDK versions.

Why does the frame rate of the two SDK versions deviate so much when recording both depth and color? Paul

MartyG-RealSense commented 3 years ago

The amount of time that has passed between 2.35.0 and 2.44.0 would make it very difficult to identify a specific cause for a change in performance. In these situations, it is easier to try older versions in small steps (e.g 2.37.0, 2.39.0, 2.41.0 etc) to narrow down the point in the SDK's history at which the behavior of the script changes. It may not be worth doing so though unless you are curious, as you will still likely need to return to using the modern SDK version afterwards.

A notable historical change was when there were internal changes in the firmware from firmware version 5.12.8.200 onwards so that a minimum of SDK version 2.39.0 was required

image

A way to validate the FPS of the bag's depth and color streams would be to launch the RealSense Viewer tool without a camera plugged in and then import the bag into the Viewer, either by using the Add Source option at the top of the options side-panel or by drag-and-dropping the bag into the center panel of the Viewer. The bag will begin automatically playing, and if you left-click on the 'i' option at the top of each stream panel so that the 'i' is colored blue (On) then the FPS of each stream will be displayed.

image

pasandal commented 3 years ago

@MartyG-RealSense this is not a performance issue. The issue is that the python SDK reads 270 frames in a file where there only exists 135 frames.

If i change the frame_number += 1 counter with the built-in frameSet.get_frame_number() method, like this:

while success:
    success, frameSet = pipeline.try_wait_for_frames(1000)
    if success:
        frame_number = frameSet.get_frame_number()
        print(frame_number)

the printed result is:

....
....
128
128
129
129
130
130
131
131
132
132
133
133
134
134
135
135

This indicates that pipeline.try_wait_for_frames(1000) method reads each frames two times before proceeding to next frame. I tried to add a time.sleep(0.1) between each frame read to check if I was reading the frame too fast, but the result was the same. When using the pyrealsense2==2.35.0.1791 version however, the printed result is:

....
....
128
129
130
131
132
133
134
135

Realsense.Viewer is showing the correct values: 135 frames / around 30 fps

The change of behavior happens when going from ver 2.40.0.2483 to ver 2.41.0.2666. In 2.40.0.2483 the frameSet.get_frame_number() increases between each frame and in 2.41.0.2666 the frameSet.get_frame_number() increases every second frame.

MartyG-RealSense commented 3 years ago

The first pipeline open-close section handles the bag recording part of the program and then the second pipeline open is for the playback, yes?

image

My next question would be the method that you use to build librealsense on Windows. Do you use the automated installer file on the Releases page or build it with CMake?

If the frame count is reported consistently as 2x the correct total every time, a hacky workaround til a permanent solution is found may be to increment frame_number by 0.5 instead of 1.

pasandal commented 3 years ago

@MartyG-RealSense, you are correct about the pipeline start/stop logic.

I installed pyrealsense2 via pip with the following command: pip install pyrealsense2==2.44.0.3073, and downloaded the stand alone Intel.RealSense.Viewer.exe from you release page.

An incorrect frame number is not the main issue here. The biggest burden is that we are reading duplicate frames which leads to a 2x post-processing time and a wrong fps when storing the frames in a mp4 file after the video processing.

Yes, a workaround could be to discard every second frame, but then I prefer to use the old SDK version until it is fixed.

Are you able to replicate the duplicate frame behavior when using the 2.44.0.3073 version @MartyG-RealSense?

MartyG-RealSense commented 3 years ago

My computer is not set up to run pyrealsense2 and so I cannot perform a validation test of the duplicate frame behavior.

Duplication of frames can occur during recording of a bag, if the stream has a 'hiccup' and returns to the last known good frame before continuing onwards. I have not seen a case before where every single frame is duplicated though. If you are using the same bag file on 2.35.0 and 2.44.0 then that would suggest that the source of the problem is not within the bag-file.

Given that the row of dots at the top of the frame number list is printed twice, this makes me wonder whether the frames are actually being duplicated in reality or whether the on-screen information is just being printed twice.

image

pasandal commented 3 years ago

Sorry for the confusion. I typed in the dots manually to illustrate that there are in addition 127 frame numbers printed out.

I ran a test to identify the source of the problem and this is the result:

  1. Make bag file with 2.44.0 and read it with 2.35.0 results in none duplicated frames
  2. Make bag file with 2.35.0 and read it with 2.44.0 results in duplicated frames
  3. Make bag file with 2.35.0 and read it with 2.35.0 results in none duplicated frames
  4. Make bag file with 2.44.0 and read it with 2.44.0 results in duplicated frames
  5. Make bag file with 2.44.0 and read it with RealSense Viewer 2.43.0 results in none duplicated frames

It is quite clear that the source of the problem is not the bag-file, but the pipeline.try_wait_for_frames() method.

Do you have the opportunity to ask someone in your team to do a validation test @MartyG-RealSense?

MartyG-RealSense commented 3 years ago

For the moment, this particular phenomenon (a repeat of every frame instead of just some frames) seems to be an isolated case rather than a suspected bug to refer for deeper testing, as there have not been reports of the same effect from other RealSense users.

Now that librealsense 2.45.0 and Python wrapper 2.45.0.3217 are available, would it be possible to upgrade again and check whether the same effect is present in the latest SDK?

Also, does the problem still occur if you use wait_for_frames instead of try_wait_for_frames? The difference between the two instructions is that if there is a time-out when using try_wait_for_frames then it simply returns a 'False' result instead of throwing an exception.

https://github.com/IntelRealSense/librealsense/issues/2422#issuecomment-423254709

Thanks very much!

pasandal commented 3 years ago

@MartyG-RealSense , One user has to be the first. :)

To verify that this is a bug and not an isolated case, I did the following:

  1. Downloaded outdoors.bag file from your github page Outdoors scene captured with D415 pre-production sample (Depth from Stereo)
  2. Installed python 3.9 and 2.45.0.3217 SDK on a clean windows 10 computer
  3. Ran the code below which resulted in count: 380
  4. Downgraded SDK to 2.35.0.1791
  5. Ran the code again which resulted in count: 194
import pyrealsense2 as rs2

path = r"C:\temp\outdoors.bag"
config = rs2.config()
pipeline = rs2.pipeline()
config.enable_stream(rs2.stream.depth, 1280, 720, rs2.format.z16, 30)
config.enable_stream(rs2.stream.color, 640, 480, rs2.format.rgb8, 30)

config.enable_device_from_file(path, repeat_playback=False)

pipeline_profile = pipeline.start(config)
playback = pipeline_profile.get_device().as_playback()
playback.set_real_time(False)
count = 0
success = True

while success:
    try:
        frames = pipeline.wait_for_frames(1000)
        print(frames.get_frame_number())
        count += 1

    except:
        success = False

print(count)
MartyG-RealSense commented 3 years ago

Thanks very much for your careful testing. I will seek further advice from Intel. Thank you for your patience!

pasandal commented 3 years ago

Thank you. I am glad you are looking into it.

MartyG-RealSense commented 3 years ago

After discussion with Intel, I set up a Python 3.9.5 installation on a Windows 10 computer with the latest pyrealsense2 wrapper and librealsense 2.45.0. I ran your script and confirmed the repeating frames. I have provided Intel with a log of the frame-counter output and will discuss it further with them.

pasandal commented 3 years ago

Ok. Thanks for update!

MartyG-RealSense commented 3 years ago

Hi @pasandal An official bug report about the duplicating frame-count when reading a bag file in pyrealsense2 on Windows 10 has been filed with Intel. This case should be left open whilst that bug report is active. Thanks again for reporting the issue! In the meantime, the best solution for you may be to continue using SDK 2.35.0 for your project.

shivak7 commented 3 years ago

I can confirm this is definitely not an isolated case. I spent days trying to figure out what went wrong in my C++ code when I finally narrowed it down to differences between SDK versions 2.45 and 2.36. I examined the problem in more detail by looking at individual frame numbers and timestamps directly from the stream of the bag file, and this is what I found. It's not exactly duplicating framesets. However there are duplicate frames across different framesets. In other words, with the newer SDKs each frameset staggers color and depth alternatively.

For example the original sequence of frameset grabs during wait_for_frames() or poll_for_frames() is: (c1,d1), (c2,d2), (c3,d3), ... (c_n, d_n) where, c and d stand for color and depth frames. They are best matched according to timestamps.

With the new SDK version this is the sequence I get: (c1,d1), (c1, d2), (c2,d2), (c2,d3), (c3,d3), (c3, d4)... etc.

As you can see duplicate frames across framesets are alternatively staggered almost like some bad interpolation instead of properly matching frames together. This leads to approximately doubling of the frames as reported by psandal. Hope this information helps. I will try to post actual stats from my bag file to illustrate this issue.

Edit: Posting actual numbers from my tests: First with the 2.36 SDK. Frames are optimally matched. There are rare duplicates but over all things add up. Each frameset grab results in unique color and depth frames as you can see from the relative timestamps. (relative timestamps are calculated by subtracting the first frame's timestamp from the current timestamp and dividing by 1000 to convert into seconds).

Frameset Depth_Frame Color_Frame Time_difference Frame: 0 Time1:0.01666 Time2:0.009694 Difference:0.006966 Frame: 1 Time1:0.033321 Time2:0.026494 Difference:0.006827 Frame: 2 Time1:0.049982 Time2:0.043294 Difference:0.006688 Frame: 3 Time1:0.066642 Time2:0.060094 Difference:0.006548 Frame: 4 Time1:0.083303 Time2:0.076894 Difference:0.006409 Frame: 5 Time1:0.099964 Time2:0.093694 Difference:0.00627 Frame: 6 Time1:0.116624 Time2:0.110494 Difference:0.00613 Frame: 7 Time1:0.133285 Time2:0.127294 Difference:0.005991 Frame: 8 Time1:0.149946 Time2:0.144094 Difference:0.005852 Frame: 9 Time1:0.166606 Time2:0.160894 Difference:0.005712 Frame: 10 Time1:0.183267 Time2:0.177694 Difference:0.005573

Now with the 2,45 SDK this is what I get:

Frameset Depth_Frame Color_Frame Time_difference Frame: 0 Time1:0.016661 Time2:0.009555 Difference:0.007106 Frame: 1 Time1:0.016661 Time2:0.026355 Difference:-0.009694 Frame: 2 Time1:0.016661 Time2:0.043155 Difference:-0.026494 Frame: 3 Time1:0.033321 Time2:0.043155 Difference:-0.009834 Frame: 4 Time1:0.033321 Time2:0.059955 Difference:-0.026634 Frame: 5 Time1:0.049982 Time2:0.059955 Difference:-0.009973 Frame: 6 Time1:0.049982 Time2:0.076755 Difference:-0.026773 Frame: 7 Time1:0.066643 Time2:0.076755 Difference:-0.010112 Frame: 8 Time1:0.066643 Time2:0.093555 Difference:-0.026912 Frame: 9 Time1:0.083303 Time2:0.093555 Difference:-0.010252 Frame: 10 Time1:0.083303 Time2:0.110355 Difference:-0.027052

Here you can see that going by frame timestamp as an ID, that each frameset is different but frames are usually staggered alternatively. Additionally, the color frame timestamps are not the same for some reason across the two different SDKs!

MartyG-RealSense commented 3 years ago

Thanks very much @shivak7 for the detailed feedback about your own experiences with this issue!

shivak7 commented 3 years ago

Thanks very much @shivak7 for the detailed feedback about your own experiences with this issue!

Glad to help. I too would like this fixed ASAP. If @pasandal is correct in his claim that 2.43 does not result in duplicate frames when reading from a bag file, then I think I've possibly narrowed down the issue to the file: concurrency.h or a related file which might have been affected during the Mar 21st update.

shivak7 commented 3 years ago

Actually further investigation into 2.43 suggests that this fix might be the potential cause of this bug: #8378

MartyG-RealSense commented 3 years ago

@shivak7 I cannot provide a time estimate for when the bug report related to the repeating frames issue will be actioned upon, and so cannot guarantee an ASAP fix. Your feedback about possible causes will be able to read by Intel RealSense team members though when handling the bug report.

shivak7 commented 3 years ago

@MartyG-RealSense That's OK. I've reverted to SDK version 2.36 and am using a custom workaround to handle another bug which was the reason I upgraded to 2.45 in the first place. I'm good for now.

MartyG-RealSense commented 3 years ago

Thanks very much @shivak7 for the update!

As mentioned earlier, this case will remain open whilst there is an active bug report relating to this issue.

pasandal commented 2 years ago

@MartyG-RealSense Would it be possible to get an estimate on when this bug will be looked at? I noticed that the issue is not included in the Release Note - Known issues list. Is it because you have placed the issue in a kind of backlog? I consider it as a pretty critical bug which should have been given more attention...

MartyG-RealSense commented 2 years ago

The bug has been officially logged with Intel but there is no further information to provide or a time estimate regarding when a fix might be delivered if it is confirmed to be a bug. I suggest trying 2.49.0 to see whether the problem has been corrected as a side-effect of changes to other systems in the SDK.

Nir-Az commented 2 years ago

Hi @pasandal , I ran the python script attached on latest LibRealSense version 2.49 and the result is as expected (136 frames) I am not sure what was the version that the fix was introduce but I am glad to say the issue is no longer exist. Please update if you find it fixed on latest release.

Thanks for notifying on the issue.

MartyG-RealSense commented 2 years ago

@Nir-Az Thanks very much for your help! The Intel bug report DSO-17075 associated with this case has now been closed.

MartyG-RealSense commented 2 years ago

Case closed due to the associated Intel bug report DSO-17075 having been closed.