diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml
index ba27f6da08d3d2bbc3dc5a5add6d432e09b9cf13..cc612eb9459b81e5be3501e20bafd92ea23d3dc3 100644
--- a/.gitlab-ci.yml
+++ b/.gitlab-ci.yml
@@ -267,3 +267,8 @@ test-set-affinity-on-block:
extends:
- .test
- .set-affinity-on-block
+
+test-mmapped-log:
+ extends:
+ - .meson-test
+ script: make && EMPER_LOG_FILE=emper.log make test
diff --git a/emper/Debug.hpp b/emper/Debug.hpp
index 507399fc96c6fa6441330b1eb4042123e08091cd..6520cf6c7fd322ab8f2683e19b85496f626b3701 100644
--- a/emper/Debug.hpp
+++ b/emper/Debug.hpp
@@ -2,11 +2,14 @@
// Copyright © 2020-2021 Florian Schmaus, Florian Fischer
#pragma once
+#include <atomic>
+#include <cstddef>
#include <sstream> // IWYU pragma: keep
#include <string>
#include <string_view>
#include "emper-config.h"
+#include "log/log.hpp"
// If we apply clang-format to the following region, then clang-format
// will create multi-line macros. However clang-tidy's NOLINTNEXTLINE
@@ -24,7 +27,7 @@
#define LOG(level, x, log_func) do { if constexpr (level <= EMPER_LOG_LEVEL) { log_func(EMPER_BUILD_STR(x)); } } while (false)
// NOLINTNEXTLINE(bugprone-macro-parentheses)
-#define DBG(x) LOG(Debug, x, emper_log_no_prefix);
+#define DBG(x) LOG(Debug, x, emper::log::log_no_prefix);
// To avoid "error: there are no arguments to ‘logD’ that depend on a
// template parameter, so a declaration of ‘logD’ must be available"
@@ -35,19 +38,19 @@
#define LOGDD(x) LOG(FineDebug, x, this->logDD);
// NOLINTNEXTLINE(bugprone-macro-parentheses)
-#define LOGI(x) LOG(Info, "Info: " << x, emper_log_no_prefix);
+#define LOGI(x) LOG(Info, "Info: " << x, emper::log::log_no_prefix);
// NOLINTNEXTLINE(bugprone-macro-parentheses)
#define LOGGER_LOGI(x) LOG(Info, "Info: " << x, this->logI);
// NOLINTNEXTLINE(bugprone-macro-parentheses)
-#define LOGW(x) LOG(Warning, "Warning: " << x, emper_log_no_prefix);
+#define LOGW(x) LOG(Warning, "Warning: " << x, emper::log::log_no_prefix);
// NOLINTNEXTLINE(bugprone-macro-parentheses)
#define LOGGER_LOGW(x) LOG(Warning, "Warning: " << x, this->logW);
// NOLINTNEXTLINE(bugprone-macro-parentheses)
-#define LOGE(x) LOG(Error, "Error: " << x, emper_log_no_prefix);
+#define LOGE(x) LOG(Error, "Error: " << x, emper::log::log_no_prefix);
// NOLINTNEXTLINE(bugprone-macro-parentheses)
-#define LOGGER_LOGE(x) LOG(Error, "Error: " << x, emper_log_no_prefix);
+#define LOGGER_LOGE(x) LOG(Error, "Error: " << x, emper::log::log_no_prefix);
// NOLINTNEXTLINE(bugprone-macro-parentheses)
#define ABORT(x) { LOGE(x); abort(); }
@@ -92,12 +95,6 @@ enum LogLevel {
ALL,
};
-void emper_add_timestamp_to(std::ostringstream& logMessage);
-
-void emper_log(const std::string& prefix, const std::string& message);
-
-static inline void emper_log_no_prefix(const std::string& message) { emper_log("", message); }
-
template <LogSubsystem logSubsystem>
class Logger {
private:
@@ -171,7 +168,7 @@ class Logger {
sst << " " << this;
}
- emper_log(sst.str(), string);
+ emper::log::log(sst.str(), string);
}
inline void logE(const std::string& string) const { log<Error>(string); }
diff --git a/emper/Runtime.cpp b/emper/Runtime.cpp
index 0ca865bd2ddf2f4ce463cda408feb25876a4747f..4ea9687c5664d500523f86ea0f7152e0976d284a 100644
--- a/emper/Runtime.cpp
+++ b/emper/Runtime.cpp
@@ -33,6 +33,7 @@
#include "io/IoContext.hpp"
#include "io/Stats.hpp"
#include "lib/DebugUtil.hpp"
+#include "log/LogBuffer.hpp"
#include "stats/FromAnywhere.hpp"
#include "stats/Worker.hpp"
#include "strategies/AbstractWorkStealingScheduler.hpp"
@@ -95,6 +96,11 @@ Runtime::Runtime(workerid_t workerCount, RuntimeStrategyFactory& strategyFactory
currentRuntime = this;
}
+ const char* envValueLogFile = std::getenv("EMPER_LOG_FILE");
+ if (envValueLogFile) {
+ logBuffer = new emper::log::LogBuffer(envValueLogFile);
+ }
+
if constexpr (emper::STATS) {
workerStats = new WorkerLocalData<emper::stats::Worker>(
[workerCount] {
@@ -227,12 +233,15 @@ Runtime::~Runtime() {
delete fromAnywhereStats;
}
+ DBG("Runtime " << this << " terminated");
+
// TODO: Move this before the delete invocations?
{
std::lock_guard<std::mutex> lock(currentRuntimeMutex);
currentRuntime = nullptr;
}
- DBG("Runtime " << this << " terminated");
+
+ delete logBuffer;
}
auto Runtime::workerLoop(Worker* worker) -> void* {
diff --git a/emper/Runtime.hpp b/emper/Runtime.hpp
index efe1cbe8178a330ae79d74ab3cfad7ca8ffd1c2e..c9f71733893a3cc77818da15daa23b8cd38908dd 100644
--- a/emper/Runtime.hpp
+++ b/emper/Runtime.hpp
@@ -44,6 +44,9 @@ namespace io {
class GlobalIoContext;
class IoContext;
} // namespace io
+namespace log {
+class LogBuffer;
+}
namespace stats {
class Worker;
class FromAnywhere;
@@ -89,6 +92,8 @@ class Runtime : public Logger<LogSubsystem::RUNTI> {
WorkerLocalData<emper::stats::Worker>* workerStats;
emper::stats::FromAnywhere* fromAnywhereStats;
+ emper::log::LogBuffer* logBuffer = nullptr;
+
auto workerLoop(Worker* worker) -> void*;
WorkerSleepStrategy workerSleepStrategy;
@@ -210,5 +215,5 @@ class Runtime : public Logger<LogSubsystem::RUNTI> {
template <typename>
friend class WorkerLocalData;
- friend void emper_log(const std::string& prefix, const std::string& message);
+ friend void emper::log::log(const std::string& prefix, const std::string& message);
};
diff --git a/emper/io/GlobalIoContext.hpp b/emper/io/GlobalIoContext.hpp
index 862c944afba565523c84cd42af41f9d1b29ff99d..611793f2a34e9f1861420a346d4d090d59c50e8f 100644
--- a/emper/io/GlobalIoContext.hpp
+++ b/emper/io/GlobalIoContext.hpp
@@ -15,7 +15,7 @@ class Runtime;
namespace emper::io {
class GlobalIoContext : public IoContext {
friend Runtime;
- friend void ::emper_log(const std::string& prefix, const std::string& message);
+ friend void emper::log::log(const std::string& prefix, const std::string& message);
friend class Future;
friend class SendFuture;
friend class RecvFuture;
diff --git a/emper/log/LogBuffer.cpp b/emper/log/LogBuffer.cpp
new file mode 100644
index 0000000000000000000000000000000000000000..790abb9b51208d22621bbac232bb9c01e45e8a6d
--- /dev/null
+++ b/emper/log/LogBuffer.cpp
@@ -0,0 +1,124 @@
+// SPDX-License-Identifier: LGPL-3.0-or-later
+// Copyright © 2020 Florian Schmaus
+#include "LogBuffer.hpp"
+
+#include <fcntl.h>
+#include <sys/mman.h>
+#include <sys/stat.h>
+#include <unistd.h>
+
+#include <cstring>
+#include <ostream>
+
+#include "Common.hpp"
+
+namespace emper::log {
+
+LogBuffer::LogBuffer(const std::string& logFile) : logFile(logFile) {
+ logFd = open(logFile.c_str(), O_RDWR | O_TRUNC | O_CREAT, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
+ if (logFd == -1) {
+ DIE_MSG_ERRNO("opening log file " << logFile << " failed");
+ }
+
+ for (size_t i = 0; i < BUFFER_COUNT; ++i) {
+ const auto off = static_cast<off_t>(i * BUFFER_SIZE);
+ void* res = mmap(nullptr, BUFFER_SIZE, PROT_WRITE, MAP_FILE | MAP_SHARED, logFd, off);
+ // NOLINTNEXTLINE(performance-no-int-to-ptr)
+ if (res == MAP_FAILED) {
+ DIE_MSG_ERRNO("mmap failed");
+ }
+ bufs[i] = static_cast<char*>(res);
+ }
+
+ if (ftruncate(logFd, BUFFER_COUNT * BUFFER_SIZE)) {
+ DIE_MSG_ERRNO("initial log file " << logFile << "truncation failed");
+ }
+}
+
+LogBuffer::~LogBuffer() {
+ auto finalPos = static_cast<off_t>(bufPos.load(std::memory_order_relaxed));
+ if (ftruncate(logFd, finalPos)) {
+ DIE_MSG_ERRNO("trimming log file " << logFile << " failed");
+ }
+
+ for (auto* buf : bufs) {
+ if (munmap(buf, BUFFER_SIZE)) {
+ DIE_MSG_ERRNO("munmap failed");
+ }
+ }
+
+ close(logFd);
+}
+
+void LogBuffer::log(const std::string& message) {
+ const size_t messageLen = message.size();
+ const size_t startPos = bufPos.fetch_add(messageLen, std::memory_order_relaxed);
+ const size_t endPos = startPos + messageLen - 1;
+ char* buf = getBuf(startPos);
+ const size_t bufOffset = startPos % BUFFER_SIZE;
+ char* msgEndBuf = getBuf(endPos);
+
+ // The message fits completly into the current buffer
+ if (buf == msgEndBuf) {
+ // NOLINTNEXTLINE(bugprone-not-null-terminated-result)
+ memcpy(&buf[bufOffset], message.c_str(), message.size());
+
+ // Are we still in the active buffer?
+ if (bufOffset > 0) {
+ return;
+ }
+ // The message spans the active and the next buffer
+ } else {
+ const size_t leftInActive = BUFFER_SIZE - (startPos % BUFFER_SIZE);
+ // NOLINTNEXTLINE(bugprone-not-null-terminated-result)
+ memcpy(&buf[bufOffset], message.c_str(), leftInActive);
+ // NOLINTNEXTLINE(bugprone-not-null-terminated-result)
+ memcpy(&msgEndBuf[0], &message.c_str()[leftInActive], message.size() - leftInActive);
+ }
+
+ // This is the first overflow there is no old buffer to remap
+ if (bufPos < BUFFER_SIZE * 2) {
+ return;
+ }
+
+ // We are the first writing to the next buffer therefore we are responsible
+ // to remap the old.
+
+ // NOTE: This is NOT sound it is possible that other threads are still using the old
+ // buffer. But with big enough BUFFER_SIZE it is likely that all threads are using
+ // the current active buffer
+
+ // Active buffer -> old buffer
+ // Fresh buffer -> active buffer
+ // Remap old buffer -> next fresh buffer
+
+ // Remap the old buffer
+ const size_t oldBufIdx = ((startPos / BUFFER_SIZE) - 1) % BUFFER_COUNT;
+ char* oldBufPtr = bufs[oldBufIdx];
+
+ // The buffer [0, BUFFER_SIZE) is the first active buffer
+ // Therefore at bufPos = BUFFER_SIZE + 1 we are in the second active buffer
+ const size_t nthActive = (endPos / BUFFER_SIZE) + 1;
+
+ // Our log file has the size of all ever active buffers plus the new fresh one
+ const auto logFileSize = static_cast<off_t>((nthActive + 1) * BUFFER_SIZE);
+
+ // Grow the log file
+ if (ftruncate(logFd, logFileSize)) {
+ DIE_MSG_ERRNO("growing log file " << logFile << " failed");
+ }
+
+ const auto nextOffset = static_cast<off_t>(nthActive * BUFFER_SIZE);
+ void* res = mmap(nullptr, BUFFER_SIZE, PROT_WRITE, MAP_FILE | MAP_SHARED, logFd, nextOffset);
+ // NOLINTNEXTLINE(performance-no-int-to-ptr)
+ if (res == MAP_FAILED) {
+ DIE_MSG_ERRNO("mmap of fresh buffer failed");
+ }
+ bufs[oldBufIdx] = static_cast<char*>(res);
+
+ if (munmap(oldBufPtr, BUFFER_SIZE)) {
+ DIE_MSG_ERRNO("munmap of replaced buffer failed");
+ }
+}
+
+} // namespace emper::log
diff --git a/emper/log/LogBuffer.hpp b/emper/log/LogBuffer.hpp
new file mode 100644
index 0000000000000000000000000000000000000000..8518b2c8fd6b091e25edb50a36e508fee62abb0f
--- /dev/null
+++ b/emper/log/LogBuffer.hpp
@@ -0,0 +1,31 @@
+// SPDX-License-Identifier: LGPL-3.0-or-later
+// Copyright © 2021 Florian Fischer
+#pragma once
+
+#include <atomic>
+#include <cstddef>
+#include <string>
+
+namespace emper::log {
+class LogBuffer {
+ // We use a triple buffer scheme, where one buffer is active, one is old and one is fresh
+ // The old buffer gets remapped by the first accessing the fresh buffer
+ static const int BUFFER_COUNT = 3;
+ static const size_t BUFFER_SIZE = 1 << 20;
+
+ char* bufs[BUFFER_COUNT];
+
+ std::atomic<size_t> bufPos = 0;
+
+ std::string logFile;
+ int logFd;
+
+ auto getBuf(size_t pos) -> char* { return bufs[(pos / BUFFER_SIZE) % BUFFER_COUNT]; }
+
+ public:
+ LogBuffer(const std::string& logFile);
+ ~LogBuffer();
+
+ void log(const std::string& message);
+};
+} // namespace emper::log
diff --git a/emper/Debug.cpp b/emper/log/log.cpp
similarity index 76%
rename from emper/Debug.cpp
rename to emper/log/log.cpp
index 953fef6ffe30d92cc77752cf203c0d953803b288..97898272f18f4bfcadf8ec7ababcf5f104d85d1f 100644
--- a/emper/Debug.cpp
+++ b/emper/log/log.cpp
@@ -1,6 +1,7 @@
// SPDX-License-Identifier: LGPL-3.0-or-later
// Copyright © 2020 Florian Schmaus
-#include "Debug.hpp"
+// Copyright © 2021 Florian Fischer
+#include "log.hpp"
#include <pthread.h>
@@ -15,14 +16,14 @@
#include "Runtime.hpp"
#include "Worker.hpp"
#include "emper-common.h" // for workerid_t
-#include "emper-config.h" // for EMPER_LOG_LEVEL
#include "io/GlobalIoContext.hpp"
+#include "log/LogBuffer.hpp"
using emper::io::GlobalIoContext;
-static std::mutex emper_log_mutex;
+namespace emper::log {
-void emper_add_timestamp_to(std::ostringstream& logMessage) {
+static void add_timestamp_to(std::ostringstream& logMessage) {
auto now = std::chrono::high_resolution_clock::now();
auto now_time_t = std::chrono::high_resolution_clock::to_time_t(now);
@@ -37,7 +38,10 @@ void emper_add_timestamp_to(std::ostringstream& logMessage) {
logMessage << remaining_nanos;
}
-void emper_log(const std::string& prefix, const std::string& message) {
+static std::mutex log_mutex;
+
+void log(const std::string& prefix, const std::string& message) {
+ Runtime* runtime = Runtime::getRuntime();
Worker* worker = Worker::getCurrentWorker();
std::ostringstream logMessage;
if (likely(worker)) {
@@ -46,7 +50,6 @@ void emper_log(const std::string& prefix, const std::string& message) {
logMessage << std::setfill('0') << std::setw(3) << workerIdAsString << " ";
} else {
// Are we the global IO completer
- Runtime* runtime = Runtime::getRuntime();
GlobalIoContext* gio = runtime ? runtime->globalIo : nullptr;
if (gio && pthread_self() == gio->completer) {
logMessage << "IOC ";
@@ -56,7 +59,7 @@ void emper_log(const std::string& prefix, const std::string& message) {
}
if constexpr (emper::LOG_TIMESTAMP) {
- emper_add_timestamp_to(logMessage);
+ add_timestamp_to(logMessage);
}
if (!prefix.empty()) {
@@ -67,11 +70,11 @@ void emper_log(const std::string& prefix, const std::string& message) {
logMessage << message << std::endl;
- std::unique_lock<std::mutex> lock(emper_log_mutex);
- std::cerr << logMessage.str();
-}
-
-// global log_level which can be changed to control the log output
-namespace emper {
-enum LogLevel log_level = EMPER_LOG_LEVEL;
+ if (likely(runtime) && runtime->logBuffer) {
+ runtime->logBuffer->log(logMessage.str());
+ } else {
+ std::unique_lock<std::mutex> lock(log_mutex);
+ std::cerr << logMessage.str();
+ }
}
+} // namespace emper::log
diff --git a/emper/log/log.hpp b/emper/log/log.hpp
new file mode 100644
index 0000000000000000000000000000000000000000..9bab9ca259b09ef1f5e50073efb7b622740a6151
--- /dev/null
+++ b/emper/log/log.hpp
@@ -0,0 +1,11 @@
+// SPDX-License-Identifier: LGPL-3.0-or-later
+// Copyright © 2020-2021 Florian Schmaus, Florian Fischer
+#pragma once
+
+#include <string>
+
+namespace emper::log {
+void log(const std::string& prefix, const std::string& message);
+
+static inline void log_no_prefix(const std::string& message) { log("", message); }
+} // namespace emper::log
diff --git a/emper/log/meson.build b/emper/log/meson.build
new file mode 100644
index 0000000000000000000000000000000000000000..6de1e134d89b7135ad80df2700b20a05a368eac7
--- /dev/null
+++ b/emper/log/meson.build
@@ -0,0 +1,4 @@
+emper_cpp_sources += files(
+ 'log.cpp',
+ 'LogBuffer.cpp',
+)
diff --git a/emper/meson.build b/emper/meson.build
index 5e827d84a94854a66dc5a45437c101080a7c237d..e5b942b972dc96bf175fd3ad34e7d5e9a2c151e7 100644
--- a/emper/meson.build
+++ b/emper/meson.build
@@ -21,7 +21,6 @@ emper_cpp_sources = [
'Scheduler.cpp',
'Dispatcher.cpp',
'Common.cpp',
- 'Debug.cpp',
'ContextManager.cpp',
'BinaryPrivateSemaphore.cpp',
'CountingPrivateSemaphore.cpp',
@@ -39,6 +38,7 @@ emper_library_include += include_directories('.')
subdir('io')
subdir('lib')
+subdir('log')
subdir('stats')
subdir('strategies')
subdir('sleep_strategy')