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
--- 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)
