From b8523189572883dbbbdd0da64024ff06e38d277a Mon Sep 17 00:00:00 2001 From: fenugrec Date: Sat, 9 Dec 2017 11:55:17 -0500 Subject: [PATCH 1/5] Output sinks : new (untested) sync file out Synchronous (blocking) file output sink for Windows / *nix. WIP, only compile-tested --- CMakeLists.txt | 1 + zf_log/CMakeLists.txt | 10 ++- zf_log/output_file_sync.c | 140 ++++++++++++++++++++++++++++++++++++++ zf_log/zf_log_sinks.h | 29 ++++++++ 4 files changed, 179 insertions(+), 1 deletion(-) create mode 100644 zf_log/output_file_sync.c create mode 100644 zf_log/zf_log_sinks.h diff --git a/CMakeLists.txt b/CMakeLists.txt index 62a1bfa..5ba8000 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -22,6 +22,7 @@ option(ZF_LOG_PERF_TESTS "Build performance tests (requires Python)" OFF) option(ZF_LOG_USE_ANDROID_LOG "Use Android log by defaul when available" OFF) option(ZF_LOG_USE_NSLOG "Use NSLog (Apple System Log) by default when available" OFF) option(ZF_LOG_USE_DEBUGSTRING "Use OutputDebugString (Windows) by default when available" OFF) +option(ZF_LOG_USE_OUTFILE_SYNC "Enable synchronous file output sink" OFF) option(ZF_LOG_OPTIMIZE_SIZE "Optimize for size (prefer size over speed)" OFF) add_subdirectory(zf_log) diff --git a/zf_log/CMakeLists.txt b/zf_log/CMakeLists.txt index 5d6fc2f..768a655 100644 --- a/zf_log/CMakeLists.txt +++ b/zf_log/CMakeLists.txt @@ -2,7 +2,7 @@ cmake_minimum_required(VERSION 3.2) # zf_log target (required) set(HEADERS_DIR ${CMAKE_CURRENT_SOURCE_DIR}) -set(HEADERS zf_log.h) +set(HEADERS zf_log.h zf_log_sinks.h) set(SOURCES zf_log.c) set(CMAKE_C_STANDARD 99) @@ -14,6 +14,11 @@ else() set(CMAKE_C_FLAGS "${CMAKE_C_FLAGS} -Wall -Wextra -Werror -pedantic-errors") endif() +# add optional sources +if(ZF_LOG_USE_OUTFILE_SYNC) + set(SOURCES "${SOURCES}" output_file_sync.c) +endif() + add_library(zf_log ${HEADERS} ${SOURCES}) target_include_directories(zf_log PUBLIC $) if(ZF_LOG_LIBRARY_PREFIX) @@ -30,6 +35,9 @@ endif() if(ZF_LOG_USE_DEBUGSTRING) target_compile_definitions(zf_log PRIVATE "ZF_LOG_USE_DEBUGSTRING") endif() +if(ZF_LOG_USE_OUTFILE_SYNC) + target_compile_definitions(zf_log PRIVATE "ZF_LOG_USE_OUTFILE_SYNC") +endif() if(ZF_LOG_OPTIMIZE_SIZE) target_compile_definitions(zf_log PRIVATE "ZF_LOG_OPTIMIZE_SIZE") endif() diff --git a/zf_log/output_file_sync.c b/zf_log/output_file_sync.c new file mode 100644 index 0000000..a43fc03 --- /dev/null +++ b/zf_log/output_file_sync.c @@ -0,0 +1,140 @@ +/* synchronous file output sink + * + * (c) fenugrec 2017 + * + * This is designed for single-process, multi-thread logging. + * Multiple processes won't work due to the type of mutex used. + * + * OS implementations: + * - Windows (winXP and up) + * - POSIX (unix / linux / etc) + * + * Log file is created if inexistant, otherwise appended to. + * Currently works with a single, global output file, just + * as zf_log has only one single global logging stream. + */ + + +#if defined(_WIN32) + /* covers win32 / win64 targets */ + #include + +#elif defined(__unix__) + /* covers lots of stuff including linux, but not macs? */ + #include + #include + #include + #include + #include + #include +#else + #error No sync file output implementation for your OS ! +#endif + +#include "zf_log.h" + +/* private stuff, per-output file */ +struct sf_out { +#if defined(_WIN32) + HANDLE hfil; + CRITICAL_SECTION mtx; //lightweight mutex +#elif defined(__unix__) + int filedes; + pthread_mutex_t mtx; +#endif +}; + +static struct sf_out global_sf; + +static void sf_out_cb(const zf_log_message *msg, void *arg) +{ + struct sf_out *sf = arg; + + *msg->p = '\n'; + +#if defined(_WIN32) + DWORD towrite, writ; + + towrite = msg->p - msg->buf + 1; + EnterCriticalSection(&sf->mtx); + if (!WriteFile(sf->hfil, msg->buf, towrite, &writ, NULL)) { + /* write error : silently ignore, where else would we report this ? */ + LeaveCriticalSection(&sf->mtx); + return; + } + LeaveCriticalSection(&sf->mtx); +#elif defined(__unix__) + ssize_t towrite, writ = 0; + ssize_t errval; + + towrite = msg->p - msg->buf + 1; + + pthread_mutex_lock(&sf->mtx); + do { + errval = write(sf->filedes, &msg->buf[writ], towrite - writ); + /* catch non-fatal interrupted writes due to signal */ + if ((errval == -1) && (errno == EINTR)) { + /* nothing written */ + continue; + } + if (errval >= 0) { + writ += errval; + continue; + } + /* unrecoverable error */ + break; + } while (writ != towrite); + + pthread_mutex_unlock(&sf->mtx); +#endif + return; +} + +/* Assume that caller has finished generating log outputs + * when calling this + */ +void sf_out_close(void) { + struct sf_out *sf = &global_sf; + +#ifdef _WIN32 + DeleteCriticalSection(&sf->mtx); + CloseHandle(sf->hfil); +#elif defined(__unix__) + int errval; + pthread_mutex_destroy(&sf->mtx); + do { + errval = close(sf->filedes); + } while (errval == EINTR); + +#endif // if + return; + +} + +int sf_out_open(const char *const fname) { + struct sf_out *sf = &global_sf; + +#ifdef _WIN32 + sf->hfil = CreateFile(fname, GENERIC_WRITE, 0, NULL, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL); + if (sf->hfil == INVALID_HANDLE_VALUE) { + ZF_LOGW("Failed to create/open log file %s", fname); + return -1; + } + InitializeCriticalSection(&sf->mtx); +#elif defined(__unix__) + if (pthread_mutex_init(&sf->mtx, NULL)) { + ZF_LOGW("pthread_mutex_init failed"); + return -1; + } + + sf->filedes = open(fname, O_WRONLY | O_CREAT | O_APPEND); + if (sf->filedes == -1) { + ZF_LOGW("Failed to create/open log file %s", fname); + pthread_mutex_destroy(&sf->mtx); + return -1; + } +#endif // if + + zf_log_set_output_v(ZF_LOG_PUT_STD, sf, sf_out_cb); + return 0; +} diff --git a/zf_log/zf_log_sinks.h b/zf_log/zf_log_sinks.h new file mode 100644 index 0000000..ecb14b6 --- /dev/null +++ b/zf_log/zf_log_sinks.h @@ -0,0 +1,29 @@ +#ifndef ZF_LOG_SINKS_H +#define ZF_LOG_SINKS_H + +/* Collection of additional output sinks. + * All are optional and selectable at compile-time. + */ + +#ifdef __cplusplus +extern "C" { +#endif + + +/*********** + * Synchronous (blocking) file output sink. + * Caller must ensure no more logging calls will be made + * by any of its threads before calling sf_out_close(). + */ + +/** Ret 0 if ok */ +int sf_out_open(const char *const fname); + +void sf_out_close(void); + + +#ifdef __cplusplus +} +#endif + +#endif // ZF_LOG_SINKS_H From 8b9fa7ad836980b7158691f38e28c1305d46501c Mon Sep 17 00:00:00 2001 From: fenugrec Date: Tue, 9 Jan 2018 00:40:41 -0500 Subject: [PATCH 2/5] Examples : added multithreaded file output Creates multiple threads that send messages to the synchronous file output sink. --- examples/CMakeLists.txt | 6 ++ examples/multithread_output.c | 147 ++++++++++++++++++++++++++++++++++ 2 files changed, 153 insertions(+) create mode 100644 examples/multithread_output.c diff --git a/examples/CMakeLists.txt b/examples/CMakeLists.txt index 6a39f8d..aa76817 100644 --- a/examples/CMakeLists.txt +++ b/examples/CMakeLists.txt @@ -24,3 +24,9 @@ target_link_libraries(file_output zf_log) add_executable(args_eval args_eval.c) target_link_libraries(args_eval zf_log) + +if(ZF_LOG_USE_OUTFILE_SYNC) + add_executable(multithread_output multithread_output.c) + target_link_libraries(multithread_output zf_log pthread) + set_property(TARGET multithread_output PROPERTY C_EXTENSIONS ON) +endif() diff --git a/examples/multithread_output.c b/examples/multithread_output.c new file mode 100644 index 0000000..af97dbf --- /dev/null +++ b/examples/multithread_output.c @@ -0,0 +1,147 @@ +/* + * fenugrec 2018 + * Test for multiple threads generating logging messages. + * Speed, # of threads, and # of messages can be adjusted. + * + * This uses the synchronous file output sink, with either + * the first arg as output file, or a hardcoded file name + * + */ + +#define MT_MCOUNT 2000UL // # of log messages per thread +#define MT_THREADS 4 //concurrent threads +#define MT_DELAY 0 //delay between each log message call +#define DEFAULT_LOGFILE "mt.log" + +#include +#include + +#if defined(_WIN32) + /* covers win32 / win64 targets */ + #include + +#elif defined(__unix__) + #define _XOPEN_SOURCE 700 + + /* covers most other OSes */ + + #include + #include + #include + #include +#else + #error weird OS +#endif + + +#include "zf_log.h" +#include "zf_log_sinks.h" + +struct tdata { + unsigned thread_no; + const char *msg_header; +}; + +#if defined(_WIN32) +HANDLE ttable[MT_MCOUNT]; + +DWORD WINAPI logger_func(LPVOID priv) { + struct tdata *td = priv; + unsigned mcnt; + + for (mcnt = 0; mcnt < MT_MCOUNT; mcnt++) { + ZF_LOGI(td->msg_header, td->thread_no, mcnt); + if (MT_DELAY) { + Sleep(MT_DELAY); + } + } + return 0; +} + +#elif defined(__unix__) +pthread_t ttable[MT_THREADS]; + +static void *logger_func(void *priv) { + struct tdata *td = priv; + unsigned mcnt; + + for (mcnt = 0; mcnt < MT_MCOUNT; mcnt++) { + ZF_LOGI(td->msg_header, td->thread_no, mcnt); + if (MT_DELAY) { + + struct timespec rqst, resp; + int rv; + + rqst.tv_sec = MT_DELAY / 1000; + rqst.tv_nsec = (MT_DELAY % 1000) * 1000*1000; + + errno = 0; + //clock_nanosleep is interruptible, hence this loop + while ((rv=nanosleep(&rqst, &resp)) != 0) { + if (rv == EINTR) { + rqst = resp; + errno = 0; + } else { + //unlikely + break; + } + } + } //MT_DELAY + } //for + return NULL; +} +#endif + + +static void start_test(void) { + unsigned n; + struct tdata td[MT_THREADS]; + const char header_base[] = "\t\t\t\t%02u mcnt=%u"; + + for (n=0; n < MT_THREADS; n++) { + td[n].msg_header = &header_base[(n & 0x03)]; //just an offset to help visualizing + td[n].thread_no = n; + printf("starting thread %u/%u\n", n, MT_THREADS); +#if defined(_WIN32) + ttable[n] = CreateThread(NULL, 0, logger_func, &td[n], 0, NULL); + if (ttable[n] == NULL) { + printf("CreateThread creation problem. good luck\n"); + } + +#elif defined(__unix__) + if (pthread_create(&ttable[n], NULL, logger_func, &td[n])) { + printf("pthread creation problem. good luck\n"); + } +#endif + } + + + for (n=0; n < MT_THREADS; n++) { +#if defined(_WIN32) + WaitForSingleObject(ttable[n], 0); +#elif defined(__unix__) + pthread_join(ttable[n], NULL); +#endif + printf("thread %u/%u finished.\n", n, MT_THREADS); + } +} + +int main(int argc, char **argv) { + const char dname[]=DEFAULT_LOGFILE; + const char *fname; + + if (argc > 1) { + fname = argv[1]; + } else { + fname = dname; + } + + if (sf_out_open(fname)) { + exit(1); + } + + start_test(); + + sf_out_close(); + return 0; +} From 6c31b3fb3ea750830955d4291b87ebe70c800387 Mon Sep 17 00:00:00 2001 From: fenugrec Date: Tue, 9 Jan 2018 11:46:53 -0500 Subject: [PATCH 3/5] output_file_sync : use fopen/fwrite on *nix There seems to be no point in using POSIX open+write; using fwrite takes less code and can be marginally faster. --- zf_log/output_file_sync.c | 46 ++++++++++----------------------------- 1 file changed, 12 insertions(+), 34 deletions(-) diff --git a/zf_log/output_file_sync.c b/zf_log/output_file_sync.c index a43fc03..c36c07a 100644 --- a/zf_log/output_file_sync.c +++ b/zf_log/output_file_sync.c @@ -21,12 +21,10 @@ #elif defined(__unix__) /* covers lots of stuff including linux, but not macs? */ - #include - #include - #include - #include + #include #include #include + #else #error No sync file output implementation for your OS ! #endif @@ -39,7 +37,7 @@ struct sf_out { HANDLE hfil; CRITICAL_SECTION mtx; //lightweight mutex #elif defined(__unix__) - int filedes; + FILE *hfil; pthread_mutex_t mtx; #endif }; @@ -63,30 +61,13 @@ static void sf_out_cb(const zf_log_message *msg, void *arg) return; } LeaveCriticalSection(&sf->mtx); -#elif defined(__unix__) - ssize_t towrite, writ = 0; - ssize_t errval; - - towrite = msg->p - msg->buf + 1; +#elif defined(__unix__) pthread_mutex_lock(&sf->mtx); - do { - errval = write(sf->filedes, &msg->buf[writ], towrite - writ); - /* catch non-fatal interrupted writes due to signal */ - if ((errval == -1) && (errno == EINTR)) { - /* nothing written */ - continue; - } - if (errval >= 0) { - writ += errval; - continue; - } - /* unrecoverable error */ - break; - } while (writ != towrite); - + fwrite(msg->buf, 1, (msg->p - msg->buf + 1), sf->hfil); // no point in checking for errors pthread_mutex_unlock(&sf->mtx); #endif + return; } @@ -100,13 +81,10 @@ void sf_out_close(void) { DeleteCriticalSection(&sf->mtx); CloseHandle(sf->hfil); #elif defined(__unix__) - int errval; pthread_mutex_destroy(&sf->mtx); - do { - errval = close(sf->filedes); - } while (errval == EINTR); - -#endif // if + fclose(sf->hfil); + sf->hfil = NULL; +#endif return; } @@ -127,13 +105,13 @@ int sf_out_open(const char *const fname) { return -1; } - sf->filedes = open(fname, O_WRONLY | O_CREAT | O_APPEND); - if (sf->filedes == -1) { + sf->hfil = fopen(fname, "ab"); + if (sf->hfil == NULL) { ZF_LOGW("Failed to create/open log file %s", fname); pthread_mutex_destroy(&sf->mtx); return -1; } -#endif // if +#endif zf_log_set_output_v(ZF_LOG_PUT_STD, sf, sf_out_cb); return 0; From 519b1e7d302b5d885ebdb4bfe9e7bc85411fb88a Mon Sep 17 00:00:00 2001 From: fenugrec Date: Tue, 9 Jan 2018 12:31:41 -0500 Subject: [PATCH 4/5] output_file_sync : append to file on win* too Wrong CreateFile flags --- zf_log/output_file_sync.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zf_log/output_file_sync.c b/zf_log/output_file_sync.c index c36c07a..813206b 100644 --- a/zf_log/output_file_sync.c +++ b/zf_log/output_file_sync.c @@ -93,7 +93,7 @@ int sf_out_open(const char *const fname) { struct sf_out *sf = &global_sf; #ifdef _WIN32 - sf->hfil = CreateFile(fname, GENERIC_WRITE, 0, NULL, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL); + sf->hfil = CreateFile(fname, FILE_APPEND_DATA, 0, NULL, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL); if (sf->hfil == INVALID_HANDLE_VALUE) { ZF_LOGW("Failed to create/open log file %s", fname); return -1; From ecba1c35fab8a8b559218eee4bbc3a0237d7b7c4 Mon Sep 17 00:00:00 2001 From: fenugrec Date: Tue, 9 Jan 2018 12:32:24 -0500 Subject: [PATCH 5/5] examples: fix multithread_output on win Not checking for thread completion properly; needs INFINITE timeout not 0 ! --- examples/multithread_output.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/examples/multithread_output.c b/examples/multithread_output.c index af97dbf..8dd0af6 100644 --- a/examples/multithread_output.c +++ b/examples/multithread_output.c @@ -43,7 +43,7 @@ struct tdata { }; #if defined(_WIN32) -HANDLE ttable[MT_MCOUNT]; +HANDLE ttable[MT_THREADS]; DWORD WINAPI logger_func(LPVOID priv) { struct tdata *td = priv; @@ -118,7 +118,7 @@ static void start_test(void) { for (n=0; n < MT_THREADS; n++) { #if defined(_WIN32) - WaitForSingleObject(ttable[n], 0); + WaitForSingleObject(ttable[n], INFINITE); #elif defined(__unix__) pthread_join(ttable[n], NULL); #endif