трейсы

This commit is contained in:
gorbenko.pavel
2026-08-20 17:10:54 +05:00
parent c6c549eae9
commit a4e6e097f3
3 changed files with 385 additions and 83 deletions
+312 -70
View File
@@ -1,31 +1,44 @@
import { TimelinePipe } from '@pnp/core';
import { Queryable } from '@pnp/queryable';
/**
* Замер времени ЭТАПОВ загрузки — «на что именно ушло ожидание», а не просто
* «страница долго грузится».
* Замер загрузки: «на что именно ушло ожидание», а не просто «страница долго
* грузится».
*
* Зачем отдельно от вкладки Network: браузер показывает запросы, но не
* логические этапы. Из списка URL не видно, что десяток одинаковых
* `.../rootfolder` — это резолв адресов списков согласования по партициям, а
* два одинаковых Search-запроса подряд — это один и тот же индекс, собранный
* дважды (счётчиками меню и самой таблицей). Метки дают этот срез.
* Пишет ДВА среза сразу, и они дополняют друг друга:
* • ЭТАПЫ — логические шаги, размеченные вручную через traced()/perfScope().
* Из списка URL не видно, что десяток одинаковых `.../rootfolder` —
* это резолв адресов списков согласования по партициям.
* • ЗАПРОСЫ — КАЖДЫЙ HTTP-вызов PnPjs, сгруппированный по виду операции.
* Снимается автоматически (см. PerfObserver ниже, подключён в
* shared/pnp/pnpjs.ts), поэтому покрывает ВСЕ разделы портала —
* включая формы и панель заявки, где ручной разметки нет.
*
* Складывать эти два среза между собой нельзя: запросы лежат ВНУТРИ этапов,
* сумма получилась бы двойной. Поэтому и таблицы две, с отдельными итогами.
*
* Как читать: «ОЖИДАНИЕ» — сколько реально прошло от начала операции до конца,
* то есть ровно то, что чувствует пользователь. Сумма времён отдельных шагов
* всегда БОЛЬШЕ: шаги идут параллельно (Promise.all) и их времена накладываются.
* Поэтому большая сумма у шага сама по себе ещё ничего не значит — важно, лежит
* ли он на последовательной цепочке. Признак: сложил несколько шагов и получил
* примерно ожидание — значит они идут друг за другом, и сокращать надо их.
*
* Включение/выключение БЕЗ пересборки — из консоли браузера:
* window.rpPerf = true // включить
* window.rpPerf = false // выключить
* window.rpPerfLast // последняя сводка объектом (скопировать/отдать)
*
* Флаг ЗАПОМИНАЕТСЯ в localStorage: выставил один раз — работает и после
* перезагрузки страницы, и завтра. Разбор производительности обычно идёт
* несколькими заходами с F5 между ними, и переписывать флаг в консоль каждый
* раз — ровно та мелочь, из-за которой замером перестают пользоваться.
* перезагрузки. Разбор производительности идёт несколькими заходами с F5 между
* ними, и переписывать флаг каждый раз — ровно та мелочь, из-за которой замером
* перестают пользоваться. Сделано свойством-аксессором на window, а не функцией
* setPerf(): в консоли естественно написать `window.rpPerf = true`.
*
* Сделано через свойство-аксессор на window, а не через отдельную функцию
* setPerf(): в консоли естественно написать `window.rpPerf = true`, и это
* должно работать. Сеттер кладёт значение в localStorage, геттер отдаёт
* текущее — снаружи флаг выглядит обычным полем.
*
* По умолчанию выключено: предыдущая версия этого модуля (коммит 7bd540e)
* писала в консоль всегда, без флага, и её пришлось снимать целиком вместе со
* всеми обёртками. С флагом обёртки могут жить в коде постоянно — выключенный
* traced() не делает ничего, кроме вызова переданной функции.
* По умолчанию выключено: предыдущая версия модуля (коммит 7bd540e) писала в
* консоль всегда, без флага, и её пришлось снимать целиком вместе со всеми
* обёртками. С флагом обёртки живут в коде постоянно — выключенный traced() не
* делает ничего, кроме вызова переданной функции.
*/
const DEFAULT_PERF: boolean = false;
@@ -36,29 +49,61 @@ const PREFIX = '[Перф]';
// его можно было найти и снять, не зная про этот модуль.
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;
}
const stats = new Map<string, IStat>();
/** Накопленное по одной операции за ВСЕ её прогоны — база для среднего. */
interface IRunHistory {
runs: number;
wallTotalMs: number;
stages: Map<string, IStat>;
requests: Map<string, IStat>;
}
// Текущий (ещё не напечатанный) прогон.
const stages = new Map<string, IStat>();
const requests = new Map<string, IStat>();
// История по операциям — живёт до перезагрузки страницы или window.rpPerfReset().
const history = new Map<string, IRunHistory>();
// Глубина открытых perfScope. Сводка печатается, когда закрылась ПОСЛЕДНЯЯ
// внешняя операция: этапы почти всегда идут параллельно (Promise.all), и
// печатать таблицу на каждом вложенном завершении значило бы печатать её
// десятками кусков. Если две верхнеуровневые операции наложились по времени
// (типичный случай: счётчики меню и загрузка таблицы стартуют вместе), их
// метки попадут в одну таблицу — это и нужно, там как раз видны дубли.
// внешняя операция: шаги почти всегда идут параллельно, и печатать таблицу на
// каждом вложенном завершении значило бы печатать её десятками кусков. Если две
// верхнеуровневые операции наложились (типичный случай: счётчики меню и загрузка
// таблицы стартуют вместе), их метки попадут в одну таблицу — это и нужно, там
// как раз видны дубли.
let openScopes = 0;
let scopeStart = 0;
let scopeLabels: string[] = [];
// localStorage может быть недоступен (приватный режим, политика браузера,
// iframe с ограничениями) — отладочный флаг не повод падать, поэтому обе
// операции обёрнуты и молча откатываются к значению в памяти.
// Границы текущего окна накопления — для «ОЖИДАНИЯ». Начало ставит открытие
// 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;
@@ -82,19 +127,13 @@ function perfEnabled(): boolean {
return enabled;
}
/**
* Вешает window.rpPerf как свойство с геттером и сеттером.
*
* Вызывается один раз при загрузке модуля. Значение, которое кто-то успел
* присвоить ДО этого (например, в снипете, выполненном раньше), не теряем —
* подхватываем и запоминаем.
*/
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', {
@@ -111,27 +150,49 @@ function installFlag(): void {
enabled = preset;
writeStoredFlag(preset);
} else if (enabled) {
// Иначе легко забыть, что флаг остался включённым с прошлого раза, и
// потом гадать, откуда в консоли таблицы.
// Иначе легко забыть, что флаг остался включённым с прошлого раза, и потом
// гадать, откуда в консоли таблицы.
console.log(`${PREFIX} замер включён (запомнен ранее). Выключить: window.rpPerf = false`);
}
}
installFlag();
function record(label: string, ms: number): void {
const stat = stats.get(label) ?? { calls: 0, totalMs: 0, maxMs: 0 };
// ---------------------------------------------------------------------------
// Накопление
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);
stats.set(label, stat);
into.set(label, stat);
scheduleIdleFlush();
}
// Разделы без ручной разметки (панель заявки, формы) сводку сами не закрывают —
// закрываем по тишине. Пока открыт perfScope, решает он.
function scheduleIdleFlush(): void {
if (idleTimer !== undefined) window.clearTimeout(idleTimer);
idleTimer = window.setTimeout(() => {
idleTimer = undefined;
if (openScopes === 0) print();
}, IDLE_FLUSH_MS);
}
// ---------------------------------------------------------------------------
// Разметка этапов
/**
* Обернуть один этап замером. Метку делай осмысленной и повторяемой: одинаковые
* этапы разных партиций должны попадать в ОДНУ строку сводки (число вызовов
* важнее, чем какая именно партиция), поэтому в метку не надо подставлять
* listId — только имя этапа и, при необходимости, тип заявки.
* listId — только имя этапа.
*/
export async function traced<T>(label: string, fn: () => Promise<T>): Promise<T> {
if (!perfEnabled()) return fn();
@@ -140,26 +201,20 @@ export async function traced<T>(label: string, fn: () => Promise<T>): Promise<T>
try {
return await fn();
} finally {
record(label, performance.now() - start);
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) {
stats.clear();
scopeStart = performance.now();
scopeLabels = [];
reset();
windowStart = performance.now();
}
openScopes += 1;
scopeLabels.push(label);
@@ -168,29 +223,216 @@ export async function perfScope<T>(label: string, fn: () => Promise<T>): Promise
return await fn();
} finally {
openScopes -= 1;
if (openScopes === 0) print(performance.now() - scopeStart);
if (openScopes === 0) print();
}
}
function print(wallMs: number): void {
if (stats.size === 0) return;
// ---------------------------------------------------------------------------
// Автоматический учёт КАЖДОГО запроса PnPjs
const rows = Array.from(stats.entries())
.map(([label, s]) => ({
'этап': label,
'вызовов': s.calls,
'сумма, мс': Math.round(s.totalMs),
'макс, мс': Math.round(s.maxMs)
}))
.sort((a, b) => b['сумма, мс'] - a['сумма, мс']);
// Вид операции по 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;
}
const total = rows.reduce((acc, r) => acc + r['сумма, мс'], 0);
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 mergeInto(target: Map<string, IStat>, source: Map<string, IStat>): void {
source.forEach((s, label) => {
const t = target.get(label) ?? { calls: 0, totalMs: 0, maxMs: 0 };
t.calls += s.calls;
t.totalMs += s.totalMs;
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(), и её зовут тогда, когда строка показала, что смотреть
* есть на что.
*
* Среднее в строке важнее текущего значения: одиночный сетевой замер шумит
* настолько, что по нему нельзя сказать, стало лучше или просто повезло.
*/
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) ?? {
runs: 0,
wallTotalMs: 0,
stages: new Map<string, IStat>(),
requests: new Map<string, IStat>()
};
hist.runs += 1;
hist.wallTotalMs += wallMs;
mergeInto(hist.stages, stages);
mergeInto(hist.requests, requests);
history.set(key, hist);
// Дольше всего — по этапам, если разметка есть; иначе по видам запросов
// (разделы без ручной разметки: панель заявки, формы).
const top = heaviest(stages.size > 0 ? stages : requests, TOP_IN_LINE);
console.log(
`${PREFIX} ${scopeLabels.join(' + ')}: стена ${Math.round(wallMs)} мс, сумма по этапам ${total} мс`
`${PREFIX} ${key} | ожидание ${Math.round(wallMs)} мс` +
` (сред. ${Math.round(hist.wallTotalMs / hist.runs)} за ${hist.runs})` +
` | запросов ${totalCalls(requests)}` +
(top ? ` | дольше всего: ${top}` : '')
);
console.table(rows);
stats.clear();
scopeLabels = [];
reset();
}
/** Строки полной раскладки по одной операции — средние за все её прогоны. */
function detailLines(key: string, hist: IRunHistory): string[] {
const lines = [`${PREFIX} ${key} - прогонов ${hist.runs}, ожидание в среднем ${Math.round(hist.wallTotalMs / hist.runs)} мс`];
const dump = (name: string, source: Map<string, IStat>): void => {
if (source.size === 0) return;
lines.push(` ${name} (в среднем за прогон)`);
Array.from(source.entries())
.sort((a, b) => b[1].totalMs - a[1].totalMs)
.forEach(([label, s]) => {
lines.push(
` ${Math.round(s.totalMs / hist.runs)} мс, вызовов ${(s.calls / hist.runs).toFixed(1)}, макс ${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;
};
// Старые прогоны тянут среднее назад, и «стало быстрее» проявится в нём
// только через несколько заходов — перед сравнением «до/после» серию надо
// обнулять.
w.rpPerfReset = (): void => {
history.clear();
reset();
console.log(`${PREFIX} история замеров очищена`);
};
}
installDetailApi();