CHDKPTP - PC Remote Control Performance Analysis - page 17 - RAW Shooting and Processing - CHDK Forum

CHDKPTP - PC Remote Control Performance Analysis

  • 465 Replies
  • 153137 Views
*

Offline SticK

  • *****
  • 779
Re: CHDKPTP - PC Remote Control Performance Analysis
« Reply #160 on: 11 / September / 2012, 15:18:30 »
Advertisements
Here is something strange to add to the info arsenal .......

) After the last myshoot fail I did not PDN camera.

) The camera was left in REC mode working OK, camera LCD live and OK.

) With lens extended and running, I quit chdkptp.

) Removed the peppered sleeps in dcimdl and put the dcimdl delay to 3s.

) Restarted chdkptp

) Turned ON liveview

) Pressed REC

) Bingo ... camera LCD went totally dark on REC.

) However ..... chdkptp liveview continues working !

) I do the 1st myshoot and all's well // chdkptp liveview is still up ... but .... camera LCD is black !

) On the 2nd myshoot, I get the fail.

Strange, no ?

So the idea now is to get another failure and make sure the LOG is date-stamped correctly.
« Last Edit: 11 / September / 2012, 15:26:00 by SticK »

*

Offline SticK

  • *****
  • 779
Re: CHDKPTP - PC Remote Control Performance Analysis
« Reply #161 on: 11 / September / 2012, 15:41:41 »
Stapled SCREEN SHOT & ROMLOG

ROMLOG guaranteed date stamp.

dcimdl delay is 3s to get more frequent fails.  At 3s I still get a stable camera LCD about 1s before CHDK activity.

"ASSERT!! ReadFDir.c Line 96"  .. is that Canon or you?  I seen this in the last 3 logs I think.

*

Offline SticK

  • *****
  • 779
Re: CHDKPTP - PC Remote Control Performance Analysis
« Reply #162 on: 11 / September / 2012, 16:26:55 »
SCREEN SHOT & ROMLOG - 43rd myshoot

It is possible that initial conditions may not have been consistent before giving me the illusion of randomness.  This time I made sure initial conditions are clean and can be repeated:

==> manually delete hanging directories & then PDN/PUP.  Leave chdkptp running as it seems not to be the contributor AFAIK.

For the next post I will do another run like this and determine if the failure also occurs on 43 rd myshoot.

*

Offline SticK

  • *****
  • 779
Re: CHDKPTP - PC Remote Control Performance Analysis
« Reply #163 on: 11 / September / 2012, 16:47:35 »
SCREEN SHOT & ROMLOG  8 myshoots

Same initial conditions as previous post.  Note  free block drop to 9K on enter to dcimdl.

Answer: Random.

Next: your suggestion to skip over calls in dcimdl.

*

Offline reyalp

  • ******
  • 14140
Re: CHDKPTP - PC Remote Control Performance Analysis
« Reply #164 on: 11 / September / 2012, 17:10:33 »
Quote "Given that you had a lot of crashes while the camera was writing files, it's possible your filesystem got messed up."

No, that's not the case.  I make sure the sleep in front of dcimdl is long enough to put the camera state into "I am ready for the next shot."  So definitely not while the SD is written.  I did another similar test -- see below.
That doesn't follow. You probably had crashes similar to the ones that I encountered on D10 before you added the sleep. Those would have by definition happened when the Canon firmware had files open. You apparently also have some other problem, which could conceivably have been caused by the earlier crashes messing up the filesystem. I'd guess this is fairly unlikely, but not impossible.
Quote
#1 - I peppered dcimdl with 200ms sleeps (a very honest and real hack because fundamentally I have no idea what I'm doing) and the highest number of myshoots in a row I got was 40 // in effect, no difference.
I told you this was pointless.
Quote
#5 - I figured this  ...... the only asynchronous event I know that could interfere of is liveview.  Liveview on the SX110 bench is 2.7 to 3 fps.   I have had liveview running by itself overnight on the SX110 w/o a problem.  So I set fps to 1, and I could see the slow transfer for a few frames.  I left the bench unattended for a couple of minutes and came back to a dead system.  There was *no* ptp error, in fact no message at all anywhere ... as if everything had frozen in time.  Very strange.
Not just strange, it must be wrong. If the camera stopped responding, then there would be a PTP error. If there was not PTP error, then the camera was running.

Are you sure the "dead system" isn't a combination of canon power save and the alt mode issue I explained before (where you need to press the alt key a couple times to get fully into or out of alt mode) ?

Note that a better way to take live view out of the equation is to turn it off completely. Switching away from the live tab also disables it until you switch back.

Quote
#10 - I reset the liveview to 3 fps and noticed a similar effect before failure, Fig 2 next post.  So there may *in fact* be something related to malloc() which is transient and occurs randomly affecting only the functions in dcimdl ??
Um yeah. From http://chdk.setepontos.com/index.php?topic=8613.msg90661#msg90661
Quote
The current 1.1 builds  for most cameras have a very hacky thing in the ptp code that determines the amount of free memory by repeatedly mallocing larger and larger blocks. This may cause problems. I can provide builds use camera functions to check available memory. The 1.2 (unstable) builds do this by default.

Quote
Q1.  Does listdir return after it has delivered the goods?
Q2.  Does mdl return only after it has delivered the goods?
I already answered this.
Quote
) Bingo ... camera LCD went totally dark on REC.
) However ..... chdkptp liveview continues working !
) I do the 1st myshoot and all's well // chdkptp liveview is still up ... but .... camera LCD is black !
Is the live view actually updating (e.g. if you wave your hand in front of the camera do you see it ?), or is it just showing the last image before the screen went dark ?

Assuming the second case, this is almost certainly going into canon "display off" power save mode. Sending a keypress should wake it up. As I described repeatedly before, waking it up from the cameras physical keyboard is subject to the confused alt mode issue.

You don't need to keep posting identical romlogs and screenshots. You should look at the rom logs, and if it's the same assert then I don't need more copies. I might ask for a fresh romlog if I give you a new build.
Quote
"ASSERT!! ReadFDir.c Line 96"  .. is that Canon or you?  I seen this in the last 3 logs I think.
All the romlog asserts in Canon code. The triggering condition may ultimately be due to CHDK code. I need to investigate that one further, but that will take time.

I've already overrun my lunch break but I will try to make you a fresh build which will give me a somewhat more useful romlog, and also change the memory checking option I mentioned earlier.
Don't forget what the H stands for.

*

Offline reyalp

  • ******
  • 14140
Re: CHDKPTP - PC Remote Control Performance Analysis
« Reply #165 on: 11 / September / 2012, 17:30:06 »
Here's the updated build, for sx110

Please post one new romlog of the ASSERT!! ReadFDir.c Line 96 error with this, assuming it happens.

Don't forget what the H stands for.

*

Offline SticK

  • *****
  • 779
Re: CHDKPTP - PC Remote Control Performance Analysis
« Reply #166 on: 11 / September / 2012, 17:47:45 »
Quote "That doesn't follow. You probably had crashes similar to the ones that I encountered on D10 before you added the sleep."

There's something that doesn't jive here from my side too ..... when I had dcimdl sleep=0s, there were successful myshoots, but only a few in a row ... something like 3 or 4 at most.  In all my tests I believe I had a fail only once on the 1st shot.

Quote "Note that a better way to take live view out of the equation is to turn it off completely."

I tried this too but did not report it // same results.

Quote "Um yeah."

I'm just wondering aloud if there is an asynchronous event that hogs most of the heap, which we don't always see in the memory sniffs, and if it happens at the wrong time for dcimdl, then it's goodbye. 

Quote "I already answered this."

I only asked about shoot which you answered.  If you made a comment about the other two as well, I missed it -- my apologies.  Next time when you get the chance please point me to your comment.

Quote " If there was not PTP error, then the camera was running."

I will keep it in mind next time this happens.

Quote "Is the live view actually updating "

Yes .. that was the whole point of my report: the dichotomy which theoretically should not exist.

Quote "Assuming the second case,"

First case.

Quote "my lunch break"

Please don't put your job on the line over this // I always can wait until the evening .. and ... don't forget to stop for that refreshing beer along the way back. :)

*

Offline SticK

  • *****
  • 779
Re: CHDKPTP - PC Remote Control Performance Analysis
« Reply #167 on: 11 / September / 2012, 19:17:05 »
ROMLOG AA - SX110 2141-test1 - worth 2 beer on me!

Test #1:  3s delay to dcimdl , dcimdl memory sniff ON, 1M JPG, 101 myshoots, NO FAIL, stopped by me

Test #2:  200 ms delay to dcimdl, dcimdl memory sniff OFF, 1M JPG, 60 myshoots, DOS screen clean NO FAIL, stopped by me

Test #3:  200 ms delay to dcimdl, dcimdl memory sniff OFF, 1M JPG & 15MB DNG, FAIL after 7 myshoots (14 files downloaded successfully), failed on DNG, JPG not reached.

I know you'll have something to say about the short delay // and I do have questions about why it works too in test 2 and even in test 3.  Test 3 takes several good seconds to save both files to SD, way beyond 200 ms.  Hmmmm?

This looks like on the right track // my turn for a beer // chat later.

*

Offline SticK

  • *****
  • 779
Re: CHDKPTP - PC Remote Control Performance Analysis
« Reply #168 on: 11 / September / 2012, 23:12:37 »
ROMLOG 55 SX110  JPG & DNG -- FAIL after 33 myshoots (with memory sniff ON).

delay to dcimdl: 200 ms

Shoot: 2 sec
Save: 5 sec

Since test-1 both logs are of the "Vector" type.  I have not yet noticed any major dip in free block.

The top memory sniff is "enter dcimdl", not visible off top of screen.
« Last Edit: 11 / September / 2012, 23:15:03 by SticK »

*

Offline reyalp

  • ******
  • 14140
Re: CHDKPTP - PC Remote Control Performance Analysis
« Reply #169 on: 11 / September / 2012, 23:15:45 »
Test #1:  3s delay to dcimdl , dcimdl memory sniff ON, 1M JPG, 101 myshoots, NO FAIL, stopped by me
Test #2:  200 ms delay to dcimdl, dcimdl memory sniff OFF, 1M JPG, 60 myshoots, DOS screen clean NO FAIL, stopped by me
The build I posted has CAM_FIRMWARE_MEMINFO, which means it uses firmware functions to get the available memory instead of the malloc hack mentioned earlier. This suggest to me that the earlier instability might have been caused by the malloc hack, and thus the extra memory debugging calls would have *decreased* stability. I have firmware meminfo enabled on all my cameras, so I wouldn't have seen the same thing. I'll try without though...

Quote
Test #3:  200 ms delay to dcimdl, dcimdl memory sniff OFF, 1M JPG & 15MB DNG, FAIL after 7 myshoots (14 files downloaded successfully), failed on DNG, JPG not reached.

Code: [Select]
Exception!! Vector 0x10
Occured Time  2012:09:11 19:00:00
Task ID: 29491262
Task name: FolderCreate0
Exc Registers:
...
This romlog is quite different from the others. The other ones were in PhySw task, which is one we modify. We don't do anything with  FolderCreate0. It's also an invalid memory access exception, rather than an assert. The name suggests that it might be responsible for creating the image folders. In this case, you might try only removing the files from within the folders instead of removing the folders themselves.
Quote
I know you'll have something to say about the short delay // and I do have questions about why it works too in test 2 and even in test 3.  Test 3 takes several good seconds to save both files to SD, way beyond 200 ms.  Hmmmm?
Shoot waits for most of the shooting process to complete. In particular, it shouldn't return until CHDK raw is complete, if it's enabled.

edit:
since firmware meminfo obviously works on this camera, I'll check that in in the release branch.

edit:
The ReadFDir.c Line 96 assert would be triggered by a malloc failure, which matches the conclusion above. The amount of memory it tries to allocate is 32k

edit:
The FolderCreate0 romlogs are bizarre.
ROMLOG_55 is vector 0x04 = invalid instruction, while romlog_aa is invalid memory access
In both cases, PC is not a ROM value or a CHDK code value.
LR in both cases is 0x000C5BC9 which is inside CHDK Lua thumb code. The stack also looks like it's in thumb code. Lua should only run in PhySwtask, certainly not FolderCreate0... Possibly a corrupted TCB ?

Quote
Next time when you get the chance please point me to your comment.
http://chdk.setepontos.com/index.php?topic=8613.msg90679#msg90679
Quote
The commands in dcimdl will only return when they are actually complete.
If you think about something like download, it can't possibly return until it's done (all the data is downloaded from the camera). rm could be fire and forget, but it's not.
« Last Edit: 11 / September / 2012, 23:55:31 by reyalp »
Don't forget what the H stands for.

 

Related Topics


SimplePortal © 2008-2014, SimplePortal