Makefile.am | 3 common/Util.cpp | 25 +++- common/Util.hpp | 3 kit/ForKit.cpp | 1 loolwsd.spec.in | 1 wsd/Admin.cpp | 47 +++++++- wsd/Admin.hpp | 11 + wsd/AdminModel.cpp | 280 ++++++++++++++++++++++++++++++++++++++++++++++++- wsd/AdminModel.hpp | 38 ++++++ wsd/ClientSession.cpp | 6 + wsd/ClientSession.hpp | 3 wsd/DocumentBroker.cpp | 11 + wsd/DocumentBroker.hpp | 3 wsd/LOOLWSD.cpp | 47 +++++++- wsd/Storage.cpp | 3 wsd/Storage.hpp | 3 wsd/metrics.txt | 155 +++++++++++++++++++++++++++ 17 files changed, 621 insertions(+), 19 deletions(-)
New commits: commit 2164f5207c1717173edcd462433bfa0ee3257045 Author: Gabriel Masei <gabriel.ma...@1and1.ro> AuthorDate: Tue Nov 12 11:50:33 2019 +0200 Commit: Michael Meeks <michael.me...@collabora.com> CommitDate: Mon Nov 25 13:06:01 2019 +0100 Add REST endpoint for admin metrics. Change-Id: I701485631931334d27594c4907cb770f9888e5bf Reviewed-on: https://gerrit.libreoffice.org/82492 Reviewed-by: Michael Meeks <michael.me...@collabora.com> Tested-by: Michael Meeks <michael.me...@collabora.com> diff --git a/Makefile.am b/Makefile.am index c2912f279..ac6a45307 100644 --- a/Makefile.am +++ b/Makefile.am @@ -33,7 +33,8 @@ man_MANS = man/loolwsd.1 \ dist_doc_DATA = wsd/README \ wsd/README.vars \ wsd/protocol.txt \ - wsd/reference.md + wsd/reference.md \ + wsd/metrics.txt loolwsddatadir = @LOOLWSD_DATADIR@ diff --git a/common/Util.cpp b/common/Util.cpp index a589785d4..931de51d2 100644 --- a/common/Util.cpp +++ b/common/Util.cpp @@ -195,7 +195,7 @@ namespace Util } // close what we have - far faster than going up to a 1m open_max eg. - static bool closeFdsFromProc() + static bool closeFdsFromProc(std::map<int, int> *mapFdsToKeep = nullptr) { DIR *fdDir = opendir("/proc/self/fd"); if (!fdDir) @@ -219,6 +219,9 @@ namespace Util if (fd < 3) continue; + if (mapFdsToKeep && mapFdsToKeep->find(fd) != mapFdsToKeep->end()) + continue; + if (close(fd) < 0) std::cerr << "Unexpected failure to close fd " << fd << std::endl; } @@ -227,22 +230,23 @@ namespace Util return true; } - static void closeFds() + static void closeFds(std::map<int, int> *mapFdsToKeep = nullptr) { - if (!closeFdsFromProc()) + if (!closeFdsFromProc(mapFdsToKeep)) { std::cerr << "Couldn't close fds efficiently from /proc" << std::endl; for (int fd = 3; fd < sysconf(_SC_OPEN_MAX); ++fd) - close(fd); + if (mapFdsToKeep->find(fd) != mapFdsToKeep->end()) + close(fd); } } - int spawnProcess(const std::string &cmd, const std::vector<std::string> &args, int *stdInput) + int spawnProcess(const std::string &cmd, const std::vector<std::string> &args, const std::vector<int>* fdsToKeep, int *stdInput) { int pipeFds[2] = { -1, -1 }; if (stdInput) { - if (pipe(pipeFds) < 0) + if (pipe2(pipeFds, O_NONBLOCK) < 0) { LOG_ERR("Out of file descriptors spawning " << cmd); throw Poco::SystemException("Out of file descriptors"); @@ -255,6 +259,12 @@ namespace Util params.push_back(const_cast<char *>(i.c_str())); params.push_back(nullptr); + std::map<int, int> mapFdsToKeep; + + if (fdsToKeep) + for (const auto& i : *fdsToKeep) + mapFdsToKeep[i] = i; + int pid = fork(); if (pid < 0) { @@ -266,7 +276,7 @@ namespace Util if (stdInput) dup2(pipeFds[0], STDIN_FILENO); - closeFds(); + closeFds(&mapFdsToKeep); int ret = execvp(params[0], ¶ms[0]); if (ret < 0) @@ -282,6 +292,7 @@ namespace Util } return pid; } + #endif bool dataFromHexString(const std::string& hexString, std::vector<unsigned char>& data) diff --git a/common/Util.hpp b/common/Util.hpp index 82389c1ab..66ce0b5b1 100644 --- a/common/Util.hpp +++ b/common/Util.hpp @@ -69,7 +69,8 @@ namespace Util /// Spawn a process if stdInput is non-NULL it contains a writable descriptor /// to send data to the child. int spawnProcess(const std::string &cmd, const std::vector<std::string> &args, - int *stdInput = nullptr); + const std::vector<int>* fdsToKeep = nullptr, int *stdInput = nullptr); + #endif /// Hex to unsigned char diff --git a/kit/ForKit.cpp b/kit/ForKit.cpp index 62491374c..164489589 100644 --- a/kit/ForKit.cpp +++ b/kit/ForKit.cpp @@ -209,6 +209,7 @@ static void cleanupChildren() std::vector<std::string> jails; Process::PID exitedChildPid; int status; + // Reap quickly without doing slow cleanup so WSD can spawn more rapidly. while ((exitedChildPid = waitpid(-1, &status, WUNTRACED | WNOHANG)) > 0) { diff --git a/loolwsd.spec.in b/loolwsd.spec.in index 790e12f67..d78760e82 100644 --- a/loolwsd.spec.in +++ b/loolwsd.spec.in @@ -106,6 +106,7 @@ echo "account required pam_unix.so" >> %{buildroot}/etc/pam.d/loolwsd /usr/share/doc/loolwsd/README.vars /usr/share/doc/loolwsd/protocol.txt /usr/share/doc/loolwsd/reference.md +/usr/share/doc/loolwsd/metrics.txt /usr/share/man/man1/loolwsd.1 /usr/share/man/man1/loolforkit.1 /usr/share/man/man1/loolconvert.1 diff --git a/wsd/Admin.cpp b/wsd/Admin.cpp index 3e64b5a1f..c4c48dfeb 100644 --- a/wsd/Admin.cpp +++ b/wsd/Admin.cpp @@ -504,7 +504,7 @@ size_t Admin::getTotalMemoryUsage() // memory to the forkit; and then count only dirty pages in the clients // since we know that they share everything else with the forkit. const size_t forkitRssKb = Util::getMemoryUsageRSS(_forKitPid); - const size_t wsdPssKb = Util::getMemoryUsagePSS(Poco::Process::id()); + const size_t wsdPssKb = Util::getMemoryUsagePSS(getpid()); const size_t kitsDirtyKb = _model.getKitsMemoryUsage(); const size_t totalMem = wsdPssKb + forkitRssKb + kitsDirtyKb; @@ -514,7 +514,7 @@ size_t Admin::getTotalMemoryUsage() size_t Admin::getTotalCpuUsage() { const size_t forkitJ = Util::getCpuUsage(_forKitPid); - const size_t wsdJ = Util::getCpuUsage(Poco::Process::id()); + const size_t wsdJ = Util::getCpuUsage(getpid()); const size_t kitsJ = _model.getKitsJiffies(); if (_lastJiffies == 0) @@ -564,6 +564,21 @@ void Admin::addBytes(const std::string& docKey, uint64_t sent, uint64_t recv) addCallback([=] { _model.addBytes(docKey, sent, recv); }); } +void Admin::setViewLoadDuration(const std::string& docKey, const std::string& sessionId, std::chrono::milliseconds viewLoadDuration) +{ + addCallback([=]{ _model.setViewLoadDuration(docKey, sessionId, viewLoadDuration); }); +} + +void Admin::setDocWopiDownloadDuration(const std::string& docKey, std::chrono::milliseconds wopiDownloadDuration) +{ + addCallback([=]{ _model.setDocWopiDownloadDuration(docKey, wopiDownloadDuration); }); +} + +void Admin::setDocWopiUploadDuration(const std::string& docKey, const std::chrono::milliseconds uploadDuration) +{ + addCallback([=]{ _model.setDocWopiUploadDuration(docKey, uploadDuration); }); +} + void Admin::notifyForkit() { std::ostringstream oss; @@ -688,6 +703,34 @@ void Admin::scheduleMonitorConnect(const std::string &uri, std::chrono::steady_c _pendingConnects.push_back(todo); } +void Admin::getMetrics(std::ostringstream &metrics) +{ + size_t memAvail = getTotalAvailableMemory(); + size_t memUsed = getTotalMemoryUsage(); + + metrics << "global_host_system_memory_bytes " << _totalSysMemKb * 1024 << std::endl; + metrics << "global_memory_available_bytes " << memAvail * 1024 << std::endl; + metrics << "global_memory_used_bytes " << memUsed * 1024 << std::endl; + metrics << "global_memory_free_bytes " << (memAvail - memUsed) * 1024 << std::endl; + metrics << std::endl; + + _model.getMetrics(metrics); +} + +void Admin::sendMetrics(const std::shared_ptr<StreamSocket>& socket, const std::shared_ptr<Poco::Net::HTTPResponse>& response) +{ + std::ostringstream oss; + response->write(oss); + getMetrics(oss); + socket->send(oss.str()); + socket->shutdown(); +} + +void Admin::sendMetricsAsync(const std::shared_ptr<StreamSocket>& socket, const std::shared_ptr<Poco::Net::HTTPResponse>& response) +{ + addCallback([this, socket, response]{ sendMetrics(socket, response); }); +} + void Admin::start() { bool haveMonitors = false; diff --git a/wsd/Admin.hpp b/wsd/Admin.hpp index f29ea2c4f..2157def98 100644 --- a/wsd/Admin.hpp +++ b/wsd/Admin.hpp @@ -90,7 +90,7 @@ public: /// Remove the document with all views. Used on termination or catastrophic failure. void rmDoc(const std::string& docKey); - void setForKitPid(const int forKitPid) { _forKitPid = forKitPid; } + void setForKitPid(const int forKitPid) { _forKitPid = forKitPid; _model.setForKitPid(forKitPid);} void setForKitWritePipe(const int forKitWritePipe) { _forKitWritePipe = forKitWritePipe; } /// Callers must ensure that modelMutex is acquired @@ -123,6 +123,15 @@ public: /// Attempt a synchronous connection to a monitor with @uri @when that future comes void scheduleMonitorConnect(const std::string &uri, std::chrono::steady_clock::time_point when); + void sendMetrics(const std::shared_ptr<StreamSocket>& socket, const std::shared_ptr<Poco::Net::HTTPResponse>& response); + void sendMetricsAsync(const std::shared_ptr<StreamSocket>& socket, const std::shared_ptr<Poco::Net::HTTPResponse>& response); + + void setViewLoadDuration(const std::string& docKey, const std::string& sessionId, std::chrono::milliseconds viewLoadDuration); + void setDocWopiDownloadDuration(const std::string& docKey, std::chrono::milliseconds wopiDownloadDuration); + void setDocWopiUploadDuration(const std::string& docKey, const std::chrono::milliseconds uploadDuration); + + void getMetrics(std::ostringstream &metrics); + private: /// Notify Forkit of changed settings. void notifyForkit(); diff --git a/wsd/AdminModel.cpp b/wsd/AdminModel.cpp index f5232d6db..f8302f842 100644 --- a/wsd/AdminModel.cpp +++ b/wsd/AdminModel.cpp @@ -27,6 +27,9 @@ #include <Util.hpp> #include <wsd/LOOLWSD.hpp> +#include <fnmatch.h> +#include <dirent.h> + void Document::addView(const std::string& sessionId, const std::string& userName, const std::string& userId) { const auto ret = _views.emplace(sessionId, View(sessionId, userName, userId)); @@ -56,6 +59,13 @@ int Document::expireView(const std::string& sessionId) return _activeViews; } +void Document::setViewLoadDuration(const std::string& sessionId, std::chrono::milliseconds viewLoadDuration) +{ + std::map<std::string, View>::iterator it = _views.find(sessionId); + if (it != _views.end()) + it->second.setLoadDuration(viewLoadDuration); +} + std::pair<std::time_t, std::string> Document::getSnapshot() const { std::time_t ct = std::time(nullptr); @@ -529,7 +539,7 @@ void AdminModel::removeDocument(const std::string& docKey, const std::string& se // to the admin console with views. if (docIt->second.expireView(sessionId) == 0) { - _expiredDocuments.emplace(*docIt); + _expiredDocuments.emplace(docIt->first + std::to_string(std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::steady_clock::now().time_since_epoch()).count()), docIt->second); _documents.erase(docIt); } } @@ -555,7 +565,7 @@ void AdminModel::removeDocument(const std::string& docKey) } LOG_DBG("Removed admin document [" << docKey << "]."); - _expiredDocuments.emplace(*docIt); + _expiredDocuments.emplace(docIt->first + std::to_string(std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::steady_clock::now().time_since_epoch()).count()), docIt->second); _documents.erase(docIt); } } @@ -740,4 +750,270 @@ double AdminModel::getServerUptime() return uptime.count(); } +void AdminModel::setViewLoadDuration(const std::string& docKey, const std::string& sessionId, std::chrono::milliseconds viewLoadDuration) +{ + std::map<std::string, Document>::iterator it = _documents.find(docKey); + if (it != _documents.end()) + it->second.setViewLoadDuration(sessionId, viewLoadDuration); +} + +void AdminModel::setDocWopiDownloadDuration(const std::string& docKey, std::chrono::milliseconds wopiDownloadDuration) +{ + std::map<std::string, Document>::iterator it = _documents.find(docKey); + if (it != _documents.end()) + it->second.setWopiDownloadDuration(wopiDownloadDuration); +} + +void AdminModel::setDocWopiUploadDuration(const std::string& docKey, const std::chrono::milliseconds wopiUploadDuration) +{ + std::map<std::string, Document>::iterator it = _documents.find(docKey); + if (it != _documents.end()) + it->second.setWopiUploadDuration(wopiUploadDuration); +} + +int filterNumberName(const struct dirent *dir) +{ + return !fnmatch("[0-9]*", dir->d_name, 0); +} + +int AdminModel::getPidsFromProcName(const std::regex& procNameRegEx, std::vector<int> *pids) +{ + struct dirent **namelist = NULL; + int n = scandir("/proc", &namelist, filterNumberName, 0); + int pidCount = 0; + + if (n < 0) + return n; + + std::string comm; + char line[256] = { 0 }; //Here we need only 16 bytes but for safety reasons we use file name max length + + if (pids != NULL) + pids->clear(); + + while (n--) + { + comm = "/proc/"; + comm += namelist[n]->d_name; + comm += "/comm"; + FILE* fp = fopen(comm.c_str(), "r"); + if (fp != nullptr) + { + if (fgets(line, sizeof (line), fp)) + { + char *nl = strchr(line, '\n'); + if (nl != NULL) + *nl = 0; + if (regex_match(line, procNameRegEx)) + { + pidCount ++; + if (pids) + pids->push_back(strtol(namelist[n]->d_name, NULL, 10)); + } + } + fclose(fp); + } + free(namelist[n]); + } + free(namelist); + + return pidCount; +} + +class AggregateStats +{ +public: + AggregateStats() + : _total(0), _min(0xFFFFFFFFFFFFFFFF), _max(0), _count(0) + {} + + void Update(uint64_t value) + { + _total += value; + _min = (_min > value ? value : _min); + _max = (_max < value ? value : _max); + _count ++; + } + + uint64_t getIntAverage() const { return _count ? std::round(_total / (double)_count) : 0; } + double getDoubleAverage() const { return _count ? _total / (double) _count : 0; } + uint64_t getMin() const { return _min == 0xFFFFFFFFFFFFFFFF ? 0 : _min; } + uint64_t getMax() const { return _max; } + uint64_t getTotal() const { return _total; } + uint64_t getCount() const { return _count; } + + void Print(std::ostringstream &oss, const char *prefix, const char* unit) const + { + std::string newUnit = std::string(unit && unit[0] ? "_" : "") + unit; + std::string newPrefix = prefix + std::string(prefix && prefix[0] ? "_" : ""); + + oss << newPrefix << "total" << newUnit << " " << _total << std::endl; + oss << newPrefix << "average" << newUnit << " " << getIntAverage() << std::endl; + oss << newPrefix << "min" << newUnit << " " << getMin() << std::endl; + oss << newPrefix << "max" << newUnit << " " << _max << std::endl; + } + +private: + uint64_t _total; + uint64_t _min; + uint64_t _max; + uint32_t _count; +}; + +struct ActiveExpiredStats +{ +public: + + void Update(uint64_t value, bool active) + { + _all.Update(value); + if (active) + _active.Update(value); + else + _expired.Update(value); + } + + void Print(std::ostringstream &oss, const char *prefix, const char* name, const char* unit) const + { + std::ostringstream ossTmp; + std::string newName = std::string(name && name[0] ? "_" : "") + name; + std::string newPrefix = prefix + std::string(prefix && prefix[0] ? "_" : ""); + + ossTmp << newPrefix << "all" << newName; + _all.Print(oss, ossTmp.str().c_str(), unit); + ossTmp.str(std::string()); + ossTmp << newPrefix << "active" << newName; + _active.Print(oss, ossTmp.str().c_str(), unit); + ossTmp.str(std::string()); + ossTmp << newPrefix << "expired" << newName; + _expired.Print(oss, ossTmp.str().c_str(), unit); + } + + AggregateStats _all; + AggregateStats _active; + AggregateStats _expired; +}; + +struct DocumentAggregateStats +{ + void Update(const Document &d, bool active) + { + _kitUsedMemory.Update(d.getMemoryDirty(), active); + _viewsCount.Update(d.getViews().size(), active); + _activeViewsCount.Update(d.getActiveViews(), active); + _expiredViewsCount.Update(d.getViews().size() - d.getActiveViews(), active); + _openedTime.Update(d.getOpenTime(), active); + _bytesSentToClients.Update(d.getSentBytes(), active); + _bytesRecvFromClients.Update(d.getRecvBytes(), active); + _wopiDownloadDuration.Update(d.getWopiDownloadDuration().count(), active); + _wopiUploadDuration.Update(d.getWopiUploadDuration().count(), active); + + //View load duration + for (const auto& v : d.getViews()) + _viewLoadDuration.Update(v.second.getLoadDuration().count(), active); + } + + ActiveExpiredStats _kitUsedMemory; + ActiveExpiredStats _viewsCount; + ActiveExpiredStats _activeViewsCount; + ActiveExpiredStats _expiredViewsCount; + ActiveExpiredStats _openedTime; + ActiveExpiredStats _bytesSentToClients; + ActiveExpiredStats _bytesRecvFromClients; + ActiveExpiredStats _wopiDownloadDuration; + ActiveExpiredStats _wopiUploadDuration; + ActiveExpiredStats _viewLoadDuration; +}; + +struct KitProcStats +{ + void UpdateAggregateStats(int pid) + { + _threadCount.Update(Util::getStatFromPid(pid, 19)); + _cpuTime.Update(Util::getCpuUsage(pid)); + } + + int unassignedCount; + int assignedCount; + AggregateStats _threadCount; + AggregateStats _cpuTime; +}; + +void AdminModel::CalcDocAggregateStats(DocumentAggregateStats& stats) +{ + for (auto& d : _documents) + stats.Update(d.second, true); + + for (auto& d : _expiredDocuments) + stats.Update(d.second, false); +} + +void CalcKitStats(KitProcStats& stats) +{ + std::vector<int> childProcs; + stats.unassignedCount = AdminModel::getPidsFromProcName(std::regex("kit_spare_[0-9]*"), &childProcs); + stats.assignedCount = AdminModel::getPidsFromProcName(std::regex("kitbroker_[0-9]*"), &childProcs); + for (int& pid : childProcs) + { + stats.UpdateAggregateStats(pid); + } +} + +void PrintDocActExpMetrics(std::ostringstream &oss, const char* name, const char* unit, const ActiveExpiredStats &values) +{ + values.Print(oss, "document", name, unit); +} + +void PrintKitAggregateMetrics(std::ostringstream &oss, const char* name, const char* unit, const AggregateStats &values) +{ + std::string prefix = std::string("kit_") + name; + values.Print(oss, prefix.c_str(), unit); +} + +void AdminModel::getMetrics(std::ostringstream &oss) +{ + oss << "loolwsd_count " << getPidsFromProcName(std::regex("loolwsd"), nullptr) << std::endl; + oss << "loolwsd_thread_count " << Util::getStatFromPid(getpid(), 19) << std::endl; + oss << "loolwsd_cpu_time_seconds " << Util::getCpuUsage(getpid()) / sysconf (_SC_CLK_TCK) << std::endl; + oss << "loolwsd_memory_used_bytes " << Util::getMemoryUsagePSS(getpid()) * 1024 << std::endl; + oss << std::endl; + + oss << "forkit_count " << getPidsFromProcName(std::regex("forkit"), nullptr) << std::endl; + oss << "forkit_thread_count " << Util::getStatFromPid(_forKitPid, 19) << std::endl; + oss << "forkit_cpu_time_seconds " << Util::getCpuUsage(_forKitPid) / sysconf (_SC_CLK_TCK) << std::endl; + oss << "forkit_memory_used_bytes " << Util::getMemoryUsageRSS(_forKitPid) * 1024 << std::endl; + oss << std::endl; + + DocumentAggregateStats docStats; + KitProcStats kitStats; + + CalcDocAggregateStats(docStats); + CalcKitStats(kitStats); + + oss << "kit_count " << kitStats.unassignedCount + kitStats.assignedCount << std::endl; + oss << "kit_unassigned_count " << kitStats.unassignedCount << std::endl; + oss << "kit_assigned_count " << kitStats.assignedCount << std::endl; + PrintKitAggregateMetrics(oss, "thread_count", "", kitStats._threadCount); + PrintKitAggregateMetrics(oss, "memory_used", "bytes", docStats._kitUsedMemory._all); + PrintKitAggregateMetrics(oss, "cpu_time", "seconds", kitStats._cpuTime); + oss << std::endl; + + PrintDocActExpMetrics(oss, "views_all_count", "", docStats._viewsCount); + docStats._activeViewsCount._active.Print(oss, "document_active_views_active_count", ""); + docStats._expiredViewsCount._active.Print(oss, "document_active_views_expired_count", ""); + oss << std::endl; + + PrintDocActExpMetrics(oss, "opened_time", "seconds", docStats._openedTime); + oss << std::endl; + PrintDocActExpMetrics(oss, "sent_to_clients", "bytes", docStats._bytesSentToClients); + oss << std::endl; + PrintDocActExpMetrics(oss, "received_from_client", "bytes", docStats._bytesRecvFromClients); + oss << std::endl; + PrintDocActExpMetrics(oss, "wopi_upload_duration", "milliseconds", docStats._wopiUploadDuration); + oss << std::endl; + PrintDocActExpMetrics(oss, "wopi_download_duration", "milliseconds", docStats._wopiDownloadDuration); + oss << std::endl; + PrintDocActExpMetrics(oss, "view_load_duration", "milliseconds", docStats._viewLoadDuration); +} + /* vim:set shiftwidth=4 softtabstop=4 expandtab: */ diff --git a/wsd/AdminModel.hpp b/wsd/AdminModel.hpp index 57e7193e1..4fd736b50 100644 --- a/wsd/AdminModel.hpp +++ b/wsd/AdminModel.hpp @@ -13,6 +13,7 @@ #include <memory> #include <set> #include <string> +#include <cmath> #include <Poco/Process.h> @@ -20,6 +21,8 @@ #include "net/WebSocketHandler.hpp" #include "Util.hpp" +class DocumentAggregateStats; + /// A client view in Admin controller. class View { @@ -28,7 +31,8 @@ public: _sessionId(sessionId), _userName(userName), _userId(userId), - _start(std::time(nullptr)) + _start(std::time(nullptr)), + _loadDuration(0) { } @@ -37,6 +41,8 @@ public: std::string getUserId() const { return _userId; } std::string getSessionId() const { return _sessionId; } bool isExpired() const { return _end != 0 && std::time(nullptr) >= _end; } + std::chrono::milliseconds getLoadDuration() const { return _loadDuration; } + void setLoadDuration(std::chrono::milliseconds loadDuration) { _loadDuration = loadDuration; } private: const std::string _sessionId; @@ -44,6 +50,7 @@ private: const std::string _userId; const std::time_t _start; std::time_t _end = 0; + std::chrono::milliseconds _loadDuration; }; struct DocProcSettings @@ -108,6 +115,8 @@ public: _end(0), _sentBytes(0), _recvBytes(0), + _wopiDownloadDuration(0), + _wopiUploadDuration(0), _isModified(false) { } @@ -155,6 +164,15 @@ public: const DocProcSettings& getDocProcSettings() const { return _docProcSettings; } void setDocProcSettings(const DocProcSettings& docProcSettings) { _docProcSettings = docProcSettings; } + std::time_t getOpenTime() const { return isExpired() ? _end - _start : getElapsedTime(); } + uint64_t getSentBytes() const { return _sentBytes; } + uint64_t getRecvBytes() const { return _recvBytes; } + void setViewLoadDuration(const std::string& sessionId, std::chrono::milliseconds viewLoadDuration); + void setWopiDownloadDuration(std::chrono::milliseconds wopiDownloadDuration) { _wopiDownloadDuration = wopiDownloadDuration; } + std::chrono::milliseconds getWopiDownloadDuration() const { return _wopiDownloadDuration; } + void setWopiUploadDuration(const std::chrono::milliseconds wopiUploadDuration) { _wopiUploadDuration = wopiUploadDuration; } + std::chrono::milliseconds getWopiUploadDuration() const { return _wopiUploadDuration; } + std::string to_string() const; private: @@ -179,6 +197,10 @@ private: /// Total bytes sent and recv'd by this document. uint64_t _sentBytes, _recvBytes; + //Download/upload duration from/to storage for this document + std::chrono::milliseconds _wopiDownloadDuration; + std::chrono::milliseconds _wopiUploadDuration; + /// Per-doc kit process settings. DocProcSettings _docProcSettings; bool _isModified; @@ -224,6 +246,7 @@ private: class AdminModel { public: + AdminModel() : _owner(std::this_thread::get_id()) { @@ -289,6 +312,15 @@ public: /// Document basic info list sorted by most idle time std::vector<DocBasicInfo> getDocumentsSortedByIdle() const; + void setViewLoadDuration(const std::string& docKey, const std::string& sessionId, std::chrono::milliseconds viewLoadDuration); + void setDocWopiDownloadDuration(const std::string& docKey, std::chrono::milliseconds wopiDownloadDuration); + void setDocWopiUploadDuration(const std::string& docKey, const std::chrono::milliseconds wopiUploadDuration); + void setForKitPid(pid_t pid) { _forKitPid = pid; } + + void getMetrics(std::ostringstream &oss); + + static int getPidsFromProcName(const std::regex& procNameRegEx, std::vector<int> *pids); + private: std::string getMemStats(); @@ -302,6 +334,8 @@ private: std::string getDocuments() const; + void CalcDocAggregateStats(DocumentAggregateStats& stats); + private: std::map<int, Subscriber> _subscribers; std::map<std::string, Document> _documents; @@ -323,6 +357,8 @@ private: uint64_t _sentBytesTotal; uint64_t _recvBytesTotal; + pid_t _forKitPid; + /// We check the owner even in the release builds, needs to be always correct. std::thread::id _owner; }; diff --git a/wsd/ClientSession.cpp b/wsd/ClientSession.cpp index c55985a9f..db51d5836 100644 --- a/wsd/ClientSession.cpp +++ b/wsd/ClientSession.cpp @@ -740,6 +740,7 @@ bool ClientSession::loadDocument(const char* /*buffer*/, int /*length*/, return false; } + _viewLoadStart = std::chrono::steady_clock::now(); LOG_INF("Requesting document load from child."); try { @@ -1361,6 +1362,11 @@ bool ClientSession::handleKitToClientMessage(const char* buffer, const int lengt { setState(ClientSession::SessionState::LIVE); docBroker->setLoaded(); + +#if !MOBILEAPP + Admin::instance().setViewLoadDuration(docBroker->getDocKey(), getId(), std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::steady_clock::now() - _viewLoadStart)); +#endif + // Wopi post load actions if (_wopiFileInfo && !_wopiFileInfo->getTemplateSource().empty()) { diff --git a/wsd/ClientSession.hpp b/wsd/ClientSession.hpp index d4b31dbea..770371df0 100644 --- a/wsd/ClientSession.hpp +++ b/wsd/ClientSession.hpp @@ -275,6 +275,9 @@ private: /// Sockets to send binary selection content to std::vector<std::weak_ptr<StreamSocket>> _clipSockets; + + ///Time when loading of view started + std::chrono::steady_clock::time_point _viewLoadStart; }; diff --git a/wsd/DocumentBroker.cpp b/wsd/DocumentBroker.cpp index ef1ad7ed6..d243a338c 100644 --- a/wsd/DocumentBroker.cpp +++ b/wsd/DocumentBroker.cpp @@ -191,7 +191,8 @@ DocumentBroker::DocumentBroker(const std::string& uri, _closeReason("stopped"), _lockCtx(new LockContext()), _tileVersion(0), - _debugRenderedTileCount(0) + _debugRenderedTileCount(0), + _wopiLoadDuration(0) { assert(!_docKey.empty()); assert(!LOOLWSD::ChildRoot.empty()); @@ -837,6 +838,7 @@ bool DocumentBroker::load(const std::shared_ptr<ClientSession>& session, const s auto callDuration = wopiStorage->getWopiLoadDuration(); // Add the time taken to check file info callDuration += getInfoCallDuration; + _wopiLoadDuration = std::chrono::duration_cast<std::chrono::milliseconds>(callDuration); const std::string msg = "stats: wopiloadduration " + std::to_string(callDuration.count()); LOG_TRC("Sending to Client [" << msg << "]."); session->sendTextFrame(msg); @@ -965,6 +967,12 @@ bool DocumentBroker::saveToStorageInternal(const std::string& sessionId, bool su auth, *_lockCtx, saveAsPath, saveAsFilename, isRename); if (storageSaveResult.getResult() == StorageBase::SaveResult::OK) { +#if !MOBILEAPP + WopiStorage* wopiStorage = dynamic_cast<WopiStorage*>(_storage.get()); + if (wopiStorage != nullptr) + Admin::instance().setDocWopiUploadDuration(_docKey, std::chrono::duration_cast<std::chrono::milliseconds>(wopiStorage->getWopiSaveDuration())); +#endif + if (!isSaveAs && !isRename) { // Saved and stored; update flags. @@ -1280,6 +1288,7 @@ size_t DocumentBroker::addSessionInternal(const std::shared_ptr<ClientSession>& #if !MOBILEAPP // Tell the admin console about this new doc Admin::instance().addDoc(_docKey, getPid(), getFilename(), id, session->getUserName(), session->getUserId()); + Admin::instance().setDocWopiDownloadDuration(_docKey, _wopiLoadDuration); #endif // Add and attach the session. diff --git a/wsd/DocumentBroker.hpp b/wsd/DocumentBroker.hpp index 5c0a83b07..f0a1ac061 100644 --- a/wsd/DocumentBroker.hpp +++ b/wsd/DocumentBroker.hpp @@ -33,6 +33,8 @@ #include "common/SigUtil.hpp" +#include "Admin.hpp" + // Forwards. class PrisonerRequestDispatcher; class DocumentBroker; @@ -500,6 +502,7 @@ private: std::chrono::steady_clock::time_point _lastActivityTime; std::chrono::steady_clock::time_point _threadStart; std::chrono::milliseconds _loadDuration; + std::chrono::milliseconds _wopiLoadDuration; /// Unique DocBroker ID for tracing and debugging. static std::atomic<unsigned> DocBrokerId; diff --git a/wsd/LOOLWSD.cpp b/wsd/LOOLWSD.cpp index 2b70488a9..a5dee7870 100644 --- a/wsd/LOOLWSD.cpp +++ b/wsd/LOOLWSD.cpp @@ -378,7 +378,7 @@ static int forkChildren(const int number) #else const std::string aMessage = "spawn " + std::to_string(number) + "\n"; LOG_DBG("MasterToForKit: " << aMessage.substr(0, aMessage.length() - 1)); - if (IoUtil::writeToPipe(LOOLWSD::ForKitWritePipe, aMessage) > 0) + if (write(LOOLWSD::ForKitWritePipe, aMessage.c_str(), aMessage.length()) > 0) #endif { OutstandingForks += number; @@ -1667,7 +1667,7 @@ bool LOOLWSD::createForKit() LastForkRequestTime = std::chrono::steady_clock::now(); int childStdin = -1; - int child = Util::spawnProcess(forKitPath, args, &childStdin); + int child = Util::spawnProcess(forKitPath, args, nullptr, &childStdin); ForKitWritePipe = childStdin; ForKitProcId = child; @@ -2167,6 +2167,47 @@ private: } } + else if (reqPathSegs.size() >= 2 && reqPathSegs[0] == "lool" && reqPathSegs[1] == "getMetrics") + { + //See metrics.txt + std::shared_ptr<Poco::Net::HTTPResponse> response(new Poco::Net::HTTPResponse()); + + if (!LOOLWSD::AdminEnabled) + throw Poco::FileAccessDeniedException("Admin console disabled"); + + try{ + if (!FileServerRequestHandler::isAdminLoggedIn(request, *response.get())) + throw Poco::Net::NotAuthenticatedException("Invalid admin login"); + } + catch (const Poco::Net::NotAuthenticatedException& exc) + { + //LOG_ERR("FileServerRequestHandler::NotAuthenticated: " << exc.displayText()); + std::ostringstream oss; + oss << "HTTP/1.1 401 \r\n" + << "Content-Type: text/html charset=UTF-8\r\n" + << "Date: " << Poco::DateTimeFormatter::format(Poco::Timestamp(), Poco::DateTimeFormat::HTTP_FORMAT) << "\r\n" + << "User-Agent: " << WOPI_AGENT_STRING << "\r\n" + << "WWW-authenticate: Basic realm=\"online\"\r\n" + << "\r\n"; + socket->send(oss.str()); + socket->shutdown(); + return; + } + + response->add("Last-Modified", Poco::DateTimeFormatter::format(Poco::Timestamp(), Poco::DateTimeFormat::HTTP_FORMAT)); + // Ask UAs to block if they detect any XSS attempt + response->add("X-XSS-Protection", "1; mode=block"); + // No referrer-policy + response->add("Referrer-Policy", "no-referrer"); + response->add("User-Agent", HTTP_AGENT_STRING); + response->add("Content-Type", "text/plain"); + response->add("X-Content-Type-Options", "nosniff"); + + disposition.setMove([response](const std::shared_ptr<Socket> &moveSocket){ + const std::shared_ptr<StreamSocket> streamSocket = std::static_pointer_cast<StreamSocket>(moveSocket); + Admin::instance().sendMetricsAsync(streamSocket, response); + }); + } // Client post and websocket connections else if ((request.getMethod() == HTTPRequest::HTTP_GET || request.getMethod() == HTTPRequest::HTTP_HEAD) && @@ -3516,7 +3557,7 @@ int LOOLWSD::innerMain() // atexit handlers tend to free Admin before Documents LOG_INF("Exiting. Cleaning up lingering documents."); -#ifndef MOBILEAPP +#if !MOBILEAPP if (!SigUtil::getShutdownRequestFlag()) { // This shouldn't happen, but it's fail safe to always cleanup properly. diff --git a/wsd/Storage.cpp b/wsd/Storage.cpp index cc380ae7d..45198ad77 100644 --- a/wsd/Storage.cpp +++ b/wsd/Storage.cpp @@ -858,6 +858,7 @@ StorageBase::SaveResult WopiStorage::saveLocalFileToStorage(const Authorization& LOG_INF("Uploading URI via WOPI [" << uriAnonym << "] from [" << filePathAnonym + "]."); StorageBase::SaveResult saveResult(StorageBase::SaveResult::FAILED); + const auto startTime = std::chrono::steady_clock::now(); try { std::unique_ptr<Poco::Net::HTTPClientSession> psession(getHTTPClientSession(uriObject)); @@ -945,6 +946,8 @@ StorageBase::SaveResult WopiStorage::saveLocalFileToStorage(const Authorization& Poco::Net::HTTPResponse response; std::istream& rs = psession->receiveResponse(response); + _wopiSaveDuration = std::chrono::steady_clock::now() - startTime; + std::ostringstream oss; Poco::StreamCopier::copyStream(rs, oss); std::string responseString = oss.str(); diff --git a/wsd/Storage.hpp b/wsd/Storage.hpp index 655e089b4..cad148c7e 100644 --- a/wsd/Storage.hpp +++ b/wsd/Storage.hpp @@ -325,6 +325,7 @@ public: const std::string& jailPath) : StorageBase(uri, localStorePath, jailPath), _wopiLoadDuration(0), + _wopiSaveDuration(0), _reuseCookies(false) { const auto& app = Poco::Util::Application::instance(); @@ -548,10 +549,12 @@ public: /// Total time taken for making WOPI calls during load std::chrono::duration<double> getWopiLoadDuration() const { return _wopiLoadDuration; } + std::chrono::duration<double> getWopiSaveDuration() const { return _wopiSaveDuration; } private: // Time spend in loading the file from storage std::chrono::duration<double> _wopiLoadDuration; + std::chrono::duration<double> _wopiSaveDuration; /// Whether or not to re-use cookies from the browser for the WOPI requests. bool _reuseCookies; }; diff --git a/wsd/metrics.txt b/wsd/metrics.txt new file mode 100644 index 000000000..f12c3fe64 --- /dev/null +++ b/wsd/metrics.txt @@ -0,0 +1,155 @@ +Below is the description of the metrics returned by 'getMetrics' REST endpoint. +The general format of the output is complient with Prometheus text-based format +which can be found here: https://prometheus.io/docs/instrumenting/exposition_formats/#text-based-format + +GLOBAL + + global_host_system_memory_bytes - Total host system memory in bytes. + global_memory_available_bytes – Memory available to our application in bytes. This is equal to global_host_system_memory_bytes * memproportion where memproportion represents the maximum percentage of system memory consumed by all of the LibreOffice Online, after which we start cleaning up idle documents. This parameter can be setup in loolwsd.xml. + global_memory_used_bytes – Total memory usage: PSS(loolwsd) + RSS(forkit) + Private_Dirty(all assigned loolkits). + global_memory_free_bytes - global_memory_available_bytes - global_memory_used_bytes + +LOOLWSD + + loolwsd_count – number of running loolwsd processes. + loolwsd_thread_count – number of threads in the current loolwsd process. + loolwsd_cpu_time_seconds – the CPU usage by current loolwsd process. + loolwsd_memory_used_bytes – the memory used by current loolwsd process: PSS(loolwsd). + +FORKIT + + forkit_process_count – number of running forkit processes. + forkit_thread_count – number of threads in the current forkit process. + forkit_cpu_time_seconds – the CPU usage by the current forkit process. + forkit_memory_used_bytes - the memory used by the current forkit process: RSS(forkit). + +KITS + + kit_count – total number of running kit processes. + kit_unassigned_count – number of running kit processes that are not assigned to documents. + kit_assigned_count – number of running kit processes that are assigned to documents. + kit_thread_count_total - total number of threads in all running kit processes. + kit_thread_count_average – average number of threads per running kit process. + kit_thread_count_min - minimum from the number of threads in each running kit process. + kit_thread_count_max – maximum from the number of threads in each running kit process. + kit_memory_used_total_bytes – total Private_Dirty memory used by all running kit processes. + kit_memory_used_average_bytes – average between the Private_Dirty memory used by each active kit process. + kit_memory_used_min_bytes – minimum from the Private_Dirty memory used by each running kit process. + kit_memory_used_max_bytes - maximum from the Private_Dirty memory used by each running kit process. + kit_cpu_time_total_seconds – total CPU time for all running kit processes. + kit_cpu_time_average_seconds – average between the CPU time each running kit process used. + kit_cpu_time_min_seconds – minimum from the CPU time each running kit process used. + kit_cpu_time_max_seconds - maximum from the CPU time each running kit process used. + +DOCUMENT VIEWS + + document_all_views_all_count_total - total number of views (active or expired) of all documents (active and expired). + document_all_views_all_count_average – average between the number of all views (active or expired) per document (active or expired). + document_all_views_all_count_min – minimum from the number of all views (active or expired) of each document (active or expired). + document_all_views_all_count_max – maximum from the number of all views (active or expired) of each document (active or expired). + document_active_views_all_count_total - total number of all views (active or expired) of active documents. + document_active_views_all_count_average – average between the number of all views (active or expired) of each active document. + document_active_views_all_count_min – minimum from the number of all views (active or expired) of each active document. + document_active_views_all_count_max – maximum from the number of all views (active or expired) of each active document. + document_expired_views_all_count_total - total number of all views (active or expired) of expired documents. + document_expired_views_all_count_average – average between the number of all views (active or expired) of each expired document. + document_expired_views_all_count_min – minimum from the number of all views (active or expired) of each expired document. + document_expired_views_all_count_max – maximum from the number of all views (active or expired) of each expired document. + document_active_views_active_count_total – total number of active views of all active documents. + document_active_views_active_count_average – average between the number of active views of each active document. + document_active_views_active_count_min – minimum from the number of active views of each active document. + document_active_views_active_count_max – maximum from the number of active views of each active document. + document_active_views_expired_count_total – total number of expired views of all active documents. + document_active_views_expired_count_average – average between the number of expired views of each active document. + document_active_views_expired_count_min – minimum from the number of expired views of each active document. + document_active_views_expired_count_max – maximum from the number of expired views of each active document. + +DOCUMENT OPENED TIME + + document_all_opened_time_total_seconds - sum of time each document (active or expired) was kept opened. + document_all_opened_time_average_seconds – average between the time intervals each document (active or expired) was kept opened. + document_all_opened_time_min_seconds – minimum from the time intervals each document (active or expired) was kept opened. + document_all_opened_time_max_seconds - maximum from the time intervals each document (active or expired) was kept opened. + document_active_opened_time_total_seconds - sum of time each active document was kept opened. + document_active_opened_time_average_seconds – average between the time intervals each active document was kept opened. + document_active_opened_time_min_seconds - minimum from the time intervals each active document was kept opened. + document_active_opened_time_max_seconds - maximum from the time intervals each active document was kept opened. + document_expired_opened_time_total_seconds - sum of time each expired document was kept opened. + document_expired_opened_time_average_seconds – average between the time intervals each expired document was kept opened. + document_expired_opened_time_min_seconds - minimum from the time intervals each expired document was kept opened. + document_expired_opened_time_max_seconds – maximum from the time intervals each expired document was kept opened. + +DOCUMENT BYTES SENT TO CLIENTS + + document_all_sent_to_clients_total_bytes - total number of bytes sent to clients by all documents (active or expired). + document_all_sent_to_clients_average_bytes – average between the number of bytes sent to clients by each document (active or expired). + document_all_sent_to_clients_min_bytes - minimum from the number of bytes sent to clients by each document (active or expired). + document_all_sent_to_clients_max_bytes - maximum from the number of bytes sent to clients by each document (active or expired). + document_active_sent_to_clients_total_bytes - total number of bytes sent to clients by active documents. + document_active_sent_to_clients_average_bytes - average between the number of bytes sent to clients by each active document. + document_active_sent_to_clients_min_bytes - minimum from the number of bytes sent to clients by each active document. + document_active_sent_to_clients_max_bytes - maximum from the number of bytes sent to clients by each active document. + document_expired_sent_to_clients_total_bytes - total number of bytes sent to clients by expired documents. + document_expired_sent_to_clients_average_bytes – average between the number of bytes sent to clients by each expired document. + document_expired_sent_to_clients_min_bytes - minimum from the number of bytes sent to clients by each expired document. + document_expired_sent_to_clients_max_bytes - maximum from the number of bytes sent to clients by each expired document. + +DOCUMENT BYTES RECEIVED FROM CLIENTS + + document_all_received_from_clients_total_bytes - total number of bytes received from clients by all documents (active or expired). + document_all_received_from_clients_average_bytes – average between the number of bytes received from clients by each document (active or expired). + document_all_received_from_clients_min_bytes - minimum from the number of bytes received from clients by each document (active or expired). + document_all_received_from_clients_max_bytes - maximum from the number of bytes received from clients by each document (active or expired). + document_active_received_from_clients_total_bytes - total number of bytes received from clients by active documents. + document_active_received_from_clients_average_bytes - average between the number of bytes received from clients by each active document. + document_active_received_from_clients_min_bytes - minimum from the number of bytes received from clients by each active document. + document_active_received_from_clients_max_bytes - maximum from the number of bytes received from clients by each active document. + document_expired_received_from_clients_total_bytes - total number of bytes received from clients by expired documents. + document_expired_received_from_clients_average_bytes - average between the number of bytes received from clients by each expired document. + document_expired_received_from_clients_min_bytes - minimum from the number of bytes received from clients by each expired document. + document_expired_received_from_clients_max_bytes - maximum from the number of bytes received from clients by each expired document. + +DOCUMENT DOWNLOAD DURATION + + document_all_wopi_download_duration_total_seconds - sum of download duration of each document (active or expired). + document_all_wopi_download_duration_average_seconds – average between the download duration of each document (active or expired). + document_all_wopi_download_duration_min_seconds – minimum from the download duration of each document (active or expired). + document_all_wopi_download_duration_max_seconds - maximum from the download duration of each document (active or expired). + document_active_wopi_download_duration_total_seconds - sum of download duration of each active document. + document_active_wopi_download_duration_average_seconds - average between the download duration of each active document. + document_active_wopi_download_duration_min_seconds - minimum from the download duration of each active document. + document_active_wopi_download_duration_max_seconds - maximum from the download duration of each active document. + document_expired_wopi_download_duration_total_seconds - sum of download duration of each expired document. + document_expired_wopi_download_duration_average_seconds - average between the download duration of each expired document. + document_expired_wopi_download_duration_min_seconds - minimum from the download duration of each expired document. + document_expired_wopi_download_duration_max_seconds - maximum from the download duration of each expired document. + +DOCUMENT UPLOAD DURATION + + document_all_wopi_upload_duration_total_seconds - sum of upload duration of each document (active or expired). + document_all_wopi_upload_duration_average_seconds – average between the upload duration of each document (active or expired). + document_all_wopi_upload_duration_min_seconds – minimum from the upload duration of each document (active or expired). + document_all_wopi_upload_duration_max_seconds - maximum from the upload duration of each document (active or expired). + document_active_wopi_upload_duration_total_seconds - sum of upload duration of each active document. + document_active_wopi_upload_duration_average_seconds - average between the upload duration of each active document. + document_active_wopi_upload_duration_min_seconds - minimum from the upload duration of each active document. + document_active_wopi_upload_duration_max_seconds - maximum from the upload duration of each active document. + document_expired_wopi_upload_duration_total_seconds - sum of upload duration of each expired document. + document_expired_wopi_upload_duration_average_seconds - average between the upload duration of each expired document. + document_expired_wopi_upload_duration_min_seconds - minimum from the upload duration of each expired document. + document_expired_wopi_upload_duration_max_seconds - maximum from the upload duration of each expired document. + +DOCUMENT VIEW LOAD DURATION + + document_all_view_load_duration_total_seconds - sum of load duration of each view (active or expired) of each document (active or expired). + document_all_view_load_duration_average_seconds – average between the load duration of all views (active or expired) of each document (active or expired). + document_all_view_load_duration_min_seconds – minimum from the load duration of all views (active or expired) of each document (active or expired). + document_all_view_load_duration_max_seconds - maximum from the load duration of all views (active or expired) of each document (active or expired). + document_active_view_load_duration_total_seconds - sum of load duration of all views (active or expired) of each active document. + document_active_view_load_duration_average_seconds - average between the load duration of all views (active or expired) of each active document. + document_active_view_load_duration_min_seconds - minimum from the load duration of all views (active or expired) of each active document. + document_active_view_load_duration_max_seconds - maximum from the load duration of all views (active or expired) of each active document. + document_expired_view_load_duration_total_seconds - sum of load duration of all views (active or expired) of each expired document. + document_expired_view_load_duration_average_seconds - average between the load duration of all views (active or expired) of each expired document. + document_expired_view_load_duration_min_seconds - minimum from the load duration of all views (active or expired) of each expired document. + document_expired_view_load_duration_max_seconds - maximum from the load duration of all views (active or expired) of each expired document. _______________________________________________ Libreoffice-commits mailing list libreoffice-comm...@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/libreoffice-commits