Logs which shader is active to allow per shader profiling.
Merged cpu profiling code from retrace to trace_profiler.
Allow choice of profiling for gpu / cpu / pixels drawn.
namespace trace {
Profiler::Profiler()
- : baseTime(0)
+ : lastProgram(0),
+ baseGpuTime(0),
+ baseCpuTime(0),
+ cpuTimes(false),
+ gpuTimes(true),
+ pixelsDrawn(false)
{
}
{
}
-void Profiler::addCall(unsigned no, const char *name, uint64_t gpu_start, uint64_t gpu_duration, uint64_t samples_passed)
+void Profiler::setup(bool cpuTimes_, bool gpuTimes_, bool pixelsDrawn_)
{
- if (baseTime == 0)
- baseTime = gpu_start;
-
- std::cout << "call "
- << no << " "
- << (gpu_start - baseTime) << " "
- << gpu_duration << " "
- << samples_passed << " "
- << name << std::endl;
+ cpuTimes = cpuTimes_;
+ gpuTimes = gpuTimes_;
+ pixelsDrawn = pixelsDrawn_;
+
+ std::cout << "# frame begin <no> <gpu_start> <cpu_start>" << std::endl;
+ std::cout << "# frame end <no> <gpu_end> <gpu_dura> <cpu_end> <cpu_dura>" << std::endl;
+ std::cout << "# call <no> <gpu_start> <gpu_dura> <cpu_start> <cpu_dura> <pixels> <function>" << std::endl;
+ std::cout << "# use shader program <no>" << std::endl;
}
-void Profiler::addFrameStart(unsigned no, uint64_t timestamp)
+void Profiler::addCall(unsigned no,
+ const char *name,
+ unsigned program,
+ uint64_t pixels,
+ uint64_t gpuStart, uint64_t gpuDuration,
+ uint64_t cpuStart, uint64_t cpuDuration)
{
- if (baseTime == 0)
- baseTime = timestamp;
+ if (baseGpuTime == 0)
+ baseGpuTime = gpuStart;
+
+ if (baseCpuTime == 0)
+ baseCpuTime = cpuStart;
+
+ if (program != lastProgram) {
+ std::cout << "use shader program " << program << std::endl;
+ lastProgram = program;
+ }
+
+ std::cout << "call " << no;
+
+ if (gpuTimes) {
+ std::cout << " "
+ << (gpuStart - baseGpuTime) << " "
+ << gpuDuration;
+ } else {
+ std::cout << " _ _";
+ }
+
+ if (cpuTimes) {
+ std::cout << " "
+ << (cpuStart - baseCpuTime) << " "
+ << cpuDuration;
+ } else {
+ std::cout << " _ _";
+ }
+
+ if (pixelsDrawn) {
+ std::cout << " " << pixels;
+ } else {
+ std::cout << " _";
+ }
+
+ std::cout << " " << name << std::endl;
+}
+
+void Profiler::addFrameStart(unsigned no, uint64_t gpuStart, uint64_t cpuStart)
+{
+ if (baseGpuTime == 0)
+ baseGpuTime = gpuStart;
+
+ if (baseCpuTime == 0)
+ baseCpuTime = cpuStart;
lastFrame.no = no;
- lastFrame.start = timestamp - baseTime;
+ lastFrame.gpuStart = gpuStart - baseGpuTime;
+
+ std::cout << "frame begin " << lastFrame.no;
+
+ if (gpuTimes) {
+ std::cout << " " << lastFrame.gpuStart;
+ } else {
+ std::cout << " _";
+ }
+
+ if (gpuTimes) {
+ std::cout << " " << lastFrame.cpuStart;
+ } else {
+ std::cout << " _";
+ }
- std::cout << "frame begin "
- << lastFrame.no << " "
- << lastFrame.start << std::endl;
+ std::cout << std::endl;
}
-void Profiler::addFrameEnd(uint64_t timestamp)
+void Profiler::addFrameEnd(uint64_t gpuEnd, uint64_t cpuEnd)
{
- if (baseTime == 0)
- baseTime = timestamp;
+ if (baseGpuTime == 0)
+ baseGpuTime = gpuEnd;
+
+ if (baseCpuTime == 0)
+ baseCpuTime = cpuEnd;
+
+ lastFrame.gpuEnd = gpuEnd - baseGpuTime;
+
+ std::cout << "frame end " << lastFrame.no;
+
+ if (gpuTimes) {
+ std::cout << " " << lastFrame.gpuEnd << " " << (lastFrame.gpuEnd - lastFrame.gpuStart);
+ } else {
+ std::cout << " _ _";
+ }
- lastFrame.end = timestamp - baseTime;
+ if (cpuTimes) {
+ std::cout << " " << lastFrame.cpuEnd << " " << (lastFrame.cpuEnd - lastFrame.cpuStart);
+ } else {
+ std::cout << " _ _";
+ }
- std::cout << "frame end "
- << lastFrame.no << " "
- << lastFrame.end << " "
- << (lastFrame.end - lastFrame.start) << std::endl;
+ std::cout << std::endl;
}
}
Profiler();
~Profiler();
- void addCall(unsigned no, const char* name, uint64_t gpu_start, uint64_t gpu_duration, uint64_t samples_passed);
+ void setup(bool cpuTimes_, bool gpuTimes_, bool pixelsDrawn_);
- void addFrameStart(unsigned no, uint64_t timestamp);
- void addFrameEnd(uint64_t timestamp);
+ void addFrameStart(unsigned no, uint64_t gpuStart, uint64_t cpuStart);
+ void addFrameEnd(uint64_t gpuEnd, uint64_t cpuEnd);
+
+ void addCall(unsigned no,
+ const char* name,
+ unsigned program,
+ uint64_t pixels,
+ uint64_t gpuStart, uint64_t gpuDuration,
+ uint64_t cpuStart, uint64_t cpuDuration);
private:
- uint64_t baseTime;
+ unsigned lastProgram;
+ uint64_t baseGpuTime;
+ uint64_t baseCpuTime;
+
+ bool cpuTimes;
+ bool gpuTimes;
+ bool pixelsDrawn;
struct {
unsigned no;
- uint64_t start;
- uint64_t end;
+ uint64_t gpuStart;
+ uint64_t gpuEnd;
+ uint64_t cpuStart;
+ uint64_t cpuEnd;
} lastFrame;
};
}
void updateDrawable(int width, int height);
void flushQueries();
-void beginProfileGPU(trace::Call &call);
-void endProfileGPU(trace::Call &call);
+void beginProfile(trace::Call &call);
+void endProfile(trace::Call &call);
+void setActiveProgram(GLuint program);
} /* namespace glretrace */
+GLuint retrace_unmap_program(GLuint val);
#endif /* _GLRETRACE_HPP_ */
function.name in self.misc_draw_function_names
)
- # Only profile if not inside a list as the queries get inserted into lsit
+ if function.name in ('glUseProgram', 'glUseProgramObjectARB'):
+ print r' glretrace::setActiveProgram((call.arg(0)).toUInt());'
+
+ # Only profile if not inside a list as the queries get inserted into list
if function.name == 'glNewList':
- print r' glretrace::insideList = true;';
+ print r' glretrace::insideList = true;'
if function.name == 'glEndList':
- print r' glretrace::insideList = false;';
+ print r' glretrace::insideList = false;'
if profileDraw:
- print r' if (!glretrace::insideList && retrace::profileGPU) {'
- print r' glretrace::beginProfileGPU(call);'
+ print r' if (!glretrace::insideList && retrace::profiling) {'
+ print r' glretrace::beginProfile(call);'
print r' }'
if function.name == 'glCreateShaderProgramv':
Retracer.invokeFunction(self, function)
if profileDraw:
- print r' if (!glretrace::insideList && retrace::profileGPU) {'
- print r' glretrace::endProfileGPU(call);'
+ print r' if (!glretrace::insideList && retrace::profiling) {'
+ print r' glretrace::endProfile(call);'
print r' }'
# Error checking
#include "glproc.hpp"
#include "glstate.hpp"
#include "glretrace.hpp"
+#include "os_time.hpp"
namespace glretrace {
{
GLuint ids[3];
unsigned call;
+ GLuint program;
const trace::FunctionSig *sig;
+ uint64_t start;
+ uint64_t duration;
};
static bool firstFrame = true;
static std::list<CallQuery> callQueries;
static const int maxActiveCallQueries = 128;
+static std::map<glws::Context*, GLuint> activePrograms;
void
}
static GLuint64
-getTimestamp() {
+getGpuTimestamp() {
GLuint query = 0;
GLuint64 timestamp = 0;
- glGenQueries(1, &query);
- glQueryCounter(query, GL_TIMESTAMP);
- glGetQueryObjectui64vEXT(query, GL_QUERY_RESULT, ×tamp);
- glDeleteQueries(1, &query);
+ if (retrace::profilingGpuTimes) {
+ glGenQueries(1, &query);
+ glQueryCounter(query, GL_TIMESTAMP);
+ glGetQueryObjectui64vEXT(query, GL_QUERY_RESULT, ×tamp);
+ glDeleteQueries(1, &query);
+ }
return timestamp;
}
+static GLuint64
+getCpuTimestamp() {
+ if (retrace::profilingCpuTimes) {
+ return os::getTime() * (1.0E9 / os::timeFrequency);
+ } else {
+ return 0;
+ }
+}
+
static void
completeCallQuery(CallQuery& query) {
/* Get call start and duration */
GLuint64 timestamp = 0, duration = 0, samples = 0;
- glGetQueryObjectui64vEXT(query.ids[0], GL_QUERY_RESULT, ×tamp);
- glGetQueryObjectui64vEXT(query.ids[1], GL_QUERY_RESULT, &duration);
- glGetQueryObjectui64vEXT(query.ids[2], GL_QUERY_RESULT, &samples);
+
+ if (retrace::profilingGpuTimes) {
+ glGetQueryObjectui64vEXT(query.ids[0], GL_QUERY_RESULT, ×tamp);
+ glGetQueryObjectui64vEXT(query.ids[1], GL_QUERY_RESULT, &duration);
+ }
+
+ if (retrace::profilingPixelsDrawn) {
+ glGetQueryObjectui64vEXT(query.ids[2], GL_QUERY_RESULT, &samples);
+ }
+
glDeleteQueries(3, query.ids);
/* Add call to profile */
- retrace::profiler.addCall(query.call, query.sig->name, timestamp, duration, samples);
+ retrace::profiler.addCall(query.call, query.sig->name, query.program, samples, timestamp, duration, query.start, query.duration);
}
void
callQueries.clear();
}
+void setActiveProgram(GLuint program)
+{
+ activePrograms[glretrace::currentContext] = program;
+}
+
+static GLuint
+getActiveProgram()
+{
+ std::map<glws::Context*, GLuint>::iterator it;
+ it = activePrograms.find(glretrace::currentContext);
+ if (it == activePrograms.end())
+ return 0;
+
+ return it->second;
+}
+
void
-beginProfileGPU(trace::Call &call) {
+beginProfile(trace::Call &call) {
if (firstFrame) {
frame_start();
}
CallQuery query;
query.call = call.no;
query.sig = call.sig;
+ query.program = getActiveProgram();
glGenQueries(3, query.ids);
- glQueryCounter(query.ids[0], GL_TIMESTAMP);
- glBeginQuery(GL_TIME_ELAPSED, query.ids[1]);
- glBeginQuery(GL_SAMPLES_PASSED, query.ids[2]);
+
+ if (retrace::profilingGpuTimes) {
+ glQueryCounter(query.ids[0], GL_TIMESTAMP);
+ glBeginQuery(GL_TIME_ELAPSED, query.ids[1]);
+ }
+
+ if (retrace::profilingPixelsDrawn) {
+ glBeginQuery(GL_SAMPLES_PASSED, query.ids[2]);
+ }
callQueries.push_back(query);
+
+ if (retrace::profilingCpuTimes) {
+ query.start = os::getTime();
+ }
}
void
-endProfileGPU(trace::Call &call) {
- glEndQuery(GL_TIME_ELAPSED);
- glEndQuery(GL_SAMPLES_PASSED);
+endProfile(trace::Call &call) {
+ if (retrace::profilingCpuTimes) {
+ CallQuery& query = callQueries.back();
+ query.duration = (os::getTime() - query.start) * (1.0E9 / os::timeFrequency);
+ }
+
+ if (retrace::profilingGpuTimes) {
+ glEndQuery(GL_TIME_ELAPSED);
+ }
+
+ if (retrace::profilingPixelsDrawn) {
+ glEndQuery(GL_SAMPLES_PASSED);
+ }
}
void
frame_start() {
firstFrame = false;
- if (retrace::profileGPU) {
- retrace::profiler.addFrameStart(retrace::frameNo, getTimestamp());
+ if (retrace::profiling) {
+ retrace::profiler.addFrameStart(retrace::frameNo, getGpuTimestamp(), getCpuTimestamp());
}
}
void
frame_complete(trace::Call &call) {
- if (retrace::profileGPU) {
+ if (retrace::profiling) {
/* Complete any remaining queries */
flushQueries();
/* Indicate end of current frame */
- retrace::profiler.addFrameEnd(getTimestamp());
+ retrace::profiler.addFrameEnd(getGpuTimestamp(), getCpuTimestamp());
}
retrace::frameComplete(call);
assert(callback);
assert(callbacks[id] == callback);
- if (retrace::profiling) {
- long long startTime = os::getTime();
- callback(call);
- long long stopTime = os::getTime();
- float timeInterval = (stopTime - startTime) * (1.0E6 / os::timeFrequency);
-
- std::cout
- << call.no << " "
- << "[" << timeInterval << " usec] "
- ;
- trace::dump(call, std::cout, trace::DUMP_FLAG_NO_CALL_NO | trace::DUMP_FLAG_NO_COLOR);
- } else {
- callback(call);
- }
+ callback(call);
}
* Add profiling data to the dump when retracing.
*/
extern bool profiling;
+extern bool profilingCpuTimes;
+extern bool profilingGpuTimes;
+extern bool profilingPixelsDrawn;
/**
* State dumping.
extern bool doubleBuffer;
extern bool coreProfile;
-extern bool profileGPU;
-
extern unsigned frameNo;
int verbosity = 0;
bool debug = true;
-bool profiling = false;
-bool profileGPU = false;
bool dumpingState = false;
-
bool doubleBuffer = true;
bool coreProfile = false;
+bool profiling = false;
+bool profilingGpuTimes = false;
+bool profilingCpuTimes = false;
+bool profilingPixelsDrawn = false;
unsigned frameNo = 0;
long long endTime = os::getTime();
float timeInterval = (endTime - startTime) * (1.0 / os::timeFrequency);
- if ((retrace::verbosity >= -1) || (retrace::profiling) || (retrace::profileGPU)) {
+ if ((retrace::verbosity >= -1) || (retrace::profiling)) {
std::cout <<
"Rendered " << frameNo << " frames"
" in " << timeInterval << " secs,"
"Replay TRACE.\n"
"\n"
" -b benchmark mode (no error checking or warning messages)\n"
- " -p profiling mode (run whole trace, dump profiling info)\n"
- " -pgpu gpu profiling mode (run whole trace, dump gpu profiling info)\n"
+ " -pcpu cpu profiling (cpu times per call)\n"
+ " -pgpu gpu profiling (gpu times per draw call)\n"
+ " -ppd pixels drawn profiling (pixels drawn per draw call)\n"
" -c PREFIX compare against snapshots\n"
" -C CALLSET calls to compare (default is every frame)\n"
" -core use core profile\n"
} else if (!strcmp(arg, "-b")) {
retrace::debug = false;
retrace::verbosity = -1;
- } else if (!strcmp(arg, "-p")) {
- retrace::debug = false;
- retrace::profiling = true;
- retrace::verbosity = -1;
- } else if (!strcmp(arg, "-pgpu")) {
- retrace::profileGPU = true;
-
- retrace::debug = false;
- retrace::profiling = false;
- retrace::verbosity = -1;
} else if (!strcmp(arg, "-c")) {
comparePrefix = argv[++i];
if (compareFrequency.empty()) {
++retrace::verbosity;
} else if (!strcmp(arg, "-w")) {
waitOnFinish = true;
+ } else if (arg[1] == 'p') {
+ retrace::debug = false;
+ retrace::profiling = true;
+ retrace::verbosity = -1;
+
+ if (!strcmp(arg, "-pcpu")) {
+ retrace::profilingCpuTimes = true;
+ } else if (!strcmp(arg, "-pgpu")) {
+ retrace::profilingGpuTimes = true;
+ } else if (!strcmp(arg, "-ppd")) {
+ retrace::profilingPixelsDrawn = true;
+ }
} else {
std::cerr << "error: unknown option " << arg << "\n";
usage(argv[0]);
}
retrace::setUp();
+ if (retrace::profiling) {
+ retrace::profiler.setup(retrace::profilingCpuTimes, retrace::profilingGpuTimes, retrace::profilingPixelsDrawn);
+ }
for ( ; i < argc; ++i) {
if (!retrace::parser.open(argv[i])) {