Script sleep oddity

lapser

1093

Re: Script sleep oddity

« Reply #40 on: 23 / January / 2013, 17:10:33 »

Advertisements

Quote from: philmoz on 23 / January / 2013, 16:37:01

Are you sure it's not getting stuck in the inner 'repeat' loop waiting for the exposure count to change?
Try counting how many times it loops waiting for exp~=exp0, or record the before and after tick counts.

I'll try that, but the important thing is that without the print_screen(), there is no delay, and the shot rate is normal. With print_screen(), the sleep(10) calls aren't delayed. The shot rate slows, so there should be more delay in waiting for the shot. I'll test to see if there's a delay returning from the print statements, and how much delay there is at each point. That's a good idea.

Logged

EOS-M3_120f / SX50_100b / SX260_101a / G1X_100g / D20_100b
https://www.youtube.com/user/DrLapser/videos

lapser

1093

Re: Script sleep oddity

« Reply #41 on: 24 / January / 2013, 01:12:51 »

I did some more testing, including measuring the time waiting for the shot, and the time waiting for the print statement. When the camera slows down, the time increases in both, and the script starts to miss shots.

But I tried it without CHDK under the same conditions, and the camera also slowed down. It took a few more shots before it slowed down, but it slowed down quite a bit.

I found this tech note about continuous shooting:
http://support-asia.canon-asia.com/contents/ASIA/EN/8201444500.html

It says that the camera will slow down when it's zoomed in. Sure enough, when I zoomed all the way out, the delays didn't happen. I didn't know the zoom position had anything to do with the shot speed. It may be related to the time it takes to correct the lens distortion when creating the jpg. Or something!

So I need to do a little more research with zoom position, writing a log file, and shot rate in continuous mode.

But the results so far have shown that the sleep(10) function always returns in 10 msec, and occasionally 20 msec, even when the camera is busy. I'll sleep well tonight knowing that, at least.

Logged

EOS-M3_120f / SX50_100b / SX260_101a / G1X_100g / D20_100b
https://www.youtube.com/user/DrLapser/videos

philmoz

3449

Re: Script sleep oddity

« Reply #42 on: 24 / January / 2013, 02:56:40 »

Quote from: lapser on 23 / January / 2013, 17:10:33

Quote from: philmoz on 23 / January / 2013, 16:37:01
Are you sure it's not getting stuck in the inner 'repeat' loop waiting for the exposure count to change?
Try counting how many times it loops waiting for exp~=exp0, or record the before and after tick counts.
I'll try that, but the important thing is that without the print_screen(), there is no delay, and the shot rate is normal. With print_screen(), the sleep(10) calls aren't delayed. The shot rate slows, so there should be more delay in waiting for the shot. I'll test to see if there's a delay returning from the print statements, and how much delay there is at each point. That's a good idea.

Which camera did you use and what type/speed SD card?

I just tried your script on my G1X with a 32GB Lexar 400x card and it took over 200 shots without any slowdown (before I stopped the script).

Phil.

Logged

CHDK ports:
sx30is (1.00c, 1.00h, 1.00l, 1.00n & 1.00p)
g12 (1.00c, 1.00e, 1.00f & 1.00g)
sx130is (1.01d & 1.01f)
ixus310hs (1.00a & 1.01a)
sx40hs (1.00d, 1.00g & 1.00i)
g1x (1.00e, 1.00f & 1.00g)
g5x (1.00c, 1.01a, 1.01b)
g7x2 (1.01a, 1.01b, 1.10b)

lapser

1093

Re: Script sleep oddity

« Reply #43 on: 24 / January / 2013, 03:43:36 »

Quote from: philmoz on 24 / January / 2013, 02:56:40

I just tried your script on my G1X with a 32GB Lexar 400x card and it took over 200 shots without any slowdown (before I stopped the script).

I had the same result with the G1X all the way zoomed in. On the SX260 (with class 10 Sandisk 32GB), I don't see any slow down when zoomed in the same amount as the G1X. The slowdown happens when zoomed in all the way (20x optical only). So it's related to the zoom, and slightly increased by writing the log file on my sx260.

The sx260 seems to have a little faster shot rate than the G1X in continuous mode. That might have something to do with it too.

I had both cameras halt with Lua errors after about 2,000 shots at 1 shot per second (with my new shot interval delay) in continuous mode, and writing a lot of log data. The Lua error was a large decimal number that looked like it might have been a memory address. I didn't write it down, but it was different on each camera. I haven't triggered the error except when writing log files, and at 1 frame per second. So I think it has something to do with the camera writing too much data too fast. If I reduce the jpg file size, it takes more pictures before slowing down, with full 20x zoom.

I didn't write a log on my last time lapse, and both cameras lasted around 3,000 shots before I stopped them normally. Do you think there is a different issue with writing a log with a large number of pictures? Something about too many file handles?

Thanks for testing the script. I think your sleep changes are a success. As for the shoot() single repeat, I'm sure however you decide to do it will be fine. There's been another report of shoot() hanging:
http://chdk.setepontos.com/index.php?topic=9357.msg96214#msg96214

Here's the new script I've been using with more timings as you suggested:

Code: (lua) [Select]

--[[
@title Sleep Test
@param p log file #
@default p 1
--]]
function tsleep(delay)
  time0=get_tick_count()
  sleep(delay)
  return get_tick_count()-time0
end

--assume continuous mode
print_screen(p)
press("shoot_half")
repeat print(tsleep(10)) until get_shooting()
exp0=get_exp_count()
sleep(1000)
press("shoot_full_only")
tick2=get_tick_count()
repeat
  tick1=get_tick_count()
  prtime=tick1-tick2 -- time in print
  repeat
    stime=tsleep(10)
    exp=get_exp_count()
    if(stime>10)then print(stime) end
  until exp~=exp0
  tick2=get_tick_count()
  print(exp,"=exp Shot Time=",tick2-tick1,"Print Time=",prtime )
  exp0=exp
until false

Logged

EOS-M3_120f / SX50_100b / SX260_101a / G1X_100g / D20_100b
https://www.youtube.com/user/DrLapser/videos

philmoz

3449

Re: Script sleep oddity

« Reply #44 on: 24 / January / 2013, 04:03:27 »

Quote from: lapser on 24 / January / 2013, 03:43:36

The slowdown happens when zoomed in all the way (20x optical only). So it's related to the zoom, and slightly increased by writing the log file on my sx260.

No slowdown on the SX40 zoomed it to 35x. Possibly something specific to the SX260.

Phil.

Logged

CHDK ports:
sx30is (1.00c, 1.00h, 1.00l, 1.00n & 1.00p)
g12 (1.00c, 1.00e, 1.00f & 1.00g)
sx130is (1.01d & 1.01f)
ixus310hs (1.00a & 1.01a)
sx40hs (1.00d, 1.00g & 1.00i)
g1x (1.00e, 1.00f & 1.00g)
g5x (1.00c, 1.01a, 1.01b)
g7x2 (1.01a, 1.01b, 1.10b)

lapser

1093

Re: Script sleep oddity

« Reply #45 on: 24 / January / 2013, 11:54:00 »

Quote from: philmoz on 24 / January / 2013, 04:03:27

No slowdown on the SX40 zoomed it to 35x. Possibly something specific to the SX260.

Maybe so. This is what the tech note in the link above says (sx240&260):

The focus, brightness and white balance will be set with the first shot.
Nothing will appear on the screen while shooting.
There may be a delay after continuous shooting before you can shoot again. Additionally, depending on the memory card, there may be a delay before you can shoot again. Speed Class 6 or higher memory cards are recommended.
Depending on the shooting conditions, camera settings and the zoom position, the shooting speed may slow down.
When using Face ID, the location in the image where the name is recorded will be determined in the first shot, and will be recorded in the same place for further shots.
[ISO speed] is set to [AUTO] ().

You'd think the sx260 would be faster with the Digic 5. I guess zooming in that much with the smaller lens creates more distortion that takes longer to correct? But it seems like the most distortion is when zoomed out. Anyone have an explanation why shot rate slows when zoomed in on the sx260?

The last picture DOES show on the screen while shooting in continuous mode for the sx260 and g1x. I consider that a big advantage of using continuous mode (slowed down) for time lapse. Do you know if this is true on other cameras?

It also says ISO is set to AUTO. That doesn't appear to be true either. Viewing the pictures shows the ISO remains at the camera setting. Interestingly, on the sx260, setting ISO to 1600 or 3200 cuts the shot rate approximately in half, that is, slows it down. It sounds like ISO 1600 and 3200 must be done in software. Checking when the shot rate drops at higher ISO might be a good way to check what the maximum ISO of the camera really is. I suspect that it makes no sense to shoot higher than 800 on the sx260 unless you don't want to post process the pictures.

The shot rate on the G1X slows down starting at ISO 6400. ISO 5000 (1/3 f stop below) gives a normal rate. So ISO 5000 sounds like the highest useful G1X ISO setting. That's still pretty incredible compared to all the other CHDK cameras.

Logged

EOS-M3_120f / SX50_100b / SX260_101a / G1X_100g / D20_100b
https://www.youtube.com/user/DrLapser/videos

lapser

1093

shoot() fix . . . final offer

« Reply #46 on: 24 / January / 2013, 12:40:23 »

Code: [Select]

static int action_stack_AS_WAIT_SHOOT_DONE()
{
    if (shooting_in_progress()) return 0;
    action_pop_func();
    if(camera_info.state.state_shooting_progress == SHOOTING_PROGRESS_NONE)
    {
        action_pop_func(); //pop extra delay
        action_pop();      //off the stack
        action_push_func(action_stack_AS_SHOOT);
        script_console_add_line((long)"SHOOT FAILED"); //for debugging
    }
    return 1;
}

After considering all the ideas presented here, I think this is the best way to fix the shoot() problem. The other proposed solutions add unnecessary code and complexity to the shoot() function.

My basic design philosophy is to figure out what the real world problem is before writing any code. I spend a lot more time thinking of the best way to solve a problem than coding. I throw out 90% of the code I write (sometimes 100%) when I think up a better solution. This is a better solution.

The real world problem is that shoot() fails very rarely on certain cameras under certain conditions. The solution above fixed this problem on the only known camera where we could reproduce the problem reliably. It fixed it with one re-shoot every time, and never hung re-shooting over and over.

The possibility of a re-shoot infinite loop hang is a theoretical coding problem, not a real world problem. The solution above is a big improvement to the current shoot() function in that it corrects the problem in the tests we can do now. It is certainly no worse than the current shoot() function, which just hangs.

If the shoot() function ever enters a continuous re-shoot loop, it will be obvious what happened, unlike the silent hanging of the script that happens now. If this ever happens, then it becomes a real world problem and would be worth adding complexity and coding to correct.

In addition to the complexity in the C code required to implement the other proposed solutions, they add complexity to the script code to account for the possibility of an error return. Again, until shoot() actually hangs in a re-shoot loop, adding this complexity is not worthwhile.

As for the issue of coding clarity, the solution is to change the name of the function from AS_WAIT_SAVE to AS_WAIT_SHOOT_DONE. This describes what the function actually does, and makes it clear that it's tightly coupled to AS_SHOOT. The code is much simpler and easier to follow this way than the other proposed solutions.

I agree that the shoot() change should be separate from the sleep fix. Let's put this simple shoot() fix in the trunk right now on its own and see what happens. If you agree, I'll test it again with this precise code and submit a diff for inclusion in the trunk.

Another thing... This statement, the final delay, in AS_SHOOT isn't necessary. You don't need to wait for the file to be saved, which this delay doesn't do anyway. The next shoot() call waits for shooting_in_progress(), which should be sufficient. Am I wrong?

// XXX FIXME find out how to wait to jpeg save finished
action_push_delay(conf.script_shoot_delay*100);

« Last Edit: 24 / January / 2013, 12:50:28 by lapser »

Logged

EOS-M3_120f / SX50_100b / SX260_101a / G1X_100g / D20_100b
https://www.youtube.com/user/DrLapser/videos

philmoz

3449

Re: Script sleep oddity

« Reply #47 on: 24 / January / 2013, 14:10:54 »

Quote from: lapser on 24 / January / 2013, 11:54:00

Maybe so. This is what the tech note in the link above says (sx240&260):

The focus, brightness and white balance will be set with the first shot.
Nothing will appear on the screen while shooting.
There may be a delay after continuous shooting before you can shoot again. Additionally, depending on the memory card, there may be a delay before you can shoot again. Speed Class 6 or higher memory cards are recommended.
Depending on the shooting conditions, camera settings and the zoom position, the shooting speed may slow down.
When using Face ID, the location in the image where the name is recorded will be determined in the first shot, and will be recorded in the same place for further shots.
[ISO speed] is set to [AUTO] ().

That tech note is for HQ burst mode.

The user manual has the same information for both the SX260 and G1X.

Quote

You'd think the sx260 would be faster with the Digic 5. I guess zooming in that much with the smaller lens creates more distortion that takes longer to correct? But it seems like the most distortion is when zoomed out. Anyone have an explanation why shot rate slows when zoomed in on the sx260?

On all my cameras lens correction only appears to be applied at the wide end not when zoomed in.
The SX260 is a very small body for such a large zoom range so it's possible that the telephoto end requires correction.

You should be able to see if this is the case by saving DNG images at either end and comparing them to the camera JPEG.

It could also be a memory problem - how much free memory is there when the script is running?
There's a block of code near the end of core_spytask in an #ifdef DEBUG_PRINT_TO_LCD you can edit to display stuff all the time on screen.

Phil.

Logged

CHDK ports:
sx30is (1.00c, 1.00h, 1.00l, 1.00n & 1.00p)
g12 (1.00c, 1.00e, 1.00f & 1.00g)
sx130is (1.01d & 1.01f)
ixus310hs (1.00a & 1.01a)
sx40hs (1.00d, 1.00g & 1.00i)
g1x (1.00e, 1.00f & 1.00g)
g5x (1.00c, 1.01a, 1.01b)
g7x2 (1.01a, 1.01b, 1.10b)

philmoz

3449

Re: Script sleep oddity

« Reply #48 on: 24 / January / 2013, 16:39:07 »

Quote from: lapser on 24 / January / 2013, 12:40:23

Code: [Select]
static int action_stack_AS_WAIT_SHOOT_DONE() { if (shooting_in_progress()) return 0; action_pop_func(); if(camera_info.state.state_shooting_progress == SHOOTING_PROGRESS_NONE) { action_pop_func(); //pop extra delay action_pop(); //off the stack action_push_func(action_stack_AS_SHOOT); script_console_add_line((long)"SHOOT FAILED"); //for debugging } return 1; }After considering all the ideas presented here, I think this is the best way to fix the shoot() problem. The other proposed solutions add unnecessary code and complexity to the shoot() function.

We'll have to agree to disagree.

At the end of the day there are two problems with this solution that would prevent me from accepting it into SVN (and I suspect reyalp would agree).

1. It contains a potential infinite loop. Regardless of the likelihood of occurrence, the potential risk would not be accepted. A good model to work to is to always 'fail safely' - a single shoot failure may not indicate a problem, a second failure immediately afterwards probably means something is wrong. Blindly retrying over and over is not a good solution.

2. CHDK is about giving more control to users over their camera. Your solution take the control and power away from the script writer and assumes everyone will always want to do things this way. Returning an error to the script, and allowing the script to bypass the single retry if desired, puts the control back where it belongs.

Phil.

Logged

CHDK ports:
sx30is (1.00c, 1.00h, 1.00l, 1.00n & 1.00p)
g12 (1.00c, 1.00e, 1.00f & 1.00g)
sx130is (1.01d & 1.01f)
ixus310hs (1.00a & 1.01a)
sx40hs (1.00d, 1.00g & 1.00i)
g1x (1.00e, 1.00f & 1.00g)
g5x (1.00c, 1.01a, 1.01b)
g7x2 (1.01a, 1.01b, 1.10b)

lapser

1093

Re: Script sleep oddity

« Reply #49 on: 24 / January / 2013, 17:44:19 »

Quote from: philmoz on 24 / January / 2013, 16:39:07

We'll have to agree to disagree.

Your way will work, but I don't think it will ever return as a failure. If your way never returns a failure, then my way would be better. But the main thing is to get it done and in the trunk. If you feel the need to add all the extra code, do it. It won't hurt anything, but I don't think it will help.

Quote

1. It contains a potential infinite loop. Regardless of the likelihood of occurrence, the potential risk would not be accepted. A good model to work to is to always 'fail safely' - a single shoot failure may not indicate a problem, a second failure immediately afterwards probably means something is wrong. Blindly retrying over and over is not a good solution.

AS_WAIT_SHOOTING_IN_PROGRESS() is a potential infinite loop, but it has never happened, so we accept the risk. A second shoot failure has never happened, so at this point I think we can accept the risk. A single failure happens so rarely that people have been using shoot() successfully for years. And what is the "risk"? We discover it immediately and then switch to your code.

Quote

2. CHDK is about giving more control to users over their camera. Your solution take the control and power away from the script writer and assumes everyone will always want to do things this way. Returning an error to the script, and allowing the script to bypass the single retry if desired, puts the control back where it belongs.

I totally agree. I'm all for more control for users, and scripts. I'm just saying that adding code to test for a condition that never happens is wasteful. Show me that it's possible to hang my shoot code in a re-shoot loop and I'm with you 100% on your method. If we get a report that the camera is going chuckachuckachucka in shoot(), we'll chucka my code and use yours.

Logged

EOS-M3_120f / SX50_100b / SX260_101a / G1X_100g / D20_100b
https://www.youtube.com/user/DrLapser/videos