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
This commit is contained in:
Dave Townsend 2020-08-10 20:09:27 +00:00
parent b80fa4c694
commit d49a4517e8
20 changed files with 595 additions and 82 deletions

View File

@ -226,7 +226,7 @@ nsresult OpenDBConnection(const QuotaInfo& aQuotaInfo, nsIFile* aDBFile,
}
nsCOMPtr<mozIStorageConnection> 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 +239,7 @@ 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 +258,7 @@ 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;
}

View File

@ -3806,8 +3806,7 @@ nsresult UpgradeSchemaFrom25_0To26_0(mozIStorageConnection& aConnection) {
}
Result<nsCOMPtr<nsIFileURL>, 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<nsCOMPtr<nsIFileURL>, nsresult> GetDatabaseFileURL(
? "&directoryLockId="_ns + IntCString(aDirectoryLockId)
: EmptyCString();
nsAutoCString telemetryFilenameClause;
if (aTelemetryId) {
telemetryFilenameClause.AssignLiteral("&telemetryFilename=indexedDB-");
telemetryFilenameClause.AppendInt(aTelemetryId);
telemetryFilenameClause.Append(NS_ConvertUTF16toUTF8(kSQLiteSuffix));
}
nsCOMPtr<nsIFileURL> 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,19 @@ struct StorageOpenTraits;
template <>
struct StorageOpenTraits<nsIFileURL> {
static Result<MovingNotNull<nsCOMPtr<mozIStorageConnection>>, 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<mozIStorageConnection> connection;
nsresult rv = aStorageService.OpenDatabaseWithFileURL(
&aFileURL, getter_AddRefs(connection));
&aFileURL, telemetryFilename, getter_AddRefs(connection));
return ValOrErr(std::move(connection), rv);
}
@ -4001,7 +4001,8 @@ struct StorageOpenTraits<nsIFileURL> {
template <>
struct StorageOpenTraits<nsIFile> {
static Result<MovingNotNull<nsCOMPtr<mozIStorageConnection>>, nsresult> Open(
mozIStorageService& aStorageService, nsIFile& aFile) {
mozIStorageService& aStorageService, nsIFile& aFile,
const uint32_t aTelemetryId = 0) {
nsCOMPtr<mozIStorageConnection> connection;
nsresult rv = aStorageService.OpenUnsharedDatabase(
&aFile, getter_AddRefs(connection));
@ -4021,12 +4022,13 @@ struct StorageOpenTraits<nsIFile> {
template <class FileOrURLType>
Result<MovingNotNull<nsCOMPtr<mozIStorageConnection>>, nsresult>
OpenDatabaseAndHandleBusy(mozIStorageService& aStorageService,
FileOrURLType& aFileOrURL) {
FileOrURLType& aFileOrURL,
const uint32_t aTelemetryId = 0) {
MOZ_ASSERT(!NS_IsMainThread());
MOZ_ASSERT(!IsOnBackgroundThread());
auto connectionOrErr =
StorageOpenTraits<FileOrURLType>::Open(aStorageService, aFileOrURL);
StorageOpenTraits<FileOrURLType>::Open(aStorageService, aFileOrURL, aTelemetryId);
if (connectionOrErr.isErr() &&
connectionOrErr.inspectErr() == NS_ERROR_STORAGE_BUSY) {
@ -4052,7 +4054,7 @@ OpenDatabaseAndHandleBusy(mozIStorageService& aStorageService,
PR_Sleep(PR_MillisecondsToInterval(100));
connectionOrErr =
StorageOpenTraits<FileOrURLType>::Open(aStorageService, aFileOrURL);
StorageOpenTraits<FileOrURLType>::Open(aStorageService, aFileOrURL, aTelemetryId);
if (!connectionOrErr.isErr() ||
connectionOrErr.inspectErr() != NS_ERROR_STORAGE_BUSY ||
TimeStamp::NowLoRes() - start > TimeDuration::FromSeconds(10)) {
@ -4081,7 +4083,7 @@ CreateStorageConnection(nsIFile& aDBFile, nsIFile& aFMDirectory,
bool exists;
auto dbFileUrlOrErr =
GetDatabaseFileURL(aDBFile, aDirectoryLockId, aTelemetryId);
GetDatabaseFileURL(aDBFile, aDirectoryLockId);
if (NS_WARN_IF(dbFileUrlOrErr.isErr())) {
return dbFileUrlOrErr.propagateErr();
}
@ -4095,7 +4097,7 @@ 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 +4135,7 @@ CreateStorageConnection(nsIFile& aDBFile, nsIFile& aFMDirectory,
}
}
connectionOrErr = OpenDatabaseAndHandleBusy(*ss, *dbFileUrl);
connectionOrErr = OpenDatabaseAndHandleBusy(*ss, *dbFileUrl, aTelemetryId);
}
if (NS_WARN_IF(connectionOrErr.isErr())) {
@ -4548,7 +4550,7 @@ GetStorageConnection(nsIFile& aDatabaseFile, const int64_t aDirectoryLockId,
}
auto dbFileUrlOrErr =
GetDatabaseFileURL(aDatabaseFile, aDirectoryLockId, aTelemetryId);
GetDatabaseFileURL(aDatabaseFile, aDirectoryLockId);
if (NS_WARN_IF(dbFileUrlOrErr.isErr())) {
return dbFileUrlOrErr.propagateErr();
}
@ -4560,7 +4562,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();
}

View File

@ -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

View File

@ -122,8 +122,8 @@ 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 +147,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);
@ -157,13 +157,18 @@ bool AsyncExecuteStatements::bindExecuteAndProcessStatement(
}
bool AsyncExecuteStatements::executeAndProcessStatement(
sqlite3_stmt* aStatement, bool aLastStatement) {
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 +213,16 @@ bool AsyncExecuteStatements::executeAndProcessStatement(
return true;
}
bool AsyncExecuteStatements::executeStatement(sqlite3_stmt* aStatement) {
bool AsyncExecuteStatements::executeStatement(StatementData& aData) {
mMutex.AssertNotCurrentThreadOwns();
Telemetry::AutoTimer<Telemetry::MOZ_STORAGE_ASYNC_REQUESTS_MS>
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 +245,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 +269,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 +561,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;
}
}

View File

@ -119,14 +119,14 @@ 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 executeAndProcessStatement(StatementData& aData,
bool aLastStatement);
/**
@ -134,11 +134,11 @@ class AsyncExecuteStatements final : public Runnable,
*
* @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

View File

@ -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,103 @@ 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 +672,7 @@ nsresult Connection::initialize() {
// database.
nsresult rv = initializeInternal();
RecordOpenStatus(rv);
NS_ENSURE_SUCCESS(rv, rv);
return NS_OK;
@ -597,6 +687,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 +717,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 +735,14 @@ 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 +756,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 +771,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 +796,7 @@ 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 +930,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;
@ -1068,11 +1160,7 @@ nsresult Connection::internalClose(sqlite3* aNativeConnection) {
}
nsCString Connection::getFilename() {
nsCString leafname(":memory:");
if (mDatabaseFile) {
(void)mDatabaseFile->GetNativeLeafName(leafname);
}
return leafname;
return mTelemetryFilename;
}
int Connection::stepStatement(sqlite3* aNativeConnection,
@ -1189,6 +1277,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 +1532,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;

View File

@ -103,7 +103,7 @@ 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 +305,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.

View File

@ -27,6 +27,16 @@ 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;
if (rc == SQLITE_OK || rc == SQLITE_ROW || rc == SQLITE_DONE) {
return false;
}
return true;
}
nsresult convertResultCode(int aSQLiteResultCode) {
// Drop off the extended result bits of the result code.
int rc = aSQLiteResultCode & 0xFF;

View File

@ -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.
*

View File

@ -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<Connection> 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);

View File

@ -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)) {

View File

@ -76,12 +76,26 @@ class Statement final : public mozIStorageStatement,
nsTArray<nsCString> 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.

View File

@ -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<BindingParamsArray> mParamsArray;
bool mQueryStatusRecorded;
/**
* We hold onto a reference of the statement's owner so it doesn't get

Binary file not shown.

Binary file not shown.

View File

@ -10,12 +10,31 @@ var { AppConstants } = ChromeUtils.import(
"resource://gre/modules/AppConstants.jsm"
);
const { TelemetryTestUtils } = ChromeUtils.import(
"resource://testing-common/TelemetryTestUtils.jsm"
);
const OPEN_HISTOGRAM = "SQLITE_STORE_OPEN";
const QUERY_HISTOGRAM = "SQLITE_STORE_QUERY";
const TELEMETRY_VALUES = {
success: 0,
failure: 1,
access: 2,
diskio: 3,
corrupt: 4,
busy: 5,
misuse: 6,
diskspace: 7,
};
do_get_profile();
var gDBConn = null;
const TEST_DB_NAME = "test_storage.sqlite";
function getTestDB() {
var db = Services.dirsvc.get("ProfD", Ci.nsIFile);
db.append("test_storage.sqlite");
db.append(TEST_DB_NAME);
return db;
}
@ -95,6 +114,10 @@ function asyncCleanup() {
function getOpenedDatabase() {
if (!gDBConn) {
gDBConn = Services.storage.openDatabase(getTestDB());
// Clear out counts for any queries that occured while opening the database.
TelemetryTestUtils.getAndClearKeyedHistogram(OPEN_HISTOGRAM);
TelemetryTestUtils.getAndClearKeyedHistogram(QUERY_HISTOGRAM);
}
return gDBConn;
}

View File

@ -179,16 +179,34 @@ function execAsync(aStmt, aOptions, aResults) {
* error synchronously (and is tested elsewhere).
*/
function test_illegal_sql_async_deferred() {
let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(QUERY_HISTOGRAM);
// gibberish
let stmt = makeTestStatement("I AM A ROBOT. DO AS I SAY.");
execAsync(stmt, { error: Ci.mozIStorageError.ERROR });
stmt.finalize();
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
TEST_DB_NAME,
TELEMETRY_VALUES.failure,
1
);
histogram.clear();
// legal SQL syntax, but with semantics issues.
stmt = makeTestStatement("SELECT destination FROM funkytown");
execAsync(stmt, { error: Ci.mozIStorageError.ERROR });
stmt.finalize();
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
TEST_DB_NAME,
TELEMETRY_VALUES.failure,
1
);
histogram.clear();
run_next_test();
}
test_illegal_sql_async_deferred.asyncOnly = true;
@ -197,6 +215,8 @@ function test_create_table() {
// Ensure our table doesn't exist
Assert.ok(!getOpenedDatabase().tableExists("test"));
let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(QUERY_HISTOGRAM);
var stmt = makeTestStatement(
"CREATE TABLE test (" +
"id INTEGER, " +
@ -209,18 +229,34 @@ function test_create_table() {
execAsync(stmt);
stmt.finalize();
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
TEST_DB_NAME,
TELEMETRY_VALUES.success,
1
);
histogram.clear();
// Check that the table has been created
Assert.ok(getOpenedDatabase().tableExists("test"));
histogram.clear();
// Verify that it's created correctly (this will throw if it wasn't)
let checkStmt = getOpenedDatabase().createStatement(
"SELECT id, string, number, nuller, blober FROM test"
);
checkStmt.finalize();
// Nothing has executed so the histogram should be empty.
Assert.ok(!histogram.snapshot().values);
run_next_test();
}
function test_add_data() {
let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(QUERY_HISTOGRAM);
var stmt = makeTestStatement(
"INSERT INTO test (id, string, number, nuller, blober) " +
"VALUES (?, ?, ?, ?, ?)"
@ -234,16 +270,35 @@ function test_add_data() {
execAsync(stmt);
stmt.finalize();
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
TEST_DB_NAME,
TELEMETRY_VALUES.success,
1
);
histogram.clear();
// Check that the result is in the table
verifyQuery(
"SELECT string, number, nuller, blober FROM test WHERE id = ?",
INTEGER,
[TEXT, REAL, null, BLOB]
);
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
TEST_DB_NAME,
TELEMETRY_VALUES.success,
1
);
histogram.clear();
run_next_test();
}
function test_get_data() {
let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(QUERY_HISTOGRAM);
var stmt = makeTestStatement(
"SELECT string, number, nuller, blober, id FROM test WHERE id = ?"
);
@ -308,10 +363,21 @@ function test_get_data() {
},
]);
stmt.finalize();
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
TEST_DB_NAME,
TELEMETRY_VALUES.success,
1
);
histogram.clear();
run_next_test();
}
function test_tuple_out_of_bounds() {
let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(QUERY_HISTOGRAM);
var stmt = makeTestStatement("SELECT string FROM test");
execAsync(stmt, {}, [
function(tuple) {
@ -348,6 +414,15 @@ function test_tuple_out_of_bounds() {
},
]);
stmt.finalize();
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
TEST_DB_NAME,
TELEMETRY_VALUES.success,
1
);
histogram.clear();
run_next_test();
}
@ -450,10 +525,21 @@ function test_cancellation_after_execution() {
* handleResult to get called multiple times) and not comprehensive.
*/
function test_double_execute() {
let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(QUERY_HISTOGRAM);
var stmt = makeTestStatement("SELECT 1");
execAsync(stmt, null, 1);
execAsync(stmt, null, 1);
stmt.finalize();
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
TEST_DB_NAME,
TELEMETRY_VALUES.success,
2
);
histogram.clear();
run_next_test();
}

View File

@ -42,36 +42,78 @@ function test_openUnsharedDatabase_null_file() {
function test_openDatabase_file_DNE() {
// the file should be created after calling
let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(OPEN_HISTOGRAM);
var db = getTestDB();
Assert.ok(!db.exists());
Services.storage.openDatabase(db);
Assert.ok(db.exists());
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
db.leafName,
TELEMETRY_VALUES.success,
1
);
}
function test_openDatabase_file_exists() {
// it should already exist from our last test
let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(OPEN_HISTOGRAM);
var db = getTestDB();
Assert.ok(db.exists());
Services.storage.openDatabase(db);
Assert.ok(db.exists());
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
db.leafName,
TELEMETRY_VALUES.success,
1
);
}
function test_corrupt_db_throws_with_openDatabase() {
let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(OPEN_HISTOGRAM);
let db = getCorruptDB();
try {
getDatabase(getCorruptDB());
getDatabase(db);
do_throw("should not be here");
} catch (e) {
Assert.equal(Cr.NS_ERROR_FILE_CORRUPTED, e.result);
}
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
db.leafName,
TELEMETRY_VALUES.corrupt,
1
);
}
function test_fake_db_throws_with_openDatabase() {
let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(OPEN_HISTOGRAM);
let db = getFakeDB();
try {
getDatabase(getFakeDB());
getDatabase(db);
do_throw("should not be here");
} catch (e) {
Assert.equal(Cr.NS_ERROR_FILE_CORRUPTED, e.result);
}
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
db.leafName,
TELEMETRY_VALUES.corrupt,
1
);
}
function test_backup_not_new_filename() {
@ -113,6 +155,106 @@ function test_backup_new_folder() {
parentDir.remove(true);
}
function test_openDatabase_directory() {
let dir = getTestDB().parent;
dir.append("test_storage_temp");
if (dir.exists()) {
dir.remove(true);
}
dir.create(Ci.nsIFile.DIRECTORY_TYPE, 0o755);
Assert.ok(dir.exists());
let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(OPEN_HISTOGRAM);
try {
getDatabase(dir);
do_throw("should not be here");
} catch (e) {
Assert.equal(Cr.NS_ERROR_FILE_ACCESS_DENIED, e.result);
}
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
dir.leafName,
TELEMETRY_VALUES.access,
1
);
dir.remove(true);
}
function test_read_gooddb() {
let file = do_get_file("goodDB.sqlite");
let db = getDatabase(file);
let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(QUERY_HISTOGRAM);
db.executeSimpleSQL("SELECT * FROM Foo;");
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
file.leafName,
TELEMETRY_VALUES.success,
1
);
histogram.clear();
let stmt = db.createStatement("SELECT id from Foo");
while (true) {
if (!stmt.executeStep()) {
break;
}
}
stmt.finalize();
// A single statement should count as a single access.
TelemetryTestUtils.assertKeyedHistogramValue(
histogram,
file.leafName,
TELEMETRY_VALUES.success,
1
);
}
function test_read_baddb() {
let file = do_get_file("baddataDB.sqlite");
let db = getDatabase(file);
let histogram = TelemetryTestUtils.getAndClearKeyedHistogram(QUERY_HISTOGRAM);
Assert.throws(
() => 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,6 +266,9 @@ 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() {

View File

@ -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

View File

@ -15442,5 +15442,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"
]
}
}