intermittent picamera.exc.PiCameraRuntimeError: Timed out waiting for capture to end

[AndySchroder]

I'm getting the following error message intermittently: "picamera.exc.PiCameraRuntimeError: Timed out waiting for capture to end", from the command: "camera.capture(image_data, 'yuv',use_video_port=False)", where the image_data object was created with "BytesIO()".

I record an image every 1 second at the camera's maximum resolution of 2592x1944 using the command above. I have some timers and sleep statements to ensure this image capture rate. The error may happen after 18 hours, it may happen after 7 days, it may happen after 36 hours of running.

I'm using a raspberry pi 2. The image_data object is actually written to ffmpeg/avconv as standard input. So, disk write speeds are usually less than 1MB/second after the image data is compressed to a video format. I've tested write speeds of about 26MB/second with my disk on the raspberry pi 2, so I'm sure it is not a disk IO issue. I'm also sure that I have 3.6TB of free disk space. System loads are typically about 2.7 with this script and ffmpeg/avconv running, which for this quad core CPU, I don't think is very high. From what I recall, in order to maintain the capture rate of 1 image per second, I think the python script is usually delaying about 180ms. It apparently takes about 820ms for the camera to capture an image at the maximum resolution without using the video port. I haven't checked to see if using the video port to capture images resolves this intermittent issue, but I don't want to because the image quality is terrible when using the video port.

Restarting the script seems to fix the problem, although I normally just reboot the raspberry pi just so the script is relaunched again in the same way, using the /etc/rc.local file. I haven't tried any try/except statements to catch the error and retry, so I'm not sure if restarting the python interpreter is required to temporarily overcome the issue.

Any ideas on why this error may be happening?

[AndySchroder]

I should also note that this raspberry pi 2 is in a fairly temperature controlled evironoment. The camera is taped to a window though, but the season at the moment is fall, so the window temperature is between 15C-25C. I've tried this in two completely different physical locations (about 10km apart), and I don't think there is any kind of electromagnetic interferance messing with the camera.

[AndySchroder]

I added some try, except statements to my code. I make it retry every 5 seconds for 50 seconds after the problem happens. The problem happens all 10 times. If I restart the interpreter, the problem is resolved for another several days. It doesn't seem like a reboot is really necessary.

[waveform80]

I suspect this is something to do with blocked writes to the background ffmpeg/avconv process. Briefly, what goes on during capture is something like this:

• Script calls capture
• An encoder is created and attached to the still/video port according to the specified options (in the case of unencoded captures an actual MMAL encoder isn't created, but an encoder class instance is still created just to manage passing data to the output file)
• The encoder tells the camera to "start the capture" (the camera is already capturing data, this really just tells it to start feeding the next frame to the output ports)
• At this point the main thread is free to continue doing what it wants; the capture and writing of the image data is handled by a background thread. In picamera's capture method, it just goes into a blocking wait on an Event object
• Hopefully in the background the capture proceeds, data is written to the specified output and when it's finished, the background thread sets the Event object, freeing the main thread to continue

Now, in the past I've come across a few conditions which caused the capture to fail to complete. That meant the Event never got set, so the main thread got stuck. Hence, the main thread now waits a limited time for the capture to complete. The time limit is quite arbitrary: 30 seconds (which I figured should be long enough for any capture to complete writing to any reasonable output).

Given that there's no "real" encoder being used in your case, I think there's only one of two realistic explanations:

1. The firmware's gone wrong and for some reason hasn't signalled the end of the frame, so the capture doesn't complete. I doubt this simply because I've never seen an unencoded capture fail before (I've seen them go horribly slow when dealing with massive formats like RGB, but never near the 30 second timeout).
2. The pipe to the background avconv/ffmpeg process has filled up (avconv/ffmpeg isn't emptying it fast enough for whatever reason) so further writes block, and the background thread winds up running over the 30 second timeout.

You might want to try extending the capture timeout just to see if that makes a difference (I doubt it'll fix it outright, but it might delay the error occurring; if that's the case it would point to the second scenario). You can do so like this:

import picamera

camera = picamera.PiCamera()
camera.CAPTURE_TIMEOUT = 60 # seconds
camera.capture(...)

I'm not sure how you're launching the background avconv/ffmpeg process but if it's via subprocess it might be worth having a play with the bufsize parameter too. The buffer size probably ought to be large enough to hold at least an entire frame's worth of data (i.e. 2592_1944_1.5=7558272 bytes which it certainly won't be by default).

[markfickett]

I ran into these symptoms too: PiCameraRuntimeError: Timed out waiting for capture to end after a while. I'm also using PWM, and in my case this was the fix: http://raspberrypi.stackexchange.com/questions/40126/can-the-gpio-interfere-with-the-picamera-and-cause-an-error . Calling PWM's start() and stop() repeatedly was using up the per-process thread limit, which eventually blocked the camera, so switching to pwm.ChangeDutyCycle(0.0) to effectively stop PWM fixed my issue.

[AndySchroder]

I never had time to create a simple, isolated test case to prove that the ffmpeg/avconv piping is not part of the problem. I really don't think it is at all, but I'll need to write to /dev/null instead to truely prove it to you.

Anyway, I did setup a second camera. That new system is also having the problem described above, but it is also having an even worse problem. Above I mentioned that I included some try/except statements and a calling bash script to catch the error and restart the interpreter when the problem happens. This lost some footage, but was at least working. With this new system, that does not always work. A complete reboot is sometimes required. Even a simple script just hangs indefinitely once the system is in this messed up state.

$ python
Python 2.7.9 (default, Mar  8 2015, 00:52:26) 
[GCC 4.9.2] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import picamera
>>> camera=picamera.PiCamera()

Control-C does not work, you have to manually kill the python process to get that console to respond again after picamera.PiCamera() is called.

I'm not sure if these two problems are related or unrelated.

The only difference between my new system and old are the fact that the new system uses a Raspbian Jessie image rather than a Raspbian Wheezy image. The new system also has a slightly longer camera ribbon cable installed. I'm not sure why a longer ribbon cable would cause a system screwup though.

[waveform80]

Hmmm ... if it's taking a reboot to fix that does vaguely imply the firmware might've gotten stuck (if it is a firmware issue there's very little I can do about that; picamera is merely a relatively thin wrapper over MMAL which in turn wraps the firmware).

If it's not firmware, then you're hitting the timeout because the output doesn't have enough buffering or isn't clearing its queue fast enough (30-seconds should be more than sufficient for any YUV capture, even a full resolution one). There really isn't much else going on: in the case of unencoded captures all picamera does is setup the camera for capture, then call write() on an output in response to callbacks from the camera. The Event wait is simply there to make the capture() method synchronous.

You could also try rejigging your code a bit to avoid capture() (and its Event wait) altogether by using a YUV-based video recording with a custom output that redirects frames to the ffmpeg process. I can post an example of that if you're interested?

[AndySchroder]

You're talking about using the video port?

Just a little background, I'm not using the hardware video encoder because it can't handle the camera's highest spatial resolution, even at 1 frame per second (it just gives errors). Another reason I'm using ffmpeg is because I don't want h264, and I also want more control on the encoding parameters. Although h264 is better compression, it is really slow to seek videos with most players at this high spatial resolution, and with long time-lapse videos, this is needed to find the time of interest. In this case, disk space is cheap enough that I'd rather be able to seek faster.

Another reason why I'm not using the video port is because the image quality was substantially lower when in video port mode.

If you know of a way to do it without these limitations, I'd love to see an example. If not, I guess I'll wait a week or so until it happens again and try to use a non-picamera camera tool and see what that does before I reboot, and then report back.

[waveform80]

Fair enough. I'm afraid you're stuck with events then - if it's a still port capture you've got to wait for the capture to terminate, then start the next one (no continual capture on the still port, even in burst mode) hence an event (or some form of synchronization primitive) is required to wait on the callbacks to indicate the frame's ended.

I still think it's probably worth exploring if the ffmpeg/avconv pipe is the issue though...

[AndySchroder]

One other change I forgot to mention about my new camera system is that I now have the no-IR camera. I don't see why that would make a difference though.

I will try eliminating ffmpeg after I at least wait one more time to get it into the state where it needs a full reboot and try non-picamera camera tool first. This will take several weeks though.

If it is a firmware issue, do you know who to contact, and is it something that can be updated or is it baked into a chip and would need to wait for the next pi model?

[AndySchroder]

After some time, I was able to get both (slightly different) systems described above to get into the state where a reboot is required to restore the camera's functionality.

When in this state, after killing the python process that was running picamera, but before rebooting, I've tried running

$ raspistill -t 2000 -n -o test.jpg

and this command also hangs forever. After rebooting, both picamera and raspistill seem to work fine again.

So, it seems like the problem described above that requires a reboot may be unrelated to picamera and as was suggested above, possibly a firmware issue. It's still unclear whether the other problem described above that just requires the python interpreter to be restarted is related to picamera, the potential firmware problem, or both.

Is there any contact at the raspberry pi foundation that may care about this issue with the camera?

Right now, the only real work around is to do a precautionary reboot (say once a week), although I really don't like this approach. I may try to reduce the capture rate on one of my systems (without implementing the precautionary reboot) and see if that has any impact on the time until the problem occurs again.

[waveform80]

One other change I forgot to mention about my new camera system is that I now have the no-IR camera. I don't see why that would make a difference though.

Yup, that won't make any difference - I don't think the firmware even knows whether it's a visual / noir camera attached since it's just a filter removed.

Is there any contact at the raspberry pi foundation that may care about this issue with the camera?

Unfortunately, no - all work on the camera module from firmware all the way to picamera is done by volunteers. The best place to report firmware issues is generally the https://github.com/raspberrypi/firmware repo but you will need to have a minimal reproducible test case if you want them to look at it. It may also be worth including the last lines of the output of sudo vcdbg log msg and all of the output of sudo vcdbg reloc (run these once the hang occurs in another terminal / SSH session).

[AndySchroder]

Thanks for the reply. I am setting up a raspberry pi 3 with a version 2 camera very soon exclusively for debugging this problem (maybe the problem will happen to be gone with the new hardware). I will test on that new hardware and also follow the advice you have just given to do more troubleshooting and submit a useful report to the firmware volunteers.

[AndySchroder]

I just got the problem to happen again on one of my systems where the reboot is required.

There isn't much interesting from vcdbg log msg .

Here is what I am getting from vcdbg reloc . I don't have anything plugged into the HDMI port.

$ sudo vcdbg reloc

Relocatable heap version 4 found at 0x37000000
total space allocated is 108M, with 108M relocatable, 0 legacy and 0 offline
0 legacy blocks of size 2359296

free list at 0x3a3b8a00
36M free memory in 3 free block(s)
largest free block is 36M bytes

0x37000000: free 36M
[  41] 0x3942b340: used 5.1K (refcount 1 lock count 0, size     5184, align   32, data 0x3942b360, d0ruAl) 'dir sw_sharpen y_spd_delay_line_h'
[  44] 0x3942c7c0: used 7.2M (refcount 1 lock count 0, size  7589376, align   32, data 0x3942c7e0, d1rual) 'ril mem ril.camera-3'
[  81] 0x39b69600: used 7.2M (refcount 1 lock count 0, size  7589376, align   32, data 0x39b69620, d1rual) 'ril.camera:out:1(I420)'
[  11] 0x3a2a6440: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x3a2a6460, d0rual) 'stabilise current image'
[  60] 0x3a2aa480: used  48K (refcount 1 lock count 0, size    49152, align   32, data 0x3a2aa4a0, d0rual) 'stabilise ref'
[  46] 0x3a2b64c0: used  48K (refcount 1 lock count 0, size    49152, align   32, data 0x3a2b64e0, d0rual) 'stabilise ref'
[  14] 0x3a2c2500: used 349K (refcount 1 lock count 0, size   356864, align   32, data 0x3a2c2520, d0ruAl) 'drc lp'
[  58] 0x3a319740: used  45K (refcount 1 lock count 0, size    45696, align   32, data 0x3a319760, d0ruAl) 'drc out'
[  54] 0x3a324a00: used 169K (refcount 1 lock count 0, size   173184, align   32, data 0x3a324a20, d0ruAl) 'drc out'
[  55] 0x3a34eec0: used 169K (refcount 1 lock count 0, size   173184, align   32, data 0x3a34eee0, d0ruAl) 'drc in'
[  71] 0x3a379380: used  52K (refcount 1 lock count 0, size    53504, align    4, data 0x3a3793a0, d1rual) 'AWB State (makesum_direct)'
[  20] 0x3a3864c0: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a3864e0, d1rual) 'AWB State (CCMs)'
[  49] 0x3a38ad00: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a38ad20, d1rual) 'AWB State (CCMs)'
[  51] 0x3a38f540: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a38f560, d1rual) 'AWB State (CCMs)'
0x3a393d80: free 2.6K
[  29] 0x3a3947c0: used 5.1K (refcount 1 lock count 0, size     5184, align   32, data 0x3a3947e0, d0ruAl) 'dir sw_sharpen y_input_delay_line'
[  12] 0x3a395c40: used 3.1K (refcount 1 lock count 0, size     3072, align   32, data 0x3a395c60, d0rual) 'stabilise ref_ss'
[  43] 0x3a396880: used 3.1K (refcount 1 lock count 0, size     3072, align   32, data 0x3a3968a0, d0rual) 'stabilise ref_ss'
[  64] 0x3a3974c0: used 1.2K (refcount 1 lock count 0, size     1152, align   32, data 0x3a3974e0, d0ruAl) 'drc out'
[  59] 0x3a397980: used 1.2K (refcount 1 lock count 0, size     1152, align   32, data 0x3a3979a0, d0ruAl) 'drc in'
[  16] 0x3a397e40: used 3.8K (refcount 1 lock count 0, size     3840, align   32, data 0x3a397e60, d0ruAl) 'drc out'
[  15] 0x3a398d80: used 3.8K (refcount 1 lock count 0, size     3840, align   32, data 0x3a398da0, d0ruAl) 'drc in'
[   5] 0x3a399cc0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a399ce0, d0rual) 'ls table 4'
[  23] 0x3a39ff20: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a39ff40, d0rual) 'ls table 3'
[  61] 0x3a3a6180: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a3a61a0, d0rual) 'ls table 2'
[  45] 0x3a3ac3e0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a3ac400, d0rual) 'ls table 1'
[  31] 0x3a3b2640: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a3b2660, d0rual) 'ls table 0'
0x3a3b88a0: free 384
[  13] 0x3a3b8a20: used  576 (refcount 1 lock count 0, size      512, align   32, data 0x3a3b8a40, d0ruAl) 'drc in last lvl'
[  56] 0x3a3b8c60: used  12K (refcount 1 lock count 0, size    12672, align   32, data 0x3a3b8c80, d0ruAl) 'drc out'
[  57] 0x3a3bbe20: used  12K (refcount 1 lock count 0, size    12672, align   32, data 0x3a3bbe40, d0ruAl) 'drc in'
[  53] 0x3a3befe0: used  45K (refcount 1 lock count 0, size    45696, align   32, data 0x3a3bf000, d0ruAl) 'drc in'
[   7] 0x3a3ca2a0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca2c0, d1rual) 'null_sink:in:0(OPQV)'
[   8] 0x3a3ca360: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca380, d1rual) 'null_sink:in:0(OPQV)'
[  52] 0x3a3ca420: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca440, d1rual) 'null_sink:in:0(OPQV)'
[  63] 0x3a3ca4e0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca500, d1rual) 'null_sink:in:0(OPQV)'
[  28] 0x3a3ca5a0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca5c0, d1rual) 'null_sink:in:0(OPQV)'
[  50] 0x3a3ca660: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca680, d1rual) 'null_sink:in:0(OPQV)'
[  10] 0x3a3ca720: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca740, d1rual) 'null_sink:in:0(OPQV)'
[   9] 0x3a3ca7e0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca800, d1rual) 'null_sink:in:0(OPQV)'
[  68] 0x3a3ca8a0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca8c0, d1rual) 'null_sink:in:0(OPQV)'
[  18] 0x3a3ca960: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca980, d1rual) 'null_sink:in:0(OPQV)'
[  78] 0x3a3caa20: used 4.3K (refcount 1 lock count 0, size     4378, align    4, data 0x3a3caa40, d0rual) 'distortion table'
[  80] 0x3a3cbb80: used 135K (refcount 1 lock count 0, size   138240, align    4, data 0x3a3cbba0, d0rual) 'isp sw stage buffers'
[  21] 0x3a3ed7c0: used 271K (refcount 1 lock count 0, size   277512, align    4, data 0x3a3ed7e0, d0rual) 'concurrent mdata'
[  25] 0x3a431420: used 4.3K (refcount 1 lock count 0, size     4378, align    4, data 0x3a431440, d0rual) 'distortion table'
[  70] 0x3a432580: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a4325a0, d0rual) 'ls table isp'
[  62] 0x3a4387e0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a438800, d0rual) 'ls table tx1'
[  30] 0x3a43ea40: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a43ea60, d0rual) 'ls table tx0'
[  69] 0x3a444ca0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a444cc0, d0rual) 'ls table 1'
[   6] 0x3a44af00: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a44af20, d0rual) 'ls table 0'
[  22] 0x3a451160: used  52K (refcount 1 lock count 0, size    53504, align    4, data 0x3a451180, d1rual) 'AWB State (makesum_direct)'
[  34] 0x3a45e2a0: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a45e2c0, d1rual) 'AWB State (CCMs)'
[  79] 0x3a462ae0: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a462b00, d1rual) 'AWB State (CCMs)'
[  27] 0x3a467320: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a467340, d1rual) 'AWB State (CCMs)'
[  26] 0x3a46bb60: used 135K (refcount 1 lock count 0, size   138240, align    4, data 0x3a46bb80, d0rual) 'isp sw stage buffers'
[  35] 0x3a48d7a0: used 271K (refcount 1 lock count 0, size   277512, align    4, data 0x3a48d7c0, d0rual) 'concurrent mdata'
[  40] 0x3a4d1400: used 7.8M (refcount 1 lock count 3, size  8208384, align 4096, data 0x3a4d2000, d1rual) 'cameraRIL:input pool'
[  65] 0x3aca6420: used 2.1M (refcount 1 lock count 0, size  2145472, align 4096, data 0x3aca7000, d1ruAl) 'cameraRIL: lowres pool'
[  38] 0x3aeb3100: used 2.1M (refcount 1 lock count 1, size  2145472, align 4096, data 0x3aeb4000, d1rual) 'cameraRIL: lowres pool'
[  66] 0x3b0bfde0: used 2.1M (refcount 1 lock count 1, size  2145472, align 4096, data 0x3b0c0000, d1rual) 'cameraRIL: lowres pool'
[  39] 0x3b2ccac0: used 7.3M (refcount 1 lock count 0, size  7635648, align 4096, data 0x3b2cd000, d1ruAl) 'cameraRIL: hires stills pool'
[  19] 0x3ba15da0: used  11M (refcount 1 lock count 0, size 11658432, align 4096, data 0x3ba16000, d1ruAl) 'cameraRIL: hires vid pool'
[  82] 0x3c535280: used  11M (refcount 1 lock count 1, size 11658432, align 4096, data 0x3c536000, d1rual) 'cameraRIL: hires vid pool'
[  33] 0x3d054760: used  11M (refcount 1 lock count 1, size 11658432, align 4096, data 0x3d055000, d1rual) 'cameraRIL: hires vid pool'
[  36] 0x3db73c40: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db73c60, d1rual) 'ril mem ril.camera-0'
[  32] 0x3db73f80: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db73fa0, d1rual) 'ril mem ril.camera-0'
[  17] 0x3db742c0: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db742e0, d1rual) 'ril mem ril.camera-0'
[  24] 0x3db74600: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db74620, d1rual) 'ril mem ril.camera-0'
[   4] 0x3db74940: used  576 (refcount 1 lock count 0, size      512, align    4, data 0x3db74960, d0rual) 'ILCS VC buffer pool'
[   3] 0x3db74b80: used 537K (refcount 1 lock count 8, size   545792, align 4096, data 0x3db75000, d1rual) 'ARM FB'
[   2] 0x3dbfafa0: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x3dbfafc0, d0ruAl) 'audioplus_tmp_buf'
[   1] 0x3dbfefe0: used 4.0K (refcount 1 lock count 0, size        0, align 4096, data 0x3dbff000, d1rual) 'camera fast alloc arena'
small allocs not requested

[AndySchroder]

Here is what I get after a fresh boot:

$ sudo vcdbg reloc

Relocatable heap version 4 found at 0x37000000
total space allocated is 108M, with 108M relocatable, 0 legacy and 0 offline
0 legacy blocks of size 2359296

free list at 0x3db74920
107M free memory in 1 free block(s)
largest free block is 107M bytes

0x37000000: free 107M
[   4] 0x3db74940: used  576 (refcount 1 lock count 0, size      512, align    4, data 0x3db74960, d0rual) 'ILCS VC buffer pool'
[   3] 0x3db74b80: used 537K (refcount 1 lock count 8, size   545792, align 4096, data 0x3db75000, d1rual) 'ARM FB'
[   2] 0x3dbfafa0: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x3dbfafc0, d0ruAl) 'audioplus_tmp_buf'
[   1] 0x3dbfefe0: used 4.0K (refcount 1 lock count 0, size        0, align 4096, data 0x3dbff000, d1rual) 'camera fast alloc arena'
small allocs not requested

[AndySchroder]

With picamera working:

$ sudo vcdbg reloc

Relocatable heap version 4 found at 0x37000000
total space allocated is 108M, with 108M relocatable, 0 legacy and 0 offline
0 legacy blocks of size 2359296

free list at 0x3a3b8a00
36M free memory in 3 free block(s)
largest free block is 36M bytes

0x37000000: free 36M
[  69] 0x3942b340: used 5.1K (refcount 1 lock count 0, size     5184, align   32, data 0x3942b360, d0ruAl) 'dir sw_sharpen y_spd_delay_line_h'
[  61] 0x3942c7c0: used 7.2M (refcount 1 lock count 0, size  7589376, align   32, data 0x3942c7e0, d1rual) 'ril mem ril.camera-3'
[  63] 0x39b69600: used 7.2M (refcount 1 lock count 0, size  7589376, align   32, data 0x39b69620, d1rual) 'ril.camera:out:1(I420)'
[  56] 0x3a2a6440: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x3a2a6460, d0rual) 'stabilise current image'
[  41] 0x3a2aa480: used  48K (refcount 1 lock count 0, size    49152, align   32, data 0x3a2aa4a0, d0rual) 'stabilise ref'
[  14] 0x3a2b64c0: used  48K (refcount 1 lock count 0, size    49152, align   32, data 0x3a2b64e0, d0rual) 'stabilise ref'
[  28] 0x3a2c2500: used 349K (refcount 1 lock count 0, size   356864, align   32, data 0x3a2c2520, d0ruAl) 'drc lp'
[  10] 0x3a319740: used  45K (refcount 1 lock count 0, size    45696, align   32, data 0x3a319760, d0ruAl) 'drc out'
[  16] 0x3a324a00: used 169K (refcount 1 lock count 0, size   173184, align   32, data 0x3a324a20, d0ruAl) 'drc out'
[  15] 0x3a34eec0: used 169K (refcount 1 lock count 0, size   173184, align   32, data 0x3a34eee0, d0ruAl) 'drc in'
[  42] 0x3a379380: used  52K (refcount 1 lock count 0, size    53504, align    4, data 0x3a3793a0, d1rual) 'AWB State (makesum_direct)'
[  71] 0x3a3864c0: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a3864e0, d1rual) 'AWB State (CCMs)'
[  70] 0x3a38ad00: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a38ad20, d1rual) 'AWB State (CCMs)'
[  44] 0x3a38f540: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a38f560, d1rual) 'AWB State (CCMs)'
0x3a393d80: free 2.6K
[  65] 0x3a3947c0: used 5.1K (refcount 1 lock count 0, size     5184, align   32, data 0x3a3947e0, d0ruAl) 'dir sw_sharpen y_input_delay_line'
[  57] 0x3a395c40: used 3.1K (refcount 1 lock count 0, size     3072, align   32, data 0x3a395c60, d0rual) 'stabilise ref_ss'
[  13] 0x3a396880: used 3.1K (refcount 1 lock count 0, size     3072, align   32, data 0x3a3968a0, d0rual) 'stabilise ref_ss'
[   8] 0x3a3974c0: used 1.2K (refcount 1 lock count 0, size     1152, align   32, data 0x3a3974e0, d0ruAl) 'drc out'
[   7] 0x3a397980: used 1.2K (refcount 1 lock count 0, size     1152, align   32, data 0x3a3979a0, d0ruAl) 'drc in'
[   6] 0x3a397e40: used 3.8K (refcount 1 lock count 0, size     3840, align   32, data 0x3a397e60, d0ruAl) 'drc out'
[   5] 0x3a398d80: used 3.8K (refcount 1 lock count 0, size     3840, align   32, data 0x3a398da0, d0ruAl) 'drc in'
[  34] 0x3a399cc0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a399ce0, d0rual) 'ls table 4'
[  35] 0x3a39ff20: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a39ff40, d0rual) 'ls table 3'
[  37] 0x3a3a6180: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a3a61a0, d0rual) 'ls table 2'
[  39] 0x3a3ac3e0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a3ac400, d0rual) 'ls table 1'
[  40] 0x3a3b2640: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a3b2660, d0rual) 'ls table 0'
0x3a3b88a0: free 384
[  19] 0x3a3b8a20: used  576 (refcount 1 lock count 0, size      512, align   32, data 0x3a3b8a40, d0ruAl) 'drc in last lvl'
[  12] 0x3a3b8c60: used  12K (refcount 1 lock count 0, size    12672, align   32, data 0x3a3b8c80, d0ruAl) 'drc out'
[  11] 0x3a3bbe20: used  12K (refcount 1 lock count 0, size    12672, align   32, data 0x3a3bbe40, d0ruAl) 'drc in'
[   9] 0x3a3befe0: used  45K (refcount 1 lock count 0, size    45696, align   32, data 0x3a3bf000, d0ruAl) 'drc in'
[  18] 0x3a3ca2a0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca2c0, d1rual) 'null_sink:in:0(OPQV)'
[  17] 0x3a3ca360: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca380, d1rual) 'null_sink:in:0(OPQV)'
[  67] 0x3a3ca420: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca440, d1rual) 'null_sink:in:0(OPQV)'
[  64] 0x3a3ca4e0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca500, d1rual) 'null_sink:in:0(OPQV)'
[  66] 0x3a3ca5a0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca5c0, d1rual) 'null_sink:in:0(OPQV)'
[  60] 0x3a3ca660: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca680, d1rual) 'null_sink:in:0(OPQV)'
[  68] 0x3a3ca720: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca740, d1rual) 'null_sink:in:0(OPQV)'
[  58] 0x3a3ca7e0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca800, d1rual) 'null_sink:in:0(OPQV)'
[  59] 0x3a3ca8a0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca8c0, d1rual) 'null_sink:in:0(OPQV)'
[  62] 0x3a3ca960: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca980, d1rual) 'null_sink:in:0(OPQV)'
[  45] 0x3a3caa20: used 4.3K (refcount 1 lock count 0, size     4378, align    4, data 0x3a3caa40, d0rual) 'distortion table'
[  32] 0x3a3cbb80: used 135K (refcount 1 lock count 0, size   138240, align    4, data 0x3a3cbba0, d0rual) 'isp sw stage buffers'
[  30] 0x3a3ed7c0: used 271K (refcount 1 lock count 0, size   277512, align    4, data 0x3a3ed7e0, d0rual) 'concurrent mdata'
[  49] 0x3a431420: used 4.3K (refcount 1 lock count 0, size     4378, align    4, data 0x3a431440, d0rual) 'distortion table'
[  31] 0x3a432580: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a4325a0, d0rual) 'ls table isp'
[  50] 0x3a4387e0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a438800, d0rual) 'ls table tx1'
[  51] 0x3a43ea40: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a43ea60, d0rual) 'ls table tx0'
[  52] 0x3a444ca0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a444cc0, d0rual) 'ls table 1'
[  53] 0x3a44af00: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a44af20, d0rual) 'ls table 0'
[  36] 0x3a451160: used  52K (refcount 1 lock count 0, size    53504, align    4, data 0x3a451180, d1rual) 'AWB State (makesum_direct)'
[  54] 0x3a45e2a0: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a45e2c0, d1rual) 'AWB State (CCMs)'
[  55] 0x3a462ae0: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a462b00, d1rual) 'AWB State (CCMs)'
[  48] 0x3a467320: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a467340, d1rual) 'AWB State (CCMs)'
[  47] 0x3a46bb60: used 135K (refcount 1 lock count 0, size   138240, align    4, data 0x3a46bb80, d0rual) 'isp sw stage buffers'
[  46] 0x3a48d7a0: used 271K (refcount 1 lock count 0, size   277512, align    4, data 0x3a48d7c0, d0rual) 'concurrent mdata'
[  23] 0x3a4d1400: used 7.8M (refcount 1 lock count 1, size  8208384, align 4096, data 0x3a4d2000, d1rual) 'cameraRIL:input pool'
[  24] 0x3aca6420: used 2.1M (refcount 1 lock count 0, size  2145472, align 4096, data 0x3aca7000, d1ruAl) 'cameraRIL: lowres pool'
[  38] 0x3aeb3100: used 2.1M (refcount 1 lock count 1, size  2145472, align 4096, data 0x3aeb4000, d1rual) 'cameraRIL: lowres pool'
[  25] 0x3b0bfde0: used 2.1M (refcount 1 lock count 1, size  2145472, align 4096, data 0x3b0c0000, d1rual) 'cameraRIL: lowres pool'
[  26] 0x3b2ccac0: used 7.3M (refcount 1 lock count 0, size  7635648, align 4096, data 0x3b2cd000, d1ruAl) 'cameraRIL: hires stills pool'
[  27] 0x3ba15da0: used  11M (refcount 1 lock count 0, size 11658432, align 4096, data 0x3ba16000, d1ruAl) 'cameraRIL: hires vid pool'
[  43] 0x3c535280: used  11M (refcount 1 lock count 0, size 11658432, align 4096, data 0x3c536000, d1ruAl) 'cameraRIL: hires vid pool'
[  29] 0x3d054760: used  11M (refcount 1 lock count 1, size 11658432, align 4096, data 0x3d055000, d1rual) 'cameraRIL: hires vid pool'
[  22] 0x3db73c40: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db73c60, d1rual) 'ril mem ril.camera-0'
[  33] 0x3db73f80: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db73fa0, d1rual) 'ril mem ril.camera-0'
[  21] 0x3db742c0: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db742e0, d1rual) 'ril mem ril.camera-0'
[  20] 0x3db74600: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db74620, d1rual) 'ril mem ril.camera-0'
[   4] 0x3db74940: used  576 (refcount 1 lock count 0, size      512, align    4, data 0x3db74960, d0rual) 'ILCS VC buffer pool'
[   3] 0x3db74b80: used 537K (refcount 1 lock count 8, size   545792, align 4096, data 0x3db75000, d1rual) 'ARM FB'
[   2] 0x3dbfafa0: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x3dbfafc0, d0ruAl) 'audioplus_tmp_buf'
[   1] 0x3dbfefe0: used 4.0K (refcount 1 lock count 0, size        0, align 4096, data 0x3dbff000, d1rual) 'camera fast alloc arena'
small allocs not requested

[AndySchroder]

I then hit Control-C to kill picamera and the python interpreter. After python is shut down I get:

$ sudo vcdbg reloc

Relocatable heap version 4 found at 0x37000000
total space allocated is 108M, with 108M relocatable, 0 legacy and 0 offline
0 legacy blocks of size 2359296

free list at 0x3db74920
52M free memory in 5 free block(s)
largest free block is 52M bytes

0x37000000: free 53M
[  23] 0x3a4d1400: used 7.8M (refcount 1 lock count 0, size  8208384, align 4096, data 0x3a4d2000, d1ruAl) 'cameraRIL:input pool'
[  24] 0x3aca6420: used 2.1M (refcount 1 lock count 0, size  2145472, align 4096, data 0x3aca7000, d1ruAl) 'cameraRIL: lowres pool'
0x3aeb3100: free 45M
[   4] 0x3db74940: used  576 (refcount 1 lock count 0, size      512, align    4, data 0x3db74960, d0rual) 'ILCS VC buffer pool'
[   3] 0x3db74b80: used 537K (refcount 1 lock count 8, size   545792, align 4096, data 0x3db75000, d1rual) 'ARM FB'
[   2] 0x3dbfafa0: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x3dbfafc0, d0ruAl) 'audioplus_tmp_buf'
[   1] 0x3dbfefe0: used 4.0K (refcount 1 lock count 0, size        0, align 4096, data 0x3dbff000, d1rual) 'camera fast alloc arena'
small allocs not requested

[AndySchroder]

I then changed gpu_mem to 256 in /boot/config.txt and ran picamera. The output doesn't seem to be much different than with gpu_mem=128.

$ sudo vcdbg reloc

Relocatable heap version 4 found at 0x2f000000
total space allocated is 236M, with 236M relocatable, 0 legacy and 0 offline
0 legacy blocks of size 2359296

free list at 0x3a3b8a00
164M free memory in 3 free block(s)
largest free block is 164M bytes

0x2f000000: free 164M
[  61] 0x3942b340: used 5.1K (refcount 1 lock count 0, size     5184, align   32, data 0x3942b360, d0ruAl) 'dir sw_sharpen y_spd_delay_line_h'
[  54] 0x3942c7c0: used 7.2M (refcount 1 lock count 0, size  7589376, align   32, data 0x3942c7e0, d1rual) 'ril mem ril.camera-3'
[  53] 0x39b69600: used 7.2M (refcount 1 lock count 0, size  7589376, align   32, data 0x39b69620, d1rual) 'ril.camera:out:1(I420)'
[  30] 0x3a2a6440: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x3a2a6460, d0rual) 'stabilise current image'
[  16] 0x3a2aa480: used  48K (refcount 1 lock count 0, size    49152, align   32, data 0x3a2aa4a0, d0rual) 'stabilise ref'
[  29] 0x3a2b64c0: used  48K (refcount 1 lock count 0, size    49152, align   32, data 0x3a2b64e0, d0rual) 'stabilise ref'
[  43] 0x3a2c2500: used 349K (refcount 1 lock count 0, size   356864, align   32, data 0x3a2c2520, d0ruAl) 'drc lp'
[  45] 0x3a319740: used  45K (refcount 1 lock count 0, size    45696, align   32, data 0x3a319760, d0ruAl) 'drc out'
[  56] 0x3a324a00: used 169K (refcount 1 lock count 0, size   173184, align   32, data 0x3a324a20, d0ruAl) 'drc out'
[  57] 0x3a34eec0: used 169K (refcount 1 lock count 0, size   173184, align   32, data 0x3a34eee0, d0ruAl) 'drc in'
[  26] 0x3a379380: used  52K (refcount 1 lock count 0, size    53504, align    4, data 0x3a3793a0, d1rual) 'AWB State (makesum_direct)'
[  82] 0x3a3864c0: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a3864e0, d1rual) 'AWB State (CCMs)'
[  79] 0x3a38ad00: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a38ad20, d1rual) 'AWB State (CCMs)'
[  68] 0x3a38f540: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a38f560, d1rual) 'AWB State (CCMs)'
0x3a393d80: free 2.6K
[  61] 0x3a3947c0: used 5.1K (refcount 1 lock count 0, size     5184, align   32, data 0x3a3947e0, d0ruAl) 'dir sw_sharpen y_input_delay_line'
[  32] 0x3a395c40: used 3.1K (refcount 1 lock count 0, size     3072, align   32, data 0x3a395c60, d0rual) 'stabilise ref_ss'
[  39] 0x3a396880: used 3.1K (refcount 1 lock count 0, size     3072, align   32, data 0x3a3968a0, d0rual) 'stabilise ref_ss'
[  38] 0x3a3974c0: used 1.2K (refcount 1 lock count 0, size     1152, align   32, data 0x3a3974e0, d0ruAl) 'drc out'
[  49] 0x3a397980: used 1.2K (refcount 1 lock count 0, size     1152, align   32, data 0x3a3979a0, d0ruAl) 'drc in'
[  50] 0x3a397e40: used 3.8K (refcount 1 lock count 0, size     3840, align   32, data 0x3a397e60, d0ruAl) 'drc out'
[  51] 0x3a398d80: used 3.8K (refcount 1 lock count 0, size     3840, align   32, data 0x3a398da0, d0ruAl) 'drc in'
[  18] 0x3a399cc0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a399ce0, d0rual) 'ls table 4'
[  81] 0x3a39ff20: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a39ff40, d0rual) 'ls table 3'
[  23] 0x3a3a6180: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a3a61a0, d0rual) 'ls table 2'
[  24] 0x3a3ac3e0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a3ac400, d0rual) 'ls table 1'
[  25] 0x3a3b2640: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a3b2660, d0rual) 'ls table 0'
0x3a3b88a0: free 384
[  44] 0x3a3b8a20: used  576 (refcount 1 lock count 0, size      512, align   32, data 0x3a3b8a40, d0ruAl) 'drc in last lvl'
[  42] 0x3a3b8c60: used  12K (refcount 1 lock count 0, size    12672, align   32, data 0x3a3b8c80, d0ruAl) 'drc out'
[  41] 0x3a3bbe20: used  12K (refcount 1 lock count 0, size    12672, align   32, data 0x3a3bbe40, d0ruAl) 'drc in'
[  55] 0x3a3befe0: used  45K (refcount 1 lock count 0, size    45696, align   32, data 0x3a3bf000, d0ruAl) 'drc in'
[  58] 0x3a3ca2a0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca2c0, d1rual) 'null_sink:in:0(OPQV)'
[  59] 0x3a3ca360: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca380, d1rual) 'null_sink:in:0(OPQV)'
[  60] 0x3a3ca420: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca440, d1rual) 'null_sink:in:0(OPQV)'
[  27] 0x3a3ca4e0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca500, d1rual) 'null_sink:in:0(OPQV)'
[  48] 0x3a3ca5a0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca5c0, d1rual) 'null_sink:in:0(OPQV)'
[  62] 0x3a3ca660: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca680, d1rual) 'null_sink:in:0(OPQV)'
[  47] 0x3a3ca720: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca740, d1rual) 'null_sink:in:0(OPQV)'
[  46] 0x3a3ca7e0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca800, d1rual) 'null_sink:in:0(OPQV)'
[  31] 0x3a3ca8a0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca8c0, d1rual) 'null_sink:in:0(OPQV)'
[  52] 0x3a3ca960: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3a3ca980, d1rual) 'null_sink:in:0(OPQV)'
[  67] 0x3a3caa20: used 4.3K (refcount 1 lock count 0, size     4378, align    4, data 0x3a3caa40, d0rual) 'distortion table'
[  17] 0x3a3cbb80: used 135K (refcount 1 lock count 0, size   138240, align    4, data 0x3a3cbba0, d0rual) 'isp sw stage buffers'
[  15] 0x3a3ed7c0: used 271K (refcount 1 lock count 0, size   277512, align    4, data 0x3a3ed7e0, d0rual) 'concurrent mdata'
[  80] 0x3a431420: used 4.3K (refcount 1 lock count 0, size     4378, align    4, data 0x3a431440, d0rual) 'distortion table'
[  36] 0x3a432580: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a4325a0, d0rual) 'ls table isp'
[  37] 0x3a4387e0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a438800, d0rual) 'ls table tx1'
[  63] 0x3a43ea40: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a43ea60, d0rual) 'ls table tx0'
[  64] 0x3a444ca0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a444cc0, d0rual) 'ls table 1'
[  28] 0x3a44af00: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3a44af20, d0rual) 'ls table 0'
[  78] 0x3a451160: used  52K (refcount 1 lock count 0, size    53504, align    4, data 0x3a451180, d1rual) 'AWB State (makesum_direct)'
[  71] 0x3a45e2a0: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a45e2c0, d1rual) 'AWB State (CCMs)'
[  70] 0x3a462ae0: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a462b00, d1rual) 'AWB State (CCMs)'
[  35] 0x3a467320: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3a467340, d1rual) 'AWB State (CCMs)'
[  66] 0x3a46bb60: used 135K (refcount 1 lock count 0, size   138240, align    4, data 0x3a46bb80, d0rual) 'isp sw stage buffers'
[  65] 0x3a48d7a0: used 271K (refcount 1 lock count 0, size   277512, align    4, data 0x3a48d7c0, d0rual) 'concurrent mdata'
[  40] 0x3a4d1400: used 7.8M (refcount 1 lock count 1, size  8208384, align 4096, data 0x3a4d2000, d1rual) 'cameraRIL:input pool'
[   5] 0x3aca6420: used 2.1M (refcount 1 lock count 0, size  2145472, align 4096, data 0x3aca7000, d1ruAl) 'cameraRIL: lowres pool'
[   9] 0x3aeb3100: used 2.1M (refcount 1 lock count 0, size  2145472, align 4096, data 0x3aeb4000, d1ruAl) 'cameraRIL: lowres pool'
[  10] 0x3b0bfde0: used 2.1M (refcount 1 lock count 1, size  2145472, align 4096, data 0x3b0c0000, d1rual) 'cameraRIL: lowres pool'
[  11] 0x3b2ccac0: used 7.3M (refcount 1 lock count 0, size  7635648, align 4096, data 0x3b2cd000, d1ruAl) 'cameraRIL: hires stills pool'
[  12] 0x3ba15da0: used  11M (refcount 1 lock count 0, size 11658432, align 4096, data 0x3ba16000, d1ruAL) 'cameraRIL: hires vid pool'
[  13] 0x3c535280: used  11M (refcount 1 lock count 0, size 11658432, align 4096, data 0x3c536000, d1ruAL) 'cameraRIL: hires vid pool'
[  14] 0x3d054760: used  11M (refcount 1 lock count 1, size 11658432, align 4096, data 0x3d055000, d1ruaL) 'cameraRIL: hires vid pool'
[   8] 0x3db73c40: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db73c60, d1rual) 'ril mem ril.camera-0'
[   7] 0x3db73f80: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db73fa0, d1rual) 'ril mem ril.camera-0'
[   6] 0x3db742c0: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db742e0, d1rual) 'ril mem ril.camera-0'
[  33] 0x3db74600: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db74620, d1rual) 'ril mem ril.camera-0'
[   4] 0x3db74940: used  576 (refcount 1 lock count 0, size      512, align    4, data 0x3db74960, d0rual) 'ILCS VC buffer pool'
[   3] 0x3db74b80: used 537K (refcount 1 lock count 8, size   545792, align 4096, data 0x3db75000, d1rual) 'ARM FB'
[   2] 0x3dbfafa0: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x3dbfafc0, d0ruAl) 'audioplus_tmp_buf'
[   1] 0x3dbfefe0: used 4.0K (refcount 1 lock count 0, size        0, align 4096, data 0x3dbff000, d1rual) 'camera fast alloc arena'
small allocs not requested

[AndySchroder]

I then changed the resolution picamera was using to be 1296x972 (was 2592x1944). The output changed a bit. The memory free increased slightly and the memory used by many of the items was reduced. I'm not sure what "blocks" are, but maybe they have a certain maximum per block and it is too close to that limit with the highest resolution that sometimes it doesn't have enough? I am going to run with this resolution for several weeks and see if it reduces the frequency of the problem.

$ sudo vcdbg reloc

Relocatable heap version 4 found at 0x2f000000
total space allocated is 236M, with 236M relocatable, 0 legacy and 0 offline
0 legacy blocks of size 2359296

free list at 0x3c9d2400
213M free memory in 3 free block(s)
largest free block is 213M bytes

0x2f000000: free 213M
[  52] 0x3c579240: used 2.6K (refcount 1 lock count 0, size     2624, align   32, data 0x3c579260, d0ruAl) 'dir sw_sharpen y_spd_delay_line_h'
[  46] 0x3c579cc0: used 1.8M (refcount 1 lock count 0, size  1920768, align   32, data 0x3c579ce0, d1rual) 'ril mem ril.camera-3'
[  47] 0x3c74ec00: used 1.8M (refcount 1 lock count 0, size  1920768, align   32, data 0x3c74ec20, d1rual) 'ril.camera:out:1(I420)'
[  35] 0x3c923b40: used  48K (refcount 1 lock count 0, size    49152, align   32, data 0x3c923b60, d0rual) 'stabilise ref'
[  16] 0x3c92fb80: used  48K (refcount 1 lock count 0, size    49152, align   32, data 0x3c92fba0, d0rual) 'stabilise ref'
[  49] 0x3c93bbc0: used 174K (refcount 1 lock count 0, size   178432, align   32, data 0x3c93bbe0, d0ruAl) 'drc lp'
[  29] 0x3c967500: used  87K (refcount 1 lock count 0, size    88704, align   32, data 0x3c967520, d0ruAl) 'drc out'
[  39] 0x3c97cfc0: used  87K (refcount 1 lock count 0, size    88704, align   32, data 0x3c97cfe0, d0ruAl) 'drc in'
[  24] 0x3c992a80: used  52K (refcount 1 lock count 0, size    53504, align    4, data 0x3c992aa0, d1rual) 'AWB State (makesum_direct)'
[  25] 0x3c99fbc0: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3c99fbe0, d1rual) 'AWB State (CCMs)'
[  26] 0x3c9a4400: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3c9a4420, d1rual) 'AWB State (CCMs)'
[  82] 0x3c9a8c40: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3c9a8c60, d1rual) 'AWB State (CCMs)'
0x3c9ad480: free 2.1K
[  31] 0x3c9adcc0: used 2.6K (refcount 1 lock count 0, size     2624, align   32, data 0x3c9adce0, d0ruAl) 'dir sw_sharpen y_input_delay_line'
[  71] 0x3c9ae740: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x3c9ae760, d0rual) 'stabilise current image'
[  70] 0x3c9b2780: used 3.1K (refcount 1 lock count 0, size     3072, align   32, data 0x3c9b27a0, d0rual) 'stabilise ref_ss'
[  17] 0x3c9b33c0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3c9b33e0, d0rual) 'ls table 4'
[  67] 0x3c9b9620: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3c9b9640, d0rual) 'ls table 3'
[  18] 0x3c9bf880: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3c9bf8a0, d0rual) 'ls table 2'
[  81] 0x3c9c5ae0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3c9c5b00, d0rual) 'ls table 1'
[  23] 0x3c9cbd40: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3c9cbd60, d0rual) 'ls table 0'
0x3c9d1fa0: free 1.1K
[  32] 0x3c9d2420: used 3.1K (refcount 1 lock count 0, size     3072, align   32, data 0x3c9d2440, d0rual) 'stabilise ref_ss'
[  50] 0x3c9d3060: used  320 (refcount 1 lock count 0, size      256, align   32, data 0x3c9d3080, d0ruAl) 'drc in last lvl'
[  51] 0x3c9d31a0: used  832 (refcount 1 lock count 0, size      768, align   32, data 0x3c9d31c0, d0ruAl) 'drc out'
[  42] 0x3c9d34e0: used  832 (refcount 1 lock count 0, size      768, align   32, data 0x3c9d3500, d0ruAl) 'drc in'
[  41] 0x3c9d3820: used 1.9K (refcount 1 lock count 0, size     1920, align   32, data 0x3c9d3840, d0ruAl) 'drc out'
[  45] 0x3c9d3fe0: used 1.9K (refcount 1 lock count 0, size     1920, align   32, data 0x3c9d4000, d0ruAl) 'drc in'
[  55] 0x3c9d47a0: used 6.8K (refcount 1 lock count 0, size     6912, align   32, data 0x3c9d47c0, d0ruAl) 'drc out'
[  56] 0x3c9d62e0: used 6.8K (refcount 1 lock count 0, size     6912, align   32, data 0x3c9d6300, d0ruAl) 'drc in'
[  57] 0x3c9d7e20: used  23K (refcount 1 lock count 0, size    23936, align   32, data 0x3c9d7e40, d0ruAl) 'drc out'
[  30] 0x3c9ddbe0: used  23K (refcount 1 lock count 0, size    23936, align   32, data 0x3c9ddc00, d0ruAl) 'drc in'
[  38] 0x3c9e39a0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3c9e39c0, d1rual) 'null_sink:in:0(OPQV)'
[  44] 0x3c9e3a60: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3c9e3a80, d1rual) 'null_sink:in:0(OPQV)'
[  43] 0x3c9e3b20: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3c9e3b40, d1rual) 'null_sink:in:0(OPQV)'
[  53] 0x3c9e3be0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3c9e3c00, d1rual) 'null_sink:in:0(OPQV)'
[  58] 0x3c9e3ca0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3c9e3cc0, d1rual) 'null_sink:in:0(OPQV)'
[  62] 0x3c9e3d60: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3c9e3d80, d1rual) 'null_sink:in:0(OPQV)'
[  59] 0x3c9e3e20: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3c9e3e40, d1rual) 'null_sink:in:0(OPQV)'
[  60] 0x3c9e3ee0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3c9e3f00, d1rual) 'null_sink:in:0(OPQV)'
[  27] 0x3c9e3fa0: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3c9e3fc0, d1rual) 'null_sink:in:0(OPQV)'
[  48] 0x3c9e4060: used  192 (refcount 1 lock count 0, size      128, align   32, data 0x3c9e4080, d1rual) 'null_sink:in:0(OPQV)'
[  79] 0x3c9e4120: used 4.3K (refcount 1 lock count 0, size     4378, align    4, data 0x3c9e4140, d0rual) 'distortion table'
[  15] 0x3c9e5280: used 135K (refcount 1 lock count 0, size   138240, align    4, data 0x3c9e52a0, d0rual) 'isp sw stage buffers'
[  14] 0x3ca06ec0: used 271K (refcount 1 lock count 0, size   277512, align    4, data 0x3ca06ee0, d0rual) 'concurrent mdata'
[  65] 0x3ca4ab20: used 4.3K (refcount 1 lock count 0, size     4378, align    4, data 0x3ca4ab40, d0rual) 'distortion table'
[  66] 0x3ca4bc80: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3ca4bca0, d0rual) 'ls table isp'
[  80] 0x3ca51ee0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3ca51f00, d0rual) 'ls table tx1'
[  36] 0x3ca58140: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3ca58160, d0rual) 'ls table tx0'
[  37] 0x3ca5e3a0: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3ca5e3c0, d0rual) 'ls table 1'
[  63] 0x3ca64600: used  25K (refcount 1 lock count 0, size    25100, align    4, data 0x3ca64620, d0rual) 'ls table 0'
[  64] 0x3ca6a860: used  52K (refcount 1 lock count 0, size    53504, align    4, data 0x3ca6a880, d1rual) 'AWB State (makesum_direct)'
[  28] 0x3ca779a0: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3ca779c0, d1rual) 'AWB State (CCMs)'
[  78] 0x3ca7c1e0: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3ca7c200, d1rual) 'AWB State (CCMs)'
[  61] 0x3ca80a20: used  18K (refcount 1 lock count 0, size    18432, align    4, data 0x3ca80a40, d1rual) 'AWB State (CCMs)'
[  22] 0x3ca85260: used 135K (refcount 1 lock count 0, size   138240, align    4, data 0x3ca85280, d0rual) 'isp sw stage buffers'
[  68] 0x3caa6ea0: used 271K (refcount 1 lock count 0, size   277512, align    4, data 0x3caa6ec0, d0rual) 'concurrent mdata'
[  33] 0x3caeab00: used 6.1M (refcount 1 lock count 0, size  6422528, align 4096, data 0x3caeb000, d1ruAl) 'cameraRIL:input pool'
[  40] 0x3d10bb20: used 595K (refcount 1 lock count 0, size   605376, align 4096, data 0x3d10c000, d1ruAl) 'cameraRIL: lowres pool'
[   5] 0x3d1a0800: used 595K (refcount 1 lock count 0, size   605376, align 4096, data 0x3d1a1000, d1ruAl) 'cameraRIL: lowres pool'
[   9] 0x3d2354e0: used 595K (refcount 1 lock count 1, size   605376, align 4096, data 0x3d236000, d1rual) 'cameraRIL: lowres pool'
[  10] 0x3d2ca1c0: used 1.9M (refcount 1 lock count 0, size  1967040, align 4096, data 0x3d2cb000, d1ruAl) 'cameraRIL: hires stills pool'
[  11] 0x3d4ab5a0: used 2.3M (refcount 1 lock count 0, size  2366656, align 4096, data 0x3d4ac000, d1ruAL) 'cameraRIL: hires vid pool'
[  12] 0x3d6ee280: used 2.3M (refcount 1 lock count 0, size  2366656, align 4096, data 0x3d6ef000, d1ruAL) 'cameraRIL: hires vid pool'
[  13] 0x3d930f60: used 2.3M (refcount 1 lock count 1, size  2366656, align 4096, data 0x3d931000, d1ruaL) 'cameraRIL: hires vid pool'
[   6] 0x3db73c40: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db73c60, d1rual) 'ril mem ril.camera-0'
[   7] 0x3db73f80: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db73fa0, d1rual) 'ril mem ril.camera-0'
[   8] 0x3db742c0: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db742e0, d1rual) 'ril mem ril.camera-0'
[  54] 0x3db74600: used  832 (refcount 1 lock count 0, size      740, align   32, data 0x3db74620, d1rual) 'ril mem ril.camera-0'
[   4] 0x3db74940: used  576 (refcount 1 lock count 0, size      512, align    4, data 0x3db74960, d0rual) 'ILCS VC buffer pool'
[   3] 0x3db74b80: used 537K (refcount 1 lock count 8, size   545792, align 4096, data 0x3db75000, d1rual) 'ARM FB'
[   2] 0x3dbfafa0: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x3dbfafc0, d0ruAl) 'audioplus_tmp_buf'
[   1] 0x3dbfefe0: used 4.0K (refcount 1 lock count 0, size        0, align 4096, data 0x3dbff000, d1rual) 'camera fast alloc arena'
small allocs not requested

[AndySchroder]

I should note that these results are not from a raspberry pi 3 or the v2 camera. The v2 camera is very out of focus, so I did not use it. I did run rpi-update a few weeks ago.

[AndySchroder]

I unfortunately have still not yet been able to follow all of the troubleshooting suggestions indicated above.

One thing I was able to do was reduce the spatial resolution from 2592x1944 down to 1296x972. After doing so I have had 40 days so far of continuous run time without the need for a python interpreter restart or reboot.

[Amrosik]

"'PiCamera' object attribute 'CAPTURE_TIMEOUT' is read-only"

Who did that? I was able to do long exposures with the V2. Why was this made read-only?

[waveform80]

@Amrosik sorry, that's my fault for adding __slots__ into 1.11 (or thereabouts). Just adjust the parameter on the class instead of the instance as a workaround:

import picamera

camera = picamera.PiCamera()
picamera.PiCamera.CAPTURE_TIMEOUT = 60
...

[waveform80]

I'm going to tentatively mark this upstream given there's an open firmware issue for now...

[sumitkm]

Was there a fix for this? I have done multiple updates/upgrades but my Pi Camera v1 on a Raspberry Pi 3A+ doesn't want to capture anything. The Red light comes on and then it times out with the capture timeout error.

This is my code

from time import sleep
from picamera import PiCamera

camera = PiCamera()
camera.resolution = (1024, 768)
# Camera warm-up time
sleep(2)
camera.capture('foo.jpg')

And this is what I get

Traceback (most recent call last):
  File "camera_test.py", line 9, in <module>
    camera.capture('foo.jpg')
  File "/usr/lib/python3/dist-packages/picamera/camera.py", line 1423, in capture
    'Timed out waiting for capture to end')
picamera.exc.PiCameraRuntimeError: Timed out waiting for capture to end

December 2020 build of Raspbian Lite.

Is there a way to force firmware overwrite? If I had to swap what do I swap, the Pi or the Camera?

Update 1:
I swapped the Pi 3A+ with latest build with a Pi 3A+ with an older build and the same camera works. So firmware corruption is probably the issue or the latest December 2020 build has broken something.
This old build works

Linux enviropi 4.19.118-v7+ #1311 SMP Mon Apr 27 14:21:24 BST 2020 armv7l GNU/Linux