Author Topic: How accurate is the ML Intervalometer?  (Read 2142 times)

c_joerg

  • Freshman
  • **
  • Posts: 50
How accurate is the ML Intervalometer?
« on: February 13, 2018, 07:47:14 PM »
I made a time lapse with the ML Intervalometer (on 6D) and wonder about the time variance of 0.5s.
 The settings were:
 Interval = 25s
 TV = 20s
 ISO = 800

I evaluated the whole thing with the time stamp in the RAW data which has a resolution of 10ms.



6D

Levas

  • Contributor
  • Hero Member
  • *****
  • Posts: 1482
  • 6d - Nightly build user
Re: How accurate is the ML Intervalometer?
« Reply #1 on: February 13, 2018, 10:00:17 PM »
Never noticed the difference, but it could be there.

Just wondering, did you shoot normal canon CR2 raw files or Magic lantern MLV or DNG files with silent shutter options?
And how fast type of SD card did you use?

I do know that with silent picture mode, you need to have enough seconds between pictures to encode(If shooting DNG) and write the file to memory card.
But with a fast enough card, UHS-type I, 5 seconds should be enough.(25 seconds between pictures and 20 seconds exposure time.)

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12326
  • Holidays!
Re: How accurate is the ML Intervalometer?
« Reply #2 on: February 13, 2018, 10:38:26 PM »
The intervalometer wasn't written with timing accuracy in mind (in particular, there is a 300ms delay in its waiting loop), but I've recently touched some nearby code, so maybe it's not a bad idea to improve it a bit.

Can you test the timing accuracy with the following Lua script, using the latest lua_fix experimental build?

Code: [Select]
-- Simplest intervalometer in Lua
while true do
    camera.shoot()
    msleep(2500)
end

c_joerg

  • Freshman
  • **
  • Posts: 50
Re: How accurate is the ML Intervalometer?
« Reply #3 on: February 14, 2018, 08:53:49 AM »
Never noticed the difference, but it could be there.

On a 25s Interval you will not notice 0.5s but on a 4s Interval and moving objects you will notice on a time - lapse. 

Just wondering, did you shoot normal canon CR2 raw

Only Canon RAW, no silent shutter options.
But I’m not sure anymore if I used RAW + JPG or only RAW. Next time I will use only RAW.

And how fast type of SD card did you use?
I don’t think that’s the SD Card
I use a 32GB SanDisk Extreme SDHC UHS-I Card. On my EOS M3 I measured with this Card more than 50MB/s.


The intervalometer wasn't written with timing accuracy in mind (in particular, there is a 300ms delay in its waiting loop), but I've recently touched some nearby code, so maybe it's not a bad idea to improve it a bit.

The 300ms delay would explain ever think…

Can you test the timing accuracy with the following Lua script, using the latest lua_fix experimental build?

I'm still not very familiar with the 6D and ML. Yes I can test it but I want to exclude some other things first. So it can take a while.

If I make this measurement with my EOS M3 and CHDK at an interval of 4s, then I get pretty much an average of 4s. The deviation is maximum + -10ms which corresponds to the time resolution.
6D

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12326
  • Holidays!
Re: How accurate is the ML Intervalometer?
« Reply #4 on: February 14, 2018, 12:15:52 PM »
At 4s, the delay is reduced - can you test that scenario as well? (just to know whether it's just that delay, or there are other places to look into).

c_joerg

  • Freshman
  • **
  • Posts: 50
Re: How accurate is the ML Intervalometer?
« Reply #5 on: February 14, 2018, 05:55:46 PM »
At 4s, the delay is reduced
How big is the delay?
can you test that scenario as well? 
I made a short run with 38 Pictures. Variance is 0.2s.
Intervall = 4s
TV=0.1s, AV=1.8, ISO100
On the camera itself I use ‘Silent single shouting’ instead of ‘Single shouting’. Doe s this makes a different?

I notice on my last run with Interval=25s and TV=20s that a could not stop intervalometer with Menu, rotating the mode dial or Play. I have to switch the camera off.







6D

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12326
  • Holidays!
Re: How accurate is the ML Intervalometer?
« Reply #6 on: February 14, 2018, 07:42:48 PM »
Captured a diagnostic log while taking pictures. All tests outside LiveView, exposure time 1/60, image review set to Hold, 5D3 1.1.3.

Intervalometer 4s (delay 20ms in the loop - this part wasn't touched since 2012):
Code: [Select]
014.090598> ShootCaptu:ff147854:00:00: scsReleaseStart
018.103665> ShootCaptu:ff147854:00:00: scsReleaseStart
022.205001> ShootCaptu:ff147854:00:00: scsReleaseStart
026.136541> ShootCaptu:ff147854:00:00: scsReleaseStart
030.243190> ShootCaptu:ff147854:00:00: scsReleaseStart
034.158872> ShootCaptu:ff147854:00:00: scsReleaseStart
038.083843> ShootCaptu:ff147854:00:00: scsReleaseStart
042.197127> ShootCaptu:ff147854:00:00: scsReleaseStart
046.094324> ShootCaptu:ff147854:00:00: scsReleaseStart
050.193793> ShootCaptu:ff147854:00:00: scsReleaseStart
054.113567> ShootCaptu:ff147854:00:00: scsReleaseStart
058.224719> ShootCaptu:ff147854:00:00: scsReleaseStart
062.124466> ShootCaptu:ff147854:00:00: scsReleaseStart
066.227926> ShootCaptu:ff147854:00:00: scsReleaseStart
070.124189> ShootCaptu:ff147854:00:00: scsReleaseStart
074.239629> ShootCaptu:ff147854:00:00: scsReleaseStart
078.133923> ShootCaptu:ff147854:00:00: scsReleaseStart
082.235476> ShootCaptu:ff147854:00:00: scsReleaseStart
086.152324> ShootCaptu:ff147854:00:00: scsReleaseStart
090.248260> ShootCaptu:ff147854:00:00: scsReleaseStart

Code: [Select]
    for (int i = 0; i < 10; i++)
    {
        call("Release");
        msleep(4000);
    }
Code: [Select]
017.850043> ShootCaptu:ff147854:00:00: scsReleaseStart
022.101754> ShootCaptu:ff147854:00:00: scsReleaseStart
026.262829> ShootCaptu:ff147854:00:00: scsReleaseStart
030.431187> ShootCaptu:ff147854:00:00: scsReleaseStart
034.607526> ShootCaptu:ff147854:00:00: scsReleaseStart
038.785915> ShootCaptu:ff147854:00:00: scsReleaseStart
042.969365> ShootCaptu:ff147854:00:00: scsReleaseStart
047.421037> ShootCaptu:ff147854:00:00: scsReleaseStart
051.591992> ShootCaptu:ff147854:00:00: scsReleaseStart
055.768427> ShootCaptu:ff147854:00:00: scsReleaseStart

Code: [Select]
    for (int i = 0; i < 10; i++)
    {
        lens_take_picture(0, AF_DONT_CHANGE);
        msleep(4000);
    }
Code: [Select]
069.961026> ShootCaptu:ff147854:00:00: scsReleaseStart
074.131963> ShootCaptu:ff147854:00:00: scsReleaseStart
078.309513> ShootCaptu:ff147854:00:00: scsReleaseStart
082.766403> ShootCaptu:ff147854:00:00: scsReleaseStart
086.931094> ShootCaptu:ff147854:00:00: scsReleaseStart
091.112603> ShootCaptu:ff147854:00:00: scsReleaseStart
095.289315> ShootCaptu:ff147854:00:00: scsReleaseStart
099.471819> ShootCaptu:ff147854:00:00: scsReleaseStart
103.921049> ShootCaptu:ff147854:00:00: scsReleaseStart
108.094151> ShootCaptu:ff147854:00:00: scsReleaseStart

Code: [Select]
static void * sem = 0;

static void tick()
{
    delayed_call(4000, tick, 0);
    give_semaphore(sem);
}

static void run_test()
{
    sem = create_named_semaphore(0,0);

    delayed_call(4000, tick, 0);
    for (int i = 0; i < 10; i++)
    {
        take_semaphore(sem, 0);
        lens_take_picture(0, AF_DONT_CHANGE);
    }
}

Code: [Select]
122.291142> ShootCaptu:ff147854:00:00: scsReleaseStart
126.286008> ShootCaptu:ff147854:00:00: scsReleaseStart
130.281867> ShootCaptu:ff147854:00:00: scsReleaseStart
134.311895> ShootCaptu:ff147854:00:00: scsReleaseStart
138.301815> ShootCaptu:ff147854:00:00: scsReleaseStart
142.307970> ShootCaptu:ff147854:00:00: scsReleaseStart
146.353380> ShootCaptu:ff147854:00:00: scsReleaseStart
150.332302> ShootCaptu:ff147854:00:00: scsReleaseStart
154.365366> ShootCaptu:ff147854:00:00: scsReleaseStart
158.352378> ShootCaptu:ff147854:00:00: scsReleaseStart

Feel free to create graphs from these numbers.

Last method seems a little more promising (variations twice as small, compared to ML intervalometer), but no chance to get as good as CHDK. Worth the trouble?



edit: looked some more into it:
Code: [Select]
static void * sem = 0;

static void tick()
{
    delayed_call(4000, tick, 0);
    DryosDebugMsg(0x93,0,"timer tick");
    give_semaphore(sem);
}

static void run_test()
{
    sem = create_named_semaphore(0,0);

    delayed_call(4000, tick, 0);
    for (int i = 0; i < 10; i++)
    {
        take_semaphore(sem, 0);
        DryosDebugMsg(0x93,0,"sem tick");
        call("Release");
    }
}
Code: [Select]
013.254581> **INT-0Ah*:000756a8:00:00: timer tick
013.255118>   run_test:00075fbc:00:00: sem tick
013.340152> ShootCaptu:ff14b8ac:00:00: scsReleaseOn
013.340194> ShootCaptu:ff147854:00:00: scsReleaseStart
013.367919> ShootCaptu:ff14827c:00:00: scsReleaseData
013.372125> ShootCaptu:ff148aa8:00:00: NormalCapture(scsReleaseData)
013.575617> ShootCaptu:ff14a70c:00:00: scsReleaseEnd
013.575650> ShootCaptu:ff14b8ec:00:00: scsReleaseOff
017.264571> **INT-0Ah*:000756a8:00:00: timer tick
017.265032>   run_test:00075fbc:00:00: sem tick
017.333651> ShootCaptu:ff14b8ac:00:00: scsReleaseOn
017.333719> ShootCaptu:ff147854:00:00: scsReleaseStart
017.361277> ShootCaptu:ff14827c:00:00: scsReleaseData
017.365522> ShootCaptu:ff148aa8:00:00: NormalCapture(scsReleaseData)
017.569092> ShootCaptu:ff14a70c:00:00: scsReleaseEnd
017.569128> ShootCaptu:ff14b8ec:00:00: scsReleaseOff
021.274574> **INT-0Ah*:000756a8:00:00: timer tick
021.275035>   run_test:00075fbc:00:00: sem tick
021.332103> ShootCaptu:ff14b8ac:00:00: scsReleaseOn
021.332151> ShootCaptu:ff147854:00:00: scsReleaseStart
021.359644> ShootCaptu:ff14827c:00:00: scsReleaseData
021.363841> ShootCaptu:ff148aa8:00:00: NormalCapture(scsReleaseData)
021.567529> ShootCaptu:ff14a70c:00:00: scsReleaseEnd
021.567563> ShootCaptu:ff14b8ec:00:00: scsReleaseOff
025.284573> **INT-0Ah*:000756a8:00:00: timer tick
025.285034>   run_test:00075fbc:00:00: sem tick
025.361692> ShootCaptu:ff14b8ac:00:00: scsReleaseOn
025.361761> ShootCaptu:ff147854:00:00: scsReleaseStart
025.389261> ShootCaptu:ff14827c:00:00: scsReleaseData
025.393495> ShootCaptu:ff148aa8:00:00: NormalCapture(scsReleaseData)
025.597195> ShootCaptu:ff14a70c:00:00: scsReleaseEnd
025.597230> ShootCaptu:ff14b8ec:00:00: scsReleaseOff
029.294573> **INT-0Ah*:000756a8:00:00: timer tick
029.295094>   run_test:00075fbc:00:00: sem tick
029.352165> ShootCaptu:ff14b8ac:00:00: scsReleaseOn
029.352235> ShootCaptu:ff147854:00:00: scsReleaseStart
029.379737> ShootCaptu:ff14827c:00:00: scsReleaseData
029.383951> ShootCaptu:ff148aa8:00:00: NormalCapture(scsReleaseData)
029.587726> ShootCaptu:ff14a70c:00:00: scsReleaseEnd
029.587762> ShootCaptu:ff14b8ec:00:00: scsReleaseOff
033.304572> **INT-0Ah*:000756a8:00:00: timer tick
033.305031>   run_test:00075fbc:00:00: sem tick
033.355983> ShootCaptu:ff14b8ac:00:00: scsReleaseOn
033.356029> ShootCaptu:ff147854:00:00: scsReleaseStart
033.383521> ShootCaptu:ff14827c:00:00: scsReleaseData
033.387830> ShootCaptu:ff148aa8:00:00: NormalCapture(scsReleaseData)
033.591475> ShootCaptu:ff14a70c:00:00: scsReleaseEnd
033.591508> ShootCaptu:ff14b8ec:00:00: scsReleaseOff
037.314575> **INT-0Ah*:000756a8:00:00: timer tick
037.315039>   run_test:00075fbc:00:00: sem tick
037.397913> ShootCaptu:ff14b8ac:00:00: scsReleaseOn
037.397960> ShootCaptu:ff147854:00:00: scsReleaseStart
037.425557> ShootCaptu:ff14827c:00:00: scsReleaseData
037.429807> ShootCaptu:ff148aa8:00:00: NormalCapture(scsReleaseData)
037.659595> ShootCaptu:ff14b8ec:00:00: scsReleaseOff
041.324574> **INT-0Ah*:000756a8:00:00: timer tick
041.325036>   run_test:00075fbc:00:00: sem tick
041.415961> ShootCaptu:ff14b8ac:00:00: scsReleaseOn
041.416007> ShootCaptu:ff147854:00:00: scsReleaseStart
041.443567> ShootCaptu:ff14827c:00:00: scsReleaseData
041.447838> ShootCaptu:ff148aa8:00:00: NormalCapture(scsReleaseData)
041.667834> ShootCaptu:ff14a70c:00:00: scsReleaseEnd
041.667866> ShootCaptu:ff14b8ec:00:00: scsReleaseOff
045.334578> **INT-0Ah*:000756a8:00:00: timer tick
045.335039>   run_test:00075fbc:00:00: sem tick
045.409788> ShootCaptu:ff14b8ac:00:00: scsReleaseOn
045.409865> ShootCaptu:ff147854:00:00: scsReleaseStart
045.437346> ShootCaptu:ff14827c:00:00: scsReleaseData
045.441577> ShootCaptu:ff148aa8:00:00: NormalCapture(scsReleaseData)
045.645191> ShootCaptu:ff14a70c:00:00: scsReleaseEnd
045.645224> ShootCaptu:ff14b8ec:00:00: scsReleaseOff
049.344577> **INT-0Ah*:000756a8:00:00: timer tick
049.345104>   run_test:00075fbc:00:00: sem tick
049.401676> ShootCaptu:ff14b8ac:00:00: scsReleaseOn
049.401722> ShootCaptu:ff147854:00:00: scsReleaseStart
049.429216> ShootCaptu:ff14827c:00:00: scsReleaseData
049.433428> ShootCaptu:ff148aa8:00:00: NormalCapture(scsReleaseData)
049.637111> ShootCaptu:ff14a70c:00:00: scsReleaseEnd
049.637147> ShootCaptu:ff14b8ec:00:00: scsReleaseOff
053.354577> **INT-0Ah*:000756a8:00:00: timer tick
057.364585> **INT-0Ah*:000756a8:00:00: timer tick

In other words, even if we are able to call Canon's image capture function with very accurate timing (50 microseconds stdev), you can still notice variations of about 50 ms when the image capture starts (with an average delay of about 70ms).

Why it's that? Canon knows :D



If you are wondering what happens between our call("Release") and the actual image capture start:
Code: [Select]
011.604602  **INT-0Ah*:000756a8:93:00: timer tick
011.605164    run_test:00075fbc:93:00: sem tick
011.605215    run_test:ff1bf390:90:16: Release
011.605422     PropMgr:ff2714c8:33:03: PROP_REMOTE_RELEASE[0]
011.605471     PropMgr:ff104798:33:01: SendPipeEvent [0][0][48]
011.605641      PtpDps:ff1044e0:33:01: Dispatch : Cur = 0, Event = 48, Param = 0x0
011.605721      PtpDps:ff271b84:33:03: ptpPropButtonSW1:1,0
011.605945     PropMgr:000b1130:00:00: *** mpu_send(08 06 04 16 01 00 00), from ff122df8
011.606557  **INT-36h*:000b1198:00:00: *** mpu_recv(06 05 04 16 00 00), from ff2e4494
011.607045  **INT-36h*:000b1198:00:00: *** mpu_recv(06 05 06 26 01 00), from ff2e4494
011.607170    MainCtrl:ff0cea60:9c:01: ID:26(8)
011.607222    MainCtrl:ff0cc1cc:89:03: bindReceiveSwitch (38, 1)
011.607241    MainCtrl:ff0cc718:89:03: COM_SW_SOMETHING
011.607258    MainCtrl:ff0decb0:85:03: GUI_Control:82 0x0
011.607357     PropMgr:ff270ea0:33:01: PropCBR camctrl:0x80020015,0x0
011.607383     PropMgr:ff2712f4:33:03: PROP_REMOTE_SW1[0]
011.607525  GuiMainTas:ff0df028:84:01: GUI_CONTROL:82
011.607585  GuiMainTas:ff1a6104:84:03: GUICMD_PRESS_BUTTON_SOMETHING(0x0)
011.607673  GuiMainTas:ff1a7100:84:01: gui control end
011.607697  GuiMainTas:ff1a7124:84:01: 0msec = 12640 - 12640
011.607720  GuiMainTas:ff1a7140:84:01: 126msec = 73204 - 73330
011.608072      PtpDps:ff271c28:33:03: ptpPropButtonSW2:1
011.611562  **INT-36h*:000b1198:00:00: *** mpu_recv(06 04 05 00 00), from ff2e4494
011.611800    EventMgr:ff2041bc:8d:03: emDeliverMulticastEvent : SW1ON
011.611930    MainCtrl:ff0cea60:9c:01: ID:0(9)
011.611948    MainCtrl:ff146030:9c:03: cam event metering start
011.611968    MainCtrl:ff0e533c:2c:03: MVP_CancelMoviePlay
011.611995    MainCtrl:ff0decb0:85:03: GUI_Control:78 0x0
011.612029    MainCtrl:ff146284:89:05: EVENTID_METERING_START
011.621605     PropMgr:000b1130:00:00: *** mpu_send(08 06 04 17 01 03 00), from ff122df8
011.622018  GuiMainTas:ff0df028:84:01: GUI_CONTROL:78
011.622126  GuiMainTas:ff1a7100:84:01: gui control end
011.622152  GuiMainTas:ff1a7124:84:01: 0msec = 12650 - 12650
011.622175  GuiMainTas:ff1a7140:84:01: 88msec = 87697 - 87785
011.622419     CtrlSrv:ff357560:83:03: IDLEHandler PRESS_SW1_BUTTON
011.622670    Fstorage:ff1ae018:9e:03: fssSW1On
011.623214  **INT-36h*:000b1198:00:00: *** mpu_recv(06 05 06 26 01 00), from ff2e4494
011.623295    MainCtrl:ff0cea60:9c:01: ID:26(10)
011.623347    MainCtrl:ff0cc1cc:89:03: bindReceiveSwitch (38, 1)
011.623364    MainCtrl:ff0cc718:89:03: COM_SW_SOMETHING
011.623381    MainCtrl:ff0decb0:85:03: GUI_Control:82 0x0
011.623493  GuiMainTas:ff0df028:84:01: GUI_CONTROL:82
011.623552  GuiMainTas:ff1a6104:84:03: GUICMD_PRESS_BUTTON_SOMETHING(0x0)
011.623639  GuiMainTas:ff1a7100:84:01: gui control end
011.623663  GuiMainTas:ff1a7124:84:01: 0msec = 12650 - 12650
011.623684  GuiMainTas:ff1a7140:84:01: 122msec = 89174 - 89296
011.644880     CtrlSrv:ff4b6d98:83:01: DlgShootOlc.c LOCAL_DIALOG_REFRESH
011.659045  **INT-36h*:000b1198:00:00: *** mpu_recv(06 05 03 54 00 00), from ff2e4494
011.659396  **INT-36h*:000b1198:00:00: *** mpu_recv(06 04 05 01 00), from ff2e4494
011.659719  **INT-36h*:000b1198:00:00: *** mpu_recv(06 04 05 0e 00), from ff2e4494
011.660060  **INT-36h*:000b1198:00:00: *** mpu_recv(06 05 03 12 00 00), from ff2e4494
011.660373  **INT-36h*:000b1198:00:00: *** mpu_recv(06 05 04 17 00 00), from ff2e4494
011.661918    EventMgr:ff204554:8d:03: emDeliverMulticastEvent (ID = 14)
011.662462  **INT-36h*:000b1198:00:00: *** mpu_recv(10 0f 0a 08 41 00 04 00 01 02 dd 01 01 fb 00 00), from ff2e4494
011.662588    EventMgr:ff2041dc:8d:03: emDeliverMulticastEvent : SW2ON
011.662825  ShootCaptu:ff14b8ac:93:03: scsReleaseOn
011.662901  ShootCaptu:ff147854:93:03: scsReleaseStart

dmilligan

  • Developer
  • Hero Member
  • *****
  • Posts: 3218
  • 60Da / 1100D / EOSM
Re: How accurate is the ML Intervalometer?
« Reply #7 on: February 15, 2018, 03:48:37 AM »
Could be better in LV perhaps since mirror is already up? (Too hard to get a DM log from LV with all the extra noise?) Also perhaps FRSP is even more consistent. And of course grabbing every Nth LV frame would be microsecond acurrate.

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12326
  • Holidays!
Re: How accurate is the ML Intervalometer?
« Reply #8 on: February 15, 2018, 11:08:34 AM »
Yes, there are options for more accurate timing. In particular, any kind of timelapse with FPS override should be quite good (I can check the timing on this one too; I expect it to be limited just by interrupt processing overhead - minor jitter, but no bias).

From a log I've already captured (1080p25):
Code: [Select]
0.005.636         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.045.633         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.085.645         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.125.637         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.165.656         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.205.642         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.245.646         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.285.651         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.325.645         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.365.642         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.405.630         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.445.634         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.485.635         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.525.647         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.565.635         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.605.638         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.645.686         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.685.631         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.725.639         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt

Standard deviation of time deltas: 20 microseconds (1080p25, with large logging overhead, as I was logging everything I could, including all MMIO events and interrupts).

Logging things in LiveView can be done, but one needs to select a small subset of messages for scenarios than take more than 0.5 seconds or so (as it's extremely verbose). I did the same for the above experiment, as otherwise the log buffer would have been full after 2 pictures or so. This filtering is done in my_DebugMsg - just return early if the message doesn't look interesting (checked by message class, by first letter, by context - what task printed that message etc).

With that trick (logging only regular messages starting with 'e', all the "extra" loggers commented out), I get only this in the log:
Code: [Select]
0.000.000     PropMgr:ff0f53b8:8d:02: emAutoPowerOffRequestChangeCBR (1)
0.000.114    EventMgr:ff204988:8d:03: emAutoPowerOff : PERMIT (1)
0.000.340         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
0.013.019  **INT-6Ah*:ff184d30:9b:01: eppDeliverInterruptCBR[0]
0.013.090  **INT-6Ah*:ff18360c:9b:01: eppVramInterruptCBR[1]
0.013.169         Evf:ff16b308:a9:01: evfVdInterrupt[415][413]
0.039.330         Evf:ff16b6c8:a9:01: evfSetParamInterrupt
0.040.320         Evf:ff16b8e8:a9:01: evfReadOutDoneInterrupt
...

Timestamps from 30 seconds of LiveView (evfReadOutDoneInterrupt, 1080p25, newline after 25 frames):
Code: [Select]
0.000340 0.040320 0.080321 0.120322 0.160329 0.200320 0.240324 0.280318 0.320334 0.360336 0.400335 0.440318 0.480320 0.520320 0.560319 0.600315 0.640326 0.680334 0.720317 0.760322 0.800322 0.840328 0.880334 0.920331 0.960322
1.000321 1.040361 1.080320 1.120325 1.160323 1.200330 1.240320 1.280321 1.320319 1.360326 1.400331 1.440328 1.480320 1.520322 1.560318 1.600317 1.640332 1.680320 1.720315 1.760323 1.800320 1.840322 1.880327 1.920329 1.960334
2.000322 2.040317 2.080320 2.120317 2.160328 2.200325 2.240327 2.280319 2.320319 2.360317 2.400319 2.440318 2.480370 2.520330 2.560332 2.600316 2.640317 2.680318 2.720343 2.760318 2.800321 2.840321 2.880318 2.920317 2.960329
3.000325 3.040328 3.080319 3.120317 3.160317 3.200362 3.240318 3.280316 3.320325 3.360317 3.400318 3.440317 3.480328 3.520331 3.560331 3.600315 3.640322 3.680345 3.720319 3.760322 3.800322 3.840318 3.880318 3.920315 3.960317
4.000328 4.040328 4.080321 4.120319 4.160364 4.200321 4.240321 4.280322 4.320324 4.360323 4.400317 4.440316 4.480311 4.520323 4.560330 4.600317 4.640342 4.680323 4.720324 4.760321 4.800317 4.840321 4.880320 4.920323 4.960322
5.000330 5.040331 5.080327 5.120340 5.160321 5.200319 5.240324 5.280321 5.320325 5.360322 5.400319 5.440318 5.480329 5.520331 5.560334 5.600321 5.640322 5.680321 5.720334 5.760328 5.800318 5.840314 5.880322 5.920319 5.960325
6.000329 6.040332 6.080326 6.120318 6.160322 6.200321 6.240316 6.280316 6.320313 6.360321 6.400321 6.440321 6.480333 6.520327 6.560342 6.600313 6.640320 6.680336 6.720315 6.760324 6.800317 6.840323 6.880322 6.920319 6.960335
7.000331 7.040339 7.080320 7.120320 7.160323 7.200324 7.240320 7.280321 7.320321 7.360321 7.400312 7.440322 7.480331 7.520337 7.560326 7.600316 7.640342 7.680319 7.720321 7.760317 7.800316 7.840321 7.880324 7.920321 7.960327
8.000374 8.040332 8.080321 8.120321 8.160320 8.200319 8.240319 8.280315 8.320318 8.360317 8.400315 8.440320 8.480336 8.520335 8.560321 8.600320 8.640321 8.680323 8.720338 8.760321 8.800319 8.840319 8.880321 8.920320 8.960336
9.000334 9.040324 9.080322 9.120321 9.160324 9.200333 9.240313 9.280321 9.320316 9.360317 9.400322 9.440333 9.480331 9.520330 9.560321 9.600317 9.640320 9.680333 9.720319 9.760313 9.800315 9.840321 9.880330 9.920321 9.960329
10.000331 10.040321 10.080318 10.120334 10.160317 10.200334 10.240335 10.280319 10.320334 10.360317 10.400347 10.440336 10.480336 10.520331 10.560326 10.600332 10.640334 10.680325 10.720321 10.760329 10.800318 10.840316 10.880340 10.920327 10.960315
11.000320 11.040328 11.080325 11.120315 11.160317 11.200327 11.240318 11.280320 11.320317 11.360323 11.400318 11.440313 11.480324 11.520321 11.560330 11.600323 11.640318 11.680319 11.720320 11.760335 11.800335 11.840323 11.880322 11.920321 11.960318
12.000310 12.040326 12.080326 12.120316 12.160318 12.200325 12.240318 12.280326 12.320318 12.360312 12.400315 12.440314 12.480312 12.520314 12.560311 12.600308 12.640315 12.680324 12.720318 12.760310 12.800315 12.840315 12.880311 12.920313 12.960310
13.000328 13.040313 13.080317 13.120312 13.160309 13.200330 13.240311 13.280310 13.320314 13.360311 13.400315 13.440312 13.480311 13.520308 13.560313 13.600310 13.640311 13.680312 13.720328 13.760328 13.800307 13.840311 13.880312 13.920312 13.960315
14.000312 14.040310 14.080351 14.120314 14.160322 14.200312 14.240314 14.280318 14.320312 14.360311 14.400312 14.440309 14.480308 14.520310 14.560305 14.600309 14.640312 14.680314 14.720306 14.760313 14.800311 14.840312 14.880312 14.920307 14.960319
15.000310 15.040312 15.080306 15.120310 15.160309 15.200311 15.240311 15.280307 15.320312 15.360312 15.400315 15.440308 15.480318 15.520324 15.560310 15.600313 15.640314 15.680308 15.720313 15.760308 15.800310 15.840317 15.880308 15.920309 15.960310
16.000313 16.040312 16.080306 16.120316 16.160316 16.200312 16.240311 16.280312 16.320305 16.360310 16.400312 16.440304 16.480308 16.520310 16.560311 16.600310 16.640308 16.680309 16.720316 16.760317 16.800312 16.840313 16.880312 16.920312 16.960310
17.000311 17.040308 17.080304 17.120315 17.160312 17.200314 17.240321 17.280313 17.320312 17.360312 17.400310 17.440306 17.480310 17.520315 17.560313 17.600305 17.640310 17.680306 17.720310 17.760315 17.800308 17.840311 17.880311 17.920314 17.960307
18.000310 18.040317 18.080310 18.120311 18.160310 18.200312 18.240310 18.280313 18.320310 18.360307 18.400312 18.440312 18.480308 18.520309 18.560312 18.600310 18.640313 18.680318 18.720309 18.760310 18.800316 18.840311 18.880309 18.920311 18.960313
19.000313 19.040313 19.080316 19.120308 19.160306 19.200315 19.240315 19.280305 19.320312 19.360313 19.400307 19.440314 19.480313 19.520313 19.560310 19.600306 19.640309 19.680312 19.720314 19.760306 19.800307 19.840313 19.880312 19.920307 19.960316
20.000349 20.040310 20.080312 20.120315 20.160316 20.200314 20.240308 20.280310 20.320309 20.360306 20.400317 20.440314 20.480312 20.520315 20.560310 20.600309 20.640314 20.680310 20.720318 20.760311 20.800315 20.840313 20.880308 20.920309 20.960311
21.000309 21.040310 21.080312 21.120308 21.160313 21.200309 21.240308 21.280324 21.320308 21.360312 21.400314 21.440310 21.480313 21.520306 21.560309 21.600309 21.640317 21.680309 21.720318 21.760316 21.800309 21.840313 21.880314 21.920311 21.960313
22.000309 22.040316 22.080315 22.120311 22.160318 22.200307 22.240311 22.280309 22.320315 22.360313 22.400313 22.440309 22.480308 22.520310 22.560313 22.600317 22.640314 22.680316 22.720314 22.760311 22.800310 22.840309 22.880312 22.920306 22.960314
23.000312 23.040311 23.080309 23.120329 23.160310 23.200314 23.240309 23.280308 23.320346 23.360317 23.400316 23.440312 23.480310 23.520310 23.560316 23.600315 23.640313 23.680312 23.720311 23.760313 23.800305 23.840307 23.880316 23.920313 23.960316
24.000316 24.040304 24.080311 24.120317 24.160308 24.200317 24.240311 24.280314 24.320316 24.360312 24.400314 24.440315 24.480313 24.520306 24.560312 24.600312 24.640311 24.680312 24.720313 24.760311 24.800313 24.840312 24.880306 24.920309 24.960313
25.000313 25.040309 25.080311 25.120306 25.160316 25.200309 25.240310 25.280311 25.320316 25.360311 25.400311 25.440313 25.480316 25.520312 25.560311 25.600317 25.640312 25.680321 25.720311 25.760307 25.800314 25.840306 25.880314 25.920308 25.960313
26.000323 26.040305 26.080315 26.120311 26.160309 26.200307 26.240310 26.280320 26.320303 26.360315 26.400315 26.440307 26.480310 26.520313 26.560309 26.600305 26.640350 26.680312 26.720315 26.760314 26.800306 26.840314 26.880312 26.920312 26.960313
27.000307 27.040320 27.080311 27.120309 27.160316 27.200314 27.240311 27.280318 27.320303 27.360310 27.400317 27.440306 27.480305 27.520309 27.560311 27.600311 27.640311 27.680314 27.720310 27.760307 27.800309 27.840313 27.880314 27.920316 27.960314
28.000312 28.040314 28.080318 28.120317 28.160314 28.200309 28.240314 28.280311 28.320318 28.360310 28.400306 28.440307 28.480315 28.520309 28.560314 28.600311 28.640310 28.680316 28.720314 28.760316 28.800303 28.840311 28.880313 28.920310 28.960312
29.000311 29.040308 29.080307 29.120312 29.160321 29.200312 29.240313 29.280310 29.320318 29.360304 29.400316 29.440312 29.480308 29.520311 29.560306 29.600315 29.640315 29.680313 29.720322 29.760308 29.800312 29.840305 29.880319 29.920329 29.960355

Have fun crunching these numbers ;)

FRSP + intervalometer is also more consistent, given that it stays outside LiveView during the entire timelapse, with the main screen turned off after the image review times out, to save power (ironically, that's something a lot of folks complained about). Bonus - you are limited to long exposures, so a bit of motion blur is guaranteed - something you actually want during a timelapse!

Full-res MLV saved on CF, intervalometer 4 seconds (first frame likely outlier from creating the MLV headers, only done once every 4GB):
Code: [Select]
17.326.699  ShootCaptu:ff147854:93:03: scsReleaseStart
21.216.037  ShootCaptu:ff147854:93:03: scsReleaseStart
25.216.042  ShootCaptu:ff147854:93:03: scsReleaseStart
29.216.039  ShootCaptu:ff147854:93:03: scsReleaseStart
33.216.048  ShootCaptu:ff147854:93:03: scsReleaseStart
37.216.039  ShootCaptu:ff147854:93:03: scsReleaseStart
41.216.041  ShootCaptu:ff147854:93:03: scsReleaseStart
45.206.032  ShootCaptu:ff147854:93:03: scsReleaseStart
49.216.055  ShootCaptu:ff147854:93:03: scsReleaseStart
53.216.041  ShootCaptu:ff147854:93:03: scsReleaseStart

(card full, sorry)

c_joerg

  • Freshman
  • **
  • Posts: 50
Re: How accurate is the ML Intervalometer?
« Reply #9 on: February 15, 2018, 12:46:04 PM »
I did not really understand everything so sorry maybe my stupid questions…


Feel free to create graphs from these numbers.
Done..  :)





Last method seems a little more promising (variations twice as small, compared to ML intervalometer),

Definitely…

Worth the trouble?

From lapser side definitely…

If you made a time-lapse from a moving Cruise ship, you will see variation in time from around 5%. On moving clouds you will not see it. I would prefer less than 1% variation in time to reduce other side effects…


But why you use delay?
My experience on CHDK where, that was not very accurate (removes Overhead).
I did it in LUA like this
Code: [Select]
t1=os.time()+interval
repeat
    if os.difftime(os.time(),t1)>=0 then
       shoot()
        t1=os.time()+interval

       …


but no chance to get as good as CHDK.

I am really spoiled by CHDK, especially from this script
http://chdk.wikia.com/wiki/Lua/Scripts:_Raw_Meter_Intervalometer

But I have to say, I always run my cams with CHDK in Canon continuous mode (with delays inserted to maintain the desired interval) or the cam stays all the time in half press und does only a full shoot. That could make a big difference


In other words, even if we are able to call Canon's image capture function with very accurate timing (50 microseconds stdev), you can still notice variations of about 50 ms when the image capture starts (with an average delay of about 70ms).

That would be fine…
I never checked an external timer or EOS utility …


Could be better in LV perhaps since mirror is already up?

One reason for the 6D was the heating of sensor on my EOS M3 even when display is switched of. On 5 minutes live view the temperature goes higher as on 60 Minutes exposure time…

Is it possible, to fix the mirror all the time, when intervalometer is running?

Yes, there are options for more accurate timing. In particular, any kind of timelapse with FPS override should be quite good (I can check the timing on this one too; I expect it to be limited just by interrupt processing overhead - minor jitter, but no bias).
Timestamps from 30 seconds of LiveView

But in this case I have no full size RAW Data or?


6D

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12326
  • Holidays!
Re: How accurate is the ML Intervalometer?
« Reply #10 on: February 15, 2018, 01:25:40 PM »
Then, full-resolution silent pictures is what you are looking for. Timing accuracy is fairly good, they run outside LiveView, without shutter/mirror actuations, are compatible with all DIGIC 4 and 5 models running ML, but they are limited to long-ish exposures, with gradient. They are scriptable in Lua, too - just enable them in menu, then camera.shoot() will use them. Use the experimental Lua builds for that. On 5D3, there's also full-res LiveView, also a very good choice for timelapse (up to 5 fps continuous, without exposure gradient and with very accurate timing).

Raw-based exposure metering is done by Auto ETTR (also usable for timelapse, but requires deflicker in post). No idea how it compares with CHDK tools. There's also the advanced intervalometer from dmilligan (manual ramping), also implemented as Lua script.

Your os.time loop should be as accurate as our delayed_call (which is a DryOS event fired from their timer interrupt, running outside regular tasks), but I doubt os.time is available in our Lua implementation (you could use dryos.ms_clock for this purpose - reports with millisecond accuracy - and msleep - with 10ms resolution).

Sorry, I don't run CHDK (though I do follow their forum), so Lua scripting compatibility between the two isn't something I can check, but I agree it would be nice to have.

c_joerg

  • Freshman
  • **
  • Posts: 50
Re: How accurate is the ML Intervalometer?
« Reply #11 on: February 15, 2018, 04:12:19 PM »
Then, full-resolution silent pictures is what you are looking for. Timing accuracy is fairly good, they run outside LiveView, without shutter/mirror actuations, are compatible with all DIGIC 4 and 5 models running ML, but they are

That sounds really interesting… I try to go deeper into it…

What does ramping mean?
Could you change exposure time and ISO continuously (In CHDK in steps of 1/96EV) from frame to frame instead of 1/3EV?
The following test video I made with CHDK by changing ISO in 1/96EV steps.


Sorry, I don't run CHDK (though I do follow their forum), so Lua scripting compatibility between the two isn't something I can check, but I agree it would be nice to have.
The rawopint.lua is absolutely great. Auto ramping for exposure time and ISO in 1/96EV steps.
The following videos are made with this script. No deflicker or exposure correction was necessary in postprocessing.





6D

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12326
  • Holidays!
Re: How accurate is the ML Intervalometer?
« Reply #12 on: February 15, 2018, 04:45:47 PM »
EOS firmware uses 1/8 EV internally (actually, most recent models only accept 1/3 and 1/2 EV multiples, that is, 3/8, 4/8, 5/8 and full stops). You can get finer control only in LiveView (by programming the shutter blanking timer directly), but this is not currently exploited for timelapse. There is a gradual exposure feature for video, that uses this method, and there's also an option for shutter fine-tuning.

In photo mode, the shutter mechanism is driven by the MPU, a secondary processor not exactly under our control. That processor receives the shutter speed (in 1/8 EV increments) and decides when to move the mirror and the shutter mechanism on its own (even if you lock up the main CPU completely, and press the shutter button, you'll still hear the mirror going up, for example).

It may be possible to fine-tune the exposure time for full-res silent pictures, although this change requires some good understanding of photo capture internals (even though the shutter actuation is done on another CPU, the sensor is driven from the ARM side), and is likely model-specific. It can also be done with the full-res LiveView (it's a lot easier actually that way), but first you'll probably want this feature ported to your camera.

c_joerg

  • Freshman
  • **
  • Posts: 50
Re: How accurate is the ML Intervalometer?
« Reply #13 on: February 15, 2018, 06:45:07 PM »
In photo mode, the shutter mechanism is driven by the MPU, a secondary processor not exactly under our control. That processor receives the shutter speed (in 1/8 EV increments) and decides when to move the mirror and the shutter mechanism on its own (even if you lock up the main CPU completely, and press the shutter button, you'll still hear the mirror going up, for example).
For me it sounds, that’s much more complicated as on Powershoots …
I try to get deeper into the whole stuff…
Thanks for explanations…
6D

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 12326
  • Holidays!
Re: How accurate is the ML Intervalometer?
« Reply #14 on: February 17, 2018, 11:05:15 PM »
Posted an experimental build (lua_fix) that also has improved intervalometer accuracy.

My quick test:
Code: [Select]
12.004.624  shoot_task:000841e4:00:00: lens_take_picture
16.004.611  shoot_task:000841e4:00:00: lens_take_picture
20.004.610  shoot_task:000841e4:00:00: lens_take_picture
24.004.612  shoot_task:000841e4:00:00: lens_take_picture
28.004.605  shoot_task:000841e4:00:00: lens_take_picture
32.004.622  shoot_task:000841e4:00:00: lens_take_picture
36.004.609  shoot_task:000841e4:00:00: lens_take_picture
40.004.609  shoot_task:000841e4:00:00: lens_take_picture
44.004.624  shoot_task:000841e4:00:00: lens_take_picture
48.004.609  shoot_task:000841e4:00:00: lens_take_picture

12.063.545  ShootCaptu:ff147854:93:03: scsReleaseStart
16.062.177  ShootCaptu:ff147854:93:03: scsReleaseStart
20.071.782  ShootCaptu:ff147854:93:03: scsReleaseStart
24.058.987  ShootCaptu:ff147854:93:03: scsReleaseStart
28.061.618  ShootCaptu:ff147854:93:03: scsReleaseStart
32.066.348  ShootCaptu:ff147854:93:03: scsReleaseStart
36.062.039  ShootCaptu:ff147854:93:03: scsReleaseStart
40.072.756  ShootCaptu:ff147854:93:03: scsReleaseStart
44.072.025  ShootCaptu:ff147854:93:03: scsReleaseStart
48.087.256  ShootCaptu:ff147854:93:03: scsReleaseStart

Just FYI: the intervalometer already used a loop similar to the one you suggested, since 2012 (that's why, even if there was some variation, there was no drift, unless the camera couldn't keep up because of slow card or whatever); it was just the delays within the waiting loop, and the timer update interval, that were too high.

c_joerg

  • Freshman
  • **
  • Posts: 50
Re: How accurate is the ML Intervalometer?
« Reply #15 on: February 19, 2018, 09:26:29 AM »
Posted an experimental build (lua_fix) that also has improved intervalometer accuracy.

Is behind the ML build in intervalometer a lua script?
Does this update improves the ML build in intervalometer or must I start a lua script like in CHDK?

6D

c_joerg

  • Freshman
  • **
  • Posts: 50
Re: How accurate is the ML Intervalometer?
« Reply #16 on: February 21, 2018, 08:10:53 PM »
Posted an experimental build (lua_fix) that also has improved intervalometer accuracy.

Thanks, works very well ...


6D

c_joerg

  • Freshman
  • **
  • Posts: 50
Re: How accurate is the ML Intervalometer?
« Reply #17 on: July 09, 2018, 08:21:45 PM »
I run the intervalometer with 6s and Auto ETTR. I got a jitter from around +- 0.2s.
Can it come from Auto ETTR?


I haven’t changed anything on installation since last time…
6D