wine/gecko
0
0
Fork 0
mirror of https://gitlab.winehq.org/wine/wine-gecko.git synced 2024-09-13 09:24:08 -07:00
Code Issues Packages Projects Releases Wiki Activity

Bug 699051. Report slow prepared SQL statements to Telemetry. r=sdwilsh.

Browse Source 
--HG--
extra : rebase_source : dcf66cca7ae7b603b77a6bdacb50b3df1c0442ce
This commit is contained in:
Vladan Djeric 2011-12-06 15:12:55 -05:00
parent 8b1c73bf93
commit 659a71d040
9 changed files with 362 additions and 173 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

3
storage/src/mozStorageAsyncStatement.cpp
View File

@ -333,8 +333,7 @@ AsyncStatement::getAsyncStatement(sqlite3_stmt **_stmt)
#endif
if (!mAsyncStatement) {
int rc = prepareStmt(mDBConnection->GetNativeConnection(), mSQLString,
&mAsyncStatement);
int rc = mDBConnection->prepareStatement(mSQLString, &mAsyncStatement);
if (rc != SQLITE_OK) {
#ifdef PR_LOGGING
PR_LOG(gStorageLog, PR_LOG_ERROR,

2
storage/src/mozStorageAsyncStatementExecution.cpp
View File

@ -365,7 +365,7 @@ AsyncExecuteStatements::executeStatement(sqlite3_stmt *aStatement)
// lock the sqlite mutex so sqlite3_errmsg cannot change
SQLiteMutexAutoLock lockedScope(mDBMutex);
int rc = stepStmt(aStatement);
int rc = mConnection->stepStatement(aStatement);
// Stop if we have no more results.
if (rc == SQLITE_DONE)
{

155
storage/src/mozStorageConnection.cpp
View File

@ -50,6 +50,9 @@
#include "nsIMemoryReporter.h"
#include "nsThreadUtils.h"
#include "nsILocalFile.h"
#include "mozilla/Telemetry.h"
#include "mozilla/Mutex.h"
#include "mozilla/CondVar.h"
#include "mozIStorageAggregateFunction.h"
#include "mozIStorageCompletionCallback.h"
@ -278,6 +281,66 @@ aggregateFunctionFinalHelper(sqlite3_context *aCtx)
}
}
/**
* This code is heavily based on the sample at:
* http://www.sqlite.org/unlock_notify.html
*/
class UnlockNotification
{
public:
UnlockNotification()
: mMutex("UnlockNotification mMutex")
, mCondVar(mMutex, "UnlockNotification condVar")
, mSignaled(false)
{
}
void Wait()
{
MutexAutoLock lock(mMutex);
while (!mSignaled) {
(void)mCondVar.Wait();
}
}
void Signal()
{
MutexAutoLock lock(mMutex);
mSignaled = true;
(void)mCondVar.Notify();
}
private:
Mutex mMutex;
CondVar mCondVar;
bool mSignaled;
};
void
UnlockNotifyCallback(void **aArgs,
int aArgsSize)
{
for (int i = 0; i < aArgsSize; i++) {
UnlockNotification *notification =
static_cast<UnlockNotification *>(aArgs[i]);
notification->Signal();
}
}
int
WaitForUnlockNotify(sqlite3* aDatabase)
{
UnlockNotification notification;
int srv = ::sqlite3_unlock_notify(aDatabase, UnlockNotifyCallback,
&notification);
MOZ_ASSERT(srv == SQLITE_LOCKED || srv == SQLITE_OK);
if (srv == SQLITE_OK) {
notification.Wait();
}
return srv;
}
} // anonymous namespace
////////////////////////////////////////////////////////////////////////////////
@ -580,9 +643,9 @@ Connection::initialize(nsIFile *aDatabaseFile,
// Get the current page_size, since it may differ from the specified value.
sqlite3_stmt *stmt;
srv = prepareStmt(mDBConn, NS_LITERAL_CSTRING("PRAGMA page_size"), &stmt);
srv = prepareStatement(NS_LITERAL_CSTRING("PRAGMA page_size"), &stmt);
if (srv == SQLITE_OK) {
if (SQLITE_ROW == stepStmt(stmt)) {
if (SQLITE_ROW == stepStatement(stmt)) {
pageSize = ::sqlite3_column_int64(stmt, 0);
}
(void)::sqlite3_finalize(stmt);
@ -658,11 +721,11 @@ Connection::databaseElementExists(enum DatabaseElementType aElementType,
query.Append("'");
sqlite3_stmt *stmt;
int srv = prepareStmt(mDBConn, query, &stmt);
int srv = prepareStatement(query, &stmt);
if (srv != SQLITE_OK)
return convertResultCode(srv);
srv = stepStmt(stmt);
srv = stepStatement(stmt);
// we just care about the return value from step
(void)::sqlite3_finalize(stmt);
@ -788,6 +851,90 @@ Connection::getFilename()
return leafname;
}
int
Connection::stepStatement(sqlite3_stmt *aStatement)
{
bool checkedMainThread = false;
TimeStamp startTime = TimeStamp::Now();
(void)::sqlite3_extended_result_codes(mDBConn, 1);
int srv;
while ((srv = ::sqlite3_step(aStatement)) == SQLITE_LOCKED_SHAREDCACHE) {
if (!checkedMainThread) {
checkedMainThread = true;
if (::NS_IsMainThread()) {
NS_WARNING("We won't allow blocking on the main thread!");
break;
}
}
srv = WaitForUnlockNotify(mDBConn);
if (srv != SQLITE_OK) {
break;
}
::sqlite3_reset(aStatement);
}
// Report very slow SQL statements to Telemetry
TimeDuration duration = TimeStamp::Now() - startTime;
if (duration.ToMilliseconds() >= Telemetry::kSlowStatementThreshold) {
nsDependentCString statementString(::sqlite3_sql(aStatement));
Telemetry::RecordSlowSQLStatement(statementString, getFilename(),
duration.ToMilliseconds());
}
(void)::sqlite3_extended_result_codes(mDBConn, 0);
// Drop off the extended result bits of the result code.
return srv & 0xFF;
}
int
Connection::prepareStatement(const nsCString &aSQL,
sqlite3_stmt **_stmt)
{
bool checkedMainThread = false;
(void)::sqlite3_extended_result_codes(mDBConn, 1);
int srv;
while((srv = ::sqlite3_prepare_v2(mDBConn, aSQL.get(), -1, _stmt, NULL)) ==
SQLITE_LOCKED_SHAREDCACHE) {
if (!checkedMainThread) {
checkedMainThread = true;
if (::NS_IsMainThread()) {
NS_WARNING("We won't allow blocking on the main thread!");
break;
}
}
srv = WaitForUnlockNotify(mDBConn);
if (srv != SQLITE_OK) {
break;
}
}
if (srv != SQLITE_OK) {
nsCString warnMsg;
warnMsg.AppendLiteral("The SQL statement '");
warnMsg.Append(aSQL);
warnMsg.AppendLiteral("' could not be compiled due to an error: ");
warnMsg.Append(::sqlite3_errmsg(mDBConn));
#ifdef DEBUG
NS_WARNING(warnMsg.get());
#endif
#ifdef PR_LOGGING
PR_LOG(gStorageLog, PR_LOG_ERROR, ("%s", warnMsg.get()));
#endif
}
(void)::sqlite3_extended_result_codes(mDBConn, 0);
// Drop off the extended result bits of the result code.
return srv & 0xFF;
}
////////////////////////////////////////////////////////////////////////////////
//// nsIInterfaceRequestor

21
storage/src/mozStorageConnection.h
View File

@ -154,6 +154,27 @@ public:
*/
nsCString getFilename();
/**
* Creates an sqlite3 prepared statement object from an SQL string.
*
* @param aSQL
* The SQL statement string to compile.
* @param _stmt
* New sqlite3_stmt object.
* @return the result from sqlite3_prepare_v2.
*/
int prepareStatement(const nsCString &aSQL, sqlite3_stmt **_stmt);
/**
* Performs a sqlite3_step on aStatement, while properly handling SQLITE_LOCKED
* when not on the main thread by waiting until we are notified.
*
* @param aStatement
* A pointer to a sqlite3_stmt object.
* @return the result from sqlite3_step.
*/
int stepStatement(sqlite3_stmt* aStatement);
private:
~Connection();

137
storage/src/mozStoragePrivateHelpers.cpp
View File

@ -186,7 +186,6 @@ convertJSValToVariant(
return nsnull;
}
namespace {
class CallbackEvent : public nsRunnable
{
@ -213,143 +212,7 @@ newCompletionEvent(mozIStorageCompletionCallback *aCallback)
return event.forget();
}
/**
* This code is heavily based on the sample at:
* http://www.sqlite.org/unlock_notify.html
*/
namespace {
class UnlockNotification
{
public:
UnlockNotification()
: mMutex("UnlockNotification mMutex")
, mCondVar(mMutex, "UnlockNotification condVar")
, mSignaled(false)
{
}
void Wait()
{
mozilla::MutexAutoLock lock(mMutex);
while (!mSignaled) {
(void)mCondVar.Wait();
}
}
void Signal()
{
mozilla::MutexAutoLock lock(mMutex);
mSignaled = true;
(void)mCondVar.Notify();
}
private:
mozilla::Mutex mMutex;
mozilla::CondVar mCondVar;
bool mSignaled;
};
void
UnlockNotifyCallback(void **aArgs,
int aArgsSize)
{
for (int i = 0; i < aArgsSize; i++) {
UnlockNotification *notification =
static_cast<UnlockNotification *>(aArgs[i]);
notification->Signal();
}
}
int
WaitForUnlockNotify(sqlite3* aDatabase)
{
UnlockNotification notification;
int srv = ::sqlite3_unlock_notify(aDatabase, UnlockNotifyCallback,
&notification);
NS_ASSERTION(srv == SQLITE_LOCKED || srv == SQLITE_OK, "Bad result!");
if (srv == SQLITE_OK)
notification.Wait();
return srv;
}
} // anonymous namespace
int
stepStmt(sqlite3_stmt* aStatement)
{
bool checkedMainThread = false;
sqlite3* db = ::sqlite3_db_handle(aStatement);
(void)::sqlite3_extended_result_codes(db, 1);
int srv;
while ((srv = ::sqlite3_step(aStatement)) == SQLITE_LOCKED_SHAREDCACHE) {
if (!checkedMainThread) {
checkedMainThread = true;
if (NS_IsMainThread()) {
NS_WARNING("We won't allow blocking on the main thread!");
break;
}
}
srv = WaitForUnlockNotify(sqlite3_db_handle(aStatement));
if (srv != SQLITE_OK)
break;
::sqlite3_reset(aStatement);
}
(void)::sqlite3_extended_result_codes(db, 0);
// Drop off the extended result bits of the result code.
return srv & 0xFF;
}
int
prepareStmt(sqlite3* aDatabase,
const nsCString &aSQL,
sqlite3_stmt **_stmt)
{
bool checkedMainThread = false;
(void)::sqlite3_extended_result_codes(aDatabase, 1);
int srv;
while((srv = ::sqlite3_prepare_v2(aDatabase, aSQL.get(), -1, _stmt, NULL)) ==
SQLITE_LOCKED_SHAREDCACHE) {
if (!checkedMainThread) {
checkedMainThread = true;
if (NS_IsMainThread()) {
NS_WARNING("We won't allow blocking on the main thread!");
break;
}
}
srv = WaitForUnlockNotify(aDatabase);
if (srv != SQLITE_OK)
break;
}
if (srv != SQLITE_OK) {
nsCString warnMsg;
warnMsg.AppendLiteral("The SQL statement '");
warnMsg.Append(aSQL);
warnMsg.AppendLiteral("' could not be compiled due to an error: ");
warnMsg.Append(::sqlite3_errmsg(aDatabase));
#ifdef DEBUG
NS_WARNING(warnMsg.get());
#endif
#ifdef PR_LOGGING
PR_LOG(gStorageLog, PR_LOG_ERROR, ("%s", warnMsg.get()));
#endif
}
(void)::sqlite3_extended_result_codes(aDatabase, 0);
// Drop off the extended result bits of the result code.
return srv & 0xFF;
}
} // namespace storage
} // namespace mozilla

23
storage/src/mozStoragePrivateHelpers.h
View File

@ -113,29 +113,6 @@ already_AddRefed<nsIRunnable> newCompletionEvent(
mozIStorageCompletionCallback *aCallback
);
/**
* Performs a sqlite3_step on aStatement, while properly handling SQLITE_LOCKED
* when not on the main thread by waiting until we are notified.
*
* @param aStatement
* A pointer to a sqlite3_stmt object.
* @return the result from sqlite3_step.
*/
int stepStmt(sqlite3_stmt *aStatement);
/**
* Obtains a prepared sqlite3_stmt object for aDatabase from aSQL.
*
* @param aDatabase
* The database the statement will execute on.
* @param aSQL
* The SQL statement to compile.
* @return the result from sqlite3_prepare_v2.
*/
int prepareStmt(sqlite3 *aDatabase, const nsCString &aSQL,
sqlite3_stmt **_stmt);
} // namespace storage
} // namespace mozilla

8
storage/src/mozStorageStatement.cpp
View File

@ -175,7 +175,8 @@ Statement::initialize(Connection *aDBConnection,
sqlite3 *db = aDBConnection->GetNativeConnection();
NS_ASSERTION(db, "We should never be called with a null sqlite3 database!");
int srv = prepareStmt(db, PromiseFlatCString(aSQLStatement), &mDBStatement);
int srv = aDBConnection->prepareStatement(PromiseFlatCString(aSQLStatement),
&mDBStatement);
if (srv != SQLITE_OK) {
#ifdef PR_LOGGING
PR_LOG(gStorageLog, PR_LOG_ERROR,
@ -319,8 +320,7 @@ Statement::getAsyncStatement(sqlite3_stmt **_stmt)
// If we do not yet have a cached async statement, clone our statement now.
if (!mAsyncStatement) {
nsDependentCString sql(::sqlite3_sql(mDBStatement));
int rc = prepareStmt(mDBConnection->GetNativeConnection(), sql,
&mAsyncStatement);
int rc = mDBConnection->prepareStatement(sql, &mAsyncStatement);
if (rc != SQLITE_OK) {
*_stmt = nsnull;
return rc;
@ -613,7 +613,7 @@ Statement::ExecuteStep(bool *_moreResults)
// We have bound, so now we can clear our array.
mParamsArray = nsnull;
}
int srv = stepStmt(mDBStatement);
int srv = mDBConnection->stepStatement(mDBStatement);
#ifdef PR_LOGGING
if (srv != SQLITE_ROW && srv != SQLITE_DONE) {

168
toolkit/components/telemetry/Telemetry.cpp
View File

@ -51,6 +51,8 @@
#include "nsHashKeys.h"
#include "nsBaseHashtable.h"
#include "nsXULAppAPI.h"
#include "nsThreadUtils.h"
#include "mozilla/Mutex.h"
namespace {
@ -69,14 +71,28 @@ public:
static bool CanRecord();
static already_AddRefed<nsITelemetry> CreateTelemetryInstance();
static void ShutdownTelemetry();
static void RecordSlowStatement(const nsACString &statement,
const nsACString &dbName,
PRUint32 delay);
struct StmtStats {
PRUint32 hitCount;
PRUint32 totalTime;
};
typedef nsBaseHashtableET<nsCStringHashKey, StmtStats> SlowSQLEntryType;
private:
bool AddSlowSQLInfo(JSContext *cx, JSObject *rootObj, bool mainThread);
// This is used for speedy JS string->Telemetry::ID conversions
typedef nsBaseHashtableET<nsCharPtrHashKey, Telemetry::ID> CharPtrEntryType;
typedef nsTHashtable<CharPtrEntryType> HistogramMapType;
HistogramMapType mHistogramMap;
bool mCanRecord;
static TelemetryImpl *sTelemetry;
nsTHashtable<SlowSQLEntryType> mSlowSQLOnMainThread;
nsTHashtable<SlowSQLEntryType> mSlowSQLOnOtherThread;
nsTHashtable<nsCStringHashKey> mTrackedDBs;
Mutex mHashMutex;
};
TelemetryImpl* TelemetryImpl::sTelemetry = NULL;
@ -267,12 +283,31 @@ WrapAndReturnHistogram(Histogram *h, JSContext *cx, jsval *ret)
}
TelemetryImpl::TelemetryImpl():
mCanRecord(XRE_GetProcessType() == GeckoProcessType_Default)
mCanRecord(XRE_GetProcessType() == GeckoProcessType_Default),
mHashMutex("Telemetry::mHashMutex")
{
// A whitelist to prevent Telemetry reporting on Addon & Thunderbird DBs
const char *trackedDBs[] = {
"addons.sqlite", "chromeappsstore.sqlite", "content-prefs.sqlite",
"cookies.sqlite", "downloads.sqlite", "extensions.sqlite",
"formhistory.sqlite", "index.sqlite", "permissions.sqlite", "places.sqlite",
"search.sqlite", "signons.sqlite", "urlclassifier3.sqlite",
"webappsstore.sqlite"
};
mTrackedDBs.Init();
for (int i = 0; i < sizeof(trackedDBs)/sizeof(const char*); i++)
mTrackedDBs.PutEntry(nsDependentCString(trackedDBs[i]));
mSlowSQLOnMainThread.Init();
mSlowSQLOnOtherThread.Init();
mHistogramMap.Init(Telemetry::HistogramCount);
}
TelemetryImpl::~TelemetryImpl() {
mTrackedDBs.Clear();
mSlowSQLOnMainThread.Clear();
mSlowSQLOnOtherThread.Clear();
mHistogramMap.Clear();
}
@ -287,6 +322,84 @@ TelemetryImpl::NewHistogram(const nsACString &name, PRUint32 min, PRUint32 max,
return WrapAndReturnHistogram(h, cx, ret);
}
struct EnumeratorArgs {
JSContext *cx;
JSObject *statsObj;
JSObject *statementsObj;
int32 statementIndex;
};
PLDHashOperator
StatementEnumerator(TelemetryImpl::SlowSQLEntryType *entry, void *arg)
{
EnumeratorArgs *args = static_cast<EnumeratorArgs *>(arg);
const nsACString &statement = entry->GetKey();
jsval hitCount = UINT_TO_JSVAL(entry->mData.hitCount);
jsval totalTime = UINT_TO_JSVAL(entry->mData.totalTime);
args->statementIndex++;
JSObject *hitsAndTimeObj = JS_NewArrayObject(args->cx, 2, nsnull);
if (!hitsAndTimeObj ||
!JS_SetElement(args->cx, hitsAndTimeObj, 0, &hitCount) ||
!JS_SetElement(args->cx, hitsAndTimeObj, 1, &totalTime))
return PL_DHASH_STOP;
jsid propertyId = INT_TO_JSID(args->statementIndex);
JSBool success = JS_DefinePropertyById(args->cx, args->statsObj,
INT_TO_JSID(args->statementIndex),
OBJECT_TO_JSVAL(hitsAndTimeObj),
NULL, NULL, JSPROP_ENUMERATE);
if (!success)
return PL_DHASH_STOP;
JSString *string = JS_NewStringCopyN(args->cx, statement.BeginReading(), statement.Length());
if (!string)
return PL_DHASH_STOP;
success = JS_DefinePropertyById(args->cx, args->statementsObj,
INT_TO_JSID(args->statementIndex),
STRING_TO_JSVAL(string), NULL, NULL,
JSPROP_ENUMERATE);
if (!success)
return PL_DHASH_STOP;
return PL_DHASH_NEXT;
}
bool
TelemetryImpl::AddSlowSQLInfo(JSContext *cx, JSObject *rootObj, bool mainThread)
{
JSObject *statementsObj = JS_NewObject(cx, NULL, NULL, NULL);
JSObject *statsObj = JS_NewObject(cx, NULL, NULL, NULL);
if (!statementsObj || !statsObj)
return false;
JSBool ok = JS_DefineProperty(cx, rootObj,
mainThread ? "slowSQLOnMain" : "slowSQLOnOther",
OBJECT_TO_JSVAL(statementsObj),
NULL, NULL, JSPROP_ENUMERATE);
if (!ok)
return false;
ok = JS_DefineProperty(cx, rootObj,
mainThread ? "slowSQLStatsMain" : "slowSQLStatsOther",
OBJECT_TO_JSVAL(statsObj),
NULL, NULL, JSPROP_ENUMERATE);
if (!ok)
return false;
EnumeratorArgs args = { cx, statsObj, statementsObj, 0 };
nsTHashtable<SlowSQLEntryType> *sqlMap;
sqlMap = (mainThread ? &mSlowSQLOnMainThread : &mSlowSQLOnOtherThread);
PRUint32 num = sqlMap->EnumerateEntries(StatementEnumerator,
static_cast<void*>(&args));
if (num != sqlMap->Count())
return false;
return true;
}
NS_IMETHODIMP
TelemetryImpl::GetHistogramSnapshots(JSContext *cx, jsval *ret)
{
@ -307,10 +420,18 @@ TelemetryImpl::GetHistogramSnapshots(JSContext *cx, jsval *ret)
return NS_ERROR_FAILURE;
}
}
MutexAutoLock hashMutex(mHashMutex);
// Add info about slow SQL queries on the main thread
if (!AddSlowSQLInfo(cx, root_obj, true))
return NS_ERROR_FAILURE;
// Add info about slow SQL queries on other threads
if (!AddSlowSQLInfo(cx, root_obj, false))
return NS_ERROR_FAILURE;
return NS_OK;
}
NS_IMETHODIMP
TelemetryImpl::GetHistogramById(const nsACString &name, JSContext *cx, jsval *ret)
{
@ -375,6 +496,41 @@ TelemetryImpl::ShutdownTelemetry()
NS_IF_RELEASE(sTelemetry);
}
void
TelemetryImpl::RecordSlowStatement(const nsACString &statement,
const nsACString &dbName,
PRUint32 delay)
{
if (!sTelemetry) {
// Make the service manager hold a long-lived reference to the service
nsCOMPtr<nsITelemetry> telemetryService =
do_GetService("@mozilla.org/base/telemetry;1");
if (!telemetryService || !sTelemetry)
return;
}
if (!sTelemetry->mCanRecord || !sTelemetry->mTrackedDBs.GetEntry(dbName))
return;
nsTHashtable<SlowSQLEntryType> *slowSQLMap = NULL;
if (NS_IsMainThread())
slowSQLMap = &(sTelemetry->mSlowSQLOnMainThread);
else
slowSQLMap = &(sTelemetry->mSlowSQLOnOtherThread);
MutexAutoLock hashMutex(sTelemetry->mHashMutex);
SlowSQLEntryType *entry = slowSQLMap->GetEntry(statement);
if (!entry) {
entry = slowSQLMap->PutEntry(statement);
if (NS_UNLIKELY(!entry))
return;
entry->mData.hitCount = 0;
entry->mData.totalTime = 0;
}
entry->mData.hitCount++;
entry->mData.totalTime += delay;
}
NS_IMPL_THREADSAFE_ISUPPORTS1(TelemetryImpl, nsITelemetry)
NS_GENERIC_FACTORY_SINGLETON_CONSTRUCTOR(nsITelemetry, TelemetryImpl::CreateTelemetryInstance)
@ -434,6 +590,14 @@ GetHistogramById(ID id)
return h;
}
void
RecordSlowSQLStatement(const nsACString &statement,
const nsACString &dbName,
PRUint32 delay)
{
TelemetryImpl::RecordSlowStatement(statement, dbName, delay);
}
} // namespace Telemetry
} // namespace mozilla

18
toolkit/components/telemetry/Telemetry.h
View File

@ -98,6 +98,24 @@ private:
const TimeStamp start;
MOZILLA_DECL_USE_GUARD_OBJECT_NOTIFIER
};
/**
* Records slow SQL statements for Telemetry reporting.
* For privacy reasons, only prepared statements are reported.
*
* @param statement - offending SQL statement to record
* @param dbName - DB filename; reporting is only done for whitelisted DBs
* @param delay - execution time in milliseconds
*/
void RecordSlowSQLStatement(const nsACString &statement,
const nsACString &dbName,
PRUint32 delay);
/**
* Threshold for a statement to be considered slow, in milliseconds
*/
const PRUint32 kSlowStatementThreshold = 100;
} // namespace Telemetry
} // namespace mozilla
#endif // Telemetry_h__