rsint with network socket for control using ipc

quesarilla

12

Re: rsint with network socket for control using ipc

« Reply #20 on: 11 / September / 2021, 22:03:03 »

Advertisements

Quote from: reyalp on 10 / September / 2021, 21:44:06

Quote
27 t0 to t01: 5.6353001127718e-05 t01 to t1: 0.99675145999936t1 to t4: 0.65600149700185
This seems odd. Defining two local variables should not take a noticeable fraction of a second. It should be microseconds. Can you post a diff or the files with the full logging changes?

Yeah, I think this one was my mistake, forgot to declare ones of the timing variables as local, so I was timing it from a different part of the code.

In any case I found the culprit. It's in the wait loop inside get_capture_data(). Here is the latest diff that shows the logging. Looking like it's camera side.

51 Calling capture_get_data()
wait time: 1.6381495999522
52 Calling capture_get_data()
wait time: 1.7816475
53 Calling capture_get_data()
wait time: 1.8490861000028
54 Calling capture_get_data()
wait time: 1.7832486000261
55 Calling capture_get_data()
wait time: 3.2204962000251
56 Calling capture_get_data()
wait time: 3.170976799971
57 Calling capture_get_data()
wait time: 2.9203273999738
58 Calling capture_get_data()
wait time: 3.4219162000227

Code: [Select]

--- C:\Imager\chdkptp-r921-win-x86_64\chdkptp-r921\lua\chdku_stock.lua	Sat Sep 11 21:08:40 2021
+++ C:\Imager\chdkptp-r921-win-x86_64\chdkptp-r921\lua\chdku.lua	Sat Sep 11 21:23:27 2021
@@ -1525,6 +1525,7 @@
 	true or array of store_return[bitnum][value] values on success
 	throws on error
 ]]
+log_file = io.open('C:/Imager/chdkptp-r921-win-x86_64/chdkptp-r921/con_wait_log.txt', 'w')
 function con_methods:capture_get_data(opts)
 	opts=util.extend_table({
 		timeout=20000,
@@ -1560,11 +1561,14 @@
 	local rets = {}
 
 	local done
+	log_file:write("Calling capture_get_data() \n")
+	local t0 = ticktime.get()
 	while not done do
 		local status = con:wait_status(wait_opts)
 		if status.rsdata == 0x10000000 then
 			error('remote shoot error')
 		end
+		log_file:write("  wait time: "..ticktime.elapsed(t0)..'\n')
 		-- initialize subst state when first data available, ~shot time
 		if opts.do_subst and not subst then
 			subst=varsubst.new(chdku.rc_subst_funcs)

Logged

reyalp

14079

Re: rsint with network socket for control using ipc

« Reply #21 on: 12 / September / 2021, 20:11:40 »

Quote from: quesarilla on 11 / September / 2021, 22:03:03

In any case I found the culprit. It's in the wait loop inside get_capture_data(). Here is the latest diff that shows the logging. Looking like it's camera side.

Yeah, that's essentially measuring the time between the shot being requested and the first data becoming available. Have you tried cont mode?

I tested elph130 and sx710 using the attached script. In both cases, the first shot was slower (2s for elph130, 1.5s for sx710) and the following 39 shots were very steady (~1.8s and 1s respectively)

The first shot in a series being slower is something we've seen widely.

Neither of these cameras are very close to yours in terms of model / specs, so it's not surprising they behave differently from yours, but it suggests the problem isn't a global CHDK problem.

Usage for the script is like

Code: [Select]

!m=dofile('rstest.lua')
!do_test(40)

It just feeds rsint an 's' command each time it requests input, up to the number specified.

rstest.lua (0.28 kB - downloaded 5 times.)

Logged

Don't forget what the H stands for.

quesarilla

12

Re: rsint with network socket for control using ipc

« Reply #22 on: 12 / September / 2021, 23:27:57 »

Yes, I tried cont mode but kept seeing the same delay. It turns out this may be a moot point.

I tested my custom multicam script with the 6 camera array but kept getting a timeout error. I'm guessing during the transfer of the chunks one of the instances runs into a timeout while waiting to receive the data.

On the plus side, it's good to know it's not a CHDK issue.

Thanks for the help and all the suggestions by the way

Logged

reyalp

14079

Re: rsint with network socket for control using ipc

« Reply #23 on: 12 / September / 2021, 23:59:50 »

Quote from: quesarilla on 12 / September / 2021, 23:27:57

I tested my custom multicam script with the 6 camera array but kept getting a timeout error. I'm guessing during the transfer of the chunks one of the instances runs into a timeout while waiting to receive the data.

Depending on the specific thing that times out, it may be adjustable. If you use

Code: [Select]

set err_trace=always

it should give you a stack trace that will allow identifying the specific timeout.

Logged

Don't forget what the H stands for.

Caefix

945
Sorry, busy deleting test shots...

Re: rsint with network socket for control using ipc

« Reply #24 on: 13 / September / 2021, 12:44:28 »

Gives benchmarking RAW vs small JPG any hints

?
Are the SD-cards all the same?

« Last Edit: 13 / September / 2021, 15:59:41 by Caefix »

Logged

All lifetime is a loan from eternity.

quesarilla

12

Re: rsint with network socket for control using ipc

« Reply #25 on: 13 / September / 2021, 16:28:10 »

Quote from: reyalp on 12 / September / 2021, 23:59:50

Depending on the specific thing that times out, it may be adjustable. If you use
Code: [Select]
set err_trace=alwaysit should give you a stack trace that will allow identifying the specific timeout.

Thanks for the hint, it came in handy. The camera side runs a loop in wait_shooting() that polls a state from get_shooting() for up to a timeout value; increasing it to 10000 instead of the default 2000 did the trick.

Quote from: Caefix on 13 / September / 2021, 12:44:28

Gives benchmarking RAW vs small JPG any hints ?
Are the SD-cards all the same?

I haven't tried testing with raw mode, but can say that .JPEG files were coming in as a single chunk (I want to say with some files being as large as 2MB, but take it with a grain of salt) on the single camera test. If that's the case I'm guessing the bus/sd card on the pi are the limiting factors here.

Logged

reyalp

14079

Re: rsint with network socket for control using ipc

« Reply #26 on: 13 / September / 2021, 19:59:02 »

Quote from: quesarilla on 13 / September / 2021, 16:28:10

Thanks for the hint, it came in handy. The camera side runs a loop in wait_shooting() that polls a state from get_shooting() for up to a timeout value; increasing it to 10000 instead of the default 2000 did the trick.

Interesting, that's not a place I would have expected. get_shooting should go true when autofocus and auto-exposure are done, so it shouldn't be related to having multiple cameras in the rig, though I guess the chance of one taking longer could be higher.

Quote

I haven't tried testing with raw mode, but can say that .JPEG files were coming in as a single chunk (I want to say with some files being as large as 2MB, but take it with a grain of salt) on the single camera test. If that's the case I'm guessing the bus/sd card on the pi are the limiting factors here.

FWIW, if you wanted to use Canon raw, you'd need chdkptp r964 and chdk 1.5 (or later). But I don't think this is relevant to the drop in shooting speed, since it appears to happen before the data starts.

Logged

Don't forget what the H stands for.

quesarilla

12

Re: rsint with network socket for control using ipc

« Reply #27 on: 13 / September / 2021, 23:33:19 »

Oh really? I thought it did something memory related.

I logged the time it took to complete a single 's' command on the rig over 1200 shots, resulting in an average of 2.7s to complete a single command (effectively 0.45s per camera). Occasionally it would take 4.5s to 5s, maybe every 17 shots or so, which to me looked like buffering behavior. Weird.

Logged

quesarilla2

2

Re: rsint with network socket for control using ipc

« Reply #28 on: 27 / March / 2022, 01:55:17 »

Hello again,

Some months ago I stopped working on this side project as it reached a point where it was good enough for what it needed to do, but now that I have more time I figured I'd take a look into one of the more problematic issues it was having.

Specifically during the disconnect sequence the camera is left in an inconsistent state and unable to be reconnected, throwing the message "open_camera_dev_usb: ptp_opensession failed 0x2ff" when attempting to reconnect (from a difference chdkptp instance).

As a reminder the program is simply a python wrapper that creates a pseudo terminal and attaches an instance of chdkptp.

This error is puzzling to me because the disconnect sequence consists of writing the characters 'q\nplay\ndis\nquit\n' to the terminal when the camera is in rsint mode, sleeping for 2 secs then sending sigint.
I have also added "set usb_reset_on_close=true" to my user.chdkptp file.

Any clues as to what may be going on?

For reference:
CHDK Version: 1.4.1
CHDKPTP r921
OS: raspbian stretch, wsl debian bullseye

Communication logs of the terminal:

Code: [Select]

  [>> CAM_T]:
    c -b="001" -d="012"
  [>> CAM_T]:
    !local py_status, py_res = con:is_connected_pcall()
    if (py_status and py_res) then py_return=true else py_return=false
    py_last_err="Error occurred while  attempting to determine camera
    connection" end  id_e0735f5tdwxc=py_return
  [>> CAM_T]:
    !if id_e0735f5tdwxc~=nil then print("id_e0735f5tdwxc
    =#"..tostring(id_e0735f5tdwxc).."#") end
  [CAM_T >>]:
___>
  [>> CAM_T]:
    !if id_e0735f5tdwxc~=nil then print("id_e0735f5tdwxc
    =#"..tostring(id_e0735f5tdwxc).."#") end
  [CAM_T >>]:
    open_camera_dev_usb: ptp_opensession failed 0x2ff
    Device status OK
    open_camera_dev_usb: ptp_opensession 2 failed: 0x2ff
ERROR: connection failed
stack traceback:
        [C]: in function
'connect'
        /home/debianusr/chdkptp/chdkptp-r921/lua/chdku.lua:1740:
in function 'connect'
/home/debianusr/chdkptp/chdkptp-r921/lua/cli.lua:1752: in function
</home/debianusr/chdkptp/chdkptp-r921/lua/cli.lua:1686>
        (...tail
calls...)
        [C]: in function 'xpcall'
/home/debianusr/chdkptp/chdkptp-r921/lua/cli.lua:285: in function
'execute'
        /home/debianusr/chdkptp/chdkptp-r921/lua/cli.lua:408: in
function </home/debianusr/chdkptp/chdkptp-r921/lua/cli.lua:391>
(...tail calls...)
/home/debianusr/chdkptp/chdkptp-r921/lua/main.lua:302: in main chunk
[C]: in function 'require'
        [string "require('main')"]:1: in
main chunk
___> id_e0735f5tdwxc=#false#
___>
id_e0735f5tdwxc=#false#

Kernel log (wsl):

Code: [Select]

[   18.076347] vhci_hcd vhci_hcd.0: Device attached
[   18.433749] usb 1-1: new high-speed USB device number 2 using vhci_hcd
[   18.583829] usb 1-1: SetAddress Request (2) to port 0
[   18.618664] usb 1-1: New USB device found, idVendor=04a9, idProduct=325b, bcdDevice= 0.02
[   18.618667] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[   18.618684] usb 1-1: Product: Canon Digital Camera
[   18.618685] usb 1-1: Manufacturer: Canon Inc.
[   18.618685] usb 1-1: SerialNumber: D87C98719F034A60A061B6148EB1FBC7
[   49.039414] hv_balloon: Max. dynamic memory size: 32360 MB
[   50.783042] TCP: eth0: Driver has suspect GRO implementation, TCP performance may be compromised.
[  124.514633] vhci_hcd: unlink->seqnum 411
[  124.514634] vhci_hcd: the urb (seqnum 411) was already given back
[  125.473638] usb usb1-port1: Cannot enable. Maybe the USB cable is bad?
[  126.433851] usb usb1-port1: Cannot enable. Maybe the USB cable is bad?
[  127.393878] usb usb1-port1: Cannot enable. Maybe the USB cable is bad?
[  128.353938] usb usb1-port1: Cannot enable. Maybe the USB cable is bad?
[  128.354216] usb 1-1: USB disconnect, device number 2
[  129.313896] usb usb1-port1: Cannot enable. Maybe the USB cable is bad?
[  130.273869] usb usb1-port1: Cannot enable. Maybe the USB cable is bad?
[  130.273886] usb usb1-port1: attempt power cycle
[  131.273860] usb usb1-port1: Cannot enable. Maybe the USB cable is bad?
[  132.233765] usb usb1-port1: Cannot enable. Maybe the USB cable is bad?
[  132.233782] usb usb1-port1: unable to enumerate USB device

Logged

reyalp

14079

Re: rsint with network socket for control using ipc

« Reply #29 on: 27 / March / 2022, 14:33:29 »

Quote from: quesarilla2 on 27 / March / 2022, 01:55:17

Specifically during the disconnect sequence the camera is left in an inconsistent state and unable to be reconnected, throwing the message "open_camera_dev_usb: ptp_opensession failed 0x2ff" when attempting to reconnect (from a difference chdkptp instance).

0x2ff just means IO error, so this tells you chdkptp tried to talk to the camera (or really, the USB library) and failed, but it's not very informative.

Quote

As a reminder the program is simply a python wrapper that creates a pseudo terminal and attaches an instance of chdkptp.

This error is puzzling to me because the disconnect sequence consists of writing the characters 'q\nplay\ndis\nquit\n' to the terminal when the camera is in rsint mode, sleeping for 2 secs then sending sigint.
I have also added "set usb_reset_on_close=true" to my user.chdkptp file.

Purely a guess, but one thing that occurs to me is there might need to be some delay between 'q', 'play' and 'dis'. If this is the cause, I'd expect something like half a second to be plenty.

Also FWIW, 'play' implicitly does a dis if connected, so you don't need the dis command.

Quote

Kernel log (wsl):
Code: [Select]
[ 124.514633] vhci_hcd: unlink->seqnum 411 [ 124.514634] vhci_hcd: the urb (seqnum 411) was already given back [ 125.473638] usb usb1-port1: Cannot enable. Maybe the USB cable is bad? [ 126.433851] usb usb1-port1: Cannot enable. Maybe the USB cable is bad? [ 127.393878] usb usb1-port1: Cannot enable. Maybe the USB cable is bad? [ 128.353938] usb usb1-port1: Cannot enable. Maybe the USB cable is bad? [ 128.354216] usb 1-1: USB disconnect, device number 2 [ 129.313896] usb usb1-port1: Cannot enable. Maybe the USB cable is bad? [ 130.273869] usb usb1-port1: Cannot enable. Maybe the USB cable is bad? [ 130.273886] usb usb1-port1: attempt power cycle

This suggests to me something is confused at a quite low USB level, assuming the cable isn't actually bad. Do you get the same errors on the pi? Are you using any of the same cables or hubs in both setups?

FWIW, I haven't tried chdkptp with wsl. That adds another layer for stuff to go wrong, but if that's the culprit it seems unlikely you'd get the same symptoms on the pi. I have used chdkptp from virtualbox VMs on windows and had it occasionally be flaky, but never really investigated, in recent versions it's been reliable enough to run the chdkptp camtests.

Logged

Don't forget what the H stands for.