Merge pull request #10452 from smatvienko-tb/feature/nashorn-memory-limit

Nashorn js executor sandbox memory limit

application/src/main/resources/thingsboard.yml

@@ -866,6 +866,8 @@ js:
     monitor_thread_pool_size: "${LOCAL_JS_SANDBOX_MONITOR_THREAD_POOL_SIZE:4}"
     # Maximum CPU time in milliseconds allowed for script execution
     max_cpu_time: "${LOCAL_JS_SANDBOX_MAX_CPU_TIME:8000}"
+    # Maximum memory in Bytes which JS executor thread can allocate (approximate calculation). A zero memory limit in combination with a non-zero CPU limit is not recommended due to the implementation of Nashorn 0.4.2. 100MiB is effectively unlimited for most cases
+    max_memory: "${LOCAL_JS_SANDBOX_MAX_MEMORY:104857600}"
     # Maximum allowed JavaScript execution errors before JavaScript will be blacklisted
     max_errors: "${LOCAL_JS_SANDBOX_MAX_ERRORS:3}"
     # JS Eval max request timeout. 0 - no timeout

application/src/test/java/org/thingsboard/server/service/script/NashornJsInvokeServiceTest.java

@@ -15,23 +15,29 @@
  */
 package org.thingsboard.server.service.script;
 
-import com.fasterxml.jackson.databind.node.ObjectNode;
+import com.google.common.util.concurrent.Futures;
+import com.google.common.util.concurrent.ListenableFuture;
+import lombok.extern.slf4j.Slf4j;
 import org.junit.Assert;
 import org.junit.jupiter.api.Test;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.beans.factory.annotation.Value;
 import org.springframework.test.context.TestPropertySource;
-import org.thingsboard.common.util.JacksonUtil;
+import org.thingsboard.common.util.TbStopWatch;
 import org.thingsboard.script.api.ScriptType;
 import org.thingsboard.script.api.js.NashornJsInvokeService;
 import org.thingsboard.server.common.data.id.TenantId;
 import org.thingsboard.server.controller.AbstractControllerTest;
 import org.thingsboard.server.dao.service.DaoSqlTest;
 
+import java.util.ArrayList;
+import java.util.List;
 import java.util.UUID;
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.TimeUnit;
+import java.util.concurrent.TimeoutException;
 
+import static org.assertj.core.api.Assertions.assertThat;
 import static org.assertj.core.api.Assertions.assertThatThrownBy;
 import static org.thingsboard.server.common.data.msg.TbMsgType.POST_TELEMETRY_REQUEST;
 
@@ -41,8 +47,9 @@ import static org.thingsboard.server.common.data.msg.TbMsgType.POST_TELEMETRY_RE
         "js.max_script_body_size=50",
         "js.max_total_args_size=50",
         "js.max_result_size=50",
-        "js.local.max_errors=2"
+        "js.local.max_errors=2",
 })
+@Slf4j
 class NashornJsInvokeServiceTest extends AbstractControllerTest {
 
     @Autowired
@@ -56,23 +63,64 @@ class NashornJsInvokeServiceTest extends AbstractControllerTest {
         int iterations = 1000;
         UUID scriptId = evalScript("return msg.temperature > 20");
         // warmup
-        ObjectNode msg = JacksonUtil.newObjectNode();
+        log.info("Warming up 1000 times...");
-        for (int i = 0; i < 100; i++) {
+        var warmupWatch = TbStopWatch.create();
-            msg.put("temperature", i);
+        for (int i = 0; i < 1000; i++) {
             boolean expected = i > 20;
-            boolean result = Boolean.valueOf(invokeScript(scriptId, JacksonUtil.toString(msg)));
+            boolean result = Boolean.parseBoolean(invokeScript(scriptId, "{\"temperature\":" + i + "}"));
             Assert.assertEquals(expected, result);
         }
-        long startTs = System.currentTimeMillis();
+        log.info("Warming up finished in {} ms", warmupWatch.stopAndGetTotalTimeMillis());
+        log.info("Starting performance test...");
+        var watch = TbStopWatch.create();
         for (int i = 0; i < iterations; i++) {
-            msg.put("temperature", i);
             boolean expected = i > 20;
-            boolean result = Boolean.valueOf(invokeScript(scriptId, JacksonUtil.toString(msg)));
+            boolean result = Boolean.parseBoolean(invokeScript(scriptId, "{\"temperature\":" + i + "}"));
+            log.debug("asserting result");
             Assert.assertEquals(expected, result);
         }
-        long duration = System.currentTimeMillis() - startTs;
+        long duration = watch.stopAndGetTotalTimeMillis();
-        System.out.println(iterations + " invocations took: " + duration + "ms");
+        log.info("Performance test with {} invocations took: {} ms", iterations, duration);
-        Assert.assertTrue(duration < TimeUnit.MINUTES.toMillis(4));
+        assertThat(duration).as("duration ms")
+                .isLessThan(TimeUnit.MINUTES.toMillis(1)); // effective exec time is about 500ms
+    }
+
+    @Test
+    void givenSimpleScriptMultiThreadTestPerformance() throws ExecutionException, InterruptedException, TimeoutException {
+        int iterations = 1000*4;
+        List<ListenableFuture<Object>> futures = new ArrayList<>(iterations);
+        UUID scriptId = evalScript("return msg.temperature > 20 ;");
+        // warmup
+        log.info("Warming up 1000 times...");
+
+        var warmupWatch = TbStopWatch.create();
+        for (int i = 0; i < 1000; i++) {
+            futures.add(invokeScriptAsync(scriptId, "{\"temperature\":" + i + "}"));
+        }
+        List<Object> results = Futures.allAsList(futures).get(1, TimeUnit.MINUTES);
+        for (int i = 0; i < 1000; i++) {
+            boolean expected = i > 20;
+            boolean result = Boolean.parseBoolean(results.get(i).toString());
+            Assert.assertEquals(expected, result);
+        }
+        log.info("Warming up finished in {} ms", warmupWatch.stopAndGetTotalTimeMillis());
+        futures.clear();
+
+        log.info("Starting performance test...");
+        var watch = TbStopWatch.create();
+        for (int i = 0; i < iterations; i++) {
+            futures.add(invokeScriptAsync(scriptId, "{\"temperature\":" + i + "}"));
+        }
+        results = Futures.allAsList(futures).get(1, TimeUnit.MINUTES);
+        for (int i = 0; i < iterations; i++) {
+            boolean expected = i > 20;
+            boolean result = Boolean.parseBoolean(results.get(i).toString());
+            Assert.assertEquals(expected, result);
+        }
+        long duration = watch.stopAndGetTotalTimeMillis();
+        log.info("Performance test with {} invocations took: {} ms", iterations, duration);
+        assertThat(duration).as("duration ms")
+                .isLessThan(TimeUnit.MINUTES.toMillis(1)); // effective exec time is about 500ms
     }
 
     @Test
@@ -122,7 +170,11 @@ class NashornJsInvokeServiceTest extends AbstractControllerTest {
     }
 
     private String invokeScript(UUID scriptId, String msg) throws ExecutionException, InterruptedException {
-        return invokeService.invokeScript(TenantId.SYS_TENANT_ID, null, scriptId, msg, "{}", POST_TELEMETRY_REQUEST.name()).get().toString();
+        return invokeScriptAsync(scriptId, msg).get().toString();
+    }
+
+    private ListenableFuture<Object> invokeScriptAsync(UUID scriptId, String msg) {
+        return invokeService.invokeScript(TenantId.SYS_TENANT_ID, null, scriptId, msg, "{}", POST_TELEMETRY_REQUEST.name());
     }
 
 }

application/src/test/resources/logback-test.xml

@@ -16,7 +16,7 @@
     <logger name="org.testcontainers" level="INFO" />
     <logger name="org.eclipse.leshan" level="INFO"/>
     <logger name="org.thingsboard.server.controller.AbstractWebTest" level="INFO"/>
-
+    <logger name="org.thingsboard.server.service.script" level="INFO"/>
 
     <!-- mute TelemetryEdgeSqlTest that causes a lot of randomly generated errors -->
     <logger name="org.thingsboard.server.service.edge.rpc.EdgeGrpcSession" level="OFF"/>

common/script/script-api/src/main/java/org/thingsboard/script/api/AbstractScriptInvokeService.java

@@ -145,14 +145,14 @@ public abstract class AbstractScriptInvokeService implements ScriptInvokeService
                 log.trace("[{}] InvokeScript uuid {} with timeout {}ms", tenantId, scriptId, getMaxInvokeRequestsTimeout());
                 var task = doInvokeFunction(scriptId, args);
 
-                var resultFuture = Futures.transformAsync(task.getResultFuture(), output -> {
+                var resultFuture = Futures.transform(task.getResultFuture(), output -> {
                     String result = JacksonUtil.toString(output);
                     if (resultSizeExceeded(result)) {
                         throw new TbScriptException(scriptId, TbScriptException.ErrorCode.OTHER, null, new RuntimeException(
                                 format("Script invocation result exceeds maximum allowed size of %s symbols", getMaxResultSize())
                         ));
                     }
-                    return Futures.immediateFuture(output);
+                    return output;
                 }, MoreExecutors.directExecutor());
 
                 return withTimeoutAndStatsCallback(scriptId, task, resultFuture, invokeCallback, getMaxInvokeRequestsTimeout());

common/script/script-api/src/main/java/org/thingsboard/script/api/js/NashornJsInvokeService.java

@@ -41,7 +41,6 @@ import java.util.Optional;
 import java.util.UUID;
 import java.util.concurrent.Executor;
 import java.util.concurrent.ExecutorService;
-import java.util.concurrent.Executors;
 import java.util.concurrent.locks.ReentrantLock;
 
 @Slf4j
@@ -62,9 +61,12 @@ public class NashornJsInvokeService extends AbstractJsInvokeService {
     @Value("${js.local.monitor_thread_pool_size}")
     private int monitorThreadPoolSize;
 
-    @Value("${js.local.max_cpu_time}")
+    @Value("${js.local.max_cpu_time:8000}") // 8 seconds
     private long maxCpuTime;
 
+    @Value("${js.local.max_memory:104857600}") // 100 MiB
+    private long maxMemory;
+
     @Getter
     @Value("${js.local.max_errors}")
     private int maxErrors;
@@ -107,12 +109,13 @@ public class NashornJsInvokeService extends AbstractJsInvokeService {
     @Override
     public void init() {
         super.init();
-        jsExecutor = MoreExecutors.listeningDecorator(Executors.newWorkStealingPool(jsExecutorThreadPoolSize));
+        jsExecutor = MoreExecutors.listeningDecorator(ThingsBoardExecutors.newWorkStealingPool(jsExecutorThreadPoolSize, "nashorn-js-executor"));
         if (useJsSandbox) {
             sandbox = NashornSandboxes.create();
             monitorExecutorService = ThingsBoardExecutors.newWorkStealingPool(monitorThreadPoolSize, "nashorn-js-monitor");
             sandbox.setExecutor(monitorExecutorService);
             sandbox.setMaxCPUTime(maxCpuTime);
+            sandbox.setMaxMemory(maxMemory);
             sandbox.allowNoBraces(false);
             sandbox.allowLoadFunctions(true);
             sandbox.setMaxPreparedStatements(30);

pom.xml

@@ -103,7 +103,7 @@
             org/thingsboard/server/extensions/core/plugin/telemetry/gen/**/*
         </sonar.exclusions>
         <elasticsearch.version>5.0.2</elasticsearch.version>
-        <delight-nashorn-sandbox.version>0.2.1</delight-nashorn-sandbox.version>
+        <delight-nashorn-sandbox.version>0.4.2</delight-nashorn-sandbox.version>
         <nashorn-core.version>15.4</nashorn-core.version>
         <!-- IMPORTANT: If you change the version of the kafka client, make sure to synchronize our overwritten implementation of the
         org.apache.kafka.common.network.NetworkReceive class in the application module. It addresses the issue https://issues.apache.org/jira/browse/KAFKA-4090.