diff --git a/.github/workflows/native_sanity.yml b/.github/workflows/native_sanity.yml index f9f4c7e..6543e55 100644 --- a/.github/workflows/native_sanity.yml +++ b/.github/workflows/native_sanity.yml @@ -21,7 +21,7 @@ jobs: strategy: matrix: os: [ubuntu-latest, windows-latest] - python-version: ["3.9", "3.10", "3.11"] + python-version: ["3.10", "3.11"] numpy-version: [1.23] build-config: ["Debug", "Release"] steps: diff --git a/.github/workflows/python_package.yml b/.github/workflows/python_package.yml index 5c3d933..b7e618d 100644 --- a/.github/workflows/python_package.yml +++ b/.github/workflows/python_package.yml @@ -20,7 +20,7 @@ jobs: strategy: matrix: os: ["ubuntu-latest", "windows-2022"] - python-version: ["3.9", "3.10", "3.11"] + python-version: ["3.10", "3.11"] numpy-version: [1.23] steps: - name: Checkout repo @@ -86,12 +86,10 @@ jobs: strategy: matrix: os: [ubuntu-latest, windows-2022] - python-version: ["3.9", "3.10", "3.11"] + python-version: ["3.10", "3.11"] numpy-version: [1.23] exclude: - # only latest needed for sdist, so exlude others - - os: ubuntu-latest - python-version: "3.9" + # only latest needed for sdist, so exlude all others - os: ubuntu-latest python-version: "3.10" steps: @@ -151,7 +149,7 @@ jobs: strategy: matrix: os: ["ubuntu-latest", "windows-2022"] - python-version: ["3.9", "3.10", "3.11"] + python-version: ["3.10", "3.11"] numpy-version: [1.23, 1.24] env: ANACONDA_USER: rtosholdings @@ -215,7 +213,7 @@ jobs: strategy: matrix: os: [ubuntu-latest, windows-2022] - python-version: ["3.9", "3.10", "3.11"] + python-version: ["3.10", "3.11"] numpy-version: [1.23, 1.24] steps: - name: Checkout repo (sparse) diff --git a/bench/riptide_bench/riptide_bench/bench_logging.cpp b/bench/riptide_bench/riptide_bench/bench_logging.cpp index 57462de..09297e3 100644 --- a/bench/riptide_bench/riptide_bench/bench_logging.cpp +++ b/bench/riptide_bench/riptide_bench/bench_logging.cpp @@ -1,11 +1,12 @@ -#include "logging/logger.h" +#include "logging/logging.h" #include namespace { using namespace riptide::logging; - auto & logg = logger::get(); + auto service = get_service(); + auto logg = get_logger(); static void bench_logging(benchmark::State & state) { @@ -17,15 +18,15 @@ namespace { for (auto i = 0; i < num_logs; i++) { - logg.log(loglevel::debug, "Thread: {0} log number: {1}", id, i); + logg->log(loglevel::debug, "Thread: {0} log number: {1}", id, i); } }; auto consume = [=]() { - while (logg.active()) + while (service->active()) { - auto curr{ logg.receive() }; + auto curr{ service->receive() }; if (! curr) break; @@ -34,7 +35,8 @@ namespace } }; - logg.enable({ .max_size = 1'000'000'000, .level = loglevel::debug }); + logg->set_level(loglevel::debug); + service->enable({ .max_size = 1'000'000'000 }); std::thread consumer{ consume }; std::vector threads; @@ -49,7 +51,7 @@ namespace t.join(); } - logg.disable(); + service->disable(); consumer.join(); } } diff --git a/conda_recipe/conda_build_config.yaml b/conda_recipe/conda_build_config.yaml index 0222238..e5aa72b 100644 --- a/conda_recipe/conda_build_config.yaml +++ b/conda_recipe/conda_build_config.yaml @@ -1,10 +1,10 @@ # The python and numpy variants are only used for local conda builds. # They are overridden by the CI scripts. python: - - 3.9 + - 3.11 numpy: - - 1.23 + - 1.24 c_compiler: - vs2022 # [win] diff --git a/extras/sdsfile/CMakeLists.txt b/extras/sdsfile/CMakeLists.txt index 582d549..143e2c4 100644 --- a/extras/sdsfile/CMakeLists.txt +++ b/extras/sdsfile/CMakeLists.txt @@ -20,6 +20,7 @@ set(HEADERS ../../src/MathThreads.h ../../src/MathWorker.h ../../src/SDSFile.h + ../../src/logging/logging.h ../../src/SharedMemory.h ../../src/ZstdCompress.h) @@ -29,6 +30,7 @@ set(SOURCES ../../src/MathThreads.cpp ../../src/MathWorker.cpp ../../src/SDSFile.cpp + ../../src/logging/logging.cpp ../../src/SharedMemory.cpp ../../src/ZstdCompress.cpp) diff --git a/extras/sdsfile/dllmain.cpp b/extras/sdsfile/dllmain.cpp index a6b1001..c5e1d56 100644 --- a/extras/sdsfile/dllmain.cpp +++ b/extras/sdsfile/dllmain.cpp @@ -1,15 +1,36 @@ // dllmain.cpp : Defines the entry point for the DLL application. -#include #include "../../src/CommonInc.h" #include "../../src/MathWorker.h" #include "../../src/SDSFile.h" +#include +#include + //#define LOGGING printf #define LOGGING(...) //---------------------------------------------------------------------------------- -CMathWorker * g_cMathWorker = new CMathWorker(); -bool g_bStarted = false; +CMathWorker * g_cMathWorker = nullptr; //new CMathWorker(); + +namespace +{ + // Starting working threads requires thread synchronization, so it cannot be + // called from DllMain or from static object. + // Each API needs to call ensure_threads_started() to ensure that threads have been + // started prior to continuing. + + std::once_flag g_bStarted{}; + + void ensure_threads_started() + { + std::call_once(g_bStarted, + []() + { + g_cMathWorker = new CMathWorker(); + g_cMathWorker->StartWorkerThreads(0); + }); + } +} static int64_t g_TotalAllocs = 0; static int64_t g_TotalFree = 0; @@ -140,18 +161,10 @@ uint64_t GetUTCNanos() #if defined(_WIN32) bool APIENTRY DllMain(HMODULE hModule, DWORD ul_reason_for_call, LPVOID lpReserved) { + // NOTE: Cannot do any thread-related work in DllMain. switch (ul_reason_for_call) { case DLL_PROCESS_ATTACH: - - if (! g_bStarted) - { - g_bStarted = true; - - // default to numa node 0 - g_cMathWorker->StartWorkerThreads(0); - } - break; case DLL_THREAD_ATTACH: case DLL_THREAD_DETACH: case DLL_PROCESS_DETACH: @@ -419,6 +432,8 @@ extern "C" // pointer to stReadSharedMemory RT_DLLEXPORT stReadSharedMemory * ReadFromSharedMemory(const char * fileName, const char * shareName) { + ensure_threads_started(); + // uint64_t fileNameSize; // uint64_t shareNameSize = 0; @@ -815,6 +830,8 @@ extern "C" const char * inListNames, // use commas to separate int64_t totalRows, int64_t bandSize = 0) { + ensure_threads_started(); + bool result = CreateSDSFileInternal(fileName, shareName, metaData, inListNames, // use commas to separate totalRows, bandSize); @@ -829,10 +846,11 @@ extern "C" // shareName: the sharename the user provided, may be NULL // Returns: // true/false - RT_DLLEXPORT bool AppendSDSFile(const char * outFileName, - - const char * shareFileName, const char * shareName, int64_t totalRows, int64_t bandSize = 0) + RT_DLLEXPORT bool AppendSDSFile(const char * outFileName, const char * shareFileName, const char * shareName, + int64_t totalRows, int64_t bandSize = 0) { + ensure_threads_started(); + stReadSharedMemory * pSharedMemory = (stReadSharedMemory *)ReadFromSharedMemory(shareFileName, shareName); if (pSharedMemory) { diff --git a/pyproject.toml b/pyproject.toml index aa22da7..98ad4ee 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,13 +4,12 @@ description = "Python Package with fast math util functions" readme = "README.md" license = { file = "LICENSE" } authors = [{ name = "RTOS Holdings", email = "rtosholdings-bot@sig.com" }] -requires-python = ">=3.9" +requires-python = ">=3.10" dynamic = ["version"] classifiers = [ "Development Status :: 4 - Beta", "Intended Audience :: Developers", "Programming Language :: Python :: 3", - "Programming Language :: Python :: 3.9", "Programming Language :: Python :: 3.10", "Programming Language :: Python :: 3.11", "License :: OSI Approved :: BSD License", @@ -87,10 +86,6 @@ cmake.args = [ ] # Static way of passing current Python version to CMake. -[[tool.scikit-build.overrides]] -if.python-version = "~=3.9" -cmake.define = { "RIPTIDE_PYTHON_VER" = "3.9" } - [[tool.scikit-build.overrides]] if.python-version = "~=3.10" cmake.define = { "RIPTIDE_PYTHON_VER" = "3.10" } diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index 97f3d9e..af2a662 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -18,6 +18,7 @@ set(HEADERS Hook.h is_member_tg.h Logger.h + logging/logging.h MathThreads.h MathWorker.h Merge.h @@ -54,6 +55,7 @@ set(SOURCES Hook.cpp is_member_tg.cpp Logger.cpp + logging/logging.cpp MathThreads.cpp MathWorker.cpp Merge.cpp diff --git a/src/DateTime.cpp b/src/DateTime.cpp index 4704de2..db40c95 100644 --- a/src/DateTime.cpp +++ b/src/DateTime.cpp @@ -3,6 +3,11 @@ #include "MathWorker.h" #include "DateTime.h" +#include +#include +#include +#include + const char * rt_strptime(const char * buf, const char * fmt, struct tm * tm); #define LOGGING(...) @@ -10,6 +15,74 @@ const char * rt_strptime(const char * buf, const char * fmt, struct tm * tm); const char COLON = ':'; const char PERIOD = '.'; +template +struct parsing_error +{ + const T * start; + const T * end; + const char * message; + int64_t position; + + parsing_error(const T * start, const T * end, const char * message, int64_t position) + : start(start) + , end(end) + , message(message) + , position(position) + { + } +}; + +template +class DateTimeParser +{ + const T * pStartCopy = nullptr; // Start of the string + const T * pStart = nullptr; // Current parser position + const T * pEnd = nullptr; // End of the string + + std::optional> error; // First parsing error encountered + +public: + void ParseDateTimeString(int64_t * pOutNanoTime, int64_t arrayLength, const T * pString, int64_t itemSize); + void ParseDateString(int64_t * pOutNanoTime, int64_t arrayLength, const T * pString, int64_t itemSize); + void ParseTimeString(int64_t * pOutNanoTime, int64_t arrayLength, const T * pString, int64_t itemSize); + + RT_FORCEINLINE int64_t ParseNumber(int64_t maxplaces); + bool ParseSingleNonNumber(T expected); + + void consume_leading_whitespace() + { + while (! at_end() && std::isspace(*pStart)) + pStart++; + } + + void consume_trailing_characters() + { + while (! at_end()) + { + if (! std::isspace(*pStart)) + set_error("Unexpected characters"); + + pStart++; + } + } + + bool at_end() const + { + return pStart >= pEnd || *pStart == '\0'; + } + + void set_error(const char * message) + { + if (! error.has_value()) + error = parsing_error(pStartCopy, pEnd, message, pStart - pStartCopy); + } + + const std::optional> & get_error() const + { + return error; + } +}; + //------------------------------------------------------------------ // T is either a char or UCS4 (byte string or unicode string) // pStart updated on return @@ -48,11 +121,26 @@ RT_FORCEINLINE int64_t ParseDecimal(const T ** ppStart, const T * pEnd) num = num * 10; places++; } + + *ppStart = pStart; return num; } // Return non-zero if success and increments pStart -#define ParseSingleNonNumber(pStartX, pEndX) ((pStartX < pEndX && (*pStartX < '0' || *pStartX > '9')) ? ++pStartX : 0) +template +bool DateTimeParser::ParseSingleNonNumber(T expected) +{ + if (pStart < pEnd && (*pStart < '0' || *pStart > '9')) + { + if (*pStart != expected) + set_error("Unexpected delimiter"); + + pStart++; + return true; + } + + return false; +} //------------------------------------------------------------------ // T is either a char or UCS4 (byte string or unicode string) @@ -60,15 +148,14 @@ RT_FORCEINLINE int64_t ParseDecimal(const T ** ppStart, const T * pEnd) // will stop at end, stop at nonnumber, or when places reached // pStart updated on return template -RT_FORCEINLINE int64_t ParseNumber(const T ** ppStart, const T * pEnd, int64_t maxplaces) +RT_FORCEINLINE int64_t DateTimeParser::ParseNumber(int64_t maxplaces) { - const T * pStart = *ppStart; - // skip non numbers in front while (pStart < pEnd) { if (*pStart < '0' || *pStart > '9') { + set_error("Unexpected characters"); pStart++; continue; } @@ -93,8 +180,6 @@ RT_FORCEINLINE int64_t ParseNumber(const T ** ppStart, const T * pEnd, int64_t m break; } - // update pStart - *ppStart = pStart; return num; } @@ -103,54 +188,66 @@ RT_FORCEINLINE int64_t ParseNumber(const T ** ppStart, const T * pEnd, int64_t m // T is either a char or UCS4 (byte string or unicode string) // template -void ParseTimeString(int64_t * pOutNanoTime, int64_t arrayLength, const T * pString, int64_t itemSize) +void DateTimeParser::ParseTimeString(int64_t * pOutNanoTime, int64_t arrayLength, const T * pString, int64_t itemSize) { for (int64_t i = 0; i < arrayLength; i++) { - const T * pStart = &pString[i * itemSize]; - const T * pEnd = pStart + itemSize; + pStartCopy = pStart = &pString[i * itemSize]; + pEnd = pStart + itemSize; + + consume_leading_whitespace(); + + if (at_end()) + { + pOutNanoTime[i] = 0; + continue; + } int64_t hour = 0; int64_t minute = 0; int64_t seconds = 0; - bool bSuccess = 0; + bool bSuccess = 1; + pOutNanoTime[i] = 0; - hour = ParseNumber(&pStart, pEnd, 2); + hour = ParseNumber(2); + if (hour >= 24) + bSuccess = 0; // could check for colon here... - if (hour < 24 && ParseSingleNonNumber(pStart, pEnd)) + if (ParseSingleNonNumber(':')) { // could check for colon here... - minute = ParseNumber(&pStart, pEnd, 2); + minute = ParseNumber(2); + if (minute >= 60) + bSuccess = 0; - if (minute < 60) + // seconds are not required + if (ParseSingleNonNumber(':')) { - // seconds are not required - if (ParseSingleNonNumber(pStart, pEnd)) - { - seconds = ParseNumber(&pStart, pEnd, 2); - } - - bSuccess = 1; + seconds = ParseNumber(2); + if (seconds >= 60) + bSuccess = 0; + } + if (bSuccess) + { LOGGING("time: %lld:%lld:%lld\n", hour, minute, seconds); pOutNanoTime[i] = 1000000000LL * ((hour * 3600) + (minute * 60) + seconds); + } - // check for milli/micro/etc seconds - if (pStart < pEnd && *pStart == PERIOD) - { - // skip decimal - pStart++; - pOutNanoTime[i] += ParseDecimal(&pStart, pEnd); - } + // check for milli/micro/etc seconds + if (pStart < pEnd && *pStart == PERIOD) + { + // skip decimal + pStart++; + int64_t decimal = ParseDecimal(&pStart, pEnd); + if (bSuccess) + pOutNanoTime[i] += decimal; } } - if (! bSuccess) - { - pOutNanoTime[i] = 0; - } + consume_trailing_characters(); } } @@ -216,25 +313,43 @@ int64_t YearToEpochNano(int64_t year, int64_t month, int64_t day) // T is either a char or UCS4 (byte string or unicode string) // template -void ParseDateString(int64_t * pOutNanoTime, int64_t arrayLength, const T * pString, int64_t itemSize) +void DateTimeParser::ParseDateString(int64_t * pOutNanoTime, int64_t arrayLength, const T * pString, int64_t itemSize) { for (int64_t i = 0; i < arrayLength; i++) { - const T * pStart = &pString[i * itemSize]; - const T * pEnd = pStart + itemSize; + pStartCopy = pStart = &pString[i * itemSize]; + pEnd = pStart + itemSize; + + consume_leading_whitespace(); + + if (at_end()) + { + pOutNanoTime[i] = 0; + continue; + } int64_t year = 0; int64_t month = 0; int64_t day = 0; - year = ParseNumber(&pStart, pEnd, 4); - // could check for dash here... - month = ParseNumber(&pStart, pEnd, 2); - day = ParseNumber(&pStart, pEnd, 2); + year = ParseNumber(4); + + bool expect_delimiter = ParseSingleNonNumber('-'); + + month = ParseNumber(2); + + if (expect_delimiter != ParseSingleNonNumber('-')) + set_error(expect_delimiter ? "Expected delimiter" : "Unexpected delimiter"); + + day = ParseNumber(2); + LOGGING("date: %lld:%lld:%lld\n", year, month, day); int64_t result = YearToEpochNano(year, month, day); if (result < 0) result = 0; + + consume_trailing_characters(); + pOutNanoTime[i] = result; } } @@ -244,77 +359,118 @@ void ParseDateString(int64_t * pOutNanoTime, int64_t arrayLength, const T * pStr // T is either a char or UCS4 (byte string or unicode string) // Anything invalid is set to 0 template -void ParseDateTimeString(int64_t * pOutNanoTime, int64_t arrayLength, const T * pString, int64_t itemSize) +void DateTimeParser::ParseDateTimeString(int64_t * pOutNanoTime, int64_t arrayLength, const T * pString, int64_t itemSize) { for (int64_t i = 0; i < arrayLength; i++) { - const T * pStart = &pString[i * itemSize]; - const T * pEnd = pStart + itemSize; + pStartCopy = pStart = &pString[i * itemSize]; + pEnd = pStart + itemSize; + + consume_leading_whitespace(); + + if (at_end()) + { + pOutNanoTime[i] = 0; + continue; + } int64_t year = 0; int64_t month = 0; int64_t day = 0; + bool bSuccess = 1; + + year = ParseNumber(4); + + bool expect_delimiter = ParseSingleNonNumber('-'); + + month = ParseNumber(2); + + if (expect_delimiter != ParseSingleNonNumber('-')) + set_error(expect_delimiter ? "Expected delimiter" : "Unexpected delimiter"); + + day = ParseNumber(2); - year = ParseNumber(&pStart, pEnd, 4); - // could check for dash here... - month = ParseNumber(&pStart, pEnd, 2); - day = ParseNumber(&pStart, pEnd, 2); LOGGING("date: %lld:%lld:%lld\n", year, month, day); int64_t yearresult = YearToEpochNano(year, month, day); - // What if year is negative? - if (yearresult >= 0) + if (yearresult < 0) { - int64_t hour = 0; - int64_t minute = 0; - int64_t seconds = 0; - bool bSuccess = 0; + bSuccess = 0; + yearresult = 0; + } - if (ParseSingleNonNumber(pStart, pEnd)) - { - hour = ParseNumber(&pStart, pEnd, 2); + int64_t hour = 0; + int64_t minute = 0; + int64_t seconds = 0; - // could check for colon here... - if (hour < 24 && ParseSingleNonNumber(pStart, pEnd)) - { - minute = ParseNumber(&pStart, pEnd, 2); - - if (minute < 60) - { - // seconds do not have to exist - if (ParseSingleNonNumber(pStart, pEnd)) - { - seconds = ParseNumber(&pStart, pEnd, 2); - } - - bSuccess = 1; - } - } - } + if (pStart < pEnd && (*pStart < '0' || *pStart > '9')) + { + if (*pStart != 'T' && *pStart != ' ') + set_error("Unexpected delimiter"); - if (bSuccess) + pStart++; + hour = ParseNumber(2); + if (hour >= 24) + bSuccess = 0; + + // could check for colon here... + if (ParseSingleNonNumber(':')) { - LOGGING("time: %lld:%lld:%lld\n", hour, minute, seconds); - yearresult += (1000000000LL * ((hour * 3600) + (minute * 60) + seconds)); + minute = ParseNumber(2); + if (minute >= 60) + bSuccess = 0; - // check for milli/micro/etc seconds - if (pStart < pEnd && *pStart == PERIOD) + // seconds do not have to exist + if (ParseSingleNonNumber(':')) { - // skip decimal - pStart++; - yearresult += ParseDecimal(&pStart, pEnd); + seconds = ParseNumber(2); + if (seconds >= 60) + bSuccess = 0; } } } - else + + if (bSuccess) { - yearresult = 0; + LOGGING("time: %lld:%lld:%lld\n", hour, minute, seconds); + yearresult += (1000000000LL * ((hour * 3600) + (minute * 60) + seconds)); } + // check for milli/micro/etc seconds + if (pStart < pEnd && *pStart == PERIOD) + { + // skip decimal + pStart++; + int64_t decimal = ParseDecimal(&pStart, pEnd); + + if (bSuccess) + yearresult += decimal; + } + + consume_trailing_characters(); + pOutNanoTime[i] = yearresult; } } +template +void parsing_error_to_py_warning(const parsing_error & error); + +template <> +void parsing_error_to_py_warning(const parsing_error & error) +{ + std::string datetime(error.start, error.end); + PyErr_WarnFormat(PyExc_RuntimeWarning, 1, "%s in \"%s\" at position %lld", error.message, datetime.c_str(), error.position); +} + +template <> +void parsing_error_to_py_warning(const parsing_error & error) +{ + PyObject * datetime = PyUnicode_FromKindAndData(PyUnicode_4BYTE_KIND, error.start, error.end - error.start); + PyErr_WarnFormat(PyExc_RuntimeWarning, 1, "%s in \"%U\" at position %lld", error.message, datetime, error.position); + Py_XDECREF(datetime); +} + //-------------------------------------------------------------- // Arg1: input numpy array time == assumes int64_t for now // HH:MM:SS format @@ -355,11 +511,21 @@ PyObject * TimeStringToNanos(PyObject * self, PyObject * args) if (dType == NPY_STRING) { - ParseTimeString(pNanoTime, arrayLength, pString, itemSize); + DateTimeParser parser; + parser.ParseTimeString(pNanoTime, arrayLength, pString, itemSize); + + const auto & maybe_error = parser.get_error(); + if (maybe_error) + parsing_error_to_py_warning(*maybe_error); } else { - ParseTimeString(pNanoTime, arrayLength, (uint32_t *)pString, itemSize / 4); + DateTimeParser parser; + parser.ParseTimeString(pNanoTime, arrayLength, (uint32_t *)pString, itemSize / 4); + + const auto & maybe_error = parser.get_error(); + if (maybe_error) + parsing_error_to_py_warning(*maybe_error); } return (PyObject *)outArray; } @@ -408,11 +574,21 @@ PyObject * DateStringToNanos(PyObject * self, PyObject * args) if (dType == NPY_STRING) { - ParseDateString(pNanoTime, arrayLength, pString, itemSize); + DateTimeParser parser; + parser.ParseDateString(pNanoTime, arrayLength, pString, itemSize); + + const auto & maybe_error = parser.get_error(); + if (maybe_error) + parsing_error_to_py_warning(*maybe_error); } else { - ParseDateString(pNanoTime, arrayLength, (uint32_t *)pString, itemSize / 4); + DateTimeParser parser; + parser.ParseDateString(pNanoTime, arrayLength, (uint32_t *)pString, itemSize / 4); + + const auto & maybe_error = parser.get_error(); + if (maybe_error) + parsing_error_to_py_warning(*maybe_error); } return (PyObject *)outArray; } @@ -461,11 +637,21 @@ PyObject * DateTimeStringToNanos(PyObject * self, PyObject * args) if (dType == NPY_STRING) { - ParseDateTimeString(pNanoTime, arrayLength, pString, itemSize); + DateTimeParser parser; + parser.ParseDateTimeString(pNanoTime, arrayLength, pString, itemSize); + + const auto & maybe_error = parser.get_error(); + if (maybe_error) + parsing_error_to_py_warning(*maybe_error); } else { - ParseDateTimeString(pNanoTime, arrayLength, (uint32_t *)pString, itemSize / 4); + DateTimeParser parser; + parser.ParseDateTimeString(pNanoTime, arrayLength, (uint32_t *)pString, itemSize / 4); + + const auto & maybe_error = parser.get_error(); + if (maybe_error) + parsing_error_to_py_warning(*maybe_error); } return (PyObject *)outArray; } diff --git a/src/GroupBy.cpp b/src/GroupBy.cpp index c546ce0..72a9c52 100644 --- a/src/GroupBy.cpp +++ b/src/GroupBy.cpp @@ -7,15 +7,18 @@ #include "Heap.h" #include "missing_values.h" #include "numpy_traits.h" - +#include "logging/logging.h" #include #include #include #include #include -#define LOGGING(...) -// #define LOGGING printf +namespace +{ + static auto logger = riptide::logging::get_logger("GroupBy"); + using loglevel = riptide::logging::loglevel; +} // Overloads to handle case of bool inline bool MEDIAN_SPLIT(bool X, bool Y) @@ -491,7 +494,7 @@ class GroupByBase U const invalid{ riptide::invalid_for_type::value }; if (pass <= 0) { - // printf("NanMin clearing at %p %lld %lld\n", pOut, binLow, binHigh); + logger->debug("NanMin clearing at pOut: {} low: {} high: {}", (void *)pOut, binLow, binHigh); for (int64_t i = binLow; i < binHigh; i++) { pOut[i] = invalid; @@ -1200,20 +1203,18 @@ class GroupByBase V const * const pFirst = (V *)pFirstT; V const * const pCount = (V *)pCountT; - LOGGING("in accum first low: %lld high: %lld group:%p first:%p count:%p\n", binLow, binHigh, pGroup, pFirst, pCount); + logger->debug("in accum first low: {} high: {} group: {} first: {} count:{}\n", binLow, binHigh, (void *)pGroup, + (void *)pFirst, (void *)pCount); U const invalid{ riptide::invalid_for_type::value }; // For all the bins we have to fill for (int64_t i = binLow; i < binHigh; i++) { - // printf("[%lld]", i); if (pCount[i] > 0) { V grpIndex = pFirst[i]; - // printf("(%d)", grpIndex); V bin = pGroup[grpIndex]; - // printf("{%lld}", (int64_t)bin); pDest[i] = pSrc[bin]; } else @@ -1263,14 +1264,11 @@ class GroupByBase V const * const pCount = (V *)pCountT; U const invalid{ riptide::invalid_for_type::value }; - // printf("last called %lld -- %llu %llu %llu\n", numUnique, sizeof(T), - // sizeof(U), sizeof(V)); + logger->debug("AccumLast: T: {} U: {} V: {}", sizeof(T), sizeof(U), sizeof(V)); // For all the bins we have to fill for (int64_t i = binLow; i < binHigh; i++) { - // printf("Last: %d %d\n", (int)pFirst[i], (int)pCount[i]); - // printf("Last2: %d\n", (int)(pGroup[pFirst[i] + pCount[i] - 1])); if (pCount[i] > 0) { V grpIndex = pFirst[i] + pCount[i] - 1; @@ -1709,7 +1707,7 @@ class GroupByBase int64_t const windowSize = funcParam; U const invalid{ riptide::invalid_for_type::value }; - LOGGING("in rolling count %lld %lld sizeofdest %lld\n", binLow, binHigh, sizeof(U)); + logger->debug("AccumRollingCount {} {} sizeofdest {}", binLow, binHigh, sizeof(U)); if (binLow == 0) { @@ -1732,8 +1730,6 @@ class GroupByBase U currentSum = 0; - // printf("in rolling count [%lld] %d %d\n", i, start, last); - if (windowSize < 0) { for (V j = last - 1; j >= start; j--) @@ -1776,8 +1772,7 @@ class GroupByBase int64_t windowSize = (int64_t)funcParam; - // printf("binlow %lld, binhigh %lld, windowSize: %d\n", binLow, binHigh, - // windowSize); + logger->debug("AcculRollingShift: binlow {}, binhigh {}, windowSize: {}", binLow, binHigh, windowSize); if (binLow == 0) { @@ -1840,8 +1835,6 @@ class GroupByBase windowSize = -windowSize; last--; start--; - // printf("bin[%lld] start:%d last:%d windowSize:%d\n", i, start, - // last, windowSize); for (V j = last; j > start && j > (last - windowSize); j--) { @@ -2001,7 +1994,7 @@ class GroupByBase U const invalid{ riptide::invalid_for_type::value }; - LOGGING("TrimMean rows: %lld\n", totalInputRows); + logger->debug("TrimMean rows: {}", totalInputRows); // For all the bins we have to fill for (int64_t i = binLow; i < binHigh; i++) @@ -2080,7 +2073,7 @@ class GroupByBase T * pSort = (T *)WORKSPACE_ALLOC(totalInputRows * sizeof(T)); U const invalid{ riptide::invalid_for_type::value }; - // printf("Mode %llu\n", totalInputRows); + logger->debug("AccumMode {}", totalInputRows); // For all the bins we have to fill for (int64_t i = binLow; i < binHigh; i++) @@ -2183,8 +2176,7 @@ class GroupByBase // Alloc T * const pSort = (T *)WORKSPACE_ALLOC(totalInputRows * sizeof(T)); - LOGGING("Quantile %llu %lld %lld sizeof: %lld %lld %lld\n", totalInputRows, binLow, binHigh, sizeof(T), sizeof(U), - sizeof(V)); + logger->debug("Quantile {} {} {} sizeof: {} {} {}", totalInputRows, binLow, binHigh, sizeof(T), sizeof(U), sizeof(V)); // For all the bins we have to fill for (int64_t i = binLow; i < binHigh; i++) @@ -2294,8 +2286,7 @@ class GroupByBase // Alloc T * pSort = (T *)WORKSPACE_ALLOC(totalInputRows * sizeof(T)); - LOGGING("Median %llu %lld %lld sizeof: %lld %lld %lld\n", totalInputRows, binLow, binHigh, sizeof(T), sizeof(U), - sizeof(V)); + logger->debug("AccumMedian {} {} {} sizeof: {} {} {}", totalInputRows, binLow, binHigh, sizeof(T), sizeof(U), sizeof(V)); // For all the bins we have to fill for (int64_t i = binLow; i < binHigh; i++) @@ -2312,8 +2303,6 @@ class GroupByBase // Copy over the items for this group for (V j = 0; j < nCount; j++) { - // printf("**[%lld][%d] %d\n", i, index + j, (int32_t)pGroup[index + - // j]); pSort[j] = pSrc[pGroup[index + j]]; } @@ -2325,7 +2314,6 @@ class GroupByBase T * pEnd = pSort + nCount - 1; while (pEnd >= pSort) { - // printf("checking %lf\n", (double)*pEnd); if (*pEnd == *pEnd) break; pEnd--; @@ -2353,7 +2341,6 @@ class GroupByBase middle = MEDIAN_SPLIT(pSort[nCount / 2], pSort[(nCount / 2) - 1]); } - // printf("step3 %lf, %lf ==> %lf\n", (double)pSort[nCount / 2], // (double)pSort[(nCount / 2) - 1], (double)middle); // copy the data over from pCount[i] pDest[i] = middle; @@ -2374,7 +2361,7 @@ class GroupByBase V const * const pFirst = (V *)pFirstT; V const * const pCount = (V *)pCountT; - // printf("Median string %llu\n", totalInputRows); + logger->debug("AccumMedian rows {}", totalInputRows); // For all the bins we have to fill for (int64_t i = binLow; i < binHigh; i++) { @@ -3690,7 +3677,7 @@ static GROUPBY_TWO_FUNC GetGroupByFunction(bool * hasCounts, int32_t * wantedOut template static GROUPBY_X_FUNC GetGroupByXFunction(int inputType, int outputType, GB_FUNCTIONS func) { - LOGGING("GBX Func is %d inputtype: %d outputtype: %d\n", func, inputType, outputType); + logger->debug("GBX Func is {} inputtype: {} outputtype: {}", static_cast(func), inputType, outputType); static_assert(std::is_signed::value, "Array types must be signed"); if (func == GB_TRIMBR) @@ -3772,7 +3759,7 @@ static GROUPBY_X_FUNC GetGroupByXFunction(int inputType, int outputType, GB_FUNC } else if (func == GB_ROLLING_DIFF) { - LOGGING("Rolling+diff called with type %d\n", inputType); + logger->debug("Rolling+diff called with type {}", inputType); switch (inputType) { // case NPY_BOOL: @@ -3804,7 +3791,7 @@ static GROUPBY_X_FUNC GetGroupByXFunction(int inputType, int outputType, GB_FUNC } else if (func == GB_ROLLING_SHIFT) { - LOGGING("Rolling shift called with type %d\n", inputType); + logger->debug("Rolling shift called with type {}", inputType); switch (inputType) { case NPY_BOOL: @@ -3842,7 +3829,7 @@ static GROUPBY_X_FUNC GetGroupByXFunction(int inputType, int outputType, GB_FUNC { if (func == GB_ROLLING_MEAN || func == GB_ROLLING_NANMEAN || func == GB_ROLLING_QUANTILE) { - LOGGING("Rolling+mean called with type %d\n", inputType); + logger->debug("Rolling+mean called with type {}", inputType); // default to a double for output switch (inputType) { @@ -3874,7 +3861,7 @@ static GROUPBY_X_FUNC GetGroupByXFunction(int inputType, int outputType, GB_FUNC else { // due to overflow, all ints become int64_t - LOGGING("Rolling+sum called with type %d\n", inputType); + logger->debug("Rolling+sum called with type {}", inputType); switch (inputType) { // really need to change output type for accumsum/rolling @@ -3956,7 +3943,7 @@ static bool BandedGroupByCall(struct stMATH_WORKER_ITEM * pstWorkerItem, int cor int64_t workBlock; // As long as there is work to do - while ((index = pstWorkerItem->GetNextWorkIndex(&workBlock)) > 0) + while ((index = pstWorkerItem->GetNextWorkIndex(&workBlock)) >= 0) { // aInfo only valid if we are the worker (otherwise this pointer is invalid) ArrayInfo * aInfo = pGroupBy32->aInfo; @@ -3969,10 +3956,7 @@ static bool BandedGroupByCall(struct stMATH_WORKER_ITEM * pstWorkerItem, int cor GROUPBY_X_FUNC pFunctionX = pGroupBy32->returnObjects[0].pFunctionX; void * pDataOut = pGroupBy32->returnObjects[0].pOutArray; - // First index is 1 so we subtract - index--; - - LOGGING("|%d %d %lld %p %p", core, (int)workBlock, index, pDataIn, pDataOut); + logger->debug("BandedGroupByCall |{} {} {} {} {}", core, (int)workBlock, index, pDataIn, pDataOut); int64_t binLow = pGroupBy32->returnObjects[index].binLow; int64_t binHigh = pGroupBy32->returnObjects[index].binHigh; @@ -4022,12 +4006,12 @@ static bool ScatterGroupByCall(struct stMATH_WORKER_ITEM * pstWorkerItem, int co int64_t itemSize1 = aInfo[0].ItemSize; int64_t itemSize2 = pGroupBy32->itemSize2; - // printf("Scatter working core %d %lld\n", core, len); + logger->debug("Scatter working core {} {}", core, len); // As long as there is work to do while ((lenX = pstWorkerItem->GetNextWorkBlock(&workBlock)) > 0) { - // printf("|%d %d %lld %p %p %p %p", core, (int)workBlock, lenX, pDataIn, - // pDataIn2, pCountOut, pDataOut); + logger->debug("ScatterGroupByCall: {} {} {} {} {} {} {}", core, (int)workBlock, lenX, pDataIn, pDataIn2, pCountOut, + pDataOut); int64_t inputAdj1 = pstWorkerItem->BlockSize * workBlock * itemSize1; int64_t inputAdj2 = pstWorkerItem->BlockSize * workBlock * itemSize2; @@ -4075,16 +4059,16 @@ void GroupByCall(void * pGroupBy, int64_t i) if (outArray && pFunction) { - LOGGING( - "col %llu ==> outsize %llu len: %llu numpy types %d --> %d " - "%d %d\n", + logger->debug( + "GroupByCall: col {} ==> outsize {} len: {} numpy types {} --> {} " + "{} {}", i, uniqueRows, len, aInfo[i].NumpyDType, numpyOutType, gNumpyTypeToSize[aInfo[i].NumpyDType], gNumpyTypeToSize[numpyOutType]); void * pDataOut = PyArray_BYTES(outArray); void * pDataTmp = pGroupBy32->returnObjects[i].pTmpArray; - LOGGING("%llu typeCall %d numpyOutType %d\n", i, (int)typeCall, numpyOutType); + logger->debug("GroupByCall: {} typeCall {} numpyOutType {}", i, (int)typeCall, numpyOutType); if (typeCall == ANY_GROUPBY_FUNC) { @@ -4107,7 +4091,7 @@ void GroupByCall(void * pGroupBy, int64_t i) // int32_t* pCount, void* pAccumBin, int64_t numUnique, int64_t // totalInputRows, int64_t itemSize, int64_t funcParam) { if (funcNum < GB_FIRST) - printf("!!! internal bug in GroupByCall -- %d\n", funcNum); + logger->warn("!!! internal bug in GroupByCall -- {}", funcNum); if (pFunctionX) { @@ -4117,7 +4101,7 @@ void GroupByCall(void * pGroupBy, int64_t i) } else { - printf("!!!internal error no pfunctionx\n"); + logger->error("!!!internal error no pfunctionx"); } } @@ -4128,13 +4112,13 @@ void GroupByCall(void * pGroupBy, int64_t i) // TJD: memory leak? if (outArray) { - printf("!!! deleting extra object\n"); + logger->warn("!!! deleting extra object\n"); Py_DecRef((PyObject *)outArray); } - LOGGING( - "**skipping col %llu ==> outsize %llu len: %llu numpy types " - "%d --> %d %d %d\n", + logger->debug( + "**skipping col {} ==> outsize {} len: {} numpy types " + "{} --> {} {} {}", i, uniqueRows, len, aInfo[i].NumpyDType, numpyOutType, gNumpyTypeToSize[aInfo[i].NumpyDType], gNumpyTypeToSize[numpyOutType]); pGroupBy32->returnObjects[i].returnObject = Py_None; @@ -4161,6 +4145,7 @@ PyObject * GroupByAll64(PyObject * self, PyObject * args) } // STUB NOT COMPLETED + PyErr_SetNone(PyExc_NotImplementedError); return NULL; } @@ -4204,7 +4189,7 @@ PyObject * GroupBySingleOpMultiBands(ArrayInfo * aInfo, PyArrayObject * iKey, Py int32_t numpyOutType = aInfo[0].NumpyDType; bool hasCounts = false; - LOGGING("In banded groupby %d\n", (int)firstFuncNum); + logger->debug("GroupBySingleOpMultiBands: func {}", (int)firstFuncNum); GROUPBY_X_FUNC pFunction = NULL; @@ -4242,7 +4227,7 @@ PyObject * GroupBySingleOpMultiBands(ArrayInfo * aInfo, PyArrayObject * iKey, Py if (bins < cores) cores = bins; - LOGGING("Banded cores %lld\n", cores); + logger->debug("Banded cores {}", cores); // See if we get a work item (threading might be off) stMATH_WORKER_ITEM * pWorkItem = g_cMathWorker->GetWorkItemCount(cores); @@ -4267,8 +4252,7 @@ PyObject * GroupBySingleOpMultiBands(ArrayInfo * aInfo, PyArrayObject * iKey, Py if (pstGroupBy32 == NULL) { - // out of memory - return NULL; + return PyErr_NoMemory(); } int64_t itemSize = PyArray_ITEMSIZE(outArray); @@ -4298,8 +4282,8 @@ PyObject * GroupBySingleOpMultiBands(ArrayInfo * aInfo, PyArrayObject * iKey, Py pstGroupBy32->totalInputRows = arraySizeKey; - LOGGING("groupby dtypes: key:%d ifirst:%d igroup:%d count:%d\n", PyArray_TYPE(iKey), PyArray_TYPE(iFirst), - PyArray_TYPE(iGroup), PyArray_TYPE(nCount)); + logger->debug("groupby dtypes: key:{} ifirst:{} igroup:{} count:{}", PyArray_TYPE(iKey), PyArray_TYPE(iFirst), + PyArray_TYPE(iGroup), PyArray_TYPE(nCount)); int64_t dividend = unique_rows / cores; int64_t remainder = unique_rows % cores; @@ -4339,11 +4323,8 @@ PyObject * GroupBySingleOpMultiBands(ArrayInfo * aInfo, PyArrayObject * iKey, Py pWorkItem->DoWorkCallback = BandedGroupByCall; pWorkItem->WorkCallbackArg = pstGroupBy32; - LOGGING("before threaded\n"); - // This will notify the worker threads of a new work item g_cMathWorker->WorkMain(pWorkItem, cores, 0, 1, false); - LOGGING("after threaded\n"); WORKSPACE_FREE(pstGroupBy32); @@ -4389,7 +4370,7 @@ PyObject * GroupBySingleOpMultithreaded(ArrayInfo * aInfo, PyArrayObject * iKey, firstFuncNum); } - // printf("Taking the divide path %lld \n", unique_rows); + logger->debug("Taking the divide path: rows {}", unique_rows); if (pFunction && numpyOutType != -1) { @@ -4418,22 +4399,22 @@ PyObject * GroupBySingleOpMultithreaded(ArrayInfo * aInfo, PyArrayObject * iKey, cache_aligned_buffer_array workspace_buffers; if (! workspace_buffers.allocate(numCores, unique_rows * itemSize)) { - return NULL; + return PyErr_NoMemory(); } - LOGGING("***workspace %p unique:%lld itemsize:%lld cores:%d\n", workspace.data(), unique_rows, itemSize, - numCores); + logger->debug("***workspace {} unique:{} itemsize:{} cores:{}", workspace_buffers.data(), unique_rows, itemSize, + numCores); cache_aligned_buffer_array count_buffers; if (hasCounts) { if (! count_buffers.allocate(numCores, unique_rows * pCountOutTypeSize)) { - return NULL; + return PyErr_NoMemory(); } memset(count_buffers.data(), 0, count_buffers.get_total_size()); - LOGGING("***pCountOut %p unique:%lld allocsize:%lld cores:%d\n", count_buffers.data(), unique_rows, allocSize, - numCores); + logger->debug("GroupBySingleOpMultithreaded: ***pCountOut {} unique:{} allocsize:{} cores:{}", + count_buffers.data(), unique_rows, count_buffers.get_total_size(), numCores); } int32_t tempItemSize{ 0 }; @@ -4445,7 +4426,7 @@ PyObject * GroupBySingleOpMultithreaded(ArrayInfo * aInfo, PyArrayObject * iKey, tempItemSize = NpyToSize(numpyTmpType); if (! temp_workspace_buffers.allocate(numCores, (binHigh - binLow) * tempItemSize)) { - return NULL; + return PyErr_NoMemory(); } } @@ -4456,8 +4437,7 @@ PyObject * GroupBySingleOpMultithreaded(ArrayInfo * aInfo, PyArrayObject * iKey, if (pstGroupBy32 == NULL) { - // out of memory - return NULL; + return PyErr_NoMemory(); } // build in data @@ -4492,12 +4472,12 @@ PyObject * GroupBySingleOpMultithreaded(ArrayInfo * aInfo, PyArrayObject * iKey, pWorkItem->DoWorkCallback = ScatterGroupByCall; pWorkItem->WorkCallbackArg = pstGroupBy32; - LOGGING("before threaded\n"); + logger->debug("before threaded"); // This will notify the worker threads of a new work item g_cMathWorker->WorkMain(pWorkItem, arraySizeKey, 0); - LOGGING("after threaded\n"); + logger->debug("after threaded"); // Gather resullts GROUPBY_GATHER_FUNC pGather; @@ -4517,7 +4497,7 @@ PyObject * GroupBySingleOpMultithreaded(ArrayInfo * aInfo, PyArrayObject * iKey, } else { - printf("!!!Internal error in GetGroupByGatherFunction\n"); + return PyErr_Format(PyExc_RuntimeError, "Internal error in GroupBySingleOpMultithreaded: pGather is NULL"); } // New reference @@ -4552,6 +4532,7 @@ PyObject * GroupByAll32(PyObject * self, PyObject * args) if (! PyArg_ParseTuple(args, "OO!LO!O!O!O", &inList1, &PyArray_Type, &iKey, &unique_rows, &PyList_Type, &listFuncNum, &PyList_Type, &listBinLow, &PyList_Type, &listBinHigh, ¶m)) { + // PyArg_ParseTuple sets the error return NULL; } @@ -4590,6 +4571,7 @@ PyObject * GroupByAll32(PyObject * self, PyObject * args) if (! aInfo) { + // BuildArrayInfo sets the error return NULL; } @@ -4637,6 +4619,12 @@ PyObject * GroupByAll32(PyObject * self, PyObject * args) // multithread by data segments (NOT bin ranges) // scatter/gather technique -- no memory is read twice returnTuple = GroupBySingleOpMultithreaded(aInfo, iKey, firstFuncNum, unique_rows, tupleSize, binLow, binHigh); + + if (PyErr_Occurred() != NULL) + { + // Error already set + return NULL; + } } } @@ -4653,8 +4641,7 @@ PyObject * GroupByAll32(PyObject * self, PyObject * args) if (pstGroupBy32 == NULL) { - // out of memory - return NULL; + return PyErr_NoMemory(); } pstGroupBy32->aInfo = aInfo; @@ -4729,7 +4716,7 @@ PyObject * GroupByAll32(PyObject * self, PyObject * args) pCountOut = (void *)workspaceMemList.back().get(); if (pCountOut == NULL) { - return NULL; + return PyErr_NoMemory(); } memset(pCountOut, 0, allocSize); } @@ -4741,13 +4728,15 @@ PyObject * GroupByAll32(PyObject * self, PyObject * args) pTmpArray = workspaceMemList.back().get(); if (! pTmpArray) { - return NULL; + return PyErr_NoMemory(); } } } else { - LOGGING("Failed to find function %llu for type %d\n", funcNum, numpyOutType); + return PyErr_Format(PyExc_RuntimeError, + "Internal error in GroupByAll32: failed to find function %llu for type %d\n", funcNum, + numpyOutType); } pstGroupBy32->returnObjects[i].outArray = outArray; @@ -4761,7 +4750,7 @@ PyObject * GroupByAll32(PyObject * self, PyObject * args) g_cMathWorker->WorkGroupByCall(GroupByCall, pstGroupBy32, tupleSize); - LOGGING("!!groupby done %llu\n", tupleSize); + logger->debug("!!groupby done {}", tupleSize); // New reference returnTuple = PyTuple_New(tupleSize); @@ -4775,7 +4764,6 @@ PyObject * GroupByAll32(PyObject * self, PyObject * args) if (item == Py_None) Py_INCREF(Py_None); - // printf("ref %d %llu\n", i, item->ob_refcnt); PyTuple_SET_ITEM(returnTuple, i, item); void * pCountOut = pstGroupBy32->returnObjects[i].pCountOut; @@ -4785,7 +4773,7 @@ PyObject * GroupByAll32(PyObject * self, PyObject * args) // LOGGING("Return tuple ref %llu\n", returnTuple->ob_refcnt); FreeArrayInfo(aInfo); - LOGGING("!!groupby returning\n"); + logger->debug("!!groupby returning\n"); return returnTuple; } @@ -4828,11 +4816,12 @@ PyObject * GroupByAllPack32(PyObject * self, PyObject * args) &iFirst, &PyArray_Type, &nCount, &unique_rows, &PyList_Type, &listFuncNum, &PyList_Type, &listBinLow, &PyList_Type, &listBinHigh, &funcParam)) { + // Error already set return NULL; } - LOGGING("GroupByAllPack32 types: key:%d group:%d first:%d count:%d\n", PyArray_TYPE(iKey), PyArray_TYPE(iGroup), - PyArray_TYPE(iFirst), PyArray_TYPE(nCount)); + logger->debug("GroupByAllPack32 types: key:{} group:{} first:{} count:{}", PyArray_TYPE(iKey), PyArray_TYPE(iGroup), + PyArray_TYPE(iFirst), PyArray_TYPE(nCount)); int32_t iGroupType = PyArray_TYPE(iGroup); int32_t iFirstType = PyArray_TYPE(iFirst); @@ -4865,6 +4854,7 @@ PyObject * GroupByAllPack32(PyObject * self, PyObject * args) if (! aInfo) { + // Error already set return NULL; } @@ -4907,12 +4897,18 @@ PyObject * GroupByAllPack32(PyObject * self, PyObject * args) GB_FUNCTIONS const firstFuncNum{ static_cast( PyLong_AsLongLongAndOverflow(PyList_GET_ITEM(listFuncNum, 0), &overflow)) }; - LOGGING("Checking banded %lld\n", firstFuncNum); + logger->debug("Checking banded {}", static_cast(firstFuncNum)); if ((firstFuncNum >= GB_MEDIAN && firstFuncNum <= GB_TRIMBR) || (firstFuncNum == GB_QUANTILE_MULT)) { returnTuple = GroupBySingleOpMultiBands(aInfo, iKey, iFirst, iGroup, nCount, firstFuncNum, unique_rows, tupleSize, binLow, binHigh, funcParam); + + if (PyErr_Occurred()) + { + // Error already set + return NULL; + } } } @@ -4924,6 +4920,7 @@ PyObject * GroupByAllPack32(PyObject * self, PyObject * args) { PyErr_Format(PyExc_ValueError, "GroupByAllPack32 func numbers do not match array columns %lld %lld", tupleSize, funcTupleSize); + return NULL; } int64_t binTupleSize = PyList_GET_SIZE(listBinLow); @@ -4945,7 +4942,7 @@ PyObject * GroupByAllPack32(PyObject * self, PyObject * args) // Allocate the struct + ROOM at the end of struct for all the tuple objects // being produced int64_t allocSize = (sizeof(stGroupBy32) + 8 + sizeof(stGroupByReturn)) * tupleSize; - LOGGING("in GroupByAllPack32 allocating %lld\n", allocSize); + logger->debug("GroupByAllPack32 allocating {}", allocSize); stGroupBy32 * pstGroupBy32 = (stGroupBy32 *)WORKSPACE_ALLOC(allocSize); @@ -4957,7 +4954,6 @@ PyObject * GroupByAllPack32(PyObject * self, PyObject * args) pstGroupBy32->totalInputRows = ArrayLength(iKey); - // printf("funcParam %lld\n", funcParam); pstGroupBy32->funcParam = funcParam; pstGroupBy32->pKey = PyArray_BYTES(iKey); @@ -5095,12 +5091,12 @@ PyObject * GroupByAllPack32(PyObject * self, PyObject * args) } else { - LOGGING("GroupByAllPack32: Allocating for output type: %d\n", aInfo[i].NumpyDType); + logger->debug("GroupByAllPack32: Allocating for output type: {}", aInfo[i].NumpyDType); outArray = AllocateLikeResize(aInfo[i].pObject, unique_rows); } } - // Bail if out of memory (possible memory leak) + // Bail if out of memory if (outArray == NULL) { goto ERROR_EXIT; @@ -5108,7 +5104,7 @@ PyObject * GroupByAllPack32(PyObject * self, PyObject * args) } else { - LOGGING("Failed to find function %llu for type %d\n", funcNum, numpyOutType); + logger->error("Failed to find function {} for type {}", static_cast(funcNum), numpyOutType); PyErr_Format(PyExc_NotImplementedError, "GroupByAllPack32 doesn't implement function %llu for type %d", funcNum, numpyOutType); goto ERROR_EXIT; @@ -5122,7 +5118,7 @@ PyObject * GroupByAllPack32(PyObject * self, PyObject * args) g_cMathWorker->WorkGroupByCall(GroupByCall, pstGroupBy32, tupleSize); - LOGGING("!!groupby done %llu\n", tupleSize); + logger->debug("!!groupby done {}", tupleSize); // New reference returnTuple = PyTuple_New(tupleSize); @@ -5135,7 +5131,6 @@ PyObject * GroupByAllPack32(PyObject * self, PyObject * args) if (item == Py_None) Py_INCREF(Py_None); - // printf("ref %d %llu\n", i, item->ob_refcnt); PyTuple_SET_ITEM(returnTuple, i, item); } @@ -5166,13 +5161,13 @@ PyObject * GroupByAllPack32(PyObject * self, PyObject * args) // } //} - LOGGING("Return tuple ref %llu\n", returnTuple->ob_refcnt); + logger->debug("Return tuple ref {}", returnTuple->ob_refcnt); ERROR_EXIT: WORKSPACE_FREE(pstGroupBy32); FreeArrayInfo(aInfo); - LOGGING("!!groupby returning\n"); + logger->debug("!!groupby returning"); } return returnTuple; diff --git a/src/Logger.cpp b/src/Logger.cpp index 494d5c8..237a6d1 100644 --- a/src/Logger.cpp +++ b/src/Logger.cpp @@ -1,4 +1,5 @@ -#include "logging/logger.h" +#include "logging/logging.h" + #include "Logger.h" #include @@ -9,28 +10,34 @@ namespace { PyObject * logging_lib = NULL; - PyObject * log_sink = NULL; - riptide::logging::logger & logger = riptide::logging::logger::get(); + auto service = riptide::logging::get_service(); using log_record = riptide::logging::log_record; using loglevel = riptide::logging::loglevel; + std::unordered_map sinks; std::optional exception_callback; std::optional exception_message; void UpdateLogLevel() { - auto level_attr = PyObject_GetAttrString(log_sink, "level"); - if (! PyLong_Check(level_attr)) + for (const auto & [name, sink] : sinks) { + auto level_attr = PyObject_GetAttrString(sink, "level"); + if (! PyLong_Check(level_attr)) + { + Py_XDECREF(level_attr); + continue; + ; + } + + int32_t level = PyLong_AsLong(level_attr); Py_XDECREF(level_attr); - return; - } - int32_t level = PyLong_AsLong(level_attr); - Py_XDECREF(level_attr); - if (level >= static_cast(loglevel::notset) and level <= static_cast(loglevel::crtical)) - logger.set_level(static_cast(level)); + auto logger{ riptide::logging::get_logger(name) }; + if (level >= static_cast(loglevel::notset) and level <= static_cast(loglevel::critical)) + logger->set_level(static_cast(level)); + } } void LoggingHandler() @@ -59,7 +66,7 @@ namespace { std::vector batch; // make sure we have the GIL initially. - while (logger.active()) + while (service->active()) { batch.clear(); @@ -69,11 +76,11 @@ namespace return std::chrono::duration_cast(delta); }; - auto batch_size{ logger.batch_size() }; - while (batch.size() < batch_size and diff(last_sent) < logger.interval()) + auto batch_size{ service->batch_size() }; + while (batch.size() < batch_size and diff(last_sent) < service->interval()) { // if there is no log, then this thread will sleep here. - auto curr_log{ logger.receive() }; + auto curr_log{ service->receive() }; if (! curr_log) break; @@ -91,11 +98,34 @@ namespace UpdateLogLevel(); - for (size_t index = 0; index < batch.size(); index++) + for (auto & msg : batch) { - auto res = PyObject_CallMethod(log_sink, "log", "is", static_cast(batch[index].level), - batch[index].message.c_str()); - Py_XDECREF(res); + auto sink{ sinks[msg.name] }; + + auto log_method{ PyObject_GetAttrString(sink, "log") }; + if (not log_method) + continue; + + auto source_loc{ msg.loc }; + + auto source_info{ Py_BuildValue("{s:s, s:i, s:i, s:s}", "filename", source_loc.file_name(), "line", + source_loc.line(), "column", source_loc.column(), "function", + source_loc.function_name()) }; + + auto timestamp_ns{ msg.time.time_since_epoch().count() }; + + auto extra{ Py_BuildValue("{s:O, s:I}", "source_info", source_info, "timestamp", timestamp_ns) }; + + auto args{ Py_BuildValue("(iN)", static_cast(msg.level), + PyUnicode_Decode(msg.message.c_str(), msg.message.size(), NULL, "replace")) }; + auto kwargs{ Py_BuildValue("{s:O}", "extra", extra) }; + + if (args and kwargs) + { + auto res{ PyObject_Call(log_method, args, kwargs) }; + Py_XDECREF(res); + } + Py_DECREF(log_method); } // release @@ -117,17 +147,25 @@ void SetupLogging() { // these ref should stay alive during the entire lifetime of the module. logging_lib = PyImport_ImportModule("logging"); - log_sink = PyObject_CallMethod(logging_lib, "getLogger", "s", "riptable.riptide_cpp"); + + for (auto & name : riptide::logging::get_logger_names()) + { + auto logger_name{ "riptable.riptide_cpp" + (name.empty() ? "" : "." + name) }; + auto sink{ PyObject_CallMethod(logging_lib, "getLogger", "s", logger_name.c_str()) }; + if (sink == nullptr) + continue; + sinks[name] = sink; + } } void CleanupLogging() { - logger.disable(); + service->disable(); } PyObject * EnableLogging(PyObject * self, PyObject * args) { - if (logger.active()) + if (service->active()) { Py_INCREF(Py_None); return Py_None; @@ -151,16 +189,28 @@ PyObject * EnableLogging(PyObject * self, PyObject * args) if (PyFunction_Check(callback)) exception_callback = callback; - logger.enable({ .batch_size = bsize, .flush_interval = std::chrono::milliseconds(interval), .max_size = msize }); + service->enable({ .batch_size = bsize, .flush_interval = std::chrono::milliseconds(interval), .max_size = msize }); UpdateLogLevel(); - logger.set_handler(LoggingHandler); + service->set_handler(LoggingHandler); Py_INCREF(Py_None); return Py_None; } +PyObject * GetRiptideLoggers(PyObject * self, PyObject * args) +{ + auto names{ riptide::logging::get_logger_names() }; + auto list{ PyList_New(names.size()) }; + for (size_t i = 0; i < names.size(); i++) + { + auto logger_name{ "riptable.riptide_cpp" + (names[i].empty() ? "" : "." + names[i]) }; + PyList_SetItem(list, i, PyUnicode_FromString(logger_name.c_str())); + } + return list; +} + PyObject * DisableLogging(PyObject * self, PyObject * args) { - if (! logger.active()) + if (! service->active()) { Py_INCREF(Py_None); return Py_None; @@ -176,9 +226,9 @@ PyObject * DisableLogging(PyObject * self, PyObject * args) Py_BEGIN_ALLOW_THREADS; if (timeout != -1) - logger.disable(std::chrono::milliseconds(timeout)); + service->disable(std::chrono::milliseconds(timeout)); else - logger.disable(); + service->disable(); Py_END_ALLOW_THREADS; Py_INCREF(Py_None); diff --git a/src/Logger.h b/src/Logger.h index 1f3e5da..cce2717 100644 --- a/src/Logger.h +++ b/src/Logger.h @@ -2,7 +2,8 @@ #include -void SetupLogging(); +RT_DLLEXPORT void SetupLogging(); void CleanupLogging(); PyObject * EnableLogging(PyObject * self, PyObject * args); -PyObject * DisableLogging(PyObject * self, PyObject * args); \ No newline at end of file +PyObject * DisableLogging(PyObject * self, PyObject * args); +PyObject * GetRiptideLoggers(PyObject * self, PyObject * args); \ No newline at end of file diff --git a/src/MathThreads.h b/src/MathThreads.h index 2af5119..40b5dec 100644 --- a/src/MathThreads.h +++ b/src/MathThreads.h @@ -189,7 +189,7 @@ struct stMATH_WORKER_ITEM //------------------------------------------------- // The next block (atomic) // Incremented - // If BlockNext > BlockLast -- no work to be done + // If BlockNext >= BlockLast -- no work to be done volatile int64_t BlockNext; //----------------------------------------------- @@ -216,7 +216,7 @@ struct stMATH_WORKER_ITEM //============================================================= // Called by routines that work by index - // returns 0 on failure + // returns -1 on failure // else returns length of workblock RT_FORCEINLINE int64_t GetNextWorkIndex(int64_t * workBlock) { @@ -230,7 +230,7 @@ struct stMATH_WORKER_ITEM return wBlock; } - return 0; + return -1; } //============================================================= @@ -370,8 +370,7 @@ struct stWorkerRing // Linux thread wakeup int s = futex((int *)&WorkIndex, FUTEX_WAKE, maxThreadsToWake, nullptr, nullptr, 0); if (s == -1) - printf("***error futex-FUTEX_WAKE\n"); // TODO: Change to use - // fprintf(stderr, msg) instead + perror("futex"); #elif defined(__APPLE__) // temp remove warning diff --git a/src/MathWorker.cpp b/src/MathWorker.cpp index 7e93be4..adc4e17 100644 --- a/src/MathWorker.cpp +++ b/src/MathWorker.cpp @@ -509,6 +509,22 @@ void CMathWorker::StartWorkerThreads(int numaNode) WorkerThreadHandles[i] = StartThread(pWorkerRing); } + // There's a potential for deadlock here if this function is called from DllMain + // When threads are created in DllMain, they can be suspended until DllMain exits, + // meaning the loops below will just end up waiting forever + + // Wait for all of the worker threads to start + while (static_cast(pWorkerRing->ThreadsRunning) < WorkerThreadCount) + { + YieldProcessor(); + } + + // Wait for all of the worker thread to idle + while (pWorkerRing->AnyThreadsAwakened()) + { + YieldProcessor(); + } + // Pin the main thread to a numa node? // TODO: work // uint64_t mask = ((uint64_t)1 << WorkerThreadCount);//core number starts diff --git a/src/MathWorker.h b/src/MathWorker.h index 381a656..39fda18 100644 --- a/src/MathWorker.h +++ b/src/MathWorker.h @@ -186,11 +186,8 @@ class CMathWorker int64_t workBlock; // As long as there is work to do - while ((index = pstWorkerItem->GetNextWorkIndex(&workBlock)) > 0) + while ((index = pstWorkerItem->GetNextWorkIndex(&workBlock)) >= 0) { - // First index is 1 so we subtract - index--; - pstWorkerItem->MTWorkCallback(pstWorkerItem->WorkCallbackArg, core, index); didSomeWork = true; @@ -427,7 +424,7 @@ class CMathWorker { // custom mode (called from groupby) // also can be called from parmerge - pWorkItem->BlockLast = len + 1; + pWorkItem->BlockLast = len; } pWorkItem->BlocksCompleted = 0; @@ -491,11 +488,11 @@ class CMathWorker THREADLOGGING("[%d] DoWork start loop\n", core); // As long as there is work to do - while ((index = pstWorkerItem->GetNextWorkIndex(&workBlock)) > 0) + while ((index = pstWorkerItem->GetNextWorkIndex(&workBlock)) >= 0) { - THREADLOGGING("[%d][%llu] Groupby started working on %lld\n", core, workIndex, workBlock - 1); + THREADLOGGING("[%d][%llu] Groupby started working on %lld\n", core, workIndex, workBlock); - groupByCall(pstWorkerItem->OldCallback.pDataInBase1, workBlock - 1); + groupByCall(pstWorkerItem->OldCallback.pDataInBase1, workBlock); // Indicate we completed a block didSomeWork = true; @@ -503,7 +500,7 @@ class CMathWorker // tell others we completed this work block pstWorkerItem->CompleteWorkBlock(); - THREADLOGGING("[%d][%llu] Groupby completed working on %lld\n", core, workIndex, workBlock - 1); + THREADLOGGING("[%d][%llu] Groupby completed working on %lld\n", core, workIndex, workBlock); } THREADLOGGING("[%d] Work item complete %lld\n", core, index); diff --git a/src/RipTide.cpp b/src/RipTide.cpp index 463e150..cca144a 100644 --- a/src/RipTide.cpp +++ b/src/RipTide.cpp @@ -1797,6 +1797,7 @@ static PyMethodDef CSigMathUtilMethods[] = { { "StrptimeToNanos", StrptimeToNanos, METH_VARARGS, "Parse string in strptime then .mmm to UTC epoch nanos" }, { "EnableLogging", EnableLogging, METH_VARARGS, "Enable logging with the specified parameters." }, { "DisableLogging", DisableLogging, METH_VARARGS, "Disable the logger and shutdown all associated threads" }, + { "GetRiptideLoggers", GetRiptideLoggers, METH_NOARGS, "Get the names of available riptide loggers" }, //{ "addf32x", addf32x, METH_VARARGS, "addf32 with output calculation" }, { NULL, NULL, 0, NULL } /* Sentinel - marks the end of this structure */ }; diff --git a/src/SDSFile.cpp b/src/SDSFile.cpp index 77bd00d..d9f7604 100644 --- a/src/SDSFile.cpp +++ b/src/SDSFile.cpp @@ -8,6 +8,7 @@ #include "FileReadWrite.h" #include "SDSFile.h" #include "SharedMemory.h" +#include "logging/logging.h" #include "MathWorker.h" #include @@ -48,6 +49,12 @@ extern int64_t SumBooleanMask(const int8_t * pIn, int64_t length); #define SDS_MAX_CORES 65 +namespace +{ + static auto logger = riptide::logging::get_logger("SDSFile"); + using loglevel = riptide::logging::loglevel; +} + #define LOGGING(...) //#define LOGGING printf @@ -165,7 +172,7 @@ void * SDSGetDefaultType(int32_t numpyInType) pgDefault = &gString; break; default: - printf("!!! likely problem in SDSGetDefaultType\n"); + logger->error("!!! likely problem in SDSGetDefaultType\n"); } return pgDefault; @@ -188,14 +195,14 @@ void SetErr_Format(int32_t exception, const char * format, ...) vsnprintf(g_errorbuffer, sizeof(g_errorbuffer), format, args); va_end(args); - LOGGING(g_errorbuffer); - LOGGING("\n"); + logger->error("{}", g_errorbuffer); + logger->error("{}", "\n"); } // Call to clear any previous errors static void ClearErrors() { - LOGGING("Clearing errors\n"); + logger->debug("Clearing errors"); g_lastexception = 0; g_errorbuffer[0] = 0; } @@ -204,7 +211,7 @@ static void PrintIfErrors() { if (g_errorbuffer[0] != 0) { - printf("Existing error: %s\n", g_errorbuffer); + logger->error("Existing error: {}", g_errorbuffer); } } @@ -216,7 +223,7 @@ static size_t CompressGetBound(int32_t compMode, size_t srcSize) return ZSTD_compressBound(srcSize); } - printf("!!internal CompressBound error\n"); + logger->debug("!!internal CompressBound error"); return srcSize; } @@ -229,7 +236,7 @@ static size_t CompressData(int32_t compMode, void * dst, size_t dstCapacity, con return ZstdCompressData(dst, dstCapacity, src, srcSize, compressionLevel); } - printf("!!internal CompressData error\n"); + logger->debug("!!internal CompressBound error"); return srcSize; } @@ -559,7 +566,8 @@ int64_t SDSFileReadChunk(SDS_EVENT_HANDLE eventHandle, SDS_FILE_HANDLE Handle, v if (! bReadDone) { LastError = GetLastError(); - printf("!!Read failed in getoverlapped %p %p %p %d\n", (void *)Handle, (void *)eventHandle, buffer, LastError); + logger->error("!!Read failed in getoverlapped {} {} {} {}", (void *)Handle, (void *)eventHandle, buffer, + LastError); return 0; } else @@ -567,7 +575,7 @@ int64_t SDSFileReadChunk(SDS_EVENT_HANDLE eventHandle, SDS_FILE_HANDLE Handle, v bool extraCheck = HasOverlappedIoCompleted(pos); if (! extraCheck) { - printf("!! internal error reading... complete but not really\n"); + logger->error("!! internal error reading... complete but not really"); } } } @@ -576,7 +584,7 @@ int64_t SDSFileReadChunk(SDS_EVENT_HANDLE eventHandle, SDS_FILE_HANDLE Handle, v if (! bReadDone) { DWORD LastError = GetLastError(); - printf("!!Read failed at end %p %p %p %d\n", (void *)Handle, (void *)eventHandle, buffer, LastError); + logger->error("!!Read failed at end {} {} {} {}", (void *)Handle, (void *)eventHandle, buffer, LastError); return 0; } // printf("Read %lld bytes\n",(long long) n); @@ -635,7 +643,7 @@ int64_t SDSFileWriteChunk(SDS_EVENT_HANDLE eventHandle, SDS_FILE_HANDLE Handle, if (! bWriteDone) { LastError = GetLastError(); - printf("!!Write failed ovr buff:%p size:%lld pos:%lld error:%d\n", buffer, bufferSize, BufferPos, LastError); + logger->error("!!Write failed ovr buff:{} size:{} pos:{} error:{}", buffer, bufferSize, BufferPos, LastError); return 0; } } @@ -643,14 +651,14 @@ int64_t SDSFileWriteChunk(SDS_EVENT_HANDLE eventHandle, SDS_FILE_HANDLE Handle, if (! bWriteDone) { LastError = GetLastError(); - printf("!!Write failed done buff:%p size:%lld pos:%lld error:%d\n", buffer, bufferSize, BufferPos, LastError); + logger->error("!!Write failed done buff:{} size:{} pos:{} error:{}", buffer, bufferSize, BufferPos, LastError); return 0; } if (n != count) { LastError = GetLastError(); - printf("write chunk error buff:%p size:%lld pos:%lld error:%d\n", buffer, bufferSize, BufferPos, LastError); + logger->error("write chunk error buff:{} size:{} pos:{} error:{}", buffer, bufferSize, BufferPos, LastError); } // TODO: n not always filled in... due to delayed write? return n; @@ -659,7 +667,7 @@ int64_t SDSFileWriteChunk(SDS_EVENT_HANDLE eventHandle, SDS_FILE_HANDLE Handle, //--------------------------------------------------- void SDSFileClose(SDS_FILE_HANDLE handle) { - LOGGING("File closed %p\n", handle); + logger->debug("File closed {}", (void *)handle); CloseHandle(handle); } @@ -709,7 +717,7 @@ SDS_FILE_HANDLE SDSFileOpen(const char * fileName, bool writeOption, bool overla if (filehandle < 0) { - LOGGING("openning with CREAT\n"); + logger->debug("openning with CREAT"); createFlags = O_RDWR | O_CREAT; filehandle = open(fileName, createFlags, 0666); } @@ -726,10 +734,10 @@ SDS_FILE_HANDLE SDSFileOpen(const char * fileName, bool writeOption, bool overla filehandle = open(fileName, createFlags); } - LOGGING("linux handle open\n"); + logger->debug("linux handle open"); if (filehandle < 0) { - printf("error opening file %s -- error %s\n", fileName, strerror(errno)); + logger->error("error opening file {} -- error {}", fileName, strerror(errno)); return BAD_SDS_HANDLE; } return filehandle; @@ -772,7 +780,7 @@ int64_t SDSFileReadChunk(SDS_EVENT_HANDLE eventHandle, SDS_FILE_HANDLE fileHandl if (totalRead != origSize) { - printf("!!readchunk failed for fd %d -- %lld vs %lld (errno %d)\n", fileHandle, origSize, totalRead, errno); + logger->error("!!readchunk failed for fd {} -- {} vs {} (errno {})", fileHandle, origSize, totalRead, errno); return 0; } return totalRead; @@ -784,13 +792,13 @@ int64_t SDSFileReadChunk(SDS_EVENT_HANDLE eventHandle, SDS_FILE_HANDLE fileHandl // pread() returns -1 on error; make sure the read actually succeeded. if (bytes_read == -1) { - printf("!!readchunk failed for fd %d -- %lld vs %lld (errno %d)\n", fileHandle, bufferSize, bytes_read, errno); + logger->error("!!readchunk failed for fd {} -- {} vs {} (errno {})", fileHandle, bufferSize, bytes_read, errno); return 0; } if (bytes_read != bufferSize) { - printf("!!readchunk failed for fd %d -- %lld vs %lld (errno %d)\n", fileHandle, bufferSize, bytes_read, errno); + logger->error("!!readchunk failed for fd {} -- {} vs {} (errno {})", fileHandle, bufferSize, bytes_read, errno); return 0; } return bytes_read; @@ -824,7 +832,7 @@ int64_t SDSFileWriteChunk(SDS_EVENT_HANDLE eventHandle, SDS_FILE_HANDLE fileHand if (totalWritten != origSize) { - printf("write chunk error buff:%p size:%lld pos:%lld errno:%d\n", buffer, bufferSize, bufferPos, errno); + logger->error("write chunk error buff:{} size:{} pos:{} errno:{}", buffer, bufferSize, bufferPos, errno); return 0; } @@ -837,13 +845,13 @@ int64_t SDSFileWriteChunk(SDS_EVENT_HANDLE eventHandle, SDS_FILE_HANDLE fileHand // pwrite() returns -1 on error; make sure the write actually succeeded. if (bytes_written == -1) { - printf("!!Write failed done buff:%p size:%lld pos:%lld errno:%d\n", buffer, bufferSize, bufferPos, errno); + logger->error("!!Write failed done buff:{} size:{} pos:{} errno:{}", buffer, bufferSize, bufferPos, errno); return 0; } if (bytes_written != bufferSize) { - printf("!!Write failed small buff:%p size:%lld pos:%lld errno:%d\n", buffer, bufferSize, bufferPos, errno); + logger->error("!!Write failed small buff:{} size:{} pos:{} errno:{}", buffer, bufferSize, bufferPos, errno); return 0; } @@ -858,7 +866,7 @@ void SDSFileClose(SDS_FILE_HANDLE handle) int32_t result = close(handle); if (result < 0) { - printf("Error closing file %s\n", strerror(errno)); + logger->error("Error closing file {}", strerror(errno)); } } @@ -959,7 +967,7 @@ class SharedMemory { return (SDS_FILE_HEADER *)pMapStruct->BaseAddress; } - printf("!!internal shared memory error\n"); + logger->error("!!internal shared memory error"); return NULL; } @@ -971,7 +979,7 @@ class SharedMemory { return ((char *)pMapStruct->BaseAddress) + offset; } - printf("!!internal shared memory GetMemoryOffset error\n"); + logger->error("!!internal shared memory GetMemoryOffset error"); return NULL; } @@ -987,13 +995,13 @@ class SharedMemory // HRESULT Begin(int64_t Size) { - LOGGING("Allocating mem share %s with size %lld\n", SharedMemoryName, Size); + logger->debug("Allocating mem share {} with size {}", SharedMemoryName, Size); HRESULT hr = SharedMemoryBegin(SharedMemoryName, Size, &pMapStruct); if (hr < 0) { - printf("!!!Failed to allocate shared memory share %s with size %lld\n", SharedMemoryName, Size); + logger->error("!!!Failed to allocate shared memory share {} with size {}", SharedMemoryName, Size); pMapStruct = NULL; } else @@ -1054,7 +1062,7 @@ class SharedMemory pTemp++; } - LOGGING("Orig filename:%s -- mapping: %s\n", pszFilename, pMappingName); + logger->debug("Orig filename:{} -- mapping: {}", pszFilename, pMappingName); char * pStart = SharedMemoryName; @@ -1081,7 +1089,7 @@ class SharedMemory // copy over filename part while ((*pStart++ = *pMappingName++)) ; - LOGGING("Shared memory name is %s\n", SharedMemoryName); + logger->debug("Shared memory name is {}", SharedMemoryName); } } @@ -1116,7 +1124,7 @@ class SDSIncludeExclude // loop over all included items for (const char * includeItem : *pItems) { - LOGGING("Including item: %s\n", includeItem); + logger->debug("Including item: {}", includeItem); AddItem(includeItem); } } @@ -1174,8 +1182,7 @@ class SDSIncludeExclude // Check if we matched if (FindItem(item)) { - LOGGING("Simple match %s\n", std::string(item).c_str()); - + logger->error("Simple match {}", std::string(item).c_str()); return 1; } @@ -1188,7 +1195,7 @@ class SDSIncludeExclude if (separator_pos != std::string_view::npos) { - LOGGING("Failed to match, has bang %s\n", std::string(item).c_str()); + logger->error("Failed to match, has bang {}", std::string(item).c_str()); // ignore bang std::string_view const newitem{ item.substr(0, separator_pos) }; @@ -1227,7 +1234,7 @@ class SDSIncludeExclude // ignore chars after sep std::string_view const newitem{ item.substr(0, separator_pos + 1) }; - LOGGING("Failed to match, has sep %s folder: %s\n", std::string(item).c_str(), std::string(newitem).c_str()); + logger->debug("Failed to match, has sep {} folder: {}", std::string(item).c_str(), std::string(newitem).c_str()); // if we matched return true if (FindItem(newitem)) @@ -1317,7 +1324,7 @@ static size_t DecompressWithFilter(int64_t compressedSize, // pBlockInfo->ArrayC int64_t firstBand = 0; int64_t firstData = bytesPerRow * firstBand; - LOGGING("special read: %lld lastData:%lld\n", lastRow, lastData); + logger->debug("special read: {} lastData:{}", lastRow, lastData); if (compressedSize == uncompressedSize) { @@ -1333,7 +1340,7 @@ static size_t DecompressWithFilter(int64_t compressedSize, // pBlockInfo->ArrayC // enough int64_t worstCase = CompressGetBound(compMode, lastData) + (2 * 65536); - LOGGING("[%d][%lld] worst case %lld v %lld <-- DecompressWithFilter\n", core, stackIndex, worstCase, compressedSize); + logger->debug("[{}][{}] worst case {} v {} <-- DecompressWithFilter", core, stackIndex, worstCase, compressedSize); if (worstCase < compressedSize) { // can do this with ZSTD @@ -1359,9 +1366,9 @@ static size_t DecompressWithFilter(int64_t compressedSize, // pBlockInfo->ArrayC if (dcSize != uncompressedSize) { - printf( - "[%d][%lld] MTDecompression band error direct size %lld vs " - "%lld\n", + logger->error( + "[{}][{}] MTDecompression band error direct size {} vs " + "{}", core, stackIndex, dcSize, uncompressedSize); result = -1; } @@ -1378,12 +1385,12 @@ static size_t DecompressWithFilter(int64_t compressedSize, // pBlockInfo->ArrayC if (rowOffset > lastRow) { // nothing to do - LOGGING("nothing to read all filtered out!\n"); + logger->debug("nothing to read all filtered out!"); return result; } - LOGGING( - "Boolmask bpr:%lld ai:%lld rowOffset:%lld fixup:%lld " - "masklength:%lld\n", + logger->debug( + "Boolmask bpr:{} ai:{} rowOffset:{} fixup:{} " + "masklength:{}", bytesPerRow, stackIndex, rowOffset, 0LL, pFilter->BoolMaskLength); // Make sure something to read @@ -1439,9 +1446,9 @@ static size_t DecompressWithFilter(int64_t compressedSize, // pBlockInfo->ArrayC sectionLength = pFilter->BoolMaskLength - rowOffset; } - LOGGING( - "sifting through %lld bytes with fixup %lld bpr:%lld " - "rowOffset: %lld to dest:%p\n", + logger->debug( + "sifting through {} bytes with fixup {} bpr:{} " + "rowOffset: {} to dest:{}", sectionLength, 0LL, bytesPerRow, rowOffset, pDest); switch (bytesPerRow) @@ -1549,9 +1556,9 @@ int64_t ReadAndDecompressBandWithFilter(SDS_ARRAY_BLOCK * pBlockInfo, // may con int64_t result = -1; int64_t runningTrueCount = 0; - LOGGING( - "[%lld] seek to %lld compsz:%lld uncompsz:%lld stackIndex:%lld " - "bytesPerRow:%lld <-- ReadAndDecompressBandWithFilter\n", + logger->debug( + "[{}] seek to {} compsz:{} uncompsz:{} stackIndex:{} " + "bytesPerRow:{} <-- ReadAndDecompressBandWithFilter", rowOffset, pBlockInfo->ArrayDataOffset, pBlockInfo->ArrayCompressedSize, pBlockInfo->ArrayUncompressedSize, stackIndex, bytesPerRow); @@ -1609,8 +1616,8 @@ int64_t ReadAndDecompressBandWithFilter(SDS_ARRAY_BLOCK * pBlockInfo, // may con tempFilter.pBoolMask = pFilter->pBoolMask; tempFilter.pFilterInfo = &sfi; - LOGGING("want band start:%lld masklength:%lld compsize:%lld decomp:%lld\n", rowOffset, trueCount, compressedSize, - uncompressedSize); + logger->debug("want band start:{} masklength:{} compsize:{} decomp:{}", rowOffset, trueCount, compressedSize, + uncompressedSize); result = DecompressWithFilter(compressedSize, uncompressedSize, arrayDataOffset, bytesPerRow, eventHandle, fileHandle, tempBuffer, destBandBuffer, &tempFilter, rowOffset, @@ -1653,7 +1660,7 @@ static size_t ReadAndDecompressArrayBlockWithFilter(SDS_ARRAY_BLOCK * pBlockInfo if (! tempBuffer) { - LOGGING("Allocating tempbuffer of %lld\n", pBlockInfo->ArrayCompressedSize); + logger->debug("Allocating tempbuffer of {}", pBlockInfo->ArrayCompressedSize); tempBuffer = WORKSPACE_ALLOC(pBlockInfo->ArrayCompressedSize); didAlloc = true; } @@ -1664,8 +1671,8 @@ static size_t ReadAndDecompressArrayBlockWithFilter(SDS_ARRAY_BLOCK * pBlockInfo if (pBlockInfo->ArrayBandCount > 0) { // we have bands - LOGGING("bandcount:%d bandsize:%d uncomp size: %lld\n", pBlockInfo->ArrayBandCount, pBlockInfo->ArrayBandSize, - pBlockInfo->ArrayUncompressedSize); + logger->debug("bandcount:{} bandsize:{} uncomp size: {}", pBlockInfo->ArrayBandCount, pBlockInfo->ArrayBandSize, + pBlockInfo->ArrayUncompressedSize); // read in band header // allocate memory on the stack @@ -1684,7 +1691,7 @@ static size_t ReadAndDecompressArrayBlockWithFilter(SDS_ARRAY_BLOCK * pBlockInfo } else { - printf("!!!Error reading in band header\n"); + logger->error("!!!Error reading in band header"); } } else @@ -1698,9 +1705,9 @@ static size_t ReadAndDecompressArrayBlockWithFilter(SDS_ARRAY_BLOCK * pBlockInfo } else { - printf( - "out of mem no temp buffer bandcount:%d bandsize:%d uncomp size: " - "%lld\n", + logger->debug( + "out of mem no temp buffer bandcount:{} bandsize:{} uncomp size: " + "{}", pBlockInfo->ArrayBandCount, pBlockInfo->ArrayBandSize, pBlockInfo->ArrayUncompressedSize); } if (didAlloc && tempBuffer) @@ -1730,8 +1737,8 @@ static size_t ReadAndDecompressArrayBlock(SDS_ARRAY_BLOCK * pBlockInfo, // may c int64_t result = -1; int64_t compressedSize = pBlockInfo->ArrayCompressedSize; - LOGGING("[%lld] seek to %lld sz: %lld <-- ReadAndDecompressArrayBlock\n", arrayIndex, pBlockInfo->ArrayDataOffset, - pBlockInfo->ArrayCompressedSize); + logger->debug("[{}] seek to {} sz: {} <-- ReadAndDecompressArrayBlock", arrayIndex, pBlockInfo->ArrayDataOffset, + pBlockInfo->ArrayCompressedSize); // Check if uncompressed if (compressedSize == pBlockInfo->ArrayUncompressedSize) @@ -1741,7 +1748,7 @@ static size_t ReadAndDecompressArrayBlock(SDS_ARRAY_BLOCK * pBlockInfo, // may c if (result != compressedSize) { - printf("[%d][%lld] error while reading into uncompressed sz: %lld\n", core, arrayIndex, compressedSize); + logger->error("[{}][{}] error while reading into uncompressed sz: {}", core, arrayIndex, compressedSize); result = -1; } } @@ -1791,9 +1798,9 @@ static size_t ReadAndDecompressArrayBlock(SDS_ARRAY_BLOCK * pBlockInfo, // may c arrayDataOffset); if (result != uncompressedSize) { - printf( - "[%d][%lld][%d] MTDecompression (uncompressed) band error " - "size %lld vs %lld\n", + logger->error( + "[{}][{}][{}] MTDecompression (uncompressed) band error " + "size {} vs {}", core, arrayIndex, i, uncompressedSize, compressedSize); result = -1; break; @@ -1808,9 +1815,9 @@ static size_t ReadAndDecompressArrayBlock(SDS_ARRAY_BLOCK * pBlockInfo, // may c DecompressData(NULL, compMode, destBandBuffer, uncompressedSize, tempBuffer, compressedSize); if (dcSize != uncompressedSize) { - printf( - "[%d][%lld][%d] MTDecompression band error size %lld vs " - "%lld vs %lld\n", + logger->error( + "[{}][{}][{}] MTDecompression band error size {} vs " + "{} vs {}", core, arrayIndex, i, dcSize, uncompressedSize, compressedSize); result = -1; break; @@ -1823,7 +1830,7 @@ static size_t ReadAndDecompressArrayBlock(SDS_ARRAY_BLOCK * pBlockInfo, // may c } else { - printf("!!!Error reading in band header\n"); + logger->error("!!!Error reading in band header"); } } else @@ -1833,7 +1840,7 @@ static size_t ReadAndDecompressArrayBlock(SDS_ARRAY_BLOCK * pBlockInfo, // may c if (result != compressedSize) { - printf("[%d][%lld] error while reading into decompressed sz: %lld\n", core, arrayIndex, compressedSize); + logger->error("[{}][{}] error while reading into decompressed sz: {}", core, arrayIndex, compressedSize); result = -1; } else @@ -1844,17 +1851,17 @@ static size_t ReadAndDecompressArrayBlock(SDS_ARRAY_BLOCK * pBlockInfo, // may c if (CompressIsError(compMode, dcSize)) { - printf("[%d][%lld] MTDecompression error\n", core, arrayIndex); + logger->error("[{}][{}] MTDecompression error", core, arrayIndex); result = -1; } else if (dcSize != uncompressedSize) { - printf("[%d][%lld] MTDecompression error size\n", core, arrayIndex); + logger->error("[{}][{}] MTDecompression error size", core, arrayIndex); result = -1; } else { - LOGGING("[%d][%lld] decomp success\n", core, arrayIndex); + logger->debug("[{}][{}] decomp success", core, arrayIndex); } } } @@ -1900,8 +1907,8 @@ void FillFileHeader(SDS_FILE_HEADER * pFileHeader, int64_t fileOffset, int16_t c pFileHeader->ArraysWritten = 0; pFileHeader->ArrayFirstOffset = pFileHeader->ArrayBlockOffset + SDS_PAD_NUMBER(pFileHeader->ArrayBlockSize); - LOGGING("main offsets %lld %lld %lld\n", pFileHeader->MetaBlockOffset, pFileHeader->ArrayBlockOffset, - pFileHeader->ArrayFirstOffset); + logger->debug("main offsets {} {} {}", pFileHeader->MetaBlockOffset, pFileHeader->ArrayBlockOffset, + pFileHeader->ArrayFirstOffset); pFileHeader->TotalArrayCompressedSize = 0; pFileHeader->TotalArrayUncompressedSize = 0; @@ -2038,7 +2045,7 @@ void SDSSectionName::AllocateSectionData(int64_t sectionBlockCount, int64_t sect SectionCount = sectionBlockCount; if (pSectionData != NULL) { - printf("Double Allocation sectionData!!\n"); + logger->debug("Double Allocation sectionData!!"); } pSectionData = (char *)WORKSPACE_ALLOC(sectionSize); @@ -2098,7 +2105,7 @@ void SDSSectionName::MakeListSections(const int64_t sectionBlockCount, const int int64_t value = *(int64_t *)pSections; pSections += sizeof(int64_t); - LOGGING("makelist section is %s, %d, offset at %lld\n", pStart, i, value); + logger->debug("makelist section is {}, {}, offset at {}", pStart, i, value); // The appended named pSectionNames[i] = pStart; @@ -2116,7 +2123,7 @@ void SDSSectionName::MakeListSections(const int64_t sectionBlockCount, const int // So we create a dummy section nameed '0' char * SDSSectionName::MakeFirstSectionName() { - LOGGING("**First time appending %p\n", pSectionNames); + logger->debug("**First time appending {}", (void *)pSectionNames); if (SectionCount == 0) { // Will allocate pSectionData for us @@ -2127,7 +2134,7 @@ char * SDSSectionName::MakeFirstSectionName() memcpy(pSectionData, g_firstsectiondata, sizeof(g_firstsectiondata)); return pSectionData; } - printf("This code path should not be hit\n"); + logger->warn("This code path should not be hit"); return pSectionData; } @@ -2144,8 +2151,8 @@ char * SDSSectionName::ReadListSections(SDS_FILE_HANDLE SDSFile, SDS_FILE_HEADER if (sectionSize) { - LOGGING("Section Block Count %lld, sectionSize %lld, reserved %lld\n", pFileHeader->SectionBlockCount, sectionSize, - pFileHeader->SectionBlockReservedSize); + logger->debug("Section Block Count {}, sectionSize {}, reserved {}", pFileHeader->SectionBlockCount, sectionSize, + pFileHeader->SectionBlockReservedSize); AllocateSectionData(pFileHeader->SectionBlockCount, sectionSize); @@ -2165,7 +2172,7 @@ char * SDSSectionName::ReadListSections(SDS_FILE_HANDLE SDSFile, SDS_FILE_HEADER // Run through Section list and setup pointers MakeListSections(SectionCount, sectionSize); - LOGGING("Returning sections: %s\n", pSectionData); + logger->debug("Returning sections: {}", pSectionData); return pSectionData; } return NULL; @@ -2210,7 +2217,7 @@ SDS_FILE_HANDLE StartCompressedFile(const char * fileName, SDS_FILE_HEADER * pFi fileOffset = DefaultFileIO.FileSize(fileName); if (fileOffset > 0) { - LOGGING("File already existed with append section %s, filesize: %lld\n", pWriteInfo->sectionName, fileOffset); + logger->debug("File already existed with append section {}, filesize: {}", pWriteInfo->sectionName, fileOffset); fileOffset = SDS_PAD_NUMBER(fileOffset); mode = COMPRESSION_MODE_COMPRESS_APPEND_FILE; } @@ -2282,7 +2289,7 @@ SDS_FILE_HANDLE StartCompressedFile(const char * fileName, SDS_FILE_HEADER * pFi // If folder does not exist, seek to end of file and get offset // PAD To 512 // Fill FileHeader with - LOGGING("Using fileOffset %lld\n", fileOffset); + logger->debug("Using fileOffset {}", fileOffset); FillFileHeader(pFileHeader, fileOffset, COMPRESSION_MODE_COMPRESS_FILE, compType, compLevel, fileType, stackType, authorId, listNameLength, listNameCount, cSize, arrayCount, bandSize); @@ -2291,7 +2298,7 @@ SDS_FILE_HANDLE StartCompressedFile(const char * fileName, SDS_FILE_HEADER * pFi pFileHeader->TotalMetaUncompressedSize = strMetaLength; DefaultFileIO.FileWriteChunk(NULL, fileHandle, pFileHeader, sizeof(SDS_FILE_HEADER), fileOffset); - LOGGING("meta compressed to %llu vs %lld %llu\n", cSize, strMetaLength, sizeof(SDS_FILE_HEADER)); + logger->debug("meta compressed to {} vs {} {}", cSize, strMetaLength, sizeof(SDS_FILE_HEADER)); if (listNameLength) { @@ -2332,8 +2339,8 @@ void EndCompressedFile(SDS_FILE_HANDLE sdsFile, SDS_FILE_HEADER * pFileHeader, S { // close it out - LOGGING("SDS: Array first offset --- %lld Total comp size %lld\n", pFileHeader->ArrayFirstOffset, - pFileHeader->TotalArrayCompressedSize); + logger->debug("SDS: Array first offset --- {} Total comp size {}", pFileHeader->ArrayFirstOffset, + pFileHeader->TotalArrayCompressedSize); int64_t LastFileOffset = pFileHeader->GetEndOfFileOffset(); @@ -2348,7 +2355,7 @@ void EndCompressedFile(SDS_FILE_HANDLE sdsFile, SDS_FILE_HEADER * pFileHeader, S // Are we the first entry? if (pFileHeader->FileOffset == 0) { - LOGGING("SDS: Writing first section %s at %lld\n", pWriteInfo->sectionName, LastFileOffset); + logger->debug("SDS: Writing first section {} at {}", pWriteInfo->sectionName, LastFileOffset); int64_t sectionSize = cSDSSectionName.BuildSectionNamesAndOffsets(&pListNames, pWriteInfo->sectionName, pFileHeader->FileOffset); @@ -2394,9 +2401,9 @@ void EndCompressedFile(SDS_FILE_HANDLE sdsFile, SDS_FILE_HEADER * pFileHeader, S int64_t blockCount = fileHeader.SectionBlockCount; - LOGGING( - "SDS: Writing section %s with blockcount:%lld at %lld (%lld) " - "at %lld\n", + logger->debug( + "SDS: Writing section {} with blockcount:{} at {} ({}) " + "at {}", pWriteInfo->sectionName, blockCount, pFileHeader->FileOffset, fileHeader.FileOffset, LastFileOffset); int64_t sectionSize = cSDSSectionName.BuildSectionNamesAndOffsets(&pListNames, pWriteInfo->sectionName, pFileHeader->FileOffset); @@ -2405,7 +2412,7 @@ void EndCompressedFile(SDS_FILE_HANDLE sdsFile, SDS_FILE_HEADER * pFileHeader, S fileHeader.SectionBlockCount = blockCount + 1; fileHeader.SectionBlockSize = sectionSize; - LOGGING("SDS: new section size %lld vs %lld\n", sectionSize, fileHeader.SectionBlockReservedSize); + logger->debug("SDS: new section size {} vs {}", sectionSize, fileHeader.SectionBlockReservedSize); if (fileHeader.SectionBlockReservedSize < sectionSize) { @@ -2445,14 +2452,14 @@ void EndCompressedFile(SDS_FILE_HANDLE sdsFile, SDS_FILE_HEADER * pFileHeader, S { SetErr_Format(SDS_VALUE_ERROR, "Compression error cannot write fileheader at offset %lld\n", pFileHeader->FileOffset); } - LOGGING("Total arrays written %lld --- %llu %lld\n", pFileHeader->ArraysWritten, sizeof(SDS_FILE_HEADER), result); + logger->debug("Total arrays written {} --- {} {}", pFileHeader->ArraysWritten, sizeof(SDS_FILE_HEADER), result); result = DefaultFileIO.FileWriteChunk(NULL, sdsFile, pArrayBlocks, pFileHeader->ArrayBlockSize, pFileHeader->ArrayBlockOffset); - LOGGING("array block offset --- %lld %lld %lld\n", pFileHeader->ArrayBlockOffset, pFileHeader->ArrayBlockSize, - pArrayBlocks[0].ArrayDataOffset); + logger->debug("array block offset --- {} {} {}", pFileHeader->ArrayBlockOffset, pFileHeader->ArrayBlockSize, + pArrayBlocks[0].ArrayDataOffset); if (result != pFileHeader->ArrayBlockSize) { - printf("!!!Internal error closing compressed file\n"); + logger->error("!!!Internal error closing compressed file"); } DefaultFileIO.FileClose(sdsFile); @@ -2469,13 +2476,13 @@ void EndCompressedFile(SDS_FILE_HANDLE sdsFile, SDS_FILE_HEADER * pFileHeader, S // bool DecompressFileArray(void * pstCompressArraysV, int32_t core, int64_t t) { - LOGGING("[%lld] Start of decompress array: core %d compress: %p\n", t, core, pstCompressArraysV); + logger->debug("[{}] Start of decompress array: core {} compress: {}", t, core, pstCompressArraysV); SDS_READ_DECOMPRESS_ARRAYS * pstCompressArrays = (SDS_READ_DECOMPRESS_ARRAYS *)pstCompressArraysV; SDS_FILE_HANDLE sdsFile = pstCompressArrays->fileHandle; // point32_t to blocks SDS_ARRAY_BLOCK * pBlockInfo = &pstCompressArrays->pBlockInfo[t]; - // LOGGING("[%lld] Step 2 of decompress array: core %d blockinfo %p\n", t, + // logger->debug("[{}] Step 2 of decompress array: core {} blockinfo {}", t, // core, pBlockInfo); int64_t source_size = pBlockInfo->ArrayCompressedSize; @@ -2487,13 +2494,13 @@ bool DecompressFileArray(void * pstCompressArraysV, int32_t core, int64_t t) { SDS_ARRAY_BLOCK * pArrayBlock = pstCompressArrays->pMemoryIO->GetArrayBlock(t); destBuffer = pstCompressArrays->pMemoryIO->GetMemoryOffset(pArrayBlock->ArrayDataOffset); - LOGGING("[%lld] decompressing shared memory %p\n", t, destBuffer); + logger->debug("[{}] decompressing shared memory {}", t, destBuffer); } else { // Use callback to get to array buffer destBuffer = pstCompressArrays->ArrayInfo[t].pData; - LOGGING("[%lld] decompressing into %p\n", t, destBuffer); + logger->debug("[{}] decompressing into {}", t, destBuffer); } // Make sure we have a valid buffer @@ -2515,7 +2522,7 @@ bool DecompressFileArray(void * pstCompressArraysV, int32_t core, int64_t t) pstCompressArrays->pCoreMemory[core] = WORKSPACE_ALLOC(source_size); // Log that we were forced to reallocate - LOGGING("-"); + logger->debug("forced to reallocate..."); } void * tempBuffer = pstCompressArrays->pCoreMemory[core]; @@ -2594,11 +2601,11 @@ bool CompressFileArray(void * pstCompressArraysV, int32_t core, int64_t t) pstCompressArrays->pCoreMemorySize[core] = wantedSize; pstCompressArrays->pCoreMemory[core] = WORKSPACE_ALLOC(wantedSize); - LOGGING("-"); + logger->debug("-"); } else { - LOGGING("+"); + logger->debug("+"); } void * pTempMemory = pstCompressArrays->pCoreMemory[core]; @@ -2606,7 +2613,7 @@ bool CompressFileArray(void * pstCompressArraysV, int32_t core, int64_t t) // Make sure we were able to alloc memory if (pTempMemory) { - LOGGING("[%d] started %lld %p\n", (int)t, source_size, pTempMemory); + logger->debug("[{}] started {} {}", (int)t, source_size, pTempMemory); // data to compress is after the header size_t cSize = source_size; @@ -2618,7 +2625,7 @@ bool CompressFileArray(void * pstCompressArraysV, int32_t core, int64_t t) if (bandCount > 0) { - LOGGING("[%d] banding bytesperband:%lld bandcount:%lld\n", (int)t, bytesPerBand, bandCount); + logger->debug("[{}] banding bytesperband:{} bandcount:{}", (int)t, bytesPerBand, bandCount); int64_t * pBandOffsets = (int64_t *)pTempMemory; char * pWriteMemory = (char *)(pBandOffsets + bandCount); @@ -2712,7 +2719,7 @@ bool CompressFileArray(void * pstCompressArraysV, int32_t core, int64_t t) int32_t ndim = pArrayInfo->NDim; if (ndim > SDS_MAX_DIMS) { - printf("!!!SDS: array dimensions too high: %d\n", ndim); + logger->warn("!!!SDS: array dimensions too high: {}", ndim); ndim = SDS_MAX_DIMS; } @@ -2736,7 +2743,7 @@ bool CompressFileArray(void * pstCompressArraysV, int32_t core, int64_t t) pArrayBlock->HeaderLength = sizeof(SDS_ARRAY_BLOCK); pArrayBlock->Magic = COMPRESSION_MAGIC; - LOGGING("[%lld][%lld] seek to fileOffset %lld sz: %lld\n", t, arrayNumber, fileOffset, pArrayBlock->ArrayCompressedSize); + logger->debug("[{}][{}] seek to fileOffset {} sz: {}", t, arrayNumber, fileOffset, pArrayBlock->ArrayCompressedSize); //=========================== // Write compressed chunk @@ -2745,9 +2752,9 @@ bool CompressFileArray(void * pstCompressArraysV, int32_t core, int64_t t) if ((size_t)result != cSize) { - printf( - "[%lld] error while writing into compressed offset:%lld sz: %zu " - " vs %lld\n", + logger->error( + "[{}] error while writing into compressed offset:{} sz: {} " + " vs {}", t, fileOffset, cSize, result); } } @@ -2781,7 +2788,7 @@ int64_t CalculateSharedMemorySize(SDS_FILE_HEADER * pFileHeader, SDS_ARRAY_BLOCK if (arraycount != pFileHeader->ArraysWritten) { - printf("possibly incomplete file %lld %lld\n", arraycount, pFileHeader->ArraysWritten); + logger->warn("possibly incomplete file {} {}", arraycount, pFileHeader->ArraysWritten); } } return totalSize; @@ -2874,7 +2881,7 @@ bool SDSWriteFileInternal(const char * fileName, { if (shareName) { - LOGGING("Trying to store in shared memory\n"); + logger->debug("Trying to store in shared memory"); // Fill in fake so that we can calculate size FillFileHeader(pFileHeader, 0, COMPRESSION_MODE_SHAREDMEMORY, COMPRESSION_TYPE_NONE, 0, sdsFileType, 0, authorId, @@ -2883,7 +2890,7 @@ bool SDSWriteFileInternal(const char * fileName, pFileHeader->ArraysWritten = arrayCount; - LOGGING("Making sharedname %s\n", shareName); + logger->debug("Making sharedname {}", shareName); // Try to allocate sharename DefaultMemoryIO.MakeShareName(fileName, shareName); @@ -2897,7 +2904,7 @@ bool SDSWriteFileInternal(const char * fileName, totalSize += SDS_PAD_NUMBER(aInfo[t].ArrayLength * aInfo[t].ItemSize); } - LOGGING("trying to allocate %lld\n", totalSize); + logger->debug("trying to allocate {}", totalSize); // Make sure we can allocate it HRESULT hr = DefaultMemoryIO.Begin(totalSize); @@ -2917,16 +2924,16 @@ bool SDSWriteFileInternal(const char * fileName, // Reach here, then shared memory allocated SDS_FILE_HEADER * pMemoryFileHeader = DefaultMemoryIO.GetFileHeader(); - LOGGING("Writing header to %p from %p\n", pMemoryFileHeader, pFileHeader); + logger->debug("Writing header to {} from {}", (void *)pMemoryFileHeader, (void *)pFileHeader); // Step 1: copy fileheader memcpy(pMemoryFileHeader, pFileHeader, sizeof(SDS_FILE_HEADER)); - LOGGING("Step 2\n"); + logger->debug("Step 2"); // Step 2: copy names memcpy(DefaultMemoryIO.GetMemoryOffset(pMemoryFileHeader->NameBlockOffset), pListNames, listNameSize); - LOGGING("Copying metadata size:%lld \n", (long long)metaDataSize); + logger->debug("Copying metadata size:{} ", (long long)metaDataSize); // Step 3: copy metadata memcpy(DefaultMemoryIO.GetMemoryOffset(pMemoryFileHeader->MetaBlockOffset), metaData, metaDataSize); @@ -2941,7 +2948,7 @@ bool SDSWriteFileInternal(const char * fileName, // Step 4: have to fill in arrayblocks for (int32_t arrayNumber = 0; arrayNumber < arrayCount; arrayNumber++) { - LOGGING("start offset %d %lld\n", arrayNumber, startOffset); + logger->debug("start offset {} {}", arrayNumber, startOffset); // same size since uncompressed pDestArrayBlock[arrayNumber].ArrayCompressedSize = pDestArrayBlock[arrayNumber].ArrayUncompressedSize = @@ -2979,7 +2986,7 @@ bool SDSWriteFileInternal(const char * fileName, startOffset += SDS_PAD_NUMBER(pDestArrayBlock[arrayNumber].ArrayUncompressedSize); } - LOGGING("Copying array data %lld\n", arrayCount); + logger->debug("Copying array data {}", arrayCount); // Step 5 (can make multithreaded) -- copy array blocks for (int32_t arrayNumber = 0; arrayNumber < arrayCount; arrayNumber++) @@ -2993,16 +3000,16 @@ bool SDSWriteFileInternal(const char * fileName, aInfo[arrayNumber].pData, pDestArrayBlock[arrayNumber].ArrayUncompressedSize); } - LOGGING("Succeeded in copying memory\n"); + logger->debug("Succeeded in copying memory"); // Keep handle open? } catch (...) { // NOTE this does not catch bus errors which occur when out of disk // space - printf( + logger->error( "!!!Failed to write all of shared memory. May be out of " - "shared memory.\n"); + "shared memory."); } #if defined(_WIN32) // For windows we cannot close it since that will free the memory back @@ -3010,7 +3017,7 @@ bool SDSWriteFileInternal(const char * fileName, } else { // the else is hit when the SIGBUS signal was sent - printf("BUS Error while writing to shared memory, check swap space.\n"); + logger->error("BUS Error while writing to shared memory, check swap space."); } // For linux restore signal handler signal(SIGBUS, sigbus_orighandler); @@ -3020,7 +3027,7 @@ bool SDSWriteFileInternal(const char * fileName, } else { - printf("!!Failed to create shared memory\n"); + logger->error("!!Failed to create shared memory"); } } else @@ -3037,7 +3044,7 @@ bool SDSWriteFileInternal(const char * fileName, authorId, pListNames, listNameSize, listNameCount, metaData, metaDataSize, arrayCount, mode, pFolderName, bandSize, pWriteInfo); - LOGGING("Current fileoffset is %lld\n", pFileHeader->FileOffset); + logger->debug("Current fileoffset is {}", pFileHeader->FileOffset); if (sdsFile) { // Allocate an arrayblock and zero it out @@ -3085,7 +3092,7 @@ bool SDSWriteFileInternal(const char * fileName, g_cMathWorker->DoMultiThreadedWork((int)arrayCount, CompressFileArray, pstCompressArrays); pWriteCallbacks->EndAllowThreads(saveState); - LOGGING("End of compressing\n"); + logger->debug("End of compressing"); for (int32_t j = 0; j < numCores; j++) { @@ -3105,7 +3112,7 @@ bool SDSWriteFileInternal(const char * fileName, } else { - LOGGING("Failure to start compressed file %s\n", fileName); + logger->debug("Failure to start compressed file {}", fileName); } } } @@ -3378,9 +3385,9 @@ bool PossiblyShrinkArray(SDS_ALLOCATE_ARRAY * pArrayCallback, SDS_READ_CALLBACKS newLength = dim0Length; } - LOGGING( - "-->Allocation reduction for %s filter: %lld vs %lld " - "bool:%lld flags:%d\n", + logger->debug( + "-->Allocation reduction for {} filter: {} vs {} " + "bool:{} flags:{}", pArrayCallback->pArrayName, newLength, dim0Length, pReadCallbacks->Filter.BoolMaskTrueCount, pArrayCallback->sdsFlags); pArrayCallback->dims[0] = newLength; @@ -3518,8 +3525,8 @@ class SDSDecompressFile if (isSharedMemory) { pDestInfo->pData = sdsArrayCallback.data = DefaultMemoryIO.GetMemoryOffset(pBlock->ArrayDataOffset); - LOGGING("Shared memory set to %p %lld memoryoffset: %p\n", sdsArrayCallback.data, pBlock->ArrayDataOffset, - DefaultMemoryIO.GetMemoryOffset(0)); + logger->debug("Shared memory set to {} {} memoryoffset: {}", sdsArrayCallback.data, pBlock->ArrayDataOffset, + DefaultMemoryIO.GetMemoryOffset(0)); } //----------------------------- @@ -3530,7 +3537,7 @@ class SDSDecompressFile bool wasFiltered = false; - // LOGGING("Checking to allocate name %s\n", pAllocateArray->pArrayName); + // logger->debug("Checking to allocate name {}", pAllocateArray->pArrayName); // Include exclude check if (! pArrayNames || IsNameIncluded(pInclude, pFolderName, sdsArrayCallback.pArrayName, isOneFile)) { @@ -3545,12 +3552,12 @@ class SDSDecompressFile pReadCallbacks->AllocateArrayCallback(&sdsArrayCallback); - LOGGING( - "Allocating dims:%d -- %lld %lld %lld flags:%d itemsize:%d " - "wasFiltered: %d\n", + logger->debug( + "Allocating dims:{} -- {} {} {} flags:{} itemsize:{} " + "wasFiltered: {}", (int)pBlock->NDim, pBlock->Dimensions[0], pBlock->Dimensions[1], pBlock->Dimensions[2], pBlock->Flags, pBlock->ItemSize, wasFiltered); - LOGGING("Strides %lld %lld %lld \n", pBlock->Strides[0], pBlock->Strides[1], pBlock->Strides[2]); + logger->debug("Strides {} {} {} ", pBlock->Strides[0], pBlock->Strides[1], pBlock->Strides[2]); } } @@ -3659,7 +3666,7 @@ class SDSDecompressFile { if (pArrayBlocks != NULL) { - printf("Double Allocation array blocks!!\n"); + logger->warn("Double Allocation array blocks!!"); } pArrayBlocks = (SDS_ARRAY_BLOCK *)WORKSPACE_ALLOC(pFileHeader->ArrayBlockSize); @@ -3687,7 +3694,7 @@ class SDSDecompressFile { if (MetaData != NULL) { - printf("Double Allocation meta data!!\n"); + logger->warn("Double Allocation meta data!!"); } MetaData = (char *)WORKSPACE_ALLOC(size); if (MetaData) @@ -3717,7 +3724,7 @@ class SDSDecompressFile NameCount = nameBlockCount; if (pNameData != NULL) { - printf("Double Allocation nameData!!\n"); + logger->warn("Double Allocation nameData!!"); } pNameData = (char *)WORKSPACE_ALLOC(nameSize); @@ -3761,7 +3768,7 @@ class SDSDecompressFile // Close file handle void EndDecompressedFile() { - LOGGING("End decompressed file\n"); + logger->debug("End decompressed file"); if (SDSFile != BAD_SDS_HANDLE) { @@ -3785,8 +3792,8 @@ class SDSDecompressFile int64_t GetTotalArraysWritten() { // todo: - LOGGING("Section offsets %p psectiondata %p sectioncount: %lld\n", cSectionName.pSectionOffsets, - cSectionName.pSectionData, cSectionName.SectionCount); + logger->debug("Section offsets {} psectiondata {} sectioncount: {}", (void *)cSectionName.pSectionOffsets, + cSectionName.pSectionData, cSectionName.SectionCount); return pFileHeader->ArraysWritten; } @@ -3850,8 +3857,8 @@ class SDSDecompressFile // Read in metadata from disk/network int64_t bytesRead = 0; - LOGGING("in decompress meta %lld vs %lld offset:%lld handle:%p\n", metaCompressedSize, - pFileHeader->TotalMetaUncompressedSize, pFileHeader->MetaBlockOffset, SDSFile); + logger->debug("in decompress meta {} vs {} offset:{} handle:{}", metaCompressedSize, + pFileHeader->TotalMetaUncompressedSize, pFileHeader->MetaBlockOffset, SDSFile); // Did we compress the meta data? // If the decompressed size is the same as uncompressed, then it was never @@ -3920,7 +3927,7 @@ class SDSDecompressFile int64_t metaUncompressedSize = metaCompressedSize; // meta was never compressed - LOGGING("meta was not compressed\n"); + logger->debug("meta was not compressed"); // user supplying buffer? if (! metaDataUncompressed) @@ -3942,7 +3949,7 @@ class SDSDecompressFile pFileHeader->MetaBlockOffset); } - LOGGING("out decompress meta\n"); + logger->debug("out decompress meta"); return true; } @@ -3978,7 +3985,7 @@ class SDSDecompressFile int64_t totalSize = CalculateSharedMemorySize(pFileHeader, pArrayBlocks); int64_t arrayCount = pFileHeader->ArraysWritten; - LOGGING("CopyIntoSharedMem: trying to allocate %lld\n", totalSize); + logger->debug("CopyIntoSharedMem: trying to allocate {}", totalSize); // Make sure we can allocate it HRESULT hr = DefaultMemoryIO.Begin(totalSize); @@ -3989,10 +3996,10 @@ class SDSDecompressFile // Fileheader for shared memory SDS_FILE_HEADER * pMemoryFileHeader = DefaultMemoryIO.GetFileHeader(); - LOGGING( - "Fill file header namecount:%lld arrayswritten:%lld " - "address %p\n", - pFileHeader->NameBlockCount, pFileHeader->ArraysWritten, pMemoryFileHeader); + logger->debug( + "Fill file header namecount:{} arrayswritten:{} " + "address {}", + pFileHeader->NameBlockCount, pFileHeader->ArraysWritten, (void *)pMemoryFileHeader); // The memory header // Shared memory is stored uncompressed @@ -4003,7 +4010,7 @@ class SDSDecompressFile pFileHeader->AuthorId, pFileHeader->NameBlockSize, pFileHeader->NameBlockCount, pFileHeader->TotalMetaUncompressedSize, pFileHeader->ArraysWritten, 0); - LOGGING("Fill name block\n"); + logger->debug("Fill name block"); // Read name block DefaultFileIO.FileReadChunk(NULL, SDSFile, DefaultMemoryIO.GetMemoryOffset(pMemoryFileHeader->NameBlockOffset), @@ -4016,7 +4023,7 @@ class SDSDecompressFile // goto EXIT_DECOMPRESS; } - LOGGING("Fill meta block\n"); + logger->debug("Fill meta block"); // Read from file and write to shared memory bool bResult = @@ -4024,7 +4031,7 @@ class SDSDecompressFile if (bResult) { - LOGGING("Meta string is %s\n", DefaultMemoryIO.GetMemoryOffset(pMemoryFileHeader->MetaBlockOffset)); + logger->debug("Meta string is {}", DefaultMemoryIO.GetMemoryOffset(pMemoryFileHeader->MetaBlockOffset)); SDS_ARRAY_BLOCK * pDestArrayBlock = DefaultMemoryIO.GetArrayBlock(0); @@ -4038,7 +4045,7 @@ class SDSDecompressFile // NOTE: have to fixup arrayblocks for (int32_t i = 0; i < arrayCount; i++) { - LOGGING("start offset %d %lld\n", i, startOffset); + logger->debug("start offset {} {}", i, startOffset); // same size since uncompressed pDestArrayBlock[i].ArrayCompressedSize = pDestArrayBlock[i].ArrayUncompressedSize; @@ -4057,7 +4064,7 @@ class SDSDecompressFile startOffset += SDS_PAD_NUMBER(pDestArrayBlock[i].ArrayUncompressedSize); } - LOGGING("last offset %lld\n", startOffset); + logger->debug("last offset {}", startOffset); bool oneFile = (pFileHeader->FileType == SDS_FILE_TYPE_ONEFILE); int32_t fileType = pFileHeader->FileType; @@ -4102,7 +4109,7 @@ class SDSDecompressFile } pMemoryFileHeader->ArraysWritten = arrayCount; - LOGGING("End fill array block %lld\n", arrayCount); + logger->debug("End fill array block {}", arrayCount); ; return true; } @@ -4180,7 +4187,7 @@ class SDSDecompressFile if (nameSize) { - LOGGING("Name Block Count %lld, namesize %lld\n", pFileHeader->NameBlockCount, nameSize); + logger->debug("Name Block Count {}, namesize {}", pFileHeader->NameBlockCount, nameSize); AllocateNameData(pFileHeader->NameBlockCount, nameSize); @@ -4211,7 +4218,7 @@ class SDSDecompressFile // new ver 4.3: handles filter= bool DecompressFileInternal(SDS_READ_CALLBACKS * pReadCallbacks, int32_t core, int64_t startOffset) { - LOGGING("Reading filename %s normally. Offset: %lld\n", FileName, startOffset); + logger->debug("Reading filename {} normally. Offset: {}", FileName, startOffset); // read into pFileHeader // Fills in pFileHeader @@ -4254,8 +4261,8 @@ class SDSDecompressFile goto EXIT_DECOMPRESS; } - LOGGING("Reading array block at offset:%lld size: %lld \n", pFileHeader->ArrayBlockOffset, - pFileHeader->ArrayBlockSize); + logger->debug("Reading array block at offset:{} size: {} ", pFileHeader->ArrayBlockOffset, + pFileHeader->ArrayBlockSize); int64_t bytesRead = DefaultFileIO.FileReadChunk(NULL, SDSFile, pArrayBlocks, pFileHeader->ArrayBlockSize, pFileHeader->ArrayBlockOffset); if (bytesRead != pFileHeader->ArrayBlockSize) @@ -4265,7 +4272,7 @@ class SDSDecompressFile } int64_t tupleSize = pFileHeader->ArraysWritten; - LOGGING("Arrays to read %lld %p\n", tupleSize, pArrayBlocks); + logger->debug("Arrays to read {} {}", tupleSize, (void *)pArrayBlocks); // If we got this far, the file is good IsFileValid = true; @@ -4289,7 +4296,7 @@ class SDSDecompressFile pstCompressArrays->fileHandle = SDSFile; pstCompressArrays->pFileHeader = pFileHeader; - LOGGING("Done allocating arrays %lld\n", tupleSize); + logger->debug("Done allocating arrays {}", tupleSize); // ---- ALLOCATE EVENT HANDLES int32_t numCores = g_cMathWorker->GetNumCores(); @@ -4355,7 +4362,7 @@ class SDSDecompressFile // void * DecompressFile(SDS_READ_CALLBACKS * pReadCallbacks, int32_t core, int64_t fileOffset) { - LOGGING("Start of DCF %s [%lld] %s\n", FileName, InstanceIndex, ShareName); + logger->debug("Start of DCF {} [{}] {}", FileName, InstanceIndex, ShareName); //------------------------------------------------------ // CHECK FOR SHARED MEMORY @@ -4371,7 +4378,7 @@ class SDSDecompressFile if (result < 0) { - LOGGING("Failed to find existing share name %s\n", DefaultMemoryIO.SharedMemoryName); + logger->debug("Failed to find existing share name {}", DefaultMemoryIO.SharedMemoryName); if (Mode == COMPRESSION_MODE_INFO) { @@ -4385,7 +4392,7 @@ class SDSDecompressFile if (! bResult) { - LOGGING("Failed to alloc shared memory for %s\n", FileName); + logger->debug("Failed to alloc shared memory for {}", FileName); DefaultMemoryIO.Destroy(); } } @@ -4393,7 +4400,7 @@ class SDSDecompressFile if (bResult) { - LOGGING("Success with find existing share... read from there %s\n", DefaultMemoryIO.SharedMemoryName); + logger->debug("Success with find existing share... read from there {}", DefaultMemoryIO.SharedMemoryName); SDS_SHARED_MEMORY_CALLBACK SMCB; SMCB.pFileHeader = DefaultMemoryIO.GetFileHeader(); @@ -4410,7 +4417,8 @@ class SDSDecompressFile } else { - LOGGING("Failed to find existing share: %s... going to try file %s\n", DefaultMemoryIO.SharedMemoryName, FileName); + logger->debug("Failed to find existing share: {}... going to try file {}", DefaultMemoryIO.SharedMemoryName, + FileName); } // Drop into normal file reading @@ -4498,16 +4506,16 @@ void UpgradeType(SDS_ARRAY_BLOCK * pMasterArrayBlock, int32_t newdtype, int64_t } } - LOGGING("Upgrading master dtype to %d from %d size:%d\n", newdtype, pMasterArrayBlock->DType, isize); + logger->debug("Upgrading master dtype to {} from {} size:{}", newdtype, pMasterArrayBlock->DType, isize); pMasterArrayBlock->DType = newdtype; pMasterArrayBlock->ItemSize = isize; // Check dims and fortran vs cstyle if (pMasterArrayBlock->NDim > 1 && pMasterArrayBlock->Flags & SDS_ARRAY_F_CONTIGUOUS) { - printf( + logger->error( "!!!likely internal error with fortran array > dim 1 and upgrading " - "dtype!\n"); + "dtype!"); pMasterArrayBlock->Strides[pMasterArrayBlock->NDim - 1] = isize; } else @@ -4527,9 +4535,9 @@ typedef void (*CONVERT_INPLACE)(void * pDataIn, void * pDataOut, int64_t dataOut template static void ConvertInplace(void * pDataIn, void * pDataOut, int64_t dataInSize, int32_t dtypein, int32_t dtypeout) { - LOGGING( - "**conversion %p %p inLenSize: %lld inItemSize:%lld " - "outItemSize:%lld\n", + logger->debug( + "**conversion {} {} inLenSize: {} inItemSize:{} " + "outItemSize:{}", pDataIn, pDataOut, dataInSize, sizeof(T), sizeof(U)); T * pIn = (T *)pDataIn; U * pOut = (U *)pDataOut; @@ -4541,7 +4549,7 @@ static void ConvertInplace(void * pDataIn, void * pDataOut, int64_t dataInSize, if (dataInSize > dataOutSize) { - printf("!! internal error in convertinplace\n"); + logger->error("!! internal error in convertinplace"); return; } @@ -4576,9 +4584,9 @@ static void ConvertInplace(void * pDataIn, void * pDataOut, int64_t dataInSize, template static void ConvertInplaceFloat(void * pDataIn, void * pDataOut, int64_t dataInSize, int32_t dtypein, int32_t dtypeout) { - LOGGING( - "**conversionf %p %p inLenSize: %lld inItemSize:%lld " - "outItemSize:%lld\n", + logger->debug( + "**conversionf {} {} inLenSize: {} inItemSize:{} " + "outItemSize:{}", pDataIn, pDataOut, dataInSize, sizeof(T), sizeof(U)); T * pIn = (T *)pDataIn; U * pOut = (U *)pDataOut; @@ -4589,7 +4597,7 @@ static void ConvertInplaceFloat(void * pDataIn, void * pDataOut, int64_t dataInS if (dataInSize > dataOutSize) { - printf("!! internal error in convertinplace\n"); + logger->error("!! internal error in convertinplace"); return; } @@ -4622,9 +4630,9 @@ static void ConvertInplaceFloat(void * pDataIn, void * pDataOut, int64_t dataInS template static void ConvertInplaceString(void * pDataIn, void * pDataOut, int64_t dataInSize, int32_t dtypein, int32_t dtypeout) { - LOGGING( - "**conversions %p %p inLenSize: %lld inItemSize:%lld " - "outItemSize:%lld\n", + logger->debug( + "**conversions {} {} inLenSize: {} inItemSize:{} " + "outItemSize:{}", pDataIn, pDataOut, dataInSize, sizeof(T), sizeof(U)); T * pIn = (T *)pDataIn; U * pOut = (U *)pDataOut; @@ -4634,7 +4642,7 @@ static void ConvertInplaceString(void * pDataIn, void * pDataOut, int64_t dataIn if (dataInSize > dataOutSize) { - printf("!! internal error in convertinplace\n"); + logger->error("!! internal error in convertinplace"); return; } @@ -4757,10 +4765,10 @@ static CONVERT_INPLACE GetInplaceConversionFunction(int32_t inputType, int32_t o // Invalid fill when a column exist in one file but not the other void GapFill(void * destBuffer, SDSArrayInfo * pDestInfo) { - LOGGING(">>> gap fill in decompress multi array length:%lld dtype:%d %p\n", pDestInfo->ArrayLength, pDestInfo->NumpyDType, - destBuffer); - LOGGING(">>> more gap dims: %d itemsz:%d dim0:%lld strides0:%lld\n", pDestInfo->NDim, pDestInfo->ItemSize, - pDestInfo->Dimensions[0], pDestInfo->Strides[0]); + logger->debug(">>> gap fill in decompress multi array length:{} dtype:{} {}", pDestInfo->ArrayLength, + pDestInfo->NumpyDType, destBuffer); + logger->debug(">>> more gap dims: {} itemsz:{} dim0:{} strides0:{}", pDestInfo->NDim, pDestInfo->ItemSize, + pDestInfo->Dimensions[0], pDestInfo->Strides[0]); int64_t oneRowSize = pDestInfo->ItemSize; // Calc oneRowSize for multidimensional @@ -4902,8 +4910,8 @@ void ConvertDType(char * destBuffer, SDS_ARRAY_BLOCK * pMasterBlock, SDS_ARRAY_B int32_t sdtype = FixupDType(pSlaveBlock->DType, pSlaveBlock->ItemSize); int32_t mdtype = FixupDType(pMasterBlock->DType, pMasterBlock->ItemSize); - LOGGING("Convert dtype from:%d to: %d buffer:%p size: %lld %d vs %d\n", sdtype, mdtype, destBuffer, - slaveRows * slaveItemSize, pSlaveBlock->NDim, pMasterBlock->NDim); + logger->debug("Convert dtype from:{} to: {} buffer:{} size: {} {} vs {}", sdtype, mdtype, destBuffer, + slaveRows * slaveItemSize, pSlaveBlock->NDim, pMasterBlock->NDim); CONVERT_INPLACE pConvert = GetInplaceConversionFunction(sdtype, mdtype); // Code below to be deleted when bugs in filtering while loading are gone @@ -4923,7 +4931,7 @@ void ConvertDType(char * destBuffer, SDS_ARRAY_BLOCK * pMasterBlock, SDS_ARRAY_B } else { - printf("!!Internal error cannot convert %d to %d\n", sdtype, mdtype); + logger->error("!!Internal error cannot convert {} to {}", sdtype, mdtype); } } @@ -5432,7 +5440,7 @@ void StringFixup(char * destBuffer, SDS_ARRAY_BLOCK * pMasterBlock, SDS_ARRAY_BL { if (pMasterBlock->DType == SDS_STRING) { - LOGGING("string gap: %lld rows: %lld smallerSize:%lld oneRowSize:%lld\n", gap, rows, slaveItemSize, oneRowSize); + logger->debug("string gap: {} rows: {} smallerSize:{} oneRowSize:{}", gap, rows, slaveItemSize, oneRowSize); char * pEndString1 = destBuffer + (slaveItemSize * rows); char * pEndString2 = destBuffer + (oneRowSize * rows); @@ -5459,7 +5467,7 @@ void StringFixup(char * destBuffer, SDS_ARRAY_BLOCK * pMasterBlock, SDS_ARRAY_BL } else { - LOGGING("unicode gap: %lld rows: %lld smallerSize:%lld oneRowSize:%lld\n", gap, rows, slaveItemSize, oneRowSize); + logger->debug("unicode gap: {} rows: {} smallerSize:{} oneRowSize:{}", gap, rows, slaveItemSize, oneRowSize); // Unicode loop oneRowSize /= 4; slaveItemSize /= 4; @@ -5517,9 +5525,9 @@ SDS_COMPATIBLE IsArrayCompatible(const char * colName, SDS_ARRAY_BLOCK * pMaster { // String to UNICODE happens here c.NeedsConversion = true; - LOGGING( - "step1 conversion %s %d %d masteritemsize:%d vs %d length: " - "%lld %lld\n", + logger->debug( + "step1 conversion {} {} {} masteritemsize:{} vs {} length: " + "{} {}", colName, odtype, mdtype, pMasterArrayBlock->ItemSize, pArrayBlock->ItemSize, pMasterArrayBlock->Dimensions[0], pArrayBlock->Dimensions[0]); // pick the higher type @@ -5528,7 +5536,7 @@ SDS_COMPATIBLE IsArrayCompatible(const char * colName, SDS_ARRAY_BLOCK * pMaster if (doFixup) { // upgrade the dtype - LOGGING("step2 conversion %d\n", pArrayBlock->ItemSize); + logger->debug("step2 conversion {}", pArrayBlock->ItemSize); UpgradeType(pMasterArrayBlock, odtype, pArrayBlock->ItemSize); } } @@ -5537,7 +5545,7 @@ SDS_COMPATIBLE IsArrayCompatible(const char * colName, SDS_ARRAY_BLOCK * pMaster // Special case when unicode to string if (mdtype == SDS_UNICODE && odtype == SDS_STRING) { - LOGGING("step2 special conversion %d\n", pArrayBlock->ItemSize); + logger->debug("step2 special conversion {}", pArrayBlock->ItemSize); if ((pArrayBlock->ItemSize * 4) > pMasterArrayBlock->ItemSize) { UpgradeType(pMasterArrayBlock, mdtype, pArrayBlock->ItemSize * 4); @@ -5556,9 +5564,9 @@ SDS_COMPATIBLE IsArrayCompatible(const char * colName, SDS_ARRAY_BLOCK * pMaster if (cwhole.w.isFloat && (cwhole.w.isInt || cwhole.w.isUInt)) { c.NeedsConversion = true; - LOGGING( + logger->debug( "Conversion: possible upgrade to float32/64 from int/uint32_t " - "for col %s %d to %d\n", + "for col {} {} to {}", colName, mdtype, odtype); if (doFixup) @@ -5575,7 +5583,7 @@ SDS_COMPATIBLE IsArrayCompatible(const char * colName, SDS_ARRAY_BLOCK * pMaster else { // we are ok here... - LOGGING("Conversion: did nothing\n"); + logger->debug("Conversion: did nothing"); } } else @@ -5598,7 +5606,7 @@ SDS_COMPATIBLE IsArrayCompatible(const char * colName, SDS_ARRAY_BLOCK * pMaster { bool handleInt64ToUInt64 = true; c.NeedsConversion = true; - LOGGING("Conversion: int32_t / uint32_t for col %s %d to %d fixup: %d\n", colName, mdtype, odtype, doFixup); + logger->debug("Conversion: int32_t / uint32_t for col {} {} to {} fixup: {}", colName, mdtype, odtype, doFixup); if (doFixup) { @@ -5616,9 +5624,9 @@ SDS_COMPATIBLE IsArrayCompatible(const char * colName, SDS_ARRAY_BLOCK * pMaster // here... precision loss This should be an option if (handleInt64ToUInt64) { - printf( + logger->warn( "Warning: ignoring sign loss going to from int/uint64 for " - "col: %s\n", + "col: {}", colName); // flip it back off c.NeedsConversion = false; @@ -5626,9 +5634,9 @@ SDS_COMPATIBLE IsArrayCompatible(const char * colName, SDS_ARRAY_BLOCK * pMaster else { // This is the old code - printf( + logger->warn( "Warning: precision loss going to float64 from int/uint64 " - "for col: %s\n", + "for col: {}", colName); UpgradeType(pMasterArrayBlock, SDS_DOUBLE, 8); } @@ -5657,7 +5665,7 @@ SDS_COMPATIBLE IsArrayCompatible(const char * colName, SDS_ARRAY_BLOCK * pMaster else { // NOTE possible string to unicode conversion here.. unicode - LOGGING("!!!Incompat due to dtypes %d %d\n", mdtype, odtype); + logger->debug("!!!Incompat due to dtypes {} {}", mdtype, odtype); c.IsCompatible = false; } } @@ -5668,9 +5676,9 @@ SDS_COMPATIBLE IsArrayCompatible(const char * colName, SDS_ARRAY_BLOCK * pMaster { if (pMasterArrayBlock->ItemSize != pArrayBlock->ItemSize) { - LOGGING( - "Conversion: String width mismatch on col: %s master " - "itemsize:%d vs itemsize: %d\n", + logger->debug( + "Conversion: String width mismatch on col: {} master " + "itemsize:{} vs itemsize: {}", colName, pMasterArrayBlock->ItemSize, pArrayBlock->ItemSize); if (doFixup) { @@ -5693,7 +5701,7 @@ SDS_COMPATIBLE IsArrayCompatible(const char * colName, SDS_ARRAY_BLOCK * pMaster // this a void)? if (pMasterArrayBlock->ItemSize != pArrayBlock->ItemSize) { - LOGGING("!!!Incompat due to itemsize\n"); + logger->debug("!!!Incompat due to itemsize"); c.IsCompatible = false; } } @@ -5701,7 +5709,7 @@ SDS_COMPATIBLE IsArrayCompatible(const char * colName, SDS_ARRAY_BLOCK * pMaster if (pMasterArrayBlock->NDim != pArrayBlock->NDim) { - LOGGING("!!!Incompat due to ndim %d not matching\n", pMasterArrayBlock->NDim); + logger->debug("!!!Incompat due to ndim {} not macthing", pMasterArrayBlock->NDim); c.IsCompatible = false; } @@ -5711,7 +5719,7 @@ SDS_COMPATIBLE IsArrayCompatible(const char * colName, SDS_ARRAY_BLOCK * pMaster { if (pMasterArrayBlock->Dimensions[i] != pArrayBlock->Dimensions[i]) { - LOGGING("!!!Incompat due to dim %d not matching\n", i); + logger->debug("!!!Incompat due to dim {} not macthing", i); c.IsCompatible = false; } } @@ -5767,7 +5775,7 @@ void * CheckRotationalFixup(SDS_IO_PACKET * pIOPacket) { if (pMasterBlock->NDim > 2) { - printf("!!! error cannot rotate above two dimensions\n"); + logger->error("!!! error cannot rotate above two dimensions"); } int64_t allocSize = pBlockInfo->ItemSize; for (int32_t j = 0; j < pBlockInfo->NDim; j++) @@ -5784,7 +5792,7 @@ void * CheckRotationalFixup(SDS_IO_PACKET * pIOPacket) // pick up more string dimensions if (pBlockInfo->NDim > 1) { - printf("!!! error cannot handle multid strings\n"); + logger->error("!!! error cannot handle multid strings"); } // Allocate a temporary buffer to load 1 or 4 byte string into // This buffer will have to be copied into @@ -5970,9 +5978,9 @@ bool DecompressMultiArray(void * pstCompressArraysV, //} // Stacking plus filtering // printf("**step2 %p\n", pMultiIOPackets->pFilter->pFilterInfo); - LOGGING( - "***stacking plus filter stack position: %lld buffer: %p " - "TrueCount: %lld\n", + logger->debug( + "***stacking plus filter stack position: {} buffer: {} " + "TrueCount: {}", pIOPacket->StackPosition, destBuffer, pMultiIOPackets->pFilter->pFilterInfo ? pMultiIOPackets->pFilter->pFilterInfo[pIOPacket->StackPosition].TrueCount : @@ -5997,9 +6005,9 @@ bool DecompressMultiArray(void * pstCompressArraysV, } else { - LOGGING( - "[%lld]***stacking no filter stack position: %lld buffer: %p " - " rowlength: %lld colname: %s\n", + logger->debug( + "[{}]***stacking no filter stack position: {} buffer: {} " + " rowlength: {} colname: {}", t, pIOPacket->StackPosition, destBuffer, pBlockInfo->Dimensions[0], pIOPacket->ColName); result = ReadAndDecompressArrayBlock(pBlockInfo, pMultiIOPackets->eventHandles[core], sdsFile, tempFileBuffer, @@ -6028,10 +6036,10 @@ bool DecompressMultiArray(void * pstCompressArraysV, if (pIOPacket->Compatible.NeedsConversion) { // done inplace (no need for extra buffer) - LOGGING( - "Needs conversion mb dtype:%d mb itemsize: %d dim0: " - "%lld slaveRowLength:%lld needs stringfixup: %d " - "filterflags: %d\n", + logger->debug( + "Needs conversion mb dtype:{} mb itemsize: {} dim0: " + "{} slaveRowLength:{} needs stringfixup: {} " + "filterflags: {}", pIOPacket->pMasterBlock->DType, pIOPacket->pMasterBlock->ItemSize, pIOPacket->pMasterBlock->Dimensions[0], slaveRowLength, pIOPacket->Compatible.NeedsStringFixup, pMasterBlock->Flags); @@ -6230,7 +6238,7 @@ class SDSDecompressManyFiles TotalColumnGaps++; } - LOGGING("%s ** %lld enum: %d\n", columnName, validCount, arrayEnum); + logger->debug("{} ** {} enum: {}", columnName, validCount, arrayEnum); ColumnExists.emplace(item, TotalUniqueColumns); // Brand new column @@ -6266,13 +6274,12 @@ class SDSDecompressManyFiles if (compat.NeedsRotation) { // cannot handle - printf("Column '%s' needs rotation from col or row major and currently this is not allowed\n", columnName); + logger->warn("Column '{}' needs rotation from col or row major and currently this is not allowed", columnName); TotalDimensionProblems++; } if (! compat.IsCompatible) { - printf("Warning: Column '%s' is not compatible\n", columnName); - TotalDimensionProblems++; + logger->warn("Warning: Column '{}' has both string and unicode. Support for this is experimental", columnName); } if (compat.NeedsStringFixup) { @@ -6362,7 +6369,7 @@ class SDSDecompressManyFiles } } - LOGGING("Total IO Packet %lld\n", totalIOPackets); + logger->debug("Total IO Packet {}", totalIOPackets); // Allocate MultiIO PACKETS!! SDS_MULTI_IO_PACKETS * pMultiIOPackets = SDS_MULTI_IO_PACKETS::Allocate(totalIOPackets, &pReadCallbacks->Filter); @@ -6377,7 +6384,7 @@ class SDSDecompressManyFiles { int64_t tupleSize = pSDSDecompress->pFileHeader->ArraysWritten; - LOGGING("Allocating %lld arrays\n", tupleSize); + logger->debug("Allocating {} arrays", tupleSize); SDS_IO_PACKET * pIOPacket = &pMultiIOPackets->pIOPacket[currentPos]; SDSArrayInfo * pArrayInfo = &pMultiIOPackets->pDestInfo[currentPos]; @@ -6425,7 +6432,7 @@ class SDSDecompressManyFiles static int64_t AppendToFile(SDS_FILE_HANDLE outFileHandle, SDSDecompressFile * pSDSDecompress, int64_t fileOffset, int64_t fileSize, char * pSectionData, int64_t & currentSection) { - LOGGING("files %s has size %lld\n", pSDSDecompress->FileName, fileSize); + logger->debug("files {} has size {}", pSDSDecompress->FileName, fileSize); SDS_FILE_HEADER * pFileHeader = &pSDSDecompress->FileHeader; int64_t currentOffset = fileOffset; @@ -6436,7 +6443,7 @@ class SDSDecompressManyFiles if (pFileHeader->SectionBlockOffset) { - LOGGING("!!warning file %s has section within section when concat\n", pSDSDecompress->FileName); + logger->debug("!!warning file {} has section within section when concat", pSDSDecompress->FileName); hasSections = true; } @@ -6448,7 +6455,7 @@ class SDSDecompressManyFiles // fileSize = calculatedSize; //} - LOGGING("sds_concat %lld vs %lld fileoffset:%lld\n", fileSize, pFileHeader->GetEndOfFileOffset(), fileOffset); + logger->debug("sds_concat {} vs {} fileoffset:{}", fileSize, pFileHeader->GetEndOfFileOffset(), fileOffset); // Fixup header offsets if (pFileHeader->NameBlockOffset) @@ -6469,7 +6476,7 @@ class SDSDecompressManyFiles int64_t bytesXfer = DefaultFileIO.FileWriteChunk(NULL, outFileHandle, pFileHeader, sizeof(SDS_FILE_HEADER), fileOffset); if (bytesXfer != sizeof(SDS_FILE_HEADER)) { - LOGGING("!!warning file %s failed to write header at offset %lld\n", pSDSDecompress->FileName, fileOffset); + logger->debug("!!warning file {} failed to write header at offset {}", pSDSDecompress->FileName, fileOffset); } UpdateSectionData(pSectionData, currentSection++, currentOffset); @@ -6499,7 +6506,7 @@ class SDSDecompressManyFiles int64_t sizeWritten = DefaultFileIO.FileWriteChunk(NULL, outFileHandle, pBuffer, copySize, currentOffset); if (sizeRead != sizeWritten || sizeRead != copySize) { - printf("!!Failed to copy file %s at offset %lld and %lld\n", pSDSDecompress->FileName, currentOffset, localOffset); + logger->warn("!!Failed to copy file {} at offset {} and {}", pSDSDecompress->FileName, currentOffset, localOffset); } currentOffset += copySize; localOffset += copySize; @@ -6514,8 +6521,8 @@ class SDSDecompressManyFiles bytesXfer = DefaultFileIO.FileReadChunk(NULL, inFile, pDestArrayBlock, pFileHeader->ArrayBlockSize, origArrayBlockOffset); if (bytesXfer != pFileHeader->ArrayBlockSize) { - printf("!!warning file %s failed to read array block at offset %lld\n", pSDSDecompress->FileName, - origArrayBlockOffset); + logger->warn("!!warning file {} failed to read array block at offset {}", pSDSDecompress->FileName, + origArrayBlockOffset); } // fixup arrayblocks @@ -6546,22 +6553,22 @@ class SDSDecompressManyFiles int64_t bytesRead = DefaultFileIO.FileReadChunk(NULL, inFile, &tempFileHeader, sizeof(SDS_FILE_HEADER), sectionOffset); - LOGGING("concat: reading section at %lld for output fileoffset %lld\n", sectionOffset, fileOffset); + logger->debug("concat: reading section at {} for output fileoffset {}", sectionOffset, fileOffset); if (bytesRead != sizeof(SDS_FILE_HEADER)) { - printf( - "!!warning file %s failed to read section header at offset " - "%lld\n", + logger->warn( + "!!warning file {} failed to read section header at offset " + "{}", pSDSDecompress->FileName, sectionOffset); return 0; } origArrayBlockOffset = tempFileHeader.ArrayBlockOffset; - LOGGING("concat: Some offsets %lld %lld %lld sbo:%lld fo:%lld\n", tempFileHeader.NameBlockOffset, - tempFileHeader.MetaBlockOffset, tempFileHeader.ArrayBlockOffset, tempFileHeader.SectionBlockOffset, - tempFileHeader.FileOffset); + logger->debug("concat: Some offsets {} {} {} sbo:{} fo:{}", tempFileHeader.NameBlockOffset, + tempFileHeader.MetaBlockOffset, tempFileHeader.ArrayBlockOffset, tempFileHeader.SectionBlockOffset, + tempFileHeader.FileOffset); // Fixup header offsets if (tempFileHeader.NameBlockOffset) tempFileHeader.NameBlockOffset += fileOffset; @@ -6579,16 +6586,16 @@ class SDSDecompressManyFiles int64_t newOffset = fileOffset + sectionOffset; - LOGGING("concat: newoffset: %lld %lld + %lld\n", newOffset, fileOffset, sectionOffset); + logger->debug("concat: newoffset: {} {} + {}", newOffset, fileOffset, sectionOffset); UpdateSectionData(pSectionData, currentSection++, newOffset); int64_t sizeWritten = DefaultFileIO.FileWriteChunk(NULL, outFileHandle, &tempFileHeader, sizeof(SDS_FILE_HEADER), newOffset); - LOGGING("Wrote subsect fileheader %lld bytes at offset %lld\n", sizeof(SDS_FILE_HEADER), newOffset); + logger->debug("Wrote subsect fileheader {} bytes at offset {}", sizeof(SDS_FILE_HEADER), newOffset); if (sizeof(SDS_FILE_HEADER) != sizeWritten) { - printf("!!Failed to copy file %s at offset %lld and %lld\n", pSDSDecompress->FileName, newOffset, - sectionOffset); + logger->warn("!!Failed to copy file {} at offset {} and {}", pSDSDecompress->FileName, newOffset, + sectionOffset); } // NEW CODE @@ -6601,8 +6608,8 @@ class SDSDecompressManyFiles origArrayBlockOffset); if (bytesXfer != tempFileHeader.ArrayBlockSize) { - printf("!!warning file %s failed to read array block at offset %lld\n", pSDSDecompress->FileName, - origArrayBlockOffset); + logger->warn("!!warning file {} failed to read array block at offset {}", pSDSDecompress->FileName, + origArrayBlockOffset); } // fixup arrayblocks @@ -6615,8 +6622,8 @@ class SDSDecompressManyFiles // Write the array block with offsets fixed up DefaultFileIO.FileWriteChunk(NULL, outFileHandle, pDestArrayBlock2, tempFileHeader.ArrayBlockSize, fileOffset + origArrayBlockOffset); - LOGGING("Wrote arrayblock %lld bytes at offset %lld from orig: %lld\n", tempFileHeader.ArrayBlockSize, - fileOffset + origArrayBlockOffset, origArrayBlockOffset); + logger->debug("Wrote arrayblock {} bytes at offset {} from orig: {}", tempFileHeader.ArrayBlockSize, + fileOffset + origArrayBlockOffset, origArrayBlockOffset); WORKSPACE_FREE(pDestArrayBlock2); } @@ -6634,7 +6641,7 @@ class SDSDecompressManyFiles // void SDSConcatFiles(const char * strOutputFilename, int64_t validCount) { - LOGGING("concat mode! found %lld files\n", FileCount); + logger->debug("concat mode! found {} files", FileCount); if (validCount == 0) { @@ -6766,13 +6773,13 @@ class SDSDecompressManyFiles // Find first missing file SetErr_Format(SDS_VALUE_ERROR, "Not all files found : Expected %lld files. Missing %s\n", FileCount, pSDSDecompressFile[missingfile]->FileName); - printf("ReadManyFiles failed! FileCount %lld. valid %lld.\n", FileCount, validCount); + logger->error("ReadManyFiles failed! FileCount {}. valid {}.", FileCount, validCount); return NULL; } - LOGGING( - "GetInfo ReadManyFiles complete. FileCount %lld. valid %lld. " - "mode:%d \n", + logger->debug( + "GetInfo ReadManyFiles complete. FileCount {}. valid {}. " + "mode:{}", FileCount, validCount, multiMode); // Check if concat mode @@ -6855,7 +6862,7 @@ class SDSDecompressManyFiles { // invalid file path // zero out data - LOGGING("[%lld] Zeroing bad file\n", t); + logger->debug("[{}] Zeroing bad file", t); // memset(&pReadFinalCallback[t], 0, sizeof(SDS_READ_FINAL_CALLBACK)); pReadFinalCallback[t].pFileHeader = NULL; pReadFinalCallback[t].arraysWritten = 0; @@ -6944,7 +6951,7 @@ class SDSDecompressManyFiles } } - LOGGING("In scan for sections: %lld vs %lld\n", FileWithSectionsCount, FileWithSectionsCount); + logger->debug("In scan for sections: {} vs {}", FileWithSectionsCount, FileWithSectionsCount); // If we found sections then we have to re-expand if (FileWithSectionsCount > FileCount) { @@ -6992,14 +6999,14 @@ class SDSDecompressManyFiles } } - LOGGING("Found more sections. %lld vs %lld\n", FileCount, FileWithSectionsCount); + logger->debug("Found more sections. {} vs {}", FileCount, FileWithSectionsCount); // Swap in the expanded decompressfile with the sections pSDSDecompressFile = pSDSDecompressFileExtra; FileCount = FileWithSectionsCount; return pSDSDecompressFileExtra; } - LOGGING("Did not find more sections. %lld\n", FileCount); + logger->debug("Did not find more sections. {}", FileCount); return NULL; } @@ -7044,13 +7051,13 @@ class SDSDecompressManyFiles // Find first missing file SetErr_Format(SDS_VALUE_ERROR, "Not all files found : Expected %lld files. Missing %s\n", FileCount, pSDSDecompressFile[missingfile]->FileName); - printf("ReadAndStackFiles failed! FileCount %lld. valid %lld.\n", FileCount, validCount); + logger->error("ReadAndStackFiles failed! FileCount {}. valid {}.", FileCount, validCount); return NULL; } - LOGGING( - "GetInfo ReadAndStackFiles complete. FileCount %lld. valid %lld. " - "reserve space set to %lf\n", + logger->debug( + "GetInfo ReadAndStackFiles complete. FileCount {}. valid {}. " + "reserve space set to {}", FileCount, validCount, reserveSpace); // Allocate dataset row length for blank rows (gaps) @@ -7091,7 +7098,7 @@ class SDSDecompressManyFiles // In addition, the first column ArrayBlock will be master/king and dictate the result format. // All subsequent ArrayBlocks will need to be converted to that master block format. - LOGGING("[%d][%lld] %s", t, c, columnName); + logger->debug("[{}][{}] {}", t, c, columnName); SDS_ARRAY_BLOCK * pArrayBlock = &pSDSDecompress->pArrayBlocks[c]; int32_t arrayEnum = pSDSDecompress->pArrayEnums[c]; @@ -7119,7 +7126,7 @@ class SDSDecompressManyFiles { if (pDatasets[validPos].Length != dlength) { - printf( + logger->warn( "WARNING: datasets not same length %lld v. %lld " "for column %s\n", pDatasets[validPos].Length, dlength, columnName); @@ -7128,13 +7135,11 @@ class SDSDecompressManyFiles if (validPos > validCount) { - printf("!! internal error on validPos\n"); + logger->error("!! internal error on validPos"); } // Remember the length of this dataset pDatasets[validPos].Length = dlength; - LOGGING("Thomas band %lld %lld\n", pSDSDecompress->FileHeader.BandBlockCount, - pSDSDecompress->FileHeader.BandSize); } } } @@ -7146,9 +7151,9 @@ class SDSDecompressManyFiles } } - LOGGING( - "\nTotal column stats uniq:%d, first:%d, conv:%d, strfix:%d, " - "dim:%d, colgaps:%d, valid: %lld\n", + logger->debug( + "Total column stats uniq:{}, first:{}, conv:{}, strfix:{}, " + "dim:{}, colgaps:{}, valid: {}", TotalUniqueColumns, TotalFirstColumns, TotalConversions, TotalStringFixups, TotalDimensionProblems, TotalColumnGaps, validCount); @@ -7217,7 +7222,7 @@ class SDSDecompressManyFiles if (pReadCallbacks->Filter.pBoolMask) { // Worst case allocation (only valid files calculated) - LOGGING("~ALLOCATING for filtering\n"); + logger->debug("~ALLOCATING for filtering"); pFilterInfo = (SDSFilterInfo *)WORKSPACE_ALLOC(sizeof(SDSFilterInfo) * FileCount); pReadCallbacks->Filter.pFilterInfo = pFilterInfo; } @@ -7244,7 +7249,7 @@ class SDSDecompressManyFiles } } - LOGGING("Filter info: boolmasklength:%lld stackable: %d \n", boolMaskLength, fileTypeStackable); + logger->debug("Filter info: boolmasklength:{} stackable: {} ", boolMaskLength, fileTypeStackable); // Fill in all the IOPACKETs // Skip over invalid files, loop over all valid filenames @@ -7257,10 +7262,11 @@ class SDSDecompressManyFiles // array on has ORIGINAL_CONTAINER When saving a Struct, the categories // do not have STACKABLE set // int32_t mask = SDS_FLAGS_ORIGINAL_CONTAINER; - LOGGING( - "[%lld]Col: %s -- ColPos:%lld FileRow:%d pBlock:%p Enum:%d " - "ftype:%d\n", - col, pKing->ColName, pKing->ColPos, pKing->FileRow, pKing->ppArrayBlocks, pKing->ArrayEnum, fileTypeStackable); + logger->debug( + "[{}]Col: {} -- ColPos:{} FileRow:{} pBlock:{} Enum:{} " + "ftype:{}", + col, pKing->ColName, pKing->ColPos, pKing->FileRow, (void *)pKing->ppArrayBlocks, pKing->ArrayEnum, + fileTypeStackable); int64_t currentOffset = 0; int64_t currentUnfilteredOffset = 0; @@ -7314,7 +7320,7 @@ class SDSDecompressManyFiles if (! pArrayBlock || pOriginalLengths[row] == 0) { // NO IO PACKET (GAP) - LOGGING(">>> gap fill for row: %lld col: %lld name: %s\n", row, col, pKing->ColName); + logger->debug(">>> gap fill for row: {} col: {} name: {}", row, col, pKing->ColName); calcLength = pDatasets[row].Length; } else @@ -7368,9 +7374,9 @@ class SDSDecompressManyFiles currentUnfilteredOffset += calcLength; calcLength = filterTrueCount; - LOGGING( - "ROW %lld has true: %lld ufo: %lld for offset: %lld vs " - "%lld\n", + logger->debug( + "ROW {} has true: {} ufo: {} for offset: {} vs " + "{}", row, pFilterInfo[row].TrueCount, currentUnfilteredOffset, currentOffset, pFilterInfo[row].RowOffset); } @@ -7402,7 +7408,7 @@ class SDSDecompressManyFiles // Readjust TrueCount based on what we calculated pReadCallbacks->Filter.BoolMaskTrueCount = row == 0 ? 0 : pFilterInfo[row - 1].RowOffset + pFilterInfo[row - 1].TrueCount; - LOGGING("Final TrueCount %lld masterRow: %lld\n", pReadCallbacks->Filter.BoolMaskTrueCount, row); + logger->debug("Final TrueCount {} masterRow: {}", pReadCallbacks->Filter.BoolMaskTrueCount, row); hasFilter++; } @@ -7421,9 +7427,9 @@ class SDSDecompressManyFiles pOriginalArrayOffsets[row] = currentUnfilteredOffset; pKing->TotalRowLength = rowLengthToAlloc; - LOGGING( - "stack: %d totalplusreseve:%lld totalrowlength: %lld rows: " - "%lld\n", + logger->debug( + "stack: {} totalplusreseve:{} totalrowlength: {} rows: " + "{}", isFilterable, rowLengthToAlloc, currentOffset, row); // TODO: -- allocate one big array and fixup IO PACKETS @@ -7489,16 +7495,16 @@ class SDSDecompressManyFiles // FILTERING check... wasFiltered |= PossiblyShrinkArray(&sdsArrayCallback, pReadCallbacks, fileTypeStackable); - LOGGING( - "Allocating col: %s lengthplusr: %lld length: %lld itemsize: " - "%lld strides: %lld dims:%d dtype:%d wasFiltered:%d\n", + logger->debug( + "Allocating col: {} lengthplusr: {} length: {} itemsize: " + "{} strides: {} dims:{} dtype:{} wasFiltered:{}", sdsArrayCallback.pArrayName, rowLengthToAlloc, currentOffset, sdsArrayCallback.itemsize, strides[0], (int)sdsArrayCallback.ndim, sdsArrayCallback.numpyType, wasFiltered); // callback into python or matlab to allocate memory // this will fill in pData and pArrayObject pReadCallbacks->AllocateArrayCallback(&sdsArrayCallback); - LOGGING("Array allocated at %p for object %p\n", sdsArrayCallback.pDestInfo->pData, - sdsArrayCallback.pDestInfo->pArrayObject); + logger->debug("Array allocated at {} for object {}", (void *)sdsArrayCallback.pDestInfo->pData, + sdsArrayCallback.pDestInfo->pArrayObject); } // Fill in destination information @@ -7573,9 +7579,9 @@ class SDSDecompressManyFiles SDS_ARRAY_BLOCK * pMasterBlock = &pKing->KingBlock; // NO IO PACKET (GAP) - LOGGING( - ">>> gap fill %lld for row: %lld col: %lld " - "orig:%lld ds:%lld mdtype:%d\n", + logger->debug( + ">>> gap fill {} for row: {} col: {} " + "orig:{} ds:{} mdtype:{}", gapLength, row, col, pOriginalLengths[row], pDatasets[row].Length, pMasterBlock->DType); CopyFromBlockToInfo(pMasterBlock, pDestInfo); } @@ -7603,15 +7609,15 @@ class SDSDecompressManyFiles // This is the important one, this is where the IO will be copied // into pDestInfo->pData = sdsArrayCallback.pDestInfo->pData + (oneRowSize * pArrayOffsets[row]); - LOGGING( - "Fixing up pData for stackposition: %lld itemoffset:%lld " - "onerowsize:%lld mbitemsize:%d dest:%p\n", - row, pArrayOffsets[row], oneRowSize, pMasterBlock->ItemSize, pDestInfo->pData); + logger->debug( + "Fixing up pData for stackposition: {} itemoffset:{} " + "onerowsize:{} mbitemsize:{} dest:{}", + row, pArrayOffsets[row], oneRowSize, pMasterBlock->ItemSize, (void *)pDestInfo->pData); } if (validPos > totalIOPackets) { - printf("!!!internal error validPos vs totalIOPackets\n"); + logger->error("!!!internal error validPos vs totalIOPackets\n"); } validPos++; @@ -7634,7 +7640,7 @@ class SDSDecompressManyFiles pReadCallbacks->EndAllowThreads(saveState); } - LOGGING("Multistack done reading -- returning %d cols\n", TotalUniqueColumns); + logger->debug("Multistack done reading -- returning {} cols", TotalUniqueColumns); // ALLOCATE all the Final Callbacks SDS_STACK_CALLBACK * pMultiFinalCallback = @@ -7655,7 +7661,7 @@ class SDSDecompressManyFiles if (pSDSDecompress == NULL) { - printf("!!!internal error in final multistack loop\n"); + logger->error("!!!internal error in final multistack loop"); } else { @@ -7716,7 +7722,7 @@ class SDSDecompressManyFiles } // Reduce list to valids - LOGGING("ReadAndStackFiles complete %p\n", result); + logger->debug("ReadAndStackFiles complete {}", result); return result; } }; @@ -7880,7 +7886,7 @@ extern "C" for (int64_t i = 0; i < fileCount; i++) { - LOGGING("...%s\n", pMultiRead[i].pFileName); + logger->debug("MultiMode {}", pMultiRead[i].pFileName); pSDSDecompressFile[i] = new SDSDecompressFile( pMultiRead[i].pFileName, &includeList, i, NULL, &folderList, §ionsList, multiMode == SDS_MULTI_MODE_CONCAT_MANY ? SDS_MULTI_MODE_CONCAT_MANY : COMPRESSION_MODE_INFO); diff --git a/src/Sort.cpp b/src/Sort.cpp index bd776af..433027a 100644 --- a/src/Sort.cpp +++ b/src/Sort.cpp @@ -2244,11 +2244,8 @@ static bool ParMergeThreadCallback(struct stMATH_WORKER_ITEM * pstWorkerItem, in int64_t workBlock; // As long as there is work to do - while ((index = pstWorkerItem->GetNextWorkIndex(&workBlock)) > 0) + while ((index = pstWorkerItem->GetNextWorkIndex(&workBlock)) >= 0) { - // First index is 1 so we subtract - index--; - // PLOGGING("[%d] DoWork start loop -- %lld index: %lld\n", core, // workIndex, index); diff --git a/src/logging/log_common.h b/src/logging/log_common.h new file mode 100644 index 0000000..7038ebb --- /dev/null +++ b/src/logging/log_common.h @@ -0,0 +1,50 @@ +#pragma once + +#include +#include +#include + +namespace riptide::logging +{ + using namespace std::literals; + + enum class loglevel : int32_t + { + notset = 0, + debug = 10, + info = 20, + warn = 30, + error = 40, + critical = 50, + none = 60 + }; + + struct log_config + { + uint32_t batch_size = 50; + std::chrono::milliseconds flush_interval = 1000ms; + uint32_t max_size = 1'000'000; + }; + + struct log_record + { + std::string name; + std::string message; + loglevel level; + std::source_location loc; + std::chrono::time_point time; + }; + + struct log_format + { + std::string_view format; + std::source_location loc; + + template + log_format(FormatString format, const std::source_location & loc = std::source_location::current()) + : format{ format } + , loc{ loc } + { + } + }; +} \ No newline at end of file diff --git a/src/logging/logger.h b/src/logging/logger.h index 26522c9..8ba3083 100644 --- a/src/logging/logger.h +++ b/src/logging/logger.h @@ -1,184 +1,72 @@ -#include "timer.h" -#include "waiting_deque.h" +#pragma once -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include +#include "logging_service.h" -using namespace std::literals; +#include namespace riptide::logging { - enum class loglevel : int32_t - { - notset = 0, - debug = 10, - info = 20, - warn = 30, - error = 40, - crtical = 50, - none = 60 - }; - - struct log_config - { - uint32_t batch_size = 50; - std::chrono::milliseconds flush_interval = 1000ms; - uint32_t max_size = 1'000'000; - loglevel level = loglevel::warn; - }; - - struct log_record - { - std::string message; - loglevel level; - }; - class logger { public: - ~logger() + logger(const std::string_view name, const std::shared_ptr logger) + : name_{ name } + , logger_{ logger } { - disable(); } template - void log(loglevel level, const char * format, const Args &... args) + void log(const loglevel level, const log_format & format, Args &&... args) { - if (level < logLevel_) + if (not should_log(level)) return; - log_record record{ .message = std::vformat(format, std::make_format_args(args...)), .level = level }; - logs_.push_back(std::move(record)); - } - - std::optional receive() - { - if (! active()) - return std::nullopt; - - auto log = logs_.pop_front(); - if (! log) - return std::nullopt; - - return log; - } - - bool active() noexcept - { - return ! logs_.empty() or logLevel_ != loglevel::none; - } - - bool should_log(loglevel level) noexcept - { - return level >= logLevel_; + logger_->log(name_, level, format, std::forward(args)...); } - void set_level(loglevel level) noexcept - { - if (level == loglevel::notset) - level = loglevel::none; - logLevel_ = level; - } - - void wakeup() + template + void debug(const log_format & format, Args &&... args) { - logs_.cancel_wait(); + log(loglevel::debug, format, std::forward(args)...); } - void enable(const log_config config = log_config()) - { - if (logLevel_ != loglevel::none) - return; - - set_level(config.level); - interval_ = config.flush_interval; - batch_size_ = config.batch_size; - max_size_ = config.max_size; - - logs_.set_max_size(max_size_); - - flusher_.set_interval( - [this] - { - wakeup(); - }, - interval_); - } - - void disable(const std::optional timeout = std::nullopt) + template + void warn(const log_format & format, Args &&... args) { - logLevel_ = loglevel::none; - wakeup(); - - if (handler_.joinable()) - { - if (! timeout) - { - handler_.join(); - } - else - { - auto future = std::async(std::launch::async, &std::thread::join, &handler_); - if (future.wait_for(timeout.value()) == std::future_status::timeout) - { - // if couldn't join within timeout, force thread to drop all current logs and force join - logs_.clear(); - wakeup(); - } - } - } - - flusher_.cancel(); + log(loglevel::warn, format, std::forward(args)...); } - uint32_t batch_size() noexcept + template + void info(const log_format & format, Args &&... args) { - return batch_size_; + log(loglevel::info, format, std::forward(args)...); } - std::chrono::milliseconds interval() noexcept + template + void error(const log_format & format, Args &&... args) { - return interval_; + log(loglevel::error, format, std::forward(args)...); } - uint32_t max_size() noexcept + template + void critical(const log_format & format, Args &&... args) { - return max_size_; + log(loglevel::critical, format, std::forward(args)...); } - template - void set_handler(Handler handler) + [[nodiscard]] bool should_log(const loglevel level) noexcept { - handler_ = std::thread{ handler }; + return logger_->enabled() and level >= logLevel_; } - static inline logger & get() noexcept + void set_level(const loglevel level) noexcept { - static logger instance; - return instance; + logLevel_ = level; } private: - details::waiting_deque logs_; - details::timer flusher_; - - std::thread handler_; - - loglevel logLevel_ = loglevel::none; - uint32_t batch_size_; - std::chrono::milliseconds interval_; - uint32_t max_size_; + std::string name_; + std::shared_ptr logger_; + loglevel logLevel_ = loglevel::notset; }; } diff --git a/src/logging/logging.cpp b/src/logging/logging.cpp new file mode 100644 index 0000000..d1d508b --- /dev/null +++ b/src/logging/logging.cpp @@ -0,0 +1,21 @@ +#include "logging.h" + +#include + +namespace riptide::logging +{ + std::shared_ptr get_logger(const std::string & name) + { + return registry::get().get_logger(name); + } + + std::shared_ptr get_service() + { + return registry::get().service(); + } + + std::vector get_logger_names() + { + return registry::get().get_logger_names(); + } +} diff --git a/src/logging/logging.h b/src/logging/logging.h new file mode 100644 index 0000000..f964713 --- /dev/null +++ b/src/logging/logging.h @@ -0,0 +1,57 @@ +#pragma once + +#include "logger.h" +#include "../Defs.h" + +#include + +namespace riptide::logging +{ + class registry + { + public: + auto get_logger(const std::string & name) + { + if (not loggers_.contains(name)) + loggers_[name] = std::make_shared(name, service_); + return loggers_[name]; + } + + auto get_logger_names() + { + std::vector res(loggers_.size()); + std::transform(loggers_.begin(), loggers_.end(), res.begin(), + [](auto p) + { + return p.first; + }); + return res; + } + + auto service() + { + return service_; + } + + static registry & get() + { + static registry instance; + return instance; + } + + private: + registry() + : service_{ std::make_shared() } + { + } + + registry(const registry &) = delete; + + std::shared_ptr service_; + std::unordered_map> loggers_; + }; + + RT_DLLEXPORT std::shared_ptr get_logger(const std::string & name = {}); + RT_DLLEXPORT std::shared_ptr get_service(); + RT_DLLEXPORT std::vector get_logger_names(); +} \ No newline at end of file diff --git a/src/logging/logging_service.h b/src/logging/logging_service.h new file mode 100644 index 0000000..8128974 --- /dev/null +++ b/src/logging/logging_service.h @@ -0,0 +1,198 @@ + +#pragma once + +#include "timer.h" +#include "waiting_deque.h" +#include "log_common.h" + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +using namespace std::literals; +namespace riptide::logging +{ + namespace details + { + template + T && validate_arg(T && t) + { + return std::forward(t); + } + + template > + constexpr bool is_char_type_v = std::is_same_v || std::is_same_v || + std::is_same_v || std::is_same_v || std::is_same_v; + + template + requires is_char_type_v + T * validate_arg(T * const t) + { + if (not t) + { + static T result[]{ '(', 'n', 'u', 'l', 'l', ')', '\0' }; + return result; + } + return t; + } + } + + class logging_service + { + public: + ~logging_service() + { + disable(); + } + + template + void log(const std::string & name, loglevel level, const log_format & format, Args &&... args) + { + try + { + log_record record{ .name = name, + .message = std::vformat(format.format, std::make_format_args(details::validate_arg(args)...)), + .level = level, + .loc = format.loc, + .time = std::chrono::system_clock::now() }; + + logs_.push_back(std::move(record)); + } + catch (std::exception const & e) + { + log(name, loglevel::error, "Caught exception: {}\nwhen formatting: {}", e.what(), format.format); + } + } + + std::optional receive() + { + if (! active()) + return std::nullopt; + + auto log = logs_.pop_front(); + if (! log) + return std::nullopt; + + return log; + } + + bool active() noexcept + { + return ! logs_.empty() or ! shutdown_; + } + + bool enabled() noexcept + { + return not shutdown_; + } + + void wakeup() + { + logs_.cancel_wait(); + } + + void shutdown() + { + shutdown_ = true; + } + + void enable(const log_config config = log_config()) + { + if (not shutdown_) + return; + + shutdown_ = false; + interval_ = config.flush_interval; + batch_size_ = config.batch_size; + max_size_ = config.max_size; + + logs_.set_max_size(max_size_); + + flusher_.set_interval( + [this] + { + wakeup(); + }, + interval_); + } + + void disable(const std::optional timeout = std::nullopt) + { + if (shutdown_) + return; + + shutdown(); + wakeup(); + + if (handler_.joinable()) + { + if (! timeout) + { + handler_.join(); + } + else + { + auto future = std::async(std::launch::async, &std::thread::join, &handler_); + if (future.wait_for(timeout.value()) == std::future_status::timeout) + { + // if couldn't join within timeout, force thread to drop all current logs and force join + logs_.clear(); + wakeup(); + } + } + } + + flusher_.cancel(); + } + + uint32_t batch_size() noexcept + { + return batch_size_; + } + + std::chrono::milliseconds interval() noexcept + { + return interval_; + } + + uint32_t max_size() noexcept + { + return max_size_; + } + + template + void set_handler(Handler handler) + { + handler_ = std::thread{ handler }; + } + + static logging_service & get() noexcept + { + static logging_service instance; + return instance; + } + + private: + details::waiting_deque logs_; + details::timer flusher_; + + std::thread handler_; + + std::atomic shutdown_ = true; + + uint32_t batch_size_; + std::chrono::milliseconds interval_; + uint32_t max_size_; + }; +} \ No newline at end of file diff --git a/src/logging/timer.h b/src/logging/timer.h index eb1c67c..6e29ab6 100644 --- a/src/logging/timer.h +++ b/src/logging/timer.h @@ -1,3 +1,5 @@ +#pragma once + #include #include #include @@ -16,7 +18,7 @@ namespace riptide::logging::details } template - void set_interval(Function function, interval delay) + void set_interval(Function function, const interval delay) { if (active_) return; diff --git a/src/logging/waiting_deque.h b/src/logging/waiting_deque.h index 049a4b9..128f2cc 100644 --- a/src/logging/waiting_deque.h +++ b/src/logging/waiting_deque.h @@ -1,3 +1,5 @@ +#pragma once + #include #include @@ -59,7 +61,7 @@ namespace riptide::logging::details notify_.notify_one(); } - void set_max_size(uint32_t size) noexcept + void set_max_size(const uint32_t size) noexcept { max_size_ = size; } diff --git a/test/riptide_python_test/CMakeLists.txt b/test/riptide_python_test/CMakeLists.txt index 9ba7372..d1add1e 100644 --- a/test/riptide_python_test/CMakeLists.txt +++ b/test/riptide_python_test/CMakeLists.txt @@ -7,10 +7,12 @@ set(SOURCES bins_bsearch_tests.cpp bins_sorted_tests.cpp combine_accum_tests.cpp + datetime_tests.cpp ema_test.cpp groupby_tests.cpp hash_linear_tests.cpp lexsort_tests.cpp + logging_python_tests.cpp main.cpp mkalign_tests.cpp mbget_tests.cpp diff --git a/test/riptide_python_test/datetime_tests.cpp b/test/riptide_python_test/datetime_tests.cpp new file mode 100644 index 0000000..212731a --- /dev/null +++ b/test/riptide_python_test/datetime_tests.cpp @@ -0,0 +1,206 @@ +#include "CommonInc.h" +#include "riptide_python_test.h" +#include "ut_core.h" + +#include + +using namespace boost::ut; +using namespace riptide_python_test::internal; + +using riptide_utility::ut::file_suite; + +namespace +{ + PyObject * call_datetime_function(std::string function_name, std::string argument) + { + PyObject * const function = get_named_function(riptide_module_p, function_name.c_str()); + PyObject * const list = Py_BuildValue("[s]", argument.c_str()); + PyObject * const array = PyArray_FromAny(list, nullptr, 0, 0, 0, nullptr); + PyObject * const result = PyObject_CallFunction(function, "O", array); + Py_XDECREF(list); + Py_XDECREF(array); + return result; + } + + class capture_warnings + { + PyObject * mlogging; + pyobject_ptr handler; + pyobject_ptr logger; + pyobject_ptr queue; + + public: + capture_warnings() + { + mlogging = PyImport_ImportModule("logging"); + PyObject_CallMethod(mlogging, "captureWarnings", "O", Py_True); + + auto mhandlers{ get_named_function(mlogging, "handlers") }; + auto mqueue{ PyImport_ImportModule("queue") }; + + logger = pyobject_ptr{ PyObject_CallMethod(mlogging, "getLogger", "s", "py.warnings") }; + queue = pyobject_ptr{ PyObject_CallFunction(get_named_function(mqueue, "SimpleQueue"), nullptr) }; + handler = pyobject_ptr{ PyObject_CallFunction(get_named_function(mhandlers, "QueueHandler"), "O", queue.get()) }; + + PyObject_CallMethod(logger.get(), "addHandler", "O", handler.get()); + } + + ~capture_warnings() + { + PyObject_CallMethod(mlogging, "captureWarnings", "O", Py_False); + PyObject_CallMethod(logger.get(), "removeHandler", "O", handler.get()); + } + + std::vector get_warnings() + { + std::vector result; + + while (PyObject_CallMethod(queue.get(), "empty", nullptr) == Py_False) + { + pyobject_ptr log_record{ PyObject_CallMethod(queue.get(), "get", nullptr) }; + pyobject_ptr message{ PyObject_CallMethod(log_record.get(), "getMessage", nullptr) }; + result.emplace_back(PyUnicode_AsUTF8(message.get())); + } + + return result; + } + }; + + struct test_case + { + std::string argument; + int64_t expected; + std::string warning; + + test_case(std::string argument_, int64_t expected_, std::string warning_ = "") + : argument(argument_) + , expected(expected_) + , warning(warning_) + { + } + }; + + void check_datetime_result(pyobject_ptr && result, const test_case & tc) + { + expect(no_pyerr()); + expect(fatal(result != nullptr)); + expect(fatal(PyArray_Check(result.get()))); // TODO check result + + PyArrayObject * array = reinterpret_cast(result.get()); + expect(fatal(PyArray_TYPE(array) == NPY_INT64)); + expect(fatal(PyArray_SIZE(array) == 1)); + + int64_t nanoseconds = *reinterpret_cast(PyArray_DATA(array)); + expect(nanoseconds == tc.expected) << std::format("Expected result of \"{}\" to be {}, got {}", tc.argument, tc.expected, + nanoseconds); + } + + auto expect_function_call_ok(std::string function_name) + { + return [=](const test_case & tc) + { + capture_warnings cw; + + pyobject_ptr result{ call_datetime_function(function_name, tc.argument) }; + check_datetime_result(std::move(result), tc); + + auto warnings = cw.get_warnings(); + expect(warnings.empty()) << std::format("Expected 0 warnings, got {}", warnings.size()); + }; + } + + auto expect_function_call_warn(std::string function_name) + { + return [=](const test_case & tc) + { + capture_warnings cw; + + pyobject_ptr result{ call_datetime_function(function_name, tc.argument) }; + check_datetime_result(std::move(result), tc); + + auto warnings = cw.get_warnings(); + expect(fatal(warnings.size() == 1)) << std::format("Expected 1 warning, got {}", warnings.size()); + expect(warnings[0].find(tc.warning) != std::string::npos) + << std::format("Expected warning to contain \"{}\", warning was \"{}\"", tc.warning, warnings[0]); + }; + } + + file_suite datetime_functions = [] + { + "date_string_parsing_ok"_test = expect_function_call_ok("DateStringToNanos") | std::vector{ + test_case("", 0), + test_case(" ", 0), + test_case(" ", 0), + test_case("20240506", 1714953600000000000), + test_case("2024-05-06", 1714953600000000000), + test_case(" 20240506", 1714953600000000000), + test_case("20240506 ", 1714953600000000000), + test_case(" 20240506 ", 1714953600000000000), + test_case("1969-01-01", 0), + test_case("2134-01-01", 0), + test_case("1979-13-01", 0), + test_case("1969-01-42", 0), + }; + + "date_string_parsing_warn"_test = expect_function_call_warn("DateStringToNanos") | std::vector{ + test_case("2024-0506", 1714953600000000000, "Expected delimiter"), + test_case("202405-06", 1714953600000000000, "Unexpected delimiter"), + test_case("2024:05:06", 1714953600000000000, "Unexpected delimiter"), + test_case("huh 20240506", 1714953600000000000, "Unexpected characters"), + test_case("2024huh05hmm06", 1714953600000000000, "Unexpected delimiter"), + test_case("20240506 junk", 1714953600000000000, "Unexpected characters"), + }; + + "time_string_parsing_ok"_test = expect_function_call_ok("TimeStringToNanos") | std::vector{ + test_case("", 0), + test_case(" ", 0), + test_case(" ", 0), + test_case("12", 0), + test_case(" 12:08", 43680000000000), + test_case("12:08:34 ", 43714000000000), + test_case(" 12:08:34.123 ", 43714123000000), + test_case("12:08:34.123456789", 43714123456789), + test_case("56:12:12.123", 0), + test_case("12:93:12.123", 0), + test_case("12:12:93.123", 0), + }; + + "time_string_parsing_warn"_test = expect_function_call_warn("TimeStringToNanos") | std::vector{ + test_case("12-08", 43680000000000, "Unexpected delimiter"), + test_case("12h08m", 43680000000000, "Unexpected delimiter"), + test_case("1s", 3600000000000, "Unexpected delimiter"), + test_case("2m", 7200000000000, "Unexpected delimiter"), + test_case("2H", 7200000000000, "Unexpected delimiter"), + test_case("12.08*34.123", 43714123000000, "Unexpected delimiter"), + test_case("2 any other string!", 7200000000000, "Unexpected delimiter"), + test_case("56:12:12.123 random junk", 0, "Unexpected characters"), + test_case("12:93:12.123 random junk", 0, "Unexpected characters"), + test_case("12:12:93.123 random junk", 0, "Unexpected characters"), + }; + + "datetime_string_parsing_ok"_test = expect_function_call_ok("DateTimeStringToNanos") | std::vector{ + test_case("", 0), + test_case(" ", 0), + test_case(" ", 0), + test_case("20240506 12:08", 1714997280000000000), + test_case("20240506 12:08:34 ", 1714997314000000000), + test_case(" 20240506T12:08:34.123", 1714997314123000000), + test_case(" 20240506 12:08:34.123456789 ", 1714997314123456789), + test_case("1969-01-01T12:12:12.123", 0), + test_case("1979-13-01T12:12:12.123", 0), + test_case("1979-01-42T12:12:12.123", 0), + test_case("1979-01-01T56:12:12.123", 283996800000000000), + test_case("1979-01-01T12:93:12.123", 283996800000000000), + test_case("1979-01-01T12:12:93.123", 283996800000000000), + }; + + "datetime_string_parsing_warn"_test = expect_function_call_warn("DateTimeStringToNanos") | std::vector{ + test_case("2024y05m06d12h08m34s123ms", 1714997314000000000, "Unexpected delimiter"), + test_case("2024y05m06d12h08m34.123ms", 1714997314123000000, "Unexpected delimiter"), + test_case("the date is 2024-05-06", 1714953600000000000, "Unexpected characters"), + test_case("2024-05-06 random junk", 1714953600000000000, "Unexpected characters"), + test_case("1979-13-01T12:12:12.123 random junk", 0, "Unexpected characters"), + test_case("1979-01-01T12:93:12.123 random junk", 283996800000000000, "Unexpected characters"), + }; + }; +} \ No newline at end of file diff --git a/test/riptide_python_test/logging_python_tests.cpp b/test/riptide_python_test/logging_python_tests.cpp new file mode 100644 index 0000000..40fe5f7 --- /dev/null +++ b/test/riptide_python_test/logging_python_tests.cpp @@ -0,0 +1,142 @@ + +#include "riptide_python_test.h" +#include "logging/logging.h" +#include "tuple_util.h" +#include "Logger.h" + +#include "ut_core.h" + +#include +#include +#include +#include + +using namespace boost::ut; +using riptide_utility::ut::file_suite; +using namespace riptide_utility::internal; +using namespace riptide_python_test::internal; +using riptide_python_test::internal::get_named_function; + +using loglevel = riptide::logging::loglevel; +using logger = riptide::logging::logger; + +namespace +{ + auto generate_log(const std::vector> & loggers, size_t nthreads, size_t nlogs) + { + std::vector threads; + + auto gen = [&](const std::vector> & loggers, size_t thread_id, size_t nlogs) + { + auto log_count{ nlogs / loggers.size() }; + for (auto & logg : loggers) + { + for (size_t i = 0; i < log_count; i++) + logg->debug("[{}] {}", thread_id, i); + } + }; + + for (size_t th = 0; th < nthreads; th++) + threads.emplace_back(gen, loggers, th, nlogs); + + for (auto & th : threads) + th.join(); + } + + template + using int_type = std::integral_constant; + + using SupportedThreadSize = std::tuple, int_type<16>>; + using SupportedLogSize = std::tuple>; + using SupportedBatchSize = std::tuple, int_type<50>, int_type<500>>; + + using SupportedArgs = decltype(tuple_prod(tuple_prod(SupportedThreadSize{}, SupportedLogSize{}), SupportedBatchSize{})); + + struct logging_handler_tester + { + static void exec(size_t nloggers, size_t nthreads, size_t nlogs, size_t batch_size) + { + auto mlogging{ PyImport_ImportModule("logging") }; + auto mhandlers{ get_named_function(mlogging, "handlers") }; + auto mqueue{ PyImport_ImportModule("queue") }; + auto enable_logging{ get_named_function(riptide_module_p, "EnableLogging") }; + auto disable_logging{ get_named_function(riptide_module_p, "DisableLogging") }; + + pyobject_ptr queue{ PyObject_CallFunction(get_named_function(mqueue, "Queue"), nullptr) }; + expect(queue != nullptr); + + pyobject_ptr queue_handler{ PyObject_CallFunction(get_named_function(mhandlers, "QueueHandler"), "O", queue.get()) }; + expect(queue_handler != nullptr); + + std::vector py_loggers; + std::vector> loggers; + + for (size_t i = 0; i < nloggers; i++) + { + auto name{ std::to_string(i) }; + loggers.push_back(riptide::logging::get_logger(name)); + + auto py_logger{ PyObject_CallMethod(mlogging, "getLogger", "s", + std::format("riptable.riptide_cpp.{}", name).c_str()) }; + expect(py_logger != nullptr); + + py_loggers.push_back(py_logger); + PyObject_CallMethod(py_logger, "setLevel", "i", static_cast(loglevel::debug)); + + auto add_result{ PyObject_CallMethod(py_logger, "addHandler", "O", queue_handler.get()) }; + expect(add_result != nullptr); + } + + SetupLogging(); + // EnableLogging(interval, batch_size, max_size, call_back) + auto enable_res{ PyObject_CallFunction(enable_logging, "iiiO", 1000, (int32_t)batch_size, 100'000, Py_None) }; + expect(enable_res != nullptr); + + generate_log(loggers, nthreads, nlogs); + + // DisableLogging(timeout), -1 = no timeout + auto disable_res{ PyObject_CallFunction(disable_logging, "i", -1) }; + expect(disable_res != nullptr); + + auto received{ PyLong_AsLong(PyRun_String("len(handler.queue.queue)", Py_eval_input, + Py_BuildValue("{sO}", "handler", queue_handler.get()), + Py_BuildValue("{}"))) }; + + expect(received == static_cast(nthreads * nlogs)) + << "received=" << received << ", expected=" << (nthreads * nlogs); + + for (auto & py_logger : py_loggers) + { + auto remove_res{ PyObject_CallMethod(py_logger, "removeHandler", "O", queue_handler.get()) }; + expect(remove_res != nullptr); + } + } + }; + + template + struct logging_handler_test + { + template + void operator()() + { + using ThreadLogPair = std::tuple_element_t<0, T>; + using ThreadSizeType = std::tuple_element_t<0, ThreadLogPair>; + using LogSizeType = std::tuple_element_t<1, ThreadLogPair>; + + using BatchSizeType = std::tuple_element_t<1, T>; + + constexpr auto Threads = ThreadSizeType::value; + constexpr auto Logs = LogSizeType::value; + constexpr auto BatchSize = BatchSizeType::value; + + static_assert(Logs % NumLoggers == 0, "The number of logs must be divisible by number of subloggers for testing."); + logging_handler_tester::exec(NumLoggers, Threads, Logs, BatchSize); + } + }; + + file_suite riptide_ops = [] + { + "logging_handler_test_single"_test = logging_handler_test<1>{} | SupportedArgs{}; + "logging_handler_test_multiple"_test = logging_handler_test<5>{} | SupportedArgs{}; + }; +} \ No newline at end of file diff --git a/test/riptide_test/logging_test.cpp b/test/riptide_test/logging_test.cpp index c221aa7..f04d147 100644 --- a/test/riptide_test/logging_test.cpp +++ b/test/riptide_test/logging_test.cpp @@ -1,6 +1,7 @@ #include "ut_core.h" -#include "logging/logger.h" #include "tuple_util.h" +#include "logging/logging.h" +#include "ut_extensions.h" #include #include @@ -16,13 +17,18 @@ using namespace riptide_utility::internal; namespace { - auto & logg = riptide::logging::logger::get(); + struct throw_exception + { + }; + + auto service = get_service(); + auto logger = get_logger(); void produce(size_t log_count, int id) { for (size_t i = 0; i < log_count; i++) { - logg.log(loglevel::debug, "{0} {1}", id, i); + logger->log(loglevel::debug, "{0} {1}", id, i); } } @@ -38,9 +44,9 @@ namespace void consume(std::vector & result) { - while (logg.active()) + while (service->active()) { - auto curr{ logg.receive() }; + auto curr{ service->receive() }; if (! curr) continue; @@ -70,7 +76,8 @@ namespace std::vector result; - logg.enable({ .max_size = 1'000'000'000, .level = loglevel::debug }); + logger->set_level(loglevel::debug); + service->enable({ .max_size = 1'000'000'000 }); auto prods{ producer(Threads, Logs) }; std::thread cons{ consume, std::ref(result) }; @@ -78,10 +85,10 @@ namespace for (auto & t : prods) t.join(); - logg.set_level(loglevel::none); + service->shutdown(); cons.join(); - logg.disable(); + service->disable(); std::unordered_map log_count; while (! result.empty()) @@ -111,9 +118,68 @@ namespace } }; + static_assert(! std::is_const_v()))>>); + static_assert(std::is_const_v()))>>); + + struct nullptr_format_validation_tester + { + template + void operator()() + { + using T = std::remove_pointer_t; + + char const * const expected{ "(null)" }; + auto const actual{ details::validate_arg(static_cast(nullptr)) }; + typed_expect(actual != nullptr) << fatal; + for (int i{ 0 }; i < 5; ++i) + { + typed_expect(actual[i] != 0) << fatal; + typed_expect(actual[i] == static_cast(expected[i])); + } + typed_expect(! actual[6]); + } + }; + + struct format_exception_tester + { + void operator()() + { + logger->set_level(loglevel::debug); + service->enable(); + auto format{ "Throws exception: {}" }; + expect(nothrow( + [&]() + { + logger->debug(format, throw_exception{}); + })); + + auto record{ service->receive() }; + expect(record.has_value()); + expect(record.value().message == std::format("Caught exception: {}\nwhen formatting: {}", "Formatting error", format)); + + service->disable(); + } + }; + file_suite riptide_ops = [] { // TODO: move this to riptide_python_test "test_logging_normal"_test = logging_tester{} | SupportedArgs{}; + + "test_format_validation"_test = nullptr_format_validation_tester{} | + std::tuple{}; + + "test_format_exception"_test = format_exception_tester{}; }; } + +template <> +struct std::formatter : std::formatter +{ + auto format(throw_exception const & exp, std::format_context & ctx) const + { + throw std::runtime_error("Formatting error"); + return std::format_to(ctx.out(), ""); + } +}; \ No newline at end of file diff --git a/test/riptide_test/math_worker_tests.cpp b/test/riptide_test/math_worker_tests.cpp index 713705a..5990138 100644 --- a/test/riptide_test/math_worker_tests.cpp +++ b/test/riptide_test/math_worker_tests.cpp @@ -2,9 +2,11 @@ #include "ut_core.h" -#include +#include #include +#include #include +#include using namespace boost::ut; using riptide_utility::ut::file_suite; @@ -119,6 +121,71 @@ namespace } } + struct GetNextWorkIndexTestState + { + std::mutex mutex; + std::condition_variable wakeup; + std::unordered_set cores; + }; + + static bool GetNextWorkIndexTestCallback(void * callbackArg, int32_t core, int64_t workIndex) + { + auto * state = static_cast(callbackArg); + std::unique_lock lock(state->mutex); + state->cores.insert(core); + + if (state->cores.size() == 1) + { + // This is the first thread, wait for the other + state->wakeup.wait(lock); + } + else + { + // This is the second thread, wake up the first + state->wakeup.notify_all(); + } + + lock.unlock(); + return true; + } + + struct ThreadWakeUpTestState + { + std::mutex mutex; + std::condition_variable condition; + int64_t count; + int64_t expected; + }; + + static bool ThreadWakeUpTestCallback(struct stMATH_WORKER_ITEM * worker_item, int core, int64_t work_index) + { + auto * state = static_cast(worker_item->WorkCallbackArg); + std::unique_lock lock(state->mutex); + + int64_t work_block; + worker_item->GetNextWorkBlock(&work_block); + + if (++state->count < state->expected) + { + state->condition.notify_all(); + } + else + { + auto pred = [&] + { + return state->count == state->expected; + }; + + // Wait for up to 10s + state->condition.wait_for(lock, std::chrono::seconds(10), pred); + } + + worker_item->CompleteWorkBlock(); + + lock.unlock(); + return false; + } + file_suite math_worker_ops = [] { "work_main_joins_workers"_test = [&] @@ -154,5 +221,70 @@ namespace lock.unlock(); }; + + "get_next_work_index"_test = [&] + { + expect(fatal(g_cMathWorker != nullptr)); + once_start_math_workers(); + + int64_t const numItems{ 2 }; // Two work items + int32_t const threadWakeup{ 1 }; // One worker thread (plus main thread) + GetNextWorkIndexTestState state; + + // This function uses GetNextWorkIndex internally to dispatch work + g_cMathWorker->DoMultiThreadedWork(numItems, GetNextWorkIndexTestCallback, (void *)&state, threadWakeup); + + // Two threads should have done work + expect(state.cores.size() == 2) << "state.cores=" << state.cores; + + // The main thread should be one of them + expect(state.cores.contains(0)) << "state.cores=" << state.cores; + }; + + "thread_wakeup"_test = [&](int32_t thread_wakeup) + { + switch (thread_wakeup) + { + case 1: + thread_wakeup = 1; + break; + case 2: + thread_wakeup = g_cMathWorker->WorkerThreadCount / 2; + break; + case 3: + thread_wakeup = g_cMathWorker->WorkerThreadCount; + break; + } + + expect(fatal(g_cMathWorker != nullptr)); + once_start_math_workers(); + + auto * work_item{ g_cMathWorker->GetWorkItem(CMathWorker::WORK_ITEM_BIG) }; + work_item->DoWorkCallback = ThreadWakeUpTestCallback; + + ThreadWakeUpTestState state; + state.count = 0; + state.expected = thread_wakeup; + work_item->WorkCallbackArg = &state; + + work_item->BlocksCompleted = 0; + work_item->BlockNext = 0; + work_item->BlockSize = 1; + work_item->BlockLast = thread_wakeup; + + // Wake up threads + g_cMathWorker->pWorkerRing->SetWorkItem(thread_wakeup); + + // Wait for all work items to be complete and all thread to go back to sleep + while (work_item->BlocksCompleted < work_item->BlockLast || g_cMathWorker->pWorkerRing->AnyThreadsAwakened()) + { + YieldProcessor(); + } + + // Check that the correct number of threads woke up + expect(state.count == state.expected) << "expected" << state.expected << "thread(s) to wake up, got" << state.count; + + g_cMathWorker->pWorkerRing->CompleteWorkItem(); + } | std::vector{ 1, 2, 3 }; }; } diff --git a/test/sdsfile_test/CMakeLists.txt b/test/sdsfile_test/CMakeLists.txt index 22e8e20..3f13280 100644 --- a/test/sdsfile_test/CMakeLists.txt +++ b/test/sdsfile_test/CMakeLists.txt @@ -21,4 +21,5 @@ target_link_libraries(${TARGET_NAME} proj_copy_runtime_deps(TARGET ${TARGET_NAME}) gtest_discover_tests(${TARGET_NAME} - COMMAND ${TARGET_NAME}) + COMMAND ${TARGET_NAME} + DISCOVERY_TIMEOUT 10) diff --git a/test/sdsfile_test/main_tests.cpp b/test/sdsfile_test/main_tests.cpp index dc11aab..83032b5 100644 --- a/test/sdsfile_test/main_tests.cpp +++ b/test/sdsfile_test/main_tests.cpp @@ -1,4 +1,6 @@ #include "ut_core.h" + +#include #include using namespace boost::ut; @@ -25,6 +27,19 @@ namespace { bool dummy{ 0 }; + struct tmppath + { + tmppath(std::filesystem::path const & fname) + : path_{ std::filesystem::temp_directory_path() / fname } + { + } + ~tmppath() + { + std::filesystem::remove(path_); + } + std::filesystem::path path_; + }; + file_suite stsfile_tests = [] { "test_main"_test = [&] @@ -38,5 +53,11 @@ namespace AppendSDSFile("OutFileName", "ShareFileName", "ShareName", /*TotalRows*/ 1, /*BandSize*/ 2); } }; + + "create_empty_sds_file"_test = [&] + { + tmppath const sdspath{ "test.sds" }; + CreateSDSFile(sdspath.path_.generic_string().c_str(), nullptr, nullptr, "A:I4", 1, 0); + }; }; }