diff --git a/src/store.ts b/src/store.ts index 043c93b..07bc24d 100644 --- a/src/store.ts +++ b/src/store.ts @@ -57,6 +57,8 @@ export class Store { private middlewares: Map, { placement: MiddlewarePlacement, settings?: any }> = new Map(); private _state: BehaviorSubject; private options: Partial; + private _markNames: Set = new Set(); + private _measureNames: Set = new Set(); private dispatchQueue: DispatchQueueItem[] = []; @@ -191,7 +193,7 @@ export class Store { throw new UnregisteredActionError(unregisteredAction.reducer); } - PLATFORM.performance.mark("dispatch-start"); + this.mark("dispatch-start"); const pipedActions = actions.map((a) => ({ type: this.actions.get(a.reducer)!.type, @@ -219,8 +221,8 @@ export class Store { ); if (beforeMiddleswaresResult === false) { - PLATFORM.performance.clearMarks(); - PLATFORM.performance.clearMeasures(); + this.clearMarks(); + this.clearMeasures(); return; } @@ -229,13 +231,13 @@ export class Store { for (const action of pipedActions) { result = await action.reducer(result, ...action.params); if (result === false) { - PLATFORM.performance.clearMarks(); - PLATFORM.performance.clearMeasures(); + this.clearMarks(); + this.clearMeasures(); return; } - PLATFORM.performance.mark("dispatch-after-reducer-" + action.type); + this.mark("dispatch-after-reducer-" + action.type); if (!result && typeof result !== "object") { throw new Error("The reducer has to return a new state"); @@ -249,8 +251,8 @@ export class Store { ); if (resultingState === false) { - PLATFORM.performance.clearMarks(); - PLATFORM.performance.clearMeasures(); + this.clearMarks(); + this.clearMeasures(); return; } @@ -262,16 +264,16 @@ export class Store { } this._state.next(resultingState); - PLATFORM.performance.mark("dispatch-end"); + this.mark("dispatch-end"); if (this.options.measurePerformance === PerformanceMeasurement.StartEnd) { - PLATFORM.performance.measure( + this.measure( "startEndDispatchDuration", "dispatch-start", "dispatch-end" ); - const measures = PLATFORM.performance.getEntriesByName("startEndDispatchDuration"); + const measures = PLATFORM.performance.getEntriesByName("startEndDispatchDuration", "measure"); this.logger[getLogType(this.options, "performanceLog", LogLevel.info)]( `Total duration ${measures[0].duration} of dispatched action ${callingAction.name}:`, measures @@ -285,8 +287,8 @@ export class Store { ); } - PLATFORM.performance.clearMarks(); - PLATFORM.performance.clearMeasures(); + this.clearMarks(); + this.clearMeasures(); this.updateDevToolsState({ type: callingAction.name, params: callingAction.params }, resultingState); } @@ -313,7 +315,7 @@ export class Store { return await prev; } finally { - PLATFORM.performance.mark(`dispatch-${placement}-${curr[0].name}`); + this.mark(`dispatch-${placement}-${curr[0].name}`); } }, state); } @@ -380,6 +382,28 @@ export class Store { private registerHistoryMethods() { this.registerAction("jump", jump as Reducer); } + + private mark(markName: string) { + this._markNames.add(markName); + PLATFORM.performance.mark(markName); + } + + private clearMarks() { + this._markNames.forEach((markName: string) => + PLATFORM.performance.clearMarks(markName)); + this._markNames.clear(); + } + + private measure(measureName: string, startMarkName: string, endMarkName: string) { + this._measureNames.add(measureName); + PLATFORM.performance.measure(measureName, startMarkName, endMarkName) + } + + private clearMeasures() { + this._measureNames.forEach((measureName: string) => + PLATFORM.performance.clearMeasures(measureName)); + this._measureNames.clear(); + } } export function dispatchify(action: Reducer | string) { diff --git a/test/unit/middleware.spec.ts b/test/unit/middleware.spec.ts index 9231fea..163fb4c 100644 --- a/test/unit/middleware.spec.ts +++ b/test/unit/middleware.spec.ts @@ -246,6 +246,38 @@ describe("middlewares", () => { done(); }); }); + + it("should log all dispatch durations", done => { + spyOn(PLATFORM.performance, "mark").and.callThrough(); + const store = createStoreWithState(initialState); + + const decreaseBefore = (currentState: TestState, originalState?: TestState) => { + const newState = Object.assign({}, currentState); + newState.counter = originalState!.counter; + + return newState; + } + store.registerMiddleware(decreaseBefore, MiddlewarePlacement.Before); + + const resetBefore = (currentState: TestState, originalState?: TestState) => { + expect(currentState.counter).toBe(0); + return originalState; + } + store.registerMiddleware(resetBefore, MiddlewarePlacement.Before); + + store.registerAction("IncrementAction", incrementAction); + store.dispatch(incrementAction); + + store.state.pipe( + skip(1), + take(1) + ).subscribe(() => { + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(2, "dispatch-before-decreaseBefore"); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(3, "dispatch-before-resetBefore"); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(4, "dispatch-after-reducer-IncrementAction"); + done(); + }); + }); }); describe("which are applied after the action dispatches", () => { @@ -317,6 +349,31 @@ describe("middlewares", () => { done(); }); }); + + it("should log all dispatch durations", done => { + spyOn(PLATFORM.performance, "mark").and.callThrough(); + const store = createStoreWithState(initialState); + + const decreaseAfter = (currentState: TestState, originalState: TestState | undefined) => { + const newState = Object.assign({}, currentState); + newState.counter = originalState!.counter; + + return newState; + } + store.registerMiddleware(decreaseAfter, MiddlewarePlacement.After); + + store.registerAction("IncrementAction", incrementAction); + store.dispatch(incrementAction); + + store.state.pipe( + skip(1), + take(1) + ).subscribe(() => { + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(2, "dispatch-after-reducer-IncrementAction"); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(3, "dispatch-after-decreaseAfter"); + done(); + }); + }); }); it("should handle throwing middlewares and maintain queue", done => { diff --git a/test/unit/store.spec.ts b/test/unit/store.spec.ts index 0518de0..f8134d9 100644 --- a/test/unit/store.spec.ts +++ b/test/unit/store.spec.ts @@ -1,4 +1,5 @@ import { skip } from "rxjs/operators"; +import { PLATFORM } from "aurelia-pal"; import { PerformanceMeasurement } from "../../src/store"; import { LogLevel } from "../../src/aurelia-store"; @@ -279,6 +280,13 @@ describe("store", () => { initialState, { measurePerformance: PerformanceMeasurement.StartEnd } ); + const expectedMeasures = [ + { duration: 1 }, + { duration: 2 } + ]; + spyOn(PLATFORM.performance, "mark").and.callThrough(); + spyOn(PLATFORM.performance, "measure").and.callThrough(); + spyOn(PLATFORM.performance, "getEntriesByName").and.returnValue(expectedMeasures); const loggerSpy = spyOn((store as any).logger, "info"); const actionA = (_: testState) => { @@ -290,7 +298,16 @@ describe("store", () => { store.registerAction("Action A", actionA); await store.dispatch(actionA); - expect(loggerSpy).toHaveBeenCalledWith(expect.any(String), expect.any(Array)); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(1, "dispatch-start"); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(2, "dispatch-after-reducer-Action A"); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(3, "dispatch-end"); + expect(PLATFORM.performance.measure).toHaveBeenCalledWith( + "startEndDispatchDuration", + "dispatch-start", + "dispatch-end" + ); + expect(PLATFORM.performance.getEntriesByName).toHaveBeenCalledWith("startEndDispatchDuration", "measure"); + expect(loggerSpy).toHaveBeenCalledWith("Total duration 1 of dispatched action Action A:", expectedMeasures); }); it("should log all dispatch durations if turned on via options", async () => { @@ -302,6 +319,14 @@ describe("store", () => { initialState, { measurePerformance: PerformanceMeasurement.All } ); + const expectedMarks = [ + { startTime: 1 }, + { startTime: 10 }, + { startTime: 100 }, + ]; + const expectedDuration = expectedMarks[2].startTime - expectedMarks[0].startTime; + spyOn(PLATFORM.performance, "mark").and.callThrough(); + spyOn(PLATFORM.performance, "getEntriesByType").and.returnValue(expectedMarks); const loggerSpy = spyOn((store as any).logger, "info"); const actionA = (_: testState) => { @@ -313,7 +338,79 @@ describe("store", () => { store.registerAction("Action A", actionA); await store.dispatch(actionA); - expect(loggerSpy).toHaveBeenCalledWith(expect.any(String), expect.any(Array)); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(1, "dispatch-start"); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(2, "dispatch-after-reducer-Action A"); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(3, "dispatch-end"); + expect(PLATFORM.performance.getEntriesByType).toHaveBeenCalledWith("mark"); + expect(loggerSpy).toHaveBeenCalledWith( + `Total duration ${expectedDuration} of dispatched action Action A:`, + expectedMarks + ); + }); + + it("should clear only store marks and measures if log start-end dispatch duration turned on via options", async () => { + const initialState: testState = { + foo: "bar" + }; + + const store = createStoreWithStateAndOptions( + initialState, + { measurePerformance: PerformanceMeasurement.StartEnd } + ); + PLATFORM.performance.mark("user mark 1"); + PLATFORM.performance.mark("user mark 2"); + PLATFORM.performance.measure("user measure", "user mark 1", "user mark 2"); + spyOn(PLATFORM.performance, "clearMarks").and.callThrough(); + spyOn(PLATFORM.performance, "clearMeasures").and.callThrough(); + + const actionA = (_: testState) => { + return new Promise((resolve) => { + setTimeout(() => resolve({ foo: "A" }), 1); + }); + }; + + store.registerAction("Action A", actionA); + await store.dispatch(actionA); + + expect(PLATFORM.performance.clearMarks).toHaveBeenCalledWith("dispatch-start"); + expect(PLATFORM.performance.clearMarks).toHaveBeenCalledWith("dispatch-after-reducer-Action A"); + expect(PLATFORM.performance.clearMarks).toHaveBeenCalledWith("dispatch-end"); + expect(PLATFORM.performance.clearMeasures).toHaveBeenCalledWith("startEndDispatchDuration"); + expect(PLATFORM.performance.clearMarks).not.toHaveBeenCalledWith("user mark 1"); + expect(PLATFORM.performance.clearMarks).not.toHaveBeenCalledWith("user mark 2"); + expect(PLATFORM.performance.clearMeasures).not.toHaveBeenCalledWith("user measure"); + }); + + it("should clear only store marks and measures if log all dispatch duration turned on via options", async () => { + const initialState: testState = { + foo: "bar" + }; + + const store = createStoreWithStateAndOptions( + initialState, + { measurePerformance: PerformanceMeasurement.All } + ); + PLATFORM.performance.mark("user mark 1"); + PLATFORM.performance.mark("user mark 2"); + PLATFORM.performance.measure("user measure", "user mark 1", "user mark 2"); + spyOn(PLATFORM.performance, "clearMarks").and.callThrough(); + spyOn(PLATFORM.performance, "clearMeasures").and.callThrough(); + + const actionA = (_: testState) => { + return new Promise((resolve) => { + setTimeout(() => resolve({ foo: "A" }), 1); + }); + }; + + store.registerAction("Action A", actionA); + await store.dispatch(actionA); + + expect(PLATFORM.performance.clearMarks).toHaveBeenCalledWith("dispatch-start"); + expect(PLATFORM.performance.clearMarks).toHaveBeenCalledWith("dispatch-after-reducer-Action A"); + expect(PLATFORM.performance.clearMarks).toHaveBeenCalledWith("dispatch-end"); + expect(PLATFORM.performance.clearMarks).not.toHaveBeenCalledWith("user mark 1"); + expect(PLATFORM.performance.clearMarks).not.toHaveBeenCalledWith("user mark 2"); + expect(PLATFORM.performance.clearMeasures).not.toHaveBeenCalledWith("user measure"); }); it("should reset the state without going through the internal dispatch queue", async (done) => { @@ -590,6 +687,13 @@ describe("store", () => { initialState, { measurePerformance: PerformanceMeasurement.StartEnd } ); + const expectedMeasures = [ + { duration: 1 }, + { duration: 2 } + ]; + spyOn(PLATFORM.performance, "mark").and.callThrough(); + spyOn(PLATFORM.performance, "measure").and.callThrough(); + spyOn(PLATFORM.performance, "getEntriesByName").and.returnValue(expectedMeasures); const loggerSpy = spyOn((store as any).logger, "info"); const actionA = (_: testState) => { @@ -601,7 +705,16 @@ describe("store", () => { store.registerAction("Action A", actionA); await store.pipe(actionA).dispatch(); - expect(loggerSpy).toHaveBeenCalledWith(expect.any(String), expect.any(Array)); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(1, "dispatch-start"); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(2, "dispatch-after-reducer-Action A"); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(3, "dispatch-end"); + expect(PLATFORM.performance.measure).toHaveBeenCalledWith( + "startEndDispatchDuration", + "dispatch-start", + "dispatch-end" + ); + expect(PLATFORM.performance.getEntriesByName).toHaveBeenCalledWith("startEndDispatchDuration", "measure"); + expect(loggerSpy).toHaveBeenCalledWith("Total duration 1 of dispatched action Action A:", expectedMeasures); }); it("should log all dispatch durations if turned on via options", async () => { @@ -613,6 +726,14 @@ describe("store", () => { initialState, { measurePerformance: PerformanceMeasurement.All } ); + const expectedMarks = [ + { startTime: 1 }, + { startTime: 10 }, + { startTime: 100 }, + ]; + const expectedDuration = expectedMarks[2].startTime - expectedMarks[0].startTime; + spyOn(PLATFORM.performance, "mark").and.callThrough(); + spyOn(PLATFORM.performance, "getEntriesByType").and.returnValue(expectedMarks); const loggerSpy = spyOn((store as any).logger, "info"); const actionA = (_: testState) => { @@ -624,7 +745,79 @@ describe("store", () => { store.registerAction("Action A", actionA); await store.pipe(actionA).dispatch(); - expect(loggerSpy).toHaveBeenCalledWith(expect.any(String), expect.any(Array)); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(1, "dispatch-start"); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(2, "dispatch-after-reducer-Action A"); + expect(PLATFORM.performance.mark).toHaveBeenNthCalledWith(3, "dispatch-end"); + expect(PLATFORM.performance.getEntriesByType).toHaveBeenCalledWith("mark"); + expect(loggerSpy).toHaveBeenCalledWith( + `Total duration ${expectedDuration} of dispatched action Action A:`, + expectedMarks + ); + }); + + it("should clear only store marks and measures if log start-end dispatch duration turned on via options", async () => { + const initialState: testState = { + foo: "bar" + }; + + const store = createStoreWithStateAndOptions( + initialState, + { measurePerformance: PerformanceMeasurement.StartEnd } + ); + PLATFORM.performance.mark("user mark 1"); + PLATFORM.performance.mark("user mark 2"); + PLATFORM.performance.measure("user measure", "user mark 1", "user mark 2"); + spyOn(PLATFORM.performance, "clearMarks").and.callThrough(); + spyOn(PLATFORM.performance, "clearMeasures").and.callThrough(); + + const actionA = (_: testState) => { + return new Promise((resolve) => { + setTimeout(() => resolve({ foo: "A" }), 1); + }); + }; + + store.registerAction("Action A", actionA); + await store.pipe(actionA).dispatch(); + + expect(PLATFORM.performance.clearMarks).toHaveBeenCalledWith("dispatch-start"); + expect(PLATFORM.performance.clearMarks).toHaveBeenCalledWith("dispatch-after-reducer-Action A"); + expect(PLATFORM.performance.clearMarks).toHaveBeenCalledWith("dispatch-end"); + expect(PLATFORM.performance.clearMeasures).toHaveBeenCalledWith("startEndDispatchDuration"); + expect(PLATFORM.performance.clearMarks).not.toHaveBeenCalledWith("user mark 1"); + expect(PLATFORM.performance.clearMarks).not.toHaveBeenCalledWith("user mark 2"); + expect(PLATFORM.performance.clearMeasures).not.toHaveBeenCalledWith("user measure"); + }); + + it("should clear only store marks and measures if log all dispatch duration turned on via options", async () => { + const initialState: testState = { + foo: "bar" + }; + + const store = createStoreWithStateAndOptions( + initialState, + { measurePerformance: PerformanceMeasurement.All } + ); + PLATFORM.performance.mark("user mark 1"); + PLATFORM.performance.mark("user mark 2"); + PLATFORM.performance.measure("user measure", "user mark 1", "user mark 2"); + spyOn(PLATFORM.performance, "clearMarks").and.callThrough(); + spyOn(PLATFORM.performance, "clearMeasures").and.callThrough(); + + const actionA = (_: testState) => { + return new Promise((resolve) => { + setTimeout(() => resolve({ foo: "A" }), 1); + }); + }; + + store.registerAction("Action A", actionA); + await store.pipe(actionA).dispatch(); + + expect(PLATFORM.performance.clearMarks).toHaveBeenCalledWith("dispatch-start"); + expect(PLATFORM.performance.clearMarks).toHaveBeenCalledWith("dispatch-after-reducer-Action A"); + expect(PLATFORM.performance.clearMarks).toHaveBeenCalledWith("dispatch-end"); + expect(PLATFORM.performance.clearMarks).not.toHaveBeenCalledWith("user mark 1"); + expect(PLATFORM.performance.clearMarks).not.toHaveBeenCalledWith("user mark 2"); + expect(PLATFORM.performance.clearMeasures).not.toHaveBeenCalledWith("user measure"); }); });