From c9061686f8722ce95cb0264857b1c9008424a04c Mon Sep 17 00:00:00 2001 From: Dave Townsend Date: Tue, 11 Aug 2020 20:55:33 +0000 Subject: [PATCH] Bug 1635489: Add telemetry on the status of sqlite database accesses. r=mak Includes baddataDB.sqlite which is a copy of goodDB.sqlite but with what appears to be the row count inflated beyond the end of the file. This causes loading the database to succeed but queries to fail. This increments a scalar for every database open and for every database query where a query is the full execution of a statement from start to completion. If a statement is re-used then the scalar will be incremented once for each use. Differential Revision: https://phabricator.services.mozilla.com/D73938 --- dom/cache/DBAction.cpp | 9 +- dom/indexedDB/ActorsParent.cpp | 53 +++--- storage/mozIStorageService.idl | 6 +- storage/mozStorageAsyncStatementExecution.cpp | 48 ++++-- storage/mozStorageAsyncStatementExecution.h | 13 +- storage/mozStorageConnection.cpp | 163 ++++++++++++++---- storage/mozStorageConnection.h | 17 +- storage/mozStoragePrivateHelpers.cpp | 7 + storage/mozStoragePrivateHelpers.h | 9 + storage/mozStorageService.cpp | 3 +- storage/mozStorageStatement.cpp | 43 ++++- storage/mozStorageStatement.h | 14 ++ storage/mozStorageStatementData.h | 20 ++- storage/test/unit/baddataDB.sqlite | Bin 0 -> 8192 bytes storage/test/unit/goodDB.sqlite | Bin 0 -> 8192 bytes storage/test/unit/head_storage.js | 25 ++- .../test/unit/test_statement_executeAsync.js | 93 ++++++++++ storage/test/unit/test_storage_service.js | 156 ++++++++++++++++- storage/test/unit/xpcshell.ini | 2 + toolkit/components/telemetry/Histograms.json | 42 +++++ 20 files changed, 633 insertions(+), 90 deletions(-) create mode 100644 storage/test/unit/baddataDB.sqlite create mode 100644 storage/test/unit/goodDB.sqlite diff --git a/dom/cache/DBAction.cpp b/dom/cache/DBAction.cpp index 2b9364cd97cc..ec97507090a9 100644 --- a/dom/cache/DBAction.cpp +++ b/dom/cache/DBAction.cpp @@ -226,7 +226,8 @@ nsresult OpenDBConnection(const QuotaInfo& aQuotaInfo, nsIFile* aDBFile, } nsCOMPtr conn; - rv = ss->OpenDatabaseWithFileURL(dbFileUrl, getter_AddRefs(conn)); + rv = ss->OpenDatabaseWithFileURL(dbFileUrl, EmptyCString(), + getter_AddRefs(conn)); if (rv == NS_ERROR_FILE_CORRUPTED) { NS_WARNING("Cache database corrupted. Recreating empty database."); @@ -239,7 +240,8 @@ nsresult OpenDBConnection(const QuotaInfo& aQuotaInfo, nsIFile* aDBFile, return rv; } - rv = ss->OpenDatabaseWithFileURL(dbFileUrl, getter_AddRefs(conn)); + rv = ss->OpenDatabaseWithFileURL(dbFileUrl, EmptyCString(), + getter_AddRefs(conn)); } if (NS_WARN_IF(NS_FAILED(rv))) { return rv; @@ -258,7 +260,8 @@ nsresult OpenDBConnection(const QuotaInfo& aQuotaInfo, nsIFile* aDBFile, return rv; } - rv = ss->OpenDatabaseWithFileURL(dbFileUrl, getter_AddRefs(conn)); + rv = ss->OpenDatabaseWithFileURL(dbFileUrl, EmptyCString(), + getter_AddRefs(conn)); if (NS_WARN_IF(NS_FAILED(rv))) { return rv; } diff --git a/dom/indexedDB/ActorsParent.cpp b/dom/indexedDB/ActorsParent.cpp index 4f27be600259..0dbc58d82783 100644 --- a/dom/indexedDB/ActorsParent.cpp +++ b/dom/indexedDB/ActorsParent.cpp @@ -3806,8 +3806,7 @@ nsresult UpgradeSchemaFrom25_0To26_0(mozIStorageConnection& aConnection) { } Result, nsresult> GetDatabaseFileURL( - nsIFile& aDatabaseFile, const int64_t aDirectoryLockId, - const uint32_t aTelemetryId) { + nsIFile& aDatabaseFile, const int64_t aDirectoryLockId) { MOZ_ASSERT(aDirectoryLockId >= -1); nsresult rv; @@ -3840,17 +3839,9 @@ Result, nsresult> GetDatabaseFileURL( ? "&directoryLockId="_ns + IntCString(aDirectoryLockId) : EmptyCString(); - nsAutoCString telemetryFilenameClause; - if (aTelemetryId) { - telemetryFilenameClause.AssignLiteral("&telemetryFilename=indexedDB-"); - telemetryFilenameClause.AppendInt(aTelemetryId); - telemetryFilenameClause.Append(NS_ConvertUTF16toUTF8(kSQLiteSuffix)); - } - nsCOMPtr result; rv = NS_MutateURI(mutator) - .SetQuery("cache=private"_ns + directoryLockIdClause + - telemetryFilenameClause) + .SetQuery("cache=private"_ns + directoryLockIdClause) .Finalize(result); if (NS_WARN_IF(NS_FAILED(rv))) { return Err(rv); @@ -3984,10 +3975,18 @@ struct StorageOpenTraits; template <> struct StorageOpenTraits { static Result>, nsresult> Open( - mozIStorageService& aStorageService, nsIFileURL& aFileURL) { + mozIStorageService& aStorageService, nsIFileURL& aFileURL, + const uint32_t aTelemetryId = 0) { + nsAutoCString telemetryFilename; + if (aTelemetryId) { + telemetryFilename.AssignLiteral("indexedDB-"); + telemetryFilename.AppendInt(aTelemetryId); + telemetryFilename.Append(NS_ConvertUTF16toUTF8(kSQLiteSuffix)); + } + nsCOMPtr connection; nsresult rv = aStorageService.OpenDatabaseWithFileURL( - &aFileURL, getter_AddRefs(connection)); + &aFileURL, telemetryFilename, getter_AddRefs(connection)); return ValOrErr(std::move(connection), rv); } @@ -4001,7 +4000,8 @@ struct StorageOpenTraits { template <> struct StorageOpenTraits { static Result>, nsresult> Open( - mozIStorageService& aStorageService, nsIFile& aFile) { + mozIStorageService& aStorageService, nsIFile& aFile, + const uint32_t aTelemetryId = 0) { nsCOMPtr connection; nsresult rv = aStorageService.OpenUnsharedDatabase( &aFile, getter_AddRefs(connection)); @@ -4021,12 +4021,13 @@ struct StorageOpenTraits { template Result>, nsresult> OpenDatabaseAndHandleBusy(mozIStorageService& aStorageService, - FileOrURLType& aFileOrURL) { + FileOrURLType& aFileOrURL, + const uint32_t aTelemetryId = 0) { MOZ_ASSERT(!NS_IsMainThread()); MOZ_ASSERT(!IsOnBackgroundThread()); - auto connectionOrErr = - StorageOpenTraits::Open(aStorageService, aFileOrURL); + auto connectionOrErr = StorageOpenTraits::Open( + aStorageService, aFileOrURL, aTelemetryId); if (connectionOrErr.isErr() && connectionOrErr.inspectErr() == NS_ERROR_STORAGE_BUSY) { @@ -4051,8 +4052,8 @@ OpenDatabaseAndHandleBusy(mozIStorageService& aStorageService, while (true) { PR_Sleep(PR_MillisecondsToInterval(100)); - connectionOrErr = - StorageOpenTraits::Open(aStorageService, aFileOrURL); + connectionOrErr = StorageOpenTraits::Open( + aStorageService, aFileOrURL, aTelemetryId); if (!connectionOrErr.isErr() || connectionOrErr.inspectErr() != NS_ERROR_STORAGE_BUSY || TimeStamp::NowLoRes() - start > TimeDuration::FromSeconds(10)) { @@ -4080,8 +4081,7 @@ CreateStorageConnection(nsIFile& aDBFile, nsIFile& aFMDirectory, bool exists; - auto dbFileUrlOrErr = - GetDatabaseFileURL(aDBFile, aDirectoryLockId, aTelemetryId); + auto dbFileUrlOrErr = GetDatabaseFileURL(aDBFile, aDirectoryLockId); if (NS_WARN_IF(dbFileUrlOrErr.isErr())) { return dbFileUrlOrErr.propagateErr(); } @@ -4095,7 +4095,8 @@ CreateStorageConnection(nsIFile& aDBFile, nsIFile& aFMDirectory, return Err(rv); } - auto connectionOrErr = OpenDatabaseAndHandleBusy(*ss, *dbFileUrl); + auto connectionOrErr = + OpenDatabaseAndHandleBusy(*ss, *dbFileUrl, aTelemetryId); if (connectionOrErr.isErr()) { if (connectionOrErr.inspectErr() == NS_ERROR_FILE_CORRUPTED) { // If we're just opening the database during origin initialization, then @@ -4133,7 +4134,8 @@ CreateStorageConnection(nsIFile& aDBFile, nsIFile& aFMDirectory, } } - connectionOrErr = OpenDatabaseAndHandleBusy(*ss, *dbFileUrl); + connectionOrErr = + OpenDatabaseAndHandleBusy(*ss, *dbFileUrl, aTelemetryId); } if (NS_WARN_IF(connectionOrErr.isErr())) { @@ -4547,8 +4549,7 @@ GetStorageConnection(nsIFile& aDatabaseFile, const int64_t aDirectoryLockId, return Err(NS_ERROR_DOM_INDEXEDDB_UNKNOWN_ERR); } - auto dbFileUrlOrErr = - GetDatabaseFileURL(aDatabaseFile, aDirectoryLockId, aTelemetryId); + auto dbFileUrlOrErr = GetDatabaseFileURL(aDatabaseFile, aDirectoryLockId); if (NS_WARN_IF(dbFileUrlOrErr.isErr())) { return dbFileUrlOrErr.propagateErr(); } @@ -4560,7 +4561,7 @@ GetStorageConnection(nsIFile& aDatabaseFile, const int64_t aDirectoryLockId, } auto connectionOrErr = - OpenDatabaseAndHandleBusy(*ss, *dbFileUrlOrErr.inspect()); + OpenDatabaseAndHandleBusy(*ss, *dbFileUrlOrErr.inspect(), aTelemetryId); if (NS_WARN_IF(connectionOrErr.isErr())) { return connectionOrErr.propagateErr(); } diff --git a/storage/mozIStorageService.idl b/storage/mozIStorageService.idl index 56d2a127ed22..509ac38b2214 100644 --- a/storage/mozIStorageService.idl +++ b/storage/mozIStorageService.idl @@ -161,8 +161,12 @@ interface mozIStorageService : nsISupports { * * @param aURL * A nsIFileURL that represents the database that is to be opened. + * @param [optional] aTelemetryFilename + * The name to use for the database in telemetry. Only needed if the + * actual filename can contain sensitive information. */ - mozIStorageConnection openDatabaseWithFileURL(in nsIFileURL aFileURL); + mozIStorageConnection openDatabaseWithFileURL(in nsIFileURL aFileURL, + [optional] in ACString aTelemetryFilename); /* * Utilities diff --git a/storage/mozStorageAsyncStatementExecution.cpp b/storage/mozStorageAsyncStatementExecution.cpp index 760df8f6b2bf..e951f6958c2a 100644 --- a/storage/mozStorageAsyncStatementExecution.cpp +++ b/storage/mozStorageAsyncStatementExecution.cpp @@ -122,8 +122,10 @@ bool AsyncExecuteStatements::bindExecuteAndProcessStatement( sqlite3_stmt* aStatement = nullptr; // This cannot fail; we are only called if it's available. - (void)aData.getSqliteStatement(&aStatement); - NS_ASSERTION(aStatement, "You broke the code; do not call here like that!"); + Unused << aData.getSqliteStatement(&aStatement); + MOZ_DIAGNOSTIC_ASSERT( + aStatement, + "bindExecuteAndProcessStatement called without an initialized statement"); BindingParamsArray* paramsArray(aData); // Iterate through all of our parameters, bind them, and execute. @@ -147,7 +149,7 @@ bool AsyncExecuteStatements::bindExecuteAndProcessStatement( // Advance our iterator, execute, and then process the statement. itr++; bool lastStatement = aLastStatement && itr == end; - continueProcessing = executeAndProcessStatement(aStatement, lastStatement); + continueProcessing = executeAndProcessStatement(aData, lastStatement); // Always reset our statement. (void)::sqlite3_reset(aStatement); @@ -156,14 +158,21 @@ bool AsyncExecuteStatements::bindExecuteAndProcessStatement( return continueProcessing; } -bool AsyncExecuteStatements::executeAndProcessStatement( - sqlite3_stmt* aStatement, bool aLastStatement) { +bool AsyncExecuteStatements::executeAndProcessStatement(StatementData& aData, + bool aLastStatement) { mMutex.AssertNotCurrentThreadOwns(); + sqlite3_stmt* aStatement = nullptr; + // This cannot fail; we are only called if it's available. + Unused << aData.getSqliteStatement(&aStatement); + MOZ_DIAGNOSTIC_ASSERT( + aStatement, + "executeAndProcessStatement called without an initialized statement"); + // Execute our statement bool hasResults; do { - hasResults = executeStatement(aStatement); + hasResults = executeStatement(aData); // If we had an error, bail. if (mState == ERROR || mState == CANCELED) return false; @@ -208,11 +217,17 @@ bool AsyncExecuteStatements::executeAndProcessStatement( return true; } -bool AsyncExecuteStatements::executeStatement(sqlite3_stmt* aStatement) { +bool AsyncExecuteStatements::executeStatement(StatementData& aData) { mMutex.AssertNotCurrentThreadOwns(); Telemetry::AutoTimer finallySendExecutionDuration(mRequestStartDate); + sqlite3_stmt* aStatement = nullptr; + // This cannot fail; we are only called if it's available. + Unused << aData.getSqliteStatement(&aStatement); + MOZ_DIAGNOSTIC_ASSERT( + aStatement, "executeStatement called without an initialized statement"); + bool busyRetry = false; while (true) { if (busyRetry) { @@ -235,6 +250,16 @@ bool AsyncExecuteStatements::executeStatement(sqlite3_stmt* aStatement) { SQLiteMutexAutoLock lockedScope(mDBMutex); int rc = mConnection->stepStatement(mNativeConnection, aStatement); + + // Some errors are not fatal, and we can handle them and continue. + if (rc == SQLITE_BUSY) { + ::sqlite3_reset(aStatement); + busyRetry = true; + continue; + } + + aData.MaybeRecordQueryStatus(rc); + // Stop if we have no more results. if (rc == SQLITE_DONE) { Telemetry::Accumulate(Telemetry::MOZ_STORAGE_ASYNC_REQUESTS_SUCCESS, @@ -249,13 +274,6 @@ bool AsyncExecuteStatements::executeStatement(sqlite3_stmt* aStatement) { return true; } - // Some errors are not fatal, and we can handle them and continue. - if (rc == SQLITE_BUSY) { - ::sqlite3_reset(aStatement); - busyRetry = true; - continue; - } - if (rc == SQLITE_INTERRUPT) { mState = CANCELED; return false; @@ -548,7 +566,7 @@ AsyncExecuteStatements::Run() { if (!bindExecuteAndProcessStatement(mStatements[i], finished)) break; } // Otherwise, just execute and process the statement. - else if (!executeAndProcessStatement(stmt, finished)) { + else if (!executeAndProcessStatement(mStatements[i], finished)) { break; } } diff --git a/storage/mozStorageAsyncStatementExecution.h b/storage/mozStorageAsyncStatementExecution.h index 6daebd6d7ac5..81f6ada23c95 100644 --- a/storage/mozStorageAsyncStatementExecution.h +++ b/storage/mozStorageAsyncStatementExecution.h @@ -119,26 +119,25 @@ class AsyncExecuteStatements final : public Runnable, * * @pre mMutex is not held * - * @param aStatement - * The statement to execute and then process. + * @param aData + * The StatementData to execute, and then process. * @param aLastStatement * Indicates if this is the last statement or not. If it is, we have * to set the proper state. * @returns true if we should continue to process statements, false otherwise. */ - bool executeAndProcessStatement(sqlite3_stmt* aStatement, - bool aLastStatement); + bool executeAndProcessStatement(StatementData& aData, bool aLastStatement); /** * Executes a statement to completion, properly handling any error conditions. * * @pre mMutex is not held * - * @param aStatement - * The statement to execute to completion. + * @param aData + * The StatementData to execute to completion. * @returns true if results were obtained, false otherwise. */ - bool executeStatement(sqlite3_stmt* aStatement); + bool executeStatement(StatementData& aData); /** * Builds a result set up with a row from a given statement. If we meet the diff --git a/storage/mozStorageConnection.cpp b/storage/mozStorageConnection.cpp index ebe719d044ad..fc64a9a2cc23 100644 --- a/storage/mozStorageConnection.cpp +++ b/storage/mozStorageConnection.cpp @@ -72,6 +72,9 @@ mozilla::LazyLogModule gStorageLog("mozStorage"); namespace mozilla::storage { using mozilla::dom::quota::QuotaObject; +using mozilla::Telemetry::AccumulateCategoricalKeyed; +using mozilla::Telemetry::LABELS_SQLITE_STORE_OPEN; +using mozilla::Telemetry::LABELS_SQLITE_STORE_QUERY; const char* GetVFSName(bool); @@ -559,17 +562,115 @@ nsIEventTarget* Connection::getAsyncExecutionTarget() { return mAsyncExecutionThread; } +void Connection::RecordOpenStatus(nsresult rv) { + nsCString histogramKey = mTelemetryFilename; + + if (histogramKey.IsEmpty()) { + histogramKey.AssignLiteral("unknown"); + } + + if (NS_SUCCEEDED(rv)) { + AccumulateCategoricalKeyed(histogramKey, LABELS_SQLITE_STORE_OPEN::success); + return; + } + + switch (rv) { + case NS_ERROR_FILE_CORRUPTED: + AccumulateCategoricalKeyed(histogramKey, + LABELS_SQLITE_STORE_OPEN::corrupt); + break; + case NS_ERROR_STORAGE_IOERR: + AccumulateCategoricalKeyed(histogramKey, + LABELS_SQLITE_STORE_OPEN::diskio); + break; + case NS_ERROR_FILE_ACCESS_DENIED: + case NS_ERROR_FILE_IS_LOCKED: + case NS_ERROR_FILE_READ_ONLY: + AccumulateCategoricalKeyed(histogramKey, + LABELS_SQLITE_STORE_OPEN::access); + break; + case NS_ERROR_FILE_NO_DEVICE_SPACE: + AccumulateCategoricalKeyed(histogramKey, + LABELS_SQLITE_STORE_OPEN::diskspace); + break; + default: + AccumulateCategoricalKeyed(histogramKey, + LABELS_SQLITE_STORE_OPEN::failure); + } +} + +void Connection::RecordQueryStatus(int srv) { + nsCString histogramKey = mTelemetryFilename; + + if (histogramKey.IsEmpty()) { + histogramKey.AssignLiteral("unknown"); + } + + switch (srv) { + case SQLITE_OK: + case SQLITE_ROW: + case SQLITE_DONE: + + // Note that these are returned when we intentionally cancel a statement so + // they aren't indicating a failure. + case SQLITE_ABORT: + case SQLITE_INTERRUPT: + AccumulateCategoricalKeyed(histogramKey, + LABELS_SQLITE_STORE_QUERY::success); + break; + case SQLITE_CORRUPT: + case SQLITE_NOTADB: + AccumulateCategoricalKeyed(histogramKey, + LABELS_SQLITE_STORE_QUERY::corrupt); + break; + case SQLITE_PERM: + case SQLITE_CANTOPEN: + case SQLITE_LOCKED: + case SQLITE_READONLY: + AccumulateCategoricalKeyed(histogramKey, + LABELS_SQLITE_STORE_QUERY::access); + break; + case SQLITE_IOERR: + case SQLITE_NOLFS: + AccumulateCategoricalKeyed(histogramKey, + LABELS_SQLITE_STORE_QUERY::diskio); + break; + case SQLITE_FULL: + case SQLITE_TOOBIG: + AccumulateCategoricalKeyed(histogramKey, + LABELS_SQLITE_STORE_OPEN::diskspace); + break; + case SQLITE_CONSTRAINT: + case SQLITE_RANGE: + case SQLITE_MISMATCH: + case SQLITE_MISUSE: + AccumulateCategoricalKeyed(histogramKey, + LABELS_SQLITE_STORE_OPEN::misuse); + break; + case SQLITE_BUSY: + AccumulateCategoricalKeyed(histogramKey, LABELS_SQLITE_STORE_OPEN::busy); + break; + default: + AccumulateCategoricalKeyed(histogramKey, + LABELS_SQLITE_STORE_QUERY::failure); + } +} + nsresult Connection::initialize() { NS_ASSERTION(!connectionReady(), "Initialize called on already opened database!"); MOZ_ASSERT(!mIgnoreLockingMode, "Can't ignore locking on an in-memory db."); AUTO_PROFILER_LABEL("Connection::initialize", OTHER); + mTelemetryFilename.AssignLiteral(":memory:"); + // in memory database requested, sqlite uses a magic file name int srv = ::sqlite3_open_v2(":memory:", &mDBConn, mFlags, GetVFSName(true)); if (srv != SQLITE_OK) { mDBConn = nullptr; - return convertResultCode(srv); + nsresult rv = convertResultCode(srv); + RecordOpenStatus(rv); + return rv; } #ifdef MOZ_SQLITE_FTS3_TOKENIZER @@ -583,6 +684,7 @@ nsresult Connection::initialize() { // database. nsresult rv = initializeInternal(); + RecordOpenStatus(rv); NS_ENSURE_SUCCESS(rv, rv); return NS_OK; @@ -597,6 +699,7 @@ nsresult Connection::initialize(nsIFile* aDatabaseFile) { // Do not set mFileURL here since this is database does not have an associated // URL. mDatabaseFile = aDatabaseFile; + aDatabaseFile->GetNativeLeafName(mTelemetryFilename); nsAutoString path; nsresult rv = aDatabaseFile->GetPath(path); @@ -626,7 +729,9 @@ nsresult Connection::initialize(nsIFile* aDatabaseFile) { } if (srv != SQLITE_OK) { mDBConn = nullptr; - return convertResultCode(srv); + rv = convertResultCode(srv); + RecordOpenStatus(rv); + return rv; } rv = initializeInternal(); @@ -642,12 +747,15 @@ nsresult Connection::initialize(nsIFile* aDatabaseFile) { rv = initializeInternal(); } } + + RecordOpenStatus(rv); NS_ENSURE_SUCCESS(rv, rv); return NS_OK; } -nsresult Connection::initialize(nsIFileURL* aFileURL) { +nsresult Connection::initialize(nsIFileURL* aFileURL, + const nsACString& aTelemetryFilename) { NS_ASSERTION(aFileURL, "Passed null file URL!"); NS_ASSERTION(!connectionReady(), "Initialize called on already opened database!"); @@ -661,6 +769,12 @@ nsresult Connection::initialize(nsIFileURL* aFileURL) { mFileURL = aFileURL; mDatabaseFile = databaseFile; + if (!aTelemetryFilename.IsEmpty()) { + mTelemetryFilename = aTelemetryFilename; + } else { + databaseFile->GetNativeLeafName(mTelemetryFilename); + } + nsAutoCString spec; rv = aFileURL->GetSpec(spec); NS_ENSURE_SUCCESS(rv, rv); @@ -670,10 +784,13 @@ nsresult Connection::initialize(nsIFileURL* aFileURL) { ::sqlite3_open_v2(spec.get(), &mDBConn, mFlags, GetVFSName(exclusive)); if (srv != SQLITE_OK) { mDBConn = nullptr; - return convertResultCode(srv); + rv = convertResultCode(srv); + RecordOpenStatus(rv); + return rv; } rv = initializeInternal(); + RecordOpenStatus(rv); NS_ENSURE_SUCCESS(rv, rv); return NS_OK; @@ -692,24 +809,8 @@ nsresult Connection::initializeInternal() { "SQLITE_DBCONFIG_ENABLE_FTS3_TOKENIZER should be enabled"); #endif - if (mFileURL) { - const char* dbPath = ::sqlite3_db_filename(mDBConn, "main"); - MOZ_ASSERT(dbPath); - - const char* telemetryFilename = - ::sqlite3_uri_parameter(dbPath, "telemetryFilename"); - if (telemetryFilename) { - if (NS_WARN_IF(*telemetryFilename == '\0')) { - return NS_ERROR_INVALID_ARG; - } - mTelemetryFilename = telemetryFilename; - } - } - - if (mTelemetryFilename.IsEmpty()) { - mTelemetryFilename = getFilename(); - MOZ_ASSERT(!mTelemetryFilename.IsEmpty()); - } + MOZ_ASSERT(!mTelemetryFilename.IsEmpty(), + "A telemetry filename should have been set by now."); // Properly wrap the database handle's mutex. sharedDBMutex.initWithMutex(sqlite3_db_mutex(mDBConn)); @@ -843,12 +944,17 @@ nsresult Connection::databaseElementExists( sqlite3_stmt* stmt; int srv = prepareStatement(mDBConn, query, &stmt); - if (srv != SQLITE_OK) return convertResultCode(srv); + if (srv != SQLITE_OK) { + RecordQueryStatus(srv); + return convertResultCode(srv); + } srv = stepStatement(mDBConn, stmt); // we just care about the return value from step (void)::sqlite3_finalize(stmt); + RecordQueryStatus(srv); + if (srv == SQLITE_ROW) { *_exists = true; return NS_OK; @@ -1067,13 +1173,7 @@ nsresult Connection::internalClose(sqlite3* aNativeConnection) { return convertResultCode(srv); } -nsCString Connection::getFilename() { - nsCString leafname(":memory:"); - if (mDatabaseFile) { - (void)mDatabaseFile->GetNativeLeafName(leafname); - } - return leafname; -} +nsCString Connection::getFilename() { return mTelemetryFilename; } int Connection::stepStatement(sqlite3* aNativeConnection, sqlite3_stmt* aStatement) { @@ -1189,6 +1289,7 @@ int Connection::executeSql(sqlite3* aNativeConnection, const char* aSqlString) { TimeStamp startTime = TimeStamp::Now(); int srv = ::sqlite3_exec(aNativeConnection, aSqlString, nullptr, nullptr, nullptr); + RecordQueryStatus(srv); // Report very slow SQL statements to Telemetry TimeDuration duration = TimeStamp::Now() - startTime; @@ -1443,7 +1544,7 @@ Connection::AsyncClone(bool aReadOnly, } nsresult Connection::initializeClone(Connection* aClone, bool aReadOnly) { - nsresult rv = mFileURL ? aClone->initialize(mFileURL) + nsresult rv = mFileURL ? aClone->initialize(mFileURL, mTelemetryFilename) : aClone->initialize(mDatabaseFile); if (NS_FAILED(rv)) { return rv; diff --git a/storage/mozStorageConnection.h b/storage/mozStorageConnection.h index 837a9c9bde9c..5dc88c04d784 100644 --- a/storage/mozStorageConnection.h +++ b/storage/mozStorageConnection.h @@ -103,7 +103,8 @@ class Connection final : public mozIStorageConnection, * The nsIFileURL of the location of the database to open, or create if * it does not exist. */ - nsresult initialize(nsIFileURL* aFileURL); + nsresult initialize(nsIFileURL* aFileURL, + const nsACString& aTelemetryFilename); /** * Same as initialize, but to be used on the async thread. @@ -305,11 +306,25 @@ class Connection final : public mozIStorageConnection, nsresult initializeClone(Connection* aClone, bool aReadOnly); + /** + * Records a status from a sqlite statement. + * + * @param srv The sqlite result for the failure or SQLITE_OK. + */ + void RecordQueryStatus(int srv); + private: ~Connection(); nsresult initializeInternal(); void initializeFailed(); + /** + * Records the status of an attempt to load a sqlite database to telemetry. + * + * @param rv The state of the load, success or failure. + */ + void RecordOpenStatus(nsresult rv); + /** * Sets the database into a closed state so no further actions can be * performed. diff --git a/storage/mozStoragePrivateHelpers.cpp b/storage/mozStoragePrivateHelpers.cpp index 1a5d478f1a37..87ac7fdc3d59 100644 --- a/storage/mozStoragePrivateHelpers.cpp +++ b/storage/mozStoragePrivateHelpers.cpp @@ -27,6 +27,13 @@ extern mozilla::LazyLogModule gStorageLog; namespace mozilla { namespace storage { +bool isErrorCode(int aSQLiteResultCode) { + // Drop off the extended result bits of the result code. + int rc = aSQLiteResultCode & 0xFF; + + return rc != SQLITE_OK && rc != SQLITE_ROW && rc != SQLITE_DONE; +} + nsresult convertResultCode(int aSQLiteResultCode) { // Drop off the extended result bits of the result code. int rc = aSQLiteResultCode & 0xFF; diff --git a/storage/mozStoragePrivateHelpers.h b/storage/mozStoragePrivateHelpers.h index 416c87feadb8..457ee1c1a3cf 100644 --- a/storage/mozStoragePrivateHelpers.h +++ b/storage/mozStoragePrivateHelpers.h @@ -32,6 +32,15 @@ namespace storage { //////////////////////////////////////////////////////////////////////////////// //// Functions +/** + * Returns true if the given SQLite result is an error of come kind. + * + * @param aSQLiteResultCode + * The SQLite return code to check. + * @returns true if the result represents an error. + */ +bool isErrorCode(int aSQLiteResultCode); + /** * Converts a SQLite return code to an nsresult return code. * diff --git a/storage/mozStorageService.cpp b/storage/mozStorageService.cpp index e8c4c3b37ba0..4e0d97e0e956 100644 --- a/storage/mozStorageService.cpp +++ b/storage/mozStorageService.cpp @@ -596,6 +596,7 @@ Service::OpenUnsharedDatabase(nsIFile* aDatabaseFile, NS_IMETHODIMP Service::OpenDatabaseWithFileURL(nsIFileURL* aFileURL, + const nsACString& aTelemetryFilename, mozIStorageConnection** _connection) { NS_ENSURE_ARG(aFileURL); @@ -605,7 +606,7 @@ Service::OpenDatabaseWithFileURL(nsIFileURL* aFileURL, SQLITE_OPEN_CREATE | SQLITE_OPEN_URI; RefPtr msc = new Connection(this, flags, Connection::SYNCHRONOUS); - nsresult rv = msc->initialize(aFileURL); + nsresult rv = msc->initialize(aFileURL, aTelemetryFilename); NS_ENSURE_SUCCESS(rv, rv); msc.forget(_connection); diff --git a/storage/mozStorageStatement.cpp b/storage/mozStorageStatement.cpp index d857c4816402..1c3f8fdbcac6 100644 --- a/storage/mozStorageStatement.cpp +++ b/storage/mozStorageStatement.cpp @@ -105,7 +105,9 @@ Statement::Statement() mParamCount(0), mResultColumnCount(0), mColumnNames(), - mExecuting(false) {} + mExecuting(false), + mQueryStatusRecorded(false), + mHasExecuted(false) {} nsresult Statement::initialize(Connection* aDBConnection, sqlite3* aNativeConnection, @@ -124,6 +126,9 @@ nsresult Statement::initialize(Connection* aDBConnection, ::sqlite3_errmsg(aNativeConnection))); MOZ_LOG(gStorageLog, LogLevel::Error, ("Statement was: '%s'", PromiseFlatCString(aSQLStatement).get())); + + aDBConnection->RecordQueryStatus(srv); + mQueryStatusRecorded = true; return NS_ERROR_FAILURE; } @@ -215,6 +220,28 @@ mozIStorageBindingParams* Statement::getParams() { return *mParamsArray->begin(); } +void Statement::MaybeRecordQueryStatus(int srv, bool isResetting) { + // If the statement hasn't been executed synchronously since it was last reset + // or created then there is no need to record anything. Asynchronous + // statements have their status tracked and recorded by StatementData. + if (!mHasExecuted) { + return; + } + + if (!isResetting && !isErrorCode(srv)) { + // Non-errors will be recorded when finalizing. + return; + } + + // We only record a status if no status has been recorded previously. + if (!mQueryStatusRecorded && mDBConnection) { + mDBConnection->RecordQueryStatus(srv); + } + + // Allow another status to be recorded if we are resetting this statement. + mQueryStatusRecorded = !isResetting; +} + Statement::~Statement() { (void)internalFinalize(true); } //////////////////////////////////////////////////////////////////////////////// @@ -250,6 +277,7 @@ int Statement::getAsyncStatement(sqlite3_stmt** _stmt) { int rc = mDBConnection->prepareStatement(mNativeConnection, sql, &mAsyncStatement); if (rc != SQLITE_OK) { + mDBConnection->RecordQueryStatus(rc); *_stmt = nullptr; return rc; } @@ -346,6 +374,11 @@ nsresult Statement::internalFinalize(bool aDestructing) { #endif // DEBUG } + // This will be a no-op if the status has already been recorded or if this + // statement has not been executed. Async statements have their status + // tracked and recorded in StatementData. + MaybeRecordQueryStatus(srv, true); + mDBStatement = nullptr; if (mAsyncStatement) { @@ -460,6 +493,12 @@ Statement::Reset() { mExecuting = false; + // This will be a no-op if the status has already been recorded or if this + // statement has not been executed. Async statements have their status + // tracked and recorded in StatementData. + MaybeRecordQueryStatus(SQLITE_OK, true); + mHasExecuted = false; + return NS_OK; } @@ -517,6 +556,8 @@ Statement::ExecuteStep(bool* _moreResults) { mParamsArray = nullptr; } int srv = mDBConnection->stepStatement(mNativeConnection, mDBStatement); + mHasExecuted = true; + MaybeRecordQueryStatus(srv); if (srv != SQLITE_ROW && srv != SQLITE_DONE && MOZ_LOG_TEST(gStorageLog, LogLevel::Debug)) { diff --git a/storage/mozStorageStatement.h b/storage/mozStorageStatement.h index d6016503de9f..e472a804c2d0 100644 --- a/storage/mozStorageStatement.h +++ b/storage/mozStorageStatement.h @@ -76,12 +76,26 @@ class Statement final : public mozIStorageStatement, nsTArray mColumnNames; bool mExecuting; + // Tracks whether the status for this statement has been recorded since it was + // last reset or created. + bool mQueryStatusRecorded; + // Tracks whether this statement has been executed since it was last reset or + // created. + bool mHasExecuted; + /** * @return a pointer to the BindingParams object to use with our Bind* * method. */ mozIStorageBindingParams* getParams(); + /** + * Records a query status result in telemetry. If a result has already been + * recorded for this statement then this does nothing. Otherwise the result + * is recorded if it is an error or if this is the final result. + */ + void MaybeRecordQueryStatus(int srv, bool isResetting = false); + /** * Holds the array of parameters to bind to this statement when we execute * it asynchronously. diff --git a/storage/mozStorageStatementData.h b/storage/mozStorageStatementData.h index f336e7375a72..1008496671c1 100644 --- a/storage/mozStorageStatementData.h +++ b/storage/mozStorageStatementData.h @@ -15,6 +15,7 @@ #include "mozStorageBindingParamsArray.h" #include "mozStorageConnection.h" #include "StorageBaseStatementInternal.h" +#include "mozStoragePrivateHelpers.h" struct sqlite3_stmt; @@ -28,16 +29,18 @@ class StatementData { StorageBaseStatementInternal* aStatementOwner) : mStatement(aStatement), mParamsArray(aParamsArray), + mQueryStatusRecorded(false), mStatementOwner(aStatementOwner) { MOZ_ASSERT(mStatementOwner, "Must have a statement owner!"); } StatementData(const StatementData& aSource) : mStatement(aSource.mStatement), mParamsArray(aSource.mParamsArray), + mQueryStatusRecorded(false), mStatementOwner(aSource.mStatementOwner) { MOZ_ASSERT(mStatementOwner, "Must have a statement owner!"); } - StatementData() : mStatement(nullptr) {} + StatementData() : mStatement(nullptr), mQueryStatusRecorded(false) {} ~StatementData() { // We need to ensure that mParamsArray is released on the main thread, // as the binding arguments may be XPConnect values, which are safe @@ -53,6 +56,7 @@ class StatementData { inline int getSqliteStatement(sqlite3_stmt** _stmt) { if (!mStatement) { int rc = mStatementOwner->getAsyncStatement(&mStatement); + MaybeRecordQueryStatus(rc); NS_ENSURE_TRUE(rc == SQLITE_OK, rc); } *_stmt = mStatement; @@ -74,6 +78,10 @@ class StatementData { (void)::sqlite3_reset(mStatement); (void)::sqlite3_clear_bindings(mStatement); mStatement = nullptr; + + if (!mQueryStatusRecorded) { + mStatementOwner->getOwner()->RecordQueryStatus(SQLITE_OK); + } } } @@ -108,9 +116,19 @@ class StatementData { return mParamsArray ? mParamsArray->length() : 1; } + void MaybeRecordQueryStatus(int srv) { + if (mQueryStatusRecorded || !isErrorCode(srv)) { + return; + } + + mStatementOwner->getOwner()->RecordQueryStatus(srv); + mQueryStatusRecorded = true; + } + private: sqlite3_stmt* mStatement; RefPtr mParamsArray; + bool mQueryStatusRecorded; /** * We hold onto a reference of the statement's owner so it doesn't get diff --git a/storage/test/unit/baddataDB.sqlite b/storage/test/unit/baddataDB.sqlite new file mode 100644 index 0000000000000000000000000000000000000000..5b2f9da3d698013c40f5243f3f20295aaaffb424 GIT binary patch literal 8192 zcmeI#u?oUK3zoa-TPYtnk{9hTkIaBg+KrT5P$## zAOHafKmY;|fB*y_@VmgA2jej0ZIc(*a#Pn@CQ4(U#gh4T5{nLGQk~`K(`e_@ss7E| r);-C+-AfMy0uX=z1Rwwb2tWV=5P$##AOL}X5U|#`lQqT_mW|6lYRw#x literal 0 HcmV?d00001 diff --git a/storage/test/unit/goodDB.sqlite b/storage/test/unit/goodDB.sqlite new file mode 100644 index 0000000000000000000000000000000000000000..b06884672fa98e39986252e0b4ae09f9f6ac3c27 GIT binary patch literal 8192 zcmeI#p$@_@5C-6DyWq%?Okhuf0Ray{Sq6w1#)98qBugMo$ljA@!C)}l#54j&{y%qV zdpY&F9`;$&)^Z8=TiMEjMq~`FM2INTw%UD+Ub db.executeSimpleSQL("SELECT * FROM Foo"), + /NS_ERROR_FILE_CORRUPTED/, + "Executing sql should fail." + ); + + TelemetryTestUtils.assertKeyedHistogramValue( + histogram, + file.leafName, + TELEMETRY_VALUES.corrupt, + 1 + ); + + histogram.clear(); + + let stmt = db.createStatement("SELECT * FROM Foo"); + Assert.throws( + () => stmt.executeStep(), + /NS_ERROR_FILE_CORRUPTED/, + "Executing a statement should fail." + ); + + TelemetryTestUtils.assertKeyedHistogramValue( + histogram, + file.leafName, + TELEMETRY_VALUES.corrupt, + 1 + ); +} + var tests = [ test_openSpecialDatabase_invalid_arg, test_openDatabase_null_file, @@ -124,9 +266,19 @@ var tests = [ test_backup_not_new_filename, test_backup_new_filename, test_backup_new_folder, + test_openDatabase_directory, + test_read_gooddb, + test_read_baddb, ]; function run_test() { + // Thunderbird doesn't have one or more of the probes used in this test. + // Ensure the data is collected anyway. + Services.prefs.setBoolPref( + "toolkit.telemetry.testing.overrideProductsCheck", + true + ); + for (var i = 0; i < tests.length; i++) { tests[i](); } diff --git a/storage/test/unit/xpcshell.ini b/storage/test/unit/xpcshell.ini index fde21a4add66..80baaab282f6 100644 --- a/storage/test/unit/xpcshell.ini +++ b/storage/test/unit/xpcshell.ini @@ -1,8 +1,10 @@ [DEFAULT] head = head_storage.js support-files = + baddataDB.sqlite corruptDB.sqlite fakeDB.sqlite + goodDB.sqlite locale_collation.txt vacuumParticipant.js vacuumParticipant.manifest diff --git a/toolkit/components/telemetry/Histograms.json b/toolkit/components/telemetry/Histograms.json index a395b8a2c33b..137f6fe94a0e 100644 --- a/toolkit/components/telemetry/Histograms.json +++ b/toolkit/components/telemetry/Histograms.json @@ -15452,5 +15452,47 @@ "alert_emails": ["jmathies@mozilla.com", "chsiang@mozilla.com"], "bug_numbers": [1653073, 1656355], "releaseChannelCollection": "opt-out" + }, + "SQLITE_STORE_OPEN": { + "record_in_processes": ["main"], + "products": ["firefox"], + "alert_emails": ["dtownsend@mozilla.com", "mbonardo@mozilla.com"], + "expires_in_version": "never", + "kind": "categorical", + "keyed": true, + "releaseChannelCollection": "opt-out", + "bug_numbers": [1635489], + "description": "The result of attempting to open a sqlite file.", + "labels": [ + "success", + "failure", + "access", + "diskio", + "corrupt", + "busy", + "misuse", + "diskspace" + ] + }, + "SQLITE_STORE_QUERY": { + "record_in_processes": ["main"], + "products": ["firefox"], + "alert_emails": ["dtownsend@mozilla.com", "mbonardo@mozilla.com"], + "expires_in_version": "never", + "kind": "categorical", + "keyed": true, + "releaseChannelCollection": "opt-out", + "bug_numbers": [1635489], + "description": "The result of attempting to query a sqlite file.", + "labels": [ + "success", + "failure", + "access", + "diskio", + "corrupt", + "busy", + "misuse", + "diskspace" + ] } }