This commit is contained in:
fyears 2024-04-04 21:52:01 +08:00
parent c472654060
commit cfe316f690
12 changed files with 298 additions and 77 deletions

View File

@ -271,6 +271,8 @@ export const DEFAULT_DEBUG_FOLDER = "_debug_remotely_save/";
export const DEFAULT_SYNC_PLANS_HISTORY_FILE_PREFIX =
"sync_plans_hist_exported_on_";
export const DEFAULT_LOG_HISTORY_FILE_PREFIX = "log_hist_exported_on_";
export const DEFAULT_PROFILER_RESULT_FILE_PREFIX =
"profiler_results_exported_on_";
export type SyncTriggerSourceType =
| "manual"

View File

@ -1,82 +1,24 @@
import { TAbstractFile, TFolder, TFile, Vault } from "obsidian";
import type { SyncPlanType } from "./sync";
import { readAllSyncPlanRecordTextsByVault } from "./localdb";
import {
readAllProfilerResultsByVault,
readAllSyncPlanRecordTextsByVault,
} from "./localdb";
import type { InternalDBs } from "./localdb";
import { mkdirpInVault } from "./misc";
import { mkdirpInVault, unixTimeToStr } from "./misc";
import {
DEFAULT_DEBUG_FOLDER,
DEFAULT_LOG_HISTORY_FILE_PREFIX,
DEFAULT_PROFILER_RESULT_FILE_PREFIX,
DEFAULT_SYNC_PLANS_HISTORY_FILE_PREFIX,
FileOrFolderMixedState,
} from "./baseTypes";
const turnSyncPlanToTable = (record: string) => {
const syncPlan: SyncPlanType = JSON.parse(record);
const { ts, tsFmt, remoteType, mixedStates } = syncPlan;
type allowedHeadersType = keyof FileOrFolderMixedState;
const headers: allowedHeadersType[] = [
"key",
"remoteEncryptedKey",
"existLocal",
"sizeLocal",
"sizeLocalEnc",
"mtimeLocal",
"deltimeLocal",
"changeLocalMtimeUsingMapping",
"existRemote",
"sizeRemote",
"sizeRemoteEnc",
"mtimeRemote",
"deltimeRemote",
"changeRemoteMtimeUsingMapping",
"decision",
"decisionBranch",
];
const lines = [
`ts: ${ts}${tsFmt !== undefined ? " / " + tsFmt : ""}`,
`remoteType: ${remoteType}`,
`| ${headers.join(" | ")} |`,
`| ${headers.map((x) => "---").join(" | ")} |`,
];
for (const [k1, v1] of Object.entries(syncPlan.mixedStates)) {
const k = k1 as string;
const v = v1 as FileOrFolderMixedState;
const singleLine = [];
for (const h of headers) {
const field = v[h];
if (field === undefined) {
singleLine.push("");
continue;
}
if (
h === "mtimeLocal" ||
h === "deltimeLocal" ||
h === "mtimeRemote" ||
h === "deltimeRemote"
) {
const fmt = v[(h + "Fmt") as allowedHeadersType] as string;
const s = `${field}${fmt !== undefined ? " / " + fmt : ""}`;
singleLine.push(s);
} else {
singleLine.push(field);
}
}
lines.push(`| ${singleLine.join(" | ")} |`);
}
return lines.join("\n");
};
export const exportVaultSyncPlansToFiles = async (
db: InternalDBs,
vault: Vault,
vaultRandomID: string,
howMany: number
) => {
console.info("exporting");
console.info("exporting sync plans");
await mkdirpInVault(DEFAULT_DEBUG_FOLDER, vault);
const records = await readAllSyncPlanRecordTextsByVault(db, vaultRandomID);
let md = "";
@ -101,5 +43,29 @@ export const exportVaultSyncPlansToFiles = async (
await vault.create(filePath, md, {
mtime: ts,
});
console.info("finish exporting");
console.info("finish exporting sync plans");
};
export const exportVaultProfilerResultsToFiles = async (
db: InternalDBs,
vault: Vault,
vaultRandomID: string
) => {
console.info("exporting profiler results");
await mkdirpInVault(DEFAULT_DEBUG_FOLDER, vault);
const records = await readAllProfilerResultsByVault(db, vaultRandomID);
let md = "";
if (records.length === 0) {
md = "No profiler results found";
} else {
md =
"Profiler results found:\n\n" +
records.map((x) => "```\n" + x + "\n```\n").join("\n");
}
const ts = Date.now();
const filePath = `${DEFAULT_DEBUG_FOLDER}${DEFAULT_PROFILER_RESULT_FILE_PREFIX}${ts}.md`;
await vault.create(filePath, md, {
mtime: ts,
});
console.info("finish exporting profiler results");
};

View File

@ -312,6 +312,10 @@
"settings_delprevsync_desc": "The sync algorithm keeps the previous successful sync information in DB to determine the file changes. If you want to ignore them so that all files are treated newly created, you can delete the prev sync info here.",
"settings_delprevsync_button": "Delete Prev Sync Details",
"settings_delprevsync_notice": "Previous sync history (in local DB) deleted",
"settings_profiler_results": "Export Profiler Results",
"settings_profiler_results_desc": "The plugin records the time cost of each steps. Here you can export them to know which step is slow.",
"settings_profiler_results_notice": "Profiler results exported.",
"settings_profiler_results_button_all": "Export All",
"settings_outputbasepathvaultid": "Output Vault Base Path And Randomly Assigned ID",
"settings_outputbasepathvaultid_desc": "For debugging purposes.",
"settings_outputbasepathvaultid_button": "Output",

View File

@ -311,6 +311,10 @@
"settings_delprevsync_desc": "同步算法需要上次成功同步的信息来决定文件变更,这个信息保存在本地的数据库里。如果您想忽略这些信息从而所有文件都被视为新创建的话,可以在此删除之前的信息。",
"settings_delprevsync_button": "删除上次同步明细",
"settings_delprevsync_notice": "(本地数据库里的)上次同步明细已被删除。",
"settings_profiler_results": "导出性能数据记录",
"settings_profiler_results_desc": "插件记录了每次同步每一步的耗时。这里可以导出记录得知哪一步最慢。",
"settings_profiler_results_notice": "性能数据已导出",
"settings_profiler_results_button_all": "导出所有",
"settings_outputbasepathvaultid": "输出资料库对应的位置和随机分配的 ID",
"settings_outputbasepathvaultid_desc": "用于调试。",
"settings_outputbasepathvaultid_button": "输出",

View File

@ -310,6 +310,10 @@
"settings_delprevsync_desc": "同步演算法需要上次成功同步的資訊來決定檔案變更,這個資訊儲存在本地的資料庫裡。如果您想忽略這些資訊從而所有檔案都被視為新建立的話,可以在此刪除之前的資訊。",
"settings_delprevsync_button": "刪除上次同步明細",
"settings_delprevsync_notice": "(本地資料庫裡的)上次同步明細已被刪除。",
"settings_profiler_results": "匯出效能資料記錄",
"settings_profiler_results_desc": "外掛記錄了每次同步每一步的耗時。這裡可以匯出記錄得知哪一步最慢。",
"settings_profiler_results_notice": "效能資料已匯出",
"settings_profiler_results_button_all": "匯出所有",
"settings_outputbasepathvaultid": "輸出資料庫對應的位置和隨機分配的 ID",
"settings_outputbasepathvaultid_desc": "用於除錯。",
"settings_outputbasepathvaultid_button": "輸出",

View File

@ -1,16 +1,21 @@
import { TFile, TFolder, type Vault } from "obsidian";
import type { Entity, MixedEntity } from "./baseTypes";
import { listFilesInObsFolder } from "./obsFolderLister";
import { Profiler } from "./profiler";
export const getLocalEntityList = async (
vault: Vault,
syncConfigDir: boolean,
configDir: string,
pluginID: string
pluginID: string,
profiler: Profiler
) => {
profiler.addIndent();
profiler.insert("enter getLocalEntityList");
const local: Entity[] = [];
const localTAbstractFiles = vault.getAllLoadedFiles();
profiler.insert("finish getting getAllLoadedFiles");
for (const entry of localTAbstractFiles) {
let r = {} as Entity;
let key = entry.path;
@ -54,12 +59,18 @@ export const getLocalEntityList = async (
local.push(r);
}
profiler.insert("finish transforming getAllLoadedFiles");
if (syncConfigDir) {
profiler.insert("into syncConfigDir");
const syncFiles = await listFilesInObsFolder(configDir, vault, pluginID);
for (const f of syncFiles) {
local.push(f);
}
profiler.insert("finish syncConfigDir");
}
profiler.insert("finish getLocalEntityList");
profiler.removeIndent();
return local;
};

View File

@ -17,6 +17,7 @@ export const DEFAULT_TBL_VAULT_RANDOM_ID_MAPPING = "vaultrandomidmapping";
export const DEFAULT_TBL_LOGGER_OUTPUT = "loggeroutput";
export const DEFAULT_TBL_SIMPLE_KV_FOR_MISC = "simplekvformisc";
export const DEFAULT_TBL_PREV_SYNC_RECORDS = "prevsyncrecords";
export const DEFAULT_TBL_PROFILER_RESULTS = "profilerresults";
/**
* @deprecated
@ -58,6 +59,7 @@ export interface InternalDBs {
loggerOutputTbl: LocalForage;
simpleKVForMiscTbl: LocalForage;
prevSyncRecordsTbl: LocalForage;
profilerResultsTbl: LocalForage;
/**
* @deprecated
@ -204,6 +206,10 @@ export const prepareDBs = async (
name: DEFAULT_DB_NAME,
storeName: DEFAULT_TBL_PREV_SYNC_RECORDS,
}),
profilerResultsTbl: localforage.createInstance({
name: DEFAULT_DB_NAME,
storeName: DEFAULT_TBL_PROFILER_RESULTS,
}),
fileHistoryTbl: localforage.createInstance({
name: DEFAULT_DB_NAME,
@ -524,3 +530,45 @@ export const upsertPluginVersionByVault = async (
newVersion: newVersion,
};
};
export const insertProfilerResultByVault = async (
db: InternalDBs,
profilerStr: string,
vaultRandomID: string,
remoteType: SUPPORTED_SERVICES_TYPE
) => {
const now = Date.now();
await db.profilerResultsTbl.setItem(`${vaultRandomID}\t${now}`, profilerStr);
// clear older one while writing
const records = (await db.profilerResultsTbl.keys())
.filter((x) => x.startsWith(`${vaultRandomID}\t`))
.map((x) => parseInt(x.split("\t")[1]));
records.sort((a, b) => -(a - b)); // descending
while (records.length > 5) {
const ts = records.pop()!;
await db.profilerResultsTbl.removeItem(`${vaultRandomID}\t${ts}`);
}
};
export const readAllProfilerResultsByVault = async (
db: InternalDBs,
vaultRandomID: string
) => {
const records = [] as { val: string; ts: number }[];
await db.profilerResultsTbl.iterate((value, key, iterationNumber) => {
if (key.startsWith(`${vaultRandomID}\t`)) {
records.push({
val: value as string,
ts: parseInt(key.split("\t")[1]),
});
}
});
records.sort((a, b) => -(a.ts - b.ts)); // descending
if (records === undefined) {
return [] as string[];
} else {
return records.map((x) => x.val);
}
};

View File

@ -35,6 +35,7 @@ import {
upsertLastSuccessSyncTimeByVault,
getLastSuccessSyncTimeByVault,
getAllPrevSyncRecordsByVaultAndProfile,
insertProfilerResultByVault,
} from "./localdb";
import { RemoteClient } from "./remote";
import {
@ -69,6 +70,7 @@ import AggregateError from "aggregate-error";
import { exportVaultSyncPlansToFiles } from "./debugMode";
import { changeMobileStatusBar, compareVersion } from "./misc";
import { Cipher } from "./encryptUnified";
import { Profiler } from "./profiler";
const DEFAULT_SETTINGS: RemotelySavePluginSettings = {
s3: DEFAULT_S3_CONFIG,
@ -154,6 +156,8 @@ export default class RemotelySavePlugin extends Plugin {
appContainerObserver?: MutationObserver;
async syncRun(triggerSource: SyncTriggerSourceType = "manual") {
const profiler = new Profiler("start of syncRun");
const t = (x: TransItemType, vars?: any) => {
return this.i18n.t(x, vars);
};
@ -234,6 +238,7 @@ export default class RemotelySavePlugin extends Plugin {
}
this.syncStatus = "preparing";
profiler.insert("finish step1");
if (this.settings.currLogLevel === "info") {
// pass
@ -249,12 +254,15 @@ export default class RemotelySavePlugin extends Plugin {
this.settings.dropbox,
this.settings.onedrive,
this.app.vault.getName(),
() => self.saveSettings()
() => self.saveSettings(),
profiler
);
const remoteEntityList = await client.listAllFromRemote();
console.debug("remoteEntityList:");
console.debug(remoteEntityList);
profiler.insert("finish step2 (listing remote)");
if (this.settings.currLogLevel === "info") {
// pass
} else {
@ -272,6 +280,8 @@ export default class RemotelySavePlugin extends Plugin {
throw Error(passwordCheckResult.reason);
}
profiler.insert("finish step3 (checking password)");
if (this.settings.currLogLevel === "info") {
// pass
} else {
@ -282,11 +292,14 @@ export default class RemotelySavePlugin extends Plugin {
this.app.vault,
this.settings.syncConfigDir ?? false,
this.app.vault.configDir,
this.manifest.id
this.manifest.id,
profiler
);
console.debug("localEntityList:");
console.debug(localEntityList);
profiler.insert("finish step4 (local meta)");
if (this.settings.currLogLevel === "info") {
// pass
} else {
@ -301,6 +314,8 @@ export default class RemotelySavePlugin extends Plugin {
console.debug("prevSyncEntityList:");
console.debug(prevSyncEntityList);
profiler.insert("finish step5 (prev sync)");
if (this.settings.currLogLevel === "info") {
// pass
} else {
@ -316,17 +331,21 @@ export default class RemotelySavePlugin extends Plugin {
this.settings.syncUnderscoreItems ?? false,
this.settings.ignorePaths ?? [],
cipher,
this.settings.serviceType
this.settings.serviceType,
profiler
);
profiler.insert("finish building partial mixedEntity");
mixedEntityMappings = await getSyncPlanInplace(
mixedEntityMappings,
this.settings.howToCleanEmptyFolder ?? "skip",
this.settings.skipSizeLargerThan ?? -1,
this.settings.conflictAction ?? "keep_newer",
this.settings.syncDirection ?? "bidirectional"
this.settings.syncDirection ?? "bidirectional",
profiler
);
console.info(`mixedEntityMappings:`);
console.info(mixedEntityMappings); // for debugging
profiler.insert("finish building full sync plan");
await insertSyncPlanRecordByVault(
this.db,
mixedEntityMappings,
@ -334,6 +353,9 @@ export default class RemotelySavePlugin extends Plugin {
client.serviceType
);
profiler.insert("finish writing sync plan");
profiler.insert("finish step6 (plan)");
// The operations above are almost read only and kind of safe.
// The operations below begins to write or delete (!!!) something.
@ -384,7 +406,8 @@ export default class RemotelySavePlugin extends Plugin {
decision,
triggerSource
),
this.db
this.db,
profiler
);
} else {
this.syncStatus = "syncing";
@ -397,6 +420,8 @@ export default class RemotelySavePlugin extends Plugin {
cipher.closeResources();
profiler.insert("finish step7 (actual sync)");
if (this.settings.currLogLevel === "info") {
getNotice(t("syncrun_shortstep2"));
} else {
@ -406,6 +431,8 @@ export default class RemotelySavePlugin extends Plugin {
this.syncStatus = "finish";
this.syncStatus = "idle";
profiler.insert("finish step8");
const lastSuccessSyncMillis = Date.now();
await upsertLastSuccessSyncTimeByVault(
this.db,
@ -429,6 +456,7 @@ export default class RemotelySavePlugin extends Plugin {
}-${Date.now()}: finish sync, triggerSource=${triggerSource}`
);
} catch (error: any) {
profiler.insert("start error branch");
const msg = t("syncrun_abort", {
manifestID: this.manifest.id,
theDate: `${Date.now()}`,
@ -450,7 +478,19 @@ export default class RemotelySavePlugin extends Plugin {
setIcon(this.syncRibbon, iconNameSyncWait);
this.syncRibbon.setAttribute("aria-label", originLabel);
}
profiler.insert("finish error branch");
}
profiler.insert("finish syncRun");
console.debug(profiler.toString());
insertProfilerResultByVault(
this.db,
profiler.toString(),
this.vaultRandomID,
this.settings.serviceType
);
profiler.clear();
}
async onload() {

82
src/profiler.ts Normal file
View File

@ -0,0 +1,82 @@
import { unixTimeToStr } from "./misc";
interface BreakPoint {
label: string;
fakeTimeMilli: number; // it's NOT a unix timestamp
indent: number;
}
export class Profiler {
startTime: number;
breakPoints: BreakPoint[];
indent: number;
constructor(label?: string) {
this.breakPoints = [];
this.indent = 0;
this.startTime = 0;
if (label !== undefined) {
this.startTime = Date.now();
this.breakPoints.push({
label: label,
fakeTimeMilli: performance.now(),
indent: this.indent,
});
}
}
insert(label: string) {
if (this.breakPoints.length === 0) {
this.startTime = Date.now();
}
this.breakPoints.push({
label: label,
fakeTimeMilli: performance.now(),
indent: this.indent,
});
return this;
}
addIndent() {
this.indent += 2;
}
removeIndent() {
this.indent -= 2;
if (this.indent < 0) {
this.indent = 0;
}
}
clear() {
this.breakPoints = [];
this.indent = 0;
this.startTime = 0;
return this;
}
toString() {
if (this.breakPoints.length === 0) {
return "nothing in profiler";
}
let res = `[startTime]: ${unixTimeToStr(this.startTime)}`;
for (let i = 0; i < this.breakPoints.length; ++i) {
if (i === 0) {
res += `\n[${this.breakPoints[i]["label"]}]: start`;
} else {
const label = this.breakPoints[i]["label"];
const indent = this.breakPoints[i]["indent"];
const millsec =
Math.round(
(this.breakPoints[i]["fakeTimeMilli"] -
this.breakPoints[i - 1]["fakeTimeMilli"]) *
10
) / 10.0;
res += `\n${" ".repeat(indent)}[${label}]: ${millsec}ms`;
}
}
return res;
}
}

View File

@ -13,6 +13,7 @@ import * as onedrive from "./remoteForOnedrive";
import * as s3 from "./remoteForS3";
import * as webdav from "./remoteForWebdav";
import { Cipher } from "./encryptUnified";
import { Profiler } from "./profiler";
export class RemoteClient {
readonly serviceType: SUPPORTED_SERVICES_TYPE;
@ -31,7 +32,8 @@ export class RemoteClient {
dropboxConfig?: DropboxConfig,
onedriveConfig?: OnedriveConfig,
vaultName?: string,
saveUpdatedConfigFunc?: () => Promise<any>
saveUpdatedConfigFunc?: () => Promise<any>,
profiler?: Profiler
) {
this.serviceType = serviceType;
// the client may modify the config inplace,

View File

@ -25,7 +25,10 @@ import {
CipherMethodType,
QRExportType,
} from "./baseTypes";
import { exportVaultSyncPlansToFiles } from "./debugMode";
import {
exportVaultProfilerResultsToFiles,
exportVaultSyncPlansToFiles,
} from "./debugMode";
import {
exportQrCodeUri,
importQrCodeUri,
@ -2355,6 +2358,21 @@ export class RemotelySaveSettingTab extends PluginSettingTab {
});
});
new Setting(debugDiv)
.setName(t("settings_profiler_results"))
.setDesc(t("settings_profiler_results_desc"))
.addButton(async (button) => {
button.setButtonText(t("settings_profiler_results_button_all"));
button.onClick(async () => {
await exportVaultProfilerResultsToFiles(
this.plugin.db,
this.app.vault,
this.plugin.vaultRandomID
);
new Notice(t("settings_profiler_results_notice"));
});
});
new Setting(debugDiv)
.setName(t("settings_outputbasepathvaultid"))
.setDesc(t("settings_outputbasepathvaultid_desc"))

View File

@ -34,6 +34,7 @@ import {
upsertPrevSyncRecordByVaultAndProfile,
} from "./localdb";
import { Cipher } from "./encryptUnified";
import { Profiler } from "./profiler";
export type SyncStatusType =
| "idle"
@ -323,8 +324,13 @@ export const ensembleMixedEnties = async (
syncUnderscoreItems: boolean,
ignorePaths: string[],
cipher: Cipher,
serviceType: SUPPORTED_SERVICES_TYPE
serviceType: SUPPORTED_SERVICES_TYPE,
profiler: Profiler
): Promise<SyncPlanType> => {
profiler.addIndent();
profiler.insert("ensembleMixedEnties: enter");
const finalMappings: SyncPlanType = {};
const synthFolders: Record<string, Entity> = {};
@ -383,6 +389,8 @@ export const ensembleMixedEnties = async (
}
}
profiler.insert("ensembleMixedEnties: finish remote");
console.debug(`synthFolders:`);
console.debug(synthFolders);
@ -394,6 +402,8 @@ export const ensembleMixedEnties = async (
};
}
profiler.insert("ensembleMixedEnties: finish synth");
if (Object.keys(finalMappings).length === 0 || localEntityList.length === 0) {
// Special checking:
// if one side is totally empty,
@ -438,6 +448,8 @@ export const ensembleMixedEnties = async (
}
}
profiler.insert("ensembleMixedEnties: finish prevSync");
// local has to be last
// because we want to get keyEnc based on the remote
// (we don't consume prevSync here because it gains no benefit)
@ -475,8 +487,13 @@ export const ensembleMixedEnties = async (
}
}
profiler.insert("ensembleMixedEnties: finish local");
console.debug("in the end of ensembleMixedEnties, finalMappings is:");
console.debug(finalMappings);
profiler.insert("ensembleMixedEnties: exit");
profiler.removeIndent();
return finalMappings;
};
@ -490,12 +507,16 @@ export const getSyncPlanInplace = async (
howToCleanEmptyFolder: EmptyFolderCleanType,
skipSizeLargerThan: number,
conflictAction: ConflictActionType,
syncDirection: SyncDirectionType
syncDirection: SyncDirectionType,
profiler: Profiler
) => {
profiler.addIndent();
profiler.insert("getSyncPlanInplace: enter");
// from long(deep) to short(shadow)
const sortedKeys = Object.keys(mixedEntityMappings).sort(
(k1, k2) => k2.length - k1.length
);
profiler.insert("getSyncPlanInplace: finish sorting");
const keptFolder = new Set<string>();
@ -897,6 +918,8 @@ export const getSyncPlanInplace = async (
}
}
profiler.insert("getSyncPlanInplace: finish looping");
keptFolder.delete("/");
keptFolder.delete("");
if (keptFolder.size > 0) {
@ -916,6 +939,9 @@ export const getSyncPlanInplace = async (
},
};
profiler.insert("getSyncPlanInplace: exit");
profiler.removeIndent();
return mixedEntityMappings;
};
@ -1261,8 +1287,11 @@ export const doActualSync = async (
protectModifyPercentage: number,
getProtectModifyPercentageErrorStrFunc: any,
callbackSyncProcess: any,
db: InternalDBs
db: InternalDBs,
profiler: Profiler
) => {
profiler.addIndent();
profiler.insert("doActualSync: enter");
console.debug(`concurrency === ${concurrency}`);
const {
onlyMarkSyncedOps,
@ -1280,6 +1309,7 @@ export const doActualSync = async (
console.debug(`allFilesCount: ${allFilesCount}`);
console.debug(`realModifyDeleteCount: ${realModifyDeleteCount}`);
console.debug(`realTotalCount: ${realTotalCount}`);
profiler.insert("doActualSync: finish splitting steps");
console.debug(`protectModifyPercentage: ${protectModifyPercentage}`);
@ -1304,6 +1334,8 @@ export const doActualSync = async (
allFilesCount
);
profiler.insert("doActualSync: error branch");
profiler.removeIndent();
throw Error(errorStr);
}
}
@ -1323,6 +1355,8 @@ export const doActualSync = async (
let realCounter = 0;
for (let i = 0; i < nested.length; ++i) {
profiler.addIndent();
profiler.insert(`doActualSync: step ${i} start`);
console.debug(logTexts[i]);
const operations = nested[i];
@ -1398,5 +1432,11 @@ export const doActualSync = async (
throw new AggregateError(potentialErrors);
}
}
profiler.insert(`doActualSync: step ${i} end`);
profiler.removeIndent();
}
profiler.insert(`doActualSync: exit`);
profiler.removeIndent();
};