gorbenko.pavel
489 lines
23 KiB
TypeScript
489 lines
23 KiB
TypeScript
import { TimelinePipe } from '@pnp/core';
|
||
import { Queryable } from '@pnp/queryable';
|
||
|
||
/**
|
||
* Замер загрузки: «на что именно ушло ожидание», а не просто «страница долго
|
||
* грузится».
|
||
*
|
||
* Пишет ДВА среза сразу, и они дополняют друг друга:
|
||
* • ЭТАПЫ — логические шаги, размеченные вручную через traced()/perfScope().
|
||
* Из списка URL не видно, что десяток одинаковых `.../rootfolder` —
|
||
* это резолв адресов списков согласования по партициям.
|
||
* • ЗАПРОСЫ — КАЖДЫЙ HTTP-вызов PnPjs, сгруппированный по виду операции.
|
||
* Снимается автоматически (см. PerfObserver ниже, подключён в
|
||
* shared/pnp/pnpjs.ts), поэтому покрывает ВСЕ разделы портала —
|
||
* включая формы и панель заявки, где ручной разметки нет.
|
||
*
|
||
* Складывать эти два среза между собой нельзя: запросы лежат ВНУТРИ этапов,
|
||
* сумма получилась бы двойной. Поэтому и таблицы две, с отдельными итогами.
|
||
*
|
||
* Как читать: «ОЖИДАНИЕ» — сколько реально прошло от начала операции до конца,
|
||
* то есть ровно то, что чувствует пользователь. Сумма времён отдельных шагов
|
||
* всегда БОЛЬШЕ: шаги идут параллельно (Promise.all) и их времена накладываются.
|
||
* Поэтому большая сумма у шага сама по себе ещё ничего не значит — важно, лежит
|
||
* ли он на последовательной цепочке. Признак: сложил несколько шагов и получил
|
||
* примерно ожидание — значит они идут друг за другом, и сокращать надо их.
|
||
*
|
||
* Включение/выключение БЕЗ пересборки — из консоли браузера:
|
||
* window.rpPerf = true // включить
|
||
* window.rpPerf = false // выключить
|
||
* window.rpPerfLast // последняя сводка объектом (скопировать/отдать)
|
||
*
|
||
* Флаг ЗАПОМИНАЕТСЯ в localStorage: выставил один раз — работает и после
|
||
* перезагрузки. Разбор производительности идёт несколькими заходами с F5 между
|
||
* ними, и переписывать флаг каждый раз — ровно та мелочь, из-за которой замером
|
||
* перестают пользоваться. Сделано свойством-аксессором на window, а не функцией
|
||
* setPerf(): в консоли естественно написать `window.rpPerf = true`.
|
||
*
|
||
* По умолчанию выключено: предыдущая версия модуля (коммит 7bd540e) писала в
|
||
* консоль всегда, без флага, и её пришлось снимать целиком вместе со всеми
|
||
* обёртками. С флагом обёртки живут в коде постоянно — выключенный traced() не
|
||
* делает ничего, кроме вызова переданной функции.
|
||
*/
|
||
|
||
const DEFAULT_PERF: boolean = false;
|
||
|
||
const PREFIX = '[Перф]';
|
||
|
||
// Ключ в localStorage совпадает с именем флага — чтобы в DevTools → Application
|
||
// его можно было найти и снять, не зная про этот модуль.
|
||
const STORAGE_KEY = 'rpPerf';
|
||
|
||
// Через сколько тишины считать операцию законченной и печатать сводку, если её
|
||
// никто не обрамил perfScope. Нужно для разделов без ручной разметки (панель
|
||
// заявки, формы): там просто идут запросы, и «загрузка закончилась» видно только
|
||
// по тому, что новых запросов больше нет.
|
||
const IDLE_FLUSH_MS = 900;
|
||
|
||
// Сколько самых тяжёлых меток показывать прямо в строке. Больше трёх — и строка
|
||
// перестаёт читаться с одного взгляда, а ради этого всё и затевалось;
|
||
// остальное смотрится через window.rpPerfDetail().
|
||
const TOP_IN_LINE = 3;
|
||
|
||
/** Накопленное по одной метке. */
|
||
interface IStat {
|
||
calls: number;
|
||
totalMs: number;
|
||
maxMs: number;
|
||
}
|
||
|
||
/**
|
||
* Сэмплы одной метки по всем прогонам — база для МЕДИАНЫ, а не среднего.
|
||
*
|
||
* Среднее одним выбросом (случайный 429 с ретраем, холодный кеш на первом
|
||
* заходе) утаскивает за собой всю картину надолго — а именно выбросы здесь
|
||
* основной случай, не редкость. Медиана его игнорирует: важнее «как обычно»,
|
||
* а не «как в сумме с той единственной аномалией».
|
||
*/
|
||
interface ILabelSamples {
|
||
/** totalMs метки за каждый прогон, где она встретилась (метка не обязана быть в каждом). */
|
||
totalMs: number[];
|
||
calls: number[];
|
||
/** Худший случай за всё время — в отличие от totalMs, это не медиана, а running max. */
|
||
maxMs: number;
|
||
}
|
||
|
||
// Сколько последних прогонов метки хранить ради медианы. Не безлимитный рост:
|
||
// в долгой сессии старые сэмплы устаревают быстрее, чем на них смотрят, а лимит
|
||
// защищает от утечки памяти на вкладке, оставленной открытой на весь день.
|
||
const MAX_SAMPLES = 50;
|
||
|
||
function pushSample(list: number[], value: number): void {
|
||
list.push(value);
|
||
if (list.length > MAX_SAMPLES) list.shift();
|
||
}
|
||
|
||
function median(values: number[]): number {
|
||
if (values.length === 0) return 0;
|
||
const sorted = [...values].sort((a, b) => a - b);
|
||
const mid = Math.floor(sorted.length / 2);
|
||
return sorted.length % 2 === 1 ? sorted[mid] : (sorted[mid - 1] + sorted[mid]) / 2;
|
||
}
|
||
|
||
/** Накопленное по одной операции за ВСЕ её прогоны — база для медианы. */
|
||
interface IRunHistory {
|
||
wallSamples: number[];
|
||
stages: Map<string, ILabelSamples>;
|
||
requests: Map<string, ILabelSamples>;
|
||
}
|
||
|
||
// Текущий (ещё не напечатанный) прогон.
|
||
const stages = new Map<string, IStat>();
|
||
const requests = new Map<string, IStat>();
|
||
|
||
// История по операциям — живёт до перезагрузки страницы или window.rpPerfReset().
|
||
const history = new Map<string, IRunHistory>();
|
||
|
||
// Глубина открытых perfScope. Сводка печатается, когда закрылась ПОСЛЕДНЯЯ
|
||
// внешняя операция: шаги почти всегда идут параллельно, и печатать таблицу на
|
||
// каждом вложенном завершении значило бы печатать её десятками кусков. Если две
|
||
// верхнеуровневые операции наложились (типичный случай: счётчики меню и загрузка
|
||
// таблицы стартуют вместе), их метки попадут в одну таблицу — это и нужно, там
|
||
// как раз видны дубли.
|
||
let openScopes = 0;
|
||
let scopeLabels: string[] = [];
|
||
|
||
// Границы текущего окна накопления — для «ОЖИДАНИЯ». Начало ставит открытие
|
||
// scope либо первая запись, конец двигает каждая следующая.
|
||
let windowStart = 0;
|
||
let windowEnd = 0;
|
||
|
||
let idleTimer: number | undefined;
|
||
|
||
// ---------------------------------------------------------------------------
|
||
// Флаг
|
||
|
||
function readStoredFlag(): boolean | undefined {
|
||
// localStorage может быть недоступен (приватный режим, политика браузера,
|
||
// ограниченный iframe) — отладочный флаг не повод падать.
|
||
try {
|
||
const raw = window.localStorage.getItem(STORAGE_KEY);
|
||
if (raw === null) return undefined;
|
||
return raw === 'true';
|
||
} catch {
|
||
return undefined;
|
||
}
|
||
}
|
||
|
||
function writeStoredFlag(value: boolean): void {
|
||
try {
|
||
window.localStorage.setItem(STORAGE_KEY, value ? 'true' : 'false');
|
||
} catch {
|
||
// Значение всё равно применится — просто не переживёт перезагрузку.
|
||
}
|
||
}
|
||
|
||
let enabled: boolean = readStoredFlag() ?? DEFAULT_PERF;
|
||
|
||
function perfEnabled(): boolean {
|
||
return enabled;
|
||
}
|
||
|
||
function installFlag(): void {
|
||
const w = window as unknown as { rpPerf?: boolean };
|
||
|
||
const existing = Object.getOwnPropertyDescriptor(w, 'rpPerf');
|
||
if (existing && existing.get) return;
|
||
|
||
// Значение, присвоенное ДО загрузки этого чанка, не теряем.
|
||
const preset = typeof w.rpPerf === 'boolean' ? w.rpPerf : undefined;
|
||
|
||
Object.defineProperty(w, 'rpPerf', {
|
||
configurable: true,
|
||
get: (): boolean => enabled,
|
||
set: (value: unknown): void => {
|
||
enabled = !!value;
|
||
writeStoredFlag(enabled);
|
||
if (!enabled) {
|
||
// Тишина СРАЗУ, а не после того, что уже накопилось. Без этого operация,
|
||
// стартовавшая ДО выключения (perfScope с сетевым шагом внутри) или
|
||
// ждущая debounce-таймера (см. scheduleIdleFlush), всё равно печатала
|
||
// итог ПОСЛЕ выключения — выглядело так, будто window.rpPerf = false
|
||
// не действует.
|
||
if (idleTimer !== undefined) {
|
||
window.clearTimeout(idleTimer);
|
||
idleTimer = undefined;
|
||
}
|
||
reset();
|
||
}
|
||
console.log(`${PREFIX} замер ${enabled ? 'включён' : 'выключен'} (запомнено до отмены)`);
|
||
}
|
||
});
|
||
|
||
if (preset !== undefined) {
|
||
enabled = preset;
|
||
writeStoredFlag(preset);
|
||
} else if (enabled) {
|
||
// Иначе легко забыть, что флаг остался включённым с прошлого раза, и потом
|
||
// гадать, откуда в консоли таблицы.
|
||
console.log(`${PREFIX} замер включён (запомнен ранее). Выключить: window.rpPerf = false`);
|
||
}
|
||
}
|
||
|
||
installFlag();
|
||
|
||
// ---------------------------------------------------------------------------
|
||
// Накопление
|
||
|
||
function record(into: Map<string, IStat>, label: string, ms: number): void {
|
||
const now = performance.now();
|
||
if (windowStart === 0) windowStart = now - ms;
|
||
windowEnd = now;
|
||
|
||
const stat = into.get(label) ?? { calls: 0, totalMs: 0, maxMs: 0 };
|
||
stat.calls += 1;
|
||
stat.totalMs += ms;
|
||
stat.maxMs = Math.max(stat.maxMs, ms);
|
||
into.set(label, stat);
|
||
|
||
scheduleIdleFlush();
|
||
}
|
||
|
||
// Разделы без ручной разметки (панель заявки, формы) сводку сами не закрывают —
|
||
// закрываем по тишине. Пока открыт perfScope, решает он.
|
||
function scheduleIdleFlush(): void {
|
||
if (idleTimer !== undefined) window.clearTimeout(idleTimer);
|
||
idleTimer = window.setTimeout(() => {
|
||
idleTimer = undefined;
|
||
if (openScopes === 0 && perfEnabled()) print();
|
||
}, IDLE_FLUSH_MS);
|
||
}
|
||
|
||
// ---------------------------------------------------------------------------
|
||
// Разметка этапов
|
||
|
||
/**
|
||
* Обернуть один этап замером. Метку делай осмысленной и повторяемой: одинаковые
|
||
* этапы разных партиций должны попадать в ОДНУ строку сводки (число вызовов
|
||
* важнее, чем какая именно партиция), поэтому в метку не надо подставлять
|
||
* listId — только имя этапа.
|
||
*/
|
||
export async function traced<T>(label: string, fn: () => Promise<T>): Promise<T> {
|
||
if (!perfEnabled()) return fn();
|
||
|
||
const start = performance.now();
|
||
try {
|
||
return await fn();
|
||
} finally {
|
||
record(stages, label, performance.now() - start);
|
||
}
|
||
}
|
||
|
||
/**
|
||
* Верхнеуровневая операция (открытие вкладки, счётчики меню). Когда она
|
||
* завершается, печатается сводка по всему, что накопилось внутри.
|
||
*/
|
||
export async function perfScope<T>(label: string, fn: () => Promise<T>): Promise<T> {
|
||
if (!perfEnabled()) return fn();
|
||
|
||
if (openScopes === 0) {
|
||
reset();
|
||
windowStart = performance.now();
|
||
}
|
||
openScopes += 1;
|
||
scopeLabels.push(label);
|
||
|
||
try {
|
||
return await fn();
|
||
} finally {
|
||
openScopes -= 1;
|
||
// perfEnabled() — на выходе, а не только на входе: операцию могли выключить,
|
||
// пока она ещё выполнялась (см. setter window.rpPerf выше), и тогда печатать
|
||
// её итог уже не нужно — accumulated-данные к этому моменту сам setter уже
|
||
// сбросил.
|
||
if (openScopes === 0 && perfEnabled()) print();
|
||
}
|
||
}
|
||
|
||
// ---------------------------------------------------------------------------
|
||
// Автоматический учёт КАЖДОГО запроса PnPjs
|
||
|
||
// Вид операции по url — иначе каждая партиция со своим адресом и своим $filter
|
||
// даёт отдельную строку и таблица нечитаема. Нужна именно ОПЕРАЦИЯ, а не адрес.
|
||
function classify(rawUrl: string): string {
|
||
let path: string;
|
||
let search: string;
|
||
try {
|
||
const parsed = new URL(rawUrl);
|
||
path = parsed.pathname;
|
||
search = parsed.search;
|
||
} catch {
|
||
return rawUrl;
|
||
}
|
||
|
||
if (/\/_api\/search\/(post)?query/i.test(path)) return 'search/query';
|
||
if (/\/_api\/\$batch/i.test(path)) return '$batch (пакет)';
|
||
if (/\/_api\/contextinfo/i.test(path)) return 'contextinfo (дайджест)';
|
||
|
||
const api = path.split(/\/_api\//i)[1];
|
||
if (!api) return path;
|
||
|
||
// Аргументы (getByTitle('…'), getList('/sites/…/Lists/List7')) и id элементов
|
||
// схлопываем — иначе каждая партиция даст свою строку.
|
||
const op = api.replace(/\((?:[^()]|\([^()]*\))*\)/g, '()').replace(/\/\d+(?=\/|$)/g, '/N');
|
||
|
||
// Резолв адреса списка согласования выделяем отдельно — ради него всё и
|
||
// затевалось, и в общей куче «web/lists()» его было бы не видно.
|
||
if (/rootfolder/i.test(op) || /rootfolder/i.test(search)) return `адрес списка (RootFolder) — ${op}`;
|
||
if (/^web\/lists$/i.test(op)) return 'web/lists (все списки веба)';
|
||
|
||
return op;
|
||
}
|
||
|
||
interface ITimedQueryable {
|
||
__rpStart?: number;
|
||
}
|
||
|
||
/**
|
||
* Behavior PnPjs: засекает время каждого запроса.
|
||
*
|
||
* Подключается один раз в shared/pnp/pnpjs.ts и за счёт этого покрывает ВСЕ
|
||
* разделы портала, а не только размеченные вручную. Когда замер выключен,
|
||
* наблюдатели всё равно висят, но не делают ничего дороже чтения флага.
|
||
*/
|
||
export function PerfObserver(): TimelinePipe<Queryable> {
|
||
return (instance: Queryable) => {
|
||
instance.on.pre(async function (url, init, result) {
|
||
if (perfEnabled()) (this as unknown as ITimedQueryable).__rpStart = performance.now();
|
||
return [url, init, result];
|
||
});
|
||
|
||
instance.on.post(async function (url, result) {
|
||
const start = (this as unknown as ITimedQueryable).__rpStart;
|
||
if (perfEnabled() && start !== undefined) {
|
||
record(requests, classify(url.toString()), performance.now() - start);
|
||
}
|
||
return [url, result];
|
||
});
|
||
|
||
return instance;
|
||
};
|
||
}
|
||
|
||
// ---------------------------------------------------------------------------
|
||
// Печать
|
||
|
||
function reset(): void {
|
||
stages.clear();
|
||
requests.clear();
|
||
scopeLabels = [];
|
||
windowStart = 0;
|
||
windowEnd = 0;
|
||
}
|
||
|
||
/**
|
||
* Ключ, под которым прогоны копятся в историю.
|
||
*
|
||
* Номер страницы из метки убираем: пролистать вкладку по страницам — самый
|
||
* удобный способ набрать несколько замеров одной и той же операции, и считать
|
||
* медиану надо по ним ВМЕСТЕ. Иначе каждая страница завела бы свою историю из
|
||
* одного прогона, и медиане не по чему было бы считаться.
|
||
*/
|
||
function historyKey(title: string): string {
|
||
return title.replace(/\s*стр\.\d+/g, '').trim();
|
||
}
|
||
|
||
function recordSamples(target: Map<string, ILabelSamples>, source: Map<string, IStat>): void {
|
||
source.forEach((s, label) => {
|
||
const t = target.get(label) ?? { totalMs: [], calls: [], maxMs: 0 };
|
||
pushSample(t.totalMs, s.totalMs);
|
||
pushSample(t.calls, s.calls);
|
||
t.maxMs = Math.max(t.maxMs, s.maxMs);
|
||
target.set(label, t);
|
||
});
|
||
}
|
||
|
||
function heaviest(source: Map<string, IStat>, take: number): string {
|
||
return Array.from(source.entries())
|
||
.sort((a, b) => b[1].totalMs - a[1].totalMs)
|
||
.slice(0, take)
|
||
.map(([label, s]) => `${label} ${Math.round(s.totalMs)}`)
|
||
.join(', ');
|
||
}
|
||
|
||
function totalCalls(source: Map<string, IStat>): number {
|
||
return Array.from(source.values()).reduce((acc, s) => acc + s.calls, 0);
|
||
}
|
||
|
||
/**
|
||
* Одна строка на загрузку — и всё.
|
||
*
|
||
* Раньше здесь печатались две таблицы. Их было невозможно ни окинуть взглядом
|
||
* при листании страниц, ни скопировать: console.table при переносе из консоли
|
||
* превращается в кашу из колонок. Полная раскладка никуда не делась — она за
|
||
* window.rpPerfDetail(), и её зовут тогда, когда строка показала, что смотреть
|
||
* есть на что.
|
||
*
|
||
* Медиана в строке важнее текущего значения: одиночный сетевой замер шумит
|
||
* настолько, что по нему нельзя сказать, стало лучше или просто повезло, а
|
||
* среднее в этом же шуме утаскивает один выброс (холодный кеш, ретрай на 429)
|
||
* далеко за пределы того, что происходит обычно.
|
||
*/
|
||
function print(): void {
|
||
if (idleTimer !== undefined) {
|
||
window.clearTimeout(idleTimer);
|
||
idleTimer = undefined;
|
||
}
|
||
if (stages.size === 0 && requests.size === 0) return;
|
||
|
||
const wallMs = (openScopes > 0 ? performance.now() : windowEnd) - windowStart;
|
||
const title = scopeLabels.length > 0 ? scopeLabels.join(' + ') : 'без разметки';
|
||
const key = historyKey(title);
|
||
|
||
const hist: IRunHistory = history.get(key) ?? {
|
||
wallSamples: [],
|
||
stages: new Map<string, ILabelSamples>(),
|
||
requests: new Map<string, ILabelSamples>()
|
||
};
|
||
pushSample(hist.wallSamples, wallMs);
|
||
recordSamples(hist.stages, stages);
|
||
recordSamples(hist.requests, requests);
|
||
history.set(key, hist);
|
||
|
||
// Дольше всего — по этапам, если разметка есть; иначе по видам запросов
|
||
// (разделы без ручной разметки: панель заявки, формы).
|
||
const top = heaviest(stages.size > 0 ? stages : requests, TOP_IN_LINE);
|
||
|
||
console.log(
|
||
`${PREFIX} ${key} | ожидание ${Math.round(wallMs)} мс` +
|
||
` (мед. ${Math.round(median(hist.wallSamples))} за ${hist.wallSamples.length})` +
|
||
` | запросов ${totalCalls(requests)}` +
|
||
(top ? ` | дольше всего: ${top}` : '')
|
||
);
|
||
|
||
reset();
|
||
}
|
||
|
||
/** Строки полной раскладки по одной операции — медианы за все её прогоны. */
|
||
function detailLines(key: string, hist: IRunHistory): string[] {
|
||
const lines = [
|
||
`${PREFIX} ${key} - прогонов ${hist.wallSamples.length}, ожидание медиана ${Math.round(median(hist.wallSamples))} мс`
|
||
];
|
||
|
||
const dump = (name: string, source: Map<string, ILabelSamples>): void => {
|
||
if (source.size === 0) return;
|
||
lines.push(` ${name} (медиана за прогон)`);
|
||
Array.from(source.entries())
|
||
.sort((a, b) => median(b[1].totalMs) - median(a[1].totalMs))
|
||
.forEach(([label, s]) => {
|
||
lines.push(
|
||
` ${Math.round(median(s.totalMs))} мс, вызовов ${Math.round(median(s.calls))}, макс ${Math.round(s.maxMs)} - ${label}`
|
||
);
|
||
});
|
||
};
|
||
|
||
dump('ЭТАПЫ', hist.stages);
|
||
dump('ЗАПРОСЫ', hist.requests);
|
||
return lines;
|
||
}
|
||
|
||
/**
|
||
* Полная раскладка по всем измеренным операциям — window.rpPerfDetail().
|
||
*
|
||
* Возвращает текст, а не только печатает: в консоли Chrome его удобно забрать
|
||
* целиком через copy(rpPerfDetail()).
|
||
*/
|
||
function installDetailApi(): void {
|
||
const w = window as unknown as { rpPerfDetail?: () => string; rpPerfReset?: () => void };
|
||
|
||
w.rpPerfDetail = (): string => {
|
||
if (history.size === 0) return `${PREFIX} замеров пока нет`;
|
||
const text = Array.from(history.entries())
|
||
.reduce<string[]>((acc, [key, hist]) => acc.concat(detailLines(key, hist)), [])
|
||
.join(String.fromCharCode(10));
|
||
console.log(text);
|
||
return text;
|
||
};
|
||
|
||
// Старые прогоны остаются в окне (см. MAX_SAMPLES) и тянут медиану назад —
|
||
// «стало быстрее» проявится в ней только после того, как их наберётся
|
||
// больше половины окна. Перед сравнением «до/после» серию надо обнулять.
|
||
w.rpPerfReset = (): void => {
|
||
history.clear();
|
||
reset();
|
||
console.log(`${PREFIX} история замеров очищена`);
|
||
};
|
||
}
|
||
|
||
installDetailApi();
|