use debug timer to see what takes so long, not complete (7b92d158) · Commits · hpc / gekkofs

src/client/gkfs_libc.cpp

+39 −7

Original line number	Diff line number	Diff line
		@@ -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

+12 −0

Original line number	Diff line number	Diff line
		@@ -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...");