Ignition Edge Boot Time

Theodorska · October 27, 2023, 7:17am

Hello,

we have multiple mobile units with ignition edge installed on windows 10.
We have an issue with the boot up time. It takes on average 2 minutes from JVM starts to Ignition gateway is up an running and we can get our HMI panels active.

We have changed the windows config to start with 4 cores.
We have removed modules from Ignition that we are not using.
We have also changed priority to high when starting up.

Still we are not seeing any great improvements.

Is 2 minutes a normal booting time for Ignition Edge?

Kevin.Herron · October 27, 2023, 12:43pm

Boot time is a function of your hardware and your projects/tags.

Ignition Edge is just Ignition with licensing restrictions and different graphics.

Share a wrapper.log file that includes the gateway startup?

Theodorska · October 27, 2023, 1:08pm

STATUS | wrapper  | 2023/10/27 15:01:56 | Launching a JVM...
INFO   | jvm 1    | 2023/10/27 15:01:59 | WrapperManager: Initializing...
INFO   | jvm 1    | 2023/10/27 15:02:05 | 15:02:05,191 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
INFO   | jvm 1    | 2023/10/27 15:02:05 | 15:02:05,257 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [SysoutAppender]
INFO   | jvm 1    | 2023/10/27 15:02:05 | 15:02:05,312 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
INFO   | jvm 1    | 2023/10/27 15:02:05 | 15:02:05,527 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [com.inductiveautomation.logging.SQLiteAppender]
INFO   | jvm 1    | 2023/10/27 15:02:05 | 15:02:05,588 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [DB]
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,772 |-INFO in ch.qos.logback.core.db.DataSourceConnectionSource@6721962a - Driver name=SQLite JDBC
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,772 |-INFO in ch.qos.logback.core.db.DataSourceConnectionSource@6721962a - Driver version=3.39.2.0
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,772 |-INFO in ch.qos.logback.core.db.DataSourceConnectionSource@6721962a - supportsGetGeneratedKeys=true
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,885 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender]
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,905 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [SysoutAsync]
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,906 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [SysoutAppender] to ch.qos.logback.classic.AsyncAppender[SysoutAsync]
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,906 |-INFO in ch.qos.logback.classic.AsyncAppender[SysoutAsync] - Attaching appender named [SysoutAppender] to AsyncAppender.
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,908 |-INFO in ch.qos.logback.classic.AsyncAppender[SysoutAsync] - Setting discardingThreshold to 51
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,909 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender]
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,909 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [DBAsync]
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,909 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [DB] to ch.qos.logback.classic.AsyncAppender[DBAsync]
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,910 |-INFO in ch.qos.logback.classic.AsyncAppender[DBAsync] - Attaching appender named [DB] to AsyncAppender.
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,910 |-INFO in ch.qos.logback.classic.AsyncAppender[DBAsync] - Setting discardingThreshold to 51
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,911 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,911 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [SysoutAsync] to Logger[ROOT]
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,918 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [DBAsync] to Logger[ROOT]
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,918 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
INFO   | jvm 1    | 2023/10/27 15:02:07 | 15:02:07,920 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@9b25376 - Registering current configuration as safe fallback point
INFO   | jvm 1    | 2023/10/27 15:02:08 | Scheduling logfile maintenance. Last maintenance: Thu Jan 01 01:00:00 CET 1970, events since then: 0
INFO   | jvm 1    | 2023/10/27 15:02:08 | Starting logfile maintenance. Max entries: 50000, Max filesize: 104857600
INFO   | jvm 1    | 2023/10/27 15:02:08 | Cleaned up 353 rows in 107 ms. Vacuum performed: false
INFO   | jvm 1    | 2023/10/27 15:02:08 | 15:02:08,162 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@bd5e7cd - Propagating INFO level on Logger[ROOT] onto the JUL framework
INFO   | jvm 1    | 2023/10/27 15:02:08 | W [WebResourceManagerImpl        ] [13:02:08]: Unable to read "gateway.metroKeystoreAlias" gateway.xml property. Assuming metro keystore alias is: metro-key 
INFO   | jvm 1    | 2023/10/27 15:02:09 | I [g.WebServerManager            ] [13:02:09]: Starting setup 
INFO   | jvm 1    | 2023/10/27 15:02:10 | I [g.WebServerManager            ] [13:02:09]: Setup complete 
INFO   | jvm 1    | 2023/10/27 15:02:10 | I [g.WebServerManager            ] [13:02:10]: Starting up 
INFO   | jvm 1    | 2023/10/27 15:02:11 | I [o.e.j.s.Server                ] [13:02:11]: jetty-10.0.13; built: 2022-12-07T20:13:20.134Z; git: 1c2636ea05c0ca8de1ffd6ca7f3a98ac084c766d; jvm 11.0.17+8-LTS 
INFO   | jvm 1    | 2023/10/27 15:02:11 | I [C.SecureRandomProvider        ] [13:02:11]: Secure random seed generated in 2ms 
INFO   | jvm 1    | 2023/10/27 15:02:13 | 15:02:13,024 |-INFO in ch.qos.logback.classic.servlet.LogbackServletContainerInitializer@524c47b0 - Due to deployment instructions will NOT register an instance of class ch.qos.logback.classic.servlet.LogbackServletContextListener to the current web-app
INFO   | jvm 1    | 2023/10/27 15:02:13 | W [o.e.j.u.DeprecationWarning    ] [13:02:13]: Using @Deprecated Class org.eclipse.jetty.servlet.listener.ELContextCleaner 
INFO   | jvm 1    | 2023/10/27 15:02:13 | I [o.e.j.s.s.DefaultSessionIdManager] [13:02:13]: Session workerName=node0 
INFO   | jvm 1    | 2023/10/27 15:02:13 | I [o.a.w.Application             ] [13:02:13]: [WicketFilter] init: Wicket core library initializer 
INFO   | jvm 1    | 2023/10/27 15:02:13 | I [o.a.w.RequestListenerInterface] [13:02:13]: registered listener interface [RequestListenerInterface name=IBehaviorListener, method=public abstract void org.apache.wicket.behavior.IBehaviorListener.onRequest()] 
INFO   | jvm 1    | 2023/10/27 15:02:13 | I [o.a.w.RequestListenerInterface] [13:02:13]: registered listener interface [RequestListenerInterface name=IFormSubmitListener, method=public abstract void org.apache.wicket.markup.html.form.IFormSubmitListener.onFormSubmitted()] 
INFO   | jvm 1    | 2023/10/27 15:02:13 | I [o.a.w.RequestListenerInterface] [13:02:13]: registered listener interface [RequestListenerInterface name=ILinkListener, method=public abstract void org.apache.wicket.markup.html.link.ILinkListener.onLinkClicked()] 
INFO   | jvm 1    | 2023/10/27 15:02:13 | I [o.a.w.RequestListenerInterface] [13:02:13]: registered listener interface [RequestListenerInterface name=IOnChangeListener, method=public abstract void org.apache.wicket.markup.html.form.IOnChangeListener.onSelectionChanged()] 
INFO   | jvm 1    | 2023/10/27 15:02:13 | I [o.a.w.RequestListenerInterface] [13:02:13]: registered listener interface [RequestListenerInterface name=IRedirectListener, method=public abstract void org.apache.wicket.IRedirectListener.onRedirect()] 
INFO   | jvm 1    | 2023/10/27 15:02:13 | I [o.a.w.RequestListenerInterface] [13:02:13]: registered listener interface [RequestListenerInterface name=IResourceListener, method=public abstract void org.apache.wicket.IResourceListener.onResourceRequested()] 
INFO   | jvm 1    | 2023/10/27 15:02:13 | I [o.a.w.Application             ] [13:02:13]: [WicketFilter] init: Wicket extensions initializer 
INFO   | jvm 1    | 2023/10/27 15:02:13 | I [IgnitionGateway               ] [13:02:13]: Ignition[state=STOPPED] ContextState = STARTING 
INFO   | jvm 1    | 2023/10/27 15:02:14 | I [o.a.w.p.h.WebApplication      ] [13:02:14]: [WicketFilter] Started Wicket version 6.30.0 in DEPLOYMENT mode 
INFO   | jvm 1    | 2023/10/27 15:02:14 | I [IgnitionGateway               ] [13:02:14]: Starting Ignition 8.1.25 (b2023021409) 
INFO   | jvm 1    | 2023/10/27 15:02:14 | I [IgnitionGateway               ] [13:02:14]: Reloading JDBC classloader. 
INFO   | jvm 1    | 2023/10/27 15:02:14 | I [R.S.S.InternalDb              ] [13:02:14]: Internal db synchronizer disk cache initialized. State id=f536c76a-f403-47f1-a6bf-852ba46edb37 redundant-provider=internaldb
INFO   | jvm 1    | 2023/10/27 15:02:15 | I [R.StateMonitoring             ] [13:02:14]: Redundancy state changed: Role=Independent, Activity level=Active, Project state=Good, History level=Full redundant-provider=system
INFO   | jvm 1    | 2023/10/27 15:02:15 | I [o.e.j.s.h.ContextHandler      ] [13:02:15]: Started c.i.c.MainWebAppContext@372d7575{Ignition,/,file:///C:/Program%20Files/Inductive%20Automation/Ignition/webserver/webapps/main/,AVAILABLE} 
INFO   | jvm 1    | 2023/10/27 15:02:15 | I [o.e.j.s.AbstractConnector     ] [13:02:15]: Started ServerConnector@75057e50{HTTP/1.1, (http/1.1)}{0.0.0.0:8088} 
INFO   | jvm 1    | 2023/10/27 15:02:15 | I [g.InternalDatabaseManager     ] [13:02:15]: Starting up... 
INFO   | jvm 1    | 2023/10/27 15:02:15 | I [P.InternalDatabase            ] [13:02:15]: Looking for existing internal database "config.idb"... 
INFO   | jvm 1    | 2023/10/27 15:02:15 | I [P.InternalDatabase            ] [13:02:15]: ... found existing. 
INFO   | jvm 1    | 2023/10/27 15:02:16 | I [P.InternalDatabase            ] [13:02:16]: internal database "config.idb" started up successfully. 
INFO   | jvm 1    | 2023/10/27 15:02:16 | I [P.InternalDatabase            ] [13:02:16]: Registering autobackup task [owner=Internal DB Autobackup, name=internal database "config.idb"] 
INFO   | jvm 1    | 2023/10/27 15:02:16 | WARNING: An illegal reflective access operation has occurred
INFO   | jvm 1    | 2023/10/27 15:02:16 | WARNING: Illegal reflective access by com.inductiveautomation.ignition.gateway.modules.ModuleManagerImpl (file:/C:/Program%20Files/Inductive%20Automation/Ignition/lib/core/gateway/gateway-8.1.25.jar) to field java.lang.ClassLoader.usr_paths
INFO   | jvm 1    | 2023/10/27 15:02:16 | WARNING: Please consider reporting this to the maintainers of com.inductiveautomation.ignition.gateway.modules.ModuleManagerImpl
INFO   | jvm 1    | 2023/10/27 15:02:16 | WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
INFO   | jvm 1    | 2023/10/27 15:02:16 | WARNING: All illegal access operations will be denied in a future release
INFO   | jvm 1    | 2023/10/27 15:02:17 | I [o.e.j.s.AbstractConnector     ] [13:02:17]: Started ServerConnector@278df285{SSL, (ssl, http/1.1)}{0.0.0.0:8060} 
INFO   | jvm 1    | 2023/10/27 15:02:17 | I [o.e.j.s.Server                ] [13:02:17]: Started Server@4b0671ab{STARTING}[10.0.13,sto=10000] @20335ms 
INFO   | jvm 1    | 2023/10/27 15:02:17 | I [SystemInfo                    ] [13:02:17]: os.name="windows 10", os.arch="amd64". 
INFO   | jvm 1    | 2023/10/27 15:02:17 | I [SystemInfo                    ] [13:02:17]: Validating native library "ignition64"... 
INFO   | jvm 1    | 2023/10/27 15:02:17 | I [SystemInfo                    ] [13:02:17]: Validated ignition64 (ignition64.dll) 
INFO   | jvm 1    | 2023/10/27 15:02:17 | I [SystemInfo                    ] [13:02:17]: Loading native library "ignition64"... 
INFO   | jvm 1    | 2023/10/27 15:02:17 | I [SystemInfo                    ] [13:02:17]: Native library load complete 
INFO   | jvm 1    | 2023/10/27 15:02:18 | I [g.ModuleManager               ] [13:02:18]: Loading modules.... 
INFO   | jvm 1    | 2023/10/27 15:02:25 | I [A.Notification                ] [13:02:25]: Alert notification system created. 
INFO   | jvm 1    | 2023/10/27 15:02:27 | I [g.PersistentRecordSecurityLevelConfigService] [13:02:27]: Set up in 30 ms 
INFO   | jvm 1    | 2023/10/27 15:02:27 | I [g.PersistentRecordIdpAdapterConfigService] [13:02:27]: Set up in 43 ms 
INFO   | jvm 1    | 2023/10/27 15:02:27 | I [g.PersistentRecordIdpAdapterMetricsService] [13:02:27]: Set up in 46 ms 
INFO   | jvm 1    | 2023/10/27 15:02:27 | I [IgnitionGateway               ] [13:02:27]: System properties exist in IDB. Checking if system IdP is set... 
INFO   | jvm 1    | 2023/10/27 15:02:27 | I [g.OAuth2ClientManager         ] [13:02:27]: Setup complete in 44 ms 
INFO   | jvm 1    | 2023/10/27 15:02:27 | I [g.InternalDatabaseRememberedSubjects] [13:02:27]: Set up in 47 ms 
INFO   | jvm 1    | 2023/10/27 15:02:27 | I [g.OIDCProviderManager         ] [13:02:27]: Set up in 48 ms 
INFO   | jvm 1    | 2023/10/27 15:02:31 | I [g.EmailProfileManager         ] [13:02:31]: Setup complete in 124 ms 
INFO   | jvm 1    | 2023/10/27 15:02:31 | I [G.Manager                     ] [13:02:31]: Setting up trust list managers... 
INFO   | jvm 1    | 2023/10/27 15:02:31 | I [G.Manager                     ] [13:02:31]: Trust list managers setup completed in 67 ms 
INFO   | jvm 1    | 2023/10/27 15:02:31 | W [g.LicenseManager              ] [13:02:31]: Could not read license from HASP key. HASP login() failed. Last error = 14. 
INFO   | jvm 1    | 2023/10/27 15:02:31 | I [c.i.i.g.p.r.ProjectRecordConverter] [13:02:31]: Conversion finished. Elapsed time: 103 ms 
INFO   | jvm 1    | 2023/10/27 15:02:41 | I [g.ModuleManager               ] [13:02:41]: Setting up modules 
INFO   | jvm 1    | 2023/10/27 15:02:42 | I [G.L.A.AlarmNotificationService] [13:02:42]: Remote Alarm Notification Manager initialized successfully. 
INFO   | jvm 1    | 2023/10/27 15:02:42 | I [c.c.m.t.g.TransmissionGwHook  ] [13:02:42]: Creating a 'example' transmitter 
INFO   | jvm 1    | 2023/10/27 15:02:42 | E [c.c.m.t.g.TransmissionGwHook  ] [13:02:42]: Failed to update MQTTTransmission Transmitter Records 
INFO   | jvm 1    | 2023/10/27 15:02:42 | java.lang.NullPointerException: null
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at com.cirruslink.mqtt.common.util.TagUtils.configureTag(TagUtils.java:755)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at com.cirruslink.mqtt.transmission.gateway.TransmissionGwHook.maybeUpdateMTTransmitter(TransmissionGwHook.java:913)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at com.cirruslink.mqtt.transmission.gateway.TransmissionGwHook.setup(TransmissionGwHook.java:295)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at com.inductiveautomation.ignition.gateway.modules.ModuleManagerImpl$LoadedModule.setup(ModuleManagerImpl.java:2412)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at com.inductiveautomation.ignition.gateway.modules.ModuleManagerImpl.setup(ModuleManagerImpl.java:397)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at com.inductiveautomation.ignition.gateway.IgnitionGateway.startupInternal(IgnitionGateway.java:1207)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at com.inductiveautomation.ignition.gateway.redundancy.RedundancyManagerImpl.startup(RedundancyManagerImpl.java:301)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at com.inductiveautomation.ignition.gateway.IgnitionGateway.initRedundancy(IgnitionGateway.java:751)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at com.inductiveautomation.ignition.gateway.IgnitionGateway.lambda$initInternal$0(IgnitionGateway.java:685)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine$ThrowableCatchingRunnable.run(BasicExecutionEngine.java:544)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:02:42 | 	at java.base/java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:02:43 | I [c.i.i.g.o.KeyStoreManager     ] [13:02:43]: Loading KeyStore at C:\Program Files\Inductive Automation\Ignition\data\opcua\client\security\certificates.pfx 
INFO   | jvm 1    | 2023/10/27 15:02:43 | I [c.i.i.g.o.KeyStoreManager     ] [13:02:43]: Loading KeyStore at C:\Program Files\Inductive Automation\Ignition\data\opcua\server\security\certificates.pfx 
INFO   | jvm 1    | 2023/10/27 15:02:44 | I [o.e.m.o.s.s.OpcUaServer       ] [13:02:44]: Java version: 11.0.17 
INFO   | jvm 1    | 2023/10/27 15:02:44 | I [o.e.m.o.s.s.OpcUaServer       ] [13:02:44]: Eclipse Milo OPC UA Stack version: 0.6.7 
INFO   | jvm 1    | 2023/10/27 15:02:44 | I [o.e.m.o.s.s.OpcUaServer       ] [13:02:44]: Eclipse Milo OPC UA Server SDK version: 0.6.7 
INFO   | jvm 1    | 2023/10/27 15:02:50 | I [o.e.m.o.s.s.n.OpcUaNamespace  ] [13:02:50]: Loaded 2004 nodes in 2699ms. 
INFO   | jvm 1    | 2023/10/27 15:02:57 | I [QuickStart                    ] [13:02:57]: Skipped Quick Start feature; missing required module(s): 'Reporting' 
INFO   | jvm 1    | 2023/10/27 15:03:00 | I [IgnitionGateway               ] [13:03:00]: Finalizing cleanup operations on internal database... 
INFO   | jvm 1    | 2023/10/27 15:03:01 | I [g.OAuth2ClientManager         ] [13:03:00]: Startup complete in 16 ms 
INFO   | jvm 1    | 2023/10/27 15:03:01 | I [g.EmailProfileManager         ] [13:03:00]: Startup complete in 21 ms 
INFO   | jvm 1    | 2023/10/27 15:03:01 | I [g.PersistentRecordSecurityLevelConfigService] [13:03:00]: Started up in 0 ms 
INFO   | jvm 1    | 2023/10/27 15:03:01 | I [g.SecurityLevelManager        ] [13:03:00]: Started up in 4 ms 
INFO   | jvm 1    | 2023/10/27 15:03:01 | I [g.PersistentRecordIdpAdapterConfigService] [13:03:01]: Started up in 51 ms 
INFO   | jvm 1    | 2023/10/27 15:03:01 | I [g.PersistentRecordIdpAdapterMetricsService] [13:03:01]: Started up in 0 ms 
INFO   | jvm 1    | 2023/10/27 15:03:01 | I [g.IdpAdapterManager           ] [13:03:01]: Started up in 1 ms 
INFO   | jvm 1    | 2023/10/27 15:03:01 | I [g.InternalDatabaseRememberedSubjects] [13:03:01]: Started up in 19 ms 
INFO   | jvm 1    | 2023/10/27 15:03:01 | I [g.OIDCProviderManager         ] [13:03:01]: Started up in 21 ms 
INFO   | jvm 1    | 2023/10/27 15:03:01 | I [t.m.provider                  ] [13:03:01]: Tag provider initialized. Starting to load tags... provider=System
INFO   | jvm 1    | 2023/10/27 15:03:01 | I [t.m.provider                  ] [13:03:01]: Complete tag loading in 192 ms 
INFO   | jvm 1    | 2023/10/27 15:03:01 | I [t.manager                     ] [13:03:01]: Instantiating provider 'edge' of type 'STANDARD' 
INFO   | jvm 1    | 2023/10/27 15:03:01 | I [t.m.provider                  ] [13:03:01]: Tag provider initialized. Starting to load tags... provider=edge
INFO   | jvm 1    | 2023/10/27 15:03:04 | E [Scripting[system_util_tag]    ] [13:03:04]: Error browsing tags through scripting. tag=SerialNmb
INFO   | jvm 1    | 2023/10/27 15:03:04 | java.util.concurrent.ExecutionException: java.lang.Exception: provider not found: MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at java.base/java.util.concurrent.CompletableFuture.reportGet(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at java.base/java.util.concurrent.CompletableFuture.get(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at com.inductiveautomation.ignition.gateway.script.GatewayTagUtilities.browseImpl(GatewayTagUtilities.java:156)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at com.inductiveautomation.ignition.common.script.builtin.AbstractTagUtilities.browse(AbstractTagUtilities.java:396)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:190)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at com.inductiveautomation.ignition.common.script.ScriptManager$ReflectedInstanceFunction.__call__(ScriptManager.java:552)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at org.python.core.PyObject.__call__(PyObject.java:400)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at org.python.pycode._pyx1.GetSerialNmb$2(<module:SmartSolutions>:18)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at org.python.pycode._pyx1.call_function(<module:SmartSolutions>)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at org.python.core.PyTableCode.call(PyTableCode.java:173)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at org.python.core.PyBaseCode.call(PyBaseCode.java:119)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at org.python.core.PyFunction.__call__(PyFunction.java:406)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at org.python.pycode._pyx0.f$0(<expression:runScript>:1)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at org.python.pycode._pyx0.call_function(<expression:runScript>)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at org.python.core.PyTableCode.call(PyTableCode.java:173)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at org.python.core.PyCode.call(PyCode.java:18)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at org.python.core.Py.runCode(Py.java:1687)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:803)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:751)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at com.inductiveautomation.ignition.common.expressions.functions.ScriptFunction.execute(ScriptFunction.java:66)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at com.inductiveautomation.ignition.common.expressions.FunctionExpression.execute(FunctionExpression.java:69)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at com.inductiveautomation.ignition.gateway.tags.actors.factories.value.expression.ExpressionTagActorFactory$ExpressionTagActor.runInternal(ExpressionTagActorFactory.java:166)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at com.inductiveautomation.ignition.gateway.tags.actors.factories.value.AbstractExpressionActor.run(AbstractExpressionActor.java:145)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at java.base/java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:04 | Caused by: java.lang.Exception: provider not found: MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	at com.inductiveautomation.ignition.gateway.tags.model.impl.GatewayTagManagerImpl.browseAsync(GatewayTagManagerImpl.java:760)
INFO   | jvm 1    | 2023/10/27 15:03:04 | 	... 31 common frames omitted
INFO   | jvm 1    | 2023/10/27 15:03:05 | I [t.m.provider                  ] [13:03:05]: Complete tag loading in 4 seconds 
INFO   | jvm 1    | 2023/10/27 15:03:05 | I [i.UserSourceManager           ] [13:03:05]: Starting up... 
INFO   | jvm 1    | 2023/10/27 15:03:06 | I [A.S.StorageManager            ] [13:03:05]: Starting up... 
INFO   | jvm 1    | 2023/10/27 15:03:06 | I [A.N.NotificationManager       ] [13:03:06]: Starting up... 
INFO   | jvm 1    | 2023/10/27 15:03:06 | I [ImageManager                  ] [13:03:06]: Starting up... 
INFO   | jvm 1    | 2023/10/27 15:03:06 | I [Project                       ] [13:03:06]: Starting project: Hummingbird project=Hummingbird
INFO   | jvm 1    | 2023/10/27 15:03:08 | I [SessionManager                ] [13:03:08]: Starting up... 
INFO   | jvm 1    | 2023/10/27 15:03:08 | I [c.i.i.g.ScheduledBackupManager] [13:03:08]: Registered scheduled backups for cron schedule: 45 11 * * 1-5 
INFO   | jvm 1    | 2023/10/27 15:03:08 | I [AutomaticThreadDumpManager    ] [13:03:08]: Starting up... 
INFO   | jvm 1    | 2023/10/27 15:03:08 | I [c.i.i.g.m.MulticastScheduler  ] [13:03:08]: Registered MulticastScheduler on multicast address: 231.1.1.1 using send port 4445 and receive port 4446 
INFO   | jvm 1    | 2023/10/27 15:03:08 | I [g.ClientFallbackController    ] [13:03:08]: Fallback Socket Controller starting. 
INFO   | jvm 1    | 2023/10/27 15:03:10 | I [IgnitionGateway               ] [13:03:10]: Platform module services initialized. 
INFO   | jvm 1    | 2023/10/27 15:03:10 | I [G.Manager                     ] [13:03:10]: WSChannel manager started. 
INFO   | jvm 1    | 2023/10/27 15:03:10 | I [m.M.Routing                   ] [13:03:10]: Setting max proxy route depth = 0 
INFO   | jvm 1    | 2023/10/27 15:03:11 | W [g.g.WSChannelManager          ] [13:03:11]: Require Two-Way Auth setting is disabled, rendering Gateway Network connections insecure. It is strongly recommended to enable this setting to secure the connections. 
INFO   | jvm 1    | 2023/10/27 15:03:11 | E [G.TaskManager                 ] [13:03:11]: Could not load serialized tasks from disk 
INFO   | jvm 1    | 2023/10/27 15:03:11 | org.apache.commons.lang3.SerializationException: java.io.StreamCorruptedException: invalid stream header: 00000000
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at org.apache.commons.lang3.SerializationUtils.deserialize(SerializationUtils.java:195)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at com.inductiveautomation.ignition.gateway.tasks.TaskManagerImpl.startup(TaskManagerImpl.java:132)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at com.inductiveautomation.ignition.gateway.IgnitionGateway.startupInternal(IgnitionGateway.java:1320)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at com.inductiveautomation.ignition.gateway.redundancy.RedundancyManagerImpl.startup(RedundancyManagerImpl.java:301)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at com.inductiveautomation.ignition.gateway.IgnitionGateway.initRedundancy(IgnitionGateway.java:751)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at com.inductiveautomation.ignition.gateway.IgnitionGateway.lambda$initInternal$0(IgnitionGateway.java:685)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine$ThrowableCatchingRunnable.run(BasicExecutionEngine.java:544)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at java.base/java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:11 | Caused by: java.io.StreamCorruptedException: invalid stream header: 00000000

Theodorska · October 27, 2023, 1:08pm

INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at java.base/java.io.ObjectInputStream.readStreamHeader(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at java.base/java.io.ObjectInputStream.<init>(Unknown Source)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	at org.apache.commons.lang3.SerializationUtils.deserialize(SerializationUtils.java:190)
INFO   | jvm 1    | 2023/10/27 15:03:11 | 	... 12 common frames omitted
INFO   | jvm 1    | 2023/10/27 15:03:11 | I [g.ModuleManager               ] [13:03:11]: Starting up... 
INFO   | jvm 1    | 2023/10/27 15:03:11 | I [g.ModuleManager               ] [13:03:11]: Starting up module 'com.inductiveautomation.alarm-notification' v6.1.25 (b2023021409)... module-name=Alarm Notification
INFO   | jvm 1    | 2023/10/27 15:03:11 | I [g.ModuleManager               ] [13:03:11]: Starting up module 'com.inductiveautomation.taghistorian' v4.1.25 (b2023021409)... module-name=Tag Historian
INFO   | jvm 1    | 2023/10/27 15:03:11 | I [h.ModuleHook                  ] [13:03:11]: Tag Historian module started. module-name=Tag Historian
INFO   | jvm 1    | 2023/10/27 15:03:11 | I [g.ModuleManager               ] [13:03:11]: Starting up module 'com.cirruslink.mqtt.transmission.gateway' v4.0.13 (b2022092123)... module-name=MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:11 | I [c.c.c.r.RecordService         ] [13:03:11]: Creating Record Service module-name=MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:11 | I [c.c.c.r.RecordService         ] [13:03:11]: Adding ModuleObserver com.cirruslink.common.record.RecordService@5b93231f module-name=MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:11 | I [c.c.c.r.RecordService         ] [13:03:11]: Registering listener with ID 2046784d-e74d-416b-8067-e4bef85742b6 module-name=MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:12 | I [t.m.provider                  ] [13:03:12]: Tag provider initialized. Starting to load tags... module-name=MQTT Transmission, provider=MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:12 | I [t.m.provider                  ] [13:03:12]: Complete tag loading in 98 ms module-name=MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:13 | I [c.c.m.t.g.TransmissionGwHook  ] [13:03:12]: Adding MQTT Transmission bundle module-name=MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:13 | I [c.c.m.c.g.LicenseStateUtils   ] [13:03:13]: License is activated module-name=MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:13 | I [c.c.m.t.g.TransmissionGwHook  ] [13:03:13]: Stopping Transmitters module-name=MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:13 | W [c.c.m.t.g.ClientsManager      ] [13:03:13]: Not stopping clients, they are not running module-name=MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:13 | I [c.c.m.t.g.TransmissionGwHook  ] [13:03:13]: Starting Transmitters module-name=MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:13 | W [c.c.m.t.g.ClientsManager      ] [13:03:13]: Not starting clients, MQTT Transmission is not enabled module-name=MQTT Transmission
INFO   | jvm 1    | 2023/10/27 15:03:13 | I [g.ModuleManager               ] [13:03:13]: Starting up module 'com.inductiveautomation.opcua' v9.1.25 (b2023021409)... module-name=OPC-UA
INFO   | jvm 1    | 2023/10/27 15:03:13 | I [o.e.m.o.s.s.UaStackServer     ] [13:03:13]: Binding endpoint opc.tcp://CP-65194A:62541 to localhost:62541 [Basic256Sha256/SignAndEncrypt] module-name=OPC-UA
INFO   | jvm 1    | 2023/10/27 15:03:14 | I [o.e.m.o.s.s.UaStackServer     ] [13:03:13]: Binding endpoint opc.tcp://CP-65194A:62541/discovery to localhost:62541 [None/None] module-name=OPC-UA
INFO   | jvm 1    | 2023/10/27 15:03:14 | I [o.e.m.o.s.s.UaStackServer     ] [13:03:13]: Binding endpoint opc.tcp://localhost:62541 to localhost:62541 [Basic256Sha256/SignAndEncrypt] module-name=OPC-UA
INFO   | jvm 1    | 2023/10/27 15:03:14 | I [o.e.m.o.s.s.UaStackServer     ] [13:03:13]: Binding endpoint opc.tcp://localhost:62541/discovery to localhost:62541 [None/None] module-name=OPC-UA
INFO   | jvm 1    | 2023/10/27 15:03:14 | I [o.e.m.o.s.s.UaStackServer     ] [13:03:13]: Binding endpoint opc.tcp://127.0.0.1:62541 to localhost:62541 [Basic256Sha256/SignAndEncrypt] module-name=OPC-UA
INFO   | jvm 1    | 2023/10/27 15:03:14 | I [o.e.m.o.s.s.UaStackServer     ] [13:03:13]: Binding endpoint opc.tcp://127.0.0.1:62541/discovery to localhost:62541 [None/None] module-name=OPC-UA
INFO   | jvm 1    | 2023/10/27 15:03:14 | I [c.i.i.g.o.s.IgnitionOpcUaServer] [13:03:13]: Application URI: urn:inductiveautomation:ignition:opcua:server:d93d1650-9347-44e7-956f-b0cd6782f51b module-name=OPC-UA
INFO   | jvm 1    | 2023/10/27 15:03:14 | I [OpcUaModule                   ] [13:03:14]: Routes mounted module-name=OPC-UA
INFO   | jvm 1    | 2023/10/27 15:03:14 | I [g.ModuleManager               ] [13:03:14]: Starting up module 'com.inductiveautomation.perspective' v2.1.25 (b2023021409)... module-name=Perspective
INFO   | jvm 1    | 2023/10/27 15:03:16 | I [o.e.m.o.s.c.OpcUaClient       ] [13:03:15]: Java version: 11.0.17 
INFO   | jvm 1    | 2023/10/27 15:03:16 | I [o.e.m.o.s.c.OpcUaClient       ] [13:03:15]: Eclipse Milo OPC UA Stack version: 0.6.7 
INFO   | jvm 1    | 2023/10/27 15:03:16 | I [o.e.m.o.s.c.OpcUaClient       ] [13:03:15]: Eclipse Milo OPC UA Client SDK version: 0.6.7 
INFO   | jvm 1    | 2023/10/27 15:03:16 | I [g.ModuleManager               ] [13:03:16]: Starting up module 'com.inductiveautomation.opcua.drivers.tcpudp' v6.1.25 (b2023021409)... module-name=UDP and TCP Drivers
INFO   | jvm 1    | 2023/10/27 15:03:16 | I [g.ModuleManager               ] [13:03:16]: Starting up module 'com.inductiveautomation.eam' v4.1.25 (b2023021409)... module-name=Enterprise Administration
INFO   | jvm 1    | 2023/10/27 15:03:16 | I [IgnitionGateway               ] [13:03:16]: Ignition[state=STARTING] ContextState = RUNNING 
INFO   | jvm 1    | 2023/10/27 15:03:16 | I [IgnitionGateway               ] [13:03:16]: Gateway started in 62 seconds.

Theodorska · October 27, 2023, 1:09pm

Since we cannot change our hardware, we are trying to optimize the time it takes from our HMI computer is turned on, until the gateway is live.

pturmel · October 27, 2023, 1:12pm

You should consider switching to Linux, then. In my experience, it can be trimmed considerably for faster boot times and better performance overall.

Kevin.Herron · October 27, 2023, 1:16pm

Hmm, I don't see anything too obvious. Might just be slow hardware, in particular very slow disk access.

Kevin.Herron · October 27, 2023, 1:21pm

9 seconds just to get from JVM launch to logging configuration loaded...

STATUS | wrapper  | 2023/10/27 15:01:56 | Launching a JVM...
INFO   | jvm 1    | 2023/10/27 15:01:59 | WrapperManager: Initializing...
INFO   | jvm 1    | 2023/10/27 15:02:05 | 15:02:05,191 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]

7 seconds here, loading modules from disk.

INFO   | jvm 1    | 2023/10/27 15:02:18 | I [g.ModuleManager               ] [13:02:18]: Loading modules.... 
INFO   | jvm 1    | 2023/10/27 15:02:25 | I [A.Notification                ] [13:02:25]: Alert notification system created.

Another 10 seconds here, a ScriptManager getting created, could also be disk intensive as it reads/copies pylib around.

INFO   | jvm 1    | 2023/10/27 15:02:31 | I [c.i.i.g.p.r.ProjectRecordConverter] [13:02:31]: Conversion finished. Elapsed time: 103 ms 
INFO   | jvm 1    | 2023/10/27 15:02:41 | I [g.ModuleManager               ] [13:02:41]: Setting up modules

6 seconds here, probably CPU and disk intensive:

INFO   | jvm 1    | 2023/10/27 15:02:44 | I [o.e.m.o.s.s.OpcUaServer       ] [13:02:44]: Eclipse Milo OPC UA Server SDK version: 0.6.7 
INFO   | jvm 1    | 2023/10/27 15:02:50 | I [o.e.m.o.s.s.n.OpcUaNamespace  ] [13:02:50]: Loaded 2004 nodes in 2699ms.

It seems like you have terribly slow disk access if not also CPU. Get better hardware or live with it, probably

Does this mean it's some kind of virtual environment?

michael.flagler · October 27, 2023, 2:34pm

100% agree with Linux (Kubuntu to be exact). I actually haven't set up an edge unit with Windows, but I know we have a few going out soon with Windows as it was customer supplied hardware. Everything I spec on Edge for panel PCs is all Linux based and even though they're typically slower CPUs and storage, the system is usually loaded fairly fast.

nminchin · October 28, 2023, 10:43pm

Can you tell us the hardware you're using? We've used the Atom CPUs in the past with cpu passmarks of low 800s and they're shockingly slow even as mere clients. Hate to see what they're like as servers as well!
It's not really a hard and fast rule, but we now use CPUs for clients >2000 passmarks, usually around 6000. That's generally pretty good for edge as well