Skip to content
Commits on Source (2)
Show whitespace changes
Inline Side-by-side
include/client/preload.hpp
View file @ 7b92d158
......@@ -46,6 +46,7 @@
#define EUNKNOWN (-1)
#define CTX gkfs::preload::PreloadContext::getInstance()
#define DT gkfs::preload::DebugTimer::getInstance()
namespace gkfs::preload {
void
init_environment();
......
include/client/preload_context.hpp
View file @ 7b92d158
......@@ -50,6 +50,14 @@
#include <bitset>
// Debug timer
#include <chrono>
#include <unordered_map>
#include <string>
#include <mutex>
extern char *program_invocation_name;
// ---------
/* Forward declarations */
namespace gkfs {
namespace filemap {
......@@ -75,6 +83,43 @@ class WriteSizeCache;
} // namespace cache
namespace preload {
// Debug timer
class DebugTimer {
public:
static DebugTimer&
getInstance() {
static DebugTimer instance;
return instance;
}
void
record(const std::string& name);
void
write_stats(const std::string& file);
private:
struct Stat {
std::chrono::high_resolution_clock::time_point lastTime{};
int callCount = 0;
double maxDuration = 0.0;
double totalDuration = 0.0;
};
std::chrono::high_resolution_clock::time_point start_time{};
std::unordered_map<std::string, Stat> stats_;
mutable std::mutex mutex_;
// Private constructor to enforce singleton
DebugTimer();
~DebugTimer() = default;
DebugTimer(const DebugTimer&) = delete;
DebugTimer&
operator=(const DebugTimer&) = delete;
};
// ---------
/*
* Client file system config
*/
......
src/client/gkfs_libc.cpp
View file @ 7b92d158
......@@ -580,7 +580,9 @@ is_gkfs_fd(int fd) {
#define GKFS_OPERATION(name, ...) \
if(CTX->interception_enabled() && is_gkfs_fd(fd)) { \
\
DT.record(#name); \
auto res = gkfs::syscall::gkfs_##name(__VA_ARGS__); \
DT.record(#name); \
DEBUG_INFO("[GKFS] {} -> res {}", fd, res); \
return res; \
}
......@@ -589,9 +591,13 @@ is_gkfs_fd(int fd) {
if(CTX->interception_enabled()) { \
std::string resolved; \
switch(resolve_gkfs_path(dirfd, path, resolved)) { \
case PathStatus::Internal: \
case PathStatus::Internal: { \
DEBUG_INFO("[GKFS] {}", resolved); \
return gkfs::syscall::gkfs_##name(resolved, __VA_ARGS__); \
DT.record(#name); \
auto res = gkfs::syscall::gkfs_##name(resolved, __VA_ARGS__); \
DT.record(#name); \
return res; \
} \
case PathStatus::Error: \
return -1; \
default: \
......@@ -603,10 +609,14 @@ is_gkfs_fd(int fd) {
if(CTX->interception_enabled()) { \
std::string resolved; \
switch(resolve_gkfs_path(dirfd, path, resolved)) { \
case PathStatus::Internal: \
case PathStatus::Internal: { \
DEBUG_INFO("[GKFS] {}", resolved); \
return gkfs::syscall::gkfs_##name(dirfd, resolved, \
DT.record(#name); \
auto res = gkfs::syscall::gkfs_##name(dirfd, resolved, \
__VA_ARGS__); \
DT.record(#name); \
return res; \
} \
case PathStatus::Error: \
return -1; \
default: \
......@@ -618,9 +628,13 @@ is_gkfs_fd(int fd) {
if(CTX->interception_enabled()) { \
std::string resolved; \
switch(resolve_gkfs_path(dirfd, path, resolved)) { \
case PathStatus::Internal: \
case PathStatus::Internal: { \
DEBUG_INFO("[GKFS] {}", resolved); \
return gkfs::syscall::gkfs_##name(resolved); \
DT.record(#name); \
auto res = gkfs::syscall::gkfs_##name(resolved); \
DT.record(#name); \
return res; \
} \
case PathStatus::Error: \
return -1; \
default: \
......@@ -936,7 +950,9 @@ __xstat64(int ver, const char* path, struct stat64* buf) {
switch(resolve_gkfs_path(AT_FDCWD, path, resolved)) {
case PathStatus::Internal: {
DEBUG_INFO("[GKFS] {}", resolved);
DT.record("__xstat64");
auto res = gkfs::syscall::gkfs_stat(resolved, &st);
DT.record("__xstat64");
convert(&st, buf);
return res;
}
......@@ -980,7 +996,9 @@ __lxstat(int ver, const char* path, struct stat* buf) {
switch(resolve_gkfs_path(AT_FDCWD, path, resolved, 0, false)) {
case PathStatus::Internal: {
DEBUG_INFO("[GKFS] {}", resolved);
DT.record("__lxstat");
auto res = gkfs::syscall::gkfs_stat(resolved, buf, false);
DT.record("__lxstat");
return res;
}
case PathStatus::Error: {
......@@ -1003,7 +1021,9 @@ __lxstat64(int ver, const char* path, struct stat64* buf) {
switch(resolve_gkfs_path(AT_FDCWD, path, resolved)) {
case PathStatus::Internal: {
DEBUG_INFO("[GKFS] {}", resolved);
DT.record("__lxstat64");
auto res = gkfs::syscall::gkfs_stat(resolved, &st, false);
DT.record("__lxstat64");
convert(&st, buf);
return res;
}
......@@ -1042,8 +1062,10 @@ __fxstat64(int ver, int fd, struct stat64* buf) {
if(CTX->interception_enabled() && is_gkfs_fd(fd)) {
struct stat st;
DEBUG_INFO("[GKFS] {}", CTX->file_map()->get(fd)->path());
DT.record("__fxstat64");
int res = gkfs::syscall::gkfs_stat(CTX->file_map()->get(fd)->path(),
&st, true, true);
DT.record("__fxstat64");
if(res == 0)
convert(&st, buf);
return res;
......@@ -1057,8 +1079,10 @@ fstat64(int fd, struct stat64* buf) {
if(CTX->interception_enabled() && is_gkfs_fd(fd)) {
struct stat st;
DEBUG_INFO("[GKFS] {}", CTX->file_map()->get(fd)->path());
DT.record("fstat64");
int res = gkfs::syscall::gkfs_stat(CTX->file_map()->get(fd)->path(),
&st, true, true);
DT.record("fstat64");
if(res == 0)
convert(&st, buf);
return res;
......@@ -1074,8 +1098,10 @@ fstat(int fd, struct stat* buf) {
// The fd could be a renamed file, thus when doing gkfs_stat we will get
// a is not found.
DT.record("fstat");
int res = gkfs::syscall::gkfs_stat(CTX->file_map()->get(fd)->path(),
buf, true, true);
DT.record("fstat");
return res;
}
GKFS_FALLBACK(fstat, fd, buf);
......@@ -1092,8 +1118,10 @@ __fxstatat64(int ver, int dfd, const char* path, struct stat64* buf,
case PathStatus::Internal: {
DEBUG_INFO("[GKFS] {}", resolved);
bool follow = (flags & AT_SYMLINK_NOFOLLOW) == 0;
DT.record("__fxstatat64");
auto res = gkfs::syscall::gkfs_stat(resolved, &st, follow);
convert(&st, buf);
DT.record("__fxstatat64");
return res;
}
case PathStatus::Error: {
......@@ -1122,8 +1150,10 @@ stat64(const char* path, struct stat64* buf) {
switch(resolve_gkfs_path(AT_FDCWD, path, resolved)) {
case PathStatus::Internal: {
DEBUG_INFO("[GKFS] {}", resolved);
DT.record("stat64");
auto res = gkfs::syscall::gkfs_stat(resolved, &st);
convert(&st, buf);
DT.record("stat64");
return res;
}
case PathStatus::Error: {
......@@ -1148,7 +1178,9 @@ fstatat(int dfd, const char* path, struct stat* buf, int flags) {
case PathStatus::Internal: {
DEBUG_INFO("[GKFS] {}", resolved);
bool follow = (flags & AT_SYMLINK_NOFOLLOW) == 0;
DT.record("fstatat");
auto res = gkfs::syscall::gkfs_stat(resolved, buf, follow);
DT.record("fstatat");
return res;
}
case PathStatus::Error: {
......
src/client/preload.cpp
View file @ 7b92d158
......@@ -96,6 +96,7 @@ exit_error_msg(int errcode, const string& msg) {
bool
init_hermes_client() {
DT.record("init_hermes_client");
try {
hermes::engine_options opts{};
......@@ -130,6 +131,7 @@ init_hermes_client() {
return false;
}
}
DT.record("init_hermes_client");
return true;
}
......@@ -209,6 +211,7 @@ namespace gkfs::preload {
void
init_environment() {
DT.record("init_environment");
vector<pair<string, string>> hosts{};
try {
LOG(INFO, "Loading peer addresses...");
......@@ -353,6 +356,7 @@ init_environment() {
srand(time(nullptr));
}
DT.record("init_environment");
LOG(INFO, "Environment initialization successful.");
}
......@@ -369,6 +373,7 @@ void
init_preload() {
// The original errno value will be restored after initialization to not
// leak internal error codes
DT.record("init_preload");
auto oerrno = errno;
if(atomic_exchange(&init, 1) == 0) {
pthread_atfork(&at_fork_syscall, &at_parent_syscall, &at_child_syscall);
......@@ -415,6 +420,7 @@ init_preload() {
if(!forwarding_map_file.empty()) {
init_forwarding_mapper();
}
DT.record("init_preload");
gkfs::preload::start_interception();
errno = oerrno;
......@@ -430,6 +436,7 @@ init_preload() {
*/
void
destroy_preload() {
DT.record("destroy_preload");
auto forwarding_map_file = gkfs::env::get_var(
gkfs::env::FORWARDING_MAP_FILE, gkfs::config::forwarding_file_path);
if(!forwarding_map_file.empty()) {
......@@ -461,6 +468,8 @@ destroy_preload() {
LOG(DEBUG, "Syscall interception stopped");
}
DT.record("destroy_preload");
DT.write_stats("/tmp/gkfs_stats.txt");
LOG(INFO, "All subsystems shut down. Client shutdown complete.");
}
......@@ -471,6 +480,7 @@ destroy_preload() {
*/
extern "C" int
gkfs_init() {
DT.record("gkfs_init");
CTX->init_logging();
// from here ownwards it is safe to print messages
LOG(DEBUG, "Logging subsystem initialized");
......@@ -488,6 +498,7 @@ gkfs_init() {
if(CTX->protect_fds())
CTX->unprotect_user_fds();
DT.record("gkfs_init");
return 0;
}
......@@ -543,6 +554,7 @@ init_libc() {
void
destroy_libc() {
DT.write_stats("/tmp/gkfs_libc_stats.txt");
CTX->disable_interception();
#ifdef GKFS_ENABLE_CLIENT_METRICS
LOG(INFO, "Flushing final metrics...");
......
src/client/preload_context.cpp
View file @ 7b92d158
......@@ -71,6 +71,62 @@ namespace gkfs {
namespace preload {
DebugTimer::DebugTimer() {
this->start_time = std::chrono::high_resolution_clock::now();
LOG(DEBUG, "Create DebugTimer");
}
// Debug timer
void
DebugTimer::record(const std::string& name) {
std::lock_guard<std::mutex> lock(mutex_);
auto now = std::chrono::high_resolution_clock::now();
auto& stat = stats_[name];
if(stat.lastTime.time_since_epoch().count() != 0) {
auto duration =
std::chrono::duration<double, std::milli>(now - stat.lastTime)
.count();
stat.callCount++;
if(duration > stat.maxDuration)
stat.maxDuration = duration;
stat.totalDuration += duration;
}
stat.lastTime = now;
}
void
DebugTimer::write_stats(const std::string& file) {
LOG(DEBUG, "Write DebugTimer stats");
std::lock_guard<std::mutex> lock(mutex_);
std::ofstream myfile(file, std::ios_base::app);
auto now = std::chrono::high_resolution_clock::now();
auto duration =
std::chrono::duration<double, std::milli>(now - this->start_time)
.count();
if(myfile.is_open()) {
myfile << "-----" << program_invocation_name << "-----" << std::endl;
myfile << "timestamp: " << now.time_since_epoch().count() << std::endl;
myfile << "duration: " << duration << "ms" << std::endl << std::endl;
for(const auto& [name, stat] : stats_) {
myfile << "Name: " << name << "\n Calls: " << stat.callCount
<< "\n Max duration: " << stat.maxDuration << " ms"
<< "\n Avg duration: "
<< (stat.callCount ? stat.totalDuration / stat.callCount : 0)
<< " ms\n";
}
myfile.close();
} else {
LOG(DEBUG, "could not write stats o.0");
}
}
// ---------
decltype(PreloadContext::MIN_INTERNAL_FD) constexpr PreloadContext::
MIN_INTERNAL_FD;
decltype(PreloadContext::MAX_USER_FDS) constexpr PreloadContext::MAX_USER_FDS;
......