Vita profiling

prof_viewer.c

#include <cstdio>
#include <cstdint>
#include <cstdlib>
#include <cinttypes>
#include <map>

struct prof_log_entry {
	uint64_t start;
	uint64_t end;
	char func[64];
};

struct function_info {
	uint32_t calls;
	uint64_t time;

	function_info(uint32_t _calls, uint64_t _time) :
		calls(_calls), time(_time) { }
};

int main(int argc, char *argv[])
{
	FILE *fp;
	long size;
	void *buffer;
	prof_log_entry *entry;
	uint64_t total_time;
	uint64_t delta;
	std::string func_name;
	std::size_t find_pos;
	std::map<std::string, function_info> func_info;
	std::map<std::string, function_info>::iterator it;

	if (argc < 2)
		goto error_exit;

	fp = fopen(argv[1], "rb");
	if (!fp) {
		printf("Error opening \'%s\'\n", argv[1]);
		goto error_exit;
	}

	fseek(fp, 0, SEEK_END);
	size = ftell(fp);
	rewind(fp);

	buffer = malloc(size);
	if (!buffer) {
		printf("Error allocating %ld bytes.\n", size);
		goto error_malloc;
	}

	if (fread(buffer, 1, size, fp) != size) {
		printf("Error reading %ld bytes from the file.\n", size);
		goto error_read;
	}

	total_time = 0;
	entry = (struct prof_log_entry *)buffer;
	for (; (uintptr_t)entry < (uintptr_t)buffer + size; entry++) {
		delta = entry->end  - entry->start;
		total_time += delta;

		func_name = std::string(entry->func);
		find_pos = func_name.find('(');
		if (find_pos == 0) {
			func_name = func_name.substr(1, func_name.find('(', 1) - 1);
		} else if (find_pos != string::npos) {
			func_name = func_name.substr(0, find_pos);
		}


		it = func_info.find(func_name);
		if (it == func_info.end()) {
			func_info.insert(std::make_pair(func_name,
				function_info(1, delta)));
		} else {
			it->second.time += delta;
			it->second.calls++;
		}
	}

	printf("Total time: %" PRIu64 "us\n", total_time);

	if (total_time > 0) {
		for (auto const &info: func_info) {
			printf("%9.6f%% - %8" PRIu64 "us - %5" PRIu32 " call(s) - %s\n",
				((double)info.second.time / total_time) * 100,
				info.second.time,
				info.second.calls,
				info.first.c_str());
		}
	}

	free(buffer);
	fclose(fp);
	return 0;

error_read:
	free(buffer);
error_malloc:
	fclose(fp);
error_exit:
	return -1;
}

profiling.c

#include <string.h>
#include <psp2/io/fcntl.h>
#include "profiling.h"

struct prof_log_entry {
	uint64_t start;
	uint64_t end;
	char func[64];
};

#define PROG_LOG_BUFFER_SIZE (4 * 1024)

SceKernelSysClock prof_start_time;
SceKernelSysClock prof_end_time;
const char *prof_func_name;

static struct prof_log_entry log_buffer[PROG_LOG_BUFFER_SIZE];
static unsigned int log_buffer_idx = 0;
static SceUID fd = -1;

void prof_init(const char *filename)
{
	fd = sceIoOpen(filename, SCE_O_WRONLY | SCE_O_CREAT | SCE_O_TRUNC, 0777);
	if (fd < 0) {
		return;
	}

	log_buffer_idx = 0;
}

void prof_finish()
{
	if (log_buffer_idx > 0) {
		sceIoWrite(fd, log_buffer, sizeof(*log_buffer) * log_buffer_idx);
		log_buffer_idx = 0;
	}

	if (fd >= 0) {
		sceIoClose(fd);
		fd = -1;
	}
}

void prof_log(const SceKernelSysClock *start, const SceKernelSysClock *end, const char *func)
{
	log_buffer[log_buffer_idx].start = *start;
	log_buffer[log_buffer_idx].end = *end;
	strncpy(log_buffer[log_buffer_idx].func, func, 64);

	if (log_buffer_idx++ >= PROG_LOG_BUFFER_SIZE) {
		sceIoWrite(fd, log_buffer, sizeof(log_buffer));
		log_buffer_idx = 0;
	}
}

profiling.h

#ifndef PROFILING_H
#define PROFILING_H

#include <psp2/types.h>
#include <psp2/kernel/processmgr.h>

#ifdef __cplusplus
extern "C" {
#endif

void prof_init(const char *filename);
void prof_finish();
void prof_log(const SceKernelSysClock *start, const SceKernelSysClock *end, const char *func);

extern SceKernelSysClock prof_start_time;
extern SceKernelSysClock prof_end_time;
extern const char *prof_func_name;

#define PROF_INIT(name) \
	{ \
		prof_func_name = (name); \
		sceKernelGetProcessTime(&prof_start_time); \
	}

#define PROF_END() \
	{ \
		sceKernelGetProcessTime(&prof_end_time); \
		prof_log(&prof_start_time, &prof_end_time, prof_func_name); \
	}

#define PROF(func) \
	{ \
		SceKernelSysClock start; \
		SceKernelSysClock end; \
		sceKernelGetProcessTime(&start); \
		func; \
		sceKernelGetProcessTime(&end); \
		prof_log(&start, &end, # func); \
	}

#define PROF_RET(func) \
	({ \
		typeof(func) ret; \
		SceKernelSysClock start; \
		SceKernelSysClock end; \
		sceKernelGetProcessTime(&start); \
		ret = func; \
		sceKernelGetProcessTime(&end); \
		prof_log(&start, &end, # func); \
		ret; \
	})

#ifdef __cplusplus
}
#endif

#endif