From e1066784220adb9a2e731001e72c444582fc997f Mon Sep 17 00:00:00 2001 From: Oz Linden Date: Sun, 16 Jan 2011 21:41:08 -0500 Subject: DN-202: Make avatar name caching more aggressive and error handling more uniform Add logging (mostly at DEBUG level) --- indra/llmessage/llavatarnamecache.cpp | 258 ++++++++++++++++++++-------------- 1 file changed, 155 insertions(+), 103 deletions(-) (limited to 'indra/llmessage/llavatarnamecache.cpp') diff --git a/indra/llmessage/llavatarnamecache.cpp b/indra/llmessage/llavatarnamecache.cpp index d9cb83c089..ab4785569d 100644 --- a/indra/llmessage/llavatarnamecache.cpp +++ b/indra/llmessage/llavatarnamecache.cpp @@ -38,6 +38,7 @@ #include #include +#include namespace LLAvatarNameCache { @@ -81,8 +82,11 @@ namespace LLAvatarNameCache // only need per-frame timing resolution LLFrameTimer sRequestTimer; - // Periodically clean out expired entries from the cache - //LLFrameTimer sEraseExpiredTimer; + /// Maximum time an unrefreshed cache entry is allowed + const F64 MAX_UNREFRESHED_TIME = 20.0 * 60.0; + + /// Time when unrefreshed cached names were checked last + static F64 sLastExpireCheck; //----------------------------------------------------------------------- // Internal methods @@ -99,8 +103,9 @@ namespace LLAvatarNameCache // Legacy name system callback void legacyNameCallback(const LLUUID& agent_id, - const std::string& full_name, - bool is_group); + const std::string& full_name, + bool is_group + ); void requestNamesViaLegacy(); @@ -117,7 +122,7 @@ namespace LLAvatarNameCache bool isRequestPending(const LLUUID& agent_id); // Erase expired names from cache - void eraseExpired(); + void eraseUnrefreshed(); bool expirationFromCacheControl(LLSD headers, F64 *expires); } @@ -187,6 +192,7 @@ public: { // Pull expiration out of headers if available F64 expires = LLAvatarNameCache::nameExpirationFromHeaders(mHeaders); + F64 now = LLFrameTimer::getTotalSeconds(); LLSD agents = content["agents"]; LLSD::array_const_iterator it = agents.beginArray(); @@ -207,84 +213,91 @@ public: av_name.mDisplayName = av_name.mUsername; } + LL_DEBUGS("AvNameCache") << "LLAvatarNameResponder::result for " << agent_id << " " + << "user '" << av_name.mUsername << "' " + << "display '" << av_name.mDisplayName << "' " + << "expires in " << expires - now << " seconds" + << LL_ENDL; + // cache it and fire signals LLAvatarNameCache::processName(agent_id, av_name, true); } // Same logic as error response case LLSD unresolved_agents = content["bad_ids"]; - if (unresolved_agents.size() > 0) + S32 num_unresolved = unresolved_agents.size(); + if (num_unresolved > 0) { - const std::string DUMMY_NAME("\?\?\?"); - LLAvatarName av_name; - av_name.mUsername = DUMMY_NAME; - av_name.mDisplayName = DUMMY_NAME; - av_name.mIsDisplayNameDefault = false; - av_name.mIsTemporaryName = true; - av_name.mExpires = expires; - + LL_WARNS("AvNameCache") << "LLAvatarNameResponder::result " << num_unresolved << " unresolved ids; " + << "expires in " << expires - now << " seconds" + << LL_ENDL; it = unresolved_agents.beginArray(); for ( ; it != unresolved_agents.endArray(); ++it) { const LLUUID& agent_id = *it; - // cache it and fire signals - LLAvatarNameCache::processName(agent_id, av_name, true); + + LL_WARNS("AvNameCache") << "LLAvatarNameResponder::result " + << "failed id " << agent_id + << LL_ENDL; + + LLAvatarNameCache::handleAgentError(agent_id); } } - } + LL_DEBUGS("AvNameCache") << "LLAvatarNameResponder::result " + << LLAvatarNameCache::sCache.size() << " cached names" + << LL_ENDL; + } /*virtual*/ void error(U32 status, const std::string& reason) { // If there's an error, it might be caused by PeopleApi, // or when loading textures on startup and using a very slow - // network, this query may time out. Fallback to the legacy - // cache. - - llwarns << "LLAvatarNameResponder error " << status << " " << reason << llendl; + // network, this query may time out. + // What we should do depends on whether or not we have a cached name + LL_WARNS("AvNameCache") << "LLAvatarNameResponder::error " << status << " " << reason + << LL_ENDL; - // Add dummy records for all agent IDs in this request + // Add dummy records for any agent IDs in this request that we do not have cached already std::vector::const_iterator it = mAgentIDs.begin(); for ( ; it != mAgentIDs.end(); ++it) { const LLUUID& agent_id = *it; - gCacheName->get(agent_id, false, // legacy compatibility - boost::bind(&LLAvatarNameCache::legacyNameCallback, - _1, _2, _3)); + LLAvatarNameCache::handleAgentError(agent_id); } } - - // Return time to retry a request that generated an error, based on - // error type and headers. Return value is seconds-since-epoch. - F64 errorRetryTimestamp(S32 status) - { - F64 now = LLFrameTimer::getTotalSeconds(); - - // Retry-After takes priority - LLSD retry_after = mHeaders["retry-after"]; - if (retry_after.isDefined()) - { - // We only support the delta-seconds type - S32 delta_seconds = retry_after.asInteger(); - if (delta_seconds > 0) - { - // ...valid delta-seconds - return now + F64(delta_seconds); - } - } - - // If no Retry-After, look for Cache-Control max-age - F64 expires = 0.0; - if (LLAvatarNameCache::expirationFromCacheControl(mHeaders, &expires)) - { - return expires; - } - - // No information in header, make a guess - const F64 DEFAULT_DELAY = 120.0; // 2 mintues - return now + DEFAULT_DELAY; - } }; +// Provide some fallback for agents that return errors +void LLAvatarNameCache::handleAgentError(const LLUUID& agent_id) +{ + std::map::iterator existing = sCache.find(agent_id); + if (existing == sCache.end()) + { + // there is no existing cache entry, so make a temporary name from legacy + LL_WARNS("AvNameCache") << "LLAvatarNameCache get legacy for agent " + << agent_id << LL_ENDL; + gCacheName->get(agent_id, false, // legacy compatibility + boost::bind(&LLAvatarNameCache::legacyNameCallback, + _1, _2, _3)); + } + else + { + // we have a chached (but probably expired) entry - since that would have + // been returned by the get method, there is no need to signal anyone + + // Clear this agent from the pending list + LLAvatarNameCache::sPendingQueue.erase(agent_id); + + const LLAvatarName& av_name = existing->second; + LL_DEBUGS("AvNameCache") << "LLAvatarNameCache use cache for agent " + << agent_id + << "user '" << av_name.mUsername << "' " + << "display '" << av_name.mDisplayName << "' " + << "expires in " << av_name.mExpires - LLFrameTimer::getTotalSeconds() << " seconds" + << LL_ENDL; + } +} + void LLAvatarNameCache::processName(const LLUUID& agent_id, const LLAvatarName& av_name, bool add_to_cache) @@ -326,6 +339,7 @@ void LLAvatarNameCache::requestNamesViaCapability() std::vector agent_ids; agent_ids.reserve(128); + U32 ids = 0; ask_queue_t::const_iterator it = sAskQueue.begin(); for ( ; it != sAskQueue.end(); ++it) { @@ -336,11 +350,13 @@ void LLAvatarNameCache::requestNamesViaCapability() // ...starting new request url += sNameLookupURL; url += "?ids="; + ids = 1; } else { // ...continuing existing request url += "&ids="; + ids++; } url += agent_id.asString(); agent_ids.push_back(agent_id); @@ -350,8 +366,10 @@ void LLAvatarNameCache::requestNamesViaCapability() if (url.size() > NAME_URL_SEND_THRESHOLD) { - //llinfos << "requestNames " << url << llendl; - LLHTTPClient::get(url, new LLAvatarNameResponder(agent_ids));//, LLSD(), 10.0f); + LL_DEBUGS("AvNameCache") << "LLAvatarNameCache::requestNamesViaCapability first " + << ids << " ids" + << LL_ENDL; + LLHTTPClient::get(url, new LLAvatarNameResponder(agent_ids)); url.clear(); agent_ids.clear(); } @@ -359,8 +377,10 @@ void LLAvatarNameCache::requestNamesViaCapability() if (!url.empty()) { - //llinfos << "requestNames " << url << llendl; - LLHTTPClient::get(url, new LLAvatarNameResponder(agent_ids));//, LLSD(), 10.0f); + LL_DEBUGS("AvNameCache") << "LLAvatarNameCache::requestNamesViaCapability all " + << ids << " ids" + << LL_ENDL; + LLHTTPClient::get(url, new LLAvatarNameResponder(agent_ids)); url.clear(); agent_ids.clear(); } @@ -376,6 +396,11 @@ void LLAvatarNameCache::legacyNameCallback(const LLUUID& agent_id, // Construct a dummy record for this name. By convention, SLID is blank // Never expires, but not written to disk, so lasts until end of session. LLAvatarName av_name; + LL_DEBUGS("AvNameCache") << "LLAvatarNameCache::legacyNameCallback " + << "agent " << agent_id << " " + << "full name '" << full_name << "'" + << ( is_group ? " [group]" : "" ) + << LL_ENDL; buildLegacyName(full_name, &av_name); // Don't add to cache, the data already exists in the legacy name system @@ -397,6 +422,8 @@ void LLAvatarNameCache::requestNamesViaLegacy() // invoked below. This should never happen in practice. sPendingQueue[agent_id] = now; + LL_DEBUGS("AvNameCache") << "LLAvatarNameCache::requestNamesViaLegacy agent " << agent_id << LL_ENDL; + gCacheName->get(agent_id, false, // legacy compatibility boost::bind(&LLAvatarNameCache::legacyNameCallback, _1, _2, _3)); @@ -435,21 +462,24 @@ void LLAvatarNameCache::importFile(std::istream& istr) av_name.fromLLSD( it->second ); sCache[agent_id] = av_name; } - // entries may have expired since we last ran the viewer, just - // clean them out now - eraseExpired(); - llinfos << "loaded " << sCache.size() << llendl; + // Some entries may have expired since the cache was stored, + // but next time they are read that will be checked. + // Expired entries are filtered out when the cache is stored, + // or in eraseUnrefreshed + LL_INFOS("AvNameCache") << "loaded " << sCache.size() << LL_ENDL; } void LLAvatarNameCache::exportFile(std::ostream& ostr) { LLSD agents; + F64 now = LLFrameTimer::getTotalSeconds(); cache_t::const_iterator it = sCache.begin(); for ( ; it != sCache.end(); ++it) { const LLUUID& agent_id = it->first; const LLAvatarName& av_name = it->second; - if (!av_name.mIsTemporaryName) + // Do not write temporary or expired entries to the stored cache + if (!av_name.mIsTemporaryName && av_name.mExpires >= now) { // key must be a string agents[agent_id.asString()] = av_name.asLLSD(); @@ -484,56 +514,63 @@ void LLAvatarNameCache::idle() // return; //} - // Must be large relative to above - - // No longer deleting expired entries, just re-requesting in the get - // this way first synchronous get call on an expired entry won't return - // legacy name. LF - - if (sAskQueue.empty()) + if (!sAskQueue.empty()) { - return; + if (useDisplayNames()) + { + requestNamesViaCapability(); + } + else + { + // ...fall back to legacy name cache system + requestNamesViaLegacy(); + } } - if (useDisplayNames()) - { - requestNamesViaCapability(); - } - else - { - // ...fall back to legacy name cache system - requestNamesViaLegacy(); - } + // erase anything that has not been refreshed for more than MAX_UNREFRESHED_TIME + eraseUnrefreshed(); } bool LLAvatarNameCache::isRequestPending(const LLUUID& agent_id) { + bool isPending = false; const F64 PENDING_TIMEOUT_SECS = 5.0 * 60.0; - F64 now = LLFrameTimer::getTotalSeconds(); - F64 expire_time = now - PENDING_TIMEOUT_SECS; pending_queue_t::const_iterator it = sPendingQueue.find(agent_id); if (it != sPendingQueue.end()) { - bool request_expired = (it->second < expire_time); - return !request_expired; + // in the list of requests in flight, retry if too old + F64 expire_time = LLFrameTimer::getTotalSeconds() - PENDING_TIMEOUT_SECS; + isPending = (it->second > expire_time); } - return false; + return isPending; } -void LLAvatarNameCache::eraseExpired() +void LLAvatarNameCache::eraseUnrefreshed() { F64 now = LLFrameTimer::getTotalSeconds(); - cache_t::iterator it = sCache.begin(); - while (it != sCache.end()) - { - cache_t::iterator cur = it; - ++it; - const LLAvatarName& av_name = cur->second; - if (av_name.mExpires < now) - { - sCache.erase(cur); - } + F64 max_unrefreshed = now - MAX_UNREFRESHED_TIME; + + if (!sLastExpireCheck || sLastExpireCheck < max_unrefreshed) + { + sLastExpireCheck = now; + cache_t::iterator it = sCache.begin(); + while (it != sCache.end()) + { + cache_t::iterator cur = it; + ++it; + const LLAvatarName& av_name = cur->second; + if (av_name.mExpires < max_unrefreshed) + { + const LLUUID& agent_id = it->first; + LL_DEBUGS("AvNameCache") << agent_id + << " user '" << av_name.mUsername << "' " + << "expired " << now - av_name.mExpires << " secs ago" + << LL_ENDL; + sCache.erase(cur); + } + } + LL_INFOS("AvNameCache") << sCache.size() << " cached avatar names" << LL_ENDL; } } @@ -545,7 +582,10 @@ void LLAvatarNameCache::buildLegacyName(const std::string& full_name, av_name->mDisplayName = full_name; av_name->mIsDisplayNameDefault = true; av_name->mIsTemporaryName = true; - av_name->mExpires = F64_MAX; + av_name->mExpires = F64_MAX; // not used because these are not cached + LL_DEBUGS("AvNameCache") << "LLAvatarNameCache::buildLegacyName " + << full_name + << LL_ENDL; } // fills in av_name if it has it in the cache, even if expired (can check expiry time) @@ -568,6 +608,9 @@ bool LLAvatarNameCache::get(const LLUUID& agent_id, LLAvatarName *av_name) { if (!isRequestPending(agent_id)) { + LL_DEBUGS("AvNameCache") << "LLAvatarNameCache::get " + << "refresh agent " << agent_id + << LL_ENDL; sAskQueue.insert(agent_id); } } @@ -589,6 +632,9 @@ bool LLAvatarNameCache::get(const LLUUID& agent_id, LLAvatarName *av_name) if (!isRequestPending(agent_id)) { + LL_DEBUGS("AvNameCache") << "LLAvatarNameCache::get " + << "queue request for agent " << agent_id + << LL_ENDL; sAskQueue.insert(agent_id); } @@ -621,7 +667,6 @@ void LLAvatarNameCache::get(const LLUUID& agent_id, callback_slot_t slot) { // ...name already exists in cache, fire callback now fireSignal(agent_id, slot, av_name); - return; } } @@ -717,6 +762,9 @@ F64 LLAvatarNameCache::nameExpirationFromHeaders(LLSD headers) bool LLAvatarNameCache::expirationFromCacheControl(LLSD headers, F64 *expires) { + bool fromCacheControl = false; + F64 now = LLFrameTimer::getTotalSeconds(); + // Allow the header to override the default LLSD cache_control_header = headers["cache-control"]; if (cache_control_header.isDefined()) @@ -725,12 +773,16 @@ bool LLAvatarNameCache::expirationFromCacheControl(LLSD headers, F64 *expires) std::string cache_control = cache_control_header.asString(); if (max_age_from_cache_control(cache_control, &max_age)) { - F64 now = LLFrameTimer::getTotalSeconds(); *expires = now + (F64)max_age; - return true; + fromCacheControl = true; } } - return false; + LL_DEBUGS("AvNameCache") + << ( fromCacheControl ? "expires based on cache control " : "default expiration " ) + << "in " << *expires - now << " seconds" + << LL_ENDL; + + return fromCacheControl; } -- cgit v1.2.3