generic-library/g3log
1
0
Fork 0
mirror of https://github.com/KjellKod/g3log.git synced 2024-12-13 18:45:12 +01:00
Code Issues Projects Releases Wiki Activity

Finally the right sublime AstyleFormat options pointer-align:type and reference-align:type

Browse Source 
Fixed bug with dynamic logging levels and DBUG (instead of DEBUG)
This commit is contained in:
Kjell Hedstrom 2015-01-28 12:49:36 -07:00
parent fb30aef9e8
commit c5bb9b96d8
12 changed files with 559 additions and 534 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
example/main_fatal_choice.cpp
View File

@ -94,7 +94,7 @@ void OutOfBoundsArrayIndexing() {
void AccessViolation() { void AccessViolation() {
std::cout << "Calling :" << __FUNCTION__ << " Line: " << __LINE__ << std::endl << std::flush; std::cout << "Calling :" << __FUNCTION__ << " Line: " << __LINE__ << std::endl << std::flush;
char *ptr = 0; char* ptr = 0;
LOG(INFO) << "Death by access violation is imminent"; LOG(INFO) << "Death by access violation is imminent";
*ptr = 0; *ptr = 0;
LOG(WARNING) << "Expected to have died by now..."; LOG(WARNING) << "Expected to have died by now...";
@ -200,7 +200,7 @@ void ChooseFatalExit() {
} }
} // namespace } // namespace
int main(int argc, char **argv) int main(int argc, char** argv)
{ {
auto logger_n_handle = g2::LogWorker::createWithDefaultLogger(argv[0], path_to_log_file); auto logger_n_handle = g2::LogWorker::createWithDefaultLogger(argv[0], path_to_log_file);
g2::initializeLogging(logger_n_handle.worker.get()); g2::initializeLogging(logger_n_handle.worker.get());

118
example/main_sigsegv.cpp
View File

@ -23,80 +23,80 @@ const std::string path_to_log_file = "/tmp/";
namespace example_fatal namespace example_fatal
{ {
// on Ubunti this caused get a compiler warning with gcc4.6 // on Ubunti this caused get a compiler warning with gcc4.6
// from gcc 4.7.2 (at least) it causes a crash (as expected) // from gcc 4.7.2 (at least) it causes a crash (as expected)
// On windows it'll probably crash too. // On windows it'll probably crash too.
void tryToKillWithIllegalPrintout() void tryToKillWithIllegalPrintout()
{ {
std::cout << "\n\n***** Be ready this last example may 'abort' if on Windows/Linux_gcc4.7 " << std::endl << std::flush; std::cout << "\n\n***** Be ready this last example may 'abort' if on Windows/Linux_gcc4.7 " << std::endl << std::flush;
std::cout << "************************************************************\n\n" << std::endl << std::flush; std::cout << "************************************************************\n\n" << std::endl << std::flush;
std::this_thread::sleep_for(std::chrono::seconds(1)); std::this_thread::sleep_for(std::chrono::seconds(1));
const std::string logging = "logging"; const std::string logging = "logging";
LOGF(DEBUG, "ILLEGAL PRINTF_SYNTAX EXAMPLE. WILL GENERATE compiler warning.\n\nbadly formatted message:[Printf-type %s is the number 1 for many %s]", logging.c_str()); LOGF(DEBUG, "ILLEGAL PRINTF_SYNTAX EXAMPLE. WILL GENERATE compiler warning.\n\nbadly formatted message:[Printf-type %s is the number 1 for many %s]", logging.c_str());
} }
// The function above 'tryToKillWithIllegalPrintout' IS system / compiler dependent. Older compilers sometimes did NOT generate a SIGSEGV // The function above 'tryToKillWithIllegalPrintout' IS system / compiler dependent. Older compilers sometimes did NOT generate a SIGSEGV
// fault as expected by the illegal printf-format usage. just in case we exit by zero division" // fault as expected by the illegal printf-format usage. just in case we exit by zero division"
void killByZeroDivision(int value) void killByZeroDivision(int value)
{ {
int zero = 0; // trying to fool the compiler to automatically warn int zero = 0; // trying to fool the compiler to automatically warn
LOG(INFO) << "This is a bad operation [value/zero] : " << value/zero; LOG(INFO) << "This is a bad operation [value/zero] : " << value / zero;
} }
} // example fatal } // example fatal
int main(int argc, char** argv) int main(int argc, char** argv)
{ {
double pi_d = 3.1415926535897932384626433832795; double pi_d = 3.1415926535897932384626433832795;
float pi_f = 3.1415926535897932384626433832795f; float pi_f = 3.1415926535897932384626433832795f;
using namespace g2; using namespace g2;
std::unique_ptr<LogWorker> logworker{LogWorker::createWithNoSink()}; std::unique_ptr<LogWorker> logworker {LogWorker::createWithNoSink()};
auto sinkHandle = logworker->addSink(std2::make_unique<FileSink>(argv[0], path_to_log_file), auto sinkHandle = logworker->addSink(std2::make_unique<FileSink>(argv[0], path_to_log_file),
&FileSink::fileWrite); &FileSink::fileWrite);
initializeLogging(logworker.get()); initializeLogging(logworker.get());
std::future<std::string> log_file_name = sinkHandle->call(&FileSink::fileName); std::future<std::string> log_file_name = sinkHandle->call(&FileSink::fileName);
std::cout << "* This is an example of g2log. It WILL exit by a FATAL trigger" << std::endl; std::cout << "* This is an example of g2log. It WILL exit by a FATAL trigger" << std::endl;
std::cout << "* Please see the generated log and compare to the code at" << std::endl; std::cout << "* Please see the generated log and compare to the code at" << std::endl;
std::cout << "* g2log/test_example/main.cpp" << std::endl; std::cout << "* g2log/test_example/main.cpp" << std::endl;
std::cout << "*\n* Log file: [" << log_file_name.get() << "]\n\n" << std::endl; std::cout << "*\n* Log file: [" << log_file_name.get() << "]\n\n" << std::endl;
LOGF(INFO, "Hi log %d", 123); LOGF(INFO, "Hi log %d", 123);
LOG(INFO) << "Test SLOG INFO"; LOG(INFO) << "Test SLOG INFO";
LOG(DEBUG) << "Test SLOG DEBUG"; LOG(DEBUG) << "Test SLOG DEBUG";
LOG(INFO) << "one: " << 1; LOG(INFO) << "one: " << 1;
LOG(INFO) << "two: " << 2; LOG(INFO) << "two: " << 2;
LOG(INFO) << "one and two: " << 1 << " and " << 2; LOG(INFO) << "one and two: " << 1 << " and " << 2;
LOG(DEBUG) << "float 2.14: " << 1000/2.14f; LOG(DEBUG) << "float 2.14: " << 1000 / 2.14f;
LOG(DEBUG) << "pi double: " << pi_d; LOG(DEBUG) << "pi double: " << pi_d;
LOG(DEBUG) << "pi float: " << pi_f; LOG(DEBUG) << "pi float: " << pi_f;
LOG(DEBUG) << "pi float (width 10): " << std::setprecision(10) << pi_f; LOG(DEBUG) << "pi float (width 10): " << std::setprecision(10) << pi_f;
LOGF(INFO, "pi float printf:%f", pi_f); LOGF(INFO, "pi float printf:%f", pi_f);
// //
// START: LOG Entris that were in the CodeProject article // START: LOG Entris that were in the CodeProject article
// //
//LOG(UNKNOWN_LEVEL) << "This log attempt will cause a compiler error"; //LOG(UNKNOWN_LEVEL) << "This log attempt will cause a compiler error";
LOG(INFO) << "Simple to use with streaming syntax, easy as abc or " << 123; LOG(INFO) << "Simple to use with streaming syntax, easy as abc or " << 123;
LOGF(WARNING, "Printf-style syntax is also %s", "available"); LOGF(WARNING, "Printf-style syntax is also %s", "available");
LOG_IF(INFO, (1 < 2)) << "If true this text will be logged"; LOG_IF(INFO, (1 < 2)) << "If true this text will be logged";
LOGF_IF(INFO, (1<2), "if %d<%d : then this text will be logged", 1,2); LOGF_IF(INFO, (1 < 2), "if %d<%d : then this text will be logged", 1, 2);
LOG_IF(FATAL, (2>3)) << "This message should NOT throw"; LOG_IF(FATAL, (2 > 3)) << "This message should NOT throw";
LOGF(DEBUG, "This API is popular with some %s", "programmers"); LOGF(DEBUG, "This API is popular with some %s", "programmers");
LOGF_IF(DEBUG, (1<2), "If true, then this %s will be logged", "message"); LOGF_IF(DEBUG, (1 < 2), "If true, then this %s will be logged", "message");
// OK --- on Ubunti this caused get a compiler warning with gcc4.6 // OK --- on Ubunti this caused get a compiler warning with gcc4.6
// from gcc 4.7.2 (at least) it causes a crash (as expected) // from gcc 4.7.2 (at least) it causes a crash (as expected)
// On windows itll probably crash // On windows itll probably crash
//example_fatal::tryToKillWithIllegalPrintout(); //example_fatal::tryToKillWithIllegalPrintout();
int value = 1; // system dependent but it SHOULD never reach this line int value = 1; // system dependent but it SHOULD never reach this line
example_fatal::killByZeroDivision(value); example_fatal::killByZeroDivision(value);
return 0; return 0;
} }

4
src/crashhandler.hpp
View File

@ -17,7 +17,7 @@ namespace g2 {
#if (defined(WIN32) || defined(_WIN32) || defined(__WIN32__)) #if (defined(WIN32) || defined(_WIN32) || defined(__WIN32__))
typedef unsigned long SignalType; typedef unsigned long SignalType;
/// SIGFPE, SIGILL, and SIGSEGV handling must be installed per thread /// SIGFPE, SIGILL, and SIGSEGV handling must be installed per thread
/// on Windows. This is automatically done if you do at least one LOG(...) call /// on Windows. This is automatically done if you do at least one LOG(...) call
/// you can also use this function call, per thread so make sure these three /// you can also use this function call, per thread so make sure these three
@ -41,7 +41,7 @@ bool blockForFatalHandling();
std::string exitReasonName(const LEVELS& level, g2::SignalType signal_number); std::string exitReasonName(const LEVELS& level, g2::SignalType signal_number);
/** return calling thread's stackdump*/ /** return calling thread's stackdump*/
std::string stackdump(const char *dump = nullptr); std::string stackdump(const char* dump = nullptr);
/** Re-"throw" a fatal signal, previously caught. This will exit the application /** Re-"throw" a fatal signal, previously caught. This will exit the application
* This is an internal only function. Do not use it elsewhere. It is triggered * This is an internal only function. Do not use it elsewhere. It is triggered

12
src/crashhandler_windows.cpp
View File

@ -34,7 +34,7 @@
// not all signal handlers need to be re-installed // not all signal handlers need to be re-installed
namespace { namespace {
std::atomic<bool> gBlockForFatal {true}; std::atomic<bool> gBlockForFatal {true};
void *g_vector_exception_handler = nullptr; void* g_vector_exception_handler = nullptr;
LPTOP_LEVEL_EXCEPTION_FILTER g_previous_unexpected_exception_handler = nullptr; LPTOP_LEVEL_EXCEPTION_FILTER g_previous_unexpected_exception_handler = nullptr;
// Restore back to default fatal event handling // Restore back to default fatal event handling
@ -79,7 +79,7 @@ void signalHandler(int signal_number) {
// //
// Unhandled exception catching // Unhandled exception catching
LONG WINAPI exceptionHandling(EXCEPTION_POINTERS *info) { LONG WINAPI exceptionHandling(EXCEPTION_POINTERS* info) {
const g2::SignalType exception_code = info->ExceptionRecord->ExceptionCode; const g2::SignalType exception_code = info->ExceptionRecord->ExceptionCode;
//const auto exceptionText = stacktrace::exceptionIdToText(exception_code); //const auto exceptionText = stacktrace::exceptionIdToText(exception_code);
/**** START HACK ****/ /**** START HACK ****/
@ -103,7 +103,7 @@ LONG WINAPI exceptionHandling(EXCEPTION_POINTERS *info) {
// //
// Unhandled exception catching // Unhandled exception catching
LONG WINAPI unexpectedExceptionHandling(EXCEPTION_POINTERS *info) { LONG WINAPI unexpectedExceptionHandling(EXCEPTION_POINTERS* info) {
ReverseToOriginalFatalHandling(); ReverseToOriginalFatalHandling();
return exceptionHandling(info); return exceptionHandling(info);
} }
@ -138,7 +138,7 @@ bool blockForFatalHandling() {
/// Generate stackdump. Or in case a stackdump was pre-generated and non-empty just use that one /// Generate stackdump. Or in case a stackdump was pre-generated and non-empty just use that one
/// i.e. the latter case is only for Windows and test purposes /// i.e. the latter case is only for Windows and test purposes
std::string stackdump(const char *dump) { std::string stackdump(const char* dump) {
if (nullptr != dump && !std::string(dump).empty()) { if (nullptr != dump && !std::string(dump).empty()) {
return {dump}; return {dump};
} }
@ -149,7 +149,7 @@ std::string stackdump(const char *dump) {
/// string representation of signal ID or Windows exception id /// string representation of signal ID or Windows exception id
std::string exitReasonName(const LEVELS &level, g2::SignalType fatal_id) { std::string exitReasonName(const LEVELS& level, g2::SignalType fatal_id) {
// //
std::cout << __FUNCTION__ << " exit reason: " << fatal_id << std::endl; std::cout << __FUNCTION__ << " exit reason: " << fatal_id << std::endl;
if (level == g2::internal::FATAL_EXCEPTION) { if (level == g2::internal::FATAL_EXCEPTION) {
@ -178,7 +178,7 @@ std::string exitReasonName(const LEVELS &level, g2::SignalType fatal_id) {
// Triggered by g2log::LogWorker after receiving a FATAL trigger // Triggered by g2log::LogWorker after receiving a FATAL trigger
// which is LOG(FATAL), CHECK(false) or a fatal signal our signalhandler caught. // which is LOG(FATAL), CHECK(false) or a fatal signal our signalhandler caught.
// --- If LOG(FATAL) or CHECK(false) the signal_number will be SIGABRT // --- If LOG(FATAL) or CHECK(false) the signal_number will be SIGABRT
void exitWithDefaultSignalHandler(const LEVELS &level, g2::SignalType fatal_signal_id) { void exitWithDefaultSignalHandler(const LEVELS& level, g2::SignalType fatal_signal_id) {
ReverseToOriginalFatalHandling(); ReverseToOriginalFatalHandling();
// For windows exceptions we want to continue the possibility of exception handling // For windows exceptions we want to continue the possibility of exception handling

297
src/g2log.cpp
View File

@ -31,13 +31,13 @@
#include "g2logmessage.hpp" #include "g2logmessage.hpp"
namespace { namespace {
std::once_flag g_initialize_flag; std::once_flag g_initialize_flag;
g2::LogWorker* g_logger_instance = nullptr; // instantiated and OWNED somewhere else (main) g2::LogWorker* g_logger_instance = nullptr; // instantiated and OWNED somewhere else (main)
std::mutex g_logging_init_mutex; std::mutex g_logging_init_mutex;
std::unique_ptr<g2::LogMessage> g_first_unintialized_msg = {nullptr}; std::unique_ptr<g2::LogMessage> g_first_unintialized_msg = {nullptr};
std::once_flag g_set_first_uninitialized_flag; std::once_flag g_set_first_uninitialized_flag;
std::once_flag g_save_first_unintialized_flag; std::once_flag g_save_first_unintialized_flag;
} }
@ -46,157 +46,158 @@ namespace {
namespace g2 { namespace g2 {
// signalhandler and internal clock is only needed to install once // signalhandler and internal clock is only needed to install once
// for unit testing purposes the initializeLogging might be called // for unit testing purposes the initializeLogging might be called
// several times... // several times...
// for all other practical use, it shouldn't! // for all other practical use, it shouldn't!
void initializeLogging(LogWorker *bgworker) { void initializeLogging(LogWorker* bgworker) {
std::call_once(g_initialize_flag, []() { std::call_once(g_initialize_flag, []() {
installCrashHandler(); }); installCrashHandler();
std::lock_guard<std::mutex> lock(g_logging_init_mutex); });
CHECK(!internal::isLoggingInitialized()); std::lock_guard<std::mutex> lock(g_logging_init_mutex);
CHECK(bgworker != nullptr); CHECK(!internal::isLoggingInitialized());
CHECK(bgworker != nullptr);
// Save the first uninitialized message, if any // Save the first uninitialized message, if any
std::call_once(g_save_first_unintialized_flag, [&bgworker] { std::call_once(g_save_first_unintialized_flag, [&bgworker] {
if (g_first_unintialized_msg) { if (g_first_unintialized_msg) {
bgworker->save(LogMessagePtr{std::move(g_first_unintialized_msg)}); bgworker->save(LogMessagePtr {std::move(g_first_unintialized_msg)});
} }
});
g_logger_instance = bgworker;
}
namespace internal {
bool isLoggingInitialized() {
return g_logger_instance != nullptr;
}
/**
* Shutdown the logging by making the pointer to the background logger to nullptr. The object is not deleted
* that is the responsibility of its owner. *
*/
void shutDownLogging() {
std::lock_guard<std::mutex> lock(g_logging_init_mutex);
g_logger_instance = nullptr;
}
/** Same as the Shutdown above but called by the destructor of the LogWorker, thus ensuring that no further
* LOG(...) calls can happen to a non-existing LogWorker.
* @param active MUST BE the LogWorker initialized for logging. If it is not then this call is just ignored
* and the logging continues to be active.
* @return true if the correct worker was given,. and shutDownLogging was called
*/
bool shutDownLoggingForActiveOnly(LogWorker* active) {
if (isLoggingInitialized() && nullptr != active && (active != g_logger_instance)) {
LOG(WARNING) << "\n\t\tAttempted to shut down logging, but the ID of the Logger is not the one that is active."
<< "\n\t\tHaving multiple instances of the g2::LogWorker is likely a BUG"
<< "\n\t\tEither way, this call to shutDownLogging was ignored"
<< "\n\t\tTry g2::internal::shutDownLogging() instead";
return false;
}
shutDownLogging();
return true;
}
/** explicits copy of all input. This is makes it possibly to use g3log across dynamically loaded libraries
* i.e. (dlopen + dlsym) */
void saveMessage(const char* entry, const char* file, int line, const char* function, const LEVELS& level,
const char* boolean_expression, int fatal_signal, const char* stack_trace) {
LEVELS msgLevel {level};
LogMessagePtr message {std2::make_unique<LogMessage>(file, line, function, msgLevel)};
message.get()->write().append(entry);
message.get()->setExpression(boolean_expression);
if (internal::wasFatal(level)) {
message.get()->write().append(stack_trace);
FatalMessagePtr fatal_message {std2::make_unique<FatalMessage>(*(message._move_only.get()), fatal_signal)};
// At destruction, flushes fatal message to g2LogWorker
// either we will stay here until the background worker has received the fatal
// message, flushed the crash message to the sinks and exits with the same fatal signal
//..... OR it's in unit-test mode then we throw a std::runtime_error (and never hit sleep)
fatalCall(fatal_message);
} else {
pushMessageToLogger(message);
}
}
/**
* save the message to the logger. In case of called before the logger is instantiated
* the first message will be saved. Any following subsequent unitnialized log calls
* will be ignored.
*
* The first initialized log entry will also save the first uninitialized log message, if any
* @param log_entry to save to logger
*/
void pushMessageToLogger(LogMessagePtr incoming) { // todo rename to Push SavedMessage To Worker
// Uninitialized messages are ignored but does not CHECK/crash the logger
if (!internal::isLoggingInitialized()) {
std::call_once(g_set_first_uninitialized_flag, [&] {
g_first_unintialized_msg = incoming.release();
std::string err = {"LOGGER NOT INITIALIZED:\n\t\t"};
err.append(g_first_unintialized_msg->message());
std::string& str = g_first_unintialized_msg->write();
str.clear();
str.append(err); // replace content
std::cerr << str << std::endl;
}); });
return;
g_logger_instance = bgworker;
} }
// logger is initialized
g_logger_instance->save(incoming);
}
/** Fatal call saved to logger. This will trigger SIGABRT or other fatal signal
* to exit the program. After saving the fatal message the calling thread
* will sleep forever (i.e. until the background thread catches up, saves the fatal
* message and kills the software with the fatal signal.
*/
void pushFatalMessageToLogger(FatalMessagePtr message) {
if (!isLoggingInitialized()) {
std::ostringstream error;
error << "FATAL CALL but logger is NOT initialized\n"
<< "CAUSE: " << message.get()->reason()
<< "\nMessage: \n" << message.get()->toString() << std::flush;
std::cerr << error.str() << std::flush;
internal::exitWithDefaultSignalHandler(message.get()->_level, message.get()->_signal_id);
}
g_logger_instance->fatal(message);
while (blockForFatalHandling()) {
std::this_thread::sleep_for(std::chrono::seconds(1));
}
}
// By default this function pointer goes to \ref pushFatalMessageToLogger;
std::function<void(FatalMessagePtr) > g_fatal_to_g2logworker_function_ptr = pushFatalMessageToLogger;
/** The default, initial, handling to send a 'fatal' event to g2logworker
* the caller will stay here, eternally, until the software is aborted
* ... in the case of unit testing it is the given "Mock" fatalCall that will
* define the behaviour.
*/
void fatalCall(FatalMessagePtr message) {
g_fatal_to_g2logworker_function_ptr(FatalMessagePtr {std::move(message)});
}
namespace internal { /** REPLACE fatalCallToLogger for fatalCallForUnitTest
* This function switches the function pointer so that only
bool isLoggingInitialized() { * 'unitTest' mock-fatal calls are made.
return g_logger_instance != nullptr; * */
} void setFatalExitHandler(std::function<void(FatalMessagePtr) > fatal_call) {
g_fatal_to_g2logworker_function_ptr = fatal_call;
/** }
* Shutdown the logging by making the pointer to the background logger to nullptr. The object is not deleted } // internal
* that is the responsibility of its owner. *
*/
void shutDownLogging() {
std::lock_guard<std::mutex> lock(g_logging_init_mutex);
g_logger_instance = nullptr;
}
/** Same as the Shutdown above but called by the destructor of the LogWorker, thus ensuring that no further
* LOG(...) calls can happen to a non-existing LogWorker.
* @param active MUST BE the LogWorker initialized for logging. If it is not then this call is just ignored
* and the logging continues to be active.
* @return true if the correct worker was given,. and shutDownLogging was called
*/
bool shutDownLoggingForActiveOnly(LogWorker* active) {
if (isLoggingInitialized() && nullptr != active && (active != g_logger_instance)) {
LOG(WARNING) << "\n\t\tAttempted to shut down logging, but the ID of the Logger is not the one that is active."
<< "\n\t\tHaving multiple instances of the g2::LogWorker is likely a BUG"
<< "\n\t\tEither way, this call to shutDownLogging was ignored"
<< "\n\t\tTry g2::internal::shutDownLogging() instead";
return false;
}
shutDownLogging();
return true;
}
/** explicits copy of all input. This is makes it possibly to use g3log across dynamically loaded libraries
* i.e. (dlopen + dlsym) */
void saveMessage(const char* entry, const char* file, int line, const char* function, const LEVELS& level,
const char* boolean_expression, int fatal_signal, const char* stack_trace) {
LEVELS msgLevel{level};
LogMessagePtr message{std2::make_unique<LogMessage>(file, line, function, msgLevel)};
message.get()->write().append(entry);
message.get()->setExpression(boolean_expression);
if (internal::wasFatal(level)) {
message.get()->write().append(stack_trace);
FatalMessagePtr fatal_message{std2::make_unique<FatalMessage>(*(message._move_only.get()), fatal_signal)};
// At destruction, flushes fatal message to g2LogWorker
// either we will stay here until the background worker has received the fatal
// message, flushed the crash message to the sinks and exits with the same fatal signal
//..... OR it's in unit-test mode then we throw a std::runtime_error (and never hit sleep)
fatalCall(fatal_message);
} else {
pushMessageToLogger(message);
}
}
/**
* save the message to the logger. In case of called before the logger is instantiated
* the first message will be saved. Any following subsequent unitnialized log calls
* will be ignored.
*
* The first initialized log entry will also save the first uninitialized log message, if any
* @param log_entry to save to logger
*/
void pushMessageToLogger(LogMessagePtr incoming) { // todo rename to Push SavedMessage To Worker
// Uninitialized messages are ignored but does not CHECK/crash the logger
if (!internal::isLoggingInitialized()) {
std::call_once(g_set_first_uninitialized_flag, [&] {
g_first_unintialized_msg = incoming.release();
std::string err = {"LOGGER NOT INITIALIZED:\n\t\t"};
err.append(g_first_unintialized_msg->message());
std::string& str = g_first_unintialized_msg->write();
str.clear();
str.append(err); // replace content
std::cerr << str << std::endl;
});
return;
}
// logger is initialized
g_logger_instance->save(incoming);
}
/** Fatal call saved to logger. This will trigger SIGABRT or other fatal signal
* to exit the program. After saving the fatal message the calling thread
* will sleep forever (i.e. until the background thread catches up, saves the fatal
* message and kills the software with the fatal signal.
*/
void pushFatalMessageToLogger(FatalMessagePtr message) {
if (!isLoggingInitialized()) {
std::ostringstream error;
error << "FATAL CALL but logger is NOT initialized\n"
<< "CAUSE: " << message.get()->reason()
<< "\nMessage: \n" << message.get()->toString() << std::flush;
std::cerr << error.str() << std::flush;
internal::exitWithDefaultSignalHandler(message.get()->_level, message.get()->_signal_id);
}
g_logger_instance->fatal(message);
while (blockForFatalHandling()) {
std::this_thread::sleep_for(std::chrono::seconds(1));
}
}
// By default this function pointer goes to \ref pushFatalMessageToLogger;
std::function<void(FatalMessagePtr) > g_fatal_to_g2logworker_function_ptr = pushFatalMessageToLogger;
/** The default, initial, handling to send a 'fatal' event to g2logworker
* the caller will stay here, eternally, until the software is aborted
* ... in the case of unit testing it is the given "Mock" fatalCall that will
* define the behaviour.
*/
void fatalCall(FatalMessagePtr message) {
g_fatal_to_g2logworker_function_ptr(FatalMessagePtr{std::move(message)});
}
/** REPLACE fatalCallToLogger for fatalCallForUnitTest
* This function switches the function pointer so that only
* 'unitTest' mock-fatal calls are made.
* */
void setFatalExitHandler(std::function<void(FatalMessagePtr) > fatal_call) {
g_fatal_to_g2logworker_function_ptr = fatal_call;
}
} // internal
} // g2 } // g2

4
src/g2loglevels.cpp
View File

@ -48,7 +48,7 @@ namespace g2 {
void setLogLevel(LEVELS log_level, bool enabled) { void setLogLevel(LEVELS log_level, bool enabled) {
assert(internal::g_level_size == 4 && "Mismatch between number of logging levels and their use"); assert(internal::g_level_size == 4 && "Mismatch between number of logging levels and their use");
int level = log_level.value; int level = log_level.value;
CHECK((level >= DEBUG.value) && (level <= FATAL.value)); CHECK((level >= g2::kDebugVaulue) && (level <= FATAL.value));
internal::g_log_level_status[level].store(enabled, std::memory_order_release); internal::g_log_level_status[level].store(enabled, std::memory_order_release);
} }
#endif #endif
@ -56,7 +56,7 @@ namespace g2 {
bool logLevel(LEVELS log_level) { bool logLevel(LEVELS log_level) {
#ifdef G2_DYNAMIC_LOGGING #ifdef G2_DYNAMIC_LOGGING
int level = log_level.value; int level = log_level.value;
CHECK((level >= DEBUG.value) && (level <= FATAL.value)); CHECK((level >= g2::kDebugVaulue) && (level <= FATAL.value));
bool status = (internal::g_log_level_status[level].load(std::memory_order_acquire)); bool status = (internal::g_log_level_status[level].load(std::memory_order_acquire));
return status; return status;
#endif #endif

54
src/g2loglevels.hpp
View File

@ -18,13 +18,13 @@
// the DEBUG logging level for G3log. In that case they can instead use the define // the DEBUG logging level for G3log. In that case they can instead use the define
// "CHANGE_G3LOG_DEBUG_TO_DBUG" and G3log's logging level DEBUG is changed to be DBUG // "CHANGE_G3LOG_DEBUG_TO_DBUG" and G3log's logging level DEBUG is changed to be DBUG
#if (defined(CHANGE_G3LOG_DEBUG_TO_DBUG)) #if (defined(CHANGE_G3LOG_DEBUG_TO_DBUG))
#if (defined(DBUG)) #if (defined(DBUG))
#error "DEBUG is already defined elsewhere which clashes with G3Log's log level DEBUG" #error "DEBUG is already defined elsewhere which clashes with G3Log's log level DEBUG"
#endif #endif
#else #else
#if (defined(DEBUG)) #if (defined(DEBUG))
#error "DEBUG is already defined elsewhere which clashes with G3Log's log level DEBUG" #error "DEBUG is already defined elsewhere which clashes with G3Log's log level DEBUG"
#endif #endif
#endif #endif
#include <string> #include <string>
@ -36,11 +36,13 @@ struct LEVELS {
// "dynamic, runtime loading of shared libraries" // "dynamic, runtime loading of shared libraries"
LEVELS(const LEVELS& other) LEVELS(const LEVELS& other)
: value(other.value), text(other.text.c_str()) {} : value(other.value), text(other.text.c_str()) {}
LEVELS(int id, const char* idtext) : value(id), text(idtext) {} LEVELS(int id, const char* idtext) : value(id), text(idtext) {}
friend bool operator==(const LEVELS & lhs, const LEVELS & rhs) { return (lhs.value == rhs.value && lhs.text == rhs.text); } friend bool operator==(const LEVELS& lhs, const LEVELS& rhs) {
return (lhs.value == rhs.value && lhs.text == rhs.text);
}
const int value; const int value;
const std::string text; const std::string text;
@ -48,32 +50,40 @@ struct LEVELS {
namespace g2 {
static const int kDebugVaulue = 0;
}
static const int kDebugVaulue = 0;
#if (defined(CHANGE_G3LOG_DEBUG_TO_DBUG)) #if (defined(CHANGE_G3LOG_DEBUG_TO_DBUG))
const LEVELS DBUG{kDebugVaulue, {"DEBUG"}}, const LEVELS DBUG {
g2::kDebugVaulue, {"DEBUG"}
},
#else #else
const LEVELS DEBUG{kDebugVaulue, {"DEBUG"}}, const LEVELS DEBUG {
g2::kDebugVaulue, {"DEBUG"}
},
#endif #endif
INFO{kDebugVaulue + 1, {"INFO"}}, INFO {g2::kDebugVaulue + 1, {"INFO"}},
WARNING{INFO.value + 1, {"WARNING"}}, WARNING {INFO.value + 1, {"WARNING"}},
// Insert here *any* extra logging levels that is needed // Insert here *any* extra logging levels that is needed
// 1) Remember to update the FATAL initialization below // 1) Remember to update the FATAL initialization below
// 2) Remember to update the initialization of "g2loglevels.cpp/g_log_level_status" // 2) Remember to update the initialization of "g2loglevels.cpp/g_log_level_status"
FATAL{WARNING.value + 1, {"FATAL"}}; FATAL {WARNING.value + 1, {"FATAL"}};
namespace g2 { namespace g2 {
namespace internal { namespace internal {
const LEVELS CONTRACT{100, {"CONTRACT"}}, FATAL_SIGNAL{101, {"FATAL_SIGNAL"}}, const LEVELS CONTRACT {
FATAL_EXCEPTION{102, {"FATAL_EXCEPTION"}}; 100, {"CONTRACT"}
bool wasFatal(const LEVELS& level); }, FATAL_SIGNAL {101, {"FATAL_SIGNAL"}},
} FATAL_EXCEPTION {102, {"FATAL_EXCEPTION"}};
bool wasFatal(const LEVELS& level);
}
#ifdef G2_DYNAMIC_LOGGING #ifdef G2_DYNAMIC_LOGGING
// Enable/Disable a log level {DEBUG,INFO,WARNING,FATAL} // Enable/Disable a log level {DEBUG,INFO,WARNING,FATAL}
void setLogLevel(LEVELS level, bool enabled_status); void setLogLevel(LEVELS level, bool enabled_status);
#endif #endif
bool logLevel(LEVELS level); bool logLevel(LEVELS level);
} // g2 } // g2

8
src/g2logmessagecapture.cpp
View File

@ -35,7 +35,7 @@ LogCapture::~LogCapture() {
/// Called from crash handler when a fatal signal has occurred (SIGSEGV etc) /// Called from crash handler when a fatal signal has occurred (SIGSEGV etc)
LogCapture::LogCapture(const LEVELS &level, g2::SignalType fatal_signal, const char *dump) LogCapture::LogCapture(const LEVELS &level, g2::SignalType fatal_signal, const char* dump)
: LogCapture("", 0, "", level, "", fatal_signal, dump) { : LogCapture("", 0, "", level, "", fatal_signal, dump) {
} }
@ -45,8 +45,8 @@ LogCapture::LogCapture(const LEVELS &level, g2::SignalType fatal_signal, const c
* @expression for CHECK calls * @expression for CHECK calls
* @fatal_signal for failed CHECK:SIGABRT or fatal signal caught in the signal handler * @fatal_signal for failed CHECK:SIGABRT or fatal signal caught in the signal handler
*/ */
LogCapture::LogCapture(const char *file, const int line, const char *function, const LEVELS &level, LogCapture::LogCapture(const char* file, const int line, const char* function, const LEVELS &level,
const char *expression, g2::SignalType fatal_signal, const char *dump) const char* expression, g2::SignalType fatal_signal, const char* dump)
: _file(file), _line(line), _function(function), _level(level), _expression(expression), _fatal_signal(fatal_signal) { : _file(file), _line(line), _function(function), _level(level), _expression(expression), _fatal_signal(fatal_signal) {
if (g2::internal::wasFatal(level)) { if (g2::internal::wasFatal(level)) {
@ -61,7 +61,7 @@ LogCapture::LogCapture(const char *file, const int line, const char *function, c
* capturef, used for "printf" like API in CHECKF, LOGF, LOGF_IF * capturef, used for "printf" like API in CHECKF, LOGF, LOGF_IF
* See also for the attribute formatting ref: http://www.codemaestro.com/reviews/18 * See also for the attribute formatting ref: http://www.codemaestro.com/reviews/18
*/ */
void LogCapture::capturef(const char *printf_like_message, ...) __attribute__((format(printf, 2, 3))) { void LogCapture::capturef(const char* printf_like_message, ...) __attribute__((format(printf, 2, 3))) {
static const int kMaxMessageSize = 2048; static const int kMaxMessageSize = 2048;
static const std::string kTruncatedWarningText = "[...truncated...]"; static const std::string kTruncatedWarningText = "[...truncated...]";
char finished_message[kMaxMessageSize]; char finished_message[kMaxMessageSize];

20
src/g2logmessagecapture.hpp
View File

@ -13,7 +13,7 @@
#include <csignal> #include <csignal>
#include "g2loglevels.hpp" #include "g2loglevels.hpp"
#include "g2log.hpp" #include "g2log.hpp"
#include "crashhandler.hpp" #include "crashhandler.hpp"
/** /**
* Simple struct for capturing log/fatal entries. At destruction the captured message is * Simple struct for capturing log/fatal entries. At destruction the captured message is
@ -23,7 +23,7 @@
*/ */
struct LogCapture { struct LogCapture {
/// Called from crash handler when a fatal signal has occurred (SIGSEGV etc) /// Called from crash handler when a fatal signal has occurred (SIGSEGV etc)
LogCapture(const LEVELS &level, g2::SignalType fatal_signal, const char *dump = nullptr); LogCapture(const LEVELS& level, g2::SignalType fatal_signal, const char* dump = nullptr);
/** /**
@ -32,8 +32,8 @@ struct LogCapture {
* @expression for CHECK calls * @expression for CHECK calls
* @fatal_signal for failed CHECK:SIGABRT or fatal signal caught in the signal handler * @fatal_signal for failed CHECK:SIGABRT or fatal signal caught in the signal handler
*/ */
LogCapture(const char *file, const int line, const char *function, const LEVELS &level, LogCapture(const char* file, const int line, const char* function, const LEVELS& level,
const char *expression = "", g2::SignalType fatal_signal = SIGABRT, const char *dump = nullptr); const char* expression = "", g2::SignalType fatal_signal = SIGABRT, const char* dump = nullptr);
// At destruction the message will be forwarded to the g2log worker. // At destruction the message will be forwarded to the g2log worker.
@ -49,11 +49,11 @@ struct LogCapture {
#ifndef __GNUC__ #ifndef __GNUC__
#define __attribute__(x) // Disable 'attributes' if compiler does not support 'em #define __attribute__(x) // Disable 'attributes' if compiler does not support 'em
#endif #endif
void capturef(const char *printf_like_message, ...) __attribute__((format(printf, 2, 3))); // 2,3 ref: http://www.codemaestro.com/reviews/18 void capturef(const char* printf_like_message, ...) __attribute__((format(printf, 2, 3))); // 2,3 ref: http://www.codemaestro.com/reviews/18
/// prettifying API for this completely open struct /// prettifying API for this completely open struct
std::ostringstream &stream() { std::ostringstream& stream() {
return _stream; return _stream;
} }
@ -61,11 +61,11 @@ struct LogCapture {
std::ostringstream _stream; std::ostringstream _stream;
std::string _stack_trace; std::string _stack_trace;
const char *_file; const char* _file;
const int _line; const int _line;
const char *_function; const char* _function;
const LEVELS &_level; const LEVELS& _level;
const char *_expression; const char* _expression;
const g2::SignalType _fatal_signal; const g2::SignalType _fatal_signal;
}; };

8
src/stacktrace_windows.cpp
View File

@ -60,7 +60,7 @@ const std::map<g2::SignalType, std::string> kExceptionsAsText = {
// Using the given context, fill in all the stack frames. // Using the given context, fill in all the stack frames.
// Which then later can be interpreted to human readable text // Which then later can be interpreted to human readable text
void captureStackTrace(CONTEXT *context, std::vector<uint64_t> &frame_pointers) { void captureStackTrace(CONTEXT* context, std::vector<uint64_t> &frame_pointers) {
DWORD machine_type = 0; DWORD machine_type = 0;
STACKFRAME64 frame = {}; STACKFRAME64 frame = {};
frame.AddrPC.Mode = AddrModeFlat; frame.AddrPC.Mode = AddrModeFlat;
@ -105,7 +105,7 @@ std::string getSymbolInformation(size_t index, std::vector<uint64_t> &frame_poin
DWORD64 displacement64; DWORD64 displacement64;
DWORD displacement; DWORD displacement;
char symbol_buffer[sizeof(SYMBOL_INFO) + 256]; char symbol_buffer[sizeof(SYMBOL_INFO) + 256];
SYMBOL_INFO *symbol = reinterpret_cast<SYMBOL_INFO *>(symbol_buffer); SYMBOL_INFO* symbol = reinterpret_cast<SYMBOL_INFO*>(symbol_buffer);
symbol->SizeOfStruct = sizeof(SYMBOL_INFO); symbol->SizeOfStruct = sizeof(SYMBOL_INFO);
symbol->MaxNameLen = MAX_SYM_NAME; symbol->MaxNameLen = MAX_SYM_NAME;
@ -163,14 +163,14 @@ std::string stackdump() {
} }
/// helper function: retrieve stackdump, starting from an exception pointer /// helper function: retrieve stackdump, starting from an exception pointer
std::string stackdump(EXCEPTION_POINTERS *info) { std::string stackdump(EXCEPTION_POINTERS* info) {
auto context = info->ContextRecord; auto context = info->ContextRecord;
return stackdump(context); return stackdump(context);
} }
/// main stackdump function. retrieve stackdump, from the given context /// main stackdump function. retrieve stackdump, from the given context
std::string stackdump(CONTEXT *context) { std::string stackdump(CONTEXT* context) {
stack_trace sttrace(context); // if there is a windows exception then call it like THIS stack_trace sttrace(context); // if there is a windows exception then call it like THIS
auto crashreport = sttrace.to_string(); auto crashreport = sttrace.to_string();
return crashreport; return crashreport;

244
src/working_trace.hpp
View File

@ -16,123 +16,123 @@
class sym_handler class sym_handler
{ {
public: public:
static sym_handler& get_instance() static sym_handler &get_instance()
{ {
static sym_handler instance; static sym_handler instance;
return instance; return instance;
} }
std::string get_symbol_info(DWORD64 addr) std::string get_symbol_info(DWORD64 addr)
{ {
std::stringstream ss; std::stringstream ss;
DWORD64 displacement64; DWORD64 displacement64;
DWORD displacement; DWORD displacement;
char symbol_buffer[sizeof(SYMBOL_INFO) + 256]; char symbol_buffer[sizeof(SYMBOL_INFO) + 256];
SYMBOL_INFO* symbol = reinterpret_cast<SYMBOL_INFO*>(symbol_buffer); SYMBOL_INFO* symbol = reinterpret_cast<SYMBOL_INFO*>(symbol_buffer);
symbol->SizeOfStruct = sizeof(SYMBOL_INFO); symbol->SizeOfStruct = sizeof(SYMBOL_INFO);
symbol->MaxNameLen = 255; symbol->MaxNameLen = 255;
IMAGEHLP_LINE64 line; IMAGEHLP_LINE64 line;
line.SizeOfStruct = sizeof(IMAGEHLP_LINE64); line.SizeOfStruct = sizeof(IMAGEHLP_LINE64);
// ss << addr; // ss << addr;
if (m_initialized) if (m_initialized)
{
if (SymFromAddr(GetCurrentProcess(),
addr,
&displacement64,
symbol))
{ {
ss << " " << std::string(symbol->Name, symbol->NameLen) << std::endl; if (SymFromAddr(GetCurrentProcess(),
if (SymGetLineFromAddr64(GetCurrentProcess(), addr,
addr, &displacement64,
&displacement, symbol))
&line)) {
{ ss << " " << std::string(symbol->Name, symbol->NameLen) << std::endl;
ss << "File Name:" << line.FileName << " line: " << line.LineNumber; if (SymGetLineFromAddr64(GetCurrentProcess(),
} addr,
&displacement,
&line))
{
ss << "File Name:" << line.FileName << " line: " << line.LineNumber;
}
}
else {
DWORD err = GetLastError();
}
} }
else{ return ss.str();
}
DWORD err = GetLastError(); void capture_stack_trace(CONTEXT* context, DWORD64* frame_ptrs, size_t count)
} {
} if (m_initialized)
return ss.str(); {
}
void capture_stack_trace(CONTEXT* context, DWORD64* frame_ptrs, size_t count) assert(context);
{ //CONTEXT current_context;
if (m_initialized) //// In the case of a windows exception then the context
{ //// wil be pre-set (ref: windows_exception_handler)
//// ACTUALLY ... Why can't the signal handler call
//// RtlCaptureContext.
//if (!context)
//{
// RtlCaptureContext(&current_context);
// context = &current_context;
//}
assert(context); DWORD machine_type;
//CONTEXT current_context; STACKFRAME64 frame;
//// In the case of a windows exception then the context ZeroMemory(&frame, sizeof(frame));
//// wil be pre-set (ref: windows_exception_handler) frame.AddrPC.Mode = AddrModeFlat;
//// ACTUALLY ... Why can't the signal handler call frame.AddrFrame.Mode = AddrModeFlat;
//// RtlCaptureContext. frame.AddrStack.Mode = AddrModeFlat;
//if (!context)
//{
// RtlCaptureContext(&current_context);
// context = &current_context;
//}
DWORD machine_type;
STACKFRAME64 frame;
ZeroMemory(&frame, sizeof(frame));
frame.AddrPC.Mode = AddrModeFlat;
frame.AddrFrame.Mode = AddrModeFlat;
frame.AddrStack.Mode = AddrModeFlat;
#ifdef _M_X64 #ifdef _M_X64
frame.AddrPC.Offset = context->Rip; frame.AddrPC.Offset = context->Rip;
frame.AddrFrame.Offset = context->Rbp; frame.AddrFrame.Offset = context->Rbp;
frame.AddrStack.Offset = context->Rsp; frame.AddrStack.Offset = context->Rsp;
machine_type = IMAGE_FILE_MACHINE_AMD64; machine_type = IMAGE_FILE_MACHINE_AMD64;
#else #else
frame.AddrPC.Offset = context->Eip; frame.AddrPC.Offset = context->Eip;
frame.AddrPC.Offset = context->Ebp; frame.AddrPC.Offset = context->Ebp;
frame.AddrPC.Offset = context->Esp; frame.AddrPC.Offset = context->Esp;
machine_type = IMAGE_FILE_MACHINE_I386; machine_type = IMAGE_FILE_MACHINE_I386;
#endif #endif
for (size_t i = 0; i < count; i++) for (size_t i = 0; i < count; i++)
{ {
if (StackWalk64(machine_type, if (StackWalk64(machine_type,
GetCurrentProcess(), GetCurrentProcess(),
GetCurrentThread(), GetCurrentThread(),
&frame, &frame,
context, context,
NULL, NULL,
SymFunctionTableAccess64, SymFunctionTableAccess64,
SymGetModuleBase64, SymGetModuleBase64,
NULL)) NULL))
{ {
frame_ptrs[i] = frame.AddrPC.Offset; frame_ptrs[i] = frame.AddrPC.Offset;
} }
else else
{ {
break; break;
} }
}
} }
} }
}
private: private:
sym_handler() sym_handler()
{ {
m_initialized = SymInitialize(GetCurrentProcess(), NULL, TRUE) == TRUE; m_initialized = SymInitialize(GetCurrentProcess(), NULL, TRUE) == TRUE;
} }
~sym_handler() ~sym_handler()
{ {
if (m_initialized) if (m_initialized)
{ {
SymCleanup(GetCurrentProcess()); SymCleanup(GetCurrentProcess());
m_initialized = false; m_initialized = false;
} }
} }
bool m_initialized; bool m_initialized;
}; };
@ -144,35 +144,35 @@ private:
class stack_trace class stack_trace
{ {
public: public:
stack_trace(CONTEXT* context) stack_trace(CONTEXT* context)
{ {
ZeroMemory(m_frame_ptrs, sizeof(m_frame_ptrs)); ZeroMemory(m_frame_ptrs, sizeof(m_frame_ptrs));
sym_handler::get_instance().capture_stack_trace(context, sym_handler::get_instance().capture_stack_trace(context,
m_frame_ptrs, m_frame_ptrs,
max_frame_ptrs); max_frame_ptrs);
} }
std::string to_string() const std::string to_string() const
{ {
std::stringstream ss; std::stringstream ss;
for (size_t i = 0; for (size_t i = 0;
i < max_frame_ptrs && m_frame_ptrs[i]; i < max_frame_ptrs && m_frame_ptrs[i];
++i) ++i)
{ {
ss << sym_handler::get_instance().get_symbol_info(m_frame_ptrs[i]) << "\n"; ss << sym_handler::get_instance().get_symbol_info(m_frame_ptrs[i]) << "\n";
} }
return ss.str(); return ss.str();
} }
private: private:
static const size_t max_frame_ptrs = 16; static const size_t max_frame_ptrs = 16;
DWORD64 m_frame_ptrs[max_frame_ptrs]; DWORD64 m_frame_ptrs[max_frame_ptrs];
}; };
inline std::string to_string(const stack_trace& trace) inline std::string to_string(const stack_trace &trace)
{ {
return trace.to_string(); return trace.to_string();
} }

252
test_performance/main_threaded_worst.cpp
View File

@ -16,18 +16,26 @@
#include <cmath> #include <cmath>
#if defined(G2LOG_PERFORMANCE) #if defined(G2LOG_PERFORMANCE)
const std::string title{"G2LOG"}; const std::string title {
"G2LOG"
};
#elif defined(GOOGLE_GLOG_PERFORMANCE) #elif defined(GOOGLE_GLOG_PERFORMANCE)
const std::string title{"GOOGLE__GLOG"}; const std::string title {
"GOOGLE__GLOG"
};
#else #else
#error G2LOG_PERFORMANCE or GOOGLE_GLOG_PERFORMANCE was not defined #error G2LOG_PERFORMANCE or GOOGLE_GLOG_PERFORMANCE was not defined
#endif #endif
#if (defined(WIN32) || defined(_WIN32) || defined(__WIN32__)) #if (defined(WIN32) || defined(_WIN32) || defined(__WIN32__))
const std::string g_path{"./"}; const std::string g_path {
"./"
};
#else #else
const std::string g_path{"/tmp/"}; const std::string g_path {
"/tmp/"
};
#endif #endif
@ -41,147 +49,153 @@ using namespace g2_test;
// //
int main(int argc, char** argv) int main(int argc, char** argv)
{ {
size_t number_of_threads{0}; size_t number_of_threads {0};
if(argc == 2) if (argc == 2)
{ {
number_of_threads = atoi(argv[1]); number_of_threads = atoi(argv[1]);
} }
if(argc != 2 || number_of_threads == 0) if (argc != 2 || number_of_threads == 0)
{ {
std::cerr << "USAGE is: " << argv[0] << " number_threads" << std::endl; std::cerr << "USAGE is: " << argv[0] << " number_threads" << std::endl;
return 1; return 1;
} }
std::ostringstream thread_count_oss; std::ostringstream thread_count_oss;
thread_count_oss << number_of_threads; thread_count_oss << number_of_threads;
const std::string g_prefix_log_name = title + "-performance-" + thread_count_oss.str() + "threads-WORST_LOG"; const std::string g_prefix_log_name = title + "-performance-" + thread_count_oss.str() + "threads-WORST_LOG";
const std::string g_measurement_dump= g_path + g_prefix_log_name + "_RESULT.txt"; const std::string g_measurement_dump = g_path + g_prefix_log_name + "_RESULT.txt";
const std::string g_measurement_bucket_dump= g_path + g_prefix_log_name + "_RESULT_buckets.txt"; const std::string g_measurement_bucket_dump = g_path + g_prefix_log_name + "_RESULT_buckets.txt";
const uint64_t us_to_ms{1000}; const uint64_t us_to_ms {
const uint64_t us_to_s{1000000}; 1000
};
const uint64_t us_to_s {
1000000
};
std::ostringstream oss; std::ostringstream oss;
oss << "\n\n" << title << " performance " << number_of_threads << " threads WORST (PEAK) times\n"; oss << "\n\n" << title << " performance " << number_of_threads << " threads WORST (PEAK) times\n";
oss << "Each thread running #: " << g_loop << " * " << g_iterations << " iterations of log entries" << std::endl; // worst mean case is about 10us per log entry oss << "Each thread running #: " << g_loop << " * " << g_iterations << " iterations of log entries" << std::endl; // worst mean case is about 10us per log entry
const uint64_t xtra_margin{2}; const uint64_t xtra_margin {
oss << "*** It can take som time. Please wait: Approximate wait time on MY PC was: " << number_of_threads * (uint64_t)(g_iterations * 10 * xtra_margin / us_to_s) << " seconds" << std::endl; 2
writeTextToFile(g_measurement_dump, oss.str(), kAppend); };
oss.str(""); // clear the stream oss << "*** It can take som time. Please wait: Approximate wait time on MY PC was: " << number_of_threads * (uint64_t)(g_iterations * 10 * xtra_margin / us_to_s) << " seconds" << std::endl;
writeTextToFile(g_measurement_dump, oss.str(), kAppend);
oss.str(""); // clear the stream
#if defined(G2LOG_PERFORMANCE) #if defined(G2LOG_PERFORMANCE)
auto logger_n_handle = g2::LogWorker::createWithDefaultLogger(g_prefix_log_name, g_path); auto logger_n_handle = g2::LogWorker::createWithDefaultLogger(g_prefix_log_name, g_path);
g2::initializeLogging(logger_n_handle.worker.get()); g2::initializeLogging(logger_n_handle.worker.get());
#elif defined(GOOGLE_GLOG_PERFORMANCE) #elif defined(GOOGLE_GLOG_PERFORMANCE)
google::InitGoogleLogging(argv[0]); google::InitGoogleLogging(argv[0]);
#endif #endif
std::thread* threads = new std::thread[number_of_threads]; std::thread* threads = new std::thread[number_of_threads];
std::vector<uint64_t>* threads_result = new std::vector<uint64_t>[number_of_threads]; std::vector<uint64_t>* threads_result = new std::vector<uint64_t>[number_of_threads];
// kiss: just loop, create threads, store them then join // kiss: just loop, create threads, store them then join
// could probably do this more elegant with lambdas // could probably do this more elegant with lambdas
for(uint64_t idx = 0; idx < number_of_threads; ++idx) for (uint64_t idx = 0; idx < number_of_threads; ++idx)
{ {
threads_result[idx].reserve(g_iterations); threads_result[idx].reserve(g_iterations);
} }
auto start_time = std::chrono::high_resolution_clock::now(); auto start_time = std::chrono::high_resolution_clock::now();
for(uint64_t idx = 0; idx < number_of_threads; ++idx) for (uint64_t idx = 0; idx < number_of_threads; ++idx)
{ {
std::ostringstream count; std::ostringstream count;
count << idx+1; count << idx + 1;
std::string thread_name = title + "_T" + count.str(); std::string thread_name = title + "_T" + count.str();
std::cout << "Creating thread: " << thread_name << std::endl; std::cout << "Creating thread: " << thread_name << std::endl;
threads[idx] = std::thread(measurePeakDuringLogWrites,thread_name, std::ref(threads_result[idx])); threads[idx] = std::thread(measurePeakDuringLogWrites, thread_name, std::ref(threads_result[idx]));
} }
// wait for thread finishing // wait for thread finishing
for(uint64_t idx = 0; idx < number_of_threads; ++idx) for (uint64_t idx = 0; idx < number_of_threads; ++idx)
{ {
threads[idx].join(); threads[idx].join();
} }
auto application_end_time = std::chrono::high_resolution_clock::now(); auto application_end_time = std::chrono::high_resolution_clock::now();
delete [] threads; delete [] threads;
#if defined(G2LOG_PERFORMANCE) #if defined(G2LOG_PERFORMANCE)
logger_n_handle.worker.reset(); // will flush anything in the queue to file logger_n_handle.worker.reset(); // will flush anything in the queue to file
#elif defined(GOOGLE_GLOG_PERFORMANCE) #elif defined(GOOGLE_GLOG_PERFORMANCE)
google::ShutdownGoogleLogging(); google::ShutdownGoogleLogging();
#endif #endif
auto worker_end_time = std::chrono::high_resolution_clock::now(); auto worker_end_time = std::chrono::high_resolution_clock::now();
uint64_t application_time_us = std::chrono::duration_cast<microsecond>(application_end_time - start_time).count(); uint64_t application_time_us = std::chrono::duration_cast<microsecond>(application_end_time - start_time).count();
uint64_t total_time_us = std::chrono::duration_cast<microsecond>(worker_end_time - start_time).count(); uint64_t total_time_us = std::chrono::duration_cast<microsecond>(worker_end_time - start_time).count();
oss << "\n" << number_of_threads << "*" << g_iterations << " log entries took: [" << total_time_us / us_to_s << " s] to write to disk" << std::endl; oss << "\n" << number_of_threads << "*" << g_iterations << " log entries took: [" << total_time_us / us_to_s << " s] to write to disk" << std::endl;
oss << "[Application(" << number_of_threads << "_threads+overhead time for measurement):\t" << application_time_us/us_to_ms << " ms]" << std::endl; oss << "[Application(" << number_of_threads << "_threads+overhead time for measurement):\t" << application_time_us / us_to_ms << " ms]" << std::endl;
oss << "[Background thread to finish:\t\t\t\t" << total_time_us/us_to_ms << " ms]" << std::endl; oss << "[Background thread to finish:\t\t\t\t" << total_time_us / us_to_ms << " ms]" << std::endl;
oss << "\nAverage time per log entry:" << std::endl; oss << "\nAverage time per log entry:" << std::endl;
oss << "[Application: " << application_time_us/(number_of_threads*g_iterations) << " us]" << std::endl; oss << "[Application: " << application_time_us / (number_of_threads * g_iterations) << " us]" << std::endl;
for(uint64_t idx = 0; idx < number_of_threads; ++idx) for (uint64_t idx = 0; idx < number_of_threads; ++idx)
{ {
std::vector<uint64_t>& t_result = threads_result[idx]; std::vector<uint64_t> &t_result = threads_result[idx];
uint64_t worstUs = (*std::max_element(t_result.begin(), t_result.end())); uint64_t worstUs = (*std::max_element(t_result.begin(), t_result.end()));
oss << "[Application t" << idx+1 << " worst took: " << worstUs / uint64_t(1000) << " ms (" << worstUs << " us)] " << std::endl; oss << "[Application t" << idx + 1 << " worst took: " << worstUs / uint64_t(1000) << " ms (" << worstUs << " us)] " << std::endl;
} }
writeTextToFile(g_measurement_dump,oss.str(), kAppend); writeTextToFile(g_measurement_dump, oss.str(), kAppend);
std::cout << "Result can be found at:" << g_measurement_dump << std::endl; std::cout << "Result can be found at:" << g_measurement_dump << std::endl;
// now split the result in buckets of 10ms each so that it's obvious how the peaks go // now split the result in buckets of 10ms each so that it's obvious how the peaks go
std::vector<uint64_t> all_measurements; std::vector<uint64_t> all_measurements;
all_measurements.reserve(g_iterations * number_of_threads); all_measurements.reserve(g_iterations * number_of_threads);
for(uint64_t idx = 0; idx < number_of_threads; ++idx) for (uint64_t idx = 0; idx < number_of_threads; ++idx)
{ {
std::vector<uint64_t>& t_result = threads_result[idx]; std::vector<uint64_t> &t_result = threads_result[idx];
all_measurements.insert(all_measurements.end(), t_result.begin(), t_result.end()); all_measurements.insert(all_measurements.end(), t_result.begin(), t_result.end());
} }
delete [] threads_result; // finally get rid of them delete [] threads_result; // finally get rid of them
std::sort (all_measurements.begin(), all_measurements.end()); std::sort (all_measurements.begin(), all_measurements.end());
std::map<uint64_t, uint64_t> value_amounts; std::map<uint64_t, uint64_t> value_amounts;
std::map<uint64_t, uint64_t> value_amounts_for_0ms_bucket; std::map<uint64_t, uint64_t> value_amounts_for_0ms_bucket;
for(auto iter = all_measurements.begin(); iter != all_measurements.end(); ++iter) for (auto iter = all_measurements.begin(); iter != all_measurements.end(); ++iter)
{ {
uint64_t value = (*iter)/us_to_ms; // convert to ms uint64_t value = (*iter) / us_to_ms; // convert to ms
++value_amounts[value]; // asuming uint64_t is default 0 when initialized ++value_amounts[value]; // asuming uint64_t is default 0 when initialized
if(0 == value) { if (0 == value) {
++value_amounts_for_0ms_bucket[*iter]; ++value_amounts_for_0ms_bucket[*iter];
} }
} }
oss.str(""); oss.str("");
oss << "Number of values rounded to milliseconds and put to [millisecond bucket] were dumped to file: " << g_measurement_bucket_dump << std::endl; oss << "Number of values rounded to milliseconds and put to [millisecond bucket] were dumped to file: " << g_measurement_bucket_dump << std::endl;
if(1 == value_amounts.size()) { if (1 == value_amounts.size()) {
oss << "Format: bucket of us inside bucket0 for ms\nFormat:bucket_of_ms, number_of_values_in_bucket\n\n" << std::endl; oss << "Format: bucket of us inside bucket0 for ms\nFormat:bucket_of_ms, number_of_values_in_bucket\n\n" << std::endl;
oss << "\n"; oss << "\n";
} }
else { else {
oss << "Format:bucket_of_ms, number_of_values_in_bucket\n\n" << std::endl; oss << "Format:bucket_of_ms, number_of_values_in_bucket\n\n" << std::endl;
} }
std::cout << oss.str() << std::endl; std::cout << oss.str() << std::endl;
// //
// If all values are for the 0ms bucket then instead show us buckets // If all values are for the 0ms bucket then instead show us buckets
// //
if(1 == value_amounts.size()) { if (1 == value_amounts.size()) {
oss << "\n\n***** Microsecond bucket measurement for all measurements that went inside the '0 millisecond bucket' ****\n"; oss << "\n\n***** Microsecond bucket measurement for all measurements that went inside the '0 millisecond bucket' ****\n";
for(auto us_bucket: value_amounts_for_0ms_bucket) { for (auto us_bucket : value_amounts_for_0ms_bucket) {
oss << us_bucket.first << "\t" << us_bucket.second << std::endl; oss << us_bucket.first << "\t" << us_bucket.second << std::endl;
} }
oss << "\n\n***** Millisecond bucket measurement ****\n"; oss << "\n\n***** Millisecond bucket measurement ****\n";
} }
for(auto ms_bucket: value_amounts) for (auto ms_bucket : value_amounts)
{ {
oss << ms_bucket.first << "\t, " << ms_bucket.second << std::endl; oss << ms_bucket.first << "\t, " << ms_bucket.second << std::endl;
} }
writeTextToFile(g_measurement_bucket_dump,oss.str(), kAppend, false); writeTextToFile(g_measurement_bucket_dump, oss.str(), kAppend, false);
return 0; return 0;
} }