Alerting: Query time logging (#57585)

public/app/features/alerting/unified/Analytics.ts

@@ -1,3 +1,6 @@
+import { agent, LogLevel as GrafanaLogLevel } from '@grafana/agent-web';
+import { config } from '@grafana/runtime/src';
+
 export const LogMessages = {
   filterByLabel: 'filtering alert instances by label',
   loadedList: 'loaded Alert Rules list',
@@ -8,3 +11,31 @@ export const LogMessages = {
   cancelSavingAlertRule: 'user canceled alert rule creation',
   successSavingAlertRule: 'alert rule saved successfully',
 };
+
+// logInfo from '@grafana/runtime' should be used, but it doesn't handle Grafana JS Agent and Sentry correctly
+export function logInfo(message: string, context: Record<string, string | number> = {}) {
+  if (config.grafanaJavascriptAgent.enabled) {
+    agent.api.pushLog([message], {
+      level: GrafanaLogLevel.INFO,
+      context: { ...context, module: 'Alerting' },
+    });
+  }
+}
+
+// eslint-disable-next-line @typescript-eslint/no-explicit-any
+export function withPerformanceLogging<TFunc extends (...args: any[]) => Promise<any>>(
+  func: TFunc,
+  message: string,
+  context: Record<string, string>
+): (...args: Parameters<TFunc>) => Promise<Awaited<ReturnType<TFunc>>> {
+  return async function (...args) {
+    const startLoadingTs = performance.now();
+    const response = await func(...args);
+    logInfo(message, {
+      loadTimeMs: (performance.now() - startLoadingTs).toFixed(0),
+      ...context,
+    });
+
+    return response;
+  };
+}

public/app/features/alerting/unified/RuleList.test.tsx

@@ -211,6 +211,8 @@ describe('RuleList', () => {
       return Promise.reject(new Error(`unexpected datasourceName: ${dataSourceName}`));
     });
 
+    mocks.api.fetchRulerRules.mockRejectedValue({ status: 500, data: { message: 'Server error' } });
+
     await renderRuleList();
 
     await waitFor(() => expect(mocks.api.fetchRules).toHaveBeenCalledTimes(4));

public/app/features/alerting/unified/api/alertingApi.ts

@@ -3,10 +3,21 @@ import { lastValueFrom } from 'rxjs';
 
 import { BackendSrvRequest, getBackendSrv } from '@grafana/runtime';
 
+import { logInfo } from '../Analytics';
+
 const backendSrvBaseQuery = (): BaseQueryFn<BackendSrvRequest> => async (requestOptions) => {
   try {
+    const requestStartTs = performance.now();
+
     const { data, ...meta } = await lastValueFrom(getBackendSrv().fetch(requestOptions));
 
+    logInfo('Request finished', {
+      loadTimeMs: (performance.now() - requestStartTs).toFixed(0),
+      url: requestOptions.url,
+      method: requestOptions.method ?? '',
+      responseStatus: meta.statusText,
+    });
+
     return { data, meta };
   } catch (error) {
     return { error };

public/app/features/alerting/unified/state/actions.ts

@@ -1,7 +1,7 @@
 import { createAsyncThunk } from '@reduxjs/toolkit';
 import { isEmpty } from 'lodash';
 
-import { locationService, logInfo } from '@grafana/runtime';
+import { locationService } from '@grafana/runtime';
 import {
   AlertmanagerAlert,
   AlertManagerCortexConfig,
@@ -32,7 +32,7 @@ import {
 } from 'app/types/unified-alerting-dto';
 
 import { backendSrv } from '../../../../core/services/backend_srv';
-import { LogMessages } from '../Analytics';
+import { logInfo, LogMessages, withPerformanceLogging } from '../Analytics';
 import {
   addAlertManagers,
   createOrUpdateSilence,
@@ -103,7 +103,13 @@ export const fetchPromRulesAction = createAsyncThunk(
     thunkAPI
   ): Promise<RuleNamespace[]> => {
     await thunkAPI.dispatch(fetchRulesSourceBuildInfoAction({ rulesSourceName }));
-    return await withSerializedError(fetchRules(rulesSourceName, filter));
+
+    const fetchRulesWithLogging = withPerformanceLogging(fetchRules, `[${rulesSourceName}] Prometheus rules loaded`, {
+      dataSourceName: rulesSourceName,
+      thunk: 'unifiedalerting/fetchPromRules',
+    });
+
+    return await withSerializedError(fetchRulesWithLogging(rulesSourceName, filter));
   }
 );
 
@@ -127,9 +133,17 @@ export const fetchAlertManagerConfigAction = createAsyncThunk(
         );
 
         const lazyConfigInitSupported = amFeatures?.lazyConfigInit ?? false;
+        const fetchAMconfigWithLogging = withPerformanceLogging(
+          fetchAlertManagerConfig,
+          `[${alertManagerSourceName}] Alertmanager config loaded`,
+          {
+            dataSourceName: alertManagerSourceName,
+            thunk: 'unifiedalerting/fetchAmConfig',
+          }
+        );
 
         return retryWhile(
-          () => fetchAlertManagerConfig(alertManagerSourceName),
+          () => fetchAMconfigWithLogging(alertManagerSourceName),
           // if config has been recently deleted, it takes a while for cortex start returning the default one.
           // retry for a short while instead of failing
           (e) => !!messageFromError(e)?.includes('alertmanager storage object not found') && !lazyConfigInitSupported,
@@ -195,7 +209,17 @@ export const fetchRulerRulesAction = createAsyncThunk(
   ): Promise<RulerRulesConfigDTO | null> => {
     await dispatch(fetchRulesSourceBuildInfoAction({ rulesSourceName }));
     const rulerConfig = getDataSourceRulerConfig(getState, rulesSourceName);
-    return await withSerializedError(fetchRulerRules(rulerConfig, filter));
+
+    const fetchRulerRulesWithLogging = withPerformanceLogging(
+      fetchRulerRules,
+      `[${rulesSourceName}] Ruler rules loaded`,
+      {
+        dataSourceName: rulesSourceName,
+        thunk: 'unifiedalerting/fetchRulerRules',
+      }
+    );
+
+    return await withSerializedError(fetchRulerRulesWithLogging(rulerConfig, filter));
   }
 );
 
@@ -214,7 +238,16 @@ export function fetchPromAndRulerRulesAction({ rulesSourceName }: { rulesSourceN
 export const fetchSilencesAction = createAsyncThunk(
   'unifiedalerting/fetchSilences',
   (alertManagerSourceName: string): Promise<Silence[]> => {
-    return withSerializedError(fetchSilences(alertManagerSourceName));
+    const fetchSilencesWithLogging = withPerformanceLogging(
+      fetchSilences,
+      `[${alertManagerSourceName}] Silences loaded`,
+      {
+        dataSourceName: alertManagerSourceName,
+        thunk: 'unifiedalerting/fetchSilences',
+      }
+    );
+
+    return withSerializedError(fetchSilencesWithLogging(alertManagerSourceName));
   }
 );
 
@@ -261,7 +294,17 @@ export const fetchRulesSourceBuildInfoAction = createAsyncThunk(
         }
 
         const { id, name } = ds;
-        const buildInfo = await discoverFeatures(name);
+
+        const discoverFeaturesWithLogging = withPerformanceLogging(
+          discoverFeatures,
+          `[${rulesSourceName}] Rules source features discovered`,
+          {
+            dataSourceName: rulesSourceName,
+            thunk: 'unifiedalerting/fetchPromBuildinfo',
+          }
+        );
+
+        const buildInfo = await discoverFeaturesWithLogging(name);
 
         const rulerConfig: RulerDataSourceConfig | undefined = buildInfo.features.rulerApiEnabled
           ? {
@@ -292,6 +335,8 @@ export const fetchRulesSourceBuildInfoAction = createAsyncThunk(
 
 export function fetchAllPromAndRulerRulesAction(force = false): ThunkResult<Promise<void>> {
   return async (dispatch, getStore) => {
+    const allStartLoadingTs = performance.now();
+
     await Promise.allSettled(
       getAllRulesSourceNames().map(async (rulesSourceName) => {
         await dispatch(fetchRulesSourceBuildInfoAction({ rulesSourceName }));
@@ -304,7 +349,8 @@ export function fetchAllPromAndRulerRulesAction(force = false): ThunkResult<Prom
         }
 
         const shouldLoadProm = force || !promRules[rulesSourceName]?.loading;
-        const shouldLoadRuler = (force || !rulerRules[rulesSourceName]?.loading) && dataSourceConfig.rulerConfig;
+        const shouldLoadRuler =
+          (force || !rulerRules[rulesSourceName]?.loading) && Boolean(dataSourceConfig.rulerConfig);
 
         await Promise.allSettled([
           shouldLoadProm && dispatch(fetchPromRulesAction({ rulesSourceName })),
@@ -312,6 +358,10 @@ export function fetchAllPromAndRulerRulesAction(force = false): ThunkResult<Prom
         ]);
       })
     );
+
+    logInfo('All Prom and Ruler rules loaded', {
+      loadTimeMs: (performance.now() - allStartLoadingTs).toFixed(0),
+    });
   };
 }