Script sleep oddity - General Discussion and Assistance - CHDK Forum supplierdeeply
« previous next »
Pages: [1] 2 3 4 5 6   Go Down

Script sleep oddity

  • 57 Replies
  • 14700 Views
*

Offline reyalp

  • ******
  • 13502
Script sleep oddity
« on: 05 / February / 2012, 04:28:55 »
Advertisements
I always thought sleep() operated in 10ms increments, with a minimum of 10 ms.
Code: [Select]
con 17> =t=get_tick_count();sleep(0);return get_tick_count()-t
18:return:30
con 18> =t=get_tick_count();sleep(1);return get_tick_count()-t
19:return:30
con 19> =t=get_tick_count();sleep(10);return get_tick_count()-t
20:return:30
con 20> =t=get_tick_count();sleep(20);return get_tick_count()-t
21:return:40
con 21> =t=get_tick_count();sleep(30);return get_tick_count()-t
22:return:50
con 22> =t=get_tick_count();sleep(40);return get_tick_count()-t
23:return:60
The same behavior is seen with vxworks and dryos. I haven't looked at the code, need some sleep myself  :-[
Logged
Don't forget what the H stands for.
*

Offline philmoz

  • *****
  • 3356
    • Photos
Re: Script sleep oddity
« Reply #1 on: 05 / February / 2012, 05:08:29 »
Quote from: reyalp on 05 / February / 2012, 04:28:55
I always thought sleep() operated in 10ms increments, with a minimum of 10 ms.
Code: [Select]
con 17> =t=get_tick_count();sleep(0);return get_tick_count()-t
18:return:30
con 18> =t=get_tick_count();sleep(1);return get_tick_count()-t
19:return:30
con 19> =t=get_tick_count();sleep(10);return get_tick_count()-t
20:return:30
con 20> =t=get_tick_count();sleep(20);return get_tick_count()-t
21:return:40
con 21> =t=get_tick_count();sleep(30);return get_tick_count()-t
22:return:50
con 22> =t=get_tick_count();sleep(40);return get_tick_count()-t
23:return:60
The same behavior is seen with vxworks and dryos. I haven't looked at the code, need some sleep myself  :-[

The _SleepTask / msleep function exhibits the 10 msec min & increment.

This C code:
Code: [Select]
    int sc[10];
    for (i=0; i<10; i++)
    {
        int t = get_tick_count();
        msleep(1);
        sc[i] = get_tick_count()-t;
    }

creates an array where all the values are 10.

Changing the msleep value to 11 and all the array values change to 20.

The Lua sleep command doesn't call msleep - it checks the tick count in the AS_SLEEP action until the time requested has passed. So it will depend on how often action_stack_standard gets called - at that point I got lost in the code :)

Phil.

Edit:

Changing luaCB_sleep to:
Code: [Select]
    msleep(luaL_checknumber( L, 1 ));
    return 0;

give the expected 10 msec min / increment behaviour, so it's something in the way the script code is being called.
« Last Edit: 05 / February / 2012, 05:15:37 by philmoz »
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)
*

Offline reyalp

  • ******
  • 13502
Re: Script sleep oddity
« Reply #2 on: 05 / February / 2012, 15:13:07 »
Yes, I'm pretty sure this happens because the action stack items are processed once per kbd_task iteration, and if script run isn't at the top of the stack, then script is not executed in that iteration. So there is a minimum number of iterations to process a sequence on the stack, and each of those takes a minimum of 10ms because kbd_task itself has an msleep(10) built it.

I don't think sleeping kbd_task directly from script is a good idea, as it would change significantly from the original canon behavior (phsw_status wouldn't get updated during the sleep)

Long term, I'd like to make scripts run in their own OS task, which would solve this and a lot of other ugliness, but that would be a major undertaking.
Logged
Don't forget what the H stands for.
*

Offline waterwingz

  • ******
  • 12109
    • Waterwingz
Re: Script sleep oddity
« Reply #3 on: 05 / February / 2012, 15:23:21 »
Quote from: reyalp on 05 / February / 2012, 15:13:07
Long term, I'd like to make scripts run in their own OS task, which would solve this and a lot of other ugliness, but that would be a major undertaking.
Adding a task isn't hard.  What would make running scripts in their own task difficult then ?
Logged
Ported :   A1200    SD940   G10    Powershot N    G16
*

Offline reyalp

  • ******
  • 13502
Re: Script sleep oddity
« Reply #4 on: 05 / February / 2012, 15:27:16 »
Quote from: waterwingz on 05 / February / 2012, 15:23:21
Quote from: reyalp on 05 / February / 2012, 15:13:07
Long term, I'd like to make scripts run in their own OS task, which would solve this and a lot of other ugliness, but that would be a major undertaking.
Adding a task isn't hard.  What would make running scripts in their own task difficult then ?
The interaction with the rest of the OS and the rest of the firmware. It needs to communicate with kbd_task to send key presses, there are various globals in use etc. I think at a minimum we'd need to get the inter task synchronization functions from the OS sorted out.
Logged
Don't forget what the H stands for.
*

Offline reyalp

  • ******
  • 13502
Re: Script sleep oddity
« Reply #5 on: 05 / February / 2012, 17:54:08 »
It looks like the current code goes like this

1) script pushes AS_SLEEP
2) action stack sees AS_SLEEP, and initializes the value tick value that ends the sleep
3) action stack checks the delay value
Each item requires one kbd_task iteration.

I'm looking into making 1 do the initialization step. This will only solve half the problem though, because after the delay is processed, there will be another kbd_task iteration before it gets back to script. One workaround would be to make sleep( <=10) not push anything on the stack, since the script has already yielded and thus is waiting until the next kbd_task iteration anyway. I'm not sure that all the non-script stuff is guaranteed to wait a kbd_task cycle after it pushes the delay though, more investigation needed...

edit:
Of course, I can't initialize the end tick on push, because other stuff might be pushed after that. It needs to happen when the delay comes to the top of the stack. One way to deal with this would be to have a way to process the stack again right away, instead of waiting for the next kbd_task iteration to come around.
« Last Edit: 05 / February / 2012, 19:29:26 by reyalp »
Logged
Don't forget what the H stands for.
*

Offline philmoz

  • *****
  • 3356
    • Photos
Re: Script sleep oddity
« Reply #6 on: 13 / January / 2013, 02:32:08 »
Patch that I think fixes the sleep accuracy for scripts - posting here for review as it might have side effects I have not envisaged (e.g. may alter key press sleep delay in action stack).

With this patch Lua and uBasic sleep will usually be accurate the nearest 10msec interval (it rounds the requested value up or down as needed). Occasionally it will sleep for 10msec longer than requested - presumably due to the time (in)accuracy.

Note the min sleep duration for uBasic is 20msec - not sure why this is the case (Lua is 10msec).

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

Offline waterwingz

  • ******
  • 12109
    • Waterwingz
Re: Script sleep oddity
« Reply #7 on: 13 / January / 2013, 10:35:46 »
I like these patches but the first one does raise a concern.   Currently,  when a script is not working as expected, one of the typical suggestions is to insert a "short" sleep between some of the statements.  The assumption seems to be that this might give the Canon firmware a chance to "catch-up".   This is hardly scientific and frequently does not fix the problem IIRC.    However,  if it did "stabilize" things then the first patch might "destabilize" things. 

I guess the question might be whether its reasonable to expect a script programmer to understand that issuing a sleep less than 20 mSec will result in at least 20 mSec regardless of how small a value he specifies ?
Logged
Ported :   A1200    SD940   G10    Powershot N    G16
*

Offline reyalp

  • ******
  • 13502
Re: Script sleep oddity
« Reply #8 on: 13 / January / 2013, 16:40:58 »
I have mixed feelings about this. Would be unfortunate to break existing scripts that have some hand tuned sleep values. OTOH, the fact that sleep currently sleeps 20ms longer than the value you give is clearly a bug IMO.

I currently lean toward fixing it. All the alternatives seem ugly (a sleep2 function that  uses the correct value, or set_use_less_buggy_sleep(1))

I'll play with the patch a bit today. FWIW, my through for fixing this was to change action stack processing so action_stack_process could return a value that means "immediately process the next thing on the stack"

Quote
Quote the min sleep duration for uBasic is 20msec - not sure why this is the case (Lua is 10msec).
Would be good to understand why this happens.
Logged
Don't forget what the H stands for.
*

Offline philmoz

  • *****
  • 3356
    • Photos
Re: Script sleep oddity
« Reply #9 on: 13 / January / 2013, 17:06:28 »
Quote from: reyalp on 13 / January / 2013, 16:40:58
FWIW, my through for fixing this was to change action stack processing so action_stack_process could return a value that means "immediately process the next thing on the stack"

That was my initial thinking as well; but it seemed it might cause more side effects so I went with just fixing the current symptom.

With the new action_stack logic in the trunk version it would be simple to change the 'action' functions to return a status - i.e. 1 = continue processing actions, 0 = stop processing actions. The 'action_stack_process' routine could then loop until the function called returns 0 (although it might be wise to add an upper limit on the number of actions to process per iteration).

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)
Pages: [1] 2 3 4 5 6   Go Up
« previous next »
 

Related Topics