How to Speed Up Grafana Startup Time for Live WebSocket Functionality?

I’m currently using Grafana primarily for its live WebSocket functionality and have noticed that it takes a considerable amount of time to start up. Specifically, there is a delay of about 20 seconds between these two log statements:

Oct 10 12:22:36 server-15 grafana[545]: logger=live.push_http t=2023-10-10T12:22:36.771224104-04:00 level=info msg="Live Push Gateway initialization"
Oct 10 12:23:03 server-15 grafana[545]: logger=infra.usagestats.collector t=2023-10-10T12:23:03.137499035-04:00 level=info msg="registering usage stat providers" usageStatsProvidersLen=2

I couldn’t find any further logs that could clarify what happens during this 20-second interval, and I am wondering if there is a way to speed up the startup process, given that I only require the live WebSocket functionality.

  1. Are there configuration options that allow me to disable any unrelated features or services that could be contributing to this startup delay?
  2. Can someone explain what happens in between these log statements? Could that be a point to optimize?
  3. Are there specific logs or debug modes that can provide more granular information about what’s happening during the startup?

I appreciate any insights or suggestions you can offer. Thank you!

Try to increase log level to debug and check logs again.

Hi, thanks for the response. Still not much help there. There is a delay after the live.push_http line without much explanation:

Oct 11 09:08:27 server-15 grafana[4138]: logger=accesscontrol t=2023-10-11T09:08:27.263025416-04:00 level=debug msg="adding scope attribute resolver" prefix=datasources:id:
Oct 11 09:08:27 server-15 grafana[4138]: logger=accesscontrol t=2023-10-11T09:08:27.341120271-04:00 level=debug msg="adding scope attribute resolver" prefix=dashboards:id:
Oct 11 09:08:27 server-15 grafana[4138]: logger=accesscontrol t=2023-10-11T09:08:27.348764331-04:00 level=debug msg="adding scope attribute resolver" prefix=dashboards:uid:
Oct 11 09:08:27 server-15 grafana[4138]: logger=query_data t=2023-10-11T09:08:27.352774753-04:00 level=info msg="Query Service initialization"
Oct 11 09:08:27 server-15 grafana[4138]: logger=live t=2023-10-11T09:08:27.353046131-04:00 level=debug msg="GrafanaLive initialization" ha=false
Oct 11 09:08:27 server-15 grafana[4138]: logger=live.push_http t=2023-10-11T09:08:27.482644401-04:00 level=info msg="Live Push Gateway initialization"
Oct 11 09:08:51 server-15 grafana[4138]: logger=accesscontrol t=2023-10-11T09:08:51.539021477-04:00 level=debug msg="adding scope attribute resolver" prefix=annotations:id:
Oct 11 09:08:51 server-15 grafana[4138]: logger=plugindashboards t=2023-10-11T09:08:51.540067364-04:00 level=debug msg="Looking for app dashboard updates"
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules.registry t=2023-10-11T09:08:51.541325157-04:00 level=debug msg="Registering invisible module" name=grafana-apiserver
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules.registry t=2023-10-11T09:08:51.541534615-04:00 level=debug msg="Registering invisible module" name=background-services
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules.registry t=2023-10-11T09:08:51.54163096-04:00 level=debug msg="Registering invisible module" name=cert-generator
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules.registry t=2023-10-11T09:08:51.541722826-04:00 level=debug msg="Registering invisible module" name=http-server
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules.registry t=2023-10-11T09:08:51.54181438-04:00 level=debug msg="Registering invisible module" name=provisioning
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules.registry t=2023-10-11T09:08:51.541905048-04:00 level=debug msg="Registering invisible module" name=secret-migrator
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules.registry t=2023-10-11T09:08:51.542014152-04:00 level=debug msg="Registering module" name=all
Oct 11 09:08:51 server-15 grafana[4138]: logger=infra.usagestats.collector t=2023-10-11T09:08:51.542109975-04:00 level=info msg="registering usage stat providers" usageStatsProvidersLen=2
Oct 11 09:08:51 server-15 grafana[4138]: logger=server t=2023-10-11T09:08:51.542463378-04:00 level=info msg="Writing PID file" path=/run/grafana/grafana-server.pid pid=4138
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules t=2023-10-11T09:08:51.542579721-04:00 level=debug msg="Initializing module manager" targets=[all]
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules t=2023-10-11T09:08:51.543506557-04:00 level=debug msg="Starting module service manager"
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules t=2023-10-11T09:08:51.543731691-04:00 level=debug msg="module waiting for initialization" module=provisioning waiting_for=secret-migrator
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules t=2023-10-11T09:08:51.544186334-04:00 level=debug msg="module waiting for initialization" module=background-services waiting_for=http-server
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules t=2023-10-11T09:08:51.544442506-04:00 level=info msg=initialising module=http-server
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules t=2023-10-11T09:08:51.545632598-04:00 level=info msg=initialising module=secret-migrator
Oct 11 09:08:51 server-15 grafana[4138]: logger=infra.lockservice t=2023-10-11T09:08:51.546027923-04:00 level=debug msg="Start LockExecuteAndRelease" actionName="secret migration task "
Oct 11 09:08:51 server-15 grafana[4138]: logger=infra.lockservice t=2023-10-11T09:08:51.561185547-04:00 level=debug msg="Start execution" actionName="secret migration task "
Oct 11 09:08:51 server-15 grafana[4138]: logger=secret.migration t=2023-10-11T09:08:51.561380632-04:00 level=debug msg="Starting secret migration service" service=*migrations.DataSourceSecretMigrationService
Oct 11 09:08:51 server-15 grafana[4138]: logger=infra.kvstore.sql t=2023-10-11T09:08:51.563399339-04:00 level=debug msg="got kvstore value" orgId=0 namespace=datasource key=secretMigrationStatus value=compatible
Oct 11 09:08:51 server-15 grafana[4138]: logger=secret.migration t=2023-10-11T09:08:51.563637805-04:00 level=debug msg="secret migration status is compatible"
Oct 11 09:08:51 server-15 grafana[4138]: logger=secret.migration t=2023-10-11T09:08:51.563733942-04:00 level=debug msg="Finished secret migration service" service=*migrations.DataSourceSecretMigrationService
Oct 11 09:08:51 server-15 grafana[4138]: logger=secret.migration t=2023-10-11T09:08:51.563829609-04:00 level=debug msg="Starting secret migration service" service=*migrations.MigrateToPluginService
Oct 11 09:08:51 server-15 grafana[4138]: logger=secret.migration t=2023-10-11T09:08:51.564062764-04:00 level=debug msg="Finished secret migration service" service=*migrations.MigrateToPluginService
Oct 11 09:08:51 server-15 grafana[4138]: logger=infra.lockservice t=2023-10-11T09:08:51.564174107-04:00 level=debug msg="Execution finished" actionName="secret migration task " duration=3.05095ms
Oct 11 09:08:51 server-15 grafana[4138]: logger=infra.lockservice t=2023-10-11T09:08:51.575491379-04:00 level=debug msg="LockExecuteAndRelease finished" actionName="secret migration task " duration=29.460123ms
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules t=2023-10-11T09:08:51.575777288-04:00 level=info msg=initialising module=provisioning
Oct 11 09:08:51 server-15 grafana[4138]: logger=provisioning.plugins t=2023-10-11T09:08:51.577996445-04:00 level=debug msg="Looking for plugin provisioning files" path=/etc/grafana/provisioning/plugins
Oct 11 09:08:51 server-15 grafana[4138]: logger=provisioning.plugins t=2023-10-11T09:08:51.578381511-04:00 level=debug msg="Parsing plugin provisioning file" path=/etc/grafana/provisioning/plugins file.Name=sample.yaml
Oct 11 09:08:51 server-15 grafana[4138]: logger=http.server t=2023-10-11T09:08:51.579316784-04:00 level=info msg="HTTP Server Listen" address=[::]:3000 protocol=http subUrl= socket=
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules t=2023-10-11T09:08:51.57982288-04:00 level=debug msg="module waiting for initialization" module=background-services waiting_for=provisioning
Oct 11 09:08:51 server-15 grafana[4138]: logger=provisioning.plugins t=2023-10-11T09:08:51.580182167-04:00 level=debug msg="Validating plugins"
Oct 11 09:08:51 server-15 grafana[4138]: logger=provisioning.notifiers t=2023-10-11T09:08:51.580332257-04:00 level=debug msg="Looking for alert notification provisioning files" path=/etc/grafana/provisioning/notifiers
Oct 11 09:08:51 server-15 grafana[4138]: logger=provisioning.notifiers t=2023-10-11T09:08:51.58062504-04:00 level=debug msg="Parsing alert notifications provisioning file" path=/etc/grafana/provisioning/notifiers file.Name=sample.yaml
Oct 11 09:08:51 server-15 grafana[4138]: logger=provisioning.notifiers t=2023-10-11T09:08:51.581870334-04:00 level=debug msg="Validating alert notifications"
Oct 11 09:08:51 server-15 grafana[4138]: logger=provisioning.alerting t=2023-10-11T09:08:51.582190615-04:00 level=debug msg="looking for alerting provisioning files" path=/etc/grafana/provisioning/alerting
Oct 11 09:08:51 server-15 grafana[4138]: logger=provisioning.alerting t=2023-10-11T09:08:51.582499231-04:00 level=debug msg="parsing alerting provisioning file" path=/etc/grafana/provisioning/alerting file.Name=sample.yaml
Oct 11 09:08:51 server-15 grafana[4138]: logger=provisioning.alerting t=2023-10-11T09:08:51.58493597-04:00 level=info msg="starting to provision alerting"
Oct 11 09:08:51 server-15 grafana[4138]: logger=provisioning.alerting t=2023-10-11T09:08:51.58510387-04:00 level=debug msg="read all alerting files" file_count=1
Oct 11 09:08:51 server-15 grafana[4138]: logger=provisioning.alerting t=2023-10-11T09:08:51.585239013-04:00 level=info msg="finished to provision alerting"
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules t=2023-10-11T09:08:51.585662045-04:00 level=debug msg="module waiting for initialization" module=background-services waiting_for=secret-migrator
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules t=2023-10-11T09:08:51.585835309-04:00 level=info msg=initialising module=background-services
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules t=2023-10-11T09:08:51.586355726-04:00 level=info msg="All modules healthy" modules="[http-server secret-migrator provisioning background-services]"
Oct 11 09:08:51 server-15 grafana[4138]: logger=modules t=2023-10-11T09:08:51.586924629-04:00 level=debug msg="NOTIFY_SOCKET environment variable empty or unset, can't send systemd notification"
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.587340578-04:00 level=debug msg="Starting background service" service=*live.GrafanaLive
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.588076026-04:00 level=debug msg="Starting background service" service=*pushhttp.Gateway
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.588377403-04:00 level=debug msg="Waiting on services..."
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.588332355-04:00 level=debug msg="Starting background service" service=*service.UsageStats
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.588580508-04:00 level=debug msg="Starting background service" service=*dynamic.KeyRetriever
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.589014944-04:00 level=debug msg="Starting background service" service=*store.dummyEntityEventsService
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.589314394-04:00 level=debug msg="Stopped background service" service=*store.dummyEntityEventsService reason=null
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.589438079-04:00 level=debug msg="Starting background service" service=*statscollector.Service
Oct 11 09:08:51 server-15 grafana[4138]: logger=infra.usagestats.collector t=2023-10-11T09:08:51.589608896-04:00 level=debug msg="usage stats collector started" sendInterval=30m0s nextSendInterval=58s
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.589757631-04:00 level=debug msg="Starting background service" service=*tracing.Opentelemetry
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.589989431-04:00 level=debug msg="Starting background service" service=*remotecache.RemoteCache
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.590255655-04:00 level=debug msg="Starting background service" service=*manager.SecretsService
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.590549324-04:00 level=debug msg="Starting background service" service=*store.standardStorageService
Oct 11 09:08:51 server-15 grafana[4138]: logger=grafanaStorageLogger t=2023-10-11T09:08:51.590771959-04:00 level=info msg="storage starting"
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.590873615-04:00 level=debug msg="Stopped background service" service=*store.standardStorageService reason=null
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.591012091-04:00 level=debug msg="Starting background service" service=*authimpl.UserAuthTokenService
Oct 11 09:08:51 server-15 grafana[4138]: logger=infra.kvstore.sql t=2023-10-11T09:08:51.59110453-04:00 level=debug msg="got kvstore value" orgId=0 namespace=infra.usagestats key=last_sent value=2023-10-10T15:19:26-04:00
Oct 11 09:08:51 server-15 grafana[4138]: logger=infra.lockservice t=2023-10-11T09:08:51.591207697-04:00 level=debug msg="Start LockAndExecute" actionName="cleanup expired auth tokens"
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.591299771-04:00 level=debug msg="Starting background service" service=*provisioning.ProvisioningServiceImpl
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.592818112-04:00 level=debug msg="Starting background service" service=*notifications.NotificationService
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.593005176-04:00 level=debug msg="Starting background service" service=*metrics.InternalMetricsService
Oct 11 09:08:51 server-15 grafana[4138]: logger=provisioning t=2023-10-11T09:08:51.592952421-04:00 level=debug msg="Stop polling for dashboard changes"
Oct 11 09:08:51 server-15 grafana[4138]: logger=background-services-runner t=2023-10-11T09:08:51.593166983-04:00 level=debug msg="Starting background service" service=*rendering.RenderingService
Oct 11 09:08:51 server-15 grafana[4138]: logger=rendering t=2023-10-11T09:08:51.593428051-04:00 level=debug msg="No image renderer found/installed. For image rendering support please install the grafana-image-renderer plugin. Read more at https://grafana.com/docs/grafana/latest/administration/image_rendering/"

I’m arriving to the forum looking for this specifically as well, I observe a jump from 37:49 to 38:22 - 33 seconds.

Here are logs before after the 33 second delay I’ve observed.

logger=live.push_http t=2024-04-04T21:37:49.087433037Z level=info msg="Live Push Gateway initialization"
logger=ngalert.multiorg.alertmanager t=2024-04-04T21:37:49.088030171Z level=debug msg="synchronizing Alertmanagers for orgs"
logger=infra.kvstore.sql t=2024-04-04T21:37:49.089364549Z level=debug msg="got kvstore value" orgId=1 namespace=alertmanager key=notifications value=
logger=infra.kvstore.sql t=2024-04-04T21:37:49.089827083Z level=debug msg="got kvstore value" orgId=1 namespace=alertmanager key=silences value=
logger=ngalert t=2024-04-04T21:37:49.094028775Z level=warn msg="Unexpected number of rows updating alert configuration history" rows=0 org=1 hash=e0528a75784033ae7b15c40851d89484
logger=ngalert.multiorg.alertmanager t=2024-04-04T21:37:49.094742988Z level=debug msg="done synchronizing Alertmanagers for orgs"
logger=ngalert.sender.router t=2024-04-04T21:37:49.094960549Z level=debug msg="Attempting to sync admin configs" count=0
logger=ngalert.sender.router t=2024-04-04T21:37:49.094981837Z level=debug msg="Finish of admin configuration sync"
logger=accesscontrol t=2024-04-04T21:38:22.79359561Z level=debug msg="adding scope attribute resolver" prefix=annotations:id:
logger=plugindashboards t=2024-04-04T21:38:22.793872763Z level=debug msg="Looking for app dashboard updates"
logger=modules.registry t=2024-04-04T21:38:22.794311769Z level=debug msg="Registering invisible module" name=grafana-apiserver
logger=modules.registry t=2024-04-04T21:38:22.794347851Z level=debug msg="Registering invisible module" name=background-services
logger=modules.registry t=2024-04-04T21:38:22.794355552Z level=debug msg="Registering invisible module" name=cert-generator
logger=modules.registry t=2024-04-04T21:38:22.794361925Z level=debug msg="Registering invisible module" name=http-server
logger=modules.registry t=2024-04-04T21:38:22.794369479Z level=debug msg="Registering invisible module" name=provisioning
logger=modules.registry t=2024-04-04T21:38:22.794375316Z level=debug msg="Registering invisible module" name=secret-migrator
logger=modules.registry t=2024-04-04T21:38:22.794381595Z level=debug msg="Registering module" name=all
logger=infra.usagestats.collector t=2024-04-04T21:38:22.79438941Z level=info msg="registering usage stat providers" usageStatsProvidersLen=2
logger=modules t=2024-04-04T21:38:22.794497395Z level=debug msg="Initializing module manager" targets=[all]
logger=modules t=2024-04-04T21:38:22.794726457Z level=debug msg="Starting module service manager"
logger=modules t=2024-04-04T21:38:22.794781035Z level=info msg=initialising module=http-server

These are all the warning lines during startup, nothing beyond level=info and level=debug log lines besides these.

logger=sqlstore t=2024-04-04T21:37:47.590233219Z level=warn msg="SQLite database file has broader permissions than it should" path=/var/lib/grafana/grafana.db mode=-rw-rw---- expected=-rw-r-----
logger=local.finder t=2024-04-04T21:37:48.988352947Z level=warn msg="Skipping finding plugins as directory does not exist" path=/usr/share/grafana/plugins-bundled
logger=ngalert t=2024-04-04T21:37:49.094028775Z level=warn msg="Unexpected number of rows updating alert configuration history" rows=0 org=1 hash=e0528a75784033ae7b15c40851d89484

My grafana is deployed with the official grafana Helm chart version 6.61.2, which ships grafana version 10.1.5.

Try to enable opentelemetry tracing in Grafana and inspect generated traces.
Also SQLite is not the fastest DB, so you may try some serious DB to see if there is any difference.

1 Like