From 2e8f9641f177169c156977b25c593e1ca2c0639c Mon Sep 17 00:00:00 2001
From: Bastien DUMONT <bdumont@grandlyon.com>
Date: Tue, 2 May 2023 13:47:17 +0000
Subject: [PATCH] feat: log loading times
---
src/components/Splash/SplashRoot.spec.tsx | 6 ++
src/components/Splash/SplashRoot.tsx | 7 +-
src/migrations/migration.service.ts | 6 +-
src/services/initialization.service.ts | 78 +++++++++++++++--------
src/utils/duration.ts | 13 ++++
5 files changed, 80 insertions(+), 30 deletions(-)
create mode 100644 src/utils/duration.ts
diff --git a/src/components/Splash/SplashRoot.spec.tsx b/src/components/Splash/SplashRoot.spec.tsx
index 18e45c09e..e54bcec91 100644
--- a/src/components/Splash/SplashRoot.spec.tsx
+++ b/src/components/Splash/SplashRoot.spec.tsx
@@ -5,6 +5,12 @@ import * as reactRedux from 'react-redux'
import { userChallengeExplo1OnGoing } from '../../../tests/__mocks__/userChallengeData.mock'
import SplashRoot from './SplashRoot'
+jest.mock('@sentry/react', () => ({
+ ...jest.requireActual('@sentry/react'),
+ // mock transaction because the .finish method cannot be called on undefined otherwise
+ startTransaction: () => ({ finish: jest.fn() }),
+}))
+
jest.mock('cozy-ui/transpiled/react/I18n', () => {
return {
useI18n: jest.fn(() => {
diff --git a/src/components/Splash/SplashRoot.tsx b/src/components/Splash/SplashRoot.tsx
index b3d25a583..d1de2c413 100644
--- a/src/components/Splash/SplashRoot.tsx
+++ b/src/components/Splash/SplashRoot.tsx
@@ -57,6 +57,7 @@ import { openPartnersModal } from 'store/modal/modal.slice'
import { updateProfile } from 'store/profile/profile.actions'
import { updateProfileEcogestureSuccess } from 'store/profileEcogesture/profileEcogesture.actions'
import { updateProfileType } from 'store/profileType/profileType.actions'
+import { logDuration } from 'utils/duration'
import logApp from 'utils/logger'
import { getTodayDate } from 'utils/utils'
import SplashScreen from './SplashScreen'
@@ -187,6 +188,8 @@ const SplashRoot = ({ fadeTimer = 1000, children }: SplashRootProps) => {
const customPopupService = new CustomPopupService(client)
const partnersInfoService = new PartnersInfoService(client)
const ms = new MigrationService(client, setInitStepErrors)
+ const startTime = performance.now()
+ const transaction = Sentry.startTransaction({ name: 'Initialize app' })
try {
const migrationsResult = await ms.runMigrations(migrations)
@@ -350,7 +353,7 @@ const SplashRoot = ({ fadeTimer = 1000, children }: SplashRootProps) => {
})
if (subscribed) {
- logApp.info('[Initialization] Finished successfully !')
+ logDuration('[Initialization] Finished successfully !', startTime)
setState(prev => ({
...prev,
splashStart: true,
@@ -362,6 +365,8 @@ const SplashRoot = ({ fadeTimer = 1000, children }: SplashRootProps) => {
}
logApp.error(`[Initialization] Error : ${error}`)
Sentry.captureException(JSON.stringify({ error }))
+ } finally {
+ transaction.finish()
}
}
if (!initStepErrors) loadData()
diff --git a/src/migrations/migration.service.ts b/src/migrations/migration.service.ts
index 6a603d9a6..2746f1483 100644
--- a/src/migrations/migration.service.ts
+++ b/src/migrations/migration.service.ts
@@ -4,6 +4,7 @@ import { SCHEMAS_DOCTYPE } from 'doctypes/com-grandlyon-ecolyo-schemas'
import { InitStepsErrors } from 'models/initialisationSteps.model'
import { ReleaseNotes } from 'models/releaseNotes.model'
import { Schema } from 'models/schema.models'
+import { logDuration } from 'utils/duration'
import logApp from 'utils/logger'
import { migrate, migrationLog } from './migration'
import {
@@ -38,6 +39,7 @@ export class MigrationService {
}
public async runMigrations(migrations: Migration[]): Promise<ReleaseNotes> {
+ const startTime = performance.now()
logApp.info('[Migration] Running migrations...')
let releaseStatus = false
const releaseNotes: ReleaseNotes = {
@@ -96,10 +98,10 @@ export class MigrationService {
// In case of first instance, don't show release notes
if (startMigrationIndex === 0) releaseNotes.show = false
logApp.info('[Migration] Done')
- return releaseNotes
} else {
logApp.info('[Migration] Skipped Migration Process, already up-to-date')
- return releaseNotes
}
+ logDuration('[Migration] Finished in', startTime)
+ return releaseNotes
}
}
diff --git a/src/services/initialization.service.ts b/src/services/initialization.service.ts
index 3057f611e..49daa15f0 100644
--- a/src/services/initialization.service.ts
+++ b/src/services/initialization.service.ts
@@ -42,6 +42,7 @@ import KonnectorStatusService from 'services/konnectorStatus.service'
import ProfileService from 'services/profile.service'
import QuizService from 'services/quiz.service'
import { getActualAnalysisDate } from 'utils/date'
+import { logDuration } from 'utils/duration'
import { hashFile } from 'utils/hash'
import logApp from 'utils/logger'
import EnvironmentService from './environment.service'
@@ -78,6 +79,7 @@ export default class InitializationService {
* failure return: null
*/
public async initProfile(): Promise<Profile | null> {
+ const startTime = performance.now()
const profileService = new ProfileService(this._client)
try {
this._setInitStep(InitSteps.PROFILE)
@@ -89,19 +91,18 @@ export default class InitializationService {
profileData
)
if (newProfile) {
- logApp.info('[Initialization] Profile created')
+ logDuration('[Initialization] Profile created', startTime)
} else {
this._setInitStepError(InitStepsErrors.PROFILE_ERROR)
throw new Error('initProfile: Profile not created')
}
- } else {
- logApp.info('[Initialization] Profile loaded')
}
const updatedProfile = await profileService.updateProfile({
lastConnectionDate: DateTime.local().setZone('utc', {
keepLocalTime: true,
}),
})
+ logDuration('[Initialization] Profile loaded and updated in', startTime)
return updatedProfile
} catch (error) {
this._setInitStepError(InitStepsErrors.PROFILE_ERROR)
@@ -123,10 +124,11 @@ export default class InitializationService {
* failure return: null
*/
public async initProfileType(): Promise<ProfileType | null> {
+ const startTime = performance.now()
const profileTypeEntityService = new ProfileTypeEntityService(this._client)
try {
const loadedProfileType = await profileTypeEntityService.getProfileType()
- logApp.info('[Initialization] ProfileType loaded')
+ logDuration('[Initialization] ProfileType loaded', startTime)
return loadedProfileType
} catch (error) {
this._setInitStepError(InitStepsErrors.PROFILETYPE_ERROR)
@@ -140,11 +142,12 @@ export default class InitializationService {
}
}
public async initProfileEcogesture(): Promise<ProfileEcogesture | null> {
+ const startTime = performance.now()
const profileEcogestureService = new ProfileEcogestureService(this._client)
try {
const loadedProfileEcogesture =
await profileEcogestureService.getProfileEcogesture()
- logApp.info('[Initialization] ProfileEcogesture loaded')
+ logDuration('[Initialization] ProfileEcogesture loaded', startTime)
return loadedProfileEcogesture
} catch (error) {
this._setInitStepError(InitStepsErrors.PROFILETYPE_ERROR)
@@ -159,6 +162,7 @@ export default class InitializationService {
}
public async initEcogesture(hash: string): Promise<string> {
+ const startTime = performance.now()
this._setInitStep(InitSteps.ECOGESTURE)
const hashEcogestureType = hashFile(ecogestureData)
const ecogestureService = new EcogestureService(this._client)
@@ -181,7 +185,7 @@ export default class InitializationService {
'initEcogesture: Created ecogesture type entities does not match'
)
}
- logApp.info('[Initialization] Ecogesture list created')
+ logDuration('[Initialization] Ecogesture list created', startTime)
return hashEcogestureType
} catch (error) {
this._setInitStepError(InitStepsErrors.ECOGESTURE_ERROR)
@@ -222,7 +226,7 @@ export default class InitializationService {
'initEcogesture: Created ecogesture type entities does not match'
)
}
- logApp.info('[Initialization] Ecogesture updated')
+ logDuration('[Initialization] Ecogesture updated', startTime)
return hashEcogestureType
} catch (error) {
this._setInitStepError(InitStepsErrors.ECOGESTURE_ERROR)
@@ -236,17 +240,18 @@ export default class InitializationService {
}
} else {
// Doctype already up to date
- logApp.info('[Initialization] Ecogesture already up-to-date')
+ logDuration('[Initialization] Ecogesture already up-to-date', startTime)
return hashEcogestureType
}
}
public async initFluidPrices(): Promise<boolean> {
+ const startTime = performance.now()
const fpService = new FluidPricesService(this._client)
// Populate data if none ecogesture exists
const loadedPrices = await fpService.getAllPrices()
if (loadedPrices?.length) {
- logApp.info('[Initialization] FluidPrices db already created')
+ logDuration('[Initialization] FluidPrices db already created', startTime)
return true
} else {
try {
@@ -270,7 +275,8 @@ export default class InitializationService {
for (const price of allPrices) {
await fpService.createPrice(price)
}
- throw new Error('test')
+ logDuration('[Initialization] FluidPrices db created', startTime)
+ return true
} catch (error) {
const errorMessage = `Initialization error - initFluidPrices: ${JSON.stringify(
error
@@ -284,6 +290,7 @@ export default class InitializationService {
}
public async initChallengeEntity(hash: string): Promise<string> {
+ const startTime = performance.now()
this._setInitStep(InitSteps.CHALLENGES)
const challengeHash = hashFile(challengeEntityData)
const challengeService = new ChallengeService(this._client)
@@ -304,7 +311,7 @@ export default class InitializationService {
'initChallengeEntity: Created challenge entities does not match'
)
}
- logApp.info('[Initialization] Challenge entities created')
+ logDuration('[Initialization] Challenge entities created', startTime)
return challengeHash
} catch (error) {
this._setInitStepError(InitStepsErrors.CHALLENGES_ERROR)
@@ -335,7 +342,7 @@ export default class InitializationService {
'initChallengeEntity: Created challenge entities does not match'
)
}
- logApp.info('[Initialization] Challenge entities updated')
+ logDuration('[Initialization] Challenge entities updated', startTime)
return challengeHash
} catch (error) {
this._setInitStepError(InitStepsErrors.CHALLENGES_ERROR)
@@ -349,12 +356,13 @@ export default class InitializationService {
}
} else {
// Doctype already up to date
- logApp.info('[Initialization] Challenge Entity loaded')
+ logDuration('[Initialization] Challenge Entity loaded', startTime)
return challengeHash
}
}
public async initDuelEntity(hash: string): Promise<string> {
+ const startTime = performance.now()
const hashDuelEntity = hashFile(duelEntityData)
const duelService = new DuelService(this._client)
// Populate data if none DuelEntity exists
@@ -373,7 +381,7 @@ export default class InitializationService {
'initDuelEntity: Created duel entities does not match'
)
}
- logApp.info('[Initialization] UserDuel entities created')
+ logDuration('[Initialization] UserDuel entities created', startTime)
return hashDuelEntity
} catch (error) {
this._setInitStepError(InitStepsErrors.CHALLENGES_ERROR)
@@ -404,7 +412,7 @@ export default class InitializationService {
'initDuelEntity: Created duel entities does not match'
)
}
- logApp.info('[Initialization] UserDuel entities updated')
+ logDuration('[Initialization] UserDuel entities updated', startTime)
return hashDuelEntity
} catch (error) {
this._setInitStepError(InitStepsErrors.CHALLENGES_ERROR)
@@ -418,12 +426,13 @@ export default class InitializationService {
}
} else {
// Doctype already up to date
- logApp.info('[Initialization] Duel Entity loaded')
+ logDuration('[Initialization] Duel Entity loaded', startTime)
return hashDuelEntity
}
}
public async initQuizEntity(hash: string): Promise<string> {
+ const startTime = performance.now()
const quizHash = hashFile(quizEntityData)
const quizService = new QuizService(this._client)
// Populate data if none quizEntity exists
@@ -443,7 +452,7 @@ export default class InitializationService {
)
}
- logApp.info('[Initialization] Quiz entities created')
+ logDuration('[Initialization] Quiz entities created', startTime)
return quizHash
} catch (error) {
this._setInitStepError(InitStepsErrors.CHALLENGES_ERROR)
@@ -474,7 +483,7 @@ export default class InitializationService {
'initQuizEntity: Created quiz entities does not match'
)
}
- logApp.info('[Initialization] Quiz entities updated')
+ logDuration('[Initialization] Quiz entities updated', startTime)
return quizHash
} catch (error) {
this._setInitStepError(InitStepsErrors.CHALLENGES_ERROR)
@@ -488,12 +497,13 @@ export default class InitializationService {
}
} else {
// Doctype already up to date
- logApp.info('[Initialization] Quiz Entity loaded')
+ logDuration('[Initialization] Quiz Entity loaded', startTime)
return quizHash
}
}
public async initExplorationEntity(hash: string): Promise<string> {
+ const startTime = performance.now()
const explorationHash = hashFile(explorationEntityData)
const explorationService = new ExplorationService(this._client)
// Populate data if none explorationEntity exists
@@ -516,7 +526,7 @@ export default class InitializationService {
'initExplorationEntity: Created exploration entities does not match'
)
}
- logApp.info('[Initialization] Exploration entities created')
+ logDuration('[Initialization] Exploration entities created', startTime)
return explorationHash
} catch (error) {
this._setInitStepError(InitStepsErrors.CHALLENGES_ERROR)
@@ -550,7 +560,7 @@ export default class InitializationService {
'initExplorationEntity: Created exploration entities does not match'
)
}
- logApp.info('[Initialization] Exploration entities updated')
+ logDuration('[Initialization] Exploration entities updated', startTime)
return explorationHash
} catch (error) {
this._setInitStepError(InitStepsErrors.CHALLENGES_ERROR)
@@ -564,7 +574,7 @@ export default class InitializationService {
}
} else {
// Doctype already up to date
- logApp.info('[Initialization] Exploration Entity loaded')
+ logDuration('[Initialization] Exploration Entity loaded', startTime)
return explorationHash
}
}
@@ -573,19 +583,25 @@ export default class InitializationService {
monthlyAnalysisDate: DateTime
haveSeenLastAnalysis: boolean
}> {
+ const startTime = performance.now()
try {
const actualAnalysisDate = getActualAnalysisDate()
if (
profile.monthlyAnalysisDate &&
actualAnalysisDate <= profile.monthlyAnalysisDate
) {
+ logDuration(
+ '[Initialization] Analysis information from profile loaded',
+ startTime
+ )
return {
monthlyAnalysisDate: profile.monthlyAnalysisDate,
haveSeenLastAnalysis: profile.haveSeenLastAnalysis,
}
} else {
- logApp.info(
- '[Initialization] Analysis information from profile updated'
+ logDuration(
+ '[Initialization] Analysis information from profile updated',
+ startTime
)
return {
monthlyAnalysisDate: actualAnalysisDate,
@@ -610,11 +626,12 @@ export default class InitializationService {
* failure throw error
*/
public async initFluidTypes(): Promise<FluidType[]> {
+ const startTime = performance.now()
const kss = new KonnectorStatusService(this._client)
try {
const fluidtypes = await kss.getKonnectorAccountStatus()
if (fluidtypes) {
- logApp.info('[Initialization] Fluid Types loaded')
+ logDuration('[Initialization] Fluid Types loaded', startTime)
return fluidtypes
} else {
this._setInitStepError(InitStepsErrors.CONSOS_ERROR)
@@ -639,12 +656,13 @@ export default class InitializationService {
* failure throw error
*/
public async initFluidStatus(): Promise<FluidStatus[]> {
+ const startTime = performance.now()
const fs = new FluidService(this._client)
try {
this._setInitStep(InitSteps.CONSOS)
const fluidStatus = await fs.getFluidStatus()
if (fluidStatus) {
- logApp.info('[Initialization] Fluid Status loaded')
+ logDuration('[Initialization] Fluid Status loaded', startTime)
return fluidStatus
} else {
this._setInitStepError(InitStepsErrors.CONSOS_ERROR)
@@ -670,13 +688,14 @@ export default class InitializationService {
public async initUserChallenges(
fluidStatus: FluidStatus[]
): Promise<UserChallenge[]> {
+ const startTime = performance.now()
const challengeService = new ChallengeService(this._client)
try {
const userChallengeList = await challengeService.buildUserChallengeList(
fluidStatus
)
if (userChallengeList) {
- logApp.info('[Initialization] Challenges loaded')
+ logDuration('[Initialization] initUserChallenges', startTime)
return userChallengeList
} else {
this._setInitStepError(InitStepsErrors.CHALLENGES_ERROR)
@@ -703,10 +722,12 @@ export default class InitializationService {
updatedUserChallenge: UserChallenge
dataloads: Dataload[]
}> {
+ const startTime = performance.now()
const challengeService = new ChallengeService(this._client)
try {
const { updatedUserChallenge, dataloads } =
await challengeService.initChallengeDuelProgress(userChallenge)
+ logDuration('[Initialization] initDuelProgress finished', startTime)
return { updatedUserChallenge, dataloads }
} catch (error) {
this._setInitStepError(InitStepsErrors.CHALLENGES_ERROR)
@@ -723,6 +744,7 @@ export default class InitializationService {
accepted: false,
versionType: 'init',
}
+ const startTime = performance.now()
try {
this._setInitStep(InitSteps.CONSENT)
const termService = new TermsService(this._client)
@@ -771,6 +793,8 @@ export default class InitializationService {
logApp.error(errorMessage)
Sentry.captureException(errorMessage)
throw error
+ } finally {
+ logDuration('[Initialization] initConsent finished', startTime)
}
}
}
diff --git a/src/utils/duration.ts b/src/utils/duration.ts
new file mode 100644
index 000000000..adaadaf14
--- /dev/null
+++ b/src/utils/duration.ts
@@ -0,0 +1,13 @@
+import logApp from './logger'
+
+/**
+ * Logs the time spend and add "in xx ms"
+ * @param {string} scope string Migration | Initialization | ...
+ * @param startTime number raw duration in ms
+ * @output [Scope] Finished in XXX ms
+ * @example
+ * logDuration("[Migration] Finished", 764745674); // [Migration] Finished in 685 ms
+ */
+export function logDuration(scope: string, startTime: number) {
+ logApp.info(`${scope} in ${Math.round(performance.now() - startTime)} ms`)
+}
--
GitLab