//-----------------------------------------------------------------------------
/// Convert profiler result data to string form.
/// \param pResult The profilerResult to convert.
/// \param profiledCommandsLinesStr The output string.
//-----------------------------------------------------------------------------
void VktTraceAnalyzerLayer::ProfilerResultToStr(
ProfilerResult* pResult,
gtASCIIString& profiledCommandsLinesStr)
{
// Convert timestamps to milliseconds by using the clock frequency.
#ifndef CODEXL_GRAPHICS
const double timestampFrequency = pResult->measurementInfo.idInfo.pWrappedQueue->GetTimestampFrequency();
double preStartTimestamp = (pResult->timestampResult.rawClocks.preStart / timestampFrequency) * 1000.0;
double startTimestamp = (pResult->timestampResult.rawClocks.start / timestampFrequency) * 1000.0;
double endTimestamp = (pResult->timestampResult.rawClocks.end / timestampFrequency) * 1000.0;
#else
double startTimestamp = pResult->timestampResult.alignedMillisecondTimestamps.start;
double endTimestamp = pResult->timestampResult.alignedMillisecondTimestamps.end;
#endif
FuncId funcId = (FuncId)pResult->measurementInfo.idInfo.funcId;
gtASCIIString funcName = GetFunctionNameFromId(funcId);
gtASCIIString retVal = "void";
gtASCIIString params = "";
if (pResult->measurementInfo.idInfo.funcId != FuncId_WholeCmdBuf)
{
VktAPIEntry* pResultEntry = VktFrameProfilerLayer::Instance()->FindInvocationBySampleId(pResult->measurementInfo.idInfo.sampleId);
if (pResultEntry != nullptr)
{
// Convert the functionID and return values from integers into full strings that we can use in the response.
funcName = GetFunctionNameFromId(pResultEntry->mFunctionId);
retVal = (pResultEntry->m_returnValue != -1) ? VktUtil::WriteResultCodeEnumAsString(pResultEntry->m_returnValue) : "void";
params = pResultEntry->mParameters.asCharArray();
}
}
// Vulkan Response line format:
// QueueFamilyIndex QueueIndex CommandBuffer APIType FuncId Vulkan_FuncName(Args) = ReturnValue PreStartTime StartTime EndTime SampleId
profiledCommandsLinesStr += IntToString(pResult->measurementInfo.idInfo.pWrappedQueue->GetQueueFamilyIndex());
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += IntToString(pResult->measurementInfo.idInfo.pWrappedQueue->GetQueueIndex());
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += POINTER_SUFFIX;
profiledCommandsLinesStr += UINT64ToHexString((UINT64)pResult->measurementInfo.idInfo.pWrappedCmdBuf->AppHandle());
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += IntToString(VktTraceAnalyzerLayer::Instance()->GetAPIGroupFromAPI(funcId));
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += IntToString(funcId);
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += "Vulkan_";
profiledCommandsLinesStr += funcName;
profiledCommandsLinesStr += "(";
profiledCommandsLinesStr += params;
profiledCommandsLinesStr += ") = ";
profiledCommandsLinesStr += retVal;
#ifndef CODEXL_GRAPHICS
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += DoubleToString(preStartTimestamp);
#endif
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += DoubleToString(startTimestamp);
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += DoubleToString(endTimestamp);
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += UINT64ToString(pResult->measurementInfo.idInfo.sampleId);
profiledCommandsLinesStr += "\n";
}
//-----------------------------------------------------------------------------
/// Write a DX12-specific APITrace response line into the incoming string stream.
/// \param out The stringstream instance that each trace response line is written to.
/// \param inStartTime The start time for the API call.
/// \param inEndTime The end time for the API call.
//-----------------------------------------------------------------------------
void DX12APIEntry::AppendAPITraceLine(gtASCIIString& out, double inStartTime, double inEndTime) const
{
gtASCIIString returnValueString;
PrintReturnValue(mReturnValue, mReturnValueFlags, returnValueString);
// Use the database processor to get a pointer to the object database.
DX12ObjectDatabaseProcessor* databaseProcessor = DX12ObjectDatabaseProcessor::Instance();
DX12WrappedObjectDatabase* objectDatabase = static_cast<DX12WrappedObjectDatabase*>(databaseProcessor->GetObjectDatabase());
// Use the object database to retrieve wrapper info for the given interface.
IDX12InstanceBase* wrapperInfo = objectDatabase->GetMetadataObject(mWrapperInterface);
// APIType APIFunctionId InterfacePtr D3D12Interface_FunctionName(Parameters) = ReturnValue StartMillisecond EndMillisecond SampleId
void* handle = nullptr;
const char* type = "\0";
const char* parameters = GetParameterString();
if (wrapperInfo)
{
handle = wrapperInfo->GetApplicationHandle();
type = wrapperInfo->GetTypeAsString();
}
else
{
// if there's no wrapper, it's a Present call.
// Assume type is a swap chain until the Present call is wrapped properly
type = "IDXGISwapChain";
}
out += IntToString(DX12TraceAnalyzerLayer::Instance()->GetAPIGroupFromAPI(mFunctionId));
out += " ";
out += IntToString(mFunctionId);
out += " ";
out += "0x";
out += UINT64ToHexString((UINT64)handle);
out += " ";
out += type;
out += "_";
out += GetAPIName();
out += "(";
out += parameters;
out += ") = ";
out += returnValueString.asCharArray();
out += " ";
out += DoubleToString(inStartTime);
out += " ";
out += DoubleToString(inEndTime);
out += " ";
out += UINT64ToString(mSampleId);
out += "\n";
}
//-----------------------------------------------------------------------------
/// Return GPU-time in text format, to be parsed by the Client and displayed as its own timeline.
/// \return A line-delimited, ASCII-encoded, version of the GPU Trace data.
//-----------------------------------------------------------------------------
std::string VktTraceAnalyzerLayer::GetGPUTraceTXT()
{
gtASCIIString appendString = "";
VktFrameProfilerLayer* pProfilerLayer = VktFrameProfilerLayer::Instance();
WaitAndFetchResults(pProfilerLayer);
// Query the CPU clock frequency so we can accurately convert to wall clock time.
GPS_TIMESTAMP cpuClockFrequency;
QueryPerformanceFrequency(&cpuClockFrequency);
// During QueueSubmit we stored ProfilerResults in mEntriesWithProfilingResults. Form a response using it here.
ProfilerResultsMap& profiledCmdBufResultsMap = pProfilerLayer->GetCmdBufProfilerResultsMap();
// During QueueSubmit we stored ProfilerResults in mEntriesWithProfilingResults. Form a response using it here.
if (!profiledCmdBufResultsMap.empty())
{
// Keep a count of the number of lines that we'll write in the response string.
UINT numResponseLines = 0;
gtASCIIString profiledCommandsLinesStr;
ProfilerResultsMap::iterator profIt;
for (profIt = profiledCmdBufResultsMap.begin(); profIt != profiledCmdBufResultsMap.end(); ++profIt)
{
QueueWrapperToProfilingResultsMap::iterator queuesWithProfilingResults;
QueueWrapperToProfilingResultsMap& resultsPerThread = profIt->second;
for (queuesWithProfilingResults = resultsPerThread.begin(); queuesWithProfilingResults != resultsPerThread.end(); ++queuesWithProfilingResults)
{
VktWrappedQueue* pWrappedQueue = queuesWithProfilingResults->first;
const double timestampFrequency = pWrappedQueue->GetTimestampFrequency();
// This structure holds all of the profiler results that were collected at QueueSubmit. The form is LinkId->ProfilerResult.
const SampleIdToProfilerResultMap* pQueueResults = queuesWithProfilingResults->second;
SampleIdToProfilerResultMap::const_iterator queueResultsIterInner;
for (queueResultsIterInner = pQueueResults->begin(); queueResultsIterInner != pQueueResults->end(); ++queueResultsIterInner)
{
UINT64 sampleId = queueResultsIterInner->first;
const ProfilerResult* pResult = queueResultsIterInner->second;
// Convert timestamps to milliseconds by using the clock frequency.
#ifndef CODEXL_GRAPHICS
double preStartTimestamp = (pResult->timestampResult.rawClocks.preStart / timestampFrequency) * 1000.0;
#endif
double startTimestamp = (pResult->timestampResult.rawClocks.start / timestampFrequency) * 1000.0;
double endTimestamp = (pResult->timestampResult.rawClocks.end / timestampFrequency) * 1000.0;
FuncId funcId = (FuncId)pResult->measurementInfo.idInfo.funcId;
gtASCIIString funcName = GetFunctionNameFromId(funcId);
gtASCIIString retVal = "void";
gtASCIIString params = "";
if (pResult->measurementInfo.idInfo.funcId != FuncId_WholeCmdBuf)
{
VktAPIEntry* pResultEntry = pProfilerLayer->FindInvocationBySampleId(sampleId);
if (pResultEntry != nullptr)
{
// Convert the functionID and return values from integers into full strings that we can use in the response.
funcName = GetFunctionNameFromId(pResultEntry->mFunctionId);
retVal = (pResultEntry->m_returnValue != -1) ? VktUtil::WriteResultCodeEnumAsString(pResultEntry->m_returnValue) : "void";
params = pResultEntry->mParameters.asCharArray();
}
}
UINT queueIndex = pWrappedQueue->GetQueueIndex();
#ifndef CODEXL_GRAPHICS
std::string queueInfo = "";
#else
std::string queueInfo = "0";
#endif
// Vulkan Response line format:
// CommandQueuePtr CommandBufferType CommandBufferPtr APIType FuncId Vulkan_FuncName(Args) = ReturnValue StartTime EndTime SampleId
profiledCommandsLinesStr += "0x";
profiledCommandsLinesStr += IntToString(queueIndex);
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += queueInfo.c_str();
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += "0x";
profiledCommandsLinesStr += UINT64ToHexString((UINT64)pResult->measurementInfo.idInfo.pWrappedCmdBuf->AppHandle());
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += IntToString(VktTraceAnalyzerLayer::Instance()->GetAPIGroupFromAPI(funcId));
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += IntToString(funcId);
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += "Vulkan_";
profiledCommandsLinesStr += funcName;
profiledCommandsLinesStr += "(";
profiledCommandsLinesStr += params;
profiledCommandsLinesStr += ") = ";
profiledCommandsLinesStr += retVal;
#ifndef CODEXL_GRAPHICS
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += DoubleToString(preStartTimestamp);
#endif
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += DoubleToString(startTimestamp);
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += DoubleToString(endTimestamp);
profiledCommandsLinesStr += " ";
profiledCommandsLinesStr += UINT64ToString(pResult->measurementInfo.idInfo.sampleId);
profiledCommandsLinesStr += "\n";
// We just added another line to our response buffer. Increment the count that the client will read.
numResponseLines++;
}
}
}
// We'll need to insert the GPU Trace section header before the response data, even if there aren't any results.
appendString += "//==GPU Trace==";
appendString += "\n";
appendString += "//CommandBufEventCount=";
appendString += DWORDToString(numResponseLines);
appendString += "\n";
// Include the response lines after the section header.
if (numResponseLines > 0)
{
appendString += profiledCommandsLinesStr;
}
}
else
{
appendString += "NODATA";
}
return appendString.asCharArray();
}
//--------------------------------------------------------------------------
/// Return a string with all of the logged API call data in line-delimited
/// text format. This is used within the Timeline view in the client.
/// \return A string of all of the logged API calls captured during frame render.
//--------------------------------------------------------------------------
std::string MultithreadedTraceAnalyzerLayer::GetAPITraceTXT()
{
// A switch to determine at the last moment whether or not we should send our generated response back to the client.
bool bWriteResponseString = false;
const GPS_TIMESTAMP frameStartTime = mFramestartTime;
// Concatenate all of the logged call lines into a single string that we can send to the client.
gtASCIIString appendString = "";
std::unordered_map<DWORD, ThreadTraceData*>::iterator traceIter;
for (traceIter = mThreadTraces.begin(); traceIter != mThreadTraces.end(); ++traceIter)
{
ThreadTraceData* currentTrace = traceIter->second;
const TimingLog& currentTimer = currentTrace->mAPICallTimer;
GPS_TIMESTAMP timeFrequency = currentTimer.GetTimeFrequency();
size_t numEntries = currentTrace->mLoggedCallVector.size();
// When using the updated trace format, include a preamble section for each traced thread.
// Write the trace type, API, ThreadID, and count of APIs traced.
appendString += "//==API Trace==";
appendString += "\n";
appendString += "//API=";
appendString += GetAPIString();
appendString += "\n";
appendString += "//ThreadID=";
appendString += DWORDToString(traceIter->first);
appendString += "\n";
appendString += "//ThreadAPICount=";
appendString += UINT64ToString((UINT64)numEntries);
appendString += "\n";
for (size_t entryIndex = 0; entryIndex < numEntries; ++entryIndex)
{
// Get each logged call by index.
const CallsTiming& callTiming = currentTimer.GetTimingByIndex(entryIndex);
// Divide by the clock frequency and scale to milliseconds.
double dTimeFrequency = (double)timeFrequency.QuadPart;
double deltaStartTime = (double)((callTiming.m_startTime.QuadPart - frameStartTime.QuadPart) * 1000.0) / dTimeFrequency;
double deltaEndTime = (double)((callTiming.m_endTime.QuadPart - frameStartTime.QuadPart) * 1000.0) / dTimeFrequency;
const APIEntry* callEntry = currentTrace->mLoggedCallVector[entryIndex];
// This exists as a sanity check. If a duration stretches past this point, we can be pretty sure something is messed up.
// This signal value is basically random, with the goal of it being large enough to catch any obvious duration errors.
if (deltaEndTime > 8000000000.0f)
{
const char* functionName = callEntry->GetAPIName();
Log(logWARNING, "The duration for APIEntry '%s' with index '%d' is suspicious. Tracing the application may have hung, producing inflated results.\n", functionName, entryIndex);
}
callEntry->AppendAPITraceLine(appendString, deltaStartTime, deltaEndTime);
}
bWriteResponseString = true;
}
// If for some reason we failed to write a valid response string, reply with a known failure signal so the client handles it properly.
if (!bWriteResponseString)
{
appendString += "NODATA";
}
return appendString.asCharArray();
//return traceString.str();
}
