From bda316b4dbe61eac877b25e8ea8d9d0ad7350c68 Mon Sep 17 00:00:00 2001 From: Michael Zabka Date: Mon, 7 Feb 2022 17:38:01 +0000 Subject: [PATCH 1/4] Add profiler with threshold of sync operations which detects sync cpu leaks and warn with stack trace about them --- src/ISaga.ts | 3 +++ src/combineSagas.ts | 18 ++++++++++++---- src/createModelSaga.ts | 49 ++++++++++++++++++++++++++++++++++++------ src/profiler.ts | 41 +++++++++++++++++++++++++++++++++++ 4 files changed, 100 insertions(+), 11 deletions(-) create mode 100644 src/profiler.ts diff --git a/src/ISaga.ts b/src/ISaga.ts index 2451a1a..93d1167 100644 --- a/src/ISaga.ts +++ b/src/ISaga.ts @@ -1,9 +1,12 @@ import { Action } from 'redux'; +import { ISagasMapObject } from './combineSagas'; import IUpdaterYield from './IUpdaterYield'; interface ISaga { reducer(model: TModel, action: Action): TModel; updater(model: TModel, action: Action): Iterator | AsyncIterator; + /** @protected only for internal usage when profiling */ + __combinedSagas?: ISagasMapObject; } export default ISaga; diff --git a/src/combineSagas.ts b/src/combineSagas.ts index 58cd35b..5a6a373 100644 --- a/src/combineSagas.ts +++ b/src/combineSagas.ts @@ -4,6 +4,7 @@ import ISaga from './ISaga'; import { Action } from 'redux'; import IUpdaterYield from './IUpdaterYield'; import { createDeferred, IDeferred } from './Promise/deferred'; +import { IUpdaterContext } from './createModelSaga'; export interface ISagasMapObject { [key: string]: ISaga; @@ -25,7 +26,8 @@ export default function combineSagas( }, {} )); - const updater = function (model: TModel, action: Action) { + const updater = function (this: IUpdaterContext, model: TModel, action: Action) { + const updaterContext = this; let nextDeferred: IDeferred | undefined = undefined; let done = false; @@ -76,6 +78,7 @@ export default function combineSagas( const iterator = saga.updater(model[key], action); let nextResult; do { + updaterContext.currentSaga = saga; let item: IteratorResult = await iterator.next(nextResult); if (item.done) { break; @@ -84,7 +87,7 @@ export default function combineSagas( } while (true); }; - Promise.allSettled(sagaKeys.map(async (sagaKey: string) => { + const iterateFns = sagaKeys.map((sagaKey: string) => async () => { const generator = invoke(sagaKey); let nextResult; try { @@ -100,13 +103,20 @@ export default function combineSagas( errYield(error); throw error; } - })) - .finally(() => doneYield()); + }); + + // If profiling, the synchronous processing is required to see better stack trace + const updatersPromise = updaterContext.profiler + ? iterateFns.reduce((allPromise: Promise, fn: () => Promise) => allPromise.finally(fn), Promise.resolve()) + : Promise.allSettled(iterateFns.map((fn: () => Promise) => fn())); + + updatersPromise.finally(() => doneYield()); return combinedIterator; }; return { reducer, updater, + __combinedSagas: sagas, }; } diff --git a/src/createModelSaga.ts b/src/createModelSaga.ts index 7451926..71a5a95 100644 --- a/src/createModelSaga.ts +++ b/src/createModelSaga.ts @@ -5,16 +5,36 @@ import IUpdaterYield from './IUpdaterYield'; import ObservableSubscribed from './ObservableSubscribed'; import ObservableYield from './ObservableYield'; import ActionYield from './ActionYield'; +import { startProfiler, IProfilerOptions, IProfiler } from './profiler'; +import { ISagasMapObject } from './combineSagas'; + +export interface IUpdaterContext { + currentSaga: ISaga | null; + combinedSagas: ISagasMapObject | null; + profiler: IProfiler | null; +} async function update( subscriptions: Subscription[], iterator: Iterator | AsyncIterator, dispatch: Dispatch, - sourceAction: Action + sourceAction: Action, + updaterContext: IUpdaterContext, ) { let nextResult: IUpdaterYield | undefined; do { let item: IteratorResult = await iterator.next(nextResult); + const lastTimeViolation = updaterContext.profiler?.popLastTimeViolation(); + if (lastTimeViolation) { + const combinedSagaNames = Object.keys(updaterContext.combinedSagas ?? {}); + const combinedSagas = Object.values(updaterContext.combinedSagas ?? {}); + const index = updaterContext.currentSaga && combinedSagas.indexOf(updaterContext.currentSaga); + console.warn( + `The threshold of profiler has been reached: ${lastTimeViolation} ms`, + index !== null ? combinedSagaNames[index] : 'unknown saga', + sourceAction, + ); + } nextResult = undefined; if (item.done) { break; @@ -22,7 +42,7 @@ async function update( if (isPromiseIteration(item.value)) { const promiseResult: IUpdaterYield = await item.value; if (isObservableIteration(promiseResult)) { - await handleObservable(dispatch, promiseResult.observable, subscriptions, sourceAction); + await handleObservable(dispatch, promiseResult.observable, subscriptions, sourceAction, updaterContext); } else if (isActionIteration(promiseResult)) { await handleAction(dispatch, promiseResult.action); @@ -31,7 +51,7 @@ async function update( } } else if (isObservableIteration(item.value)) { - await handleObservable(dispatch, item.value.observable, subscriptions, sourceAction); + await handleObservable(dispatch, item.value.observable, subscriptions, sourceAction, updaterContext); } else if (isActionIteration(item.value)) { await handleAction(dispatch, item.value.action); @@ -58,9 +78,10 @@ async function handleObservable( observable: Observable | AsyncIterator, Error>, subscriptions: Subscription[], sourceAction: Action, + updaterContext: IUpdaterContext, ) { const subscription = observable.subscribe(function (observableIterator: Iterator | AsyncIterator) { - update(subscriptions, observableIterator, dispatch, sourceAction); + update(subscriptions, observableIterator, dispatch, sourceAction, updaterContext); }); subscriptions.push(subscription); const promiseObservableSubscribed = dispatch({ @@ -81,15 +102,28 @@ async function handleAction(dispatch: Dispatch, action: Action) { } } -export default function createModelSaga(saga: ISaga) { +export interface IOptions { + profiler?: IProfilerOptions; +} + +export default function createModelSaga(saga: ISaga, options: IOptions = {}) { + let profiler: IProfiler | null = null; + if (options.profiler) { + profiler = startProfiler(options.profiler); + } + const updaterContext: IUpdaterContext = { + currentSaga: null, + profiler, + combinedSagas: saga.__combinedSagas ?? null, + }; const sagaStore = createStore(saga.reducer); const subscriptions: Subscription[] = []; const middleware: Middleware = (store: Store) => (nextDispatch: Dispatch) => (action: Action) => { const result = nextDispatch(action); sagaStore.dispatch(action); const model = sagaStore.getState(); - const iterator = saga.updater(model, action); - const promise = update(subscriptions, iterator, store.dispatch, action); + const iterator = saga.updater.call(updaterContext, model, action); + const promise = update(subscriptions, iterator, store.dispatch, action, updaterContext); Object.defineProperty(result, '__promise', { enumerable: false, configurable: false, @@ -99,6 +133,7 @@ export default function createModelSaga(saga: ISaga) { return result as any; }; const destroy = () => { + profiler?.stop(); subscriptions.forEach((subscription: Subscription) => subscription.unsubscribe()); }; return { diff --git a/src/profiler.ts b/src/profiler.ts new file mode 100644 index 0000000..7a903ba --- /dev/null +++ b/src/profiler.ts @@ -0,0 +1,41 @@ + +export interface IProfilerOptions { + thresholdMs: number; +} + +export type IProfiler = ReturnType; + +export function startProfiler(options: IProfilerOptions) { + let lastTimeViolationMs: number | null = null; + let stopped = false; + + const profiler = { + popLastTimeViolation() { + const timeViolationMs = lastTimeViolationMs; + lastTimeViolationMs = null; + return timeViolationMs; + }, + stop() { + stopped = true; + }, + }; + + let lastTickTimestamp = new Date().valueOf(); + + function profileNextTick() { + setImmediate(() => { + const tickTimeMs = new Date().valueOf() - lastTickTimestamp; + lastTickTimestamp = new Date().valueOf(); + if (tickTimeMs >= options.thresholdMs) { + lastTimeViolationMs = tickTimeMs; + } + if (!stopped) { + profileNextTick(); + } + }); + } + + profileNextTick(); + + return profiler; +} From 261969898430179b77b39443aa9cb908616ed7c9 Mon Sep 17 00:00:00 2001 From: Michael Zabka Date: Wed, 9 Feb 2022 17:08:35 +0000 Subject: [PATCH 2/4] Upgrade typescript to 4.5.5 --- package-lock.json | 6 +++--- package.json | 2 +- src/ISaga.ts | 4 ++-- src/combineSagas.ts | 8 ++++---- src/createModelSaga.ts | 4 ++-- tests/unit/createModelSaga.spec.ts | 6 +++--- tests/unit/sumModelMock.ts | 2 +- 7 files changed, 16 insertions(+), 16 deletions(-) diff --git a/package-lock.json b/package-lock.json index afa670f..d99492e 100644 --- a/package-lock.json +++ b/package-lock.json @@ -5458,9 +5458,9 @@ "dev": true }, "typescript": { - "version": "3.9.5", - "resolved": "https://registry.npmjs.org/typescript/-/typescript-3.9.5.tgz", - "integrity": "sha512-hSAifV3k+i6lEoCJ2k6R2Z/rp/H3+8sdmcn5NrS3/3kE7+RyZXm9aqvxWqjEXHAd8b0pShatpcdMTvEdvAJltQ==", + "version": "4.5.5", + "resolved": "https://registry.npmjs.org/typescript/-/typescript-4.5.5.tgz", + "integrity": "sha512-TCTIul70LyWe6IJWT8QSYeA54WQe8EjQFU4wY52Fasj5UKx88LNYKCgBEHcOMOrFF1rKGbD8v/xcNWVUq9SymA==", "dev": true }, "unicode-canonical-property-names-ecmascript": { diff --git a/package.json b/package.json index 7e8abc2..f783f6f 100644 --- a/package.json +++ b/package.json @@ -58,7 +58,7 @@ "should": "13.2.3", "ts-node": "8.1.0", "tslint": "5.16.0", - "typescript": "3.9.5", + "typescript": "4.5.5", "webpack": "4.30.0", "webpack-cli": "3.3.1", "zen-observable": "0.8.14" diff --git a/src/ISaga.ts b/src/ISaga.ts index 93d1167..ad537ea 100644 --- a/src/ISaga.ts +++ b/src/ISaga.ts @@ -3,9 +3,9 @@ import { Action } from 'redux'; import { ISagasMapObject } from './combineSagas'; import IUpdaterYield from './IUpdaterYield'; -interface ISaga { +interface ISaga { reducer(model: TModel, action: Action): TModel; - updater(model: TModel, action: Action): Iterator | AsyncIterator; + updater(model: TModel, action: Action): Iterator | AsyncIterator; /** @protected only for internal usage when profiling */ __combinedSagas?: ISagasMapObject; } diff --git a/src/combineSagas.ts b/src/combineSagas.ts index 5a6a373..15e026f 100644 --- a/src/combineSagas.ts +++ b/src/combineSagas.ts @@ -7,7 +7,7 @@ import { createDeferred, IDeferred } from './Promise/deferred'; import { IUpdaterContext } from './createModelSaga'; export interface ISagasMapObject { - [key: string]: ISaga; + [key: string]: ISaga; } export interface ICombinedModel { @@ -16,7 +16,7 @@ export interface ICombinedModel { export default function combineSagas( sagas: ISagasMapObject -): ISaga { +): ISaga { const sagaKeys = Object.keys(sagas); const reducer = combineReducers(sagaKeys.reduce( (reducers: ReducersMapObject, key: string) => { @@ -76,7 +76,7 @@ export default function combineSagas( const invoke = async function* (key: string) { const saga = sagas[key]; const iterator = saga.updater(model[key], action); - let nextResult; + let nextResult: undefined; do { updaterContext.currentSaga = saga; let item: IteratorResult = await iterator.next(nextResult); @@ -89,7 +89,7 @@ export default function combineSagas( const iterateFns = sagaKeys.map((sagaKey: string) => async () => { const generator = invoke(sagaKey); - let nextResult; + let nextResult: any; try { do { let item: IteratorResult = await generator.next(nextResult); diff --git a/src/createModelSaga.ts b/src/createModelSaga.ts index 71a5a95..ed656c4 100644 --- a/src/createModelSaga.ts +++ b/src/createModelSaga.ts @@ -9,7 +9,7 @@ import { startProfiler, IProfilerOptions, IProfiler } from './profiler'; import { ISagasMapObject } from './combineSagas'; export interface IUpdaterContext { - currentSaga: ISaga | null; + currentSaga: ISaga | null; combinedSagas: ISagasMapObject | null; profiler: IProfiler | null; } @@ -106,7 +106,7 @@ export interface IOptions { profiler?: IProfilerOptions; } -export default function createModelSaga(saga: ISaga, options: IOptions = {}) { +export default function createModelSaga(saga: ISaga, options: IOptions = {}) { let profiler: IProfiler | null = null; if (options.profiler) { profiler = startProfiler(options.profiler); diff --git a/tests/unit/createModelSaga.spec.ts b/tests/unit/createModelSaga.spec.ts index f89d098..8eac11f 100644 --- a/tests/unit/createModelSaga.spec.ts +++ b/tests/unit/createModelSaga.spec.ts @@ -77,13 +77,13 @@ describe('Application.craeteModelSaga', function () { autoAdding113, ]); autoAdding113.__doAdd!(); - await new Promise((resolve: () => void) => setTimeout(resolve, 2)); + await new Promise((resolve: () => void) => setTimeout(resolve, 2)); should.deepEqual(removeInternalActions(assertations.reducedActions), [ autoAdding113, added, ]); autoAdding113.__doAdd!(); - await new Promise((resolve: () => void) => setTimeout(resolve, 2)); + await new Promise((resolve: () => void) => setTimeout(resolve, 2)); should.deepEqual(removeInternalActions(assertations.reducedActions), [ autoAdding113, added, @@ -108,7 +108,7 @@ describe('Application.craeteModelSaga', function () { autoAdding113, ]); autoAdding113.__doAdd!(); - await new Promise((resolve: () => void) => setTimeout(resolve, 2)); + await new Promise((resolve: () => void) => setTimeout(resolve, 2)); should.deepEqual(removeInternalActions(assertations.reducedActions), [ autoAdding113, added, diff --git a/tests/unit/sumModelMock.ts b/tests/unit/sumModelMock.ts index b301fb3..3105a1d 100644 --- a/tests/unit/sumModelMock.ts +++ b/tests/unit/sumModelMock.ts @@ -88,7 +88,7 @@ export const sumSaga = { assertations.updatedModels!.push(model); switch (action.type) { case 'Add': - const uid = yield addAmount(action.amount); + const uid: string = yield addAmount(action.amount); yield put({ type: 'Added', uid, From c1c018926d69dd519dbe7623cfc9f40426356687 Mon Sep 17 00:00:00 2001 From: Michael Zabka Date: Wed, 9 Feb 2022 17:14:29 +0000 Subject: [PATCH 3/4] Add garbage collection of closed subscriptions to prevent memory leaks when app is running too long --- src/createModelSaga.ts | 20 ++++++++++++++++++++ tests/unit/combineSagas.spec.ts | 1 + tests/unit/createModelSaga.spec.ts | 4 ++++ types/lib.es2017.observable/index.d.ts | 4 ++-- 4 files changed, 27 insertions(+), 2 deletions(-) diff --git a/src/createModelSaga.ts b/src/createModelSaga.ts index ed656c4..7be06ee 100644 --- a/src/createModelSaga.ts +++ b/src/createModelSaga.ts @@ -102,6 +102,24 @@ async function handleAction(dispatch: Dispatch, action: Action) { } } +function startGarbageCollector(subscriptions: Subscription[]) { + const intervalHandler = setInterval( + () => { + for (let index in subscriptions) { + if (subscriptions[index].closed) { + subscriptions.splice(parseInt(index), 1); + } + } + }, + 10e3, + ); + return { + stop() { + clearInterval(intervalHandler); + }, + }; +} + export interface IOptions { profiler?: IProfilerOptions; } @@ -132,8 +150,10 @@ export default function createModelSaga(saga: ISaga { profiler?.stop(); + garbageCollector.stop(); subscriptions.forEach((subscription: Subscription) => subscription.unsubscribe()); }; return { diff --git a/tests/unit/combineSagas.spec.ts b/tests/unit/combineSagas.spec.ts index c560c4e..1c8fc57 100644 --- a/tests/unit/combineSagas.spec.ts +++ b/tests/unit/combineSagas.spec.ts @@ -132,5 +132,6 @@ describe('Application.combineSaga', function () { 113, ]); should.strictEqual(shownWarningsCount, 1); + modelSaga.destroy(); }); }); diff --git a/tests/unit/createModelSaga.spec.ts b/tests/unit/createModelSaga.spec.ts index 8eac11f..7f57b67 100644 --- a/tests/unit/createModelSaga.spec.ts +++ b/tests/unit/createModelSaga.spec.ts @@ -58,6 +58,7 @@ describe('Application.craeteModelSaga', function () { should.deepEqual(assertations.addedAmounts, [ 113, ]); + modelSaga.destroy(); }); it('should reduce action & then apply async updater with yielded observable', async function () { @@ -89,6 +90,7 @@ describe('Application.craeteModelSaga', function () { added, added, ]); + modelSaga.destroy(); }); it('should unsubscribe all yielded observables after destroy', async function () { @@ -129,6 +131,7 @@ describe('Application.craeteModelSaga', function () { const observableSubscribed = assertations.reducedActions! .find((action: Action) => action.type === ObservableSubscribed); should.notStrictEqual(observableSubscribed, undefined); + modelSaga.destroy(); }); it('should work even with async iterators as updater', async function () { @@ -163,5 +166,6 @@ describe('Application.craeteModelSaga', function () { should.deepEqual(assertations.addedAmounts, [ 113, ]); + modelSaga.destroy(); }); }); diff --git a/types/lib.es2017.observable/index.d.ts b/types/lib.es2017.observable/index.d.ts index f298d6b..645f44b 100644 --- a/types/lib.es2017.observable/index.d.ts +++ b/types/lib.es2017.observable/index.d.ts @@ -50,7 +50,7 @@ interface Subscription { unsubscribe(): void; // A boolean value indicating whether the subscription is closed - closed(): boolean; + get closed(): boolean; } interface SubscriberFunction { @@ -83,5 +83,5 @@ interface SubscriptionObserver { complete(): void; // A boolean value indicating whether the subscription is closed - closed(): boolean; + get closed(): boolean; } From 390f02abea4d1685ce923ced016641835ba4a31a Mon Sep 17 00:00:00 2001 From: Michael Zabka Date: Thu, 10 Feb 2022 19:58:17 +0000 Subject: [PATCH 4/4] Add more detail profiler info --- src/IUpdaterYield.ts | 3 ++ src/Timer/wait.ts | 4 ++ src/combineSagas.ts | 6 ++- src/createModelSaga.ts | 48 ++++++++----------- src/profiler.ts | 63 ++++++++++++++++++++---- tests/integration/profiler.spec.ts | 77 ++++++++++++++++++++++++++++++ 6 files changed, 163 insertions(+), 38 deletions(-) create mode 100644 src/Timer/wait.ts create mode 100644 tests/integration/profiler.spec.ts diff --git a/src/IUpdaterYield.ts b/src/IUpdaterYield.ts index 8e37194..667bdf8 100644 --- a/src/IUpdaterYield.ts +++ b/src/IUpdaterYield.ts @@ -14,3 +14,6 @@ type IUpdaterYield = Promise | ObservableYield | AsyncIterator, Error>> | ActionYield; export default IUpdaterYield; + +export type AnyIterator = Iterator + | AsyncIterator; diff --git a/src/Timer/wait.ts b/src/Timer/wait.ts new file mode 100644 index 0000000..8840e5e --- /dev/null +++ b/src/Timer/wait.ts @@ -0,0 +1,4 @@ + +export function wait(timeoutMs: number) { + return new Promise((resolve: () => void) => setTimeout(resolve, timeoutMs)); +} diff --git a/src/combineSagas.ts b/src/combineSagas.ts index 15e026f..9d5f1f3 100644 --- a/src/combineSagas.ts +++ b/src/combineSagas.ts @@ -75,11 +75,13 @@ export default function combineSagas( const invoke = async function* (key: string) { const saga = sagas[key]; - const iterator = saga.updater(model[key], action); + const iterator = saga.updater.call(updaterContext, model[key], action); let nextResult: undefined; do { - updaterContext.currentSaga = saga; + updaterContext.currentSagas.push(saga); let item: IteratorResult = await iterator.next(nextResult); + updaterContext.lastSagas = [...updaterContext.currentSagas]; + updaterContext.currentSagas.splice(updaterContext.currentSagas.indexOf(saga), 1); if (item.done) { break; } diff --git a/src/createModelSaga.ts b/src/createModelSaga.ts index 7be06ee..0d69337 100644 --- a/src/createModelSaga.ts +++ b/src/createModelSaga.ts @@ -1,7 +1,7 @@ import { createStore, Store, Middleware, Dispatch, Action, AnyAction } from 'redux'; import IPromiseAction from './IPromiseAction'; import ISaga from './ISaga'; -import IUpdaterYield from './IUpdaterYield'; +import IUpdaterYield, { AnyIterator } from './IUpdaterYield'; import ObservableSubscribed from './ObservableSubscribed'; import ObservableYield from './ObservableYield'; import ActionYield from './ActionYield'; @@ -9,32 +9,21 @@ import { startProfiler, IProfilerOptions, IProfiler } from './profiler'; import { ISagasMapObject } from './combineSagas'; export interface IUpdaterContext { - currentSaga: ISaga | null; + currentSagas: ISaga[]; + lastSagas: ISaga[]; combinedSagas: ISagasMapObject | null; profiler: IProfiler | null; } async function update( subscriptions: Subscription[], - iterator: Iterator | AsyncIterator, + iterator: AnyIterator, dispatch: Dispatch, sourceAction: Action, - updaterContext: IUpdaterContext, ) { let nextResult: IUpdaterYield | undefined; do { let item: IteratorResult = await iterator.next(nextResult); - const lastTimeViolation = updaterContext.profiler?.popLastTimeViolation(); - if (lastTimeViolation) { - const combinedSagaNames = Object.keys(updaterContext.combinedSagas ?? {}); - const combinedSagas = Object.values(updaterContext.combinedSagas ?? {}); - const index = updaterContext.currentSaga && combinedSagas.indexOf(updaterContext.currentSaga); - console.warn( - `The threshold of profiler has been reached: ${lastTimeViolation} ms`, - index !== null ? combinedSagaNames[index] : 'unknown saga', - sourceAction, - ); - } nextResult = undefined; if (item.done) { break; @@ -42,7 +31,7 @@ async function update( if (isPromiseIteration(item.value)) { const promiseResult: IUpdaterYield = await item.value; if (isObservableIteration(promiseResult)) { - await handleObservable(dispatch, promiseResult.observable, subscriptions, sourceAction, updaterContext); + await handleObservable(dispatch, promiseResult.observable, subscriptions, sourceAction); } else if (isActionIteration(promiseResult)) { await handleAction(dispatch, promiseResult.action); @@ -51,7 +40,7 @@ async function update( } } else if (isObservableIteration(item.value)) { - await handleObservable(dispatch, item.value.observable, subscriptions, sourceAction, updaterContext); + await handleObservable(dispatch, item.value.observable, subscriptions, sourceAction); } else if (isActionIteration(item.value)) { await handleAction(dispatch, item.value.action); @@ -78,10 +67,9 @@ async function handleObservable( observable: Observable | AsyncIterator, Error>, subscriptions: Subscription[], sourceAction: Action, - updaterContext: IUpdaterContext, ) { const subscription = observable.subscribe(function (observableIterator: Iterator | AsyncIterator) { - update(subscriptions, observableIterator, dispatch, sourceAction, updaterContext); + update(subscriptions, observableIterator, dispatch, sourceAction); }); subscriptions.push(subscription); const promiseObservableSubscribed = dispatch({ @@ -125,23 +113,27 @@ export interface IOptions { } export default function createModelSaga(saga: ISaga, options: IOptions = {}) { - let profiler: IProfiler | null = null; - if (options.profiler) { - profiler = startProfiler(options.profiler); - } const updaterContext: IUpdaterContext = { - currentSaga: null, - profiler, + currentSagas: [], + lastSagas: [], + profiler: null, combinedSagas: saga.__combinedSagas ?? null, }; + if (options.profiler) { + updaterContext.profiler = startProfiler(options.profiler, updaterContext); + } const sagaStore = createStore(saga.reducer); const subscriptions: Subscription[] = []; const middleware: Middleware = (store: Store) => (nextDispatch: Dispatch) => (action: Action) => { const result = nextDispatch(action); sagaStore.dispatch(action); const model = sagaStore.getState(); - const iterator = saga.updater.call(updaterContext, model, action); - const promise = update(subscriptions, iterator, store.dispatch, action, updaterContext); + const iterator: AnyIterator = saga.updater.call(updaterContext, model, action); + + const promise = update(subscriptions, iterator, store.dispatch, action); + if (updaterContext.profiler) { + promise.finally(() => updaterContext.profiler?.handleProfilerViolation(action)); + } Object.defineProperty(result, '__promise', { enumerable: false, configurable: false, @@ -152,7 +144,7 @@ export default function createModelSaga(saga: ISaga { - profiler?.stop(); + updaterContext.profiler?.stop(); garbageCollector.stop(); subscriptions.forEach((subscription: Subscription) => subscription.unsubscribe()); }; diff --git a/src/profiler.ts b/src/profiler.ts index 7a903ba..f2b65de 100644 --- a/src/profiler.ts +++ b/src/profiler.ts @@ -1,25 +1,68 @@ +import { Action } from "redux"; +import { ISaga } from "."; +import { IUpdaterContext } from "./createModelSaga"; + +const OriginalPromise = Promise; + +type OnWarning = (message: string, sagaNames: string[], action: Action) => void; export interface IProfilerOptions { thresholdMs: number; + onWarning?: OnWarning; } +type UnknownSaga = ISaga; + export type IProfiler = ReturnType; +export type IViolation = { + timeMs: number; + stack: string | null; + sagas: UnknownSaga[]; +}; -export function startProfiler(options: IProfilerOptions) { - let lastTimeViolationMs: number | null = null; +export function startProfiler(options: IProfilerOptions, updaterContext: IUpdaterContext) { + const onWarning: OnWarning = options.onWarning ?? console.warn.bind(console); + let lastViolation: IViolation | null = null; let stopped = false; const profiler = { - popLastTimeViolation() { - const timeViolationMs = lastTimeViolationMs; - lastTimeViolationMs = null; - return timeViolationMs; - }, stop() { + global.Promise = OriginalPromise; stopped = true; }, + async handleProfilerViolation(action: Action) { + if (lastViolation) { + const violation = lastViolation; + lastViolation = null; + const combinedSagaNames = Object.keys(updaterContext.combinedSagas ?? {}); + const combinedSagas = Object.values(updaterContext.combinedSagas ?? {}); + const indexes = combinedSagas.reduce( + (ixs: number[], currentSaga: UnknownSaga, ix: number) => violation.sagas.includes(currentSaga) ? [...ixs, ix] : ixs, + [], + ); + onWarning( + `The threshold of profiler has been reached: time=${violation.timeMs}ms, stack=\n${violation.stack}`, + indexes.map((index: number) => combinedSagaNames[index]) ?? [], + action, + ); + } + }, }; + class ProfiledPromise extends OriginalPromise { + constructor(executor: (resolve: (value: T | PromiseLike) => void, reject: (reason?: any) => void) => void) { + const error = new Error(`The threshold of profiler has been reached`); + super((resolve: (value: T | PromiseLike) => void, reject: (reason?: any) => void) => { + if (lastViolation) { + lastViolation.stack = `${error.stack ?? ''}\n${lastViolation.stack ?? ''}`; + lastViolation.sagas = [...lastViolation.sagas, ...updaterContext.lastSagas]; + } + return executor(resolve, reject); + }); + } + } + global.Promise = ProfiledPromise; + let lastTickTimestamp = new Date().valueOf(); function profileNextTick() { @@ -27,7 +70,11 @@ export function startProfiler(options: IProfilerOptions) { const tickTimeMs = new Date().valueOf() - lastTickTimestamp; lastTickTimestamp = new Date().valueOf(); if (tickTimeMs >= options.thresholdMs) { - lastTimeViolationMs = tickTimeMs; + lastViolation = { + timeMs: tickTimeMs, + stack: null, + sagas: [], + }; } if (!stopped) { profileNextTick(); diff --git a/tests/integration/profiler.spec.ts b/tests/integration/profiler.spec.ts new file mode 100644 index 0000000..94b77fb --- /dev/null +++ b/tests/integration/profiler.spec.ts @@ -0,0 +1,77 @@ +import * as should from 'should'; +import { Action, applyMiddleware, createStore } from "redux"; +import { combineSagas, createModelSaga, IPromiseAction } from "../../src"; +import { wait } from '../../src/Timer/wait'; + +describe('profiler', function () { + + const A1 = 'A1'; + type A1 = { type: typeof A1 }; + const A2 = 'A2'; + type A2 = { type: typeof A2 }; + + const saga1 = { + reducer: () => null, + updater: async function* (_model: null, action: A1) { + if (action.type === A1) { + await wait(10); + const startedAt = new Date().valueOf(); + while (new Date().valueOf() - startedAt < 200) { /* stuck thread */ } + await wait(10); + } + }, + }; + + const saga2 = { + reducer: () => null, + updater: async function* (_model: null, action: A2) { + if (action.type === A2) { + await wait(200); + } + }, + }; + + let warnings: { message: string; sagaNames: string[]; action: Action }[]; + const onWarning = (message: string, sagaNames: string[], action: Action) => { + warnings.push({ message, sagaNames, action }); + }; + + beforeEach(function () { + warnings = []; + }); + + it('should log when some saga takes too much time sync thread', async function () { + const sagas = combineSagas({ + saga1, + }); + const modelSaga = createModelSaga(sagas, { profiler: { thresholdMs: 100, onWarning } }); + + const store = createStore(() => null, applyMiddleware(modelSaga.middleware)); + const action = store.dispatch({ type: A1 }) as IPromiseAction; + await action.__promise; + should(warnings).lengthOf(1); + should(warnings[0].sagaNames).eql(['saga1']); + should(warnings[0].action).eql({ type: A1 }); + + modelSaga.destroy(); + }); + + it('should log correct saga and action when more combined sagas', async function () { + const sagas = combineSagas({ + saga1, + saga2, + }); + const modelSaga = createModelSaga(sagas, { profiler: { thresholdMs: 100, onWarning } }); + + const store = createStore(() => null, applyMiddleware(modelSaga.middleware)); + const action1 = store.dispatch({ type: A1 }) as IPromiseAction; + const action2 = store.dispatch({ type: A2 }) as IPromiseAction; + await action1.__promise; + await action2.__promise; + should(warnings).lengthOf(1); + should(warnings[0].sagaNames).eql(['saga1', 'saga2']); + should(warnings[0].action).eql({ type: A1 }); + + modelSaga.destroy(); + }); +});