dm-spy-extra.c
/**
* Some extra logging functions via DebugMsg.
* It traces user-defined function calls, such as TryPostEvent, state objects, EDMAC and whatever else you throw at it.
*
* Includes a generic logging function => simply plug the addresses into logged_functions[] and should be ready to go.
*
* TODO:
* - move to module? (I also need it as core functionality, for researching the startup process)
* - import the patched addresses from stubs
*/
#include "dryos.h"
#include "gdb.h"
#include "patch.h"
#include "state-object.h"
#include "asm.h"
#include "cache_hacks.h"
#include "console.h"
#include "edmac.h"
#include "timer.h"
#include "propvalues.h"
#include "dm-spy.h"
#include "backtrace.h"
#include "io_trace.h"
/* this needs pre_isr_hook/post_isr_hook stubs */
#undef LOG_INTERRUPTS
/* delay mpu_send calls, to allow grouping MPU messages by timestamps */
#undef MPU_DELAY_SEND
/* log calls to malloc, AllocateMemory, alloc_dma_memory */
#undef LOG_MALLOC_CALLS
/* log some common function calls that are usually in RAM */
#undef LOG_COMMON_RAM_FUNCTIONS
extern void (*pre_isr_hook)();
extern void (*post_isr_hook)();
static void generic_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void mmio_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void state_transition_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void CreateResLockEntry_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void LockEngineResources_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void UnLockEngineResources_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void fps_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void LockEngineResources_log_r4(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void UnLockEngineResources_log_r7(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void engio_write_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void engdrvbits_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void mpu_send_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void mpu_recv_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void register_interrupt_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void eeko_wakeup_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void SetEDmac_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void StartEDmac_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
static void TryPostEvent_log(uint32_t* regs, uint32_t* stack, uint32_t pc);
#define DM_OVERRIDE(field, new_value) \
do { \
struct debug_msg * dm = debug_get_last_block(); \
if (dm) dm->field = (new_value); \
} while (0)
struct logged_func
{
uint32_t addr; /* Logged address (usually at the start of the function; will be passed to gdb_add_watchpoint) */
const char * name; /* Breakpoint (function) name (optional, can be NULL) */
uint32_t args; /* Log function arguments, registers, return values etc */
patch_hook_function_cbr log_func; /* if generic_log is not enough, you may use a custom logging function */
};
/* for args: */
#define NUM_ARGS_MASK 0xF /* up to 15 function arguments */
#define R(i) (0x100 << i) /* log any registers */
#define RET (0x1000000) /* return value of the function */
#define PTR (0x2000000) /* attempt to identify interesting pointers */
#define BKT (0x4000000) /* call stack trace (backtrace) for this function */
/* helper to get a function address directly from stubs */
#define STUB_ENTRY(name, ...) { (uint32_t) &name, #name, ## __VA_ARGS__ }
#ifdef LOG_MALLOC_CALLS
extern thunk _malloc;
extern thunk _free;
extern thunk _AllocateMemory;
extern thunk _FreeMemory;
extern thunk _alloc_dma_memory;
extern thunk _free_dma_memory;
#endif
extern thunk _mpu_send;
extern thunk _mpu_recv;
static struct logged_func logged_functions[] = {
/* dummy entry, just to check cache conflicts */
{ (uint32_t) &DryosDebugMsg, "DebugMsg" },
/* MPU communication (all models) */
STUB_ENTRY(_mpu_send, 2, mpu_send_log),
STUB_ENTRY(_mpu_recv, 1, mpu_recv_log),
/* some common DIGIC V functions that are usually in RAM */
#ifdef LOG_COMMON_RAM_FUNCTIONS
#ifdef CONFIG_DIGIC_V
STUB_ENTRY(task_create, 5),
STUB_ENTRY(msleep, 1),
//STUB_ENTRY(take_semaphore, 2),
//STUB_ENTRY(give_semaphore, 1),
//STUB_ENTRY(msg_queue_post, 2),
//STUB_ENTRY(msg_queue_receive, 3),
STUB_ENTRY(ConnectReadEDmac, 2),
STUB_ENTRY(ConnectWriteEDmac, 2),
STUB_ENTRY(RegisterEDmacCompleteCBR, 3),
STUB_ENTRY(SetEDmac, 4, SetEDmac_log),
STUB_ENTRY(StartEDmac, 2, StartEDmac_log),
//STUB_ENTRY(AbortEDmac, 1),
#ifdef CONFIG_DMA_MEMCPY
STUB_ENTRY(dma_memcpy, 3),
#endif
STUB_ENTRY(SetTimerAfter, 4),
STUB_ENTRY(SetHPTimerAfterNow, 4),
STUB_ENTRY(SetHPTimerNextTick, 4),
STUB_ENTRY(CancelTimer, 1),
#endif /* CONFIG_DIGIC_V */
#endif /* LOG_COMMON_RAM_FUNCTIONS */
#ifdef LOG_MALLOC_CALLS
STUB_ENTRY(_malloc, 1 | RET),
STUB_ENTRY(_free, 1),
STUB_ENTRY(_AllocateMemory, 1 | RET),
STUB_ENTRY(_FreeMemory, 1),
STUB_ENTRY(_alloc_dma_memory, 1 | RET),
STUB_ENTRY(_free_dma_memory, 1),
#endif
#if 0
#ifdef CONFIG_DEBUG_INTERCEPT_STARTUP
#ifdef CONFIG_5D2
{ 0xff9b3cb4, "register_interrupt", 4, register_interrupt_log },
#if 0
//~ { 0xFF87284C, "dma_memcpy", 3 }, // conflicts with mpu_recv
{ 0xff9b989c, "TryPostEvent", 5, TryPostEvent_log },
{ 0xff9b8f24, "TryPostStageEvent", 5, TryPostEvent_log },
/* register-level SIO3/MREQ communication */
{ 0xFF99F318, "MREQ_ISR", 0 },
{ 0xFF99F330, "MREQ_C020302C", 1 },
{ 0xFF99F348, "MREQ_C022009C", 1 },
{ 0xFF99F36C, "MREQ_C0820304", 1 },
{ 0xFF99F3A8, "SIO3_ISR", 0 },
{ 0xFF99F3E4, "SIO3_C022009C", 1 },
{ 0xFF99F404, "SIO3_C0820304", 1 },
{ 0xFF99F658, "SIO3_recv", 1 },
{ 0xFF99F244, "MREQ_SIO3_get_data_to_send", 2 },
{ 0xFF99F418, "SIO3_get_data_to_send_ret", 1 },
{ 0xFF99F424, "SIO3_data_to_send", 1 },
{ 0xFF99F380, "MREQ_get_data_to_send_ret", 1 },
{ 0xFF99F38C, "MREQ_data_to_send", 1 },
#endif
#endif
#ifdef CONFIG_5D3_113
{ 0x83b8, "register_interrupt", 4, register_interrupt_log },
#endif
#ifdef CONFIG_5D3_123
//{ 0x17d54, "TryPostEvent", 5, TryPostEvent_log },
#endif
#ifdef CONFIG_6D /* 1.1.3 */
{ 0x39F04, "TryPostEvent", 5, TryPostEvent_log },
#endif
#ifdef CONFIG_60D
{ 0xFF0F8BA8, "evfComAct", 4 | BKT }
//~ { 0xFF1C8658, "CreateResLockEntry", 2, CreateResLockEntry_log },
//~ { 0xFF1C8B98, "LockEngineResources", 1, LockEngineResources_log },
//~ { 0xFF1C8CD4, "UnLockEngineResources", 1, UnLockEngineResources_log },
/* this conflicts with DebugMsg... not sure how to fix */
//~ { 0xFF1D68C0, "register_interrupt", 4, register_interrupt_log },
#endif
#ifdef CONFIG_700D
{ 0x13344, "register_interrupt", 4, register_interrupt_log },
#endif
#ifdef CONFIG_7D_203
{ 0xFF080094, "0xC0220024", R(0), mmio_log }, /* [GPIO] GPIO_9 (master woke up on 7D) at Startup:FF080090 (0x0)*/
#endif
#else /* not CONFIG_DEBUG_INTERCEPT_STARTUP */
#ifdef CONFIG_5D2
{ 0xff9b9198, "StateTransition", 4 , state_transition_log },
{ 0xff9b989c, "TryPostEvent", 5, TryPostEvent_log },
//~ { 0xff9b8f24, "TryPostStageEvent", 5, TryPostEvent_log }, // conflicts with SetHPTimerAfter
STUB_ENTRY(ConnectReadEDmac, 2),
STUB_ENTRY(ConnectWriteEDmac, 2),
STUB_ENTRY(RegisterEDmacCompleteCBR, 3),
//~ STUB_ENTRY(SetEDmac, 4, SetEDmac_log), // conflicts with RegisterHead1InterruptHandler
STUB_ENTRY(StartEDmac, 2, StartEDmac_log),
{ 0xff9b3cb4, "register_interrupt", 4, register_interrupt_log },
//~ { 0xffb277c8, "register_obinteg_cbr", 2 }, // conflicts with UnLockEngineResources
{ 0xffaf6930, "set_digital_gain_and_related", 3 },
//~ { 0xffaf68a4, "set_saturate_offset", 1 }, // conflicts with TryPostEvent
{ 0xffaf686c, "set_saturate_offset_2", 1 },
{ 0xff987200, "set_fps_maybe", 1, fps_log },
{ 0xffa38114, "set_fps_maybe_2", 1 },
{ 0xffa366c8, "AJ_FixedPoint_aglrw_related", 4 },
{ 0xffa37de4, "RegisterHead1InterruptHandler", 3 },
//~ { 0xff986d9c, "RegisterHead2InterruptHandler", 3 },
//~ { 0xff986ebc, "RegisterHead3InterruptHandler", 3 }, // conflicts with AJ_FixedPoint_aglrw_related
//~ { 0xff986f74, "RegisterHead4InterruptHandler", 3 },
{ 0xff86c720, "SetHPTimerAfter", 4 },
{ 0xff9a86e0, "LockEngineResources", 1, LockEngineResources_log },
{ 0xff9a87d0, "UnLockEngineResources", 1, UnLockEngineResources_log},
#endif
#ifdef CONFIG_60D
{ 0xFF1C8658, "CreateResLockEntry", 2, CreateResLockEntry_log },
{ 0xFF1C8B98, "LockEngineResources", 1, LockEngineResources_log },
{ 0xFF1C8CD4, "UnLockEngineResources", 1, UnLockEngineResources_log },
STUB_ENTRY(StartEDmac, 2, StartEDmac_log),
STUB_ENTRY(SetEDmac, 4, SetEDmac_log),
{ 0xFF06E534, "take_semaphore", 2 },
{ 0xFF06E61C, "give_semaphore", 1 },
{ 0xFF1C8C00, "resinfo_wait_smth", R(0) },
{ 0xFF1C8AC0, "resinfo_check", R(7) },
#endif
#ifdef CONFIG_550D
{ 0xff1d84f4, "StateTransition", 4 , state_transition_log },
{ 0xff1d8c30, "TryPostEvent", 5, TryPostEvent_log },
{ 0xff1d82b8, "TryPostStageEvent", 5, TryPostEvent_log },
STUB_ENTRY(ConnectReadEDmac, 2),
STUB_ENTRY(ConnectWriteEDmac, 2),
STUB_ENTRY(RegisterEDmacCompleteCBR, 3),
STUB_ENTRY(SetEDmac, 4, SetEDmac_log),
STUB_ENTRY(StartEDmac, 2, StartEDmac_log),
{ 0xff1d2944, "register_interrupt", 4, register_interrupt_log },
{ 0xff2806f8, "RegisterHead1InterruptHandler", 3 },
{ 0xFF068BB8, "SetHPTimerAfter", 4 },
{ 0xff1c4a34, "LockEngineResources", 1, LockEngineResources_log },
{ 0xff1c4618, "LockEngineResources_0", 1, LockEngineResources_log_r4 }, // note: hooking in the middle of the function to avoid conflict with engio_write
{ 0xff1c4794, "UnLockEngineResources", 1, UnLockEngineResources_log_r7}, // same here, for RegisterHead1InterruptHandler
#endif
#ifdef CONFIG_500D
{ 0xff1a62a0, "StateTransition", 4 , state_transition_log },
{ 0xff1a69a4, "TryPostEvent", 5, TryPostEvent_log },
{ 0xff1a602c, "TryPostStageEvent", 5, TryPostEvent_log },
STUB_ENTRY(ConnectReadEDmac, 2),
STUB_ENTRY(ConnectWriteEDmac, 2),
STUB_ENTRY(RegisterEDmacCompleteCBR, 3),
STUB_ENTRY(SetEDmac, 4, SetEDmac_log),
STUB_ENTRY(StartEDmac, 2, StartEDmac_log),
//~ { 0xff1a0b90, "register_interrupt", 4, register_interrupt_log }, // conflicts with ConnectReadEDmac
//~ { 0xff32646c, "register_obinteg_cbr", 2 }, // conflicts with set_digital_gain_and_related
{ 0xff2f6c7c, "set_digital_gain_and_related", 3 },
//~ { 0xff2f6bf0, "set_saturate_offset", 1 }, // conflicts with ConnectReadEDmac
{ 0xff2f6bb8, "set_saturate_offset_2", 1 },
{ 0xff171e94, "set_fps_maybe", 1, fps_log },
{ 0xff23180c, "set_fps_maybe_2", 1 },
//~ { 0xff2302a8, "AJ_FixedPoint_aglrw_related", 4 }, // conflicts with StateTransition
{ 0xff2314ac, "RegisterHead1InterruptHandler", 3 },
//~ { 0xff1719a0, "RegisterHead2InterruptHandler", 3 }, // conflicts with TryPostEvent
{ 0xff171acc, "RegisterHead3InterruptHandler", 3 },
//~ { 0xff171b84, "RegisterHead4InterruptHandler", 3 }, // conflicts with ConnectReadEDmac
{ 0xFF068268, "SetHPTimerAfter", 4 },
{ 0xff194190, "LockEngineResources", 1, LockEngineResources_log },
{ 0xff193ed0, "UnLockEngineResources", 1, UnLockEngineResources_log},
#endif
#ifdef CONFIG_5D3_113
{ 0x83b8, "register_interrupt", 4, register_interrupt_log },
{ 0x178ec, "StateTransition", 4 , state_transition_log },
{ 0xFF290B94, "CreateResLockEntry", 2, CreateResLockEntry_log },
{ 0xFF29105C, "LockEngineResources", 1, LockEngineResources_log },
{ 0xFF291200, "UnLockEngineResources", 1, UnLockEngineResources_log },
{ 0x17d54, "TryPostEvent", 5, TryPostEvent_log },
{ 0x17674, "TryPostStageEvent", 5, TryPostEvent_log },
{ 0x4588, "SetTgNextState", 2 },
//~ { 0xFF6B4E2C, "DryEFatFormat", 7 },
//~ { 0xFF729BDC, "sd_choose_filesystem", 2 },
//~ { 0xFF729FC4, "sd_choose_filesystem_ret", 1 },
//~ { 0xFF508F78, "Eeko WakeUp", 0, eeko_wakeup_log },
#endif
#ifdef CONFIG_5D3_123
{ 0x178ec, "StateTransition", 4 , state_transition_log },
{ 0x17d54, "TryPostEvent", 5, TryPostEvent_log },
{ 0x17674, "TryPostStageEvent", 5, TryPostEvent_log },
{ 0x83b8, "register_interrupt", 4, register_interrupt_log },
//~ { 0xff3aa650, "set_digital_gain_maybe", 3 },
//~ { 0xff4fa6ac, "set_fps_maybe", 1, fps_log },
//~ { 0xff2170d8, "SetSsgVsize_fps_timer_B", 1 },
//~ { 0x4588, "SetTgNextState", 2 },
{ 0xff216a20, "RegisterHead1InterruptHandler", 3 },
{ 0xff4fa16c, "RegisterHead2InterruptHandler", 3 },
//~ { 0xff4fa224, "RegisterHead3InterruptHandler", 3 }, /* conflicts with RegisterHead1InterruptHandler */
{ 0xff4fa4ec, "RegisterHead4InterruptHandler", 3 },
{ 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 },
/* only EngDrvOuts is verbose, no need to log it here */
//~ { 0xFF694880, "eeko_setup_global_vars", 10 },
//~ { 0xFF69518C, "eeko_prepare_dsunpack", 3 },
//~ { 0xFF6950BC, "eeko_prepare_adunpack", 3 },
//~ { 0xFF695124, "eeko_prepare_unpack24", 3 },
//~ { 0xFF695D50, "eeko_setup_shad", 2 },
//~ { 0xFF694DE4, "PathDrv_EekoAddRawPathCore.c", 4 },
//~ { 0xFF694C88, "eeko_setup_twoadd", 3 },
//~ { 0xFF694A04, "PathDrv_EekoAddRawPathCore.c_div8", 4 },
#endif
#endif
#endif
};
/* format arg to string and try to guess its type, with snprintf-like usage */
/* (string, ROM function name or regular number) */
static int snprintf_guess_arg(char* buf, int maxlen, uint32_t arg)
{
if (looks_like_string(arg))
{
return snprintf(buf, maxlen, "\"%s\"", arg);
}
else if (is_sane_ptr(arg) && looks_like_string(MEM(arg)))
{
return snprintf(buf, maxlen, "&\"%s\"", MEM(arg));
}
else
{
char* guessed_name = 0;
/* ROM function? try to guess its name */
/* todo: also for RAM functions (how to recognize them quickly?) */
if ((arg & 0xF0000000) == 0xF0000000)
{
guessed_name = asm_guess_func_name_from_string(arg);
}
if (guessed_name && guessed_name[0])
{
return snprintf(buf, maxlen, "0x%x \"%s\"", arg, guessed_name);
}
else
{
return snprintf(buf, maxlen, "0x%x", arg);
}
}
}
static uint32_t last_result_pc = 0;
/* temporary hook, for logging the return value of a function */
static void result_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
DryosDebugMsg(0, 0, "==> 0x%x", regs[0]);
DM_OVERRIDE(pc, pc - 4);
/* we can't disable this hook right now, as it's still executing */
/* workaround: we'll just disable the previous one */
if (last_result_pc)
{
unpatch_memory(last_result_pc);
}
last_result_pc = pc;
}
static void generic_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
uint32_t args = 0;
int num_args = 0;
int log_result = 0;
const char * func_name = 0;
for (int i = 0; i < COUNT(logged_functions); i++)
{
if (logged_functions[i].addr == pc)
{
args = logged_functions[i].args;
func_name = logged_functions[i].name;
break;
}
}
num_args = args & NUM_ARGS_MASK;
log_result = args & RET;
/* this is too large to be placed on the stack (init_task) */
/* allocate it statically and guard it with cli/sei */
static char msg[200];
int old = cli();
int len = (func_name)
? snprintf(msg, sizeof(msg), "*** %s(", func_name)
: snprintf(msg, sizeof(msg), "*** FUNC(%x)(", pc);
int first_arg = 1;
for (int i = 0; i < num_args; i++)
{
uint32_t arg = (i < 4) ? regs[i] : stack[i-4];
if (!first_arg) len += snprintf(msg + len, sizeof(msg) - len, ", ");
len += snprintf_guess_arg(msg + len, sizeof(msg) - len, arg);
first_arg = 0;
}
for (int reg = 0; reg < 13; reg++)
{
if (args & R(reg))
{
if (!first_arg) len += snprintf(msg + len, sizeof(msg) - len, ", ");
len += snprintf(msg + len, sizeof(msg) - len, "R%d=%x", reg, regs[reg]);
first_arg = 0;
}
}
len += snprintf(msg + len, sizeof(msg) - len, ")");
DryosDebugMsg(0, 0, "%s", msg);
DM_OVERRIDE(pc, PATCH_HOOK_CALLER());
sei(old);
if (args & PTR)
{
for (int i = 0; i < num_args + 13; i++)
{
uint32_t arg = (i < 4) ? regs[i] : stack[i-4];
if (i >= num_args)
{
int reg = i - num_args;
if (args & R(reg)) {
arg = regs[reg];
} else {
continue;
}
}
if (arg > 0x1000 && arg < 0x1000000 && !looks_like_string(arg))
{
DryosDebugMsg(0, 0,
" *0x%x = { %x %x %x %x %x %x %x %x %x %x %x %x ... }", arg,
MEM(arg), MEM(arg+4), MEM(arg+8), MEM(arg+12),
MEM(arg+16), MEM(arg+20), MEM(arg+24), MEM(arg+28),
MEM(arg+32), MEM(arg+36), MEM(arg+40), MEM(arg+44)
);
}
}
}
if (last_result_pc)
{
unpatch_memory(last_result_pc);
last_result_pc = 0;
}
if (log_result)
{
int err = patch_hook_function(
regs[13], MEM(regs[13]), /* LR */
result_log, "result_log"
);
if (err)
{
DryosDebugMsg(0, 0, "!!! cannot log return value (err %x)", err);
}
}
if (args & BKT)
{
static char msg[512];
backtrace_getstr(msg, sizeof(msg));
debug_log_line(msg);
}
}
/* we want this to work very early in the boot process; snprintf not available */
static void mmio_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
uint32_t caller = PATCH_HOOK_CALLER();
uint32_t args = 0;
const char * func_name = 0;
/* fixme: might be slow with many entries */
for (int i = 0; i < COUNT(logged_functions); i++)
{
if (logged_functions[i].addr == pc)
{
args = logged_functions[i].args;
func_name = logged_functions[i].name;
break;
}
}
uint32_t old = cli();
uint32_t us_timer = MEM(0xC0242014);
debug_loghex2(us_timer, 5);
debug_logstr("> [MMIO] ");
/* func_name is actually register name */
debug_logstr(func_name);
debug_logstr(": ");
int first_arg = 1;
for (int reg = 0; reg < 13; reg++)
{
if (args & R(reg))
{
if (!first_arg) debug_logstr(", ");
char regstr[] = "Rx=";
regstr[1] = '0' + reg;
debug_logstr(regstr);
debug_loghex(regs[reg]);
first_arg = 0;
}
}
debug_logstr(", from ");
if (current_task)
{
debug_logstr(current_task->name);
debug_logstr(":");
}
debug_loghex(pc);
debug_logstr(":");
debug_loghex(caller);
debug_logstr("\n");
sei(old);
}
static void state_transition_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
struct state_object * state = (void*) regs[0];
int old_state = state->current_state;
char* state_name = (char*) state->name;
int input = regs[2];
int next_state = state->state_matrix[old_state + state->max_states * input].next_state;
uint32_t next_function = (uint32_t) state->state_matrix[old_state + state->max_states * input].state_transition_function;
/* function name is on the next line, no need to print it here */
DryosDebugMsg(0, 0,
"*** %s: (%d) --%d--> (%d) "
"%x (x=%x z=%x t=%x)", state_name, old_state, input, next_state,
next_function, regs[1], regs[3], stack[0]
);
DM_OVERRIDE(pc, PATCH_HOOK_CALLER());
}
static void EngineResources_list(uint32_t* resIds, int resNum)
{
for (int i = 0; i < resNum; i++)
{
uint32_t class = resIds[i] & 0xFFFF0000;
uint32_t entry = resIds[i] & 0x0000FFFF;
char* desc =
class == 0x00000000 ? "write channel 0x%x" :
class == 0x00010000 ? "read channel 0x%x" :
class == 0x00020000 ? "write connection 0x%x" :
class == 0x00030000 ? "read connection 0x%x" :
class == 0x00110000 ? "%sPBAccessHandle" :
"?";
uint32_t arg =
class == 0x00000000 ? edmac_index_to_channel(entry, EDMAC_DIR_WRITE) :
class == 0x00010000 ? edmac_index_to_channel(entry, EDMAC_DIR_READ) :
class == 0x00110000 ? (uint32_t)(entry ? "Bitmap" : "Image") :
entry;
if (strchr(desc, '%'))
{
char msg[100];
snprintf(msg, sizeof(msg), desc, arg);
DryosDebugMsg(0, 0, " %2d) %8x (%s)", (i+1), resIds[i], msg);
}
else
{
DryosDebugMsg(0, 0, " %2d) %8x (%s)", (i+1), resIds[i], desc);
}
}
}
static void CreateResLockEntry_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
uint32_t* resIds = (void*) regs[0];
int resNum = regs[1];
DryosDebugMsg(0, 0, "*** CreateResLockEntry(%x, %d)", resIds, resNum);
DM_OVERRIDE(pc, PATCH_HOOK_CALLER());
EngineResources_list(resIds, resNum);
}
static void LockEngineResources_log_base(uint32_t* regs, char* name, uint32_t* arg0)
{
uint32_t* resLock = arg0;
uint32_t* resIds = (void*) resLock[5];
int resNum = resLock[6];
DryosDebugMsg(0, 0, "*** %s(%x) x%d:", name, resLock, resNum);
DM_OVERRIDE(pc, PATCH_HOOK_CALLER());
EngineResources_list(resIds, resNum);
}
static void LockEngineResources_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
LockEngineResources_log_base(regs, "LockEngineResources", (void*) regs[0]);
}
static void UnLockEngineResources_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
LockEngineResources_log_base(regs, "UnLockEngineResources", (void*) regs[0]);
}
static void LockEngineResources_log_r4(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
LockEngineResources_log_base(regs, "LockEngineResources", (void*) regs[4]);
}
static void UnLockEngineResources_log_r7(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
LockEngineResources_log_base(regs, "UnLockEngineResources", (void*) regs[7]);
}
static void fps_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
/* log the original call as usual */
generic_log(regs, stack, pc);
/* force very slow FPS to avoid lockup */
regs[0] = 8191;
}
static void engio_write_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
uint32_t* data_buf = (uint32_t*) regs[0];
DryosDebugMsg(0, 0, "*** engio_write(%x):", data_buf);
DM_OVERRIDE(pc, PATCH_HOOK_CALLER());
/* log all ENGIO register writes */
while(*data_buf != 0xFFFFFFFF)
{
uint32_t reg = *data_buf;
data_buf++;
uint32_t val = *data_buf;
data_buf++;
DryosDebugMsg(0, 0, " 0x%x: %x", reg, val);
}
}
static void engdrvbits_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
DryosDebugMsg(0, 0, "*** EngDrvBits(0x%x, 0x%08x, 0x%x) => 0x%x", regs[0], regs[1], regs[2], shamem_read(regs[0]));
DM_OVERRIDE(pc, PATCH_HOOK_CALLER());
}
static void mpu_decode(char* in, char* out, int max_len)
{
int len = 0;
int size = in[0];
/* print each byte as hex */
for (char* c = in; c < in + size; c++)
{
len += snprintf(out+len, max_len-len, "%02x ", *c);
}
/* trim the last space */
if (len) out[len-1] = 0;
}
static volatile int last_mpu_timestamp = 0;
static void mpu_send_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
#ifdef MPU_DELAY_SEND
if (MPU_DELAY_SEND)
{
/* wait 10ms after the last mpu_send/recv
* (related messages usually arrive at less than 1ms apart)
* note: during a mpu_send (usually called from PropMgr),
* mpu_recv may be called from other tasks;
* we'll wait until mpu_recv activity calms down for 10ms.
*/
int l, t;
do
{
/* for some reason, msleep here appears to disturb the startup process */
/* busy waiting appears fine though */
/* for thread safety, timer must be read after last_mpu_timestamp */
/* assume int assignments are atomic and not reordered */
/* => even if a context switch happens between them, t will be >= l. */
/* to test: swap the two assignments => a few loops will stop too early (t < l) */
l = last_mpu_timestamp;
t = MEM(0xC0242014);
}
while (MOD(t - l, 0x100000) < 10000);
//~ DryosDebugMsg(0, 0, "*** mpu wait (%d)", t - l);
}
#endif
char* buf = (char*) regs[0];
int size = regs[1]; /* message size */
int size_ex = (size + 2) & 0xFE; /* packet size, prepended to the message */
/* must be multiple of 2, so it's either size+1 or size+2 */
char msg[256];
mpu_decode(buf, msg, sizeof(msg));
DryosDebugMsg(0, 0, "*** mpu_send(%02x %s)", size_ex, msg);
DM_OVERRIDE(pc, PATCH_HOOK_CALLER());
last_mpu_timestamp = MEM(0xC0242014);
}
static void mpu_recv_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
char* buf = (char*) regs[0];
int size = buf[-1];
char msg[256];
mpu_decode(buf, msg, sizeof(msg));
DryosDebugMsg(0, 0, "*** mpu_recv(%02x %s)", size, msg);
DM_OVERRIDE(pc, PATCH_HOOK_CALLER());
last_mpu_timestamp = MEM(0xC0242014);
}
static void eeko_dump()
{
/* RAM (overlaps 2 memory regions) */
dump_seg((void*)0x1E00000, 0x120000, "1E00000.DMP");
/* Shared memory? (configured as I/O) */
dump_seg((void*)0x1F20000, 0x020000, "1F20000.DMP");
/* reading from 0xD028[08]000 results in camera lockup;
* let's use EekoBltDmac to copy the contents to main memory */
void (*EekoBltDmac_copy)(int zero, uint32_t dst, uint32_t src, uint32_t size, void* cbr, int arg)
= (void*) 0xFF3B940C; /* 5D3 1.1.3 */
void * buf = malloc(0x8000);
if (buf)
{
/* RAM (mapped to 0) */
EekoBltDmac_copy(0, (uint32_t)buf, 0xD0288000, 0x8000, ret_0, 0);
msleep(100);
dump_seg(buf, 0x8000, "D0288000.DMP");
/* TCM (mapped to 0x40000000) */
EekoBltDmac_copy(0, (uint32_t)buf, 0xD0280000, 0x4000, ret_0, 0);
msleep(100);
dump_seg(buf, 0x4000, "D0280000.DMP");
free(buf);
}
}
static void eeko_wakeup_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
DryosDebugMsg(0, 0, "*** Eeko about to wake up; dumping RAM...");
DM_OVERRIDE(pc, PATCH_HOOK_CALLER());
eeko_dump();
}
static void SetEDmac_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
/* we will want two messages together */
uint32_t old = cli();
/* log the original call as usual */
generic_log(regs, stack, pc);
struct edmac_info * edmac_info = (struct edmac_info *) regs[2];
if (edmac_info)
{
char * size_fmt = edmac_format_size(edmac_info);
DryosDebugMsg(0, 0, " size %s", size_fmt ? size_fmt : "(please load edmac.mo)");
}
sei(old);
}
static void StartEDmac_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
/* we will want two messages together */
uint32_t old = cli();
/* log the original call as usual */
generic_log(regs, stack, pc);
int ch = regs[0];
struct edmac_info edmac_info = edmac_get_info(ch);
char * size_fmt = edmac_format_size(&edmac_info);
uint32_t edmac_address = edmac_get_address(ch);
io_trace_pause();
uint32_t edmac_pointer = edmac_get_pointer(ch);
io_trace_resume();
DryosDebugMsg(0, 0,
" addr %x, ptr %x, size %s",
edmac_address, edmac_pointer,
size_fmt ? size_fmt : "(please load edmac.mo)"
);
DM_OVERRIDE(pc, PATCH_HOOK_CALLER());
sei(old);
}
static void TryPostEvent_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
const char * class = (const char *) MEM(regs[0]);
const char * event_prefix =
streq(class, "StageClass") ? "Stage" :
streq(class, "TaskClass" ) ? "" :
class ;
DryosDebugMsg(0, 0,
"*** TryPost%sEvent(%s, 0x%x, 0x%x, 0x%x)",
event_prefix,
MEM(regs[1]), regs[2], regs[3], MEM(stack)
);
DM_OVERRIDE(pc, PATCH_HOOK_CALLER());
}
static char* isr_names[0x200] = {
[0x0A] = "Timer",
[0x10] = "HPTimer",
[0x2E] = "Term-RD",
[0x3A] = "Term-WR",
[0x34] = "SIO1",
[0x35] = "SIO2",
[0x36] = "SIO3",
[0x50] = "MREQ",
[0x2f] = "DMA1",
[0x74] = "DMA2",
[0x75] = "DMA3",
[0x76] = "DMA4",
/* sorry, couldn't get dynamic code
* to run without stack overflows...
* (list autogenerated from qemu)
*/
[0x58] = "EDMAC#0",
[0x59] = "EDMAC#1",
[0x5A] = "EDMAC#2",
[0x5B] = "EDMAC#3",
[0x5C] = "EDMAC#4",
[0x6D] = "EDMAC#5",
[0xC0] = "EDMAC#6",
[0x5D] = "EDMAC#8",
[0x5E] = "EDMAC#9",
[0x5F] = "EDMAC#10",
[0x6E] = "EDMAC#11",
[0xC1] = "EDMAC#12",
[0xC8] = "EDMAC#13",
[0xF9] = "EDMAC#16",
[0x83] = "EDMAC#17",
[0x8A] = "EDMAC#18",
[0xCA] = "EDMAC#19",
[0xCB] = "EDMAC#20",
[0xD2] = "EDMAC#21",
[0xD3] = "EDMAC#22",
[0x8B] = "EDMAC#24",
[0x92] = "EDMAC#25",
[0xE2] = "EDMAC#26",
[0x95] = "EDMAC#27",
[0x96] = "EDMAC#28",
[0x97] = "EDMAC#29",
[0xDA] = "EDMAC#32",
[0xDB] = "EDMAC#33",
[0x9D] = "EDMAC#40",
[0x9E] = "EDMAC#41",
[0x9F] = "EDMAC#42",
[0xA5] = "EDMAC#43",
};
static void register_interrupt_log(uint32_t* regs, uint32_t* stack, uint32_t pc)
{
/* log the original call as usual */
generic_log(regs, stack, pc);
/* store the interrupt name */
int isr = regs[1];
char* name = (char*) regs[0];
if (name && !isr_names[isr & 0x1FF])
{
isr_names[isr & 0x1FF] = name;
}
}
/* don't use snprintf in interrupts - it's a little heavy
* most interrupts are fine with it, but a few are tricky */
static const char * interrupt_name(int i)
{
static char name[] = "INT-00h";
int i0 = (i & 0xF);
int i1 = (i >> 4) & 0xF;
int i2 = (i >> 8) & 0xF;
name[3] = i2 ? '0' + i2 : '-';
name[4] = i1 < 10 ? '0' + i1 : 'A' + i1 - 10;
name[5] = i0 < 10 ? '0' + i0 : 'A' + i0 - 10;
return name;
}
static void pre_isr_log(uint32_t isr)
{
/* not sure about all models, only checked 5D2, 60D and 5D3 */
#ifdef CONFIG_DIGIC_V
uint32_t handler = MEM(0x40000000 + 4*isr);
uint32_t arg = MEM(0x40000800 + 4*isr);
#else
uint32_t handler = MEM(0x400006F8 + 4*isr);
uint32_t arg = MEM(0x40000AF8 + 4*isr);
#endif
char* name = isr_names[isr & 0x1FF];
uint32_t old = cli();
debug_logstr(">>> ");
debug_logstr(interrupt_name(isr));
debug_logstr(" ");
debug_logstr(name);
debug_logstr(" ");
debug_loghex(handler);
debug_logstr("(");
debug_loghex(arg);
debug_logstr(")\n");
/* set context (what task was interrupted) */
/* fixme: only correct for first-level interrupts and likely only on specific models */
struct debug_msg * dm = debug_get_last_block();
if (dm)
{
dm->pc = MEM(0xFFC);
dm->task_name = current_task->name;
qprintf(">>> interrupted %s:%x\n", dm->task_name, dm->pc);
}
#if 1
if (name)
{
if (strncmp(name, "EDMAC#", 6) == 0)
{
int ch = atoi(name + 6);
struct edmac_info edmac_info = edmac_get_info(ch);
debug_logstr(" addr ");
debug_loghex(edmac_get_address(ch));
debug_logstr(", ptr ");
io_trace_pause();
debug_loghex(edmac_get_pointer(ch));
io_trace_resume();
debug_logstr(", size ");
char * size_fmt = edmac_format_size(&edmac_info);
debug_logstr(size_fmt ? size_fmt : "(please load edmac.mo)");
debug_logstr(", flags ");
debug_loghex(edmac_get_flags(ch));
debug_logstr("\n");
struct debug_msg * dm = debug_get_last_block();
if (dm)
{
dm->pc = MEM(0xFFC);
dm->task_name = current_task->name;
}
}
}
#endif
sei(old);
}
static void post_isr_log(uint32_t isr)
{
uint32_t old = cli();
debug_logstr("<<< ");
debug_logstr(interrupt_name(isr));
debug_logstr(" done\n");
/* set context (what task we are going to return to) */
/* fixme: how to find it? the task switch logic appears to be after this hook */
struct debug_msg * dm = debug_get_last_block();
if (dm)
{
dm->pc = MEM(0xFFC);
dm->task_name = current_task->name;
qprintf("<<< return to %s:%x\n", dm->task_name, dm->pc);
}
sei(old);
}
static int check_no_conflicts(int i)
{
#ifdef CONFIG_QEMU
/* you can safely log conflicting addresses from QEMU */
return 1;
#endif
/* two memory addresses can't be patched at the same time if their index bits are the same */
/* fixme: hardcoded masks */
int index_mask = 0x7E0;
/* but if the higher bits are identical, it's all fine */
int high_mask = 0xFFFFF800;
int a = logged_functions[i].addr;
if (!IS_ROM_PTR(a))
{
/* this function is patched in RAM - no cache conflicts possible */
return 1;
}
for (int j = 0; j < i; j++)
{
int b = logged_functions[j].addr;
if (!IS_ROM_PTR(b))
{
/* this function is patched in RAM - no cache conflicts possible */
continue;
}
if (((a & index_mask) == (b & index_mask)) && ((a & high_mask) != (b & high_mask)))
{
#if 0
/* for debugging in QEMU (without CONFIG_QEMU=y), see qemu-util.h */
/* with CONFIG_QEMU=y we don't have cache conflicts */
MEM(0xCF12300C) = logged_functions[i].addr;
MEM(0xCF12300C) = logged_functions[j].addr;
while(1);
#endif
console_show();
printf("Birthday paradox: %x %s\n"
" conflicts with: %x %s.\n",
logged_functions[i].addr, logged_functions[i].name,
logged_functions[j].addr, logged_functions[j].name
);
return 0;
}
}
/* all fine; let's also check the other cache patches, unrelated to our hooks */
if (!cache_locked())
{
/* no conflicts possible */
return 1;
}
if (cache_is_patchable(logged_functions[i].addr, TYPE_ICACHE, 0))
{
/* seems OK */
return 1;
}
/* NOK, conflict with some other patch */
console_show();
printf("%x %s not patchable.\n", logged_functions[i].addr, logged_functions[i].name);
return 0;
}
void dm_spy_extra_install()
{
printf("ICache: %db, idx=%x tag=%x word=%x seg=%x\n",
1<<CACHE_SIZE_BITS(TYPE_ICACHE),
CACHE_INDEX_ADDRMASK(TYPE_ICACHE),
CACHE_TAG_ADDRMASK(TYPE_ICACHE),
CACHE_WORD_ADDRMASK(TYPE_ICACHE),
CACHE_SEGMENT_ADDRMASK(TYPE_ICACHE)
);
/* note: first entry is DebugMsg */
for (int i = 1; i < COUNT(logged_functions); i++)
{
if (logged_functions[i].addr)
{
if (check_no_conflicts(i))
{
patch_hook_function(
logged_functions[i].addr, MEM(logged_functions[i].addr),
logged_functions[i].log_func ? logged_functions[i].log_func : generic_log,
logged_functions[i].name
);
}
}
}
#ifdef LOG_INTERRUPTS
pre_isr_hook = &pre_isr_log;
post_isr_hook = &post_isr_log;
ASSERT((void*)&post_isr_hook - (void*)&pre_isr_hook == 4);
#endif
}
void dm_spy_extra_uninstall()
{
for (int i = 1; i < COUNT(logged_functions); i++)
{
unpatch_memory(logged_functions[i].addr);
}
#ifdef LOG_INTERRUPTS
pre_isr_hook = 0;
post_isr_hook = 0;
#endif
}
