[gphoto-devel] maximizing shots per second

[Jeff Breidenbach]

I'm interested in taking and downloading continuous automatic
camera shots, as quickly as possible. Camera is Sony A7R-ii
and no memory card. Works great with today's gphoto2 from
github.

Throughput is about 0.3 shots per seconds using gphoto2
--capture-image-and-download. Due to pipelining, throughput
much higher (over 1 hertz) with gphoto2 --capture-tethered and
mashing the shutter release. I want the high throughput but not the
physical button pressing.

I suspect that libgphoto2/samples/sample-trigger-capture.c is
exactly what I am looking for. However it fails with the following
message. Looking for guidance.

$ ./sample-trigger-capture
loop is at 1482029726.742791
loop is at 1482029726.750857
Reading PTP event failed: Timeout reading from or writing to the port (-10)
loop is at 1482029727.059034
triggering capture 1
Reading PTP event failed: Timeout reading from or writing to the port (-10)
Reading PTP event failed: Timeout reading from or writing to the port (-10)
Reading PTP event failed: Timeout reading from or writing to the port (-10)
done triggering
loop is at 1482029728.542823
loop is at 1482029728.550838
loop is at 1482029728.558757
Reading PTP event failed: Timeout reading from or writing to the port (-10)
loop is at 1482029728.863078
loop is at 1482029729.086873
triggering capture 2
Reading PTP event failed: Timeout reading from or writing to the port (-10)
done triggering
loop is at 1482029729.636847
triggering capture 3
Reading PTP event failed: Timeout reading from or writing to the port (-10)
Reading PTP event failed: Timeout reading from or writing to the port (-10)
done triggering
loop is at 1482029730.773895
loop is at 1482029730.966827
loop is at 1482029730.974719
Reading PTP event failed: Timeout reading from or writing to the port (-10)
File / / capt0000.jpg added to queue.
starting download 1 (queuelength = 1)
camera readfile of / / capt0000.jpg at offset 0
You need to specify a folder starting with /store_xxxxxxxxx/

*** Contexterror ***
You need to specify a folder starting with /store_xxxxxxxxx/
'gp_filesystem_read_file (camera->fs, folder, file, type, offset, buf,
size, context)' failed: -6
gp_camera_file_read failed: -6

[Jeff Breidenbach]

Is .3 shots/second about 3 seconds/shot? (I want to confirm this)

Confirmed. Most of the time is presumably spent on things like image
processing and JPEG compression. Data transfer takes a fairly small
portion of the overall time.

Are you talking about the examples directory (I don't see samples)

You are correct, libgphoto2/examples/sample-trigger-capture.c

[Jeff Breidenbach]

Is .3 shots/second about 3 seconds/shot? (I want to confirm this)

Confirmed. Most of the time is presumably spent on things like image
processing and JPEG compression. Data transfer takes a fairly small
portion of the overall time.

Are you talking about the examples directory (I don't see samples)

You are correct, libgphoto2/examples/sample-trigger-capture.c

[Jeff Breidenbach]

I set READLEN set to 14MB, and commented out the focus commands.
The images for this test are 12MB JPEG.

If I place 21 images in RAM with gpoto2 --trigger-capture, I can download
them with gpthoto2 --cpature-tethered at a rate of 60 images per minute.

If I run examples/sample-trigger-capture, I can capture and download 35
images per minute.

Will do some deeper investigation to see exactly where the time is going.

[Jeff Breidenbach]

Getting back to maximizing shots-per-second, I pre-placed a bunch of
photographs in RAM then profiled downloading. About half the time is
spent on data transfer, and the other half is
inside camera_wait_for_event().
That part is a little mysterious to me, any idea what is going on during
this
time?

790 ms : XXX entering sony do loop in camera_wait_for_event
790 ms : Current port timeout is 20000 milliseconds.
790 ms : Setting port timeout to 150 milliseconds.
790 ms : 0x14879b8 with status 0
790 ms : requeuing complete transfer 0x14879b8
790 ms : Setting port timeout to 20000 milliseconds.
790 ms : event: nparams=0x1, code=0xC202, trans_id=0xFFFFFFFF,
p1=0xFFFFC001, p2=0x0, p3=0x0
790 ms : waiting for events timeout 500 ms
790 ms : XXX entering sony do loop in camera_wait_for_event
790 ms : Current port timeout is 20000 milliseconds.
790 ms : Setting port timeout to 150 milliseconds.
804 ms : 0x1486018 with status 0
804 ms : requeuing complete transfer 0x1486018
804 ms : Setting port timeout to 20000 milliseconds.
804 ms : event: nparams=0x1, code=0xC201, trans_id=0xFFFFFFFF,
p1=0xFFFFC001, p2=0x0, p3=0x0
804 ms : waiting for events timeout 487 ms
804 ms : XXX entering sony do loop in camera_wait_for_event
804 ms : Current port timeout is 20000 milliseconds.
804 ms : Setting port timeout to 150 milliseconds.
1104 ms : Setting port timeout to 20000 milliseconds.
1104 ms : Reading PTP event failed: Timeout reading from or writing to the
port (-10)
1105 ms : Sending PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData)
request...
1105 ms : Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) data...
1108 ms : Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData)
response...
1108 ms : ptp_sony_getalldevicepropdesc: d215: value 32790 -> 32789
1108 ms : DEBUG== 0xd215 after capture = 32789
1108 ms : SONY ObjectInMemory count change seen, retrieving file

[Marcus Meissner]

Hi Jeff,

There was one place where we waited an additional 200ms.

I applied the attached patch to current GIT, perhaps this makes it faster.

Ciao, Marcus

Post by Jeff Breidenbach
Getting back to maximizing shots-per-second, I pre-placed a bunch of
photographs in RAM then profiled downloading. About half the time is
spent on data transfer, and the other half is
inside camera_wait_for_event().
That part is a little mysterious to me, any idea what is going on during
this
time?
790 ms : XXX entering sony do loop in camera_wait_for_event
790 ms : Current port timeout is 20000 milliseconds.
790 ms : Setting port timeout to 150 milliseconds.
790 ms : 0x14879b8 with status 0
790 ms : requeuing complete transfer 0x14879b8
790 ms : Setting port timeout to 20000 milliseconds.
790 ms : event: nparams=0x1, code=0xC202, trans_id=0xFFFFFFFF,
p1=0xFFFFC001, p2=0x0, p3=0x0
790 ms : waiting for events timeout 500 ms
790 ms : XXX entering sony do loop in camera_wait_for_event
790 ms : Current port timeout is 20000 milliseconds.
790 ms : Setting port timeout to 150 milliseconds.
804 ms : 0x1486018 with status 0
804 ms : requeuing complete transfer 0x1486018
804 ms : Setting port timeout to 20000 milliseconds.
804 ms : event: nparams=0x1, code=0xC201, trans_id=0xFFFFFFFF,
p1=0xFFFFC001, p2=0x0, p3=0x0
804 ms : waiting for events timeout 487 ms
804 ms : XXX entering sony do loop in camera_wait_for_event
804 ms : Current port timeout is 20000 milliseconds.
804 ms : Setting port timeout to 150 milliseconds.
1104 ms : Setting port timeout to 20000 milliseconds.
1104 ms : Reading PTP event failed: Timeout reading from or writing to the
port (-10)
1105 ms : Sending PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData)
request...
1105 ms : Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) data...
1108 ms : Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData)
response...
1108 ms : ptp_sony_getalldevicepropdesc: d215: value 32790 -> 32789
1108 ms : DEBUG== 0xd215 after capture = 32789
1108 ms : SONY ObjectInMemory count change seen, retrieving file

[Jeff Breidenbach]

(Resending without the big log attachment)

Marcus, that was helpful. Results are interesting. I pre-loaded the camera
with 20 near-identical shots in SDRAM, and gave the camera time to settle.
Then I looped through wait_event_and_download() from
sample-trigger-capture.c

The first 7 images come very quickly, we get them off the camera is roughly
half a second.

loop is at 1484952941.731218
File / / capt0003.jpg added to queue.
camera getfile of / / capt0003.jpg
ending download 0, deleting file.
loop is at 1484952942.225195


Then things suddenly slow down, and we get timeouts during camera
communication. When looking at this very closely, the camera mysteriously
takes a long time before setting property 0xd215
(PTP_DPC_SONY_ObjectInMemory)
to the correct value. It's completely mysterious to me, because those
pictures
are sitting patiently in RAM. What is the camera doing?

I tried to ask Sony using their preferred mechanism and got nowhere.
http://stackoverflow.com/questions/41498265/documentation-for-sony-a7r-ii-
ptp-property-0xd215

Anyway, that's where we are at. Thanks again for your terrific work and the
significant progress on this topic.

loop is at 1484952947.888985
Reading PTP event failed: Timeout reading from or writing to the port (-10)
loop is at 1484952948.201827
Reading PTP event failed: Timeout reading from or writing to the port (-10)
loop is at 1484952948.510054
Reading PTP event failed: Timeout reading from or writing to the port (-10)
loop is at 1484952948.812401
File / / capt0010.jpg added to queue.
camera getfile of / / capt0010.jpg
ending download 0, deleting file.
loop is at 1484952949.335957

[Marcus Meissner]

gp_camera_wait_for_event() takes 1.1 seconds for GP_EVENT_FILE_ADDED.
This seems high, considering only 6MB is transferred. Any thoughts?

Could you regular time image downloads using gphoto2 -P or similar
just to get a feeling of how much time that takes?

Ciao, Marcus