libreoffice-online/wsd/TileCache.cpp

701 lines
23 KiB
C++
Raw Normal View History

/* -*- Mode: C++; tab-width: 4; indent-tabs-mode: nil; c-basic-offset: 4; fill-column: 100 -*- */
2015-03-12 09:18:35 -05:00
/*
* 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>
2015-03-12 09:18:35 -05:00
#include "TileCache.hpp"
#include <cassert>
#include <climits>
#include <cstddef>
#include <cstdio>
2015-03-12 09:18:35 -05:00
#include <fstream>
#include <iostream>
#include <memory>
#include <sstream>
#include <string>
#include <utility>
#include <vector>
2015-03-12 09:18:35 -05:00
#include "ClientSession.hpp"
#include <Common.hpp>
#include <Protocol.hpp>
#include <StringVector.hpp>
#include <Unit.hpp>
#include <Util.hpp>
#include <common/FileUtil.hpp>
using namespace COOLProtocol;
2015-03-12 09:18:35 -05:00
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)
2015-03-12 18:34:42 -05:00
{
#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;
2015-03-12 09:18:35 -05:00
}
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;
}
Tile TileCache::lookupTile(const TileDesc& tile)
2015-03-12 09:18:35 -05:00
{
if (_dontCache)
return Tile();
Tile ret = findTile(tile);
2015-03-12 09:18:35 -05:00
UnitWSD::get().lookupTile(tile.getPart(), tile.getWidth(), tile.getHeight(),
tile.getTilePosX(), tile.getTilePosY(),
tile.getTileWidth(), tile.getTileHeight(), ret);
return ret;
2015-03-12 09:18:35 -05:00
}
void TileCache::saveTileAndNotify(const TileDesc& tile, const char *data, const size_t size)
2015-03-12 09:18:35 -05:00
{
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));
2015-03-12 18:34:42 -05:00
}
bool TileCache::getTextStream(StreamType type, const std::string& fileName, std::string& content)
2015-03-13 07:17:51 -05:00
{
Blob 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;
2015-03-13 07:17:51 -05:00
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;
2015-03-13 07:17:51 -05:00
}
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)
2015-11-27 08:12:44 -06:00
{
// can fonts be invalidated?
saveDataToStreamCache(type, name, data, size);
2015-11-27 08:12:44 -06:00
}
Blob TileCache::lookupCachedStream(StreamType type, const std::string& name)
2015-11-27 08:12:44 -06:00
{
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 Blob();
2015-11-27 08:12:44 -06:00
}
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 = StringVector::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));
}
std::string TileCache::cacheFileName(const TileDesc& tile)
2015-03-12 18:34:42 -05:00
{
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();
2015-03-12 18:34:42 -05:00
}
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())
{
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-19 07:30:26 -06:00
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);
}
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);
return it->second;
}
return Tile();
}
void TileCache::saveDataToCache(const TileDesc &desc, const char *data, const size_t size)
{
if (_dontCache)
return;
ensureCacheSize();
auto blob = std::make_shared<BlobData>(size);
std::memcpy(blob->data(), data, size);
Tile tile = std::make_shared<TileData>(0 /* FIXME */, blob);
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 sizeof(Tile) + sizeof(TileDesc) + tile->size();
}
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;
Blob blob = std::make_shared<BlobData>(size);
std::memcpy(blob->data(), data, size);
_streamCache[type][fileName] = blob;
}
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);
}
2015-03-12 09:18:35 -05:00
/* vim:set shiftwidth=4 softtabstop=4 expandtab: */