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; requests: Map; } // Текущий (ещё не напечатанный) прогон. const stages = new Map(); const requests = new Map(); // История по операциям — живёт до перезагрузки страницы или window.rpPerfReset(). const history = new Map(); // Глубина открытых 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, 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(label: string, fn: () => Promise): Promise { if (!perfEnabled()) return fn(); const start = performance.now(); try { return await fn(); } finally { record(stages, label, performance.now() - start); } } /** * Верхнеуровневая операция (открытие вкладки, счётчики меню). Когда она * завершается, печатается сводка по всему, что накопилось внутри. */ export async function perfScope(label: string, fn: () => Promise): Promise { 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 { 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, source: Map): 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, 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): 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(), requests: new Map() }; 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): 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((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();