feature: enable redirecting of PRINT_STRING() outputs

Related-To: NEO-14742
Signed-off-by: Maciej Bielski <maciej.bielski@intel.com>
This commit is contained in:
Maciej Bielski
2025-12-01 19:39:25 +00:00
committed by Compute-Runtime-Automation
parent 850f5b0b26
commit d59df10683
9 changed files with 161 additions and 8 deletions

View File

@@ -6,13 +6,16 @@
*/
#pragma once
#include "shared/source/helpers/common_types.h"
#include "shared/source/helpers/non_copyable_or_moveable.h"
#include "shared/source/helpers/options.h"
#include "shared/source/helpers/string.h"
#include "shared/source/os_interface/sys_calls_common.h"
#include "shared/source/utilities/io_functions.h"
#include <cstdint>
#include <memory>
#include <sstream>
#include <string>
#include <type_traits>
@@ -248,21 +251,79 @@ class DurationLog {
static std::string getTimestamp();
};
template <typename... Args>
void printDebugStringForMacroUseOnly(FILE *stream, Args... args) {
template <bool useFileBackend = true>
struct FileLoggerProxy {
void logString(std::string_view data);
};
template <bool useRealFile, typename... Args>
void logStringToFile(FileLoggerProxy<useRealFile> &loggerProvider, const std::ostringstream &prefix, Args... args) {
constexpr int buffSz = 4096;
char buff[buffSz];
int bytes = 0;
if (not prefix.str().empty()) {
bytes += IoFunctions::snprintf(buff, buffSz, "%s", prefix.str().c_str());
}
bytes += IoFunctions::snprintf(buff, buffSz - bytes, args...);
const int bytesToCopy = std::min(buffSz, bytes + 1);
buff[bytesToCopy - 1] = '\0';
loggerProvider.logString({buff, static_cast<size_t>(bytesToCopy)});
}
template <bool useRealFile, typename... Args>
void printStringForMacroUseOnly(FileLoggerProxy<useRealFile> &loggerProvider, FILE *stream, Args... args) {
enum class RedirectionMode : int32_t {
inactive = 0,
toStdout = 1,
toStderr = 2,
toFile = 3,
maxSentinel = 4
};
std::ostringstream prefix;
if (NEO::debugManager.flags.DebugMessagesBitmask.get() & DebugMessagesBitmask::withPid) {
IoFunctions::fprintf(stream, "[PID: %d] ", getpid());
prefix << "[PID: " << SysCalls::getCurrentProcessId() << "] ";
}
if (NEO::debugManager.flags.DebugMessagesBitmask.get() & DebugMessagesBitmask::withTimestamp) {
IoFunctions::fprintf(stream, "%s", NEO::DurationLog::getTimestamp().c_str());
prefix << NEO::DurationLog::getTimestamp();
}
const auto redirectionMode = [&]() {
const auto flag = NEO::debugManager.flags.ForcePrintsRedirection.get();
if (flag > -1 && flag < toUnderlying(RedirectionMode::maxSentinel)) {
return toEnum<RedirectionMode>(flag);
}
return RedirectionMode::inactive;
}();
switch (redirectionMode) {
case RedirectionMode::toFile:
NEO::logStringToFile(loggerProvider, prefix, args...);
return;
case RedirectionMode::toStdout:
stream = stdout;
break;
case RedirectionMode::toStderr:
stream = stderr;
break;
default:
break;
}
if (not prefix.str().empty()) {
IoFunctions::fprintf(stream, "%s", prefix.str().c_str());
}
IoFunctions::fprintf(stream, args...);
flushDebugStream(stream, args...);
}
#define PRINT_STRING(flag, stream, ...) \
if (flag) { \
NEO::printDebugStringForMacroUseOnly(stream, __VA_ARGS__); \
#define PRINT_STRING(flag, stream, ...) \
if (flag) { \
auto fileLogger = NEO::FileLoggerProxy{}; \
NEO::printStringForMacroUseOnly(fileLogger, stream, __VA_ARGS__); \
}
#define PRINT_DEBUGGER_LOG_TO_FILE(...) \
@@ -277,7 +338,8 @@ void printDebugStringForMacroUseOnly(FILE *stream, Args... args) {
if (NEO::debugManager.flags.DebuggerLogBitmask.get() & NEO::DebugVariables::DEBUGGER_LOG_BITMASK::DUMP_TO_FILE) { \
PRINT_DEBUGGER_LOG_TO_FILE(__VA_ARGS__) \
} else { \
NEO::printDebugStringForMacroUseOnly(OUT, __VA_ARGS__); \
auto fileLogger = NEO::FileLoggerProxy{}; \
NEO::printStringForMacroUseOnly(fileLogger, OUT, __VA_ARGS__); \
}
#define PRINT_DEBUGGER_INFO_LOG(STR, ...) \

View File

@@ -455,6 +455,7 @@ DECLARE_DEBUG_VARIABLE(int32_t, ForceLowLatencyHint, -1, "Force passing low late
DECLARE_DEBUG_VARIABLE(int32_t, EmitMemAdvisePriorToCopyForNonUsm, -1, "Enable Memadvise to system memory for copy/fill with shared system input: -1: default, 0: disabled, 1: enabled")
DECLARE_DEBUG_VARIABLE(int32_t, TreatNonUsmForTransfersAsSharedSystem, -1, "-1: default, 0: import non-usm as external host ptr on copy/fill (legacy mode), 1: treat non usm on copy/fill as shared system usm")
DECLARE_DEBUG_VARIABLE(int32_t, OverrideMadviseSharedSystemPrefetchRegion, -1, "-1: default (madvise), 0: system memory, 1: same-tile local memory")
DECLARE_DEBUG_VARIABLE(int32_t, ForcePrintsRedirection, -1, "-1, 0: redirection inactive, 1: stdout, 2: stderr, 3: file, Force redirecton of PRINT_STRING messages")
/*DIRECT SUBMISSION FLAGS*/
DECLARE_DEBUG_VARIABLE(int32_t, EnableDirectSubmission, -1, "-1: default (disabled), 0: disable, 1:enable. Enables direct submission of command buffers bypassing KMD")

View File

@@ -11,6 +11,7 @@ namespace NEO {
namespace IoFunctions {
fopenFuncPtr fopenPtr = &fopen;
vfprintfFuncPtr vfprintfPtr = &vfprintf;
vsnprintfFuncPtr vsnprintfPtr = &vsnprintf;
fcloseFuncPtr fclosePtr = &fclose;
getenvFuncPtr getenvPtr = &getenv;
fseekFuncPtr fseekPtr = &fseek;

View File

@@ -22,6 +22,7 @@ namespace NEO {
namespace IoFunctions {
using fopenFuncPtr = FILE *(*)(const char *, const char *);
using vfprintfFuncPtr = int (*)(FILE *, char const *const formatStr, va_list arg);
using vsnprintfFuncPtr = int (*)(char *, size_t, char const *const, va_list);
using fcloseFuncPtr = int (*)(FILE *);
using getenvFuncPtr = decltype(&getenv);
using fseekFuncPtr = int (*)(FILE *, long int, int);
@@ -34,6 +35,7 @@ using mkdirFuncPtr = int (*)(const char *);
extern fopenFuncPtr fopenPtr;
extern vfprintfFuncPtr vfprintfPtr;
extern vsnprintfFuncPtr vsnprintfPtr;
extern fcloseFuncPtr fclosePtr;
extern getenvFuncPtr getenvPtr;
extern fseekFuncPtr fseekPtr;
@@ -52,6 +54,14 @@ inline int fprintf(FILE *fileDesc, char const *const formatStr, ...) {
return ret;
}
inline int snprintf(char *buff, size_t buffLen, char const *const formatStr, ...) {
va_list args;
va_start(args, formatStr);
int ret = IoFunctions::vsnprintfPtr(buff, buffLen, formatStr, args);
va_end(args);
return ret;
}
inline bool getEnvToBool(const char *name) {
const char *env = getenvPtr(name);
if ((nullptr == env) || (0 == strcmp("0", env))) {

View File

@@ -259,4 +259,9 @@ template class FileLogger<DebugFunctionalityLevel::none>;
template class FileLogger<DebugFunctionalityLevel::regKeys>;
template class FileLogger<DebugFunctionalityLevel::full>;
template <>
void FileLoggerProxy<true>::logString(std::string_view data) {
NEO::fileLoggerInstance().logDebugString(true, data);
}
} // namespace NEO

View File

@@ -11,6 +11,7 @@ namespace NEO {
namespace IoFunctions {
fopenFuncPtr fopenPtr = &mockFopen;
vfprintfFuncPtr vfprintfPtr = &mockVfptrinf;
vsnprintfFuncPtr vsnprintfPtr = &mockVsnprintf;
fcloseFuncPtr fclosePtr = &mockFclose;
getenvFuncPtr getenvPtr = &mockGetenv;
fseekFuncPtr fseekPtr = &mockFseek;
@@ -38,6 +39,7 @@ size_t mockFwriteReturn = 0;
char *mockFwriteBuffer = nullptr;
char *mockFreadBuffer = nullptr;
bool mockVfptrinfUseStdioFunction = false;
uint32_t mockVsnprintfCalled = 0U;
const char *openCLDriverName = "igdrcl.dll";

View File

@@ -33,6 +33,7 @@ extern size_t mockFwriteReturn;
extern char *mockFwriteBuffer;
extern char *mockFreadBuffer;
extern bool mockVfptrinfUseStdioFunction;
extern uint32_t mockVsnprintfCalled;
extern std::unordered_map<std::string, std::string> *mockableEnvValues;
@@ -52,6 +53,11 @@ inline int mockVfptrinf(FILE *stream, const char *format, va_list arg) {
return 0x10;
}
inline int mockVsnprintf(char *buff, size_t buffLen, char const *const formatStr, va_list arg) {
++mockVsnprintfCalled;
return ::vsnprintf(buff, buffLen, formatStr, arg);
}
inline int mockFclose(FILE *stream) {
mockFcloseCalled++;
return 0;

View File

@@ -684,4 +684,5 @@ AllowForOutOfOrderHostFunctionExecution = 0
Enable512NumGrfs = 1
EnableUsmPoolResidencyTracking = -1
EnableUsmPoolLazyInit = -1
ForcePrintsRedirection = -1
# Please don't edit below this line

View File

@@ -16,6 +16,7 @@
#include "shared/test/common/helpers/debug_manager_state_restore.h"
#include "shared/test/common/helpers/gtest_helpers.h"
#include "shared/test/common/helpers/stream_capture.h"
#include "shared/test/common/mocks/mock_io_functions.h"
#include "shared/test/common/utilities/base_object_utils.h"
#include "gtest/gtest.h"
@@ -660,3 +661,67 @@ TEST(CpuGpuVaLogging, givenAllocationWithoutCpuVaWhenLoggingAllocationThenNullIs
EXPECT_FALSE(true);
}
}
TEST(PrintsRedirection, GivenForcePrintsRedirectionWhenStdoutForcedThenItWorksCorrectly) {
DebugManagerStateRestore restorer;
NEO::debugManager.flags.ForcePrintsRedirection.set(1);
int i = 4;
int j = 5;
StreamCapture capture;
capture.captureStdout();
PRINT_STRING(true, stdout, "same as default: %d, ", i);
PRINT_STRING(true, stderr, "forced: %d", j);
auto output = capture.getCapturedStdout();
EXPECT_STREQ(output.c_str(), "same as default: 4, forced: 5");
}
TEST(PrintsRedirection, GivenForcePrintsRedirectionWhenStderrForcedThenItWorksCorrectly) {
DebugManagerStateRestore restorer;
NEO::debugManager.flags.ForcePrintsRedirection.set(2);
int i = 4;
int j = 5;
StreamCapture capture;
capture.captureStderr();
PRINT_STRING(true, stdout, "forced: %d, ", i);
PRINT_STRING(true, stderr, "same as default: %d", j);
auto output = capture.getCapturedStderr();
EXPECT_STREQ(output.c_str(), "forced: 4, same as default: 5");
}
template <>
struct NEO::FileLoggerProxy<false> {
static constexpr std::string_view logFileName = "mock_igdrcl.log";
::FullyEnabledFileLogger virtualFileLogger = {std::string(logFileName), NEO::debugManager.flags};
void logString(std::string_view data) {
this->virtualFileLogger.logDebugString(true, data);
}
auto getCapturedString() {
return this->virtualFileLogger.getFileString(std::string(logFileName));
}
};
TEST(PrintsRedirection, GivenForcePrintsRedirectionWhenFileOutputForcedThenItWorksCorrectly) {
DebugManagerStateRestore restorer;
NEO::debugManager.flags.ForcePrintsRedirection.set(3);
int i = 4;
StreamCapture capture;
capture.captureStderr();
capture.captureStdout();
auto callCnt = NEO::IoFunctions::mockVsnprintfCalled;
auto loggerProxy = NEO::FileLoggerProxy<false>{};
NEO::printStringForMacroUseOnly(loggerProxy, stdout, "%s: %d\n", "redirected", i);
EXPECT_EQ(NEO::IoFunctions::mockVsnprintfCalled, callCnt + 1U);
auto capturedFileOutput = loggerProxy.getCapturedString();
auto capturedStdout = capture.getCapturedStdout();
auto capturedStderr = capture.getCapturedStderr();
EXPECT_STREQ(capturedStdout.c_str(), "");
EXPECT_STREQ(capturedStderr.c_str(), "");
EXPECT_STREQ(capturedFileOutput.c_str(), "redirected: 4\n");
}