diff --git a/storage/src/TelemetryVFS.cpp b/storage/src/TelemetryVFS.cpp index ddb06ac5fffb..cfc8b1d45600 100644 --- a/storage/src/TelemetryVFS.cpp +++ b/storage/src/TelemetryVFS.cpp @@ -37,9 +37,10 @@ * * ***** END LICENSE BLOCK ***** */ +#include #include "mozilla/Telemetry.h" #include "sqlite3.h" -#include +#include "nsThreadUtils.h" namespace { @@ -74,6 +75,27 @@ Histograms gHistograms[] = { Telemetry::MOZ_SQLITE_OTHER_SYNC } }; + +/** RAII class for measuring how long io takes on/off main thread */ +class IOThreadAutoTimer { +public: + IOThreadAutoTimer(MOZILLA_GUARD_OBJECT_NOTIFIER_ONLY_PARAM) + : start(TimeStamp::Now()) + { + MOZILLA_GUARD_OBJECT_NOTIFIER_INIT; + } + + ~IOThreadAutoTimer() { + Accumulate(NS_IsMainThread() ? Telemetry::MOZ_SQLITE_MAIN_THREAD_WAIT_MS + : Telemetry::MOZ_SQLITE_OTHER_THREAD_WAIT_MS + , (TimeStamp::Now() - start).ToMilliseconds()); + } + +private: + const TimeStamp start; + MOZILLA_DECL_USE_GUARD_OBJECT_NOTIFIER +}; + struct telemetry_file { sqlite3_file base; // Base class. Must be first Histograms *histograms; // histograms pertaining to this file @@ -102,6 +124,7 @@ xClose(sqlite3_file *pFile) int xRead(sqlite3_file *pFile, void *zBuf, int iAmt, sqlite_int64 iOfst) { + IOThreadAutoTimer ioTimer; telemetry_file *p = (telemetry_file *)pFile; Telemetry::AutoTimer timer; int rc; @@ -118,6 +141,7 @@ xRead(sqlite3_file *pFile, void *zBuf, int iAmt, sqlite_int64 iOfst) int xWrite(sqlite3_file *pFile, const void *zBuf, int iAmt, sqlite_int64 iOfst) { + IOThreadAutoTimer ioTimer; telemetry_file *p = (telemetry_file *)pFile; Telemetry::AutoTimer timer; int rc; @@ -132,6 +156,7 @@ xWrite(sqlite3_file *pFile, const void *zBuf, int iAmt, sqlite_int64 iOfst) int xTruncate(sqlite3_file *pFile, sqlite_int64 size) { + IOThreadAutoTimer ioTimer; telemetry_file *p = (telemetry_file *)pFile; int rc; Telemetry::AutoTimer timer; @@ -145,6 +170,7 @@ xTruncate(sqlite3_file *pFile, sqlite_int64 size) int xSync(sqlite3_file *pFile, int flags) { + IOThreadAutoTimer ioTimer; telemetry_file *p = (telemetry_file *)pFile; const TimeStamp start = TimeStamp::Now(); int rc = p->pReal->pMethods->xSync(p->pReal, flags); @@ -271,6 +297,7 @@ int xOpen(sqlite3_vfs* vfs, const char *zName, sqlite3_file* pFile, int flags, int *pOutFlags) { + IOThreadAutoTimer ioTimer; Telemetry::AutoTimer timer; sqlite3_vfs *orig_vfs = static_cast(vfs->pAppData); int rc; diff --git a/toolkit/components/telemetry/TelemetryHistograms.h b/toolkit/components/telemetry/TelemetryHistograms.h index dc875f78abbc..e611329c7e8c 100644 --- a/toolkit/components/telemetry/TelemetryHistograms.h +++ b/toolkit/components/telemetry/TelemetryHistograms.h @@ -103,21 +103,23 @@ HTTP_HISTOGRAMS(SUB, "subitem: ") #undef HTTP_HISTOGRAMS HISTOGRAM(FIND_PLUGINS, 1, 3000, 10, EXPONENTIAL, "Time spent scanning filesystem for plugins (ms)") HISTOGRAM(CHECK_JAVA_ENABLED, 1, 3000, 10, EXPONENTIAL, "Time spent checking if Java is enabled (ms)") -HISTOGRAM(MOZ_SQLITE_OPEN, 1, 3000, 10, EXPONENTIAL, "Time spent on sqlite open() (ms)") -HISTOGRAM(MOZ_SQLITE_READ_MS, 1, 3000, 10, EXPONENTIAL, "Time spent on sqlite read() (ms)") -HISTOGRAM(MOZ_SQLITE_OTHER_READ_B, 1, 32768, 3, LINEAR, "Sqlite read() (bytes)") -HISTOGRAM(MOZ_SQLITE_PLACES_READ_B, 1, 32768, 3, LINEAR, "Sqlite read() (bytes)") -HISTOGRAM(MOZ_SQLITE_COOKIES_READ_B, 1, 32768, 3, LINEAR, "Sqlite read() (bytes)") -HISTOGRAM(MOZ_SQLITE_URLCLASSIFIER_READ_B, 1, 32768, 3, LINEAR, "Sqlite read() (bytes)") -HISTOGRAM(MOZ_SQLITE_WRITE_MS, 1, 3000, 10, EXPONENTIAL, "Time spent on sqlite write() (ms)") -HISTOGRAM(MOZ_SQLITE_PLACES_WRITE_B, 1, 32768, 3, LINEAR, "Sqlite write (bytes)") -HISTOGRAM(MOZ_SQLITE_COOKIES_WRITE_B, 1, 32768, 3, LINEAR, "Sqlite write (bytes)") -HISTOGRAM(MOZ_SQLITE_URLCLASSIFIER_WRITE_B, 1, 32768, 3, LINEAR, "Sqlite write (bytes)") -HISTOGRAM(MOZ_SQLITE_OTHER_WRITE_B, 1, 32768, 3, LINEAR, "Sqlite write (bytes)") -HISTOGRAM(MOZ_SQLITE_TRUNCATE, 1, 3000, 10, EXPONENTIAL, "Time spent on sqlite truncate() (ms)") -HISTOGRAM(MOZ_SQLITE_PLACES_SYNC, 1, 10000, 10, EXPONENTIAL, "Time spent on sqlite fsync() (ms)") -HISTOGRAM(MOZ_SQLITE_COOKIES_SYNC, 1, 10000, 10, EXPONENTIAL, "Time spent on sqlite fsync() (ms)") -HISTOGRAM(MOZ_SQLITE_URLCLASSIFIER_SYNC, 1, 10000, 10, EXPONENTIAL, "Time spent on sqlite fsync() (ms)") -HISTOGRAM(MOZ_SQLITE_OTHER_SYNC, 1, 10000, 10, EXPONENTIAL, "Time spent on sqlite fsync() (ms)") +HISTOGRAM(MOZ_SQLITE_OPEN, 1, 3000, 10, EXPONENTIAL, "Time spent on SQLite open() (ms)") +HISTOGRAM(MOZ_SQLITE_READ_MS, 1, 3000, 10, EXPONENTIAL, "Time spent on SQLite read() (ms)") +HISTOGRAM(MOZ_SQLITE_OTHER_READ_B, 1, 32768, 3, LINEAR, "SQLite read() (bytes)") +HISTOGRAM(MOZ_SQLITE_PLACES_READ_B, 1, 32768, 3, LINEAR, "SQLite read() (bytes)") +HISTOGRAM(MOZ_SQLITE_COOKIES_READ_B, 1, 32768, 3, LINEAR, "SQLite read() (bytes)") +HISTOGRAM(MOZ_SQLITE_URLCLASSIFIER_READ_B, 1, 32768, 3, LINEAR, "SQLite read() (bytes)") +HISTOGRAM(MOZ_SQLITE_WRITE_MS, 1, 3000, 10, EXPONENTIAL, "Time spent on SQLite write() (ms)") +HISTOGRAM(MOZ_SQLITE_PLACES_WRITE_B, 1, 32768, 3, LINEAR, "SQLite write (bytes)") +HISTOGRAM(MOZ_SQLITE_COOKIES_WRITE_B, 1, 32768, 3, LINEAR, "SQLite write (bytes)") +HISTOGRAM(MOZ_SQLITE_URLCLASSIFIER_WRITE_B, 1, 32768, 3, LINEAR, "SQLite write (bytes)") +HISTOGRAM(MOZ_SQLITE_OTHER_WRITE_B, 1, 32768, 3, LINEAR, "SQLite write (bytes)") +HISTOGRAM(MOZ_SQLITE_TRUNCATE, 1, 3000, 10, EXPONENTIAL, "Time spent on SQLite truncate() (ms)") +HISTOGRAM(MOZ_SQLITE_PLACES_SYNC, 1, 10000, 10, EXPONENTIAL, "Time spent on SQLite fsync() (ms)") +HISTOGRAM(MOZ_SQLITE_COOKIES_SYNC, 1, 10000, 10, EXPONENTIAL, "Time spent on SQLite fsync() (ms)") +HISTOGRAM(MOZ_SQLITE_URLCLASSIFIER_SYNC, 1, 10000, 10, EXPONENTIAL, "Time spent on SQLite fsync() (ms)") +HISTOGRAM(MOZ_SQLITE_OTHER_SYNC, 1, 10000, 10, EXPONENTIAL, "Time spent on SQLite fsync() (ms)") HISTOGRAM(STARTUP_MEASUREMENT_ERRORS, 1, 3, 4, LINEAR, "Flags errors in startup calculation()") HISTOGRAM(NETWORK_DISK_CACHE_OPEN, 1, 10000, 10, EXPONENTIAL, "Time spent opening disk cache (ms)") +HISTOGRAM(MOZ_SQLITE_MAIN_THREAD_WAIT_MS, 1, 3000, 10, EXPONENTIAL, "Time spent waiting on SQLite IO on main thread (ms)") +HISTOGRAM(MOZ_SQLITE_OTHER_THREAD_WAIT_MS, 1, 3000, 10, EXPONENTIAL, "Time spent waiting on SQLite IO off main thread (ms)")