//----------------------------------------------------------------------------- /// 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); } } } }