Scada-LTS icon indicating copy to clipboard operation
Scada-LTS copied to clipboard

Published 20 hours ago • verified publisher icon SCADA-LTS

ScadaLTS freeze after a few hours

Open nduvernois opened this issue 2 years ago • 6 comments

Once ScadaLTS is started, it freezes = no possibility to access to it either from distant terminal, or from server itself. I can't access to Tomcat management page either. Data acquisition from the data sources is also stopped. Normal behaviour is recovered by stopping & restarting Tomcat with tomcat9.exe.

Configuration

  • OS: Windows Server 2016
  • Browser : Chrome
  • Version ScadaLTS 2.6.13, Apache Tomcat 9.0.59, MySQL 5.7.19 Note : on the same server, I'm running ScadaBR 1.12.4 with Apache Tomcat 6 & MySQL 5.6

Additional context 15 493 datapoints, 302 datasources in the database imported from Scada 1.12.4

nduvernois avatar Mar 28 '22 15:03 nduvernois

Hey @nduvernois, I recommend

  1. Create an Internal Data Source and log all points, this provides valuable diagnostic data;
  2. Check how many records there are in the events table (we recommend not to exceed 5,000);
  3. Check how many records there are in the pointValues ​​table;
  4. Tomcat logs could be helpful;
  5. What hardware resources are available for the application?
  6. What are the values ​​of events and dataPoints for the ScadaBR version?
  7. Is a database restart required when a fault occurs?
  8. Is it a recurring problem or did it occur once? Can you recreate it?
  9. Could you try version 2.6.10 along with the new database import?
  10. What type of Data Sources are they?
  11. What's set in: "System Settings" -> "Datapoint runtime value synchronized"?

Limraj avatar Mar 28 '22 15:03 Limraj

Hello

As of right now, from MySQL Workbench queries

  • in my ScadaLTS : 821 297 events, 15 394 datapoints, 302 datasources. No answer for pointvalues because "error code 2013 Lost connection to MySQL server during query"
  • in my ScadaBR : 811 596 events, 304 data sources, 15 420 datapoints. No answer for pointvalues because "error code 2013 Lost connection to MySQL server during query" Update rate : typically from 1 to 5 minutes. Yes, I know, I should purge my list of events. Precision: in order to have both ScadaBR & ScadaLTS running on the same server : Tomcat 6 is on port 8080, MySQL5.6 on port 3306, whereas Tomcat 9 in on port 8443 ans MySQL5.7 on port 3308 I transfered data from ScadaBR to ScadaLTS using mysqldump (the dump itself takes 10-15 minutes, the import from the SQL scripts takes about 10 hours). I have never tested database import directly from ScadaLTS. Hardware resources : I'm working on an almost dedicated server : Lenovo SR650 with 2 Intel Xeon, 80 GB RAM, SSD disks. The only other program here is a license server. I don't need to restart database, only Tomcat restart is necessary. The problem is 100% repeatable. It just happens systematically. Type of Datasources : 130 to 140 Bacnet IP (all but 1 are deactivated, I will create a separate issue for this), about 45 Modbus IP, 14 SNMP, quite a few Meta Sources for script purposes, and a few virtual ones (not all active, for testing purpose)

"Datapoint runtime value synchronized" : not checked (just because not checked by default) UI performance : high purge events older than 6 years (that's my needs from a french law) purge report instances older than 6 years

Internal Data Source : what do you want me to record ? Points values to be written ? Point value write threads ?

nduvernois avatar Mar 29 '22 07:03 nduvernois

Some logs: from commons-daemon: [2022-03-29 08:56:29] [info] [12136] Apache Commons Daemon procrun (1.2.4.0 64-bit) started. [2022-03-29 08:56:29] [info] [12136] Running Service 'Tomcat9'... [2022-03-29 08:56:29] [info] [ 8272] Starting service... [2022-03-29 08:56:31] [info] [ 8272] Service started in 1343 milliseconds.

from catalina: 29-Mar-2022 08:56:30.841 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name: Apache Tomcat/9.0.59 29-Mar-2022 08:56:30.841 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built: Feb 21 2022 21:01:10 UTC 29-Mar-2022 08:56:30.841 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 9.0.59.0 29-Mar-2022 08:56:30.841 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name: Windows Server 2016 29-Mar-2022 08:56:30.841 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version: 10.0 29-Mar-2022 08:56:30.841 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture: amd64 29-Mar-2022 08:56:30.841 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home: C:\Program Files\Java\jdk-11.0.13 29-Mar-2022 08:56:30.841 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version: 11.0.13+10-LTS-370 29-Mar-2022 08:56:30.841 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor: Oracle Corporation 29-Mar-2022 08:56:30.841 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE: C:\Program Files\Apache Software Foundation\Tomcat 9.0 29-Mar-2022 08:56:30.841 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME: C:\Program Files\Apache Software Foundation\Tomcat 9.0 29-Mar-2022 08:56:30.872 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=C:\Program Files\Apache Software Foundation\Tomcat 9.0 29-Mar-2022 08:56:30.872 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=C:\Program Files\Apache Software Foundation\Tomcat 9.0 29-Mar-2022 08:56:30.872 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=C:\Program Files\Apache Software Foundation\Tomcat 9.0\temp 29-Mar-2022 08:56:30.872 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager 29-Mar-2022 08:56:30.872 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=C:\Program Files\Apache Software Foundation\Tomcat 9.0\conf\logging.properties 29-Mar-2022 08:56:30.872 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED 29-Mar-2022 08:56:30.872 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED 29-Mar-2022 08:56:30.872 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED 29-Mar-2022 08:56:30.872 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: exit 29-Mar-2022 08:56:30.872 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: abort 29-Mar-2022 08:56:30.872 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xms128m 29-Mar-2022 08:56:30.872 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xmx256m 29-Mar-2022 08:56:30.872 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent The Apache Tomcat Native library which allows using OpenSSL was not found on the java.library.path: [C:\Program Files\Apache Software Foundation\Tomcat 9.0\bin;C:\Windows\Sun\Java\bin;C:\Windows\system32;C:\Windows;C:\Program Files\Java\jdk-11.0.13\bin;C:\Program Files\Common Files\Oracle\Java\javapath;C:\Program Files (x86)\Common Files\Oracle\Java\javapath;C:\ProgramData\Oracle\Java\javapath;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0;C:\Program Files\Mellanox\MLNX_WinOF2\Management Tools;C:\Program Files\Mellanox\MLNX_WinOF2\Performance Tools;C:\Program Files\Mellanox\MLNX_WinOF2\Diagnostic Tools;C:\Program Files\Mellanox\MLNX_VPI\IB\Tools;%USERPROFILE%.dnx\bin;C:\Program Files\Microsoft DNX\Dnvm;C:\Windows\ServiceProfiles\LocalService\AppData\Local\Microsoft\WindowsApps;.] 29-Mar-2022 08:56:31.232 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8443"] 29-Mar-2022 08:56:31.263 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [664] milliseconds 29-Mar-2022 08:56:31.341 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina] 29-Mar-2022 08:56:31.341 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.59] 29-Mar-2022 08:56:31.372 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive [C:\Program Files\Apache Software Foundation\Tomcat 9.0\webapps\ScadaBR.war] 29-Mar-2022 08:56:53.688 WARNING [main] org.apache.tomcat.jdbc.pool.ConnectionPool.checkPoolConfiguration maxIdle is larger than maxActive, setting maxIdle to: 80 29-Mar-2022 08:56:54.017 INFO [main] java.util.ArrayList.forEach Name = scadabr Ignoring unknown property: value of "DB Connection" for "description" property 29-Mar-2022 08:56:54.314 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time. 29-Mar-2022 08:57:37.023 WARNING [pool-4-thread-3] org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport.reportSlowQuery Slow Query Report SQL=select pv.id,pv.dataPointId, pv.dataType, pv.pointValue, pv.ts, pva.textPointValueShort, pva.textPointValueLong, pva.sourceType, pva.sourceId, us.username from pointValues pv left join pointValueAnnotations pva on pv.id=pva.pointValueId left join users us on pva.sourceId = us.id where pv.dataPointId=? and pv.ts>=? and pv.ts<? order by ts; time=1719 ms; And after this line, lots of "reportSlowQuery"

In localhost: 29-Mar-2022 08:54:32.776 INFO [Thread-24] org.apache.catalina.core.ApplicationContext.log Closing Spring root WebApplicationContext 29-Mar-2022 08:56:54.360 INFO [main] org.apache.catalina.core.ApplicationContext.log No Spring WebApplicationInitializer types detected on classpath 29-Mar-2022 08:56:55.454 INFO [main] org.apache.catalina.core.ApplicationContext.log Initializing Spring root WebApplicationContext 29-Mar-2022 08:57:42.024 INFO [main] org.apache.catalina.core.ApplicationContext.log Initializing Spring FrameworkServlet 'springDispatcher' 29-Mar-2022 09:12:34.497 SEVERE [http-nio-8443-exec-7] org.apache.catalina.core.ApplicationDispatcher.invoke Servlet.service() for servlet [jsp] threw exception java.lang.OutOfMemoryError: Java heap space

nduvernois avatar Mar 29 '22 07:03 nduvernois

Hello, debugging this issue requires direct access to the server, both MySQL as well Tomcat (at least logs and via JMX). Please contact us via [email protected]

SoftQ avatar Mar 29 '22 08:03 SoftQ

Here we are, it is now frozen. In catalina log : many many Slow Query lines, and also this: 29-Mar-2022 09:38:48.033 SEVERE [Catalina-utility-2] org.apache.coyote.AbstractProtocol.startAsyncTimeout Error processing async timeouts java.util.concurrent.ExecutionException: java.lang.OutOfMemoryError: Java heap space at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122) at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:191) at org.apache.coyote.AbstractProtocol.startAsyncTimeout(AbstractProtocol.java:632) at org.apache.coyote.AbstractProtocol.lambda$start$0(AbstractProtocol.java:617) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.base/java.lang.Thread.run(Thread.java:834) Caused by: java.lang.OutOfMemoryError: Java heap space I don't know whether this is or not the exact moment when it froze.

nothing in localhost log since 9:12 (see in initial problem description). nothing either in tomcat9-stderr since 9:12 and in tomcat9-stdout ERROR 2022-03-29T09:11:05,296 (com.serotonin.mango.rt.maint.BackgroundProcessing$2.run:83) - Error in work item: java.lang.OutOfMemoryError: Java heap space at java.base/java.util.Arrays.copyOf(Arrays.java:3689) at java.base/java.util.ArrayList.grow(ArrayList.java:238) at java.base/java.util.ArrayList.grow(ArrayList.java:243) at java.base/java.util.ArrayList.add(ArrayList.java:486) at java.base/java.util.ArrayList.add(ArrayList.java:499) at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:3372) at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:464) at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:3070) at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:2338) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2725) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2465) at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1915) at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2023) at jdk.internal.reflect.GeneratedMethodAccessor55.invoke(Unknown Source) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.apache.tomcat.jdbc.pool.interceptor.AbstractQueryReport$StatementProxy.invoke(AbstractQueryReport.java:215) at com.sun.proxy.$Proxy77.executeQuery(Unknown Source) at jdk.internal.reflect.GeneratedMethodAccessor55.invoke(Unknown Source) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.apache.tomcat.jdbc.pool.interceptor.AbstractQueryReport$StatementProxy.invoke(AbstractQueryReport.java:215) at com.sun.proxy.$Proxy77.executeQuery(Unknown Source) at jdk.internal.reflect.GeneratedMethodAccessor55.invoke(Unknown Source) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:118) at com.sun.proxy.$Proxy77.executeQuery(Unknown Source) at jdk.internal.reflect.GeneratedMethodAccessor55.invoke(Unknown Source) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at net.bull.javamelody.JdbcWrapper.doExecute(JdbcWrapper.java:422)

WARN 2022-03-29T09:11:34,754 (com.serotonin.mango.rt.dataSource.PollingDataSource.scheduleTimeout:63) - B501-TGBT3: poll at 2022/03/29 09:11:34 aborted because a previous poll started at 2022/03/29 09:05:34 is still running WARN 2022-03-29T09:11:34,754 (com.serotonin.mango.rt.dataSource.PollingDataSource.scheduleTimeout:63) - TR2: poll at 2022/03/29 09:11:34 aborted because a previous poll started at 2022/03/29 09:09:34 is still running INFO 2022-03-29T09:12:10,743 (com.serotonin.mango.rt.dataSource.snmp.SnmpDataSourceRT.increaseCounterIfErrorExistOrNoResponseAppear:299) - Counter Empty Responses Or Responses With Error: 8

nduvernois avatar Mar 29 '22 08:03 nduvernois

With my material setup, this issue nows seems to be solved by configuring my.ini with this setting : innodb_buffer_pool_size=2G (I have enough RAM to afford this). However, ScadaLTS remains slow (= report sent with delay, metadata calculated with delay, ...)

nduvernois avatar Apr 05 '22 09:04 nduvernois