diff --git a/lib/trace/trace_format.hpp b/lib/trace/trace_format.hpp index bb6dc2f..30da403 100644 --- a/lib/trace/trace_format.hpp +++ b/lib/trace/trace_format.hpp @@ -49,6 +49,8 @@ enum CallDetail { CALL_THREAD, CALL_BACKTRACE, CALL_FLAGS, + CALL_CPUSTART, + CALL_CPUEND, }; enum Type { diff --git a/lib/trace/trace_model.hpp b/lib/trace/trace_model.hpp index d4b433d..eae1588 100644 --- a/lib/trace/trace_model.hpp +++ b/lib/trace/trace_model.hpp @@ -379,7 +379,6 @@ public: /** Machine-readible value */ Value *machineValue; - virtual bool toBool(void) const override; virtual signed long long toSInt(void) const override; virtual unsigned long long toUInt(void) const override; @@ -454,8 +453,8 @@ public: virtual void visit(Repr *); protected: inline void _visit(Value *value) { - if (value) { - value->visit(*this); + if (value) { + value->visit(*this); } } }; @@ -491,7 +490,7 @@ enum { * Some incomplete calls are unreproduceable, but not all. */ CALL_FLAG_NON_REPRODUCIBLE = (1 << 1), - + /** * Whether this call has no side-effects, therefore don't need to be * retraced. @@ -510,13 +509,13 @@ enum { * Whether this call causes render target to be swapped. * * This does not mark frame termination by itself -- that's solely the - * responsibility of `endOfFrame` bit. + * responsibility of `endOfFrame` bit. * * This mean that snapshots should be take prior to the call, and not * after. */ CALL_FLAG_SWAP_RENDERTARGET = (1 << 4), - + /** * Whether this call terminates a frame. * @@ -555,6 +554,8 @@ class Call public: unsigned thread_id; unsigned no; + int64_t cpuStart; + int64_t cpuEnd; const FunctionSig *sig; std::vector args; Value *ret; @@ -563,9 +564,11 @@ public: Backtrace* backtrace; Call(const FunctionSig *_sig, const CallFlags &_flags, unsigned _thread_id) : - thread_id(_thread_id), - sig(_sig), - args(_sig->num_args), + thread_id(_thread_id), + cpuStart(0), + cpuEnd(0), + sig(_sig), + args(_sig->num_args), ret(0), flags(_flags), backtrace(0) { diff --git a/lib/trace/trace_parser.cpp b/lib/trace/trace_parser.cpp index 73e287c..7e14c1b 100644 --- a/lib/trace/trace_parser.cpp +++ b/lib/trace/trace_parser.cpp @@ -147,7 +147,7 @@ void Parser::close(void) { } } enums.clear(); - + for (auto sig : bitmasks) { if (sig) { for (unsigned flag = 0; flag < sig->num_flags; ++flag) { @@ -172,7 +172,7 @@ void Parser::getBookmark(ParseBookmark &bookmark) { void Parser::setBookmark(const ParseBookmark &bookmark) { file->setCurrentOffset(bookmark.offset); next_call_no = bookmark.next_call_no; - + // Simply ignore all pending calls deleteAll(calls); } @@ -481,7 +481,7 @@ Call *Parser::parse_leave(Mode mode) { } if (!call) { /* This might happen on random access, when an asynchronous call is stranded - * between two frames. We won't return this call, but we still need to skip + * between two frames. We won't return this call, but we still need to skip * over its data. */ const FunctionSig sig = {0, NULL, 0, NULL}; @@ -538,6 +538,18 @@ bool Parser::parse_call_details(Call *call, Mode mode) { } } break; + case trace::CALL_CPUSTART: + if (TRACE_VERBOSE) { + std::cerr << "\tCALL_CPUSTART\n"; + } + call->cpuStart = read_uint(); + break; + case trace::CALL_CPUEND: + if (TRACE_VERBOSE) { + std::cerr << "\tCALL_CPUEND\n"; + } + call->cpuEnd = read_uint(); + break; default: std::cerr << "error: ("<name()<< ") unknown call detail " << c << "\n"; diff --git a/lib/trace/trace_parser.hpp b/lib/trace/trace_parser.hpp index 0bd8613..c8210bd 100644 --- a/lib/trace/trace_parser.hpp +++ b/lib/trace/trace_parser.hpp @@ -168,7 +168,6 @@ protected: EnumSig *parse_old_enum_sig(); EnumSig *parse_enum_sig(); BitmaskSig *parse_bitmask_sig(); - public: static CallFlags lookupCallFlags(const char *name); diff --git a/lib/trace/trace_parser_flags.cpp b/lib/trace/trace_parser_flags.cpp index 69bd837..6ab65e9 100644 --- a/lib/trace/trace_parser_flags.cpp +++ b/lib/trace/trace_parser_flags.cpp @@ -152,6 +152,7 @@ callFlagTable[] = { { "glDebugMessageInsertAMD", CALL_FLAG_NO_SIDE_EFFECTS | CALL_FLAG_MARKER }, { "glDebugMessageInsertARB", CALL_FLAG_NO_SIDE_EFFECTS | CALL_FLAG_MARKER }, { "glDebugMessageInsertKHR", CALL_FLAG_NO_SIDE_EFFECTS | CALL_FLAG_MARKER }, + { "glFinish", CALL_FLAG_END_FRAME }, { "glFrameTerminatorGREMEDY", CALL_FLAG_END_FRAME }, { "glGetActiveAtomicCounterBufferiv", CALL_FLAG_NO_SIDE_EFFECTS }, { "glGetActiveAttrib", CALL_FLAG_NO_SIDE_EFFECTS }, diff --git a/lib/trace/trace_writer.cpp b/lib/trace/trace_writer.cpp index 1334a0e..c92a1cf 100644 --- a/lib/trace/trace_writer.cpp +++ b/lib/trace/trace_writer.cpp @@ -191,6 +191,21 @@ Writer::writeFlags(unsigned flags) { } void +Writer::writeCpuStart(signed long long time) { + _writeByte(trace::CALL_CPUSTART); + _writeUInt(time); + +} + +void +Writer::writeCpuEnd(signed long long time) { + _writeByte(trace::CALL_CPUEND); + _writeUInt(time); + +} + + +void Writer::writeProperty(const char *name, const char *value) { assert(name); diff --git a/lib/trace/trace_writer.hpp b/lib/trace/trace_writer.hpp index 8481e52..02278f5 100644 --- a/lib/trace/trace_writer.hpp +++ b/lib/trace/trace_writer.hpp @@ -77,6 +77,9 @@ namespace trace { void writeFlags(unsigned flags); + void writeCpuStart(signed long long time); + void writeCpuEnd(signed long long time); + void beginArray(size_t length); inline void endArray(void) {} diff --git a/lib/trace/trace_writer_local.cpp b/lib/trace/trace_writer_local.cpp index 0db6232..585787e 100644 --- a/lib/trace/trace_writer_local.cpp +++ b/lib/trace/trace_writer_local.cpp @@ -32,6 +32,7 @@ #include "os.hpp" #include "os_thread.hpp" +#include "os_time.hpp" #include "os_string.hpp" #include "os_version.hpp" #include "trace_ostream.hpp" @@ -65,6 +66,7 @@ static void exceptionCallback(void) LocalWriter::LocalWriter() : acquired(0) { + startTime = os::getTime(); os::String process = os::getProcessName(); os::log("apitrace: loaded into %s\n", process.str()); @@ -206,6 +208,7 @@ unsigned LocalWriter::beginEnter(const FunctionSig *sig, bool fake) { } void LocalWriter::endEnter(void) { + Writer::writeCpuStart(os::getTime() - startTime); Writer::endEnter(); --acquired; mutex.unlock(); @@ -215,6 +218,7 @@ void LocalWriter::beginLeave(unsigned call) { mutex.lock(); ++acquired; Writer::beginLeave(call); + Writer::writeCpuEnd(os::getTime() - startTime); } void LocalWriter::endLeave(void) { diff --git a/lib/trace/trace_writer_local.hpp b/lib/trace/trace_writer_local.hpp index 5d55bd9..cf2fc2b 100644 --- a/lib/trace/trace_writer_local.hpp +++ b/lib/trace/trace_writer_local.hpp @@ -69,6 +69,7 @@ namespace trace { */ os::recursive_mutex mutex; int acquired; + int64_t startTime; /** * ID of the processed that opened the trace file. diff --git a/retrace/glretrace_main.cpp b/retrace/glretrace_main.cpp index d5c9277..18a1386 100755 --- a/retrace/glretrace_main.cpp +++ b/retrace/glretrace_main.cpp @@ -222,7 +222,8 @@ completeCallQuery(CallQuery& query) { if (retrace::profilingGpuTimes) { if (supportsTimestamp) { /* Use ARB queries in case EXT not present */ - glGetQueryObjecti64v(query.ids[GPU_START], GL_QUERY_RESULT, &gpuStart); + //glGetQueryObjecti64v(query.ids[GPU_START], GL_QUERY_RESULT, &gpuStart); + gpuStart = query.cpuStart; glGetQueryObjecti64v(query.ids[GPU_DURATION], GL_QUERY_RESULT, &gpuDuration); } else { glGetQueryObjecti64vEXT(query.ids[GPU_DURATION], GL_QUERY_RESULT, &gpuDuration); @@ -246,9 +247,7 @@ completeCallQuery(CallQuery& query) { } if (retrace::profilingCpuTimes) { - double cpuTimeScale = 1.0E9 / getTimeFrequency(); - cpuDuration = (query.cpuEnd - query.cpuStart) * cpuTimeScale; - query.cpuStart *= cpuTimeScale; + cpuDuration = query.cpuEnd - query.cpuStart; } if (retrace::profilingMemoryUsage) { @@ -330,7 +329,7 @@ beginProfile(trace::Call &call, bool isDraw) { /* CPU profiling for all calls */ if (retrace::profilingCpuTimes) { CallQuery& query = callQueries.back(); - query.cpuStart = getCurrentTime(); + query.cpuStart = call.cpuStart; } if (retrace::profilingMemoryUsage) { @@ -355,7 +354,7 @@ endProfile(trace::Call &call, bool isDraw) { /* CPU profiling for all calls */ if (retrace::profilingCpuTimes) { CallQuery& query = callQueries.back(); - query.cpuEnd = getCurrentTime(); + query.cpuEnd = call.cpuEnd; } /* GPU profiling only for draw calls */ @@ -505,10 +504,10 @@ initContext() { /* Sync the gpu and cpu start times */ if (retrace::profilingCpuTimes || retrace::profilingGpuTimes) { if (!retrace::profiler.hasBaseTimes()) { - double cpuTimeScale = 1.0E9 / getTimeFrequency(); - GLint64 currentTime = getCurrentTime() * cpuTimeScale; - retrace::profiler.setBaseCpuTime(currentTime); - retrace::profiler.setBaseGpuTime(currentTime); + //double cpuTimeScale = 1.0E9 / getTimeFrequency(); + //GLint64 currentTime = getCurrentTime() * cpuTimeScale; + //retrace::profiler.setBaseCpuTime(currentTime); + //retrace::profiler.setBaseGpuTime(currentTime); } }