You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues-all@impala.apache.org by "Laszlo Gaal (Jira)" <ji...@apache.org> on 2020/07/06 13:46:00 UTC
[jira] [Commented] (IMPALA-9900) High rate log spam during FE tests
[ https://issues.apache.org/jira/browse/IMPALA-9900?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17152025#comment-17152025 ]
Laszlo Gaal commented on IMPALA-9900:
-------------------------------------
Hi [~vihangk1], apologies from my side as well...
The only telltale sign I could find so far is that the impacted job is launched with only FE, BE and JDBC test selected (in other words FE_TEST=true, BE_TEST=true and JDBC_TEST=true); EE_TEST and CLUSTER_TEST are set to false (deselected).
The other suspicious detail is that the log spam is constrained to a single 2-minute interval, which suggests that only a single test (or maybe a low number of subsequent tests) is exhibiting this problem.
The latest occurrence is build #11191. Correlating the log spam timestamps with the Jenkins console log for the build shows that the spam is happening during JDBC_TEST:
This is from impalad_node2.ERROR
{code}
Impala/logs_static/logs/ee_tests $ head -50 impalad_node2.ERROR
Log file created at: 2020/07/01 21:45:06
Running on machine: ip-XXX-REDACTED-XXX
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
E0701 21:45:06.040009 16152 logging.cc:147] stderr will be logged to this file.
20/07/01 21:45:07 INFO util.JvmPauseMonitor: Starting JVM pause monitor
E0701 21:45:28.951961 17355 TransactionKeepalive.java:137] Unexpected exception thrown
Java exception follows:
java.lang.BootstrapMethodError: java.lang.NoClassDefFoundError: org/apache/impala/common/TransactionKeepalive$HeartbeatContext
at org.apache.impala.common.TransactionKeepalive$DaemonThread.run(TransactionKeepalive.java:114)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.NoClassDefFoundError: org/apache/impala/common/TransactionKeepalive$HeartbeatContext
... 2 more
Caused by: java.lang.ClassNotFoundException: org.apache.impala.common.TransactionKeepalive$HeartbeatContext
at java.net.URLClassLoader.findClass(URLClassLoader.java:382)
at java.lang.ClassLoader.loadClass(ClassLoader.java:418)
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:352)
at java.lang.ClassLoader.loadClass(ClassLoader.java:351)
... 2 more
E0701 21:45:28.952263 17355 TransactionKeepalive.java:137] Unexpected exception thrown
Java exception follows:
java.lang.BootstrapMethodError: java.lang.NoClassDefFoundError:
at org.apache.impala.common.TransactionKeepalive$DaemonThread.run(TransactionKeepalive.java:114)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.NoClassDefFoundError:
... 2 more
E0701 21:45:28.952461 17355 TransactionKeepalive.java:137] Unexpected exception thrown
Java exception follows:
java.lang.BootstrapMethodError: java.lang.NoClassDefFoundError:
at org.apache.impala.common.TransactionKeepalive$DaemonThread.run(TransactionKeepalive.java:114)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.NoClassDefFoundError:
... 2 more
[.......continues for another 2 minutes......]
E0701 21:47:18.512876 17367 TransactionKeepalive.java:137] Unexpected exception thrown
Java exception follows:
java.lang.BootstrapMethodError: java.lang.NoClassDefFoundError:
at org.apache.impala.common.TransactionKeepalive$DaemonThread.run(TransactionKeepalive.java:114)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.NoClassDefFoundError:
... 2 more
<end of the log file>
{code}
Console log shows at the same time:
{code}
21:45:05 Starting Impala cluster OK (Took: 0 min 9 sec)
21:45:05 ~/Impala
21:45:05 21:45:05 MainThread: Found 0 impalad/0 statestored/0 catalogd process(es)
21:45:05 21:45:05 MainThread: Starting State Store logging to /home/ubuntu/Impala/logs/ee_tests/statestored.INFO
21:45:05 21:45:05 MainThread: Starting Catalog Service logging to /home/ubuntu/Impala/logs/ee_tests/catalogd.INFO
21:45:06 21:45:06 MainThread: Starting Impala Daemon logging to /home/ubuntu/Impala/logs/ee_tests/impalad.INFO
21:45:06 21:45:06 MainThread: Starting Impala Daemon logging to /home/ubuntu/Impala/logs/ee_tests/impalad_node1.INFO
21:45:06 21:45:06 MainThread: Starting Impala Daemon logging to /home/ubuntu/Impala/logs/ee_tests/impalad_node2.INFO
21:45:09 21:45:09 MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
21:45:09 21:45:09 MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
21:45:09 21:45:09 MainThread: Getting num_known_live_backends from ip-172-31-62-150:25000
21:45:09 21:45:09 MainThread: Waiting for num_known_live_backends=3. Current value: 0
21:45:10 21:45:10 MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
21:45:10 21:45:10 MainThread: Getting num_known_live_backends from ip-172-31-62-150:25000
21:45:10 21:45:10 MainThread: Waiting for num_known_live_backends=3. Current value: 0
21:45:11 21:45:11 MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
21:45:11 21:45:11 MainThread: Getting num_known_live_backends from ip-172-31-62-150:25000
21:45:11 21:45:11 MainThread: Waiting for num_known_live_backends=3. Current value: 0
21:45:12 21:45:12 MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
21:45:12 21:45:12 MainThread: Getting num_known_live_backends from ip-172-31-62-150:25000
21:45:12 21:45:12 MainThread: Waiting for num_known_live_backends=3. Current value: 0
21:45:13 21:45:13 MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
21:45:13 21:45:13 MainThread: Getting num_known_live_backends from ip-172-31-62-150:25000
21:45:13 21:45:13 MainThread: num_known_live_backends has reached value: 3
21:45:13 21:45:13 MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
21:45:13 21:45:13 MainThread: Getting num_known_live_backends from ip-172-31-62-150:25001
21:45:13 21:45:13 MainThread: num_known_live_backends has reached value: 3
21:45:14 21:45:14 MainThread: Found E0701 21:47:18.512876 17367 TransactionKeepalive.java:137] Unexpected exception thrown
Java exception follows:
java.lang.BootstrapMethodError: java.lang.NoClassDefFoundError:
at org.apache.impala.common.TransactionKeepalive$DaemonThread.run(TransactionKeepalive.java:114)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.NoClassDefFoundError:
... 2 more
3 impalad/1 statestored/1 catalogd process(es)
21:45:14 21:45:14 MainThread: Getting num_known_live_backends from ip-172-31-62-150:25002
21:45:14 21:45:14 MainThread: num_known_live_backends has reached value: 3
21:45:14 21:45:14 MainThread: Impala Cluster Running with 3 nodes (3 coordinators, 3 executors).
21:45:14 ~/Impala/fe ~/Impala
21:45:14 ========================================================================
21:45:14 Running mvn -U test -Dtest=JdbcTest
21:45:14 Directory /home/ubuntu/Impala/fe
21:45:14 ========================================================================
[...........]
21:47:14 21:45:34 [INFO] Running org.apache.impala.service.JdbcTest
21:47:14 21:47:13 [INFO] Tests run: 30, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 98.985 s - in org.apache.impala.service.JdbcTest
21:47:14 21:47:13 [INFO] Tests run: 30, Failures: 0, Errors: 0, Skipped: 0
21:47:14 21:47:13 [INFO] BUILD SUCCESS
21:47:14 ~/Impala
21:47:18 + RET_CODE=1
21:47:18 + testdata/bin/kill-all.sh
21:47:18 Stopping Sentry
21:47:18 Stopping Hive
21:47:21 Stopping Hbase
21:47:21 stopping hbase.........
{code}
I'm not sure how much this helps, but the correlation is pretty clear.
Again, build #11191 is preserved indefinitely to help in the investigation.
> High rate log spam during FE tests
> ----------------------------------
>
> Key: IMPALA-9900
> URL: https://issues.apache.org/jira/browse/IMPALA-9900
> Project: IMPALA
> Issue Type: Bug
> Components: Frontend
> Affects Versions: Impala 4.0
> Reporter: Laszlo Gaal
> Priority: Critical
>
> During recent runs of the gerrit-verify-dryrun job FE tests exhibited a disturbing tendency: all impalad instances emitted almost 1 GB's worth of Java exception traces into their ERROR logfiles in a short, roughly 2 minute period. This bloats the archived logs pretty badly, because the contents of the ERROR log is replicated in the WARNING and in the INFO log as well, resulting in about 6 GB's of wasted space on the build server. This also makes it hard to extract meaningful information from those logs.
> The latest example is https://jenkins.impala.io/job/ubuntu-16.04-from-scratch/11102/ (the build is currently locked to prevent it from being cleaned up); the affected files are archive/Impala/logs_static/logs/ee_tests/impalad{,node1,node2}.ERROR. The spam runs are present between log timestamps 21:05 to 21:07, the first error is
> {code}
> E0624 21:05:28.938853 19419 TransactionKeepalive.java:137] Unexpected exception thrown
> Java exception follows:
> java.lang.BootstrapMethodError: java.lang.NoClassDefFoundError: org/apache/impala/common/TransactionKeepalive$HeartbeatContext
> at org.apache.impala.common.TransactionKeepalive$DaemonThread.run(TransactionKeepalive.java:114)
> at java.lang.Thread.run(Thread.java:748)
> Caused by: java.lang.NoClassDefFoundError: org/apache/impala/common/TransactionKeepalive$HeartbeatContext
> ... 2 more
> Caused by: java.lang.ClassNotFoundException: org.apache.impala.common.TransactionKeepalive$HeartbeatContext
> at java.net.URLClassLoader.findClass(URLClassLoader.java:382)
> at java.lang.ClassLoader.loadClass(ClassLoader.java:418)
> at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:352)
> at java.lang.ClassLoader.loadClass(ClassLoader.java:351)
> ... 2 more
> {code} then the repeated pattern is
> {code}
> E0624 21:05:28.939031 19419 TransactionKeepalive.java:137] Unexpected exception thrown
> Java exception follows:
> java.lang.BootstrapMethodError: java.lang.NoClassDefFoundError:
> at org.apache.impala.common.TransactionKeepalive$DaemonThread.run(TransactionKeepalive.java:114)
> at java.lang.Thread.run(Thread.java:748)
> Caused by: java.lang.NoClassDefFoundError:
> ... 2 more
> {code}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: issues-all-unsubscribe@impala.apache.org
For additional commands, e-mail: issues-all-help@impala.apache.org