high throughput experiment, Sony A7R-ii

[jbreiden]

I'm taking a look at the Sony A7R-ii again, for fastest possible sustained shooting. It can take multiple seconds to process an image onboard the camera, so I use a pipeline approach. First trigger a few shots to prime the pump. The introduce a new concept gphoto2 --pipeline which triggers a new shot, and downloads the oldest shot from RAM. The implementation is a little weird because ghoto2 --capture-tethered was the only mechanism I have to download from RAM, so I modified it meet my needs . It now only downloads the oldest picture. And it completely ignore any non-picture events from the camera. (I worry that I'm doing this part incorrectly and perhaps they are piling up somewhere in memory.) Results are interesting. Sometimes it works well, and sometimes the camera starts slowing down after a bunch of shots. I am interested in any comments or feedback on this approach, and whether it makes sense to incorporate something like this officially into gphoto2.

This is what it looks like when things go well.

# Let's watch this in action
for i in `seq 1 5`; do
  gphoto2 --trigger-capture
  sleep 1
done
gphoto2 --pipeline --quiet --force-overwrite -I 1350 -F 20 

  #00 Spent 922 of 1350 milliseconds
  #01 Spent 903 of 1350 milliseconds
  #02 Spent 953 of 1350 milliseconds
  #03 Spent 1020 of 1350 milliseconds
  #04 Spent 1029 of 1350 milliseconds
  #05 Spent 1099 of 1350 milliseconds
  #06 Spent 1063 of 1350 milliseconds
  #07 Spent 1110 of 1350 milliseconds
  #08 Spent 1090 of 1350 milliseconds
  #09 Spent 1017 of 1350 milliseconds
  #10 Spent 1051 of 1350 milliseconds
  #11 Spent 917 of 1350 milliseconds
  #12 Spent 893 of 1350 milliseconds
  #13 Spent 919 of 1350 milliseconds
  #14 Spent 872 of 1350 milliseconds
  #15 Spent 944 of 1350 milliseconds
  #16 Spent 922 of 1350 milliseconds
  #17 Spent 1035 of 1350 milliseconds
  #18 Spent 937 of 1350 milliseconds
  #19 Spent 995 of 1350 milliseconds

This is the failure mode. Once a shot gets close to our time budget, everything falls to pieces; observe shot 11 and onwards. What's happening is our old friend property 0xd215 claims that there is no image available from RAM and we have to retry a bunch of times before it shows up.

  #00 Spent 971 of 1200 milliseconds
  #01 Spent 965 of 1200 milliseconds
  #02 Spent 1075 of 1200 milliseconds
  #03 Spent 1028 of 1200 milliseconds
  #04 Spent 963 of 1200 milliseconds
  #05 Spent 896 of 1200 milliseconds
  #06 Spent 941 of 1200 milliseconds
  #07 Spent 1002 of 1200 milliseconds
  #08 Spent 950 of 1200 milliseconds
  #09 Spent 1008 of 1200 milliseconds
  #10 Spent 1044 of 1200 milliseconds
  #11 Spent 1316 of 1200 milliseconds
  #12 Spent 1244 of 1200 milliseconds
  #13 Spent 1326 of 1200 milliseconds
  #14 Spent 1575 of 1200 milliseconds
  #15 Spent 1439 of 1200 milliseconds
  #16 Spent 1363 of 1200 milliseconds
  #17 Spent 1425 of 1200 milliseconds
  #18 Spent 1611 of 1200 milliseconds
  #19 Spent 1367 of 1200 milliseconds

This is what failure looks like with logging turned on. Here we are trying four times before finding SONY ObjectInMemory. Hey, that's interesting. Why are we seeing 0x0001? It's almost looking like we have drained the pipeline. I think that's what is going on.

9.157391 actions                     (2): XXX entering action_camera_wait_event
9.157417 actions                     (2): XXX about to enter gp_camera_wait_for_event
9.157429 camera_wait_for_event       (2): waiting for events timeout 1000 ms
9.157449 ptp_usb_sendreq             (2): Sending PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) request...
9.157860 ptp_usb_getdata             (2): Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) data...
9.171264 ptp_usb_getresp             (2): Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) response...
9.180606 ptp                         (2): ptp_sony_getalldevicepropdesc: d215: value 32769 -> 1
9.180636 camera_wait_for_event       (2): DEBUG== 0xd215 after capture = 0x0001
9.180645 camera_wait_for_event       (2): XXX Did not find SONY ObjectInMemory, looking again.
9.230816 ptp_usb_sendreq             (2): Sending PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) request...
9.231210 ptp_usb_getdata             (2): Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) data...
9.232753 ptp_usb_getresp             (2): Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) response...
9.233124 camera_wait_for_event       (2): DEBUG== 0xd215 after capture = 0x0001
9.233149 camera_wait_for_event       (2): XXX Did not find SONY ObjectInMemory, looking again.
9.333297 ptp_usb_sendreq             (2): Sending PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) request...
9.333718 ptp_usb_getdata             (2): Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) data...
9.335340 ptp_usb_getresp             (2): Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) response...
9.335998 ptp                         (2): ptp_sony_getalldevicepropdesc: d215: value 1 -> 2
9.336028 camera_wait_for_event       (2): DEBUG== 0xd215 after capture = 0x0002
9.336038 camera_wait_for_event       (2): XXX Did not find SONY ObjectInMemory, looking again.
9.486194 ptp_usb_sendreq             (2): Sending PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) request...
9.486600 ptp_usb_getdata             (2): Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) data...
9.489118 ptp_usb_getresp             (2): Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) response...
9.490013 camera_wait_for_event       (2): DEBUG== 0xd215 after capture = 0x0002
9.490039 camera_wait_for_event       (2): XXX Did not find SONY ObjectInMemory, looking again.
9.690169 ptp_usb_sendreq             (2): Sending PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) request...
9.690243 _cb_irq                     (2): 0x2164d08 with status 0
9.690263 _cb_irq                     (2): requeuing complete transfer 0x2164d08
9.690284 _cb_irq                     (2): 0x2161de8 with status 0
9.690299 _cb_irq                     (2): requeuing complete transfer 0x2161de8
9.690316 _cb_irq                     (2): 0x2164ed8 with status 0
9.690328 _cb_irq                     (2): requeuing complete transfer 0x2164ed8
9.690578 ptp_usb_getdata             (2): Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) data...
9.692403 ptp_usb_getresp             (2): Reading PTP_OC 0x9209 (PTP_OC_SONY_GetAllDevicePropData) response...
9.692830 ptp                         (2): ptp_sony_getalldevicepropdesc: d215: value 2 -> 32770
9.692860 camera_wait_for_event       (2): DEBUG== 0xd215 after capture = 0x8002
9.692869 camera_wait_for_event       (2): SONY ObjectInMemory count change seen, retrieving file

Turn off autofocus because this is a manual focus lens.

--- a/camlibs/ptp2/library.c
+++ b/camlibs/ptp2/library.c
@@ -4493,8 +4467,8 @@ camera_trigger_capture (Camera *camera, GPContext *context)
                PTPDevicePropDesc       dpd;

-                /* half-press */
-               propval.u16 = 2;
-               C_PTP (ptp_sony_setdevicecontrolvalueb (params, PTP_DPC_SONY_AutoFocus, &propval, PTP_DTC_UINT16));

                /* full-press */
                propval.u16 = 2;
@@ -4504,42 +4478,16 @@ camera_trigger_capture (Camera *camera, GPContext *context)
                 * get focus, indicated by the 0xD213 property. But hold it for at most 1 second.
                 */

-               GP_LOG_D ("holding down shutterbutton");
-               event_start = time_now();
-               do {
-                       /* needed on older cameras like the a58, check for events ... */
-                       C_PTP (ptp_check_event (params));
-                       if (ptp_get_one_event(params, &event)) {
-                               GP_LOG_D ("during event.code=%04x Param1=%08x", event.Code, event.Param1);
-                               if (    (event.Code == PTP_EC_Sony_PropertyChanged) &&
-                                       (event.Param1 == PTP_DPC_SONY_FocusFound)
-                               ) {
-                                       GP_LOG_D ("SONY FocusFound change received, 0xd213... ending press");
-                                       break;
-                               }
-                       }
-
-                       /* Alternative code in case we miss the event */
-
-                       C_PTP (ptp_sony_getalldevicepropdesc (params)); /* avoid caching */
-                       C_PTP (ptp_generic_getdevicepropdesc (params, PTP_DPC_SONY_FocusFound, &dpd));
-                       GP_LOG_D ("DEBUG== 0xd213 after shutter press = %d", dpd.CurrentValue.u8);
-                       /* if prop 0xd213 = 2, the focus seems to be achieved */
-                       if (dpd.CurrentValue.u8 == 2) {
-                               GP_LOG_D ("SONY Property change seen, 0xd213... ending press");
-                               break;
-                       }
-
-               } while (time_since (event_start) < 1000);
-               GP_LOG_D ("releasing shutterbutton");

                /* release full-press */
                propval.u16 = 1;
                C_PTP (ptp_sony_setdevicecontrolvalueb (params, PTP_DPC_SONY_Capture, &propval, PTP_DTC_UINT16));

-                /* release half-press */
-               propval.u16 = 1;
-               C_PTP (ptp_sony_setdevicecontrolvalueb (params, PTP_DPC_SONY_AutoFocus, &propval, PTP_DTC_UINT16));

                return GP_OK;
        }

Transfer entire image at once.

--- a/camlibs/ptp2/usb.c
+++ b/camlibs/ptp2/usb.c
@@ -256,7 +256,7 @@ retry:
        return PTP_ERROR_IO;
 }

-#define READLEN 512*1024 /* read blob size, mostly to avoid reading all of it at once. */
+#define READLEN 16*1024*1024 /* read blob size, reading all of it at once. */

 uint16_t
 ptp_usb_getdata (PTPParams* params, PTPContainer* ptp, PTPDataHandler *handler)

Only pay attention to images; completely ignore any other camera event. I'm not sure that this is correct; should I be explicitly freeing or dropping non-image events?

--- a/camlibs/ptp2/library.c
+++ b/camlibs/ptp2/library.c
@@ -4993,6 +4941,7 @@ downloadnow:
                                gp_file_unref (file);
                                return GP_OK;
                        }
+                        GP_LOG_D ("XXX Did not find SONY ObjectInMemory, looking again.");
+                        continue;

 sonyout:
                        /* If not, check for events and handle them */

Implement gphoto2 --pipeline, that triggers capture and retrieves the oldest image from RAM. Note that we are treating glob_interval as millisecond instead of seconds. That's cheating but I need precise timing control for experiments. We support looping here to make sure we aren't wasting time with repeated camera initialization.

--- a/gphoto2/main.c
+++ b/gphoto2/main.c
@@ -791,9 +791,53 @@ sig_handler_end_next (int sig_num)
         end_next = 1;
 }

+int
+pipeline (const char *arg) {
+       int f;
+       signed long spent;
+       struct timeval capture_time;
+       int waittime;
+       for (f = 0; f < glob_frames; f++) {
+               gp_log (GP_LOG_DEBUG, "main", "XXX pipeline");
+               gettimeofday (&capture_time, NULL);
+               int result = trigger_capture();
+               if (result != GP_OK) {
+                       cli_error_print(_("Failure in pipeline capture."));
+                       return (result);
+               }
+              result = action_camera_wait_event (&gp_params, DT_DOWNLOAD, arg);
+               if (result != GP_OK) {
+                       cli_error_print(_("Failure in pipeline slurp"));
+                       return (result);
+               }
+              if (glob_interval != -1) {
+                      spent = abs(timediff_now (&capture_time));
+                      gp_log (GP_LOG_DEBUG, "main", "XXX #%02d Spent %ld of %d milliseconds", f, spent, glob_interval);
+                      printf("  #%02d Spent %ld of %d milliseconds\n", f, spent, glob_interval);
+                      waittime = glob_interval - spent;
+                      if (waittime < 0) waittime = 0;
+                      usleep(waittime * 1000);
+               }
+       }
+       return GP_OK;
+}
+
+
 /* temp test function */
 int
 trigger_capture (void) {
@@ -1576,6 +1613,9 @@ cb_arg_run (poptContext __unused__ ctx,
        case ARG_TRIGGER_CAPTURE:
                params->p.r = trigger_capture ();
                break;
+       case ARG_PIPELINE:
+               params->p.r = pipeline (arg);
+               break;
        case ARG_CAPTURE_IMAGE:
                params->p.r = capture_generic (GP_CAPTURE_IMAGE, arg, 0);
                break;
@@ -2060,6 +2106,8 @@ main (int argc, char **argv, char **envp)
                 ARG_CAPTURE_IMAGE, N_("Capture an image"), NULL},
                {"trigger-capture", '\0', POPT_ARG_NONE, NULL,
                 ARG_TRIGGER_CAPTURE, N_("Trigger capture of an image"), NULL},
+               {"pipeline", '\0', POPT_ARG_NONE, NULL,
+                ARG_PIPELINE, N_("pipeline"), NULL},
                {"capture-image-and-download", '\0', POPT_ARG_NONE, NULL,
                 ARG_CAPTURE_IMAGE_AND_DOWNLOAD, N_("Capture an image and download it"), NULL},
                {"capture-movie", '\0', POPT_ARG_STRING|POPT_ARGFLAG_OPTIONAL, NULL,
@@ -2329,6 +2375,7 @@ main (int argc, char **argv, char **envp)
        CHECK_OPT (ARG_STORAGE_INFO);
        CHECK_OPT (ARG_SUMMARY);
        CHECK_OPT (ARG_TRIGGER_CAPTURE);
+       CHECK_OPT (ARG_PIPELINE);
        CHECK_OPT (ARG_UPLOAD_FILE);
        CHECK_OPT (ARG_UPLOAD_METADATA);
        CHECK_OPT (ARG_WAIT_EVENT);

Modify action_camera_wait_event to stop once we've retrieved one image.

--- a/gphoto2/actions.c
+++ b/gphoto2/actions.c
@@ -1238,6 +1245,9 @@ action_camera_wait_event (GPParams *p, enum download_type downloadtype, const ch
                                printf(_("event found, stopping wait!\n"));
                                return GP_OK;
                        }
+                       free (data);  // XXX
+                       gp_log (GP_LOG_DEBUG, "actions", "XXX We got what we were looking for");
+                       return GP_OK;  // XXX
                        break;
                case GP_EVENT_FOLDER_ADDED:
                        fn = (CameraFilePath*)data;

[jbreiden]

I am pretty convinced this approach is hopeless. The camera is draining the pipeline by ... losing images.