//-----------------------------------------------------------------------------
/// Handles operations that need to occur before profiling an API call.
/// \param funcId The FuncId corresponding to the API call being traced.
/// \param pWrappedCmdBuf The interface pointer used to invoke the API call.
//-----------------------------------------------------------------------------
void VktFrameProfilerLayer::PreCall(FuncId funcId, VktWrappedCmdBuf* pWrappedCmdBuf)
{
if (pWrappedCmdBuf->IsProfilingEnabled() && ShouldProfileFunction(funcId))
{
osThreadId threadId = osGetCurrentThreadId();
SampleInfo* pSampleInfo = GetSampleInfoForThread(threadId);
if (pSampleInfo != nullptr)
{
UINT64 nextSampleId = SetNextSampleId(pSampleInfo);
ProfilerMeasurementId measurementId = {};
VktUtil::ConstructMeasurementInfo(funcId, nextSampleId, pWrappedCmdBuf, GetParentLayerManager()->GetFrameCount(), pWrappedCmdBuf->FillCount(), measurementId);
ProfilerResultCode beginResult = pWrappedCmdBuf->BeginCmdMeasurement(&measurementId);
if (beginResult == PROFILER_SUCCESS)
{
pSampleInfo->mSampleId = measurementId.sampleId;
pSampleInfo->mbBeginSampleSuccessful = true;
}
else
{
Log(logERROR, "Failed BeginCmdMeasurement. CmdBuf='0x%p' SampleId='%d'\n", pWrappedCmdBuf->AppHandle(), measurementId.sampleId);
}
}
else
{
Log(logERROR, "Failed to find or create SampleInfo instance for Thread %d\n", threadId);
}
}
}
//-----------------------------------------------------------------------------
/// Handler used after the real runtime implementation of an API call has been invoked.
/// \param pNewAPIEntry The new APIEntry created for the API call invocation.
/// \param pWrappedCmdBuf The interface pointer used to invoke the API call.
/// \param inFuncId The FuncId corresponding to the API call being traced.
//-----------------------------------------------------------------------------
void VktFrameProfilerLayer::PostCall(VktAPIEntry* pNewAPIEntry, FuncId inFuncId, VktWrappedCmdBuf* pWrappedCmdBuf)
{
// Wait and gather results
if (pWrappedCmdBuf->IsProfilingEnabled() && ShouldProfileFunction(inFuncId))
{
osThreadId threadId = osGetCurrentThreadId();
SampleInfo* pSampleInfo = GetSampleInfoForThread(threadId);
if (pSampleInfo != nullptr)
{
if (pSampleInfo->mbBeginSampleSuccessful == true)
{
ProfilerResultCode endResult = pWrappedCmdBuf->EndCmdMeasurement();
if (endResult == PROFILER_SUCCESS)
{
pNewAPIEntry->m_sampleId = pSampleInfo->mSampleId;
StoreProfilerResult(pNewAPIEntry);
}
else
{
Log(logERROR, "Failed EndCmdMeasurement. CmdBuf='0x%p' SampleId='%d'\n", pWrappedCmdBuf->AppHandle(), pSampleInfo->mSampleId);
}
}
else
{
Log(logERROR, "Didn't call EndMeasurement because BeginMeasurement wasn't successful.\n");
}
}
else
{
Log(logERROR, "Didn't call EndSample because there was no SampleInfo for Thread %d\n", threadId);
}
}
}
//--------------------------------------------------------------------------
/// This is called before the target function call, and will setup a new ThreadTraceData
/// structure if necessary, but will also track the start time for a function call.
/// \return Nothing.
//--------------------------------------------------------------------------
void MultithreadedTraceAnalyzerLayer::BeforeAPICall()
{
// Find the correct ThreadTraceData instance and inject the precall time.
// A single thread will only ever deal with tracing one function at a time, so we can
// leave "this" traced function's start time in the per-thread data.
DWORD threadId = osGetCurrentThreadId();
ThreadTraceData* currentThreadData = FindOrCreateThreadData(threadId);
currentThreadData->m_startTime = currentThreadData->mAPICallTimer.GetRaw();
}
//-----------------------------------------------------------------------------
/// Handler used after the real runtime implementation of an API call has been invoked.
/// \param inNewAPIEntry The new APIEntry created for the API call invocation.
/// \param inWrappedInterface The interface pointer used to invoke the API call.
/// \param inFunctionId The FuncId corresponding to the API call being traced.
//-----------------------------------------------------------------------------
void DX12FrameProfilerLayer::PostCall(DX12APIEntry* inNewAPIEntry, IUnknown* inWrappedInterface, FuncId inFunctionId)
{
Wrapped_ID3D12GraphicsCommandListCustom* pWrappedGraphicsCommandListCustom = static_cast<Wrapped_ID3D12GraphicsCommandListCustom*>(inWrappedInterface);
// Wait and gather results
if (pWrappedGraphicsCommandListCustom->IsProfilingEnabled() && ShouldProfileFunction(inFunctionId))
{
Wrapped_ID3D12GraphicsCommandList* pWrappedGraphicsCommandList = static_cast<Wrapped_ID3D12GraphicsCommandList*>(inWrappedInterface);
osThreadId threadId = osGetCurrentThreadId();
Wrapped_ID3D12CommandList* pCmdList = static_cast<Wrapped_ID3D12CommandList*>(inWrappedInterface);
if (CommandListSupportsTimestamping(pCmdList) == true)
{
SampleInfo* pSampleInfo = GetSampleInfoForThread(threadId);
if (pSampleInfo != nullptr)
{
if (pSampleInfo->mbBeginSampleSuccessful == true)
{
Wrapped_ID3D12GraphicsCommandListCustom* pCmdListCustom = static_cast<Wrapped_ID3D12GraphicsCommandListCustom*>(inWrappedInterface);
ProfilerResultCode endResult = pCmdListCustom->EndCmdMeasurement();
if (endResult == PROFILER_SUCCESS)
{
inNewAPIEntry->mSampleId = pSampleInfo->mSampleId;
StoreProfilerResult(inNewAPIEntry);
}
else
{
Log(logERROR, "Failed EndCmdMeasurement. CmdList='0x%p' SampleId='%d'\n", pWrappedGraphicsCommandList->mRealGraphicsCommandList, pSampleInfo->mSampleId);
}
}
else
{
Log(logERROR, "Didn't call EndMeasurement because BeginMeasurement wasn't successful.\n");
}
}
else
{
Log(logERROR, "Didn't call EndSample because there was no SampleInfo for Thread %d\n", threadId);
}
}
else
{
Log(logERROR, "Failed to find or create SampleInfo instance for Thread %d\n", threadId);
}
}
}
// ---------------------------------------------------------------------------
// Name: afInitializeApplicationCommand::nameThreadInDebugger
// Description:
// Name the application's main thread in Visual Studio's thread's list.
// (We assume that the main application's thread is the thread that uses afInitializeApplicationCommand)
// Author: Yaki Tebeka
// Date: 25/11/2010
// ---------------------------------------------------------------------------
void afInitializeApplicationCommand::nameMainThreadInDebugger()
{
// Naming threads in a debugger is only supported on Windows:
#if AMDT_BUILD_TARGET == AMDT_WINDOWS_OS
// Do not rename the main thread in Visual Studio:
if (!afGlobalVariablesManager::instance().isRunningInsideVisualStudio())
{
// Name the application's main thread in Visual Studio's thread's list:
osThreadId mainThreadId = osGetCurrentThreadId();
gtASCIIString mainThreadName("CodeXL - main thread");
osNameThreadInDebugger(mainThreadId, mainThreadName);
}
#endif
}
//-----------------------------------------------------------------------------
/// Spawn a worker thread to gather GPU profiler results.
/// \param pTimestampPair A pair of calibration timestamps used to align CPU and GPU timelines.
/// \param pQueue The Queue responsible for executed the profiled workload.
/// \param fenceToWaitOn The fence we want to wait on.
/// \param internalFence True if the fence we're waiting on was created by VulkanServer.
/// \param cmdBufs A vector of command buffers being executed.
//-----------------------------------------------------------------------------
void VktWrappedQueue::SpawnWorker(
CalibrationTimestampPair* pTimestampPair,
VktWrappedQueue* pQueue,
VkFence fenceToWaitOn,
bool internalFence,
const std::vector<VktWrappedCmdBuf*> cmdBufs)
{
const UINT cmdBufCount = (UINT)cmdBufs.size();
if (cmdBufCount > 0)
{
static UINT32 s_threadID = 1;
VktWorkerInfo* pWorkerInfo = new VktWorkerInfo();
pWorkerInfo->m_inputs.internalFence = internalFence;
pWorkerInfo->m_inputs.fenceToWaitOn = fenceToWaitOn;
pWorkerInfo->m_inputs.pQueue = pQueue;
pWorkerInfo->m_inputs.frameStartTime = VktTraceAnalyzerLayer::Instance()->GetFrameStartTime();
pWorkerInfo->m_threadInfo.workerThreadCountID = s_threadID++;
pWorkerInfo->m_threadInfo.parentThreadID = osGetCurrentThreadId();
for (size_t i = 0; i < cmdBufCount; i++)
{
WrappedCmdBufData cmdBufData = {};
cmdBufData.pCmdBuf = cmdBufs[i];
cmdBufData.targetFillID = cmdBufs[i]->FillCount();
cmdBufData.profiledCallCount = cmdBufs[i]->GetProfiledCallCount();
pWorkerInfo->m_inputs.cmdBufData.push_back(cmdBufData);
}
memcpy(&pWorkerInfo->m_inputs.timestampPair, pTimestampPair, sizeof(pWorkerInfo->m_inputs.timestampPair));
// The push onto m_workerThreadInfo needs to be thread safe
{
ScopeLock lock(&m_workerThreadInfoMutex);
m_workerThreadInfo.push_back(pWorkerInfo);
DWORD threadId = 0;
pWorkerInfo->m_threadInfo.threadHandle = CreateThread(nullptr, 0, ThreadFunc, pWorkerInfo, 0, &threadId);
}
}
}
//-----------------------------------------------------------------------------
/// Gets called immediately after the real Present() is called
/// \param queue The queue used to present.
/// \param pPresentInfo Presentation info.
//-----------------------------------------------------------------------------
void VktTraceAnalyzerLayer::OnPresent(VkQueue queue, const VkPresentInfoKHR* pPresentInfo)
{
VktInterceptManager* pInterceptor = VktLayerManager::GetLayerManager()->GetInterceptMgr();
if (pInterceptor->ShouldCollectTrace())
{
char argumentsBuffer[ARGUMENTS_BUFFER_SIZE];
sprintf_s(argumentsBuffer, ARGUMENTS_BUFFER_SIZE, "0x%p, 0x%p", queue, pPresentInfo);
// precall
BeforeAPICall();
// postcall
DWORD threadId = osGetCurrentThreadId();
VktAPIEntry* pNewEntry = new VktAPIEntry(threadId, FuncId_vkQueuePresentKHR, argumentsBuffer, nullptr);
pInterceptor->PostCall(pNewEntry);
}
}
//
// ThreadPool's thread start routine
// - All the worker threads will start with this routine
// - the parameter passed to this thread start routine is "WorkThreadParam"
// It has
// threadWorkFunction :- thread work function;
// threadWorkParam :- thread param for the "threadWorkFunction"
// tPool :- thread pool object itself
//
DWORD WINAPI ThreadPool::ThreadExecute(LPVOID param)
{
osNameThreadInDebugger(osGetCurrentThreadId(), "PoolThread");
PrdWorkUnit work;
if (NULL == param)
{
OS_OUTPUT_DEBUG_LOG(L"Invalid arg for worker thread", OS_DEBUG_LOG_ERROR);
return (DWORD)E_INVALIDARG;
}
WorkThreadParam* wParam = (WorkThreadParam*)param;
ThreadPool* tp = (ThreadPool*)wParam->tPool;
OS_OUTPUT_FORMAT_DEBUG_LOG(OS_DEBUG_LOG_DEBUG, L"Thread (%d) Created", GetCurrentThreadId());
// the worker cannot be assigned empty work..
// ThreadPool::fetchwork() will return false on DUMMY work;
// DUMMY work is used to request the thread to terminate.
while (tp->FetchWork(&work))
{
wParam->threadWorkFunction(wParam->threadWorkParam, (void*)&work);
tp->m_workQueue->SetWorkStatusComplete();
}
// This is to cleanup the Dummy work..
// Is there a way to verify that we have received dummy work ?
if (tp->m_workQueue->IsWorkPending())
{
tp->m_workQueue->SetWorkStatusComplete();
}
// If still some work is pending, emit a warning message
if (tp->m_workQueue->IsWorkPending())
{
OS_OUTPUT_DEBUG_LOG(L"Warning: Still some work is pending in the workqueue or work-in-progress in some other thread...\n",
OS_DEBUG_LOG_DEBUG);
}
OS_OUTPUT_FORMAT_DEBUG_LOG(OS_DEBUG_LOG_DEBUG, L"Return from the thread (%d)", GetCurrentThreadId());
return 0;
}
//-----------------------------------------------------------------------------
/// Profiler results collection worker function.
/// \param lpParam A void pointer to the incoming VktWorkerInfo argument.
/// \returns Always 0.
//-----------------------------------------------------------------------------
DWORD WINAPI ThreadFunc(LPVOID lpParam)
{
VktWorkerInfo* pWorkerInfo = (VktWorkerInfo*)lpParam;
pWorkerInfo->m_threadInfo.workerThreadID = osGetCurrentThreadId();
VkResult waitResult = VK_TIMEOUT;
#if GPU_FENCES_FOR_PROFILER_WAIT
VkDevice device = pWorkerInfo->m_inputs.pQueue->ParentDevice();
do
{
waitResult = device_dispatch_table(device)->WaitForFences(device, 1, &pWorkerInfo->m_inputs.fenceToWaitOn, VK_TRUE, GPU_FENCE_TIMEOUT_TIME);
} while (waitResult == VK_TIMEOUT);
#else
VkQueue queue = pWorkerInfo->m_inputs.pQueue->AppHandle();
waitResult = device_dispatch_table(queue)->QueueWaitIdle(queue);
#endif
if (pWorkerInfo->m_inputs.timestampPair.mQueueCanBeTimestamped)
{
for (UINT i = 0; i < pWorkerInfo->m_inputs.cmdBufs.size(); i++)
{
VktWrappedCmdBuf* pWrappedCmdBuf = pWorkerInfo->m_inputs.cmdBufs[i];
ProfilerResultCode profResult = pWrappedCmdBuf->GetCmdBufResultsMT(pWorkerInfo->m_inputs.executionID, pWorkerInfo->m_outputs.results);
if (profResult != PROFILER_SUCCESS)
{
const char* profilerErrorCode = VktCmdBufProfiler::PrintProfilerResult(profResult);
// Report that a problem occurred in retrieving full profiler results.
Log(logERROR, "Failed to retrieve full profiler results: CmdBuf 0x%p, Queue 0x%p, ErrorCode %s\n",
pWorkerInfo->m_inputs.cmdBufs[i], pWorkerInfo->m_inputs.pQueue, profilerErrorCode);
}
}
}
// This will only be set to true if the GPU results have come back in time.
pWorkerInfo->m_outputs.bResultsGathered = true;
return 0;
}
//-----------------------------------------------------------------------------
/// Handles operations that need to occur before profiling an API call.
/// \param inWrappedInterface The interface pointer used to invoke the API call.
/// \param inFunctionId The FuncId corresponding to the API call being traced.
//-----------------------------------------------------------------------------
void DX12FrameProfilerLayer::PreCall(IUnknown* inWrappedInterface, FuncId inFunctionId)
{
Wrapped_ID3D12GraphicsCommandListCustom* pWrappedGraphicsCommandListCustom = static_cast<Wrapped_ID3D12GraphicsCommandListCustom*>(inWrappedInterface);
// Check if we intend to collect GPU time
if (pWrappedGraphicsCommandListCustom->IsProfilingEnabled() && ShouldProfileFunction(inFunctionId))
{
osThreadId threadId = osGetCurrentThreadId();
SampleInfo* pSampleInfo = GetSampleInfoForThread(threadId);
if (pSampleInfo != nullptr)
{
// Don't let new sampling begin until this sample is finished with a call to EndSample.
Wrapped_ID3D12CommandList* pCmdList = static_cast<Wrapped_ID3D12CommandList*>(inWrappedInterface);
// Only some types of CommandLists can be timestamped. Check the type before proceeding.
if (CommandListSupportsTimestamping(pCmdList) == true)
{
UINT64 nextSampleId = SetNextSampleId(pSampleInfo);
ProfilerMeasurementId measurementId = {};
ConstructMeasurementInfo(inFunctionId, nextSampleId, pWrappedGraphicsCommandListCustom, measurementId);
ProfilerResultCode beginResult = pWrappedGraphicsCommandListCustom->BeginCmdMeasurement(&measurementId);
if (beginResult == PROFILER_SUCCESS)
{
pSampleInfo->mSampleId = measurementId.mSampleId;
pSampleInfo->mbBeginSampleSuccessful = true;
}
else
{
Log(logERROR, "Failed BeginCmdMeasurement. CmdList='0x%p' SampleId='%d'\n", pWrappedGraphicsCommandListCustom->mRealGraphicsCommandList, measurementId.mSampleId);
}
}
}
else
{
Log(logERROR, "Failed to find or create SampleInfo instance for Thread %d\n", threadId);
}
}
}
//-----------------------------------------------------------------------------
/// Spawn a worker thread to gather GPU profiler results.
/// \param pTimestampPair A pair of calibration timestamps used to align CPU and GPU timelines.
/// \param pQueue The Queue responsible for executed the profiled workload.
/// \param fenceToWaitOn The fence we want to wait on
/// \param internalFence True if the fence we're waiting on was created by VulkanServer
/// \param cmdBufsWithProfiledCalls The array of CommandBuffers being executed.
//-----------------------------------------------------------------------------
void VktWrappedQueue::SpawnWorker(
CalibrationTimestampPair* pTimestampPair,
VktWrappedQueue* pQueue,
VkFence fenceToWaitOn,
bool internalFence,
const std::vector<VktWrappedCmdBuf*> cmdBufs)
{
const UINT cmdBufCount = (UINT)cmdBufs.size();
if (cmdBufCount > 0)
{
static UINT32 s_threadID = 1;
VktWorkerInfo* pWorkerInfo = new VktWorkerInfo();
pWorkerInfo->m_inputs.internalFence = internalFence;
pWorkerInfo->m_inputs.fenceToWaitOn = fenceToWaitOn;
pWorkerInfo->m_inputs.pQueue = pQueue;
pWorkerInfo->m_inputs.executionID = m_executionID;
pWorkerInfo->m_threadInfo.workerThreadCountID = s_threadID++;
pWorkerInfo->m_threadInfo.parentThreadID = osGetCurrentThreadId();
for (size_t index = 0; index < cmdBufCount; index++)
{
pWorkerInfo->m_inputs.cmdBufs.push_back(cmdBufs[index]);
}
memcpy(&pWorkerInfo->m_inputs.timestampPair, pTimestampPair, sizeof(pWorkerInfo->m_inputs.timestampPair));
// The push onto m_workerThreadInfo needs to be thread safe
{
ScopeLock lock(&m_workerThreadInfoMutex);
m_workerThreadInfo.push_back(pWorkerInfo);
DWORD threadId = 0;
pWorkerInfo->m_threadInfo.threadHandle = CreateThread(nullptr, 0, ThreadFunc, pWorkerInfo, 0, &threadId);
}
}
}
//-----------------------------------------------------------------------------
/// Insert an APIEntry into the list of entries with profiler results.
/// \param pEntry An APIEntry with a sampled GPU time.
//-----------------------------------------------------------------------------
void VktFrameProfilerLayer::StoreProfilerResult(VktAPIEntry* pEntry)
{
// Need to lock here to control access into our profiling results map
ScopeLock profilerResultsLock(&mProfilingResultsMutex);
UINT32 threadId = osGetCurrentThreadId();
if (mSampleIdToEntry.find(threadId) == mSampleIdToEntry.end())
{
// create a new entry
SampleIdToAPIEntryMap newMap;
newMap[pEntry->m_sampleId] = pEntry;
mSampleIdToEntry[threadId] = newMap;
}
else
{
SampleIdToAPIEntryMap& mapEntry = mSampleIdToEntry[threadId];
mapEntry[pEntry->m_sampleId] = pEntry;
}
}
//-----------------------------------------------------------------------------
/// Insert an APIEntry into the list of entries with profiler results.
/// \param inEntry An APIEntry with a sampled GPU time.
//-----------------------------------------------------------------------------
void DX12FrameProfilerLayer::StoreProfilerResult(DX12APIEntry* inEntry)
{
UINT32 threadId = osGetCurrentThreadId();
if (mSampleIdToEntry.find(threadId) == mSampleIdToEntry.end())
{
// create a new entry
SampleIdToAPIEntryMap newMap;
newMap[inEntry->mSampleId] = inEntry;
// adding a new thread to the map so need to lock
ScopeLock profilerResultsLock(&mProfilingResultsMutex);
mSampleIdToEntry[threadId] = newMap;
}
else
{
SampleIdToAPIEntryMap& mapEntry = mSampleIdToEntry[threadId];
mapEntry[inEntry->mSampleId] = inEntry;
}
}
//-----------------------------------------------------------------------------
/// Profiler results collection worker function.
/// \param lpParam A void pointer to the incoming VktWorkerInfo argument.
/// \returns Always 0.
//-----------------------------------------------------------------------------
DWORD WINAPI ThreadFunc(LPVOID lpParam)
{
VktWorkerInfo* pWorkerInfo = (VktWorkerInfo*)lpParam;
pWorkerInfo->m_threadInfo.workerThreadID = osGetCurrentThreadId();
VkResult waitResult = VK_TIMEOUT;
#if GPU_FENCES_FOR_PROFILER_WAIT
VkDevice device = pWorkerInfo->m_inputs.pQueue->ParentDevice();
do
{
waitResult = device_dispatch_table(device)->WaitForFences(device, 1, &pWorkerInfo->m_inputs.fenceToWaitOn, VK_TRUE, GPU_FENCE_TIMEOUT_TIME);
} while (waitResult == VK_TIMEOUT);
#else
VkQueue queue = pWorkerInfo->m_inputs.pQueue->AppHandle();
waitResult = device_dispatch_table(queue)->QueueWaitIdle(queue);
#endif
for (UINT i = 0; i < pWorkerInfo->m_inputs.cmdBufData.size(); i++)
{
VktWrappedCmdBuf* pWrappedCmdBuf = pWorkerInfo->m_inputs.cmdBufData[i].pCmdBuf;
UINT64 targetFillId = pWorkerInfo->m_inputs.cmdBufData[i].targetFillID;
UINT profiledCallCount = pWorkerInfo->m_inputs.cmdBufData[i].profiledCallCount;
ProfilerResultCode profResult = pWrappedCmdBuf->GetCmdBufResultsMT(targetFillId, profiledCallCount, pWorkerInfo->m_outputs.results);
if (profResult != PROFILER_SUCCESS)
{
const char* profilerErrorCode = VktCmdBufProfiler::PrintProfilerResult(profResult);
// Report that a problem occurred in retrieving full profiler results.
Log(logERROR, "Failed to retrieve full profiler results: CmdBuf 0x%p, Queue 0x%p, ErrorCode %s\n",
pWorkerInfo->m_inputs.cmdBufData[i].pCmdBuf, pWorkerInfo->m_inputs.pQueue, profilerErrorCode);
}
}
return 0;
}
// Generate a composite log message - then finally send to handler to write and/or display
void _Log(enum LogType type, const char* fmt, ...)
{
// check to see if logging of the level is enabled, or if s_LogConsole is specified
// if not, don't process it.
int logLevel = SG_GET_INT(OptionLogLevel);
if (((type - logERROR) > logLevel && s_LogConsole == false))
{
return;
}
// Define buffer to store maximum current log message.
// Different destinations will receive a subset of this string.
// On Win32 the entire string is passed to OutputDebugString()
char fullString[PS_LOG_MAX_LENGTH] = "";
int nLen = 0;
int nSize;
bool truncated = false;
char* pLogString; // String to print to logfile
char* pConsole; // String to print to console doesn't include debug information
char* pRaw; // Raw string passed in without any additional decoration
if (truncated == false)
{
// Prepend "PerfStudio: " for windows OutputDebugString() messages
nSize = _snprintf_s(&fullString[nLen], PS_LOG_MAX_LENGTH - nLen, _TRUNCATE, "PerfStudio: ");
if ((truncated = (nSize == -1)) == false)
{
nLen += nSize;
}
}
pLogString = &fullString[nLen]; // logfile message doesn't include above WIN32 section
#if (defined PS_LOG_DEBUG) && (defined _DEBUG)
if (truncated == false)
{
// In debug builds, include the __FILE__, __LINE__ and __FUNCTION__ information
nSize = _snprintf_s(&fullString[nLen], PS_LOG_MAX_LENGTH - nLen, _TRUNCATE, "%s(%d) : %s(): ", s_LogFile, s_LogLine, s_LogFunction);
if ((truncated = (nSize == -1)) == false)
{
nLen += nSize;
}
}
#endif
// Prepend accurate timestamp
if (truncated == false)
{
gtASCIIString time = GetMicroTimeStr();
time = time.substr(12);
nSize = _snprintf_s(&fullString[nLen], PS_LOG_MAX_LENGTH - nLen, _TRUNCATE, "%-14s: ", time.asCharArray());
if ((truncated = (nSize == -1)) == false)
{
nLen += nSize;
}
}
pConsole = &fullString[nLen]; // String to print to console starts here
if (truncated == false)
{
// Add the message type string
switch (type)
{
case logERROR:
nSize = _snprintf_s(&fullString[nLen], PS_LOG_MAX_LENGTH - nLen, _TRUNCATE, "Error: ");
break;
case logWARNING:
nSize = _snprintf_s(&fullString[nLen], PS_LOG_MAX_LENGTH - nLen, _TRUNCATE, "Warning: ");
break;
case logMESSAGE:
nSize = _snprintf_s(&fullString[nLen], PS_LOG_MAX_LENGTH - nLen, _TRUNCATE, "Message: ");
break;
case logTRACE:
nSize = _snprintf_s(&fullString[nLen], PS_LOG_MAX_LENGTH - nLen, _TRUNCATE, "Trace: ");
break;
case logASSERT:
nSize = _snprintf_s(&fullString[nLen], PS_LOG_MAX_LENGTH - nLen, _TRUNCATE, "Assert: ");
break;
case logDEBUG:
nSize = _snprintf_s(&fullString[nLen], PS_LOG_MAX_LENGTH - nLen, _TRUNCATE, "Debug: ");
break;
case logRAW:
// Skip
nSize = 0;
break;
default:
nSize = _snprintf_s(&fullString[nLen], PS_LOG_MAX_LENGTH - nLen, _TRUNCATE, "Unknown: ");
break;
}
if ((truncated = (nSize == -1)) == false)
{
nLen += nSize;
}
}
// Add the module identifier
if (s_LogModule && (truncated == false))
{
nSize = _snprintf_s(&fullString[nLen], PS_LOG_MAX_LENGTH - nLen, _TRUNCATE, "PID: %10u TID: %10u %-14s: ", osGetCurrentProcessId(), osGetCurrentThreadId(), s_LogModule);
if ((truncated = (nSize == -1)) == false)
{
nLen += nSize;
}
}
if (truncated == false)
{
if (SG_GET_INT(OptionLogLevel) >= logTRACE - logERROR)
{
// Add the indent
for (int i = 0; (i < logIndent) && (nLen < PS_LOG_MAX_LENGTH - 1); i++, nLen++)
{
fullString[nLen] = ' ';
}
fullString[nLen] = 0; // Ensure string in buffer remains null terminated
truncated = (nLen == PS_LOG_MAX_LENGTH - 1);
}
}
pRaw = &fullString[nLen]; // Raw undecorated string starts here
// Add the actual Log Message
if (truncated == false)
{
va_list arg_ptr;
va_start(arg_ptr, fmt);
nSize = vsnprintf_s(&fullString[nLen], PS_LOG_MAX_LENGTH - nLen, _TRUNCATE, fmt, arg_ptr);
if ((truncated = (nSize == -1)) == false)
{
nLen += nSize;
}
va_end(arg_ptr);
}
// Check if message has been truncated and clean up accordingly
if (truncated == true)
{
// Truncation occurred - change end of line to reflect this
char truncationString[] = " ... \n";
sprintf_s(&fullString[PS_LOG_MAX_LENGTH - sizeof(truncationString)], sizeof(truncationString), "%s", truncationString);
}
// Message Constructed. Print to Log, Console, and OutputDebugString as necessary
if (type == logRAW)
{
if (s_LogConsole)
{
// Send string to console
printf("%s", pRaw);
}
_logWrite(pRaw);
}
else
{
if (s_LogConsole)
{
// Console messages are always printed in console and in log file
// regardless of logLEVEL
printf("%s", pConsole);
_logWrite(pLogString);
OutputDebugString(fullString);
}
else
{
// not a console message - filter based on log level
if ((type - logERROR) <= SG_GET_INT(OptionLogLevel))
{
if (type == logTRACE)
{
// Trace messages also go to the console
printf("%s", pConsole);
}
_logWrite(pLogString);
OutputDebugString(fullString);
}
}
}
}
