reboot after 21 days worked, but with fault - page 2 - General Help and Assistance on using CHDK stable releases - CHDK Forum
« previous next »
Pages: 1 [2] 3 4   Go Down

reboot after 21 days worked, but with fault

  • 32 Replies
  • 1114 Views
*

Offline c_joerg

  • *****
  • 824
Re: reboot after 21 days worked, but with fault
« Reply #10 on: 06 / June / 2019, 02:44:20 »
Advertisements
Quote from: Mlapse on 06 / June / 2019, 02:00:21
All things considered I think it is amaizing that it survived this run,

Definitely…
But maybe there is a limit (16Bit) for the maximum number of recordings that can be handled by the cam on the SD card ...
Logged
M100 100a, M3 101a, 2*G1x (101a,100e), S110 (103a), SX50 (100c), SX230 (101a), 2*S45,
Flickr https://www.flickr.com/photos/136329431@N06/albums
YouTube https://www.youtube.com/channel/UCrTH0tHy9OYTVDzWIvXEMlw/videos?shelf_id=0&view=0&sort=dd
*

Offline Mlapse

  • ***
  • 211
  • A480 A490 S95 M10
Re: reboot after 21 days worked, but with fault
« Reply #11 on: 06 / June / 2019, 03:03:32 »
Quote
Definitely…
But maybe there is a limit (16Bit) for the maximum number of recordings that can be handled by the cam on the SD card ...

I would have expected some 4000 more then.
to test that theorie i just copied 3000 pictures extra to that card, put it back in the cam, fired it up manually so the cam stalls checking all those files and started the script. and that works.
might not be the same as if it was the same run, but it's more files on the card. so it is not a total file number limit (yet)
« Last Edit: 06 / June / 2019, 03:07:59 by Mlapse »
Logged
frustration is a key ingredient in progress
*

Offline Mlapse

  • ***
  • 211
  • A480 A490 S95 M10
Re: reboot after 21 days worked, but with fault
« Reply #12 on: 06 / June / 2019, 03:15:05 »
Quote
The script logs this if set_record fails. If this happened, then all subsequent shooting would likely also fail (though later attempts to shoot of half press could coincidentally switch to rec on many cameras)
so if I understand you, the set_record fail was because it came in too early after the reboot. resulting in no shot at 11:51:00, but the attempt to shoot made set_record initialise correctly
so the next at 11:51:30 was then recorded.
this at least explaines partly why there is a 2.5 minute gap instead of a 1.5 minute gap when i was testing.

BTW the 10s delayed start Waterwingz made for me (CHDK 1.5.0) makes the CF zoom setting in custom mode delay as well, but since timing after reboot for the next shot was close. it mights be that the lens was not ready and this created the set_record flag and that I should set the script shoot delay in the UI menu to prevent this.

just out of curiosity, why is the 'rebooting now' time later than the startup time.
Code: [Select]
Day 21 Sat Jun  1 11:50:10 2019 lens retraction wait
Day 21 Sat Jun  1 11:51:22 2019 rebooting now

Day -- Sat Jun  1 11:50:57 2019 === Ultimate v4.8 : 11:50 ===
Day -- Sat Jun  1 11:50:57 2019 CHDK 1.5.0 s95 100k May  6 2019
« Last Edit: 06 / June / 2019, 04:19:47 by Mlapse »
Logged
frustration is a key ingredient in progress
*

Offline waterwingz

  • ******
  • 11913
    • Waterwingz
Re: reboot after 21 days worked, but with fault
« Reply #13 on: 06 / June / 2019, 08:28:00 »


Quote from: Mlapse on 06 / June / 2019, 03:15:05
just out of curiosity, why is the 'rebooting now' time later than the startup time.
The camera reads it's hardware battery backed real time clock (RTC) when it starts up. After that it maintains time in software. It's unlikely Canon worried too much about the accuracy of the software maintained time as most people don't leave their camera powered up for many hours.
Logged
Ported :   A1200    SD940   G10    Powershot N    G16
*

Offline Mlapse

  • ***
  • 211
  • A480 A490 S95 M10
Re: reboot after 21 days worked, but with fault
« Reply #14 on: 09 / June / 2019, 00:48:59 »
@waterwingz, if your explanation is right that it only reads RTC at startup, why isn't that time used after the reboot? I would suspect the reboot simulates a startup(it at least resets the tick-counter)
thus shouldn't the CF reboot with that time and thus set the time in CHDK as well?

I have found another strange thing after reboot and I think this needs more attention than the time-traveling features of the cam.
related to this or to reyalps remark of set_record fail?

the interval for this run was set at 30seconds, so it should create 2880 pics a day. and it did for the first 3 weeks.

After the time-shift in the log occured(rebooting now 11:51:22, day21)and set_record fail, i am missing 10 pictures of that day.(except for the 2 because of a reboot)
this keeps occuring the following days with loss of 20-25 frames a day.

looking through the log I found this:
the missing ones are logged with exact times in seconds (00 or 30)
those also had similar IMG_numbers in the log. It looks like the ones with the 00 or 30 sec. in the log were not recorded on the SD card, not that the old one was overwritten.
I have no missing pics on a day pre-reboot (nor have i experienced this problem in a non-reboot run ever)
Can this be solved?....or can I find out why this happens, so we might solve it in the future.
hereby a small portion from the log where it happened twice in 5 minutes.


Code: [Select]
Day 21 Sat Jun 1 21:11:04 2019 IMG_0539.JPG tv: 0.6 f: 3.1 ISO: 75 bv: 14 V: 3.949
Day 21 Sat Jun 1 21:11:30 2019 IMG_0539.JPG tv: 0.6 f: 3.1 ISO: 75 bv: 5 V: 3.949
Day 21 Sat Jun 1 21:12:04 2019 IMG_0540.JPG tv: 0.6 f: 3.1 ISO: 75 bv: -2 V: 3.953
Day 21 Sat Jun 1 21:12:34 2019 IMG_0541.JPG tv: 0.6 f: 3.1 ISO: 75 bv: -11 V: 3.94
Day 21 Sat Jun 1 21:13:04 2019 IMG_0542.JPG tv: 0.6 f: 3.1 ISO: 75 bv: -19 V: 3.949
Day 21 Sat Jun 1 21:13:34 2019 IMG_0543.JPG tv: 0.6 f: 3.1 ISO: 75 bv: -27 V: 3.953
Day 21 Sat Jun 1 21:14:00 2019 IMG_0543.JPG tv: 0.6 f: 3.1 ISO: 75 bv: -35 V: 3.949
« Last Edit: 09 / June / 2019, 05:11:07 by Mlapse »
Logged
frustration is a key ingredient in progress
*

Offline waterwingz

  • ******
  • 11913
    • Waterwingz
Re: reboot after 21 days worked, but with fault
« Reply #15 on: 09 / June / 2019, 11:30:18 »
Quote from: Mlapse on 09 / June / 2019, 00:48:59
@waterwingz, if your explanation is right that it only reads RTC at startup, why isn't that time used after the reboot? I would suspect the reboot simulates a startup (it at least resets the tick-counter) thus shouldn't the CF reboot with that time and thus set the time in CHDK as well?
My explanation is correct - the RTC is only read at startup or a reboot. And it does use the RTC time after each reboot. Which is consistent with the log file snippet you posted.  Prior to the reboot, the internal time maintained by the Canon firmware was running slightly faster than the time maintained by the RTC. So when the reboot happens the Canon firmware reads the RTC and uses that time to initialize its software internal clock. This causes the logged time to appear  to go backwards (as the software maintained time prior to reboot was running ahead of the RTC time).

Quote
I have found another strange thing after reboot and I think this needs more attention than the time-traveling features of the cam related to this or to reyalps remark of set_record fail?
This is quite interesting.  Before I dig deeper into it, it would be nice to see a much bigger piece of log file. Can you post the whole thing somewhere and sent me a link? Or at least the part of the log including the reboot message and then all the shots up until the skipped images, and then a couple hundred shots after that?

Logged
Ported :   A1200    SD940   G10    Powershot N    G16
*

Offline Mlapse

  • ***
  • 211
  • A480 A490 S95 M10
Re: reboot after 21 days worked, but with fault
« Reply #16 on: 09 / June / 2019, 12:05:45 »
hereby, i left the header and a small portion before reboot and then until the end. as you can see there is not much consistancy in when it does this, the skipped images are just scattered throughout the day.

if you want the complete thing, that ok too, but it's just this + some 58000 lines stating all is well.
« Last Edit: 09 / June / 2019, 12:42:48 by Mlapse »
Logged
frustration is a key ingredient in progress
*

Offline Mlapse

  • ***
  • 211
  • A480 A490 S95 M10
Re: reboot after 21 days worked, but with fault
« Reply #17 on: 30 / June / 2019, 14:21:30 »
Quote
This is quite interesting.  Before I dig deeper into it, it would be nice to see a much bigger piece of log file. Can you post the whole thing somewhere and sent me a link? Or at least the part of the log including the reboot message and then all the shots up until the skipped images, and then a couple hundred shots after that?

Did you find anything or thought of something that could help us track down and solve this timing issue after reboot?
I am missing some frames that i haven't tracked yet in the log, since there are only 4 double numbers in the log and i'm missing 8 on day 21. (day 21 ends on 870, should be 880, 2 lost because of reboot, 8 left) one of those missing frames is around IMG_0600.JPG at day 21, 21:44:41
 
« Last Edit: 01 / July / 2019, 14:01:07 by Mlapse »
Logged
frustration is a key ingredient in progress
*

Offline waterwingz

  • ******
  • 11913
    • Waterwingz
Re: reboot after 21 days worked, but with fault
« Reply #18 on: 02 / July / 2019, 14:58:29 »
Quote from: Mlapse on 30 / June / 2019, 14:21:30
Did you find anything or thought of something that could help us track down and solve this timing issue after reboot?
First of all,  I'm certain it's unrelated to the time shift you are seeing after a reboot.  I believe I've already explained why.

What I think is happening is that the camera tries to take a shot under script control (via the shoot( ) function) and the shot fails. 
  • The first clue here is that the time stamp of log entry of the failed shot is about five seconds earlier than a successful shot would have had.  That additional time would have been needed to take the actual shot, prepare the JPG file, and write it to the SD card.
  • The second clue is that the image count number does not advance - it stays the same as the camera never completes the shot and so does not advance it's image counter.
So why do shots randomly start failing after many days? 

I'd speculate that as the SD card fills up, things start taking longer. And one possibility is the SD card wear leveling algoritm kicking in - we have seen that happen in the past but it typically is more periodic that what seems to be happening here.

The shoot() command actually returns some limited status information but unfortunately the script ignore it.  I could modify the script to start logging that status to see if CHDK thinks the shot failed. That might give us some idea if it fails on the half-press or after that.  That might give us a clue about what's actually happening.

Quote
I am missing some frames that i haven't tracked yet in the log, since there are only 4 double numbers in the log and i'm missing 8 on day 21.
I only did a quick scan and found 5 in that log.  It would be easy suck it into a spreadsheet and play some tricks to find other duplicates but I haven't bothered yet.
Logged
Ported :   A1200    SD940   G10    Powershot N    G16
*

Offline Mlapse

  • ***
  • 211
  • A480 A490 S95 M10
Re: reboot after 21 days worked, but with fault
« Reply #19 on: 02 / July / 2019, 15:37:10 »
i concur that the failed shots lack the few seconds needed to record that jpg.
as far as i know the failed shots are 384, 543, 550, 576. what you see around 600 is not a missed shot with a :00 timestamp but a shift in interval timing resulting in one shot less.

I am assuming the interval timing is still 30 seconds, but it takes increasingly more time until a log entry is made eventually leading to a missed frame and later freezing the camera in an endless loop.
by looking at the timestamps on the actual pictures i found this lacking shot around 600.

if you think that adapting the script could give us relevant info I'm willing to test again.

i did some other tests and i haven't had results that helped me further.
but I think this problem will also occur if i reboot after a day, so i could try that first if you are interested.
taking too long to index was one of my biggest worries when i started this test, but as far as I can tell the missed shots are not related to the SD card filling up.

since it only occurs after reboot, it might be related to the lens zoom done by CF after UI is started?
the other option is that double click or lens change i heared and have seen when i use the debug mode is also there when it is not running in debug...
both sound a bit of a stretch to me, but this behaviour is unexpected anyway.
 
The card was new (transcend) when i did this test and it has given no indication that something is wrong. i did fill it up again after this test and verified the writes, all as expected without faults

 
« Last Edit: 02 / July / 2019, 16:22:43 by Mlapse »
Logged
frustration is a key ingredient in progress
Pages: 1 [2] 3 4   Go Up
« previous next »
 

Related Topics