Raspistill hangs on capture

[jetibest]

Using additional custom logging added to RaspiStill.c, I found that sometimes (arbitrarily) the following line hangs indefinitely:

if (mmal_port_parameter_set_boolean(camera_still_port, MMAL_PARAMETER_CAPTURE, 1) != MMAL_SUCCESS) *

In order to deal with this issue, I have set a timeout that kills raspistill and then restart it again. However, I would like to know how to further investigate this issue. Does anybody have any experience or ideas about this? Is it normal behavior for it to occassionally hang? What kind of direction should I be looking for?

Context: I am succesfully using raspistill to make a lot of photos every day (v2 camera board). I fork raspistill from a C++ application, using a custom version of RaspiStill.c where I send "keypresses" to raspistill to generate a photo. C++ keeps raspistill running for a few photos, and when it does not need to be used anymore (usually ~1 minute) it terminates the raspistill again. However, hanging on capture seems unrelated to these changes I made, and there is no visible correlation with how long raspistill has been open etc. I could not reproduce it consistently yet.

* I didn't use the code-block, that horrible grey text is unreadable!

[jamesh]

How do you terminate your app? If you are killing then it is possible that some camera shutdown code might not be run, which might stop the next run from working. If you are letting raspistill shut down normally, that should be OK.

[jetibest]

How do you terminate your app? If you are killing then it is possible that some camera shutdown code might not be run, which might stop the next run from working. If you are letting raspistill shut down normally, that should be OK.

Thank you for your reply.
Termination of the app is not applicable since that would mean it should hang on the first picture of the next time I start it. However, it regularly hangs after already making one or more pictures of that particular session.

For your information, I do terminate it with a regular SIGTERM kill-signal (not a hard SIGKILL). However, if it takes too long I force kill it for reliability reasons.

[jamesh]

How do you terminate your app? If you are killing then it is possible that some camera shutdown code might not be run, which might stop the next run from working. If you are letting raspistill shut down normally, that should be OK.

Thank you for your reply.
Termination of the app is not applicable since that would mean it should hang on the first picture of the next time I start it. However, it regularly hangs after already making one or more pictures of that particular session.

Ah, OK. Wasn't clear from the OP. Still sounds like a shutdown issue though. Odd.

[jetibest]

I'm sorry, I'm terrible at explaining things properly. Maybe the log says more about the frequency of this occurring, down here is a log which gives a better view of how many times this happens.

Everytime it says "photos", this means there are made about 4 to 6 photos after each other. When it says "RPI_ERROR", that is when I detected a timeout for that raspistill call.

My experience says that when something happens randomly like this, it is a timing issue (since there are no other changing variables). However, because there is an external component (the camera), I'm unfamiliar with possible reasons.

Code: Select all

2017-07-16 13:15:06 photos
2017-07-16 13:18:32 photos
2017-07-16 13:25:59 photos
2017-07-16 13:29:16 photos
2017-07-16 13:34:10 photos
2017-07-16 13:46:46 photos
2017-07-16 13:57:18 photos
2017-07-16 14:05:12 photos
2017-07-16 14:40:26 photos
2017-07-16 14:45:31 photos
2017-07-16 14:45:48 RPI_ERROR
2017-07-16 14:53:44 photos
2017-07-16 15:43:20 photos
2017-07-16 15:43:39 RPI_ERROR
2017-07-16 15:45:00 photos
2017-07-16 16:15:37 photos
2017-07-16 16:29:48 photos
2017-07-16 16:43:19 photos
2017-07-16 16:47:34 photos
2017-07-16 17:05:32 photos
2017-07-16 17:13:11 photos
2017-07-16 17:30:54 photos
2017-07-16 17:34:27 photos
2017-07-16 18:41:14 photos
2017-07-16 18:43:37 photos
2017-07-16 18:46:09 photos
2017-07-16 18:47:42 photos
2017-07-16 18:56:05 photos
2017-07-16 19:16:25 photos
2017-07-16 19:26:25 photos
2017-07-16 19:57:22 photos
2017-07-17 05:21:17 photos
2017-07-17 08:07:55 photos
2017-07-17 08:08:29 photos
2017-07-17 08:08:42 RPI_ERROR
2017-07-17 09:29:18 photos
2017-07-17 09:40:33 photos
2017-07-17 10:44:16 photos
2017-07-17 10:44:37 RPI_ERROR
2017-07-17 11:24:45 photos
2017-07-17 11:25:04 RPI_ERROR
2017-07-17 11:27:26 photos
2017-07-17 12:07:54 photos
2017-07-17 12:08:13 RPI_ERROR
2017-07-17 12:25:03 photos
2017-07-17 12:34:45 photos
2017-07-17 12:34:58 RPI_ERROR
2017-07-17 12:44:57 photos
2017-07-17 12:47:06 photos
2017-07-17 12:48:24 photos
2017-07-17 12:49:41 photos
2017-07-17 13:05:48 photos
2017-07-17 13:07:38 photos
2017-07-17 13:07:58 RPI_ERROR
2017-07-17 13:15:58 photos
2017-07-17 13:22:03 photos
2017-07-17 13:22:15 RPI_ERROR
2017-07-17 13:27:54 photos
2017-07-17 13:31:18 photos
2017-07-17 13:31:46 photos
2017-07-17 13:32:35 photos
2017-07-17 13:42:25 photos
2017-07-17 13:46:58 photos
2017-07-17 13:47:16 RPI_ERROR
2017-07-17 13:48:39 photos
2017-07-17 13:52:45 photos
2017-07-17 14:11:14 photos
2017-07-17 14:11:46 RPI_ERROR
2017-07-17 14:12:49 photos
2017-07-17 14:13:46 photos
2017-07-17 14:14:06 RPI_ERROR
2017-07-17 14:14:08 photos
2017-07-17 14:14:26 RPI_ERROR
2017-07-17 14:17:16 photos
2017-07-17 14:18:09 photos
2017-07-17 14:18:32 photos
2017-07-17 14:19:31 photos
2017-07-17 14:22:55 photos
2017-07-17 14:23:33 photos
2017-07-17 14:25:03 photos
2017-07-17 14:28:14 photos
2017-07-17 14:28:27 RPI_ERROR
2017-07-17 14:37:17 photos
2017-07-17 14:38:18 photos
2017-07-17 14:45:39 photos
2017-07-17 14:55:35 photos
2017-07-17 14:56:14 photos
2017-07-17 14:56:51 photos
2017-07-17 14:58:56 photos
2017-07-17 14:59:20 photos
2017-07-17 15:03:15 photos
2017-07-17 15:08:16 photos
2017-07-17 15:16:50 photos
2017-07-17 15:22:39 photos
2017-07-17 15:23:14 photos
2017-07-17 15:23:47 photos
2017-07-17 15:37:15 photos
2017-07-17 15:39:13 photos
2017-07-17 15:40:26 photos
2017-07-17 15:44:07 photos
2017-07-17 15:51:39 photos
2017-07-17 15:57:56 photos
2017-07-17 16:01:38 photos
2017-07-17 16:10:01 photos
2017-07-17 16:13:52 photos
2017-07-17 16:17:50 photos
2017-07-17 16:19:15 photos
2017-07-17 16:19:41 photos
2017-07-17 16:23:19 photos
2017-07-17 16:24:53 photos
2017-07-17 16:25:59 photos
2017-07-17 16:28:38 photos
2017-07-17 17:00:44 photos
2017-07-17 17:20:47 photos
2017-07-17 17:50:29 photos
2017-07-17 18:21:05 photos
2017-07-17 18:22:12 photos
2017-07-17 18:30:27 photos
2017-07-17 19:19:08 photos
2017-07-17 19:24:07 photos
2017-07-17 19:36:32 photos
2017-07-17 19:37:44 photos
2017-07-17 19:39:52 photos
2017-07-17 19:54:20 photos
2017-07-17 21:28:41 photos
2017-07-17 21:44:16 photos
2017-07-17 21:44:34 RPI_ERROR
2017-07-17 22:14:11 photos
2017-07-17 22:21:52 photos
2017-07-18 05:28:59 photos
2017-07-18 08:29:40 photos
2017-07-18 08:29:55 RPI_ERROR
2017-07-18 09:18:36 photos
2017-07-18 09:18:55 RPI_ERROR
2017-07-18 09:24:58 photos
2017-07-18 09:25:15 RPI_ERROR
2017-07-18 09:44:36 photos
2017-07-18 09:54:00 photos
2017-07-18 09:54:37 photos
2017-07-18 09:55:00 RPI_ERROR
2017-07-18 10:07:46 photos
2017-07-18 10:12:39 photos
2017-07-18 10:20:57 photos
2017-07-18 10:21:22 RPI_ERROR
2017-07-18 10:36:52 photos
2017-07-18 10:37:14 photos
2017-07-18 10:37:49 RPI_ERROR
2017-07-18 10:41:11 photos
2017-07-18 10:50:18 photos
2017-07-18 10:53:14 photos
2017-07-18 10:53:32 RPI_ERROR
2017-07-18 10:57:08 photos
2017-07-18 10:57:27 RPI_ERROR
2017-07-18 11:10:16 photos
2017-07-18 11:17:12 photos
2017-07-18 11:25:57 photos
2017-07-18 11:26:13 photos
2017-07-18 11:27:02 photos
2017-07-18 11:31:06 photos
2017-07-18 11:33:29 photos
2017-07-18 11:36:25 photos
2017-07-18 11:36:44 RPI_ERROR
2017-07-18 11:38:41 photos
2017-07-18 11:38:59 RPI_ERROR
2017-07-18 11:39:24 RPI_ERROR
2017-07-18 11:40:04 photos
2017-07-18 11:43:14 photos
2017-07-18 11:48:21 photos
2017-07-18 11:48:47 photos
2017-07-18 11:49:44 photos
2017-07-18 11:53:21 photos
2017-07-18 11:56:04 photos
2017-07-18 11:56:19 photos
2017-07-18 11:59:15 photos
2017-07-18 12:02:23 photos
2017-07-18 12:02:54 RPI_ERROR
2017-07-18 12:09:43 photos
2017-07-18 12:10:48 photos
2017-07-18 12:11:21 RPI_ERROR
2017-07-18 12:11:56 photos
2017-07-18 12:13:38 photos
2017-07-18 12:14:22 photos
2017-07-18 12:15:18 photos
2017-07-18 12:16:07 photos
2017-07-18 12:16:58 photos
2017-07-18 12:17:16 photos
2017-07-18 12:18:42 photos
2017-07-18 12:21:07 photos
2017-07-18 12:29:06 photos
2017-07-18 12:30:19 photos
2017-07-18 12:46:37 photos
2017-07-18 12:51:19 photos
2017-07-18 12:56:59 photos
2017-07-18 13:02:51 photos
2017-07-18 13:17:31 photos
2017-07-18 13:21:25 photos
2017-07-18 13:23:46 photos
2017-07-18 13:25:30 photos
2017-07-18 13:32:32 photos
2017-07-18 13:38:11 photos
2017-07-18 13:46:40 photos

[jetibest]

How do you terminate your app? If you are killing then it is possible that some camera shutdown code might not be run, which might stop the next run from working. If you are letting raspistill shut down normally, that should be OK.

Thank you for your reply.
Termination of the app is not applicable since that would mean it should hang on the first picture of the next time I start it. However, it regularly hangs after already making one or more pictures of that particular session.

Ah, OK. Wasn't clear from the OP. Still sounds like a shutdown issue though. Odd.

Oh, I made a mistake in the logs. I added a lot of additional logging now (it goes to show you can never log enough).

The line it actually hangs on is (with interesting commentary):

Code: Select all

// Wait for capture to complete
// For some reason using vcos_semaphore_wait_timeout sometimes returns immediately with bad parameter error
// even though it appears to be all correct, so reverting to untimed one until figure out why its erratic
vcos_semaphore_wait(&callback_data.complete_semaphore);

In any case, I will have to go check with the timeout version (perhaps a timeout of 1s + shutterspeed), to see if this prevents hanging correctly, and see how that goes. But I fear this will give the problem in the comments, I just don't understand that yet.
(?) Maybe possibly related: https://stackoverflow.com/questions/292 ... t-waking-c

I will have to keep on adding logs until I've found the exact problem. Although it's difficult since the problem is not easily reproduced.

UPDATE: After a few hours, the vcos_semaphore_wait_timeout with 1 second (my shutterspeed won't get above 100ms, and usually taking a photo for the first time is not more than 800ms, and after that not more than 350ms) seems to work well. But I still don't understand how and why it works.

[6by9]

UPDATE: After a few hours, the vcos_semaphore_wait_timeout with 1 second (my shutterspeed won't get above 100ms, and usually taking a photo for the first time is not more than 800ms, and after that not more than 350ms) seems to work well. But I still don't understand how and why it works.

The app asks for a capture, and then is waiting for the end of capture to be signalled from here.
By adding the timeout on the semaphore_wait you've just said that you don't care about the capture if it takes more than X amount of time, and abandon everything.

Why some captures seem to stall isn't something that can be determined with the information you've provided so far. What's the complete command line that you are using to invoke raspistill? There are far too many variables otherwise.

[jetibest]

UPDATE: After a few hours, the vcos_semaphore_wait_timeout with 1 second (my shutterspeed won't get above 100ms, and usually taking a photo for the first time is not more than 800ms, and after that not more than 350ms) seems to work well. But I still don't understand how and why it works.

The app asks for a capture, and then is waiting for the end of capture to be signalled from here.
By adding the timeout on the semaphore_wait you've just said that you don't care about the capture if it takes more than X amount of time, and abandon everything.

Why some captures seem to stall isn't something that can be determined with the information you've provided so far. What's the complete command line that you are using to invoke raspistill? There are far too many variables otherwise.

Hmm, I added extensive logs to this function:
static void encoder_buffer_callback(MMAL_PORT_T *port, MMAL_BUFFER_HEADER_T *buffer)

When the problem occurs, I'm receiving a timeout (after the specified timeout -> yes, I can see in the logs the timeout-function did not exit prematurely).
However, when this is the case, the logs indicate that 'encoder_buffer_callback' is never called at all (in contrast to normal behavior).

By the way, the timeout is necessary evil, 'cause otherwise I need to implement a timeout in the application that forked raspistill, and thus need to kill it. Exiting gracefully from within raspistill is always better than having to kill the raspistill process externally.


Because you really want to know: The parameters that are used, are usually something like this:
/usr/bin/raspistill -w 1280 -h 720 -q 80 -sa 0 -ex fixedfps -ss 955 -awb auto -ISO 100 -drc high -ifx denoise -bm -n -t 0 -k -o /tmp/raspistill.jpg
And I have my own custom code to handle '-k', but don't worry, that has nothing to do with the problem (if I had any reason to suspect this is the case, I wouldn't be asking this on this particular forum).

But I doubt you'll be able to reproduce it, since I can't even reproduce it on my other Raspberry Pi either. I mean, it did happen, but maybe a 1000 times less frequently. Not sure why, as they are the exact same model and have the exact same software and hardware.