From f21e118a4401b25281410894f104f15942326fb5 Mon Sep 17 00:00:00 2001 From: timothy65535 Date: Tue, 17 Aug 2021 16:59:43 +0800 Subject: [PATCH] [KYUUBI #940] Fix process-logger-capture thread consumes high usage CPU ### _Why are the changes needed?_ After several benchmarks in the offline environment, kyuubi consumes a lot of CPU. ``` [bigdata]$ jps 3188 Main 6036 Jps 4189 KyuubiServer [bigdata]$ top top - 09:34:21 up 23 min, 1 user, load average: 10.67, 7.85, 4.98 Tasks: 320 total, 1 running, 319 sleeping, 0 stopped, 0 zombie %Cpu(s): 48.2 us, 23.9 sy, 0.0 ni, 27.4 id, 0.0 wa, 0.5 hi, 0.0 si, 0.0 st MiB Mem : 15806.0 total, 4738.4 free, 6085.0 used, 4982.5 buff/cache MiB Swap: 0.0 total, 0.0 free, 0.0 used. 9306.5 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 4189 bigdata 20 0 10.1g 311272 22484 S 633.3 1.9 48:12.21 java ``` ``` Threads: 53 total, 6 running, 47 sleeping, 0 stopped, 0 zombie %Cpu(s): 31.9 us, 22.8 sy, 0.0 ni, 44.8 id, 0.0 wa, 0.4 hi, 0.0 si, 0.0 st MiB Mem : 15806.0 total, 4770.5 free, 6052.9 used, 4982.5 buff/cache MiB Swap: 0.0 total, 0.0 free, 0.0 used. 9338.7 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 5222 bigdata 20 0 10.1g 311272 22484 R 99.3 1.9 10:00.91 process-logger- 5044 bigdata 20 0 10.1g 311272 22484 R 99.0 1.9 10:03.98 process-logger- 4730 bigdata 20 0 10.1g 311272 22484 R 98.3 1.9 10:13.24 process-logger- 4911 bigdata 20 0 10.1g 311272 22484 R 98.3 1.9 10:06.42 process-logger- 4523 bigdata 20 0 10.1g 311272 22484 R 98.0 1.9 10:41.55 process-logger- 5769 bigdata 20 0 10.1g 311272 22484 R 96.7 1.9 2:46.80 process-logger- ``` ### _How was this patch tested?_ - [ ] Add some test cases that check the changes thoroughly including negative and positive cases if possible - [ ] Add screenshots for manual tests if appropriate - [x] [Run test](https://kyuubi.readthedocs.io/en/latest/develop_tools/testing.html#running-tests) locally before make a pull request Closes #941 from timothy65535/ky-940. Closes #940 331b9423 [timothy65535] [KYUUBI #940] Fix process-logger-capture thread consumes high usage CPU Authored-by: timothy65535 Signed-off-by: ulysses-you --- .../apache/kyuubi/engine/ProcBuilder.scala | 29 ++++++++++--------- 1 file changed, 16 insertions(+), 13 deletions(-) diff --git a/kyuubi-server/src/main/scala/org/apache/kyuubi/engine/ProcBuilder.scala b/kyuubi-server/src/main/scala/org/apache/kyuubi/engine/ProcBuilder.scala index ed64fa2ce..41d7f8726 100644 --- a/kyuubi-server/src/main/scala/org/apache/kyuubi/engine/ProcBuilder.scala +++ b/kyuubi-server/src/main/scala/org/apache/kyuubi/engine/ProcBuilder.scala @@ -110,24 +110,27 @@ trait ProcBuilder { val redirect: Runnable = { () => try { val maxErrorSize = conf.get(KyuubiConf.ENGINE_ERROR_MAX_SIZE) - var line: String = reader.readLine while (true) { - if (containsIgnoreCase(line, "Exception:") && + if (reader.ready()) { + var line: String = reader.readLine + if (containsIgnoreCase(line, "Exception:") && !line.contains("at ") && !line.startsWith("Caused by:")) { - val sb = new StringBuilder(line) - error = KyuubiSQLException(sb.toString() + s"\n See more: $engineLog") - line = reader.readLine() - while (sb.length < maxErrorSize && line != null && - (line.startsWith("\tat ") || line.startsWith("Caused by: "))) { - sb.append("\n" + line) + val sb = new StringBuilder(line) + error = KyuubiSQLException(sb.toString() + s"\n See more: $engineLog") line = reader.readLine() - } + while (sb.length < maxErrorSize && line != null && + (line.startsWith("\tat ") || line.startsWith("Caused by: "))) { + sb.append("\n" + line) + line = reader.readLine() + } - error = KyuubiSQLException(sb.toString() + s"\n See more: $engineLog") - } else if (line != null) { - lastRowOfLog = line + error = KyuubiSQLException(sb.toString() + s"\n See more: $engineLog") + } else if (line != null) { + lastRowOfLog = line + } + } else { + Thread.sleep(300) } - line = reader.readLine() } } catch { case _: IOException =>