CHDKPTP: Time Out during Remote Capture with multiple instances

jbaiter

« on: 15 / December / 2013, 08:40:57 »

Advertisements

I'm using CHDKPTP to control two Canon A2200s to capture images of books.
For this, I wrote a small program that (among a bunch of other stuff) wraps the 'chdkptp' CLI utility, sets up the cameras and controls the triggering.

My problem is this: When I trigger both cameras simultaneously, using two separate 'chdkptp' processes, each directly connecting to the desired device via the '-c' flag, the triggering goes well for up 40 captures on each camera, but inevitably at some point in the process I get a "WARNING: capture_get_data error timed out" message and a subsequent "ERROR: timed out" message, after which the program exits without a picture being taken. After this has taken place, I can no longer perform PTP actions on the device and have to reset it by powering it on and off.

Some facts/observations from my debugging sessions:

Both devices are on the same USB-Bus, directly attached to the host machines. I cannot use separate buses as none of my machines expose more than one bus to the outside.
While control via USB fails, the UI is still responsive on the timed out device
The error seems to be machine-independent: I tried with two different Raspberry Pis and my Thinkpad S430 (running Raspbian/Debian), all of which exhibited the problem
The error seems to be independent from the individual cameras: During some sessions I get the timeout from the first, during others from the second. Until I plug/unplug the devices it is the same camera that times out, though.
The number of shots it takes for one device to time out differs from host to host: My first Raspberry usually times out after 20-40 shots, the second one after ~5, while my laptop usually manages around 10 shots before the inevitable happens.
On each device, I get USB resets in the kernel message log. This happens on every shot, though, not just the ones that time out. Also, it resets on both devices, not just the one that later has the timeout.
Here's one example log entry from one of the Raspberry Pis:
usb 1-1.2: reset high-speed USB device number 4 using dwc_otg
On the Thinkpad it looks like this:
usb 1-3: reset high-speed USB device number 9 using xhci_hcd

Some information on my setup:

Raspberry Pi #1/#2: Model B, Latest raspbian update (Kernel 3.10.24) with fresh firmware, no USB-Hub, powered by a 2A power supply
Thinkpad S430: Debian unstable, latest updates, Kernel 3.12.0
Cameras: Two Canon A2200s, powered by two third-party power supplies
CHDK: CHDK 1.2.0, Build Revision 3262
CHDKPTP: r468, tried with latest SVN, too, made no difference

Any help with this would be greatly appreciated, be it hints on how to debug this further or alternate approaches to the triggering of multiple devices, anything :-)

======
Update:
Some further debugging revelead that the timeouts also appear when using only one camera. Interestingly enough, one of the cameras will reliably timeout 100% of the time, after roughly 60 shots, while the other only times out in roughly 1 of 5 cases (tested by shooting 5x200 images).

« Last Edit: 15 / December / 2013, 16:12:13 by jbaiter »

Logged

reyalp

13150

Re: CHDKPTP: Time Out during Remote Capture with multiple instances

« Reply #1 on: 15 / December / 2013, 19:19:01 »

After some extensive debugging on IRC, the root cause appears to be the alt state getting confused, which causes shoot to fail. The "confused" state involves the alt OSD being displayed, but key presses going to the original canon firmware (and chdk?), and scripted presses of shoot etc not going to the canon firmware.

Using enter_alt() before running the shooting sequence appears to avoid this.

I haven't looked in detail, but I suspect there is a timing issue in the various things that track alt state.

Contrary to the initial report, PTP still works when this problem happens, and using an explicit exit_alt() will clear the problem.

Logged

Don't forget what the H stands for.

reyalp

13150

Re: CHDKPTP: Time Out during Remote Capture with multiple instances

« Reply #2 on: 28 / December / 2013, 01:32:45 »

In changeset 3281 I checked in a change developed by philmoz.

This makes PTP scripts load in kbd task, rather than loading in the ptp task and then actually running in kbd. The old behavior has some places that looked like they might cause the alt state to get confused, but I was never able to reproduce the symptoms jbaiter described.

Starting script in kbd task should also help avoid stack overflow in the ptp task, and IMO is a good idea whether or not it solves the other issues.

This change does increase the time required to start a script, by an average of about 10ms. I wrote some test code for chdkptp to compare the times. In chdkptp, this can be loaded with

Code: [Select]

!m=require'extras/camtests'

The code repeatedly executes script and times how long it takes. The exectime test only times the call to start the script, while execwaittime waits for the return value.

note the the "wall" time for exectime is substantially larger than the total time, because it waits for the script to actually finish before running the next one. In execwaittime, this is included in waiting for return value.

Also, the very first time you run a script seems to be slower, so you should probably run something once to avoid outliers.

old code

Code: [Select]

!m.exectime({count=100})
exec 100 mean 0.0243 min 0.0230 max 0.0250 total 2.4321 (41.1161/sec) wall 4.0222 (24.8618/sec)
!m.execwaittime({count=100})
exec 100 mean 0.0550 min 0.0420 max 0.0620 total 5.5003 (18.1808/sec) wall 5.5003 (18.1808/sec)

New code

Code: [Select]

!m.exectime({count=100})
exec 100 mean 0.0334 min 0.0300 max 0.0390 total 3.3382 (29.9563/sec) wall 5.1983 (19.2371/sec)
!m.execwaittime({count=100})
exec 100 mean 0.0649 min 0.0580 max 0.0720 total 6.4904 (15.4074/sec) wall 6.4914 (15.4051/sec)

Logged

Don't forget what the H stands for.