Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Application hangs when trying to close file replay pipeline #2472

Closed
blackccpie opened this issue Oct 3, 2018 · 10 comments
Closed

Application hangs when trying to close file replay pipeline #2472

blackccpie opened this issue Oct 3, 2018 · 10 comments
Assignees
@RealSense-Customer-Engineering
Labels
question software

Comments

@blackccpie
Copy link

Required Info
Camera Model D415
Firmware Version 5.10.3
Operating System & Version Win 10
Platform PC
SDK Version 2.16.1
Language C++

Issue Description

It seems like since I upgraded to sdk version 2.16.1, my application sometimes hang when trying to close a replay pipeline (I'm playing bag files that have been recorded with a former sdk version). I'm starting to investigate, and it appears I get stuck in the pipeline::unsafe_stop() method, and more precisely when calling _active_profile->_multistream.stop(). This looks like a deadlock case, but I'm not really sure.

I'm going further in my investigations, but if someone has encountered the same problem and has a solution I'll be glad to hear.

Regards,

Albert
@blackccpie
Copy link
Author

EDIT : seems like I'm permanently stuck in the while loop at line 224 of concurrency.h, in the dispatcher thread.

@RealSense-Customer-Engineering
Copy link
Collaborator

[Realsense Customer Engineering Team Comment]
Hi @backccpie,

What's your previous working librealsense version? Please also enable the log "set LRS_LOG_LEVEL=DEBUG" to get the log file with more info.

@blackccpie
Copy link
Author

Hi @RealSense-Customer-Engineering, my previous working version of the sdk was 2.15.0.
I also forgot to mention I was using the newly functional realtime mode during my replay.
I will collect the logs asap.

@blackccpie
Copy link
Author

blackccpie commented Oct 4, 2018 •
edited
Loading

When the app exits fine I get:

04/10 11:23:53,442 DEBUG [10696] (ros_reader.h:60) Next message is a frame
 04/10 11:23:53,442 DEBUG [10696] (ros_reader.h:435) Trying to create an image frame from message
 04/10 11:23:53,442 INFO [2896] (archive.cpp:316) The user was holding on to 1 frames after stream 0x0000020197832500 stopped
 04/10 11:23:53,442 INFO [2896] (archive.cpp:316) The user was holding on to 1 frames after stream 0x0000020197832500 stopped
 04/10 11:23:53,442 INFO [2896] (archive.cpp:316) The user was holding on to 1 frames after stream 0x0000020196C603C0 stopped
 04/10 11:23:53,442 INFO [2896] (archive.cpp:316) The user was holding on to 1 frames after stream 0x0000020196C603C0 stopped
 04/10 11:23:53,442 INFO [2896] (archive.cpp:316) The user was holding on to 1 frames after stream 0x0000020196C603C0 stopped
 04/10 11:23:53,442 INFO [2896] (archive.cpp:316) The user was holding on to 1 frames after stream 0x0000020196C603C0 stopped
 04/10 11:23:53,442 DEBUG [2896] (archive.cpp:249) CallbackFinished,Depth,316,DispatchedAt,1.53865e+12
 04/10 11:23:53,442 DEBUG [2896] (archive.cpp:256) Frame Callback [Depth#316] overdue. (Duration: 35261.6ms, FPS: 30, Max Duration: 32ms)
 04/10 11:23:53,442 INFO [2896] (archive.cpp:326) All frames from stream 0x0000020196C603C0 are now released by the user
 04/10 11:23:53,442 DEBUG [2896] (archive.cpp:249) CallbackFinished,Depth,5af,DispatchedAt,1.53865e+12
 04/10 11:23:53,442 DEBUG [2896] (archive.cpp:256) Frame Callback [Depth#1455] overdue. (Duration: 1.53865e+12ms, FPS: 30, Max Duration: 32ms)
 04/10 11:23:53,442 INFO [2896] (archive.cpp:326) All frames from stream 0x000002019FC77DC0 are now released by the user
 04/10 11:23:53,442 DEBUG [2896] (archive.cpp:249) CallbackFinished,Color,0,DispatchedAt,1.53865e+12
 04/10 11:23:53,442 INFO [2896] (archive.cpp:326) All frames from stream 0x0000020197533020 are now released by the user
 04/10 11:23:53,442 DEBUG [2896] (archive.cpp:249) CallbackFinished,Depth,5af,DispatchedAt,1.53865e+12
 04/10 11:23:53,442 DEBUG [2896] (archive.cpp:256) Frame Callback [Depth#1455] overdue. (Duration: 1.53865e+12ms, FPS: 30, Max Duration: 32ms)
 04/10 11:23:53,442 INFO [2896] (archive.cpp:326) All frames from stream 0x0000020197762DC0 are now released by the user
 04/10 11:23:53,442 DEBUG [2896] (archive.cpp:249) CallbackFinished,Color,5a3,DispatchedAt,1.53865e+12
 04/10 11:23:53,442 DEBUG [2896] (archive.cpp:256) Frame Callback [Color#1443] overdue. (Duration: 1.53865e+12ms, FPS: 30, Max Duration: 32ms)
 04/10 11:23:53,442 INFO [2896] (archive.cpp:326) All frames from stream 0x00000201975F3030 are now released by the user
 04/10 11:23:53,442 DEBUG [2896] (archive.cpp:249) CallbackFinished,Depth,0,DispatchedAt,1.53865e+12
 04/10 11:23:53,442 DEBUG [2896] (archive.cpp:256) Frame Callback [Depth#0] overdue. (Duration: 1.53865e+12ms, FPS: 30, Max Duration: 32ms)
 04/10 11:23:53,442 INFO [2896] (archive.cpp:326) All frames from stream 0x0000020197832500 are now released by the user
 04/10 11:23:53,442 DEBUG [10696] (ros_reader.h:476) Created image frame: 0/1/2/0 500x2d0 5
 04/10 11:23:53,442 DEBUG [10696] (playback_device.cpp:370) Updating Time Base... m_base_sys_time 44f9cbf5c3b3 m_base_timestamp 16f
 04/10 11:23:53,442 DEBUG [10696] (playback_device.cpp:578) Dispatching frame 0/1/2/0
 04/10 11:23:53,457 DEBUG [10696] (archive.cpp:249) CallbackFinished,Color,77,DispatchedAt,1.53865e+12
 04/10 11:23:53,457 DEBUG [10696] (archive.cpp:256) Frame Callback [Color#119] overdue. (Duration: 1.53865e+12ms, FPS: 30, Max Duration: 32ms)
 04/10 11:23:53,457 ERROR [10696] (playback_device.cpp:470) Failed to read next frame from file: invalid map<K, T> key
 04/10 11:23:53,457 DEBUG [10696] (playback_sensor.cpp:141) Stop sensor 0
 04/10 11:23:53,457 DEBUG [10696] (playback_sensor.cpp:141) Stop sensor 1
 04/10 11:23:53,504 DEBUG [10696] (ros_file_format.h:430) RegexTopicQuery with expression: /device_0/sensor_(\d)+/info
 04/10 11:23:53,504 DEBUG [10696] (ros_file_format.h:430) RegexTopicQuery with expression: /device_0/sensor_0/(\w)+_(\d)+/info
 04/10 11:23:53,504 DEBUG [10696] (ros_file_format.h:430) RegexTopicQuery with expression: /device_0/sensor_0/Depth_0/tf
 04/10 11:23:53,504 DEBUG [10696] (ros_file_format.h:430) RegexTopicQuery with expression: /device_0/sensor_1/(\w)+_(\d)+/info
 04/10 11:23:53,520 DEBUG [10696] (ros_file_format.h:430) RegexTopicQuery with expression: /device_0/sensor_1/Color_0/tf
 04/10 11:23:53,520 DEBUG [10696] (playback_device.cpp:625) Catching up

When the app hangs I get:

04/10 11:19:21,747 DEBUG [4072] (ros_reader.h:60) Next message is a frame
 04/10 11:19:21,747 DEBUG [12792] (sync.cpp:99) I Depth--> Depth 122, 1536249932095.207520

 04/10 11:19:21,747 DEBUG [12792] (sync.cpp:258) SYNC (TS: )--> Depth 122 1536249932095.207520 

 04/10 11:19:21,747 DEBUG [4072] (ros_reader.h:435) Trying to create an image frame from message
 04/10 11:19:21,747 DEBUG [12792] (sync.cpp:516) fps 0 Depth 122 1536249932095.207520 
 04/10 11:19:21,747 DEBUG [12792] (sync.cpp:529) (TS: )Depth 122 1536249932095.207520 fps 30 gap 33.3333 next_expected: 1.53625e+12
 04/10 11:19:21,747 DEBUG [12792] (sync.cpp:516) fps 0 Depth 122 1536249932095.207520 
 04/10 11:19:21,747 DEBUG [12792] (sync.cpp:516) fps 0 Color 121 1536249932093.854492 
 04/10 11:19:21,747 DEBUG [12792] (syncer-processing-block.cpp:28) SYNCED: Color 121, 1536249932093.854492 Depth 122, 1536249932095.207520 
 04/10 11:19:21,747 DEBUG [12792] (sync.cpp:516) fps 0 Color 122 1536249932127.213623 
 04/10 11:19:21,747 DEBUG [12792] (sync.cpp:516) fps 0 Color 122 1536249932127.213623 
 04/10 11:19:21,747 DEBUG [12792] (sync.cpp:334) (TS: ) Color 122 1536249932127.213623  Wait for missing stream: 0 next expected 1536249932128.540771
 04/10 11:19:21,747 DEBUG [12792] (archive.cpp:463) CallbackStarted,Color,121,DispatchedAt,1.53864e+12
 04/10 11:19:21,755 DEBUG [4072] (ros_reader.h:476) Created image frame: 0/1/2/0 1280x720 5
 04/10 11:19:21,755 DEBUG [4072] (playback_device.cpp:578) Dispatching frame 0/1/2/0
 04/10 11:19:21,755 DEBUG [4072] (playback_device.cpp:534) Read action invoked
 04/10 11:19:21,755 DEBUG [4072] (ros_reader.h:60) Next message is a frame
 04/10 11:19:21,755 DEBUG [4072] (ros_reader.h:435) Trying to create an image frame from message
 04/10 11:19:21,755 DEBUG [4296] (sync.cpp:143) DISPATCH (TS: )--> Color 123 1536249932160.734863 

 04/10 11:19:21,755 DEBUG [4296] (sync.cpp:99) I Color--> Color 123, 1536249932160.734863

 04/10 11:19:21,755 DEBUG [4296] (sync.cpp:258) SYNC (TS: )--> Color 123 1536249932160.734863 

 04/10 11:19:21,755 DEBUG [4296] (sync.cpp:516) fps 0 Color 123 1536249932160.734863 
 04/10 11:19:21,755 DEBUG [4296] (sync.cpp:529) (TS: )Color 123 1536249932160.734863 fps 30 gap 33.3333 next_expected: 1.53625e+12
 04/10 11:19:21,755 DEBUG [4296] (sync.cpp:516) fps 0 Color 122 1536249932127.213623 
 04/10 11:19:21,755 DEBUG [4296] (sync.cpp:516) fps 0 Color 122 1536249932127.213623 
 04/10 11:19:21,755 DEBUG [4296] (sync.cpp:334) (TS: ) Color 122 1536249932127.213623  Wait for missing stream: 0 next expected 1536249932128.540771
 04/10 11:19:21,756 DEBUG [4072] (ros_reader.h:476) Created image frame: 0/0/1/0 640x480 1
 04/10 11:19:21,756 DEBUG [4072] (playback_device.cpp:578) Dispatching frame 0/0/1/0
 04/10 11:19:21,815 INFO [3012] (environment.cpp:85) Found 1 unreachable streams, 5 extrinsics deleted
 04/10 11:19:21,829 DEBUG [3012] (archive.cpp:249) CallbackFinished,Color,0,DispatchedAt,1.53864e+12
 04/10 11:19:21,829 DEBUG [3012] (archive.cpp:256) Frame Callback [Color#0] overdue. (Duration: 1.53864e+12ms, FPS: 30, Max Duration: 32ms)
 04/10 11:19:21,829 DEBUG [3012] (archive.cpp:463) CallbackStarted,Color,1443,DispatchedAt,1.53864e+12
 04/10 11:19:21,829 DEBUG [3012] (archive.cpp:249) CallbackFinished,Color,1442,DispatchedAt,1.53864e+12
 04/10 11:19:21,829 DEBUG [3012] (archive.cpp:256) Frame Callback [Color#1442] overdue. (Duration: 1.53864e+12ms, FPS: 30, Max Duration: 32ms)
 04/10 11:19:21,829 DEBUG [3012] (archive.cpp:249) CallbackFinished,Depth,1453,DispatchedAt,1.53864e+12
 04/10 11:19:21,829 DEBUG [3012] (archive.cpp:256) Frame Callback [Depth#1453] overdue. (Duration: 1.53864e+12ms, FPS: 30, Max Duration: 32ms)
 04/10 11:19:21,829 DEBUG [3012] (archive.cpp:249) CallbackFinished,Depth,1453,DispatchedAt,1.53864e+12
 04/10 11:19:21,829 DEBUG [3012] (archive.cpp:256) Frame Callback [Depth#1453] overdue. (Duration: 1.53864e+12ms, FPS: 30, Max Duration: 32ms)
 04/10 11:19:21,829 INFO [3012] (archive.cpp:326) All frames from stream 0x00000188DD7EA020 are now released by the user
 04/10 11:19:21,830 DEBUG [3012] (archive.cpp:249) CallbackFinished,Color,0,DispatchedAt,1.53864e+12
 04/10 11:19:21,830 DEBUG [3012] (archive.cpp:256) Frame Callback [Color#0] overdue. (Duration: 177.022ms, FPS: 30, Max Duration: 32ms)
 04/10 11:19:21,830 INFO [3012] (archive.cpp:326) All frames from stream 0x00000188DCF6D070 are now released by the user
 04/10 11:19:21,832 INFO [3012] (archive.cpp:316) The user was holding on to 1 frames after stream 0x00000188DD7FB6F0 stopped
 04/10 11:19:21,832 INFO [3012] (archive.cpp:316) The user was holding on to 1 frames after stream 0x00000188DD81C490 stopped
 04/10 11:19:21,832 INFO [3012] (archive.cpp:316) The user was holding on to 1 frames after stream 0x00000188DD7FB6F0 stopped
 04/10 11:19:21,832 INFO [3012] (archive.cpp:316) The user was holding on to 1 frames after stream 0x00000188DD81C490 stopped
 04/10 11:19:21,832 INFO [3012] (archive.cpp:316) The user was holding on to 1 frames after stream 0x00000188DD7FB6F0 stopped
 04/10 11:19:21,832 INFO [3012] (archive.cpp:316) The user was holding on to 1 frames after stream 0x00000188DD81C490 stopped
 04/10 11:19:21,924 DEBUG [3012] (playback_sensor.cpp:141) Stop sensor 0
 04/10 11:19:21,924 DEBUG [3012] (archive.cpp:249) CallbackFinished,Depth,123,DispatchedAt,1.53864e+12
 04/10 11:19:21,924 DEBUG [3012] (archive.cpp:256) Frame Callback [Depth#123] overdue. (Duration: 1.53864e+12ms, FPS: 30, Max Duration: 32ms)
 04/10 11:19:21,924 DEBUG [3012] (archive.cpp:249) CallbackFinished,Depth,124,DispatchedAt,1.53864e+12
 04/10 11:19:21,924 DEBUG [3012] (archive.cpp:256) Frame Callback [Depth#124] overdue. (Duration: 1.53864e+12ms, FPS: 30, Max Duration: 32ms)

In the latter case I don't get the Stop sensor 1 log.

This brings me to another question as I'm checking my code for errors : I'm using the pipeline::poll_for_frames method to query my frames, but it sometimes returns false even when the stream has not ended. In non-realtime mode, I would have expected to get all the frames of the file, without having poll_for_frames to return false, isn't that right?

@dorodnic
Copy link
Contributor

dorodnic commented Oct 4, 2018

@matkatz please take a look

@blackccpie blackccpie mentioned this issue Oct 16, 2018
Closed
@zhouwg zhouwg mentioned this issue Nov 8, 2018
Closed
@ogoshen ogoshen mentioned this issue Nov 11, 2018
Closed
@zhouwg zhouwg mentioned this issue Nov 23, 2018
Closed
@matkatz matkatz mentioned this issue Dec 5, 2018
Merged
@matkatz
Copy link
Contributor

matkatz commented Dec 11, 2018

Hi @blackccpie
Regarding:

I'm using the pipeline::poll_for_frames method to query my frames, but it sometimes returns false even when the stream has not ended. In non-realtime mode, I would have expected to get all the frames of the file, without having poll_for_frames to return false, isn't that right?

When working in non-realtime mode, poll_for_frames is still limited by the file reading speed from the HDD, so it is possible for poll_for_frames to return false.

Regarding the hang issue:
#2849 fix an issue that may be related to the hang that you saw, it is currently merged to the development branch and will be part of the next release.

@blackccpie
Copy link
Author

Hi @matkatz , thanks for the explanation, it's clearer for me now.
I'll have a give a try with the next release to see if my problem is solved.
By the way do you have an opinion concerning my question about the playback stop condition in this comment?

Regards

@mcasl mcasl mentioned this issue Feb 7, 2019
Closed
@RealSenseCustomerSupport
Copy link
Collaborator

@blackccpie Could you please have a try with latest release to see if still have issue? Thanks!

@blackccpie
Copy link
Author

Hi @RealSenseCustomerSupport, in fact since matkatz answer I was waiting for a release version to spent some time on upgrading/testing, but since then there only have been pre-releases. Do you know when the next major release version will be out? thx

@blackccpie
Copy link
Author

@RealSenseCustomerSupport : I took some time to test the pre-release v2.18.1, and the issue seems fixed. Anyway I'm still interested to know when the next official release will be available.

Regards

@ev-mp ev-mp mentioned this issue Sep 5, 2019
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@RealSense-Customer-Engineering RealSense-Customer-Engineering

Labels
question software
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@dorodnic @blackccpie @matkatz @RealSense-Customer-Engineering @RealSenseCustomerSupport