From: James Benton Date: Tue, 31 Jul 2012 13:11:14 +0000 (+0100) Subject: Cleaned up trace profiler output. X-Git-Url: https://git.cworth.org/git?p=apitrace;a=commitdiff_plain;h=91aed5200759b4fb7e150e52e75da1cdbc3a1b3d Cleaned up trace profiler output. Updated profileshader.py to reflect these changes. --- diff --git a/common/trace_profiler.cpp b/common/trace_profiler.cpp index 6fc0039..02d88dc 100644 --- a/common/trace_profiler.cpp +++ b/common/trace_profiler.cpp @@ -28,8 +28,7 @@ namespace trace { Profiler::Profiler() - : lastProgram(0), - baseGpuTime(0), + : baseGpuTime(0), baseCpuTime(0), cpuTimes(false), gpuTimes(true), @@ -47,10 +46,9 @@ void Profiler::setup(bool cpuTimes_, bool gpuTimes_, bool pixelsDrawn_) gpuTimes = gpuTimes_; pixelsDrawn = pixelsDrawn_; - std::cout << "# frame begin " << std::endl; - std::cout << "# frame end " << std::endl; - std::cout << "# call " << std::endl; - std::cout << "# use shader program " << std::endl; + 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 program name" << std::endl; } void Profiler::addCall(unsigned no, @@ -60,96 +58,101 @@ void Profiler::addCall(unsigned no, uint64_t gpuStart, uint64_t gpuDuration, uint64_t cpuStart, uint64_t cpuDuration) { - if (baseGpuTime == 0) + if (baseGpuTime == 0) { baseGpuTime = gpuStart; + } - if (baseCpuTime == 0) + 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; + gpuStart -= baseGpuTime; } else { - std::cout << " _ _"; + gpuStart = 0; + gpuDuration = 0; } if (cpuTimes) { - std::cout << " " - << (cpuStart - baseCpuTime) << " " - << cpuDuration; + cpuStart -= baseCpuTime; } else { - std::cout << " _ _"; + cpuStart = 0; + cpuDuration = 0; } - if (pixelsDrawn) { - std::cout << " " << pixels; - } else { - std::cout << " _"; + if (!pixelsDrawn) { + pixels = 0; } - std::cout << " " << name << std::endl; + std::cout << "call" + << " " << no + << " " << gpuStart + << " " << gpuDuration + << " " << cpuStart + << " " << cpuDuration + << " " << pixels + << " " << program + << " " << name + << std::endl; } void Profiler::addFrameStart(unsigned no, uint64_t gpuStart, uint64_t cpuStart) { - if (baseGpuTime == 0) + if (baseGpuTime == 0) { baseGpuTime = gpuStart; + } - if (baseCpuTime == 0) + if (baseCpuTime == 0) { baseCpuTime = cpuStart; - - lastFrame.no = no; - lastFrame.gpuStart = gpuStart - baseGpuTime; - - std::cout << "frame begin " << lastFrame.no; + } if (gpuTimes) { - std::cout << " " << lastFrame.gpuStart; + lastFrame.gpuStart = gpuStart - baseGpuTime; } else { - std::cout << " _"; + lastFrame.gpuStart = 0; } - if (gpuTimes) { - std::cout << " " << lastFrame.cpuStart; + if (cpuTimes) { + lastFrame.cpuStart = cpuStart - baseCpuTime; } else { - std::cout << " _"; + lastFrame.cpuStart = 0; } - std::cout << std::endl; + lastFrame.no = no; + + std::cout << "frame_begin" + << " " << lastFrame.no + << " " << lastFrame.gpuStart + << " " << lastFrame.cpuStart + << std::endl; } void Profiler::addFrameEnd(uint64_t gpuEnd, uint64_t cpuEnd) { - if (baseGpuTime == 0) - baseGpuTime = gpuEnd; - - if (baseCpuTime == 0) - baseCpuTime = cpuEnd; - - lastFrame.gpuEnd = gpuEnd - baseGpuTime; - - std::cout << "frame end " << lastFrame.no; + uint64_t gpuDuration, cpuDuration; if (gpuTimes) { - std::cout << " " << lastFrame.gpuEnd << " " << (lastFrame.gpuEnd - lastFrame.gpuStart); + gpuEnd -= baseGpuTime; + gpuDuration = gpuEnd - lastFrame.gpuStart; } else { - std::cout << " _ _"; + gpuEnd = 0; + gpuDuration = 0; } if (cpuTimes) { - std::cout << " " << lastFrame.cpuEnd << " " << (lastFrame.cpuEnd - lastFrame.cpuStart); + cpuEnd -= baseCpuTime; + cpuDuration = cpuEnd - lastFrame.cpuStart; } else { - std::cout << " _ _"; + cpuEnd = 0; + cpuDuration = 0; } - std::cout << std::endl; + std::cout << "frame_end" + << " " << lastFrame.no + << " " << gpuEnd + << " " << gpuDuration + << " " << cpuEnd + << " " << cpuDuration + << std::endl; } } diff --git a/common/trace_profiler.hpp b/common/trace_profiler.hpp index da60d72..c36fd77 100644 --- a/common/trace_profiler.hpp +++ b/common/trace_profiler.hpp @@ -50,7 +50,6 @@ public: uint64_t cpuStart, uint64_t cpuDuration); private: - unsigned lastProgram; uint64_t baseGpuTime; uint64_t baseCpuTime; @@ -61,9 +60,7 @@ private: struct { unsigned no; uint64_t gpuStart; - uint64_t gpuEnd; uint64_t cpuStart; - uint64_t cpuEnd; } lastFrame; }; } diff --git a/scripts/profileshader.py b/scripts/profileshader.py index 6d693f4..3cfa850 100755 --- a/scripts/profileshader.py +++ b/scripts/profileshader.py @@ -30,8 +30,11 @@ if len(sys.argv) <= 1: print 'Please specify a file to read' sys.exit() -shaderTimes = {} -activeShader = 0 +times = {} + +# frame_begin no gpu_start cpu_start +# frame_end no gpu_end gpu_dura cpu_end cpu_dura +# call no gpu_start gpu_dura cpu_start cpu_dura pixels program name for line in open(sys.argv[1], 'r'): words = line.split(' ') @@ -39,29 +42,29 @@ for line in open(sys.argv[1], 'r'): if line.startswith('#'): continue - if words[0:3] == ['use','shader','program']: - activeShader = long(words[3]) - elif words[0] == 'call': + if words[0] == 'call': id = long(words[1]) - func = words[-1] duration = long(words[3]) + shader = long(words[7]) + func = words[8] + + if times.has_key(shader): + times[shader]['draws'] += 1 + times[shader]['duration'] += duration - if shaderTimes.has_key(activeShader): - shaderTimes[activeShader]['draws'] += 1 - shaderTimes[activeShader]['duration'] += duration - if duration > shaderTimes[activeShader]['longestDuration']: - shaderTimes[activeShader]['longest'] = id - shaderTimes[activeShader]['longestDuration'] = duration + if duration > times[shader]['longestDuration']: + times[shader]['longest'] = id + times[shader]['longestDuration'] = duration else: - shaderTimes[activeShader] = {'draws': 1, 'duration': duration, 'longest': id, 'longestDuration': duration} + times[shader] = {'draws': 1, 'duration': duration, 'longest': id, 'longestDuration': duration} -sortedShaderTimes = sorted(shaderTimes.items(), key=lambda x: x[1]['duration'], reverse=True) +times = sorted(times.items(), key=lambda x: x[1]['duration'], reverse=True) print '+------------+--------------+--------------------+--------------+-------------+' print '| Shader[id] | Draws [#] | Duration [ns] v | Per Call[ns] | Longest[id] |' print '+------------+--------------+--------------------+--------------+-------------+' -for shader in sortedShaderTimes: +for shader in times: id = str(shader[0]).rjust(10) draw = str(shader[1]['draws']).rjust(12) dura = str(shader[1]['duration']).rjust(18)