mirrors/sqlite
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Add still more logging to determine why schema loads are so slow in some circumstances.

Browse Source 
FossilOrigin-Name: d02ec06e5bde7c8dc0f21ca2bfc44597aca015854d5656f851f4518476d04381
This commit is contained in:
dan 2024-10-22 16:26:14 +00:00
parent fdf8f9b72f
commit b9cdea7c98
6 changed files with 72 additions and 38 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

18
manifest
View File

@ -1,5 +1,5 @@
C Add\sextra\slogging\sto\sSQL\sstatements\sused\sto\sload\sthe\sdatabase\sschema\son\sthis\sbranch.\sThis\srequires\sSQLITE_ENABLE_STMT_SCANSTATUS.
D 2024-10-21T11:49:04.907
C Add\sstill\smore\slogging\sto\sdetermine\swhy\sschema\sloads\sare\sso\sslow\sin\ssome\scircumstances.
D 2024-10-22T16:26:14.924
F .fossil-settings/empty-dirs dbb81e8fc0401ac46a1491ab34a7f2c7c0452f2f06b54ebb845d024ca8283ef1
F .fossil-settings/ignore-glob 35175cdfcf539b2318cb04a9901442804be81cd677d8b889fcc9149c21f239ea
F LICENSE.md df5091916dbb40e6e9686186587125e1b2ff51f022cc334e886c19a0e9982724
@ -735,7 +735,7 @@ F src/hwtime.h f9c2dfb84dce7acf95ce6d289e46f5f9d3d1afd328e53da8f8e9008e3b3caae6
F src/in-operator.md 10cd8f4bcd225a32518407c2fb2484089112fd71
F src/insert.c f8d1a0f8ee258411009c6b7f2d93170e351bd19f5ad89d57e1180644297cbe70
F src/json.c 68a98c020c22127f2d65f08855f7fc7460ff352a6ce0b543d8931dde83319c22
F src/legacy.c 40f29a5d84e5de400dd8a645626b0c620612523d07540faff8ae26cc8df3a4f6
F src/legacy.c 5fff8efbb4f20396136beb913fff323686cff8f6f5d7d728189f68e98f7310bb
F src/loadext.c 7432c944ff197046d67a1207790a1b13eec4548c85a9457eb0896bb3641dfb36
F src/main.c def50c462ce61f722196f7615d79374e2e5b9e856cce2991192faea3b9dbd33c
F src/malloc.c 410e570b30c26cc36e3372577df50f7a96ee3eed5b2b161c6b6b48773c650c5e
@ -769,7 +769,7 @@ F src/pcache.h 1497ce1b823cf00094bb0cf3bac37b345937e6f910890c626b16512316d3abf5
F src/pcache1.c 430b86e10b8d6ae65832a19a0016f8f65f74207687bc9501c0b15a5908bcb6ad
F src/pragma.c 08472536cf1ecc38947d56f6cb2c8d8b3f6a26722451a38614c41a5b0cbcfc52
F src/pragma.h 6ebbdee90ed56a892d2c728e27fd9c1ce48c8a28841888d0c6c147946b38cb25
F src/prepare.c c2b3221d0215d75f355e7aa46020275ed8453293dd63be398b3846e2118e7e92
F src/prepare.c 140ce8271ba7da946668ad2e0c68fe14419319cb6c68cfcd660186557c271969
F src/printf.c 6a87534ebfb9e5346011191b1f3a7ebc457f5938c7e4feeea478ecf53f6a41b2
F src/random.c 9bd018738ec450bf35d28050b4b33fa9a6eebf3aaefb1a1cff42dc14a7725673
F src/resolve.c 2c127880c0634962837f16f2f48a295e514357af959330cc038de73015d5b5e8
@ -779,7 +779,7 @@ F src/shell.c.in 40de636c1d90fb8a9ca7f49dc8f50d930f1b60736e73aca5eb37c4c7d0e47f9
F src/sqlite.h.in b7ff496637807ae88b2557039fc940518db328bf5d5621e2f7c048dfba32a52b
F src/sqlite3.rc 5121c9e10c3964d5755191c80dd1180c122fc3a8
F src/sqlite3ext.h 3f046c04ea3595d6bfda99b781926b17e672fd6d27da2ba6d8d8fc39981dcb54
F src/sqliteInt.h 8e683c99197787b23b778cc715e3398e41dc4fda7339e6fa87ac1bbfba8c20f1
F src/sqliteInt.h 0c3db4598b7b9c6aced18496bd6b1f6f56f2d739ff30297e5051093f1b4cfcc2
F src/sqliteLimit.h 6878ab64bdeb8c24a1d762d45635e34b96da21132179023338c93f820eee6728
F src/status.c cb11f8589a6912af2da3bb1ec509a94dd8ef27df4d4c1a97e0bcf2309ece972b
F src/table.c 0f141b58a16de7e2fbe81c308379e7279f4c6b50eb08efeec5892794a0ba30d1
@ -849,7 +849,7 @@ F src/vdbe.c fea60cfe46d8839a08e4680d90a96898d542d3f6d7954e2e99cd92596f1a01f8
F src/vdbe.h ed70dc763f22fe856884cc065473061bfe9954bd221daaf3ac517f01c33d0b0f
F src/vdbeInt.h 494b7b3430fb53adef43e5fd9ede20029750f188f2dbb064e7b86cdf9fb755d7
F src/vdbeapi.c 80235ac380e9467fec1cb0883354d841f2a771976e766995f7e0c77f845406df
F src/vdbeaux.c 4dfb4fcad7cabf34c469fdaa41dd5f048e400fa59a72f4cdcf80649636357c5b
F src/vdbeaux.c 16323344b313db01298573fd52816f20501311a36aa825f5f0bd7afa2fd811a2
F src/vdbeblob.c 255be187436da38b01f276c02e6a08103489bbe2a7c6c21537b7aecbe0e1f797
F src/vdbemem.c 831a244831eaa45335f9ae276b50a7a82ee10d8c46c2c72492d4eb8c98d94d89
F src/vdbesort.c d0a3c7056c081703c8b6d91ad60f17da5e062a5c64bf568ed0fa1b5f4cae311f
@ -2249,8 +2249,8 @@ F vsixtest/vsixtest.tcl 6195aba1f12a5e10efc2b8c0009532167be5e301abe5b31385638080
F vsixtest/vsixtest.vcxproj.data 2ed517e100c66dc455b492e1a33350c1b20fbcdc
F vsixtest/vsixtest.vcxproj.filters 37e51ffedcdb064aad6ff33b6148725226cd608e
F vsixtest/vsixtest_TemporaryKey.pfx e5b1b036facdb453873e7084e1cae9102ccc67a0
P 6deb4794f8e24dbb946069de1e5c34fbcd4734162002f3bc7deb1a3f69adec05
R d16d707406d8d29328720dd073b80e3d
P 08e1dea9c070c9a2d668d39ceb153bc8b6d172e7273f6564a374c43055e84461
R 94bb34a3eda8f372bde8de70614acb52
U dan
Z 5d1fe4a2a6a8ab81a8ff24dd0d57a905
Z a1cf697854d2ed08ac2ba1f2daa0689c
# Remove this line to create a well-formed Fossil manifest.

2
manifest.uuid
View File

@ -1 +1 @@
08e1dea9c070c9a2d668d39ceb153bc8b6d172e7273f6564a374c43055e84461
d02ec06e5bde7c8dc0f21ca2bfc44597aca015854d5656f851f4518476d04381

16
src/legacy.c
View File

@ -48,12 +48,8 @@ int sqlite3_exec(
while( rc==SQLITE_OK && zSql[0] ){
int nCol = 0;
char **azVals = 0;
i64 tmStart = sqlite3STimeNow();
u64 svFlags = db->flags;
if( db->init.busy ){
db->flags |= SQLITE_StmtScanStatus;
}
sqlite3PrepareTimeSet(db->aSchemaTime, SCHEMA_TIME_BEFORE_PREPARE);
pStmt = 0;
rc = sqlite3_prepare_v2(db, zSql, -1, &pStmt, &zLeftover);
assert( rc==SQLITE_OK || pStmt==0 );
@ -67,6 +63,7 @@ int sqlite3_exec(
}
callbackIsInit = 0;
sqlite3PrepareTimeSet(db->aSchemaTime, SCHEMA_TIME_BEFORE_STEP);
while( 1 ){
int i;
rc = sqlite3_step(pStmt);
@ -112,10 +109,8 @@ int sqlite3_exec(
}
}
sqlite3PrepareTimeSet(db->aSchemaTime, SCHEMA_TIME_BEFORE_FINALIZE);
if( rc!=SQLITE_ROW ){
if( db->init.busy && (sqlite3STimeNow()-tmStart)>PREPARE_TIME_TIMEOUT ){
sqlite3SchemaTimeLog((Vdbe*)pStmt);
}
rc = sqlite3VdbeFinalize((Vdbe *)pStmt);
pStmt = 0;
zSql = zLeftover;
@ -124,11 +119,6 @@ int sqlite3_exec(
}
}
if( db->init.busy ){
/* Clear the SQLITE_StmtScanStatus flag if it was clear at the top
** of this loop. */
db->flags &= (~SQLITE_StmtScanStatus | svFlags);
}
sqlite3DbFree(db, azCols);
azCols = 0;
}

21
src/prepare.c
View File

@ -209,6 +209,11 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
int openedTransaction = 0;
int mask = ((db->mDbFlags & DBFLAG_EncodingFixed) | ~DBFLAG_EncodingFixed);
u64 aSchemaTime[SCHEMA_TIME_N];
memset(aSchemaTime, 0, sizeof(aSchemaTime));
db->aSchemaTime = aSchemaTime;
sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_START);
assert( (db->mDbFlags & DBFLAG_SchemaKnownOk)==0 );
assert( iDb>=0 && iDb<db->nDb );
assert( db->aDb[iDb].pSchema );
@ -243,6 +248,8 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
goto error_out;
}
sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_AFTER_CREATE_1);
/* Create a cursor to hold the database open
*/
pDb = &db->aDb[iDb];
@ -266,6 +273,8 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
openedTransaction = 1;
}
sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_AFTER_OPEN_TRANS);
/* Get the database meta information.
**
** Meta values are as follows:
@ -291,6 +300,8 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
}
pDb->pSchema->schema_cookie = meta[BTREE_SCHEMA_VERSION-1];
sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_AFTER_GET_META);
/* If opening a non-empty database, check the text encoding. For the
** main database, set sqlite3.enc to the encoding of the main database.
** For an attached db, it is an error if the encoding is not the same
@ -326,6 +337,8 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
}
pDb->pSchema->enc = ENC(db);
sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_AFTER_FIX_ENCODING);
if( pDb->pSchema->cache_size==0 ){
#ifndef SQLITE_OMIT_DEPRECATED
size = sqlite3AbsInt32(meta[BTREE_DEFAULT_CACHE_SIZE-1]);
@ -337,6 +350,8 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
sqlite3BtreeSetCacheSize(pDb->pBt, pDb->pSchema->cache_size);
}
sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_AFTER_SETCACHESIZE);
/*
** file_format==1 Version 3.0.0.
** file_format==2 Version 3.1.3. // ALTER TABLE ADD COLUMN
@ -377,6 +392,7 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
xAuth = db->xAuth;
db->xAuth = 0;
#endif
sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_BEGIN_EXEC);
rc = sqlite3_exec(db, zSql, sqlite3InitCallback, &initData, 0);
#ifndef SQLITE_OMIT_AUTHORIZATION
db->xAuth = xAuth;
@ -384,11 +400,13 @@ int sqlite3InitOne(sqlite3 *db, int iDb, char **pzErrMsg, u32 mFlags){
#endif
if( rc==SQLITE_OK ) rc = initData.rc;
sqlite3DbFree(db, zSql);
sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_BEGIN_ANALYZE_LOAD);
#ifndef SQLITE_OMIT_ANALYZE
if( rc==SQLITE_OK ){
sqlite3AnalysisLoad(db, iDb);
}
#endif
sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_END_ANALYZE_LOAD);
}
assert( pDb == &(db->aDb[iDb]) );
if( db->mallocFailed ){
@ -422,6 +440,9 @@ initone_error_out:
sqlite3BtreeLeave(pDb->pBt);
error_out:
db->aSchemaTime = 0;
sqlite3PrepareTimeSet(aSchemaTime, SCHEMA_TIME_FINISH);
sqlite3SchemaTimeLog(aSchemaTime);
if( rc ){
if( rc==SQLITE_NOMEM || rc==SQLITE_IOERR_NOMEM ){
sqlite3OomFault(db);

24
src/sqliteInt.h
View File

@ -1828,6 +1828,7 @@ struct sqlite3 {
#endif
u64 *aPrepareTime;
u64 *aSchemaTime;
};
#define PREPARE_TIME_START 0
@ -1850,9 +1851,30 @@ struct sqlite3 {
#define PREPARE_TIME_N 14
#define SCHEMA_TIME_START 0
#define SCHEMA_TIME_AFTER_CREATE_1 1
#define SCHEMA_TIME_AFTER_OPEN_TRANS 2
#define SCHEMA_TIME_AFTER_GET_META 3
#define SCHEMA_TIME_AFTER_FIX_ENCODING 4
#define SCHEMA_TIME_AFTER_SETCACHESIZE 5
#define SCHEMA_TIME_BEGIN_EXEC 6
#define SCHEMA_TIME_BEFORE_STEP 7
#define SCHEMA_TIME_BEFORE_PREPARE 8
#define SCHEMA_TIME_BEFORE_FINALIZE 9
#define SCHEMA_TIME_BEGIN_ANALYZE_LOAD 10
#define SCHEMA_TIME_END_ANALYZE_LOAD 11
#define SCHEMA_TIME_FINISH 12
#define SCHEMA_TIME_N 13
#define SCHEMA_TIME_TIMEOUT (1 * 1000 * 1000)
#define sqlite3PrepareTimeSet(x,y) sqlite3CommitTimeSet(x,y)
void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepareTime);
void sqlite3SchemaTimeLog(Vdbe *pVdbe);
void sqlite3SchemaTimeLog(u64 *aSchemaTime);
#define PREPARE_TIME_TIMEOUT (2 * 1000 * 1000) /* 2 second timeout */

29
src/vdbeaux.c
View File

@ -5471,7 +5471,7 @@ void sqlite3CommitTimeLog(u64 *aCommit){
(aCommit[ii]==0 ? 0 : (int)(aCommit[ii] - i1))
);
}
sqlite3_log(SQLITE_WARNING, "slow commit (v=3): (%s)", zStr);
sqlite3_log(SQLITE_WARNING, "slow commit (v=4): (%s)", zStr);
sqlite3_free(zStr);
}
}
@ -5499,24 +5499,25 @@ void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepare){
}
if( nByte<0 ){ nByte = sqlite3Strlen30(zSql); }
sqlite3_log(SQLITE_WARNING,
"slow prepare (v=3): (%s) [%.*s]", zStr, nByte, zSql
"slow prepare (v=4): (%s) [%.*s]", zStr, nByte, zSql
);
sqlite3_free(zStr);
}
}
void sqlite3SchemaTimeLog(Vdbe *pVdbe){
int ii;
char *zStr = 0;
for(ii=0; ii<pVdbe->nOp; ii++){
VdbeOp *pOp = &pVdbe->aOp[ii];
zStr = sqlite3_mprintf("%z%s(%s %lld %lld)", zStr, (zStr?" ":""),
(char*)sqlite3OpcodeName(pOp->opcode), pOp->nExec, pOp->nCycle
);
void sqlite3SchemaTimeLog(u64 *aSchema){
u64 i1 = aSchema[SCHEMA_TIME_START];
assert( SCHEMA_TIME_START==0 && SCHEMA_TIME_FINISH==SCHEMA_TIME_N-1 );
if( aSchema[SCHEMA_TIME_FINISH]>(i1+SCHEMA_TIME_TIMEOUT) ){
char *zStr = 0;
int ii;
for(ii=1; ii<SCHEMA_TIME_N; ii++){
zStr = sqlite3_mprintf("%z%s%d", zStr, (zStr?", ":""),
(aSchema[ii]==0 ? 0 : (int)(aSchema[ii] - i1))
);
}
sqlite3_log(SQLITE_WARNING, "slow schema (v=4): (%s)", zStr);
sqlite3_free(zStr);
}
sqlite3_log(SQLITE_WARNING,
"slow schema query (v=3): (%s) [%s]", zStr, pVdbe->zSql
);
sqlite3_free(zStr);
}