307 lines
12 KiB
C
307 lines
12 KiB
C
#include <ultra64.h>
|
|
|
|
#include "sm64.h"
|
|
#include "profiler.h"
|
|
#include "game_init.h"
|
|
|
|
s16 gProfilerMode = 0;
|
|
|
|
// the thread 3 info is logged on the opposite profiler from what is used by
|
|
// the thread4 and 5 loggers. It's likely because the sound thread runs at a
|
|
// much faster rate and shouldn't be flipping the index for the "slower" game
|
|
// threads, which could leave the frame data in a possibly corrupt or incomplete
|
|
// state.
|
|
s16 gCurrentFrameIndex1 = 1;
|
|
s16 gCurrentFrameIndex2 = 0;
|
|
|
|
struct ProfilerFrameData gProfilerFrameData[2];
|
|
|
|
// log the current osTime to the appropriate idx for current thread5 processes.
|
|
void profiler_log_thread5_time(enum ProfilerGameEvent eventID) {
|
|
gProfilerFrameData[gCurrentFrameIndex1].gameTimes[eventID] = osGetTime();
|
|
|
|
// event ID 4 is the last profiler event for after swapping
|
|
// buffers: switch the Info after updating.
|
|
if (eventID == THREAD5_END) {
|
|
gCurrentFrameIndex1 ^= 1;
|
|
gProfilerFrameData[gCurrentFrameIndex1].numSoundTimes = 0;
|
|
}
|
|
}
|
|
|
|
// log the audio system before and after osTimes in pairs to the soundTimes array.
|
|
void profiler_log_thread4_time(void) {
|
|
struct ProfilerFrameData *profiler = &gProfilerFrameData[gCurrentFrameIndex1];
|
|
|
|
if (profiler->numSoundTimes < ARRAY_COUNT(profiler->soundTimes)) {
|
|
profiler->soundTimes[profiler->numSoundTimes++] = osGetTime();
|
|
}
|
|
}
|
|
|
|
// log the times for gfxTimes: RSP completes, and RDP completes.
|
|
void profiler_log_gfx_time(enum ProfilerGfxEvent eventID) {
|
|
if (eventID == 0) {
|
|
gCurrentFrameIndex2 ^= 1;
|
|
gProfilerFrameData[gCurrentFrameIndex2].numVblankTimes = 0;
|
|
}
|
|
|
|
gProfilerFrameData[gCurrentFrameIndex2].gfxTimes[eventID] = osGetTime();
|
|
}
|
|
|
|
// log the times between vblank started and ended.
|
|
void profiler_log_vblank_time(void) {
|
|
struct ProfilerFrameData *profiler = &gProfilerFrameData[gCurrentFrameIndex2];
|
|
|
|
if (profiler->numVblankTimes < ARRAY_COUNT(profiler->vblankTimes)) {
|
|
profiler->vblankTimes[profiler->numVblankTimes++] = osGetTime();
|
|
}
|
|
}
|
|
|
|
// draw the specified profiler given the information passed.
|
|
void draw_profiler_bar(OSTime clock_base, OSTime clock_start, OSTime clock_end, s16 pos_y, u16 color) {
|
|
s64 duration_start, duration_end;
|
|
s32 rect_x1, rect_x2;
|
|
|
|
// set the duration to start, and floor to 0 if the result is below 0.
|
|
if ((duration_start = clock_start - clock_base) < 0) {
|
|
duration_start = 0;
|
|
}
|
|
// like the above, but with end.
|
|
if ((duration_end = clock_end - clock_base) < 0) {
|
|
duration_end = 0;
|
|
}
|
|
|
|
// calculate the x coordinates of where start and end begins, respectively.
|
|
rect_x1 = ((((duration_start * 1000000) / osClockRate * 3) / 1000) + 30);
|
|
rect_x2 = ((((duration_end * 1000000) / osClockRate * 3) / 1000) + 30);
|
|
|
|
//! I believe this is supposed to cap rect_x1 and rect_x2 to 320, but the
|
|
// code seems to use the wrong variables... it's possible that the variable
|
|
// names were very similar within a single letter.
|
|
if (rect_x1 > 319) {
|
|
clock_start = 319;
|
|
}
|
|
if (rect_x2 > 319) {
|
|
clock_end = 319;
|
|
}
|
|
|
|
// perform the render if start is less than end. in most cases, it should be.
|
|
if (rect_x1 < rect_x2) {
|
|
gDPPipeSync(gDisplayListHead++);
|
|
gDPSetFillColor(gDisplayListHead++, color << 16 | color);
|
|
gDPFillRectangle(gDisplayListHead++, rect_x1, pos_y, rect_x2, pos_y + 2);
|
|
}
|
|
}
|
|
|
|
void draw_reference_profiler_bars(void) {
|
|
// Draws the reference "max" bars underneath the real thing.
|
|
|
|
// Blue
|
|
gDPPipeSync(gDisplayListHead++);
|
|
gDPSetFillColor(gDisplayListHead++,
|
|
GPACK_RGBA5551(40, 80, 255, 1) << 16 | GPACK_RGBA5551(40, 80, 255, 1));
|
|
gDPFillRectangle(gDisplayListHead++, 30, 220, 79, 222);
|
|
|
|
// Yellow
|
|
gDPPipeSync(gDisplayListHead++);
|
|
gDPSetFillColor(gDisplayListHead++,
|
|
GPACK_RGBA5551(255, 255, 40, 1) << 16 | GPACK_RGBA5551(255, 255, 40, 1));
|
|
gDPFillRectangle(gDisplayListHead++, 79, 220, 128, 222);
|
|
|
|
// Orange
|
|
gDPPipeSync(gDisplayListHead++);
|
|
gDPSetFillColor(gDisplayListHead++,
|
|
GPACK_RGBA5551(255, 120, 40, 1) << 16 | GPACK_RGBA5551(255, 120, 40, 1));
|
|
gDPFillRectangle(gDisplayListHead++, 128, 220, 177, 222);
|
|
|
|
// Red
|
|
gDPPipeSync(gDisplayListHead++);
|
|
gDPSetFillColor(gDisplayListHead++,
|
|
GPACK_RGBA5551(255, 40, 40, 1) << 16 | GPACK_RGBA5551(255, 40, 40, 1));
|
|
gDPFillRectangle(gDisplayListHead++, 177, 220, 226, 222);
|
|
}
|
|
|
|
/*
|
|
Draw Profiler Mode 1. This mode draws a traditional per-event bar for durations of tasks
|
|
recorded by the profiler calls of various threads.
|
|
|
|
Information:
|
|
|
|
(yellow): Level Scripts Execution
|
|
(orange): Rendering
|
|
(blue): Display Lists Send
|
|
(red): Sound Updates
|
|
(yellow): Time from SP tasks queued to RSP complete
|
|
(orange): Time from RSP complete to RDP complete (possibly bugged, see //! note below)
|
|
(red): VBlank Times
|
|
*/
|
|
void draw_profiler_mode_1(void) {
|
|
s32 i;
|
|
struct ProfilerFrameData *profiler;
|
|
OSTime clock_base;
|
|
|
|
// the profiler logs 2 frames of data: last frame and current frame. Indexes are used
|
|
// to keep track of the current frame, so the index is xor'd to retrieve the last frame's
|
|
// data.
|
|
profiler = &gProfilerFrameData[gCurrentFrameIndex1 ^ 1];
|
|
|
|
// calculate the clock_base.
|
|
clock_base = profiler->soundTimes[0] - (16433 * osClockRate / 1000000);
|
|
|
|
// draw the profiler for the time it takes for level scripts to execute. (yellow)
|
|
draw_profiler_bar(clock_base, profiler->gameTimes[0], profiler->gameTimes[1], 212,
|
|
GPACK_RGBA5551(255, 255, 40, 1));
|
|
|
|
// draw the profiler for the time it takes for the game to render (between level scripts and
|
|
// pre-display lists). (orange)
|
|
draw_profiler_bar(clock_base, profiler->gameTimes[1], profiler->gameTimes[2], 212,
|
|
GPACK_RGBA5551(255, 120, 40, 1));
|
|
|
|
// draw the profiler for the time it takes for the display lists to send. (blue)
|
|
draw_profiler_bar(clock_base, profiler->gameTimes[2], profiler->gameTimes[3], 212,
|
|
GPACK_RGBA5551(40, 192, 230, 1));
|
|
|
|
// we need to get the amount of finished numSoundTimes pairs, so get rid of the odd bit to get the
|
|
// limit of finished pairs.
|
|
profiler->numSoundTimes &= 0xFFFE;
|
|
|
|
// draw the sound update times. (red)
|
|
for (i = 0; i < profiler->numSoundTimes; i += 2) {
|
|
draw_profiler_bar(clock_base, profiler->soundTimes[i], profiler->soundTimes[i + 1], 212,
|
|
GPACK_RGBA5551(255, 40, 40, 1));
|
|
}
|
|
|
|
//! RSP and RDP run in parallel, so while they are not absolutely guaranteed to return in order,
|
|
// it is theoretically possible they might not. In all cases, the RDP should finish later than RSP.
|
|
// Thus, this is not really a bug in practice, but should still be noted that the C doesn't check
|
|
// this.
|
|
draw_profiler_bar(clock_base, profiler->gfxTimes[0], profiler->gfxTimes[1], 216,
|
|
GPACK_RGBA5551(255, 255, 40, 1));
|
|
// (orange)
|
|
draw_profiler_bar(clock_base, profiler->gfxTimes[1], profiler->gfxTimes[2], 216,
|
|
GPACK_RGBA5551(255, 120, 40, 1));
|
|
|
|
// like earlier, toss the odd bit.
|
|
profiler->numVblankTimes &= 0xFFFE;
|
|
|
|
// render the vblank time pairs. (red)
|
|
for (i = 0; i < profiler->numVblankTimes; i += 2) {
|
|
draw_profiler_bar(clock_base, profiler->vblankTimes[i], profiler->vblankTimes[i + 1], 216,
|
|
GPACK_RGBA5551(255, 40, 40, 1));
|
|
}
|
|
|
|
draw_reference_profiler_bars();
|
|
}
|
|
|
|
/*
|
|
Draw Profiler Mode 0. This mode renders bars over each other to make it
|
|
easier to see which processes take the longest.
|
|
|
|
Information:
|
|
|
|
(red): Sound Updates
|
|
(yellow): Level Script Execution
|
|
(orange): Rendering
|
|
(orange): RDP Duration
|
|
(yellow): RSP Duration
|
|
(red): VBlank Duration
|
|
*/
|
|
void draw_profiler_mode_0(void) {
|
|
s32 i;
|
|
struct ProfilerFrameData *profiler;
|
|
|
|
u64 clock_start;
|
|
u64 level_script_duration;
|
|
u64 render_duration;
|
|
u64 task_start;
|
|
u64 rsp_duration;
|
|
u64 rdp_duration;
|
|
u64 vblank;
|
|
u64 sound_duration;
|
|
|
|
// get the last frame profiler. gCurrentFrameIndex1 has the current frame being processed, so
|
|
// xor it to get the last frame profiler.
|
|
profiler = &gProfilerFrameData[gCurrentFrameIndex1 ^ 1];
|
|
|
|
// was thread 5 ran before thread 4? set the lower one to be the clock_start.
|
|
clock_start = profiler->gameTimes[0] <= profiler->soundTimes[0] ? profiler->gameTimes[0]
|
|
: profiler->soundTimes[0];
|
|
|
|
// set variables for duration of tasks.
|
|
level_script_duration = profiler->gameTimes[1] - clock_start;
|
|
render_duration = profiler->gameTimes[2] - profiler->gameTimes[1];
|
|
task_start = 0;
|
|
rsp_duration = profiler->gfxTimes[1] - profiler->gfxTimes[0];
|
|
rdp_duration = profiler->gfxTimes[2] - profiler->gfxTimes[0];
|
|
vblank = 0;
|
|
|
|
// like above functions, toss the odd bit.
|
|
profiler->numSoundTimes &= 0xFFFE;
|
|
|
|
// sound duration seems to be rendered with empty space and not actually drawn.
|
|
for (i = 0; i < profiler->numSoundTimes; i += 2) {
|
|
// calculate sound duration of max - min
|
|
sound_duration = profiler->soundTimes[i + 1] - profiler->soundTimes[i];
|
|
task_start += sound_duration;
|
|
// was the sound time minimum less than level script execution?
|
|
if (profiler->soundTimes[i] < profiler->gameTimes[1]) {
|
|
// overlay the level_script_duration onto the profiler by subtracting the sound_duration.
|
|
level_script_duration -= sound_duration;
|
|
} else if (profiler->soundTimes[i] < profiler->gameTimes[2]) {
|
|
// overlay the render_duration onto the profiler by subtracting the sound_duration.
|
|
render_duration -= sound_duration;
|
|
}
|
|
}
|
|
|
|
// same as above. toss the odd bit.
|
|
profiler->numSoundTimes &= 0xFFFE;
|
|
|
|
//! wrong index used to retrieve vblankTimes, thus empty pairs can
|
|
// potentially be passed to draw_profiler_bar, because it could be sending
|
|
// pairs that are beyond the numVblankTimes enforced non-odd limit, due to
|
|
// using the wrong num value.
|
|
for (i = 0; i < profiler->numSoundTimes; i += 2) {
|
|
vblank += (profiler->vblankTimes[i + 1] - profiler->vblankTimes[i]);
|
|
}
|
|
|
|
// Draw top profilers.
|
|
|
|
// draw sound duration as the first bar. (red)
|
|
clock_start = 0;
|
|
draw_profiler_bar(0, clock_start, clock_start + task_start, 212, GPACK_RGBA5551(255, 40, 40, 1));
|
|
|
|
// draw level script execution duration. (yellow)
|
|
clock_start += task_start;
|
|
draw_profiler_bar(0, clock_start, clock_start + level_script_duration, 212,
|
|
GPACK_RGBA5551(255, 255, 40, 1));
|
|
|
|
// draw render duration. (orange)
|
|
clock_start += level_script_duration;
|
|
draw_profiler_bar(0, clock_start, clock_start + render_duration, 212,
|
|
GPACK_RGBA5551(255, 120, 40, 1));
|
|
|
|
// Draw bottom profilers.
|
|
|
|
// rdp duration (orange)
|
|
draw_profiler_bar(0, 0, rdp_duration, 216, GPACK_RGBA5551(255, 120, 40, 1));
|
|
// rsp duration (yellow)
|
|
draw_profiler_bar(0, 0, rsp_duration, 216, GPACK_RGBA5551(255, 255, 40, 1));
|
|
// vblank duration (red)
|
|
draw_profiler_bar(0, 0, vblank, 216, GPACK_RGBA5551(255, 40, 40, 1));
|
|
|
|
draw_reference_profiler_bars();
|
|
}
|
|
|
|
// Draw the Profiler per frame. Toggle the mode if the player presses L while this
|
|
// renderer is active.
|
|
void draw_profiler(void) {
|
|
if (gPlayer1Controller->buttonPressed & L_TRIG) {
|
|
gProfilerMode ^= 1;
|
|
}
|
|
|
|
if (gProfilerMode == 0) {
|
|
draw_profiler_mode_0();
|
|
} else {
|
|
draw_profiler_mode_1();
|
|
}
|
|
}
|