From 803dded5adf56a6d4eaf49e96fa33d9f3f374624 Mon Sep 17 00:00:00 2001 From: Cosmin Tudorache Date: Wed, 25 Aug 2021 13:56:22 +0300 Subject: [PATCH 1/3] Osrm-datastore stability fixes, extra logging Update logging, enable osrm-customize Cleanup logs Fix lock_file declaration Minor logging Extra logging Print stacktrace on signal Spring-clean also removes 'osrm-region' object Minor log Enable core dump for osrm-datastore --- include/storage/shared_datatype.hpp | 29 ++++++ include/storage/shared_memory.hpp | 41 ++++++-- include/storage/shared_monitor.hpp | 45 ++++++++- include/updater/source.hpp | 22 +++++ include/util/log.hpp | 37 +++++++ .../datafacade/shared_memory_allocator.cpp | 1 + src/storage/storage.cpp | 46 ++++++++- src/tools/store.cpp | 97 ++++++++++++++++--- src/util/log.cpp | 43 ++++++++ 9 files changed, 337 insertions(+), 24 deletions(-) diff --git a/include/storage/shared_datatype.hpp b/include/storage/shared_datatype.hpp index 5677c8af0..b872b7854 100644 --- a/include/storage/shared_datatype.hpp +++ b/include/storage/shared_datatype.hpp @@ -212,7 +212,14 @@ struct SharedRegion char name[MAX_NAME_LENGTH + 1]; std::uint64_t timestamp; std::uint16_t shm_key; + + std::string ToString() const { + std::ostringstream oss; + oss << "{name: " << name << ", timestamp: " << timestamp << ", shm_key: " << util::shmKeyToString(shm_key) << "}"; + return oss.str(); + } }; +inline std::ostream& operator<<(std::ostream& os, const SharedRegion& r) { return os << r.ToString(); } // Keeps a list of all shared regions in a fixed-sized struct // for fast access and deserialization. @@ -286,6 +293,28 @@ struct SharedRegionRegister void ReleaseKey(ShmKey key) { shm_key_in_use[key] = false; } + std::string ToString() const { + std::vector used_regions; + for (unsigned i = 0; i < regions.size(); ++i) { + if (not regions[i].IsEmpty()) { + used_regions.push_back(regions[i]); + } + } + std::vector used_keys; + for (unsigned i = 0; i < shm_key_in_use.size(); ++i) { + if (shm_key_in_use[i]) { + used_keys.push_back(i); + } + } + std::ostringstream oss; + oss << "{regions: #" << used_regions.size() << ":"; + for (const SharedRegion& reg : used_regions) { + oss << "\n - " << reg.ToString(); + } + oss << ", used_keys: " << osrm::util::ToStringArray(used_keys) << "}"; + return oss.str(); + } + static constexpr const std::size_t MAX_SHARED_REGIONS = 512; static_assert(MAX_SHARED_REGIONS < std::numeric_limits::max(), "Number of shared memory regions needs to be less than the region id size."); diff --git a/include/storage/shared_memory.hpp b/include/storage/shared_memory.hpp index 3b558238d..2dedf06f4 100644 --- a/include/storage/shared_memory.hpp +++ b/include/storage/shared_memory.hpp @@ -42,12 +42,27 @@ struct OSRMLockFile } }; +inline std::string ShmKeyToString(std::uint16_t id) { + OSRMLockFile lock_file; + std::ostringstream oss; + oss << "{path: " << lock_file(id).string() << ", id: " << id << "}"; + return oss.str(); +} + #ifndef _WIN32 class SharedMemory { public: void *Ptr() const { return region.get_address(); } std::size_t Size() const { return region.get_size(); } + int Key() const { return (int)key.get_key(); } + int Shmid() const { return shm.get_shmid(); } + + std::string ToString() const { + std::ostringstream oss; + oss << "{key: " << util::toHexString(Key()) << ", shmid: " << Shmid() << ", size: " << Size() << "}"; + return oss.str(); + } SharedMemory(const SharedMemory &) = delete; SharedMemory &operator=(const SharedMemory &) = delete; @@ -148,7 +163,9 @@ class SharedMemory } BOOST_ASSERT(ret >= 0); - std::this_thread::sleep_for(std::chrono::microseconds(100)); + //std::this_thread::sleep_for(std::chrono::microseconds(100)); + util::Log(logWARNING) << "CTudorache WaitForDetach, nattach: " << xsi_ds.shm_nattch; + std::this_thread::sleep_for(std::chrono::seconds(1)); } while (xsi_ds.shm_nattch > 1); } #else @@ -168,9 +185,11 @@ class SharedMemory try { boost::interprocess::xsi_shared_memory shm(boost::interprocess::open_only, key); + util::Log(logINFO) << "RegionExists key: " << util::toHexString(key.get_key()) << " (shmid: " << shm.get_shmid() << ") TRUE"; } catch (const boost::interprocess::interprocess_exception &e) { + util::Log(logINFO) << "RegionExists key: " << util::toHexString(key.get_key()) << " FALSE, err: " << e.what() << ", code: " << e.get_error_code(); if (e.get_error_code() != boost::interprocess::not_found_error) { throw; @@ -184,8 +203,9 @@ class SharedMemory static bool Remove(const boost::interprocess::xsi_key &key) { boost::interprocess::xsi_shared_memory xsi(boost::interprocess::open_only, key); - util::Log(logDEBUG) << "deallocating prev memory " << xsi.get_shmid(); - return boost::interprocess::xsi_shared_memory::remove(xsi.get_shmid()); + const bool success = boost::interprocess::xsi_shared_memory::remove(xsi.get_shmid()); + util::Log(logWARNING) << "deallocating prev memory " << xsi.get_shmid() << " = " << util::toHexString(key.get_key()) << ", success: " << success << ", errno: " << errno; + return success; } boost::interprocess::xsi_key key; @@ -287,10 +307,10 @@ class SharedMemory template std::unique_ptr makeSharedMemory(const IdentifierT &id, const uint64_t size = 0) { + LockFileT lock_file; static_assert(sizeof(id) == sizeof(std::uint16_t), "Key type is not 16 bits"); try { - LockFileT lock_file; if (!boost::filesystem::exists(lock_file(id))) { if (0 == size) @@ -302,13 +322,20 @@ std::unique_ptr makeSharedMemory(const IdentifierT &id, const uint boost::filesystem::ofstream ofs(lock_file(id)); } } - return std::make_unique(lock_file(id), id, size); + util::Log(logWARNING) << "CTudorache makeSharedMemory start, id: " << (int)id <<", size: " << size << ", lock_file: " << lock_file(id) << ", exists: " << boost::filesystem::exists(lock_file(id)); + auto shm = std::make_unique(lock_file(id), id, size); + util::Log(logWARNING) << "CTudorache makeSharedMemory done, id: " << (int)id <<", size: " << size << ", lock_file: " << lock_file(id) << ", exists: " << boost::filesystem::exists(lock_file(id)) << ", shm: " << shm->ToString(); + return shm; } catch (const boost::interprocess::interprocess_exception &e) { util::Log(logERROR) << "Error while attempting to allocate shared memory: " << e.what() - << ", code " << e.get_error_code(); - throw util::exception(e.what() + SOURCE_REF); + << ", code " << e.get_error_code() + << ", id: " << (int)id + << ", size: " << size + << ", lock_file: " << lock_file(id) + << ", exists: " << boost::filesystem::exists(lock_file(id)); + throw; } } } // namespace storage diff --git a/include/storage/shared_monitor.hpp b/include/storage/shared_monitor.hpp index 2084112d4..aec86c0e2 100644 --- a/include/storage/shared_monitor.hpp +++ b/include/storage/shared_monitor.hpp @@ -40,13 +40,33 @@ template struct SharedMonitor { using mutex_type = bi::interprocess_mutex; +// private: +// static SharedMonitor* g_instance; + +// public: +// static SharedMonitor& instance() { +// if (!g_instance) { +// g_instance = new SharedMonitor(); +// } +// return *g_instance; +// } +// static SharedMonitor& instance(const Data &initial_data) { +// if (!g_instance) { +// g_instance = new SharedMonitor(initial_data); +// } +// return *g_instance; +// } +// private: + SharedMonitor(const Data &initial_data) { + util::Log(logWARNING) << "CTudorache sharedMonitor OPEN or CREATE: " << (const char*)Data::name; shmem = bi::shared_memory_object(bi::open_or_create, Data::name, bi::read_write); bi::offset_t size = 0; if (shmem.get_size(size) && size == 0) { + util::Log(logWARNING) << "CTudorache sharedMonitor NEW, name: " << shmem.get_name(); shmem.truncate(rounded_internal_size + sizeof(Data)); region = bi::mapped_region(shmem, bi::read_write); new (&internal()) InternalData; @@ -54,7 +74,9 @@ template struct SharedMonitor } else { + util::Log(logWARNING) << "CTudorache sharedMonitor EXISTS, name: " << shmem.get_name() << ", size: " << size; region = bi::mapped_region(shmem, bi::read_write); + util::Log(logWARNING) << "CTudorache sharedMonitor content: " << data().ToString(); } } @@ -62,7 +84,9 @@ template struct SharedMonitor { try { + util::Log(logWARNING) << "CTudorache sharedMonitor OPEN ONLY: " << (const char*)Data::name; shmem = bi::shared_memory_object(bi::open_only, Data::name, bi::read_write); + util::Log(logWARNING) << "CTudorache sharedMonitor => FOUND"; bi::offset_t size = 0; if (!shmem.get_size(size) || size != rounded_internal_size + sizeof(Data)) @@ -77,6 +101,7 @@ template struct SharedMonitor } catch (const bi::interprocess_exception &exception) { + util::Log(logERROR) << "CTudorache sharedMonitor => NOT FOUND"; auto message = boost::format("No shared memory block '%1%' found, have you forgotten " "to run osrm-datastore?") % (const char *)Data::name; @@ -84,6 +109,7 @@ template struct SharedMonitor } } +// public: Data &data() const { auto region_pointer = reinterpret_cast(region.get_address()); @@ -116,7 +142,19 @@ template struct SharedMonitor } #endif - static void remove() { bi::shared_memory_object::remove(Data::name); } + static void remove(bool alsoDeleteShmObject) { + try { + util::Log(logWARNING) << "CTudorache sharedMonitor UNLOCK global mutex"; + SharedMonitor monitor; + monitor.get_mutex().unlock(); + } catch (...) { + util::Log(logWARNING) << "CTudorache sharedMonitor UNLOCK global mutex EXCEPTION"; + } + if (alsoDeleteShmObject) { + util::Log(logWARNING) << "CTudorache sharedMonitor DELETING shared obj: " << (const char*)Data::name; + bi::shared_memory_object::remove(Data::name); + } + } static bool exists() { try @@ -126,6 +164,7 @@ template struct SharedMonitor } catch (const bi::interprocess_exception &exception) { + util::Log(logWARNING) << "CTudorache sharedMonitor exists exception: " << exception.what(); return false; } return true; @@ -234,6 +273,10 @@ template struct SharedMonitor bi::shared_memory_object shmem; bi::mapped_region region; }; + +// template < typename Data > +// SharedMonitor* SharedMonitor::g_instance = nullptr; + } // namespace storage } // namespace osrm diff --git a/include/updater/source.hpp b/include/updater/source.hpp index 58a19e080..d81fef59d 100644 --- a/include/updater/source.hpp +++ b/include/updater/source.hpp @@ -6,6 +6,7 @@ #include #include +#include namespace osrm { @@ -45,6 +46,11 @@ struct Segment final { return std::tie(from, to) == std::tie(rhs.from, rhs.to); } + std::string ToString() const { + std::ostringstream oss; + oss << "{from: " << from << ", to: " << to << "}"; + return oss.str(); + } }; struct SpeedSource final @@ -53,6 +59,12 @@ struct SpeedSource final unsigned speed; boost::optional rate; std::uint8_t source; + std::string ToString() const { + std::ostringstream oss; + oss << "{speed: " << speed << ", source: " << (int)source << "}"; + return oss.str(); + } + }; struct Turn final @@ -76,6 +88,11 @@ struct Turn final { return std::tie(from, via, to) == std::tie(rhs.from, rhs.via, rhs.to); } + std::string ToString() const { + std::ostringstream oss; + oss << "{from: " << from << ", via: " << via << ", to: " << to << "}"; + return oss.str(); + } }; struct PenaltySource final @@ -84,6 +101,11 @@ struct PenaltySource final double duration; double weight; std::uint8_t source; + std::string ToString() const { + std::ostringstream oss; + oss << "{duration: " << duration << ", weight: " << weight << ", source: " << source << "}"; + return oss.str(); + } }; using SegmentLookupTable = LookupTable; diff --git a/include/util/log.hpp b/include/util/log.hpp index be3650961..e114e0fd9 100644 --- a/include/util/log.hpp +++ b/include/util/log.hpp @@ -4,6 +4,7 @@ #include #include #include +#include enum LogLevel { @@ -101,6 +102,42 @@ class UnbufferedLog : public Log public: UnbufferedLog(LogLevel level_ = logINFO); }; + +template +std::string ToStringArray(const CONTAINER& arr) { + std::ostringstream oss; + oss << "#" << arr.size() << "{"; + bool first = true; + for (const auto& e : arr) { + if (not first) { + oss << ", "; + } + first = false; + oss << e; + } + oss << "}"; + return oss.str(); +} + +template +std::string ToStringMap(const std::map& m) { + std::ostringstream oss; + oss << "#" << m.size() << "{"; + bool first = true; + for (const auto& p : m) { + if (not first) { + oss << ", "; + } + first = false; + oss << p.first << ": " << p.second; + } + oss << "}"; + return oss.str(); +} + +std::string toHexString(int a); +std::string shmKeyToString(std::uint16_t shm_key); + } // namespace util } // namespace osrm diff --git a/src/engine/datafacade/shared_memory_allocator.cpp b/src/engine/datafacade/shared_memory_allocator.cpp index d90302bf9..4d0328df7 100644 --- a/src/engine/datafacade/shared_memory_allocator.cpp +++ b/src/engine/datafacade/shared_memory_allocator.cpp @@ -22,6 +22,7 @@ SharedMemoryAllocator::SharedMemoryAllocator( { util::Log(logDEBUG) << "Loading new data for region " << (int)shm_key; BOOST_ASSERT(storage::SharedMemory::RegionExists(shm_key)); + util::Log(logWARNING) << "CTudorache SharedMemoryAllocator, shm_key: " << shm_key; auto mem = storage::makeSharedMemory(shm_key); storage::io::BufferReader reader(reinterpret_cast(mem->Ptr()), mem->Size()); diff --git a/src/storage/storage.cpp b/src/storage/storage.cpp index 9494285ab..34a3fe2f5 100644 --- a/src/storage/storage.cpp +++ b/src/storage/storage.cpp @@ -49,7 +49,13 @@ struct RegionHandle std::unique_ptr memory; char *data_ptr; std::uint16_t shm_key; + std::string ToString() const { + std::ostringstream oss; + oss << "{shm_key: " << shm_key << "}"; + return oss.str(); + } }; +inline std::ostream& operator<<(std::ostream& os, const RegionHandle& r) { return os << r.ToString(); } RegionHandle setupRegion(SharedRegionRegister &shared_register, const storage::BaseDataLayout &layout) @@ -62,7 +68,9 @@ RegionHandle setupRegion(SharedRegionRegister &shared_register, // to detach at the end of the function if (storage::SharedMemory::RegionExists(shm_key)) { - util::Log(logWARNING) << "Old shared memory region " << (int)shm_key << " still exists."; + util::Log(logWARNING) << "Old shared memory region " << ShmKeyToString(shm_key) << " still exists. Attempting open"; + auto shm = osrm::storage::makeSharedMemory(shm_key); + util::Log(logWARNING) << "Old shared memory region " << ShmKeyToString(shm_key) << " still exists: " << shm->ToString(); util::UnbufferedLog() << "Retrying removal... "; storage::SharedMemory::Remove(shm_key); util::UnbufferedLog() << "ok."; @@ -74,15 +82,17 @@ RegionHandle setupRegion(SharedRegionRegister &shared_register, // Allocate shared memory block auto regions_size = encoded_static_layout.size() + layout.GetSizeOfLayout(); - util::Log() << "Data layout has a size of " << encoded_static_layout.size() << " bytes"; - util::Log() << "Allocating shared memory of " << regions_size << " bytes"; + util::Log() << "Data layout has a size of " << encoded_static_layout.size() << " bytes, Allocating shared memory of " << regions_size << " bytes"; auto memory = makeSharedMemory(shm_key, regions_size); + util::Log(logWARNING) << "CTudorache setupRegion, shm_key: " << shm_key << ", regions_size: " << regions_size << ", mem: " << memory->ToString(); // Copy memory static_layout to shared memory and populate data + //util::Log(logWARNING) << "CTudorache setupRegion, copy data, size: " << encoded_static_layout.size(); char *shared_memory_ptr = static_cast(memory->Ptr()); auto data_ptr = std::copy_n(encoded_static_layout.data(), encoded_static_layout.size(), shared_memory_ptr); + //util::Log(logWARNING) << "CTudorache setupRegion, copy data DONE"; return RegionHandle{std::move(memory), data_ptr, shm_key}; } @@ -91,6 +101,7 @@ bool swapData(Monitor &monitor, const std::map &handles, int max_wait) { + util::Log(logWARNING) << "CTudorache swapData, max_wait: " << max_wait << ", shared_register: " << shared_register.ToString() << ", handles: " << osrm::util::ToStringMap(handles); std::vector old_handles; { // Lock for write access shared region mutex @@ -114,20 +125,41 @@ bool swapData(Monitor &monitor, } else { + util::Log(logWARNING) << "CTudorache swapData locking sharedMonitor mutex"; lock.lock(); } for (auto &pair : handles) { auto region_id = shared_register.Find(pair.first); + util::Log(logWARNING) << "CTudorache swapData name: " << pair.first + << ", old region_id: " << region_id << (region_id == SharedRegionRegister::INVALID_REGION_ID ? "(INVALID)" : "(VALID)") + << ", new shm_key: " << pair.second.shm_key; + if (region_id != SharedRegionRegister::INVALID_REGION_ID) + { + auto &shared_region = shared_register.GetRegion(region_id); + if (!storage::SharedMemory::RegionExists(shared_region.shm_key)) + { + util::Log(logERROR) << "CTudorache swapData old region shm_key does not exist: " << shared_region.ToString(); + shared_region.timestamp = 0; + shared_register.ReleaseKey(shared_region.shm_key); + OSRMLockFile lock_file; + boost::filesystem::remove(lock_file(shared_region.shm_key)); + region_id = SharedRegionRegister::INVALID_REGION_ID; + } + } + if (region_id == SharedRegionRegister::INVALID_REGION_ID) { + util::Log(logWARNING) << "CTudorache swapData register: " << pair.first << ", key: " << util::shmKeyToString(pair.second.shm_key); region_id = shared_register.Register(pair.first, pair.second.shm_key); } else { auto &shared_region = shared_register.GetRegion(region_id); - + util::Log(logWARNING) << "CTudorache swapData replacing shared_region: " + << shared_region.ToString() << "(exists: " << storage::SharedMemory::RegionExists(shared_region.shm_key) <<")" + << ", with new shm_key: " << pair.second.shm_key; old_handles.push_back(RegionHandle{ makeSharedMemory(shared_region.shm_key), nullptr, shared_region.shm_key}); @@ -262,6 +294,7 @@ int Storage::Run(int max_wait, const std::string &dataset_name, bool only_metric Storage::PopulateLayoutWithRTree(*static_layout); std::vector> files = Storage::GetStaticFiles(); Storage::PopulateLayout(*static_layout, files); + util::Log(logWARNING) << "CTudorache Storage::Run setupRegion static"; auto static_handle = setupRegion(shared_register, *static_layout); regions.push_back({static_handle.data_ptr, std::move(static_layout)}); handles[dataset_name + "/static"] = std::move(static_handle); @@ -271,6 +304,7 @@ int Storage::Run(int max_wait, const std::string &dataset_name, bool only_metric std::make_unique(); std::vector> files = Storage::GetUpdatableFiles(); Storage::PopulateLayout(*updatable_layout, files); + util::Log(logWARNING) << "CTudorache Storage::Run setupRegion updatable"; auto updatable_handle = setupRegion(shared_register, *updatable_layout); regions.push_back({updatable_handle.data_ptr, std::move(updatable_layout)}); handles[dataset_name + "/updatable"] = std::move(updatable_handle); @@ -279,12 +313,16 @@ int Storage::Run(int max_wait, const std::string &dataset_name, bool only_metric if (!only_metric) { + util::Log(logWARNING) << "CTudorache Storage::Run PopulateStaticData"; PopulateStaticData(index); } + util::Log(logWARNING) << "CTudorache Storage::Run PopulateUpdatableData"; PopulateUpdatableData(index); + util::Log(logWARNING) << "CTudorache Storage::Run swapData"; swapData(monitor, shared_register, handles, max_wait); + util::Log(logWARNING) << "CTudorache Storage::Run DONE. SharedRegister: " << monitor.data().ToString(); return EXIT_SUCCESS; } diff --git a/src/tools/store.cpp b/src/tools/store.cpp index 1504d9ed2..462ea9e19 100644 --- a/src/tools/store.cpp +++ b/src/tools/store.cpp @@ -1,6 +1,7 @@ #include "storage/serialization.hpp" #include "storage/shared_memory.hpp" #include "storage/shared_monitor.hpp" +#include "storage/shared_datatype.hpp" #include "storage/storage.hpp" #include "osrm/exception.hpp" @@ -11,13 +12,20 @@ #include #include +#include +#include #include #include +#include +#include +#include + +#include using namespace osrm; -void removeLocks() { storage::SharedMonitor::remove(); } +void removeLocks(bool alsoDeleteOsrmRegion) { storage::SharedMonitor::remove(alsoDeleteOsrmRegion); } void deleteRegion(const storage::SharedRegionRegister::ShmKey key) { @@ -29,9 +37,10 @@ void deleteRegion(const storage::SharedRegionRegister::ShmKey key) void listRegions(bool show_blocks) { - osrm::util::Log() << "name\tshm key\ttimestamp\tsize"; + osrm::util::Log() << "name\tshm key\ttimestamp\tsize\tkey\tshmid"; if (!storage::SharedMonitor::exists()) { + util::Log(logWARNING) << "CTudorache sharedMonitor DOES NOT EXIST: " << (const char *)storage::SharedRegionRegister::name; return; } storage::SharedMonitor monitor; @@ -43,8 +52,11 @@ void listRegions(bool show_blocks) auto id = shared_register.Find(name); auto region = shared_register.GetRegion(id); auto shm = osrm::storage::makeSharedMemory(region.shm_key); - osrm::util::Log() << name << "\t" << static_cast(region.shm_key) << "\t" - << region.timestamp << "\t" << shm->Size(); + osrm::util::Log() << "name: " << name + << ", shm_key:" << static_cast(region.shm_key) + << ", timestamp: " << region.timestamp + << ", size: " << shm->Size() + << ", shm: " << shm->ToString(); if (show_blocks) { @@ -87,7 +99,7 @@ void springClean() { deleteRegion(key); } - removeLocks(); + removeLocks(true); } } @@ -200,7 +212,7 @@ bool generateDataStoreOptions(const int argc, if (option_variables.count("remove-locks")) { - removeLocks(); + removeLocks(false); return false; } @@ -215,10 +227,16 @@ bool generateDataStoreOptions(const int argc, return true; } -[[noreturn]] void CleanupSharedBarriers(int signum) +void CleanupSharedBarriers(int signum) { // Here the lock state of named mutexes is unknown, make a hard cleanup - removeLocks(); - std::_Exit(128 + signum); + util::Log(logERROR) << "[signal] " << signum << " (" << strsignal(signum) << ")"; + + removeLocks(false); + + // The signal handler is installed with SA_RESETHAND, + // so returning from this function will trigger the signal again + // but it will be handled by the default handler => core dump. + //std::_Exit(128 + signum); } int main(const int argc, const char *argv[]) @@ -227,7 +245,12 @@ try int signals[] = {SIGTERM, SIGSEGV, SIGINT, SIGILL, SIGABRT, SIGFPE}; for (auto sig : signals) { - std::signal(sig, CleanupSharedBarriers); + struct sigaction act; + sigemptyset(&act.sa_mask); + act.sa_flags = SA_RESETHAND; + act.sa_handler = &CleanupSharedBarriers; + sigaction(sig, &act, NULL); + //std::signal(sig, CleanupSharedBarriers); } util::LogPolicy::GetInstance().Unmute(); @@ -268,11 +291,61 @@ try } storage::Storage storage(std::move(config)); - return storage.Run(max_wait, dataset_name, only_metric); + //////////////////////////////////// + // tmp directory for logs + const std::string log_dirpath = "/tmp/osrm-datastore-log"; + if (not boost::filesystem::is_directory(log_dirpath)) { + boost::filesystem::create_directory(log_dirpath); + } + + // keep last 200 logs (200 x 15 min => 50h = 2 days) + const unsigned LOG_COUNT_TO_KEEP = 200; + std::vector log_files; + for (boost::filesystem::directory_iterator it(log_dirpath), end; it != end; ++it) { + const std::string filepath = it->path().string(); + if (filepath.rfind(".log") != std::string::npos) { + log_files.push_back(it->path().string()); + } + } + std::sort(log_files.begin(), log_files.end(), std::greater<>()); + for (unsigned i = LOG_COUNT_TO_KEEP - 1; i < log_files.size(); ++i) { + std::cout << "Removing old log file: " << log_files[i] << std::endl; + boost::filesystem::remove(log_files[i]); + } + + // tee log to new file + char log_filepath[256] = {0}; + std::time_t now = std::time(nullptr); + std::strftime(log_filepath, sizeof(log_filepath), (log_dirpath + "/%Y-%m-%d_%H-%M-%S_" + dataset_name + ".log").c_str(), std::localtime(&now)); + std::ofstream log_file; + log_file.open(log_filepath); + std::ostream tmp(std::cout.rdbuf()); + boost::iostreams::tee_device log_output_device(tmp, log_file); + boost::iostreams::stream> logger(log_output_device); + const auto original_cout = std::cout.rdbuf(); + const auto original_cerr = std::cerr.rdbuf(); + std::cout.rdbuf(logger.rdbuf()); + std::cerr.rdbuf(logger.rdbuf()); + std::cout << "Redirected log to file: " << log_filepath << std::endl; + //////////////////////////////////// + + int result = storage.Run(max_wait, dataset_name, only_metric); + + // restore cout/cerr after tee log to file + std::cout << "Closing log file: " << log_filepath << std::endl; + std::cout.rdbuf(original_cout); + std::cerr.rdbuf(original_cerr); + logger.close(); + log_output_device.close(); + + std::cout.flush(); + std::cerr.flush(); + // ::sleep(5); + return result; } catch (const osrm::RuntimeError &e) { - util::Log(logERROR) << e.what(); + util::Log(logERROR) << "[RuntimeError] " << e.what(); return e.GetCode(); } catch (const std::bad_alloc &e) diff --git a/src/util/log.cpp b/src/util/log.cpp index f8063c748..5d0be185f 100644 --- a/src/util/log.cpp +++ b/src/util/log.cpp @@ -1,10 +1,20 @@ +#include +#include +#include + #include "util/log.hpp" #include "util/isatty.hpp" #include #include +#include +#include #include +#include #include #include +#include +#include "storage/shared_memory.hpp" +#include namespace osrm { @@ -68,6 +78,10 @@ Log::Log(LogLevel level_, std::ostream &ostream) : level(level_), stream(ostream std::lock_guard lock(get_mutex()); if (!LogPolicy::GetInstance().IsMute() && level <= LogPolicy::GetInstance().GetLevel()) { + std::chrono::system_clock::time_point now_ts = std::chrono::system_clock::now(); + std::time_t now = std::chrono::system_clock::to_time_t(now_ts); + const long ms = std::chrono::time_point_cast(now_ts).time_since_epoch().count() % 1000; + stream << "[" << std::put_time(std::localtime(&now), "%H:%M:%S.") << ms << "] [pid: " << syscall(SYS_gettid) << "] [tid: " << pthread_self() << "] "; const bool is_terminal = IsStdoutATTY(); switch (level) { @@ -143,6 +157,7 @@ Log::~Log() stream << std::endl; } } + stream.flush(); } UnbufferedLog::UnbufferedLog(LogLevel level_) @@ -150,5 +165,33 @@ UnbufferedLog::UnbufferedLog(LogLevel level_) { stream.flags(std::ios_base::unitbuf); } + +std::string toHexString(int a) { + std::ostringstream oss; + oss << "0x" << std::setw(8) << std::setfill('0') << std::hex << a; + return oss.str(); +} + +std::string shmKeyToString(std::uint16_t shm_key) { + std::ostringstream oss; + osrm::storage::OSRMLockFile lock_file; + oss << shm_key << " ("; + try { + oss << "file: " << lock_file(shm_key); + boost::interprocess::xsi_key key(lock_file(shm_key).string().c_str(), shm_key); + oss << ", key: " << toHexString(key.get_key()); + bool exists = storage::SharedMemory::RegionExists(shm_key); + oss << ", exists: " << exists; + } catch (const std::exception& e) { + oss << "error: " << e.what(); + std::string path = lock_file(shm_key).string(); + oss << ", path: " << path << ", exists: " << boost::filesystem::exists(path); + key_t k = ::ftok(path.c_str(), shm_key); + oss << ", ftok: " << k << ", errno: " << errno; + } + oss << ")"; + return oss.str(); +} + } // namespace util } // namespace osrm From 9ebb4278a33f2aede2ea7cada90a1e2df723d484 Mon Sep 17 00:00:00 2001 From: Cosmin Tudorache Date: Sun, 10 Apr 2022 20:08:05 +0300 Subject: [PATCH 2/3] Cleanup some unnecessary logs & comments --- include/storage/shared_memory.hpp | 4 +--- include/storage/shared_monitor.hpp | 19 ------------------- .../datafacade/shared_memory_allocator.cpp | 1 - src/storage/storage.cpp | 3 --- src/tools/store.cpp | 2 +- 5 files changed, 2 insertions(+), 27 deletions(-) diff --git a/include/storage/shared_memory.hpp b/include/storage/shared_memory.hpp index 2dedf06f4..c9892d7d2 100644 --- a/include/storage/shared_memory.hpp +++ b/include/storage/shared_memory.hpp @@ -163,9 +163,7 @@ class SharedMemory } BOOST_ASSERT(ret >= 0); - //std::this_thread::sleep_for(std::chrono::microseconds(100)); - util::Log(logWARNING) << "CTudorache WaitForDetach, nattach: " << xsi_ds.shm_nattch; - std::this_thread::sleep_for(std::chrono::seconds(1)); + std::this_thread::sleep_for(std::chrono::microseconds(100)); } while (xsi_ds.shm_nattch > 1); } #else diff --git a/include/storage/shared_monitor.hpp b/include/storage/shared_monitor.hpp index aec86c0e2..99340053f 100644 --- a/include/storage/shared_monitor.hpp +++ b/include/storage/shared_monitor.hpp @@ -40,24 +40,6 @@ template struct SharedMonitor { using mutex_type = bi::interprocess_mutex; -// private: -// static SharedMonitor* g_instance; - -// public: -// static SharedMonitor& instance() { -// if (!g_instance) { -// g_instance = new SharedMonitor(); -// } -// return *g_instance; -// } -// static SharedMonitor& instance(const Data &initial_data) { -// if (!g_instance) { -// g_instance = new SharedMonitor(initial_data); -// } -// return *g_instance; -// } -// private: - SharedMonitor(const Data &initial_data) { util::Log(logWARNING) << "CTudorache sharedMonitor OPEN or CREATE: " << (const char*)Data::name; @@ -109,7 +91,6 @@ template struct SharedMonitor } } -// public: Data &data() const { auto region_pointer = reinterpret_cast(region.get_address()); diff --git a/src/engine/datafacade/shared_memory_allocator.cpp b/src/engine/datafacade/shared_memory_allocator.cpp index 4d0328df7..d90302bf9 100644 --- a/src/engine/datafacade/shared_memory_allocator.cpp +++ b/src/engine/datafacade/shared_memory_allocator.cpp @@ -22,7 +22,6 @@ SharedMemoryAllocator::SharedMemoryAllocator( { util::Log(logDEBUG) << "Loading new data for region " << (int)shm_key; BOOST_ASSERT(storage::SharedMemory::RegionExists(shm_key)); - util::Log(logWARNING) << "CTudorache SharedMemoryAllocator, shm_key: " << shm_key; auto mem = storage::makeSharedMemory(shm_key); storage::io::BufferReader reader(reinterpret_cast(mem->Ptr()), mem->Size()); diff --git a/src/storage/storage.cpp b/src/storage/storage.cpp index 34a3fe2f5..0ee314dac 100644 --- a/src/storage/storage.cpp +++ b/src/storage/storage.cpp @@ -87,12 +87,10 @@ RegionHandle setupRegion(SharedRegionRegister &shared_register, util::Log(logWARNING) << "CTudorache setupRegion, shm_key: " << shm_key << ", regions_size: " << regions_size << ", mem: " << memory->ToString(); // Copy memory static_layout to shared memory and populate data - //util::Log(logWARNING) << "CTudorache setupRegion, copy data, size: " << encoded_static_layout.size(); char *shared_memory_ptr = static_cast(memory->Ptr()); auto data_ptr = std::copy_n(encoded_static_layout.data(), encoded_static_layout.size(), shared_memory_ptr); - //util::Log(logWARNING) << "CTudorache setupRegion, copy data DONE"; return RegionHandle{std::move(memory), data_ptr, shm_key}; } @@ -101,7 +99,6 @@ bool swapData(Monitor &monitor, const std::map &handles, int max_wait) { - util::Log(logWARNING) << "CTudorache swapData, max_wait: " << max_wait << ", shared_register: " << shared_register.ToString() << ", handles: " << osrm::util::ToStringMap(handles); std::vector old_handles; { // Lock for write access shared region mutex diff --git a/src/tools/store.cpp b/src/tools/store.cpp index 462ea9e19..b92a73f8c 100644 --- a/src/tools/store.cpp +++ b/src/tools/store.cpp @@ -37,7 +37,7 @@ void deleteRegion(const storage::SharedRegionRegister::ShmKey key) void listRegions(bool show_blocks) { - osrm::util::Log() << "name\tshm key\ttimestamp\tsize\tkey\tshmid"; + osrm::util::Log() << "name\tshm key\ttimestamp\tsize"; if (!storage::SharedMonitor::exists()) { util::Log(logWARNING) << "CTudorache sharedMonitor DOES NOT EXIST: " << (const char *)storage::SharedRegionRegister::name; From 2bb32ef4201bd11fe378ed7a1130a11b822e6845 Mon Sep 17 00:00:00 2001 From: Cosmin Tudorache Date: Mon, 11 Apr 2022 18:16:21 +0300 Subject: [PATCH 3/3] Cleanup commented code --- include/storage/shared_monitor.hpp | 4 ---- 1 file changed, 4 deletions(-) diff --git a/include/storage/shared_monitor.hpp b/include/storage/shared_monitor.hpp index 99340053f..084f373d1 100644 --- a/include/storage/shared_monitor.hpp +++ b/include/storage/shared_monitor.hpp @@ -254,10 +254,6 @@ template struct SharedMonitor bi::shared_memory_object shmem; bi::mapped_region region; }; - -// template < typename Data > -// SharedMonitor* SharedMonitor::g_instance = nullptr; - } // namespace storage } // namespace osrm