From 14b756a6923d69a5a51fd7234e2895b662516e1b Mon Sep 17 00:00:00 2001 From: Andrei Kortunov Date: Thu, 1 Nov 2018 14:08:33 +0400 Subject: [PATCH] Use a generic logging system for RecastNavigation --- apps/openmw/mwmechanics/pathfinding.cpp | 3 +- apps/openmw/mwworld/scene.cpp | 2 - apps/openmw/mwworld/worldimp.cpp | 3 - components/debug/debugging.cpp | 2 + components/debug/debugging.hpp | 1 + components/debug/debuglog.hpp | 5 +- .../detournavigator/asyncnavmeshupdater.cpp | 28 +++--- components/detournavigator/debug.hpp | 99 ------------------- components/detournavigator/makenavmesh.cpp | 30 +++--- components/detournavigator/navmeshmanager.cpp | 10 +- .../reference/modding/settings/navigator.rst | 21 ---- 11 files changed, 42 insertions(+), 162 deletions(-) diff --git a/apps/openmw/mwmechanics/pathfinding.cpp b/apps/openmw/mwmechanics/pathfinding.cpp index db6b8d686..4ff28e01a 100644 --- a/apps/openmw/mwmechanics/pathfinding.cpp +++ b/apps/openmw/mwmechanics/pathfinding.cpp @@ -327,8 +327,7 @@ namespace MWMechanics } catch (const DetourNavigator::NavigatorException& exception) { - DetourNavigator::log("PathFinder::buildPathByNavigator navigator exception: ", exception.what()); - Log(Debug::Verbose) << "Build path by navigator exception: \"" << exception.what() + Log(Debug::Debug) << "Build path by navigator exception: \"" << exception.what() << "\" for \"" << actor.getClass().getName(actor) << "\" (" << actor.getBase() << ") from " << startPoint << " to " << endPoint << " with flags (" << DetourNavigator::WriteFlags {flags} << ")"; diff --git a/apps/openmw/mwworld/scene.cpp b/apps/openmw/mwworld/scene.cpp index 8cccb2fc5..59f9cfc09 100644 --- a/apps/openmw/mwworld/scene.cpp +++ b/apps/openmw/mwworld/scene.cpp @@ -327,7 +327,6 @@ namespace MWWorld void Scene::unloadCell (CellStoreCollection::iterator iter) { Log(Debug::Info) << "Unloading cell " << (*iter)->getCell()->getDescription(); - DetourNavigator::log("unload cell ", (*iter)->getCell()->getDescription()); const auto navigator = MWBase::Environment::get().getWorld()->getNavigator(); ListAndResetObjectsVisitor visitor; @@ -388,7 +387,6 @@ namespace MWWorld if(result.second) { Log(Debug::Info) << "Loading cell " << cell->getCell()->getDescription(); - DetourNavigator::log("load cell ", cell->getCell()->getDescription()); float verts = ESM::Land::LAND_SIZE; float worldsize = ESM::Land::REAL_SIZE; diff --git a/apps/openmw/mwworld/worldimp.cpp b/apps/openmw/mwworld/worldimp.cpp index 60ccc8f89..ce9284774 100644 --- a/apps/openmw/mwworld/worldimp.cpp +++ b/apps/openmw/mwworld/worldimp.cpp @@ -202,9 +202,6 @@ namespace MWWorld navigatorSettings->mMaxClimb = MWPhysics::sStepSizeUp; navigatorSettings->mMaxSlope = MWPhysics::sMaxSlope; navigatorSettings->mSwimHeightScale = mSwimHeightScale; - if (Settings::Manager::getBool("enable log", "Navigator")) - DetourNavigator::Log::instance().setSink(std::unique_ptr( - new DetourNavigator::FileSink(Settings::Manager::getString("log path", "Navigator")))); DetourNavigator::RecastGlobalAllocator::init(); mNavigator.reset(new DetourNavigator::NavigatorImpl(*navigatorSettings)); } diff --git a/components/debug/debugging.cpp b/components/debug/debugging.cpp index 2d05fbc55..28446ccc7 100644 --- a/components/debug/debugging.cpp +++ b/components/debug/debugging.cpp @@ -76,6 +76,8 @@ namespace Debug CurrentDebugLevel = Info; else if (value == "VERBOSE") CurrentDebugLevel = Verbose; + else if (value == "DEBUG") + CurrentDebugLevel = Debug; return; } diff --git a/components/debug/debugging.hpp b/components/debug/debugging.hpp index 81b01d055..e815543a1 100644 --- a/components/debug/debugging.hpp +++ b/components/debug/debugging.hpp @@ -83,6 +83,7 @@ namespace Debug mColors[Warning] = Yellow; mColors[Info] = Reset; mColors[Verbose] = DarkGray; + mColors[Debug] = DarkGray; mColors[NoLevel] = Reset; } diff --git a/components/debug/debuglog.hpp b/components/debug/debuglog.hpp index 0676f7689..0da5b9cbd 100644 --- a/components/debug/debuglog.hpp +++ b/components/debug/debuglog.hpp @@ -14,9 +14,10 @@ namespace Debug Warning = 2, Info = 3, Verbose = 4, - Marker = Verbose, + Debug = 5, + Marker = Debug, - NoLevel = 5 // Do not filter messages in this case + NoLevel = 6 // Do not filter messages in this case }; extern Level CurrentDebugLevel; diff --git a/components/detournavigator/asyncnavmeshupdater.cpp b/components/detournavigator/asyncnavmeshupdater.cpp index 6bd4f01c9..ef81565c2 100644 --- a/components/detournavigator/asyncnavmeshupdater.cpp +++ b/components/detournavigator/asyncnavmeshupdater.cpp @@ -92,7 +92,7 @@ namespace DetourNavigator } } - log("posted ", mJobs.size(), " jobs"); + Log(Debug::Debug) << "Posted " << mJobs.size() << " navigator jobs"; if (!mJobs.empty()) mHasJob.notify_all(); @@ -120,7 +120,7 @@ namespace DetourNavigator void AsyncNavMeshUpdater::process() throw() { - log("start process jobs"); + Log(Debug::Debug) << "Start process navigator jobs"; while (!mShouldStop) { try @@ -131,15 +131,15 @@ namespace DetourNavigator } catch (const std::exception& e) { - DetourNavigator::log("AsyncNavMeshUpdater::process exception: ", e.what()); + Log(Debug::Error) << "AsyncNavMeshUpdater::process exception: ", e.what(); } } - log("stop process jobs"); + Log(Debug::Debug) << "Stop navigator jobs processing"; } bool AsyncNavMeshUpdater::processJob(const Job& job) { - log("process job for agent=", job.mAgentHalfExtents); + Log(Debug::Debug) << "Process job for agent=(" << std::fixed << std::setprecision(2) << job.mAgentHalfExtents << ")"; const auto start = std::chrono::steady_clock::now(); @@ -163,14 +163,14 @@ namespace DetourNavigator using FloatMs = std::chrono::duration; - { - const auto locked = navMeshCacheItem->lockConst(); - log("cache updated for agent=", job.mAgentHalfExtents, " status=", status, - " generation=", locked->getGeneration(), - " revision=", locked->getNavMeshRevision(), - " time=", std::chrono::duration_cast(finish - start).count(), "ms", - " total_time=", std::chrono::duration_cast(finish - firstStart).count(), "ms"); - } + const auto locked = navMeshCacheItem->lockConst(); + Log(Debug::Debug) << std::fixed << std::setprecision(2) << + "Cache updated for agent=(" << job.mAgentHalfExtents << ")" << + " status=" << status << + " generation=" << locked->getGeneration() << + " revision=" << locked->getNavMeshRevision() << + " time=" << std::chrono::duration_cast(finish - start).count() << "ms" << + " total_time=" << std::chrono::duration_cast(finish - firstStart).count() << "ms"; return isSuccess(status); } @@ -184,7 +184,7 @@ namespace DetourNavigator mDone.notify_all(); return boost::none; } - log("got ", mJobs.size(), " jobs"); + Log(Debug::Debug) << "Got " << mJobs.size() << " navigator jobs"; const auto job = mJobs.top(); mJobs.pop(); const auto pushed = mPushed.find(job.mAgentHalfExtents); diff --git a/components/detournavigator/debug.hpp b/components/detournavigator/debug.hpp index 05d212e2f..541680997 100644 --- a/components/detournavigator/debug.hpp +++ b/components/detournavigator/debug.hpp @@ -28,105 +28,6 @@ namespace DetourNavigator class RecastMesh; - inline std::ostream& operator <<(std::ostream& stream, const std::chrono::steady_clock::time_point& value) - { - using float_s = std::chrono::duration>; - return stream << std::fixed << std::setprecision(4) - << std::chrono::duration_cast(value.time_since_epoch()).count(); - } - - struct Sink - { - virtual ~Sink() = default; - virtual void write(const std::string& text) = 0; - }; - - class FileSink final : public Sink - { - public: - FileSink(std::string path) - : mPath(std::move(path)) - { - mFile.exceptions(std::ios::failbit | std::ios::badbit); - } - - void write(const std::string& text) override - { - if (!mFile.is_open()) - { - mFile.open(mPath); - } - mFile << text << std::flush; - } - - private: - std::string mPath; - std::ofstream mFile; - }; - - class StdoutSink final : public Sink - { - public: - void write(const std::string& text) override - { - std::cout << text << std::flush; - } - }; - - class Log - { - public: - void setSink(std::unique_ptr sink) - { - *mSink.lock() = std::move(sink); - } - - bool isEnabled() - { - return bool(*mSink.lockConst()); - } - - void write(const std::string& text) - { - const auto sink = mSink.lock(); - if (*sink) - sink.get()->write(text); - } - - static Log& instance() - { - static Log value; - return value; - } - - private: - Misc::ScopeGuarded> mSink; - }; - - inline void write(std::ostream& stream) - { - stream << '\n'; - } - - template - void write(std::ostream& stream, const Head& head, const Tail& ... tail) - { - stream << head; - write(stream, tail ...); - } - - template - void log(Ts&& ... values) - { - auto& log = Log::instance(); - if (!log.isEnabled()) - return; - std::ostringstream stream; - stream << '[' << std::chrono::steady_clock::now() << "] [" << std::this_thread::get_id() << "] "; - write(stream, std::forward(values) ...); - log.write(stream.str()); - } - void writeToFile(const RecastMesh& recastMesh, const std::string& pathPrefix, const std::string& revision); void writeToFile(const dtNavMesh& navMesh, const std::string& pathPrefix, const std::string& revision); } diff --git a/components/detournavigator/makenavmesh.cpp b/components/detournavigator/makenavmesh.cpp index 7caad9ec6..ae26ced7e 100644 --- a/components/detournavigator/makenavmesh.cpp +++ b/components/detournavigator/makenavmesh.cpp @@ -17,6 +17,8 @@ #include #include +#include + #include #include #include @@ -486,23 +488,21 @@ namespace DetourNavigator const std::vector& offMeshConnections, const Settings& settings, const SharedNavMeshCacheItem& navMeshCacheItem, NavMeshTilesCache& navMeshTilesCache) { - log("update NavMesh with mutiple tiles:", - " agentHeight=", std::setprecision(std::numeric_limits::max_exponent10), - getHeight(settings, agentHalfExtents), - " agentMaxClimb=", std::setprecision(std::numeric_limits::max_exponent10), - getMaxClimb(settings), - " agentRadius=", std::setprecision(std::numeric_limits::max_exponent10), - getRadius(settings, agentHalfExtents), - " changedTile=", changedTile, - " playerTile=", playerTile, - " changedTileDistance=", getDistance(changedTile, playerTile)); + Log(Debug::Debug) << std::fixed << std::setprecision(2) << + "Update NavMesh with multiple tiles:" << + " agentHeight=" << getHeight(settings, agentHalfExtents) << + " agentMaxClimb=" << getMaxClimb(settings) << + " agentRadius=" << getRadius(settings, agentHalfExtents) << + " changedTile=(" << changedTile << ")" << + " playerTile=(" << playerTile << ")" << + " changedTileDistance=" << getDistance(changedTile, playerTile); const auto params = *navMeshCacheItem->lockConst()->getImpl().getParams(); const osg::Vec3f origin(params.orig[0], params.orig[1], params.orig[2]); if (!recastMesh) { - log("ignore add tile: recastMesh is null"); + Log(Debug::Debug) << "Ignore add tile: recastMesh is null"; return navMeshCacheItem->lock()->removeTile(changedTile); } @@ -517,13 +517,13 @@ namespace DetourNavigator if (isEmpty(recastMeshBounds)) { - log("ignore add tile: recastMesh is empty"); + Log(Debug::Debug) << "Ignore add tile: recastMesh is empty"; return navMeshCacheItem->lock()->removeTile(changedTile); } if (!shouldAddTile(changedTile, playerTile, std::min(settings.mMaxTilesNumber, params.maxTiles))) { - log("ignore add tile: too far from player"); + Log(Debug::Debug) << "Ignore add tile: too far from player"; return navMeshCacheItem->lock()->removeTile(changedTile); } @@ -540,7 +540,7 @@ namespace DetourNavigator if (!navMeshData.mValue) { - log("ignore add tile: NavMeshData is null"); + Log(Debug::Debug) << "Ignore add tile: NavMeshData is null"; return navMeshCacheItem->lock()->removeTile(changedTile); } @@ -557,7 +557,7 @@ namespace DetourNavigator if (!cachedNavMeshData) { - log("cache overflow"); + Log(Debug::Debug) << "Navigator cache overflow"; return navMeshCacheItem->lock()->updateTile(changedTile, std::move(navMeshData)); } } diff --git a/components/detournavigator/navmeshmanager.cpp b/components/detournavigator/navmeshmanager.cpp index a43410e91..4bd797326 100644 --- a/components/detournavigator/navmeshmanager.cpp +++ b/components/detournavigator/navmeshmanager.cpp @@ -6,6 +6,8 @@ #include "navmeshcacheitem.hpp" #include "settings.hpp" +#include + #include namespace @@ -95,7 +97,7 @@ namespace DetourNavigator return; mCache.insert(std::make_pair(agentHalfExtents, std::make_shared(makeEmptyNavMesh(mSettings), ++mGenerationCounter))); - log("cache add for agent=", agentHalfExtents); + Log(Debug::Debug) << "cache add for agent=" << agentHalfExtents; } bool NavMeshManager::reset(const osg::Vec3f& agentHalfExtents) @@ -193,9 +195,9 @@ namespace DetourNavigator mAsyncNavMeshUpdater.post(agentHalfExtents, cached, playerTile, tilesToPost); if (changedTiles != mChangedTiles.end()) changedTiles->second.clear(); - log("cache update posted for agent=", agentHalfExtents, - " playerTile=", lastPlayerTile->second, - " recastMeshManagerRevision=", lastRevision); + Log(Debug::Debug) << "cache update posted for agent=" << agentHalfExtents << + " playerTile=" << lastPlayerTile->second << + " recastMeshManagerRevision=" << lastRevision; } void NavMeshManager::wait() diff --git a/docs/source/reference/modding/settings/navigator.rst b/docs/source/reference/modding/settings/navigator.rst index d9ddf5381..42494a476 100644 --- a/docs/source/reference/modding/settings/navigator.rst +++ b/docs/source/reference/modding/settings/navigator.rst @@ -79,27 +79,6 @@ Developer's settings This section is for developers or anyone who wants to investigate how nav mesh system works in OpenMW. -enable log ----------- - -:Type: boolean -:Range: True/False -:Default: False - -Enable debug log. -Detournavigator module will write own debug log into separate file. -Potentially decreases performance. - -log path --------- - -:Type: string -:Range: file system path -:Default: detournavigator.log - -Write debug log to this file. -Try use tmpfs or any other in-memory file system to reduce performance impact. - enable write recast mesh to file --------------------------------