Co-authored-by: gorbenko.pavel <gorbenko.pavel@tansu.kz> Reviewed-on: http://git.tnsu.kz/timur.gorodetskiy/request-portal/pulls/12
This commit was merged in pull request #12.
This commit is contained in:
@@ -0,0 +1,488 @@
|
||||
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();
|
||||
Reference in New Issue
Block a user