From 5d626151d30145e3e339b0b898a91cb7cd3c4ec9 Mon Sep 17 00:00:00 2001 From: heck Date: Wed, 15 Apr 2020 18:18:04 +0200 Subject: [PATCH 1/4] More Logging (in DEBUG build) --- .hgignore | 2 ++ Adapter.cc | 20 +++++++++++++------- Adapter.hh | 9 +-------- Makefile | 2 +- Makefile.conf | 4 ++-- utils.hh | 9 +++++++++ 6 files changed, 28 insertions(+), 18 deletions(-) create mode 100644 utils.hh diff --git a/.hgignore b/.hgignore index 9b4c464..b081e1b 100644 --- a/.hgignore +++ b/.hgignore @@ -9,3 +9,5 @@ test_adapter lib local.conf build/ +# Default ignored files +.idea/ diff --git a/Adapter.cc b/Adapter.cc index cd213f9..579dd69 100644 --- a/Adapter.cc +++ b/Adapter.cc @@ -12,6 +12,7 @@ using namespace std; namespace pEp { void throw_status(PEP_STATUS status) { + pEpLog("called"); if (status == PEP_STATUS_OK) return; if (status >= 0x400 && status <= 0x4ff) @@ -28,7 +29,7 @@ namespace pEp { RuntimeError::RuntimeError(const std::string& _text, PEP_STATUS _status) : std::runtime_error(_text.c_str()), text(_text), status(_status) { - + pEpLog("called"); } namespace Adapter { @@ -36,18 +37,19 @@ namespace pEp { notifyHandshake_t _notifyHandshake = nullptr; std::thread *_sync_thread = nullptr; - ::utility::locked_queue< SYNC_EVENT, ::free_Sync_event > q; + ::utility::locked_queue< SYNC_EVENT, ::free_Sync_event > sync_q; std::mutex m; int _inject_sync_event(SYNC_EVENT ev, void *management) { + pEpLog("called"); try { if (ev == nullptr) { - q.clear(); - q.push_back(ev); + sync_q.clear(); + sync_q.push_back(ev); } else { - q.push_front(ev); + sync_q.push_front(ev); } } catch (exception&) { @@ -61,7 +63,7 @@ namespace pEp { delete _sync_thread; _sync_thread = nullptr; pEpLog("...thread joined"); - q.clear(); + sync_q.clear(); } else { //FATAL pEpLog("FATAL: sync thread not joinable/detached"); @@ -74,8 +76,9 @@ namespace pEp { // threshold: max waiting time in seconds SYNC_EVENT _retrieve_next_sync_event(void *management, unsigned threshold) { + pEpLog("called"); SYNC_EVENT syncEvent = nullptr; - const bool success = q.try_pop_front(syncEvent, std::chrono::seconds(threshold)); + const bool success = sync_q.try_pop_front(syncEvent, std::chrono::seconds(threshold)); if (!success) return new_sync_timeout_event(); @@ -85,6 +88,7 @@ namespace pEp { bool on_sync_thread() { + pEpLog("called"); if (_sync_thread && _sync_thread->get_id() == this_thread::get_id()) return true; else @@ -93,6 +97,7 @@ namespace pEp { PEP_SESSION session(session_action action) { + pEpLog("called"); std::lock_guard lock(m); bool in_sync = on_sync_thread(); @@ -131,6 +136,7 @@ namespace pEp { bool is_sync_running() { + pEpLog("called"); return _sync_thread != nullptr; } } diff --git a/Adapter.hh b/Adapter.hh index d22b5cb..f17f984 100644 --- a/Adapter.hh +++ b/Adapter.hh @@ -7,14 +7,7 @@ #include #include #include - -// TODO: put into not yet existing libpEpAdapter_utils.h, to be across whole libpEpAdapter -#ifdef NDEBUG - #define pEpLog(msg) do{}while(0) -#else - #include - #define pEpLog(msg) do{std::cerr << __FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0) -#endif +#include "utils.hh" namespace pEp { diff --git a/Makefile b/Makefile index b8c723c..98d82c4 100644 --- a/Makefile +++ b/Makefile @@ -17,7 +17,7 @@ ifdef BUILD_CONFIG $(info ================================================) endif -.PHONY: all, lib, test, install, uninstall, clean +.PHONY: all lib test install uninstall clean SOURCE=$(wildcard *.cc) HEADERS=$(wildcard *.hh *.hxx) diff --git a/Makefile.conf b/Makefile.conf index bb95499..74f33b0 100644 --- a/Makefile.conf +++ b/Makefile.conf @@ -32,11 +32,11 @@ else CXXFLAGS+=-DNDEBUG=1 endif -######### Engine ######### +# Defaults ENGINE_LIB_PATH=$(HOME)/lib ENGINE_INC_PATH=$(HOME)/include -######### Overrides ######### +# Config File -include $(HERE)/local.conf # Add -L Prefixes to LIB/INC paths, diff --git a/utils.hh b/utils.hh new file mode 100644 index 0000000..ab328c1 --- /dev/null +++ b/utils.hh @@ -0,0 +1,9 @@ +#pragma once + + +#ifdef NDEBUG + #define pEpLog(msg) do{}while(0) +#else + #include + #define pEpLog(msg) do{std::cerr << __FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0) +#endif From 15a20035eb14bc4fc45f1e810c1769d600b75108 Mon Sep 17 00:00:00 2001 From: heck Date: Thu, 16 Apr 2020 21:22:23 +0200 Subject: [PATCH 2/4] Improved Logging, prefixed with thread_id now. (DEBUG build only) added pEpErr() (DEBUG and RELEASE build) non-local vars names with len == 1 are not handy at all --- Adapter.cc | 26 ++++++++++++++++++++------ Adapter.hh | 1 - Adapter.hxx | 6 +++++- test/test_adapter.cc | 16 ++++++++-------- test/test_adapter_cxx.cc | 3 ++- utils.hh | 7 +++++-- 6 files changed, 40 insertions(+), 19 deletions(-) diff --git a/Adapter.cc b/Adapter.cc index 579dd69..ce6d7f7 100644 --- a/Adapter.cc +++ b/Adapter.cc @@ -6,13 +6,15 @@ #include #include #include "status_to_string.hh" +#include "utils.hh" + using namespace std; namespace pEp { void throw_status(PEP_STATUS status) { - pEpLog("called"); + //pEpLog("called"); if (status == PEP_STATUS_OK) return; if (status >= 0x400 && status <= 0x4ff) @@ -38,21 +40,24 @@ namespace pEp { std::thread *_sync_thread = nullptr; ::utility::locked_queue< SYNC_EVENT, ::free_Sync_event > sync_q; - std::mutex m; + std::mutex mutex_global; int _inject_sync_event(SYNC_EVENT ev, void *management) { pEpLog("called"); try { if (ev == nullptr) { + pEpLog("SYNC_EVENT: NULL"); sync_q.clear(); sync_q.push_back(ev); } else { + pEpLog("SYNC_EVENT:" << ev); sync_q.push_front(ev); } } catch (exception&) { + pEpErr("Exception"); return 1; } if (ev == nullptr) { @@ -80,15 +85,18 @@ namespace pEp { SYNC_EVENT syncEvent = nullptr; const bool success = sync_q.try_pop_front(syncEvent, std::chrono::seconds(threshold)); - if (!success) + if (!success) { + pEpLog("timeout after [sec]: " << threshold); return new_sync_timeout_event(); + } + pEpLog("returning SYNC_EVENT: " << syncEvent); return syncEvent; } bool on_sync_thread() { - pEpLog("called"); + //pEpLog("called"); if (_sync_thread && _sync_thread->get_id() == this_thread::get_id()) return true; else @@ -98,7 +106,7 @@ namespace pEp { PEP_SESSION session(session_action action) { pEpLog("called"); - std::lock_guard lock(m); + std::lock_guard lock(mutex_global); bool in_sync = on_sync_thread(); thread_local static PEP_SESSION _session = nullptr; @@ -107,14 +115,19 @@ namespace pEp { switch (action) { case release: if (_session) { + pEpLog("action = release: releasing session: " << _session); ::release(_session); _session = nullptr; + } else { + pEpLog("action = release: No session to release"); } break; case init: - if (!_session) + if (!_session) { + pEpLog("action = init: creating new session"); status = ::init(&_session, _messageToSend, _inject_sync_event); + } break; default: @@ -122,6 +135,7 @@ namespace pEp { } throw_status(status); + pEpLog("returning session: " << _session); return _session; } diff --git a/Adapter.hh b/Adapter.hh index f17f984..55bc101 100644 --- a/Adapter.hh +++ b/Adapter.hh @@ -7,7 +7,6 @@ #include #include #include -#include "utils.hh" namespace pEp { diff --git a/Adapter.hxx b/Adapter.hxx index 73947dc..9b19605 100644 --- a/Adapter.hxx +++ b/Adapter.hxx @@ -6,6 +6,7 @@ #include #include "locked_queue.hh" #include +#include "utils.hh" namespace pEp { namespace Adapter { @@ -16,7 +17,7 @@ namespace pEp { extern std::thread *_sync_thread; extern ::utility::locked_queue< SYNC_EVENT, ::free_Sync_event > q; - extern std::mutex m; + extern std::mutex mutex_global; SYNC_EVENT _retrieve_next_sync_event(void *management, unsigned threshold); @@ -25,6 +26,7 @@ namespace pEp { template< class T > void sync_thread(T *obj, function< void(T *) > _startup, function< void(T *) > _shutdown) { + pEpLog("called"); _ex = nullptr; assert(_messageToSend); assert(_notifyHandshake); @@ -67,6 +69,8 @@ namespace pEp { ) throw (RuntimeError) { + pEpLog("called"); + if (messageToSend) _messageToSend = messageToSend; diff --git a/test/test_adapter.cc b/test/test_adapter.cc index 75e78c0..226b72e 100644 --- a/test/test_adapter.cc +++ b/test/test_adapter.cc @@ -1,24 +1,25 @@ // This file is under GNU General Public License 3.0 // see LICENSE.txt -#include "Adapter.hh" #include #include #include #include +#include "Adapter.hh" +#include "../utils.hh" using namespace std; using namespace pEp::Adapter; PEP_STATUS messageToSend(struct _message *msg) { - pEpLog("called()"); + pEpLog("called"); return PEP_STATUS_OK; } PEP_STATUS notifyHandshake(pEp_identity *me, pEp_identity *partner, sync_handshake_signal signal) { - pEpLog("called()"); + pEpLog("called"); return PEP_STATUS_OK; } @@ -33,17 +34,16 @@ int main() pEp::throw_status(status); // start and stop sync repeatedly - useconds_t sleepuSec = 1000 * 100; - unsigned long long int nrIters = 1000 * 1000 * 1000; + useconds_t sleepuSec = 1000 * 1000; + unsigned long long int nrIters = 3;//1000 * 1000 * 1000; for (int i = 0; i < nrIters; i++) { - pEpLog("RUN NR: "); - pEpLog(i); + pEpLog("RUN NR: " << i); pEpLog("SYNC START"); - pEpLog("starting the adapter including sync"); startup(messageToSend, notifyHandshake); pEpLog("SYNC STOP"); usleep(sleepuSec); shutdown(); + usleep(sleepuSec); } return 0; } diff --git a/test/test_adapter_cxx.cc b/test/test_adapter_cxx.cc index e44a2ed..885224a 100644 --- a/test/test_adapter_cxx.cc +++ b/test/test_adapter_cxx.cc @@ -1,11 +1,12 @@ // This file is under GNU General Public License 3.0 // see LICENSE.txt -#include "Adapter.hh" #include #include #include #include +#include "Adapter.hh" +#include "../utils.hh" using namespace pEp::Adapter; diff --git a/utils.hh b/utils.hh index ab328c1..5ddb8be 100644 --- a/utils.hh +++ b/utils.hh @@ -1,9 +1,12 @@ #pragma once +#include +#include #ifdef NDEBUG #define pEpLog(msg) do{}while(0) #else - #include - #define pEpLog(msg) do{std::cerr << __FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0) + #define pEpLog(msg) do{std::cout << "Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0) #endif + +#define pEpErr(msg) do{std::cerr << "Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0) \ No newline at end of file From 4e47aa6d9e897a566db8ba43d01ff6e68b910d9f Mon Sep 17 00:00:00 2001 From: heck Date: Mon, 20 Apr 2020 21:22:40 +0200 Subject: [PATCH 3/4] pEpLog() / pEpErr() - Add high-res timestamp Add test_peplog.cc --- test/Makefile | 5 ++++- test/test_peplog.cc | 16 ++++++++++++++++ utils.hh | 40 +++++++++++++++++++++++++++++++++++----- 3 files changed, 55 insertions(+), 6 deletions(-) create mode 100644 test/test_peplog.cc diff --git a/test/Makefile b/test/Makefile index 7f8f4d2..0d64421 100644 --- a/test/Makefile +++ b/test/Makefile @@ -6,7 +6,7 @@ CXXFLAGS+=-I../ .PHONY=all, test_adapter, test_adapter_cxx, test_library -all: test_adapter test_adapter_cxx test_library +all: test_adapter test_adapter_cxx test_library test_peplog test_adapter: test_adapter.cc ../libpEpAdapter.a @@ -14,6 +14,9 @@ test_adapter_cxx: test_adapter_cxx.cc ../libpEpAdapter.a test_library: test_library.cc ../libpEpAdapter.a +test_peplog: test_peplog.cc + + clean: rm -vf test_adapter rm -rvf test_adapter.dSYM diff --git a/test/test_peplog.cc b/test/test_peplog.cc new file mode 100644 index 0000000..2210238 --- /dev/null +++ b/test/test_peplog.cc @@ -0,0 +1,16 @@ +// This file is under GNU General Public License 3.0 +// see LICENSE.txt + +#include "utils.hh" +// Single threaded test of pEpLog() function. +// check for uniformity of time + +int main() +{ + pEpLog("Test Starting... observe uniformity of timestamp."); + int nr_log_lines = 1000000; + for (int i; i < nr_log_lines; i++) { + pEpLog("log line nr: " << i); + } + return 0; +} diff --git a/utils.hh b/utils.hh index 5ddb8be..f03b500 100644 --- a/utils.hh +++ b/utils.hh @@ -1,12 +1,42 @@ #pragma once - #include #include +#include +#include + +// Returns a timestamp string featuring microseconds precision +// Uses system clock, so time might not pass uniformly + +inline std::string timestamp_usec() { + std::ostringstream buffer; + std::chrono::system_clock::duration d = std::chrono::system_clock::now().time_since_epoch(); + + std::chrono::microseconds us = std::chrono::duration_cast(d); + std::chrono::seconds s = std::chrono::duration_cast (d); + + std::time_t t = s.count(); + std::tm tm = *std::localtime(&t); + + std::size_t fractional_seconds = us.count() % 1000000; + buffer << std::put_time(&tm, "%H%:%M:%S") << "." << fractional_seconds; + + return buffer.str(); +} + +// pEpLog(msg) - logs to STDOUT +// pEpErr(msg) - logs to STDERR +// +// Log format is: +// TIMESTAMP.usecs THREAD-ID SRC_FILE_NAME::FUNCTION_NAME - msg +// +// example: +// 21:06:04.214884 Thread:0x10f2ce5c0 test_peplog.cc::main - test run nr: 436744 +// +// if -DNDEBUG=1 (for release builds), all pEpLog() calls will be optimized away. #ifdef NDEBUG - #define pEpLog(msg) do{}while(0) +#define pEpLog(msg) do{}while(0) #else - #define pEpLog(msg) do{std::cout << "Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0) +#define pEpLog(msg) do{ std::cout << timestamp_usec() << " Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0) #endif - -#define pEpErr(msg) do{std::cerr << "Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0) \ No newline at end of file +#define pEpErr(msg) do{ std::cout << timestamp_usec() << " Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0) From 7c8a840aeec87bea1229392b1c01ff14ddbe3daa Mon Sep 17 00:00:00 2001 From: heck Date: Tue, 21 Apr 2020 00:06:23 +0200 Subject: [PATCH 4/4] pEpLog() / pEpErr() - enable automatic flushing on std::cout and std::cerr --- utils.hh | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/utils.hh b/utils.hh index f03b500..cc253ed 100644 --- a/utils.hh +++ b/utils.hh @@ -37,6 +37,6 @@ inline std::string timestamp_usec() { #ifdef NDEBUG #define pEpLog(msg) do{}while(0) #else -#define pEpLog(msg) do{ std::cout << timestamp_usec() << " Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0) +#define pEpLog(msg) do{ std::cout << std::unitbuf; std::cout << timestamp_usec() << " Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << std::endl;} while(0) #endif -#define pEpErr(msg) do{ std::cout << timestamp_usec() << " Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0) +#define pEpErr(msg) do{ std::cerr << std::unitbuf; std::cerr << timestamp_usec() << " Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << std::endl;} while(0)