libreoffice-online/wsd/TileCache.cpp
Ashod Nakashian b53d353779 wsd: reduce debug and generally redundant logs
In 'debug' log-level we expect a detailed, but
still readable output. Having one area with
disproportionately large number of logs reduces
the overall utility of the log output.

This patch reduces a number of redundant log
entries, including errors that are already
logged. It also reduces the level of some
others from 'information' to 'debug' and
from 'debug' to 'trace'.

The goal is to make 'debug' level as useful as
possible to read the progress and be able to
understand what was going on, such that one is
able to decide which area to dig deeper into.
Then, trace level could be used to get more
insight into that area, if necessary. For
example, when investigating a test failure,
one first enables 'debug' logs and reads through.
Once a section between two debug entries is
identified as being of interest, enabling 'trace'
level logs becomes more productive as it's
now possible to easily reach the first DBG
entry and read through until the second one.

It's unfortunate that we don't have per-area
control for enabling/disabling logs, so it
is common to see more and more 'debug' log
entries added all around, making logs
less and less readable.

It is also a limitation of the levels we have
that we really only have 3 usable levels:
one, two, many. That is, 'information' for
the most important events, 'debug' for
technical details needed to investigate issues,
and 'trace' for everything else. ('warning'
and 'error' aren't really 'levels'; they have
semantics that makes them special-cases.)
So we have to avoid degrading one into the
other, or have differences without distinction.

If any of these entries are needed to be
displayed more frequently, changing them
back to 'debug' or even 'information' should
be done. Though for me they seem special
cases that don't benefit most log readings.

Change-Id: Id2c6a9dc027483b81a066b0b4b50a298c5eff449
Signed-off-by: Ashod Nakashian <ashod.nakashian@collabora.co.uk>
2022-02-24 07:38:13 -05:00

708 lines
23 KiB
C++

/* -*- Mode: C++; tab-width: 4; indent-tabs-mode: nil; c-basic-offset: 4; fill-column: 100 -*- */
/*
* This Source Code Form is subject to the terms of the Mozilla Public
* License, v. 2.0. If a copy of the MPL was not distributed with this
* file, You can obtain one at http://mozilla.org/MPL/2.0/.
*/
#include <config.h>
#include "TileCache.hpp"
#include <cassert>
#include <climits>
#include <cstddef>
#include <cstdio>
#include <fstream>
#include <iostream>
#include <memory>
#include <sstream>
#include <string>
#include <utility>
#include <vector>
#include "ClientSession.hpp"
#include <Common.hpp>
#include <Protocol.hpp>
#include <Unit.hpp>
#include <Util.hpp>
#include <common/FileUtil.hpp>
using namespace COOLProtocol;
TileCache::TileCache(std::string docURL, const std::chrono::system_clock::time_point& modifiedTime,
bool dontCache)
: _docURL(std::move(docURL))
, _dontCache(dontCache)
, _cacheSize(0)
, _maxCacheSize(512 * 1024)
{
#ifndef BUILDING_TESTS
LOG_INF("TileCache ctor for uri [" << COOLWSD::anonymizeUrl(_docURL) <<
"], modifiedTime=" << std::chrono::duration_cast<std::chrono::seconds>
(modifiedTime.time_since_epoch()).count() << "], dontCache=" << _dontCache);
#endif
(void)modifiedTime;
}
TileCache::~TileCache()
{
_owner = std::thread::id();
#ifndef BUILDING_TESTS
LOG_INF("~TileCache dtor for uri [" << COOLWSD::anonymizeUrl(_docURL) << "].");
#endif
}
void TileCache::clear()
{
_cache.clear();
_cacheSize = 0;
for (auto i : _streamCache)
i.clear();
LOG_INF("Completely cleared tile cache for: " << _docURL);
}
/// Tracks the rendering of a given tile
/// to avoid duplication and help clock
/// rendering latency.
struct TileCache::TileBeingRendered
{
explicit TileBeingRendered(const TileDesc& tile, const std::chrono::steady_clock::time_point &now)
: _startTime(now), _tile(tile) { }
const TileDesc& getTile() const { return _tile; }
int getVersion() const { return _tile.getVersion(); }
void setVersion(int version) { _tile.setVersion(version); }
std::chrono::steady_clock::time_point getStartTime() const { return _startTime; }
std::chrono::milliseconds getElapsedTimeMs(const std::chrono::steady_clock::time_point* now
= nullptr) const
{
return std::chrono::duration_cast<std::chrono::milliseconds>(
(now ? *now : std::chrono::steady_clock::now()) - _startTime);
}
bool isStale(const std::chrono::steady_clock::time_point* now = nullptr) const
{
return getElapsedTimeMs(now) > std::chrono::milliseconds(COMMAND_TIMEOUT_MS);
}
std::vector<std::weak_ptr<ClientSession>>& getSubscribers() { return _subscribers; }
void dumpState(std::ostream& os);
private:
std::vector<std::weak_ptr<ClientSession>> _subscribers;
std::chrono::steady_clock::time_point _startTime;
TileDesc _tile;
};
size_t TileCache::countTilesBeingRenderedForSession(const std::shared_ptr<ClientSession>& session,
const std::chrono::steady_clock::time_point &now)
{
size_t count = 0;
for (auto& it : _tilesBeingRendered)
{
if (it.second->isStale(&now))
continue;
for (auto& s : it.second->getSubscribers())
{
if (s.lock() == session)
++count;
}
}
return count;
}
bool TileCache::hasTileBeingRendered(const TileDesc& tileDesc, const std::chrono::steady_clock::time_point *now) const
{
const auto it = _tilesBeingRendered.find(tileDesc);
if (it == _tilesBeingRendered.end())
return false;
/// did we stall ? if so re-issue.
return !now ? true : !it->second->isStale(now);
}
std::shared_ptr<TileCache::TileBeingRendered> TileCache::findTileBeingRendered(const TileDesc& tileDesc)
{
assertCorrectThread();
const auto tile = _tilesBeingRendered.find(tileDesc);
return tile != _tilesBeingRendered.end() ? tile->second : nullptr;
}
void TileCache::forgetTileBeingRendered(const std::shared_ptr<TileCache::TileBeingRendered>& tileBeingRendered)
{
assertCorrectThread();
assert(tileBeingRendered);
assert(hasTileBeingRendered(tileBeingRendered->getTile()));
LOG_TRC("Removing all subscribers for " << tileBeingRendered->getTile().serialize());
_tilesBeingRendered.erase(tileBeingRendered->getTile());
}
int TileCache::getTileBeingRenderedVersion(const TileDesc& tile)
{
std::shared_ptr<TileBeingRendered> tileBeingRendered = findTileBeingRendered(tile);
return tileBeingRendered ? tileBeingRendered->getVersion() : 0;
}
TileCache::Tile TileCache::lookupTile(const TileDesc& tile)
{
if (_dontCache)
return TileCache::Tile();
TileCache::Tile ret = findTile(tile);
UnitWSD::get().lookupTile(tile.getPart(), tile.getWidth(), tile.getHeight(),
tile.getTilePosX(), tile.getTilePosY(),
tile.getTileWidth(), tile.getTileHeight(), ret);
return ret;
}
void TileCache::saveTileAndNotify(const TileDesc& tile, const char *data, const size_t size)
{
assertCorrectThread();
if (size > 0)
{
// Save to in-memory cache.
// Ignore if we can't save the tile, things will work anyway, but slower.
// An error indication is supposed to be sent to all users in that case.
saveDataToCache(tile, data, size);
LOG_TRC("Saved cache tile: " << cacheFileName(tile) << " of size " << size << " bytes");
}
else
LOG_TRC("Zero sized cache tile: " << cacheFileName(tile));
// Notify subscribers, if any.
std::shared_ptr<TileBeingRendered> tileBeingRendered = findTileBeingRendered(tile);
if (tileBeingRendered)
{
const size_t subscriberCount = tileBeingRendered->getSubscribers().size();
if (size > 0 && subscriberCount > 0)
{
std::string response = tile.serialize("tile:");
LOG_DBG("Sending tile message to " << subscriberCount << " subscribers: " << response);
// Send to first subscriber as-is (without cache marker).
auto payload = std::make_shared<Message>(response,
Message::Dir::Out,
response.size() + 1 + size);
payload->append("\n", 1);
payload->append(data, size);
auto& firstSubscriber = tileBeingRendered->getSubscribers()[0];
std::shared_ptr<ClientSession> firstSession = firstSubscriber.lock();
if (firstSession)
{
firstSession->enqueueSendMessage(payload);
}
if (subscriberCount > 1)
{
// All others must get served from the cache.
response += " renderid=cached\n";
// Create a new Payload.
payload.reset();
payload = std::make_shared<Message>(response,
Message::Dir::Out,
response.size() + size);
payload->append(data, size);
for (size_t i = 1; i < subscriberCount; ++i)
{
auto& subscriber = tileBeingRendered->getSubscribers()[i];
std::shared_ptr<ClientSession> session = subscriber.lock();
if (session)
{
session->enqueueSendMessage(payload);
}
}
}
}
else if (subscriberCount == 0)
LOG_DBG("No subscribers for: " << cacheFileName(tile));
// else zero sized
// Remove subscriptions.
if (tileBeingRendered->getVersion() <= tile.getVersion())
{
LOG_DBG("STATISTICS: tile " << tile.getVersion() << " internal roundtrip " <<
tileBeingRendered->getElapsedTimeMs());
forgetTileBeingRendered(tileBeingRendered);
}
}
else
LOG_DBG("No subscribers for: " << cacheFileName(tile));
}
bool TileCache::getTextStream(StreamType type, const std::string& fileName, std::string& content)
{
Tile textStream = lookupCachedStream(type, fileName);
if (!textStream)
{
// This is not an error because the first time
// we lookup a file, it won't be in the cache.
LOG_INF("Could not open " << fileName);
return false;
}
std::vector<char> buffer = *textStream;
if (!buffer.empty() && buffer.back() == '\n')
buffer.pop_back();
content = std::string(buffer.data(), buffer.size());
LOG_INF("Read '" << COOLProtocol::getAbbreviatedMessage(content.c_str(), content.size()) <<
"' from " << fileName);
return true;
}
void TileCache::saveTextStream(StreamType type, const std::string& text, const std::string& fileName)
{
LOG_INF("Saving '" << COOLProtocol::getAbbreviatedMessage(text.c_str(), text.size()) <<
"' to " << fileName << " of size " << text.size() << " bytes");
saveDataToStreamCache(type, fileName, text.c_str(), text.size());
}
void TileCache::saveStream(StreamType type, const std::string& name, const char *data, std::size_t size)
{
// can fonts be invalidated?
saveDataToStreamCache(type, name, data, size);
}
TileCache::Tile TileCache::lookupCachedStream(StreamType type, const std::string& name)
{
auto it = _streamCache[type].find(name);
if (it != _streamCache[type].end())
{
LOG_TRC("Found stream cache tile: " << name << " of size " << it->second->size() << " bytes");
return it->second;
}
return TileCache::Tile();
}
void TileCache::invalidateTiles(int part, int x, int y, int width, int height, int normalizedViewId)
{
LOG_TRC("Removing invalidated tiles: part: " << part <<
", x: " << x << ", y: " << y <<
", width: " << width <<
", height: " << height);
assertCorrectThread();
for (auto it = _cache.begin(); it != _cache.end();)
{
if (intersectsTile(it->first, part, x, y, width, height, normalizedViewId))
{
LOG_TRC("Removing tile: " << it->first.serialize());
_cacheSize -= itemCacheSize(it->second);
it = _cache.erase(it);
}
else
{
++it;
}
}
}
void TileCache::invalidateTiles(const std::string& tiles, int normalizedViewId)
{
const std::pair<int, Util::Rectangle> result = TileCache::parseInvalidateMsg(tiles);
const Util::Rectangle& invalidateRect = result.second;
invalidateTiles(result.first, invalidateRect.getLeft(), invalidateRect.getTop(),
invalidateRect.getWidth(), invalidateRect.getHeight(), normalizedViewId);
}
std::pair<int, Util::Rectangle> TileCache::parseInvalidateMsg(const std::string& tiles)
{
StringVector tokens = Util::tokenize(tiles);
assert(!tokens.empty() && tokens.equals(0, "invalidatetiles:"));
if (tokens.size() == 2 && tokens.equals(1, "EMPTY"))
{
return std::pair<int, Util::Rectangle>(-1, Util::Rectangle(0, 0, INT_MAX, INT_MAX));
}
if (tokens.size() == 3 && tokens.equals(1, "EMPTY,"))
{
int part = 0;
if (stringToInteger(tokens[2], part))
return std::pair<int, Util::Rectangle>(part, Util::Rectangle(0, 0, INT_MAX, INT_MAX));
}
else
{
int part = 0;
int x = 0;
int y = 0;
int width = 0;
int height = 0;
if (tokens.size() == 6 &&
getTokenInteger(tokens[1], "part", part) &&
getNonNegTokenInteger(tokens[2], "x", x) &&
getNonNegTokenInteger(tokens[3], "y", y) &&
getNonNegTokenInteger(tokens[4], "width", width) &&
getNonNegTokenInteger(tokens[5], "height", height))
{
return std::pair<int, Util::Rectangle>(part, Util::Rectangle(x, y, width, height));
}
}
LOG_ERR("Unexpected invalidatetiles request [" << tiles << "].");
return std::pair<int, Util::Rectangle>(-1, Util::Rectangle(0, 0, 0, 0));
}
void TileCache::removeStream(StreamType type, const std::string& fileName)
{
auto it = _streamCache[type].find(fileName);
if (it != _streamCache[type].end())
{
LOG_INF("Removed file: " << fileName);
_streamCache[type].erase(it);
}
}
std::string TileCache::cacheFileName(const TileDesc& tile)
{
std::ostringstream oss;
oss << tile.getNormalizedViewId() << '_' << tile.getPart() << '_' << tile.getWidth() << 'x' << tile.getHeight() << '.'
<< tile.getTilePosX() << ',' << tile.getTilePosY() << '.'
<< tile.getTileWidth() << 'x' << tile.getTileHeight() << ".png";
return oss.str();
}
bool TileCache::parseCacheFileName(const std::string& fileName, int& part, int& width, int& height,
int& tilePosX, int& tilePosY, int& tileWidth, int& tileHeight,
int& nviewid)
{
return std::sscanf(fileName.c_str(), "%d_%d_%dx%d.%d,%d.%dx%d.png", &nviewid, &part, &width,
&height, &tilePosX, &tilePosY, &tileWidth, &tileHeight)
== 8;
}
bool TileCache::intersectsTile(const TileDesc &tileDesc, int part, int x, int y, int width, int height, int normalizedViewId)
{
if (part != -1 && tileDesc.getPart() != part)
return false;
if (normalizedViewId != tileDesc.getNormalizedViewId())
return false;
const int left = std::max(x, tileDesc.getTilePosX());
const int right = std::min(x + width, tileDesc.getTilePosX() + tileDesc.getTileWidth());
const int top = std::max(y, tileDesc.getTilePosY());
const int bottom = std::min(y + height, tileDesc.getTilePosY() + tileDesc.getTileHeight());
return left <= right && top <= bottom;
}
// FIXME: to be further simplified when we centralize tile messages.
void TileCache::subscribeToTileRendering(const TileDesc& tile, const std::shared_ptr<ClientSession>& subscriber,
const std::chrono::steady_clock::time_point &now)
{
assertCorrectThread();
std::shared_ptr<TileBeingRendered> tileBeingRendered = findTileBeingRendered(tile);
if (tileBeingRendered)
{
if (tileBeingRendered->isStale(&now))
LOG_DBG("Painting stalled; need to re-issue on tile " << tile.debugName());
for (const auto &s : tileBeingRendered->getSubscribers())
{
if (s.lock().get() == subscriber.get())
{
LOG_TRC("Redundant request to subscribe on tile " << tile.debugName());
tileBeingRendered->setVersion(tile.getVersion());
return;
}
}
LOG_DBG("Subscribing " << subscriber->getName() << " to tile " << tile.debugName() << " which has " <<
tileBeingRendered->getSubscribers().size() << " subscribers already.");
tileBeingRendered->getSubscribers().push_back(subscriber);
}
else
{
LOG_DBG("Subscribing " << subscriber->getName() << " to tile " << tile.debugName() <<
" ver=" << tile.getVersion() << " which has no subscribers " << tile.serialize());
assert(_tilesBeingRendered.find(tile) == _tilesBeingRendered.end());
tileBeingRendered = std::make_shared<TileBeingRendered>(tile, now);
tileBeingRendered->getSubscribers().push_back(subscriber);
_tilesBeingRendered[tile] = tileBeingRendered;
}
}
void TileCache::registerTileBeingRendered(const TileDesc& tile)
{
std::shared_ptr<TileBeingRendered> tileBeingRendered = findTileBeingRendered(tile);
auto now = std::chrono::steady_clock::now();
if (tileBeingRendered)
{
if (tileBeingRendered->isStale(&now))
{
// Tile painting has stalled. Reissue.
tileBeingRendered->setVersion(tile.getVersion());
}
}
else
{
assert(_tilesBeingRendered.find(tile) == _tilesBeingRendered.end());
tileBeingRendered = std::make_shared<TileBeingRendered>(tile, now);
_tilesBeingRendered[tile] = tileBeingRendered;
}
}
std::string TileCache::cancelTiles(const std::shared_ptr<ClientSession> &subscriber)
{
assert(subscriber && "cancelTiles expects valid subscriber");
LOG_TRC("Cancelling tiles for " << subscriber->getName());
assertCorrectThread();
const ClientSession* sub = subscriber.get();
std::ostringstream oss;
for (auto it = _tilesBeingRendered.begin(); it != _tilesBeingRendered.end(); )
{
if (it->second->getTile().getId() >= 0)
{
// Tile is for a thumbnail, don't cancel it
++it;
continue;
}
auto& subscribers = it->second->getSubscribers();
LOG_TRC("Tile " << it->first.serialize() << " has " << subscribers.size() << " subscribers.");
const auto itRem = std::find_if(subscribers.begin(), subscribers.end(),
[sub](std::weak_ptr<ClientSession>& ptr){ return ptr.lock().get() == sub; });
if (itRem != subscribers.end())
{
LOG_TRC("Tile " << it->first.serialize() << " has " << subscribers.size() <<
" subscribers. Removing " << subscriber->getName() << '.');
subscribers.erase(itRem, itRem + 1);
if (subscribers.empty())
{
// No other subscriber, remove it from the render queue.
oss << it->second->getVersion() << ',';
it = _tilesBeingRendered.erase(it);
continue;
}
}
++it;
}
const std::string canceltiles = oss.str();
return canceltiles.empty() ? canceltiles : "canceltiles " + canceltiles;
}
void TileCache::assertCorrectThread()
{
const bool correctThread = _owner == std::thread::id() || std::this_thread::get_id() == _owner;
if (!correctThread)
{
LOG_ERR("TileCache method invoked from foreign thread. Expected: "
<< Log::to_string(_owner) << " but called from " << std::this_thread::get_id()
<< " (" << Util::getThreadId() << ").");
}
assert (correctThread);
}
TileCache::Tile TileCache::findTile(const TileDesc &desc)
{
const auto it = _cache.find(desc);
if (it != _cache.end() && it->first.getNormalizedViewId() == desc.getNormalizedViewId())
{
LOG_TRC("Found cache tile: " << desc.serialize() << " of size " << it->second->size() << " bytes");
return it->second;
}
return TileCache::Tile();
}
void TileCache::saveDataToCache(const TileDesc &desc, const char *data, const size_t size)
{
if (_dontCache)
return;
ensureCacheSize();
TileCache::Tile tile = std::make_shared<std::vector<char>>(size);
std::memcpy(tile->data(), data, size);
auto res = _cache.emplace(desc, tile);
if (!res.second)
{
_cacheSize -= itemCacheSize(res.first->second);
_cache[desc] = tile;
}
_cacheSize += itemCacheSize(tile);
}
size_t TileCache::itemCacheSize(const Tile &tile)
{
return tile->size() + sizeof(TileDesc);
}
void TileCache::assertCacheSize()
{
#if ENABLE_DEBUG
size_t recalcSize = 0;
for (const auto& it : _cache)
{
recalcSize += itemCacheSize(it.second);
}
assert(recalcSize == _cacheSize);
#endif
}
void TileCache::ensureCacheSize()
{
assertCacheSize();
if (_cacheSize < _maxCacheSize || _cache.size() < 2)
return;
LOG_TRC("Cleaning tile cache of size " << _cacheSize << " vs. " << _maxCacheSize <<
" with " << _cache.size() << " entries");
struct WidSize {
TileWireId _wid;
size_t _size;
WidSize(TileWireId w, size_t s) : _wid(w), _size(s) {}
};
std::vector<WidSize> wids;
for (const auto& it : _cache)
wids.emplace_back(it.first.getWireId(), itemCacheSize(it.second));
std::sort(wids.begin(), wids.end(),
[](const WidSize &a, const WidSize &b) { return a._wid < b._wid; });
// FIXME: should we just take a wid 25% into the list ?
TileWireId maxToRemove = wids.front()._wid;
// do we have (the very rare) WID wrap-around
if (wids.back()._wid - wids.front()._wid > 256 * 256 * 256)
{
maxToRemove = wids.back()._wid;
}
else
{
// calculate which wid to start at.
size_t total = 0;
for (const auto &it : wids)
{
total += it._size;
maxToRemove = it._wid;
if (total > _maxCacheSize / 4)
break;
}
}
LOG_TRC("cleaning up to wid " << maxToRemove << " between " <<
wids.front()._wid << " and " << wids.back()._wid);
for (auto it = _cache.begin(); it != _cache.end();)
{
if (it->first.getWireId() <= maxToRemove)
{
LOG_TRC("cleaned out tile: " << it->first.serialize());
_cacheSize -= itemCacheSize(it->second);
it = _cache.erase(it);
}
else
{
++it;
}
}
LOG_TRC("Cache is now of size " << _cacheSize << " and " <<
_cache.size() << " entries after cleaning");
assertCacheSize();
}
void TileCache::setMaxCacheSize(size_t cacheSize)
{
_maxCacheSize = cacheSize;
ensureCacheSize();
}
void TileCache::saveDataToStreamCache(StreamType type, const std::string &fileName, const char *data, const size_t size)
{
if (_dontCache)
return;
TileCache::Tile tile = std::make_shared<std::vector<char>>(size);
std::memcpy(tile->data(), data, size);
_streamCache[type][fileName] = tile;
}
void TileCache::TileBeingRendered::dumpState(std::ostream& os)
{
os << " " << _tile.serialize() << ' ' << std::setw(4) << getElapsedTimeMs()
<< _subscribers.size() << " subscribers\n";
for (const auto& it : _subscribers)
{
std::shared_ptr<ClientSession> session = it.lock();
if (session)
{
os << " " << session->getId() << ' ' << session->getUserId() << ' '
<< session->getName() << '\n';
}
}
}
void TileCache::dumpState(std::ostream& os)
{
os << "\n TileCache:";
os << "\n num: " << _cache.size() << " size: " << _cacheSize << " bytes\n";
for (const auto& it : _cache)
{
os << " " << std::setw(4) << it.first.getWireId()
<< '\t' << std::setw(6) << it.second->size() << " bytes"
<< "\t'" << it.first.serialize() << "'\n" ;
}
int type = 0;
for (const auto& i : _streamCache)
{
size_t num = 0;
size_t size = 0;
for (const auto& it : i)
{
num++;
size += it.second->size();
}
os << " stream cache: " << type++ << " num: " << num << " size: " << size << " bytes\n";
for (const auto& it : i)
{
os << " " << it.first
<< '\t' << std::setw(6) << it.second->size() << " bytes\n";
}
}
os << " tiles being rendered " << _tilesBeingRendered.size() << '\n';
for (const auto& it : _tilesBeingRendered)
it.second->dumpState(os);
}
/* vim:set shiftwidth=4 softtabstop=4 expandtab: */