Author Topic: Intercepting DebugMsg with cache hacks  (Read 14865 times)

nikfreak

  • Developer
  • Hero Member
  • *****
  • Posts: 944
Re: Intercepting DebugMsg with cache hacks
« Reply #25 on: April 14, 2017, 12:27:21 PM »
just gave it a quick try after a long time (=months).
Best thing is that dm.log doesn't get overwritten like in past:

https://drive.google.com/drive/folders/0B9Mu66yg5QzROGV6aTNWTlJNbFE?usp=sharing
70D.112 & 100D.101

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 9831
  • 5D Mark Free
Re: Intercepting DebugMsg with cache hacks
« Reply #26 on: April 14, 2017, 12:48:04 PM »
You can log code sequences from other branches as well. Here's an example for debugging compressed_raw on 5D3 1.2.3:

Makefile.user:
Code: [Select]
CONFIG_DEBUG_INTERCEPT = y

Merge the two branches:
Code: [Select]
hg update compressed_raw -C
hg merge dm-spy-experiments

(there will be some merge conflicts, sorry about that, I'm still novice in this area)
(maybe it's best to cleanup the dm-spy-experiments branch a bit and merge it in mainline)
(ignore mlv_lite and mlv_rec for now, as we are not going to use them - just merge the other files)

Change the code to enable logging:
Code: [Select]
diff -r ad3969261ccf modules/silent/lossless.c
--- a/modules/silent/lossless.c
+++ b/modules/silent/lossless.c
@@ -3,6 +3,7 @@
 #include "lens.h"
 #include "raw.h"
 #include "edmac.h"
+#include "dm-spy.h"
 
 struct TwoInTwoOutLosslessPath_args
 {
@@ -251,10 +252,18 @@
 
 int lossless_compress_raw(struct raw_info * raw_info, struct memSuite * output_memsuite)
 {
-    return lossless_compress_raw_rectangle(
+    /* start logging */
+    debug_intercept();
+
+    int result = lossless_compress_raw_rectangle(
         output_memsuite, raw_info->buffer,
         raw_info->width, 0, 0,
         raw_info->width, raw_info->height
     );
+
+    /* stop logging and save to file */
+    debug_intercept();
+
+    return result;
 }

Now compile ML core and the silent picture module, place them on the card, and take a full-res silent picture with lossless compression (so the routine we have modified will get called in a quiet context - with LiveView turned off).

Code: [Select]
cd platform/5D3.123
make clean; make
make installq       # this copies only autoexec and sym file
cd ../../modules/silent
make clean; make
make install        # copy only this module to your card

You should get a file named dm-000.log in the root of the card, that contains these lines (among many others):
Code: [Select]
172EB> shoot_task:000aeef0:00:00: *** register_interrupt("Jp57IntrHandler", 0xa3, 0xff291e2c, 0x0), from ff3dcc78
17882> shoot_task:ff3dd01c:16:03: [TTL] START WR1:0x18800064 WR2:0x15a0c000
178B2> shoot_task:ff3dd048:16:03: [TTL] START RD1:0x86051a8 RD2:0xad24490
34733> **INT-A3h*:ff3dcc08:16:03: [TTL][0,0,0] JpCoreCompleteCBR( 0x15336af )
3476D> **INT-83h*:00a0e980:00:00: LosslessCompleteCBR







Want more details?

Let's enable interrupts and ENGIO messages:
Code: [Select]
diff -r 9146aa47814c src/dm-spy-extra.c
--- a/src/dm-spy-extra.c
+++ b/src/dm-spy-extra.c
@@ -20,7 +20,7 @@
 #include "timer.h"
 
 /* this needs pre_isr_hook/post_isr_hook stubs */
-//~ #define LOG_INTERRUPTS
+#define LOG_INTERRUPTS
 
 /* delay mpu_send calls, to allow grouping MPU messages by timestamps */
 #define MPU_DELAY_SEND
@@ -338,11 +338,11 @@
     { 0xff2953b8, "LockEngineResources", 1, LockEngineResources_log },
     { 0xff29555c, "UnLockEngineResources", 1, UnLockEngineResources_log},
 
-    //~ { 0xff290f98, "engio_write", 1, engio_write_log},   /* on 5D3, Canon's engio_write is silent */
-    //~ { 0xff290c80, "EngDrvOut", 2 },                     /* same here */
-    //~ { 0xff290ca0, "EngDrvIn", 1 },
-    //~ { 0xff290d38, "EngDrvBits", 3, engdrvbits_log},
-    //~ { 0xff290cd4, "EngDrvIns", 3 },
+    { 0xff290f98, "engio_write", 1, engio_write_log},   /* on 5D3, Canon's engio_write is silent */
+    { 0xff290c80, "EngDrvOut", 2 },                     /* same here */
+    { 0xff290ca0, "EngDrvIn", 1 },
+    { 0xff290d38, "EngDrvBits", 3, engdrvbits_log},
+    { 0xff290cd4, "EngDrvIns", 3 },
     /* only EngDrvOuts is verbose, no need to log it here */
     
     //~ { 0xFF694880, "eeko_setup_global_vars", 10 },
diff -r 9146aa47814c src/dm-spy.c
--- a/src/dm-spy.c
+++ b/src/dm-spy.c
@@ -52,8 +52,6 @@
 {
     if (!buf) return;
         
-    if (class == 21) // engio, lots of messages
-        return;
     
     #ifdef CONFIG_7D
     if (class == 0x3E) // IPC, causes ERR70

Lots of messages now! Let's look at some of them.

How does SetEDmac work?

Code: [Select]
CDD68> shoot_task:000af06c:00:00: *** SetEDmac(0x11, 0x58800064, 0x1c42ac, 0x20000001), from ff580f28
CDD80> shoot_task:000af168:00:00:     *0x1c42ac = { 0 0 0 0  0 0 2000 0  fff 0 0 a0f7f8 ... }
CDDBD> shoot_task:ff290e18:15:02: [ENGIO](Addr:0xc0f2610c, Data:0x       0)[8]EngDrvOuts
CDDE5> shoot_task:ff290e18:15:02: [ENGIO](Addr:0xc0f26110, Data:0x fff2000)[7]EngDrvOuts
CDE0F> shoot_task:ff290e18:15:02: [ENGIO](Addr:0xc0f26114, Data:0x       0)[6]EngDrvOuts
CDE32> shoot_task:ff290e18:15:02: [ENGIO](Addr:0xc0f26118, Data:0x       0)[5]EngDrvOuts
CDE55> shoot_task:ff290e18:15:02: [ENGIO](Addr:0xc0f2611c, Data:0x       0)[4]EngDrvOuts
CDE79> shoot_task:ff290e18:15:02: [ENGIO](Addr:0xc0f26120, Data:0x       0)[3]EngDrvOuts
CDE9C> shoot_task:ff290e18:15:02: [ENGIO](Addr:0xc0f26124, Data:0x       0)[2]EngDrvOuts
CDEBF> shoot_task:ff290e18:15:02: [ENGIO](Addr:0xc0f26128, Data:0x       0)[1]EngDrvOuts
CDEE5> shoot_task:000125c0:15:01: ResetEDmac(0x20000001)
CDF1F> shoot_task:000af06c:00:00: *** EngDrvOut(0xc0f26104, 0x20000001), from 125d4
CDF55> shoot_task:000af06c:00:00: *** EngDrvOut(0xc0f26108, 0x18800064), from 125ec

This reveals the register configuration performed by SetEDmac.

How do we know where to stop? The next line reads:
Code: [Select]
CDF9C> shoot_task:000af06c:00:00: *** RegisterEDmacCompleteCBR(0x11, 0xff580b3c "[PackMem] CompleteInterrupt In %d", 0x11), from ff580f38

which is the next call, and nothing interesting happens in-between (so, all those messages must be from SetEDmac).

Alternative: log the return value of SetEDmac, so you'll know for sure where this call ends. Exercise for the reader.

How does the main CPU know when the compression is finished?

The JPCORE CPU announces it using an interrupt:
Code: [Select]
EC9F6> **INT-A3h*:000aed4c:00:00: >>> INT-A3h Jp57IntrHandler ff291e2c(0)
ECA36> **INT-A3h*:000af06c:00:00: *** EngDrvIn(0xc0e20044), from ff291ce4
ECA70> **INT-A3h*:000af06c:00:00: *** EngDrvIn(0xc0e20024), from ff291d18
ECA90> **INT-A3h*:ff3dcc08:16:03: [TTL][0,0,0] JpCoreCompleteCBR( 0x1403b4e )
ECADC> **INT-A3h*:000af06c:00:00: *** EngDrvOut(0xc0f26104, 0x20000006), from 12aec
...
ECCB1> **INT-83h*:00000588:00:00: <<< INT-A3h done

That magic number is 0x1403b4e = 20986702 - looks like a valid compressed size for a full-res picture (and you can confirm by printing output_size in lossless.c).

OK, so that must be where the firmware finds out the compressed size! Let's see which of these registers returns it. Enable logging the return value of EngDrvIn and repeat the experiment:

Code: [Select]
-    { 0xff290ca0, "EngDrvIn", 1 },
+    { 0xff290ca0, "EngDrvIn", 1 | RET },

Code: [Select]
D46DC> **INT-A3h*:000aed4c:00:00: >>> INT-A3h Jp57IntrHandler ff291e2c(0)
D4720> **INT-A3h*:000af06c:00:00: *** EngDrvIn(0xc0e20044), from ff291ce4
D482B> **INT-A3h*:000af1d0:00:00: !!! cannot log return value (err 10)
D4876> **INT-A3h*:000af06c:00:00: *** EngDrvIn(0xc0e20024), from ff291d18
D491E> **INT-A3h*:000aee24:00:00: ==> 0x14264a0, from ff291d18
D4954> **INT-A3h*:ff3dcc08:16:03: [TTL][0,0,0] JpCoreCompleteCBR( 0x14264a0 )
D49AA> **INT-A3h*:000af06c:00:00: *** EngDrvOut(0xc0f26104, 0x20000006), from 12aec
...
D4E17> **INT-0Ah*:00000588:00:00: <<< INT-A3h done

So it's the register 0xc0e20024 where compressed output size is coming from!

Still, what's up with 0xc0e20044? Why its value could not be logged? Look up the error code in patch.h => E_PATCH_CACHE_COLLISION...

Oh no, a cache conflict! What do we do?

Check the index bits of ff291ce8 (LR after the first EngDrvIn call): 0xff291ce8 & 0x7E0 = 0x4e0. Check the other logged addresses (I know, this should be automatic) => 0xff4fa4ec & 0x7E0 = 0x4e0. Comment it out.

Not feeling like doing the math? Just comment out all other ROM addresses (those starting with FF).

Code: [Select]
E45AF> **INT-A3h*:000aed4c:00:00: >>> INT-A3h Jp57IntrHandler ff291e2c(0)
E45F3> **INT-A3h*:000af06c:00:00: *** EngDrvIn(0xc0e20044), from ff291ce4
E4681> **INT-A3h*:000aee24:00:00: ==> 0x400, from ff291ce4
E46D2> **INT-A3h*:000af06c:00:00: *** EngDrvIn(0xc0e20024), from ff291d18
E47C4> **INT-A3h*:000aee24:00:00: ==> 0x14c14d8, from ff291d18
E47FA> **INT-A3h*:ff3dcc08:16:03: [TTL][0,0,0] JpCoreCompleteCBR( 0x14c14d8 )

With this method and some patience, you can trace just about anything in the firmware.

nikfreak

  • Developer
  • Hero Member
  • *****
  • Posts: 944
Re: Intercepting DebugMsg with cache hacks
« Reply #27 on: April 14, 2017, 01:03:14 PM »
Wow, thx for the nice tour and explanation.  8)
Will definitely become useful, not only for me. It just becomes a pain to insert the card a dozen of times but i am used to it from porting. Guess QEMU is the way to go in future...
70D.112 & 100D.101

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 9831
  • 5D Mark Free
Re: Intercepting DebugMsg with cache hacks
« Reply #28 on: April 14, 2017, 01:30:38 PM »
It just becomes a pain to insert the card a dozen of times

Here's my current solution for this.

nikfreak

  • Developer
  • Hero Member
  • *****
  • Posts: 944
Re: Intercepting DebugMsg with cache hacks
« Reply #29 on: April 14, 2017, 03:44:48 PM »
Houston, we've got a malloc problem and that only with the lossless DNG option, rest is fine:

70D.112 & 100D.101

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 9831
  • 5D Mark Free
Re: Intercepting DebugMsg with cache hacks
« Reply #30 on: April 14, 2017, 05:33:58 PM »
This should help: https://bitbucket.org/hudson/magic-lantern/commits/05a3127230a07ceefabaa45c870739c5460e4945?at=crop_rec_4k

(the same steps should work just fine on the crop_rec_4k branch)

dfort

  • Hero Member
  • *****
  • Posts: 1590
Re: Intercepting DebugMsg with cache hacks
« Reply #31 on: April 15, 2017, 12:05:22 AM »
(the same steps should work just fine on the crop_rec_4k branch)

You mean the same steps should work on the compressed_raw branch?

Last time I checked, full res silent lossless compressed DNG (that was a mouthful) wasn't working on the crop_rec_4k branch. The files were being created but the files were way too small and would not open with any of the raw editing programs I've got. Mainly Adobe Camera Raw and dcraw.
EOSM.202 EOSM.203 EOSM2.103 700D.115 5D3.*

Ant123

  • Freshman
  • **
  • Posts: 65
Re: Intercepting DebugMsg with cache hacks
« Reply #32 on: April 15, 2017, 12:09:09 AM »
Can anybody post here logs containing UHS-SD initialisation messages(like there)

nikfreak

  • Developer
  • Hero Member
  • *****
  • Posts: 944
Re: Intercepting DebugMsg with cache hacks
« Reply #33 on: April 15, 2017, 12:40:25 AM »
70D.112 & 100D.101

dfort

  • Hero Member
  • *****
  • Posts: 1590
Re: Intercepting DebugMsg with cache hacks
« Reply #34 on: April 16, 2017, 07:58:28 AM »
Now compile ML core and the silent picture module, place them on the card, and take a full-res silent picture with lossless compression (so the routine we have modified will get called in a quiet context - with LiveView turned off).

Not sure how to shoot a silent full resolution picture with LiveView turned off but I did manage to capture a dm-0000.log file on the 5D3.123 starting from the compressed_raw branch.

Code: [Select]
B0B0A> shoot_task:000af81c:00:00: *** register_interrupt("Jp57IntrHandler", 0xa3, 0xff291e2c, 0x0), from ff3dcc78
B10AE> shoot_task:ff3dd01c:16:03: [TTL] START WR1:0x18800064 WR2:0x15a0c000
B10DA> shoot_task:ff3dd048:16:03: [TTL] START RD1:0x86051a8 RD2:0xad24490
CDF6B> **INT-A3h*:ff3dcc08:16:03: [TTL][0,0,0] JpCoreCompleteCBR( 0x1327926 )
CDFAA> **INT-83h*:00a12858:00:00: LosslessCompleteCBR

Switching over to the 700D I got the Malloc error that @nikfreak pointed out and no log saved. Next I tried silent.c from the crop_rec_4k branch but that gave the same errors that I reported back in Reply #31 on the 5D3.123 with the crop_rec_4k branch. A screenshot is probably worth more than any description I can come up with:



Then I tried applying just the changes in the commit that @a1ex pointed out but ended up with the same results. On the 700D it results in a system freeze that requires a battery pull. No log or DNG file saved.
EOSM.202 EOSM.203 EOSM2.103 700D.115 5D3.*

a1ex

  • Administrator
  • Hero Member
  • *****
  • Posts: 9831
  • 5D Mark Free
Re: Intercepting DebugMsg with cache hacks
« Reply #35 on: April 21, 2017, 11:44:43 PM »
Last time I checked, full res silent lossless compressed DNG (that was a mouthful) wasn't working on the crop_rec_4k branch.

Hopefully fixed.