From 2b9c55e379e9ee2e4b23a99761a90abf05b80870 Mon Sep 17 00:00:00 2001 From: dan Date: Sat, 5 Oct 2019 19:17:40 +0000 Subject: [PATCH] Add a timestamp to each osinst log entry, to facilitate merging multiple log files. FossilOrigin-Name: c9519c0cec3f0eae3ec4abe39fabbcc59a38d3c2eba11e19cfec4b769ed7376e --- manifest | 16 +++-- manifest.uuid | 2 +- src/test_osinst.c | 148 +++++++++++++++++++++++++--------------------- tool/osinst2sql.c | 58 ++++++++++++++++++ 4 files changed, 147 insertions(+), 77 deletions(-) create mode 100644 tool/osinst2sql.c diff --git a/manifest b/manifest index 5e5069e066..02985f89b0 100644 --- a/manifest +++ b/manifest @@ -1,5 +1,5 @@ -C Have\ssqlite3.c\sautomatically\sturn\son\sosinst\slogging\sfor\sall\sconnections. -D 2019-10-05T17:29:52.699 +C Add\sa\stimestamp\sto\seach\sosinst\slog\sentry,\sto\sfacilitate\smerging\smultiple\slog\sfiles. +D 2019-10-05T19:17:40.314 F .fossil-settings/empty-dirs dbb81e8fc0401ac46a1491ab34a7f2c7c0452f2f06b54ebb845d024ca8283ef1 F .fossil-settings/ignore-glob 35175cdfcf539b2318cb04a9901442804be81cd677d8b889fcc9149c21f239ea F LICENSE.md df5091916dbb40e6e9686186587125e1b2ff51f022cc334e886c19a0e9982724 @@ -568,7 +568,7 @@ F src/test_multiplex.c e054459f7633f3ff8ce1245da724f9a8be189e4e F src/test_multiplex.h 5436d03f2d0501d04f3ed50a75819e190495b635 F src/test_mutex.c 7f4337ba23ee6b1d2ec81c189653608cb069926a F src/test_onefile.c f31e52e891c5fef6709b9fcef54ce660648a34172423a9cbdf4cbce3ba0049f4 -F src/test_osinst.c 192fbbafc7c92513efa238f1f3d0f5e64c49807f7328802fd37f508e022831c4 +F src/test_osinst.c 6c94ed7cf950d8af22c0380f91616647bb2a014536042a2e85d5e34fa1a8f52d F src/test_pcache.c a5cd24730cb43c5b18629043314548c9169abb00 F src/test_quota.c 6cb9297115b551f433a9ad1741817a9831abed99 F src/test_quota.h 2a8ad1952d1d2ca9af0ce0465e56e6c023b5e15d @@ -1791,6 +1791,7 @@ F tool/mkvsix.tcl b9e0777a213c23156b6542842c238479e496ebf5 F tool/offsets.c fe4262fdfa378e8f5499a42136d17bf3b98f6091 F tool/omittest.tcl 27f9413c3343bac200a28d81e8234adb0f5e141c4771893cb19b40235a91f1e0 F tool/opcodesum.tcl 740ed206ba8c5040018988129abbf3089a0ccf4a +F tool/osinst2sql.c 112ed2fb0175d1a341b87557c2f4dbc40f1d97d267533840124bec7df2dc72e2 F tool/pagesig.c ff0ca355fd3c2398e933da5e22439bbff89b803b F tool/replace.tcl 60f91e8dd06ab81f74d213ecbd9c9945f32ac048 F tool/restore_jrnl.tcl 6957a34f8f1f0f8285e07536225ec3b292a9024a @@ -1846,10 +1847,7 @@ F vsixtest/vsixtest.tcl 6a9a6ab600c25a91a7acc6293828957a386a8a93 F vsixtest/vsixtest.vcxproj.data 2ed517e100c66dc455b492e1a33350c1b20fbcdc F vsixtest/vsixtest.vcxproj.filters 37e51ffedcdb064aad6ff33b6148725226cd608e F vsixtest/vsixtest_TemporaryKey.pfx e5b1b036facdb453873e7084e1cae9102ccc67a0 -P c20a35336432025445f9f7e289d0cc3e4003fb17f45a4ce74c6269c407c6e09f -R da26f1d5f4fd9d7b5a1d749e81c81be8 -T *branch * osinst -T *sym-osinst * -T -sym-trunk * +P eea231f81b3ca6196949a84e8e0eb73a1ed03cb1ddd21f3b24787999caef8b1a +R 9449485fb0843fcd1870f8be2c2fea3e U dan -Z 090999d6315a1173b23966f6f90f5a7e +Z ff2cfb2995d2d610b52cd1a91d9e0a5c diff --git a/manifest.uuid b/manifest.uuid index a75d77129c..d428ffdde0 100644 --- a/manifest.uuid +++ b/manifest.uuid @@ -1 +1 @@ -eea231f81b3ca6196949a84e8e0eb73a1ed03cb1ddd21f3b24787999caef8b1a \ No newline at end of file +c9519c0cec3f0eae3ec4abe39fabbcc59a38d3c2eba11e19cfec4b769ed7376e \ No newline at end of file diff --git a/src/test_osinst.c b/src/test_osinst.c index 9b722203ba..5a0692f01a 100644 --- a/src/test_osinst.c +++ b/src/test_osinst.c @@ -62,6 +62,7 @@ ** CREATE TABLE v( ** event TEXT, // "xOpen", "xRead" etc. ** file TEXT, // Name of file this call applies to +** time INTEGER, // Timestamp ** clicks INTEGER, // Time spent in call ** rc INTEGER, // Return value ** size INTEGER, // Bytes read or written @@ -247,14 +248,15 @@ static sqlite3_uint64 vfslog_time(){ } #endif -static void vfslog_call(sqlite3_vfs *, int, int, sqlite3_int64, int, int, int); +static void vfslog_call( +sqlite3_vfs *, int, int, sqlite3_uint64, sqlite3_int64, int, int, int); static void vfslog_string(sqlite3_vfs *, const char *); /* ** Close an vfslog-file. */ static int vfslogClose(sqlite3_file *pFile){ - sqlite3_uint64 t; + sqlite3_uint64 t, t2; int rc = SQLITE_OK; VfslogFile *p = (VfslogFile *)pFile; @@ -262,8 +264,8 @@ static int vfslogClose(sqlite3_file *pFile){ if( p->pReal->pMethods ){ rc = p->pReal->pMethods->xClose(p->pReal); } - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_CLOSE, p->iFileId, t, rc, 0, 0); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_CLOSE, p->iFileId, t, t2, rc, 0, 0); return rc; } @@ -277,12 +279,12 @@ static int vfslogRead( sqlite_int64 iOfst ){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); rc = p->pReal->pMethods->xRead(p->pReal, zBuf, iAmt, iOfst); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_READ, p->iFileId, t, rc, iAmt, (int)iOfst); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_READ, p->iFileId, t, t2, rc, iAmt, (int)iOfst); return rc; } @@ -296,12 +298,12 @@ static int vfslogWrite( sqlite_int64 iOfst ){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); rc = p->pReal->pMethods->xWrite(p->pReal, z, iAmt, iOfst); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_WRITE, p->iFileId, t, rc, iAmt, (int)iOfst); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_WRITE, p->iFileId, t, t2, rc, iAmt, (int)iOfst); return rc; } @@ -310,12 +312,12 @@ static int vfslogWrite( */ static int vfslogTruncate(sqlite3_file *pFile, sqlite_int64 size){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); rc = p->pReal->pMethods->xTruncate(p->pReal, size); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_TRUNCATE, p->iFileId, t, rc, 0, (int)size); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_TRUNCATE, p->iFileId, t, t2, rc, 0, (int)size); return rc; } @@ -324,12 +326,12 @@ static int vfslogTruncate(sqlite3_file *pFile, sqlite_int64 size){ */ static int vfslogSync(sqlite3_file *pFile, int flags){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); rc = p->pReal->pMethods->xSync(p->pReal, flags); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_SYNC, p->iFileId, t, rc, flags, 0); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_SYNC, p->iFileId, t, t2, rc, flags, 0); return rc; } @@ -338,12 +340,12 @@ static int vfslogSync(sqlite3_file *pFile, int flags){ */ static int vfslogFileSize(sqlite3_file *pFile, sqlite_int64 *pSize){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); rc = p->pReal->pMethods->xFileSize(p->pReal, pSize); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_FILESIZE, p->iFileId, t, rc, 0, (int)*pSize); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_FILESIZE, p->iFileId, t, t2, rc, 0, (int)*pSize); return rc; } @@ -352,12 +354,12 @@ static int vfslogFileSize(sqlite3_file *pFile, sqlite_int64 *pSize){ */ static int vfslogLock(sqlite3_file *pFile, int eLock){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); rc = p->pReal->pMethods->xLock(p->pReal, eLock); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_LOCK, p->iFileId, t, rc, eLock, 0); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_LOCK, p->iFileId, t, t2, rc, eLock, 0); return rc; } @@ -366,12 +368,12 @@ static int vfslogLock(sqlite3_file *pFile, int eLock){ */ static int vfslogUnlock(sqlite3_file *pFile, int eLock){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); rc = p->pReal->pMethods->xUnlock(p->pReal, eLock); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_UNLOCK, p->iFileId, t, rc, eLock, 0); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_UNLOCK, p->iFileId, t, t2, rc, eLock, 0); return rc; } @@ -380,12 +382,12 @@ static int vfslogUnlock(sqlite3_file *pFile, int eLock){ */ static int vfslogCheckReservedLock(sqlite3_file *pFile, int *pResOut){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); rc = p->pReal->pMethods->xCheckReservedLock(p->pReal, pResOut); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_CHECKRESERVEDLOCK, p->iFileId, t, rc, *pResOut, 0); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_CHECKRESERVEDLOCK, p->iFileId, t,t2,rc,*pResOut,0); return rc; } @@ -406,12 +408,12 @@ static int vfslogFileControl(sqlite3_file *pFile, int op, void *pArg){ */ static int vfslogSectorSize(sqlite3_file *pFile){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); rc = p->pReal->pMethods->xSectorSize(p->pReal); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_SECTORSIZE, p->iFileId, t, rc, 0, 0); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_SECTORSIZE, p->iFileId, t, t2, rc, 0, 0); return rc; } @@ -420,23 +422,23 @@ static int vfslogSectorSize(sqlite3_file *pFile){ */ static int vfslogDeviceCharacteristics(sqlite3_file *pFile){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); rc = p->pReal->pMethods->xDeviceCharacteristics(p->pReal); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_DEVCHAR, p->iFileId, t, rc, 0, 0); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_DEVCHAR, p->iFileId, t, t2, rc, 0, 0); return rc; } static int vfslogShmLock(sqlite3_file *pFile, int ofst, int n, int flags){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); rc = p->pReal->pMethods->xShmLock(p->pReal, ofst, n, flags); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_SHMLOCK, p->iFileId, t, rc, 0, 0); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_SHMLOCK, p->iFileId, t, t2, rc, 0, 0); return rc; } static int vfslogShmMap( @@ -447,30 +449,30 @@ static int vfslogShmMap( volatile void **pp ){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); rc = p->pReal->pMethods->xShmMap(p->pReal, iRegion, szRegion, isWrite, pp); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_SHMMAP, p->iFileId, t, rc, 0, 0); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_SHMMAP, p->iFileId, t, t2, rc, 0, 0); return rc; } static void vfslogShmBarrier(sqlite3_file *pFile){ - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); p->pReal->pMethods->xShmBarrier(p->pReal); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_SHMBARRIER, p->iFileId, t, SQLITE_OK, 0, 0); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_SHMBARRIER, p->iFileId, t, t2, SQLITE_OK, 0, 0); } static int vfslogShmUnmap(sqlite3_file *pFile, int deleteFlag){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; t = vfslog_time(); rc = p->pReal->pMethods->xShmUnmap(p->pReal, deleteFlag); - t = vfslog_time() - t; - vfslog_call(p->pVfslog, OS_SHMUNMAP, p->iFileId, t, rc, 0, 0); + t2 = vfslog_time() - t; + vfslog_call(p->pVfslog, OS_SHMUNMAP, p->iFileId, t, t2, rc, 0, 0); return rc; } @@ -486,7 +488,7 @@ static int vfslogOpen( int *pOutFlags ){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; VfslogFile *p = (VfslogFile *)pFile; VfslogVfs *pLog = (VfslogVfs *)pVfs; @@ -497,9 +499,9 @@ static int vfslogOpen( t = vfslog_time(); rc = REALVFS(pVfs)->xOpen(REALVFS(pVfs), zName, p->pReal, flags, pOutFlags); - t = vfslog_time() - t; + t2 = vfslog_time() - t; - vfslog_call(pVfs, OS_OPEN, p->iFileId, t, rc, 0, 0); + vfslog_call(pVfs, OS_OPEN, p->iFileId, t, t2, rc, 0, 0); vfslog_string(pVfs, zName); return rc; } @@ -511,11 +513,11 @@ static int vfslogOpen( */ static int vfslogDelete(sqlite3_vfs *pVfs, const char *zPath, int dirSync){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; t = vfslog_time(); rc = REALVFS(pVfs)->xDelete(REALVFS(pVfs), zPath, dirSync); - t = vfslog_time() - t; - vfslog_call(pVfs, OS_DELETE, 0, t, rc, dirSync, 0); + t2 = vfslog_time() - t; + vfslog_call(pVfs, OS_DELETE, 0, t, t2, rc, dirSync, 0); vfslog_string(pVfs, zPath); return rc; } @@ -531,11 +533,11 @@ static int vfslogAccess( int *pResOut ){ int rc; - sqlite3_uint64 t; + sqlite3_uint64 t, t2; t = vfslog_time(); rc = REALVFS(pVfs)->xAccess(REALVFS(pVfs), zPath, flags, pResOut); - t = vfslog_time() - t; - vfslog_call(pVfs, OS_ACCESS, 0, t, rc, flags, *pResOut); + t2 = vfslog_time() - t; + vfslog_call(pVfs, OS_ACCESS, 0, t, t2, rc, flags, *pResOut); vfslog_string(pVfs, zPath); return rc; } @@ -653,6 +655,7 @@ static void vfslog_call( sqlite3_vfs *pVfs, int eEvent, int iFileid, + sqlite3_uint64 tStamp, sqlite3_int64 nClick, int return_code, int size, @@ -660,17 +663,19 @@ static void vfslog_call( ){ VfslogVfs *p = (VfslogVfs *)pVfs; unsigned char *zRec; - if( (24+p->nBuf)>sizeof(p->aBuf) ){ + if( (32+p->nBuf)>sizeof(p->aBuf) ){ vfslog_flush(p); } zRec = (unsigned char *)&p->aBuf[p->nBuf]; vfslogPut32bits(&zRec[0], eEvent); vfslogPut32bits(&zRec[4], iFileid); - vfslogPut32bits(&zRec[8], (unsigned int)(nClick&0xffffffff)); - vfslogPut32bits(&zRec[12], return_code); - vfslogPut32bits(&zRec[16], size); - vfslogPut32bits(&zRec[20], offset); - p->nBuf += 24; + vfslogPut32bits(&zRec[8], (unsigned int)((tStamp>>32)&0xffffffff)); + vfslogPut32bits(&zRec[12], (unsigned int)(tStamp&0xffffffff)); + vfslogPut32bits(&zRec[16], (unsigned int)(nClick&0xffffffff)); + vfslogPut32bits(&zRec[20], return_code); + vfslogPut32bits(&zRec[24], size); + vfslogPut32bits(&zRec[28], offset); + p->nBuf += 32; } static void vfslog_string(sqlite3_vfs *pVfs, const char *zStr){ @@ -759,11 +764,12 @@ int sqlite3_vfslog_new( int sqlite3_vfslog_annotate(const char *zVfs, const char *zMsg){ sqlite3_vfs *pVfs; + sqlite3_uint64 t = vfslog_time(); pVfs = sqlite3_vfs_find(zVfs); if( !pVfs || pVfs->xOpen!=vfslogOpen ){ return SQLITE_ERROR; } - vfslog_call(pVfs, OS_ANNOTATE, 0, 0, 0, 0, 0); + vfslog_call(pVfs, OS_ANNOTATE, 0, t, 0, 0, 0, 0); vfslog_string(pVfs, zMsg); return SQLITE_OK; } @@ -901,7 +907,7 @@ static int vlogConnect( if( rc==SQLITE_OK ){ p->pFd->pMethods->xFileSize(p->pFd, &p->nByte); sqlite3_declare_vtab(db, - "CREATE TABLE xxx(event, file, click, rc, size, offset)" + "CREATE TABLE xxx(event, file, time, click, rc, size, offset)" ); *ppVtab = &p->base; }else{ @@ -973,7 +979,7 @@ static int vlogNext(sqlite3_vtab_cursor *pCursor){ sqlite3_free(pCsr->zTransient); pCsr->zTransient = 0; - nRead = 24; + nRead = 32; if( pCsr->iOffset+nRead<=p->nByte ){ int eEvent; rc = p->pFd->pMethods->xRead(p->pFd, pCsr->aBuf, nRead, pCsr->iOffset); @@ -1037,18 +1043,18 @@ static int vlogColumn( sqlite3_context *ctx, int i ){ - unsigned int val; VfslogCsr *pCsr = (VfslogCsr *)pCursor; assert( i<7 ); - val = get32bits(&pCsr->aBuf[4*i]); switch( i ){ case 0: { + unsigned int val = get32bits(&pCsr->aBuf[0]); sqlite3_result_text(ctx, vfslog_eventname(val), -1, SQLITE_STATIC); break; } case 1: { + unsigned int val = get32bits(&pCsr->aBuf[4]); char *zStr = pCsr->zTransient; if( val!=0 && val<(unsigned)pCsr->nFile ){ zStr = pCsr->azFile[val]; @@ -1056,9 +1062,17 @@ static int vlogColumn( sqlite3_result_text(ctx, zStr, -1, SQLITE_TRANSIENT); break; } - default: + case 2: { + unsigned int v1 = get32bits(&pCsr->aBuf[8]); + unsigned int v2 = get32bits(&pCsr->aBuf[12]); + sqlite3_result_int64(ctx,(((sqlite3_int64)v1) << 32) + (sqlite3_int64)v2); + break; + } + default: { + unsigned int val = get32bits(&pCsr->aBuf[4*(i+1)]); sqlite3_result_int(ctx, val); break; + } } return SQLITE_OK; diff --git a/tool/osinst2sql.c b/tool/osinst2sql.c new file mode 100644 index 0000000000..0d03da3524 --- /dev/null +++ b/tool/osinst2sql.c @@ -0,0 +1,58 @@ +/* +****************************************************************************** +*/ + +#include + +#include +#include + +int sqlite3_vfslog_register(sqlite3 *db); + +static int xCallback(void *pUnused, int nArg, char **azArg, char **azName){ + char *zPrint = 0; + + assert( nArg==7 ); + zPrint = sqlite3_mprintf( + "INSERT INTO osinst VALUES(%Q, %Q, %s, %s, %s, %s, %s);", + azArg[0], azArg[1], azArg[2], azArg[3], azArg[4], azArg[5], azArg[6] + ); + printf("%s\n", zPrint); + sqlite3_free(zPrint); + return SQLITE_OK; +} + +int main(int argc, char **argv){ + sqlite3 *db = 0; + int i; + + sqlite3_open("", &db); + sqlite3_vfslog_register(db); + + printf("BEGIN;\n"); + printf("CREATE TABLE IF NOT EXISTS osinst(\n"); + printf(" event TEXT, -- xOpen, xRead etc.\n"); + printf(" file TEXT, -- Name of file this call applies to\n"); + printf(" time INTEGER, -- Timestamp\n"); + printf(" clicks INTEGER, -- Time spent in call\n"); + printf(" rc INTEGER, -- Return value\n"); + printf(" size INTEGER, -- Bytes read or written\n"); + printf(" offset INTEGER -- File offset read or written\n"); + printf(");\n"); + + for(i=1; i