Changeset 181086 in webkit


Ignore:
Timestamp:
Mar 5, 2015 10:59:57 AM (9 years ago)
Author:
Chris Dumez
Message:

NetworkCache efficacy logging is using too much CPU
​https://bugs.webkit.org/show_bug.cgi?id=142186
<rdar://problem/19632080>

Reviewed by Antti Koivisto.

Source/WebKit2:

NetworkCache efficacy logging was using too much CPU mostly due to
database writes. Logging was using ~11.3% of the NetworkProcess'
CPU usage (~9.2% for writes / ~1.3% for reads).

This patch buffers writes requests in memory and only writes them
to disk every 10 seconds. We are thus writing to this less frequently
and writing more at once, in a single SQL transaction. After this
change, efficacy logging only accounts for ~3.5% of the NetworkProcess'
CPU activity (1.5% for writes / 1.2% for reads).

Now that CPU usage is more acceptable, this patch re-enables the
network cache efficicy logging.

  • NetworkProcess/cache/NetworkCacheStatistics.h:
  • NetworkProcess/cache/NetworkCacheStatisticsCocoa.mm:

(WebKit::executeSQLCommand):
(WebKit::executeSQLStatement):
Call step() instead of executeCommand() because:

  • The input statement is already prepared.
  • step() does not finalize() the statement and thus we caller can reuse it after calling reset().

(WebKit::NetworkCacheStatistics::NetworkCacheStatistics):
(WebKit::NetworkCacheStatistics::initialize):
(WebKit::NetworkCacheStatistics::bootstrapFromNetworkCache):
(WebKit::NetworkCacheStatistics::recordNotCachingResponse):
(WebKit::NetworkCacheStatistics::recordNotUsingCacheForRequest):
(WebKit::NetworkCacheStatistics::recordRetrievalFailure):
(WebKit::NetworkCacheStatistics::markAsRequested):
(WebKit::NetworkCacheStatistics::writeTimerFired):
(WebKit::NetworkCacheStatistics::queryWasEverRequested):
(WebKit::NetworkCacheStatistics::addHashesToDatabase):
(WebKit::NetworkCacheStatistics::addStoreDecisionsToDatabase):
(WebKit::NetworkCacheStatistics::addHashToDatabase): Deleted.

  • UIProcess/Cocoa/WebProcessPoolCocoa.mm:

(WebKit::registerUserDefaultsIfNeeded):
Re-enable the network cache efficacy logging.

Source/WTF:

  • wtf/HashMap.h:

(WTF::copyToVector):
Add copyToVector() utility function for HashMap that uses an std::pair<key, value>
as element type.

  • wtf/text/WTFString.h:

(WTF::StringCapture::StringCapture):
(WTF::StringCapture::operator=):
Add default constructor and assignment operator to StringCapture so that
it can be used in a Vector.

Location:
trunk/Source
Files:
7 edited

Legend:

Unmodified
Added
Removed

  • trunk/Source/WTF/ChangeLog

    r181080 r181086  
     12015-03-05  Chris Dumez  <cdumez@apple.com>
     2
     3        NetworkCache efficacy logging is using too much CPU
     4        https://bugs.webkit.org/show_bug.cgi?id=142186
     5        <rdar://problem/19632080>
     6
     7        Reviewed by Antti Koivisto.
     8
     9        * wtf/HashMap.h:
     10        (WTF::copyToVector):
     11        Add copyToVector() utility function for HashMap that uses an std::pair<key, value>
     12        as element type.
     13
     14        * wtf/text/WTFString.h:
     15        (WTF::StringCapture::StringCapture):
     16        (WTF::StringCapture::operator=):
     17        Add default constructor and assignment operator to StringCapture so that
     18        it can be used in a Vector.
     19
    1202015-03-05  Antti Koivisto  <antti@apple.com>
    221

  • trunk/Source/WTF/wtf/HashMap.h

    r174268 r181086  
    501501
    502502template<typename T, typename U, typename V, typename W, typename X, typename Y>
     503inline void copyToVector(const HashMap<T, U, V, W, X>& collection, Y& vector)
     504{
     505    typedef typename HashMap<T, U, V, W, X>::const_iterator iterator;
     506
     507    vector.resize(collection.size());
     508
     509    iterator it = collection.begin();
     510    iterator end = collection.end();
     511    for (unsigned i = 0; it != end; ++it, ++i)
     512        vector[i] = { (*it).key, (*it).value };
     513}
     514
     515template<typename T, typename U, typename V, typename W, typename X, typename Y>
    503516inline void copyKeysToVector(const HashMap<T, U, V, W, X>& collection, Y& vector)
    504517{

  • trunk/Source/WTF/wtf/text/WTFString.h

    r177860 r181086  
    639639class StringCapture {
    640640public:
    641     explicit StringCapture(const String& string) : m_string(string) { }
     641    StringCapture() { }
     642    StringCapture(const String& string) : m_string(string) { }
    642643    explicit StringCapture(String&& string) : m_string(string) { }
    643644    StringCapture(const StringCapture& other) : m_string(other.m_string.isolatedCopy()) { }
    … …  
    645646    String releaseString() { return WTF::move(m_string); }
    646647
     648    void operator=(const StringCapture& other) { m_string = other.m_string.isolatedCopy(); }
     649
    647650private:
    648     void operator=(const StringCapture&) = delete;
    649651    String m_string;
    650652};

  • trunk/Source/WebKit2/ChangeLog

    r181079 r181086  
     12015-03-05  Chris Dumez  <cdumez@apple.com>
     2
     3        NetworkCache efficacy logging is using too much CPU
     4        https://bugs.webkit.org/show_bug.cgi?id=142186
     5        <rdar://problem/19632080>
     6
     7        Reviewed by Antti Koivisto.
     8
     9        NetworkCache efficacy logging was using too much CPU mostly due to
     10        database writes. Logging was using ~11.3% of the NetworkProcess'
     11        CPU usage (~9.2% for writes / ~1.3% for reads).
     12
     13        This patch buffers writes requests in memory and only writes them
     14        to disk every 10 seconds. We are thus writing to this less frequently
     15        and writing more at once, in a single SQL transaction. After this
     16        change, efficacy logging only accounts for ~3.5% of the NetworkProcess'
     17        CPU activity (1.5% for writes / 1.2% for reads).
     18
     19        Now that CPU usage is more acceptable, this patch re-enables the
     20        network cache efficicy logging.
     21
     22        * NetworkProcess/cache/NetworkCacheStatistics.h:
     23
     24        * NetworkProcess/cache/NetworkCacheStatisticsCocoa.mm:
     25        (WebKit::executeSQLCommand):
     26        (WebKit::executeSQLStatement):
     27        Call step() instead of executeCommand() because:
     28        - The input statement is already prepared.
     29        - step() does not finalize() the statement and thus we caller can
     30          reuse it after calling reset().
     31
     32        (WebKit::NetworkCacheStatistics::NetworkCacheStatistics):
     33        (WebKit::NetworkCacheStatistics::initialize):
     34        (WebKit::NetworkCacheStatistics::bootstrapFromNetworkCache):
     35        (WebKit::NetworkCacheStatistics::recordNotCachingResponse):
     36        (WebKit::NetworkCacheStatistics::recordNotUsingCacheForRequest):
     37        (WebKit::NetworkCacheStatistics::recordRetrievalFailure):
     38        (WebKit::NetworkCacheStatistics::markAsRequested):
     39        (WebKit::NetworkCacheStatistics::writeTimerFired):
     40        (WebKit::NetworkCacheStatistics::queryWasEverRequested):
     41        (WebKit::NetworkCacheStatistics::addHashesToDatabase):
     42        (WebKit::NetworkCacheStatistics::addStoreDecisionsToDatabase):
     43        (WebKit::NetworkCacheStatistics::addHashToDatabase): Deleted.
     44
     45        * UIProcess/Cocoa/WebProcessPoolCocoa.mm:
     46        (WebKit::registerUserDefaultsIfNeeded):
     47        Re-enable the network cache efficacy logging.
     48
    1492015-03-05  Antti Koivisto  <antti@apple.com>
    250

  • trunk/Source/WebKit2/NetworkProcess/cache/NetworkCacheStatistics.h

    r180456 r181086  
    3333#include "NetworkCacheStorage.h"
    3434#include <WebCore/SQLiteDatabase.h>
     35#include <WebCore/Timer.h>
    3536
    3637namespace WebCore {
    … …  
    5859    void shrinkIfNeeded();
    5960
    60     void addHashToDatabase(const String& hash);
     61    void addHashesToDatabase(const Vector<StringCapture>& hashes);
     62    void addStoreDecisionsToDatabase(const Vector<std::pair<StringCapture, NetworkCache::StoreDecision>>&);
     63    void writeTimerFired();
    6164
    6265    typedef std::function<void (bool wasEverRequested, const Optional<NetworkCache::StoreDecision>&)> RequestedCompletionHandler;
    63     void queryWasEverRequested(const String&, const RequestedCompletionHandler&);
     66    enum class NeedUncachedReason { No, Yes };
     67    void queryWasEverRequested(const String&, NeedUncachedReason, const RequestedCompletionHandler&);
    6468    void markAsRequested(const String& hash);
    6569
    6670    struct EverRequestedQuery {
    6771        String hash;
     72        bool needUncachedReason;
    6873        RequestedCompletionHandler completionHandler;
    6974    };
    … …  
    7681    mutable HashSet<std::unique_ptr<const EverRequestedQuery>> m_activeQueries;
    7782    WebCore::SQLiteDatabase m_database;
     83    HashSet<String> m_hashesToAdd;
     84    HashMap<String, NetworkCache::StoreDecision> m_storeDecisionsToAdd;
     85    WebCore::Timer m_writeTimer;
    7886};
    7987

  • trunk/Source/WebKit2/NetworkProcess/cache/NetworkCacheStatisticsCocoa.mm

    r180517 r181086  
    4444
    4545static const char* networkCacheStatisticsDatabaseName = "WebKitCacheStatistics.db";
     46static const std::chrono::milliseconds mininumWriteInterval = std::chrono::milliseconds(10000);
    4647
    4748static bool executeSQLCommand(WebCore::SQLiteDatabase& database, const String& sql)
    … …  
    6465    ASSERT(statement.database().isOpen());
    6566
    66     bool result = statement.executeCommand();
    67     if (!result)
     67    if (statement.step() != WebCore::SQLResultDone) {
    6868        LOG_ERROR("Network cache statistics: failed to execute statement \"%s\" error \"%s\"", statement.query().utf8().data(), statement.database().lastErrorMsg());
    69 
    70     return result;
     69        return false;
     70    }
     71
     72    return true;
    7173}
    7274
    … …  
    8183NetworkCacheStatistics::NetworkCacheStatistics(const String& databasePath)
    8284    : m_backgroundIOQueue(adoptDispatch(dispatch_queue_create("com.apple.WebKit.Cache.Statistics.Background", DISPATCH_QUEUE_SERIAL)))
     85    , m_writeTimer(*this, &NetworkCacheStatistics::writeTimerFired)
    8386{
    8487    dispatch_set_target_queue(m_backgroundIOQueue.get(), dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_BACKGROUND, 0));
    … …  
    142145    LOG(NetworkCache, "(NetworkProcess) Bootstrapping the network cache statistics database from the network cache...");
    143146
     147    Vector<StringCapture> hashes;
     148    traverseCacheFiles(networkCachePath, [&hashes](const String& hash, const String&) {
     149        hashes.append(hash);
     150    });
     151
    144152    WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
    145     WebCore::SQLiteTransaction bootstrapTransaction(m_database);
    146     bootstrapTransaction.begin();
    147 
    148     traverseCacheFiles(networkCachePath, [this](const String& hash, const String&) {
    149         addHashToDatabase(hash);
    150     });
    151     bootstrapTransaction.commit();
     153    WebCore::SQLiteTransaction writeTransaction(m_database);
     154    writeTransaction.begin();
     155
     156    addHashesToDatabase(hashes);
     157
     158    writeTransaction.commit();
    152159}
    153160
    … …  
    175182    ASSERT(storeDecision != NetworkCache::StoreDecision::Yes);
    176183
    177     StringCapture hashCapture(key.hashAsString());
    178     dispatch_async(m_backgroundIOQueue.get(), [this, hashCapture, storeDecision] {
    179         if (!m_database.isOpen())
    180             return;
    181         WebCore::SQLiteStatement statement(m_database, ASCIILiteral("INSERT OR REPLACE INTO UncachedReason (hash, reason) VALUES (?, ?)"));
    182         if (statement.prepare() != WebCore::SQLResultOk)
    183             return;
    184 
    185         statement.bindText(1, hashCapture.string());
    186         statement.bindInt(2, static_cast<int>(storeDecision));
    187         executeSQLStatement(statement);
    188     });
     184    m_storeDecisionsToAdd.set(key.hashAsString(), storeDecision);
     185    if (!m_writeTimer.isActive())
     186        m_writeTimer.startOneShot(mininumWriteInterval);
    189187}
    190188
    … …  
    213211    String hash = key.hashAsString();
    214212    WebCore::URL requestURL = request.url();
    215     queryWasEverRequested(hash, [this, hash, requestURL, webPageID, retrieveDecision](bool wasEverRequested, const Optional<NetworkCache::StoreDecision>&) {
     213    queryWasEverRequested(hash, NeedUncachedReason::No, [this, hash, requestURL, webPageID, retrieveDecision](bool wasEverRequested, const Optional<NetworkCache::StoreDecision>&) {
    216214        if (wasEverRequested) {
    217215            String diagnosticKey = retrieveDecisionToDiagnosticKey(retrieveDecision);
    … …  
    247245    String hash = key.hashAsString();
    248246    WebCore::URL requestURL = request.url();
    249     queryWasEverRequested(hash, [this, hash, requestURL, webPageID](bool wasPreviouslyRequested, const Optional<NetworkCache::StoreDecision>& storeDecision) {
     247    queryWasEverRequested(hash, NeedUncachedReason::Yes, [this, hash, requestURL, webPageID](bool wasPreviouslyRequested, const Optional<NetworkCache::StoreDecision>& storeDecision) {
    250248        if (wasPreviouslyRequested) {
    251249            String diagnosticKey = storeDecisionToDiagnosticKey(storeDecision.value());
    … …  
    291289    ASSERT(RunLoop::isMain());
    292290
    293     StringCapture hashCapture(hash);
    294     dispatch_async(m_backgroundIOQueue.get(), [this, hashCapture] {
     291    m_hashesToAdd.add(hash);
     292    if (!m_writeTimer.isActive())
     293        m_writeTimer.startOneShot(mininumWriteInterval);
     294}
     295
     296void NetworkCacheStatistics::writeTimerFired()
     297{
     298    ASSERT(RunLoop::isMain());
     299
     300    Vector<StringCapture> hashesToAdd;
     301    copyToVector(m_hashesToAdd, hashesToAdd);
     302    m_hashesToAdd.clear();
     303
     304    Vector<std::pair<StringCapture, NetworkCache::StoreDecision>> storeDecisionsToAdd;
     305    copyToVector(m_storeDecisionsToAdd, storeDecisionsToAdd);
     306    m_storeDecisionsToAdd.clear();
     307
     308    shrinkIfNeeded();
     309
     310    dispatch_async(m_backgroundIOQueue.get(), [this, hashesToAdd, storeDecisionsToAdd] {
     311        if (!m_database.isOpen())
     312            return;
     313
    295314        WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
    296         if (m_database.isOpen())
    297             addHashToDatabase(hashCapture.string());
    298     });
    299 
    300     shrinkIfNeeded();
    301 }
    302 
    303 void NetworkCacheStatistics::queryWasEverRequested(const String& hash, const RequestedCompletionHandler& completionHandler)
    304 {
    305     ASSERT(RunLoop::isMain());
    306 
    307     auto everRequestedQuery = std::make_unique<EverRequestedQuery>(EverRequestedQuery { hash, completionHandler });
     315        WebCore::SQLiteTransaction writeTransaction(m_database);
     316        writeTransaction.begin();
     317
     318        addHashesToDatabase(hashesToAdd);
     319        addStoreDecisionsToDatabase(storeDecisionsToAdd);
     320
     321        writeTransaction.commit();
     322    });
     323}
     324
     325void NetworkCacheStatistics::queryWasEverRequested(const String& hash, NeedUncachedReason needUncachedReason, const RequestedCompletionHandler& completionHandler)
     326{
     327    ASSERT(RunLoop::isMain());
     328
     329    // Query pending writes first.
     330    bool wasAlreadyRequested = m_hashesToAdd.contains(hash);
     331    if (wasAlreadyRequested && needUncachedReason == NeedUncachedReason::No) {
     332        completionHandler(true, Nullopt);
     333        return;
     334    }
     335    if (needUncachedReason == NeedUncachedReason::Yes && m_storeDecisionsToAdd.contains(hash)) {
     336        completionHandler(true, m_storeDecisionsToAdd.get(hash));
     337        return;
     338    }
     339
     340    // Query the database.
     341    auto everRequestedQuery = std::make_unique<EverRequestedQuery>(EverRequestedQuery { hash, needUncachedReason == NeedUncachedReason::Yes, completionHandler });
    308342    auto& query = *everRequestedQuery;
    309343    m_activeQueries.add(WTF::move(everRequestedQuery));
    310     dispatch_async(m_backgroundIOQueue.get(), [this, &query] {
     344    dispatch_async(m_backgroundIOQueue.get(), [this, wasAlreadyRequested, &query] () mutable {
    311345        WebCore::SQLiteTransactionInProgressAutoCounter transactionCounter;
    312         bool wasAlreadyRequested = false;
    313346        Optional<NetworkCache::StoreDecision> storeDecision;
    314347        if (m_database.isOpen()) {
    315             WebCore::SQLiteStatement statement(m_database, ASCIILiteral("SELECT AlreadyRequested.hash, reason FROM AlreadyRequested LEFT OUTER JOIN UncachedReason ON AlreadyRequested.hash=UncachedReason.hash WHERE AlreadyRequested.hash=?"));
    316             if (statement.prepare() == WebCore::SQLResultOk) {
    317                 statement.bindText(1, query.hash);
    318                 if (statement.step() == WebCore::SQLResultRow) {
    319                     wasAlreadyRequested = true;
    320                     storeDecision = statement.isColumnNull(1) ? NetworkCache::StoreDecision::Yes : static_cast<NetworkCache::StoreDecision>(statement.getColumnInt(1));
     348            if (!wasAlreadyRequested) {
     349                WebCore::SQLiteStatement statement(m_database, ASCIILiteral("SELECT hash FROM AlreadyRequested WHERE hash=?"));
     350                if (statement.prepare() == WebCore::SQLResultOk) {
     351                    statement.bindText(1, query.hash);
     352                    wasAlreadyRequested = (statement.step() == WebCore::SQLResultRow);
     353                }
     354            }
     355            if (wasAlreadyRequested && query.needUncachedReason) {
     356                WebCore::SQLiteStatement statement(m_database, ASCIILiteral("SELECT reason FROM UncachedReason WHERE hash=?"));
     357                storeDecision = NetworkCache::StoreDecision::Yes;
     358                if (statement.prepare() == WebCore::SQLResultOk) {
     359                    statement.bindText(1, query.hash);
     360                    if (statement.step() == WebCore::SQLResultRow)
     361                        storeDecision = static_cast<NetworkCache::StoreDecision>(statement.getColumnInt(0));
    321362                }
    322363            }
    … …  
    346387}
    347388
    348 void NetworkCacheStatistics::addHashToDatabase(const String& hash)
     389void NetworkCacheStatistics::addHashesToDatabase(const Vector<StringCapture>& hashes)
    349390{
    350391    ASSERT(!RunLoop::isMain());
    … …  
    356397        return;
    357398
    358     statement.bindText(1, hash);
    359     if (!executeSQLStatement(statement))
    360         return;
    361 
    362     ++m_approximateEntryCount;
     399    for (auto& hash : hashes) {
     400        statement.bindText(1, hash.string());
     401        if (executeSQLStatement(statement))
     402            ++m_approximateEntryCount;
     403        statement.reset();
     404    }
     405}
     406
     407void NetworkCacheStatistics::addStoreDecisionsToDatabase(const Vector<std::pair<StringCapture, NetworkCache::StoreDecision>>& storeDecisions)
     408{
     409    ASSERT(!RunLoop::isMain());
     410    ASSERT(WebCore::SQLiteDatabaseTracker::hasTransactionInProgress());
     411    ASSERT(m_database.isOpen());
     412
     413    WebCore::SQLiteStatement statement(m_database, ASCIILiteral("INSERT OR REPLACE INTO UncachedReason (hash, reason) VALUES (?, ?)"));
     414    if (statement.prepare() != WebCore::SQLResultOk)
     415        return;
     416
     417    for (auto& pair : storeDecisions) {
     418        statement.bindText(1, pair.first.string());
     419        statement.bindInt(2, static_cast<int>(pair.second));
     420        executeSQLStatement(statement);
     421        statement.reset();
     422    }
    363423}
    364424

  • trunk/Source/WebKit2/UIProcess/Cocoa/WebProcessPoolCocoa.mm

    r180869 r181086  
    108108#if ENABLE(NETWORK_CACHE)
    109109    [registrationDictionary setObject:[NSNumber numberWithBool:YES] forKey:WebKitNetworkCacheEnabledDefaultsKey];
    110     [registrationDictionary setObject:[NSNumber numberWithBool:NO] forKey:WebKitNetworkCacheEfficacyLoggingEnabledDefaultsKey];
     110    [registrationDictionary setObject:[NSNumber numberWithBool:YES] forKey:WebKitNetworkCacheEfficacyLoggingEnabledDefaultsKey];
    111111#endif
    112112
Note: See TracChangeset for help on using the changeset viewer.