Самоуничтожение вилки JVM.Тайм-аут PING истек - PullRequest
Новая
       49

Самоуничтожение вилки JVM.Тайм-аут PING истек

0 голосов
/ 19 февраля 2019

РЕДАКТИРОВАТЬ: Я просто хотел уточнить, что, в интересах задать вопрос, который имеет известный, объективный ответ, этот вопрос, что на самом деле означает, что «Убийство само разветвляется JVM. Истекло время PING истекло», например, что пингчто и почему отказоустойчивые решают, что должны выйти из процесса тестирования?Поскольку это StackOverflow, пожалуйста, не отвечайте советами, которые исправляют некоторые выходы из ВМ, особенно те, которые приводят к поведению, отличному от того, что мы видим ниже.Например, в консоли нет OutOfMemoryError, поэтому я не думаю, что виртуальной машине не хватает места в куче.Если вы ответите таким образом, администратор SO может неправильно понять мой вопрос и заблокировать его или закрыть.

Иногда в сборке CI возникает сбой виртуальной машины, например: 

[INFO] Results:
[INFO] 
[WARNING] Tests run: 8152, Failures: 0, Errors: 0, Skipped: 31
...
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-failsafe-plugin:2.22.1:verify (integration-test) on project app_server: There are test failures.
[ERROR] 
[ERROR] Please refer to /builds/App/Development/App/app_server/target/surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[ERROR] org.apache.maven.surefire.booter.SurefireBooterForkException: The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /builds/App/Development/App/app_server && /usr/lib/jvm/java-1.8-openjdk/jre/bin/java -Xmx3g -jar /builds/App/Development/App/app_server/target/surefire/surefirebooter7662621916357034130.jar /builds/App/Development/App/app_server/target/surefire 2019-01-09T21-23-07_397-jvmRun1 surefire1770987927673067492tmp surefire_37459604808221437221tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 1
[ERROR] Crashed tests:
[ERROR] com.company.blah.blah.ITSomeIntegrationTests
[ERROR]     at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:669)
[ERROR]     at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:282)
[ERROR]     at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:245)
[ERROR]     at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1183)
[ERROR]     at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:1011)
[ERROR]     at org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:857)
[ERROR]     at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
[ERROR]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
[ERROR]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:154)
[ERROR]     at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:146)
[ERROR]     at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
[ERROR]     at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81)
[ERROR]     at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56)
[ERROR]     at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
[ERROR]     at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305)
[ERROR]     at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192)
[ERROR]     at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105)
[ERROR]     at org.apache.maven.cli.MavenCli.execute(MavenCli.java:954)
[ERROR]     at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
[ERROR]     at org.apache.maven.cli.MavenCli.main(MavenCli.java:192)
[ERROR]     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[ERROR]     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[ERROR]     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[ERROR]     at java.lang.reflect.Method.invoke(Method.java:498)
[ERROR]     at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
[ERROR]     at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
[ERROR]     at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
[ERROR]     at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)

(Конечно, «есть ошибки при тестировании» - это неправильно, так как не было провальных тестов.)

Сначала я хочу узнать, что пытается сказать нам отказоустойчивая система?Вот некоторая информация, которую мы собираем:

Во-первых, нет никакого дампа стека или дампа кучи, но есть файлы .dump, оставленные верными и отказоустойчивыми.Для неудачного проекта всегда есть файл .dump, например: 

# Created at 2019-02-12T14:31:16.410
System.exit() or native command error interrupted process checker.
java.lang.IllegalStateException: Cannot use PPID 158 process information. Going to use NOOP events.
    at org.apache.maven.surefire.booter.PpidChecker.checkProcessInfo(PpidChecker.java:155)
    at org.apache.maven.surefire.booter.PpidChecker.isProcessAlive(PpidChecker.java:124)
    at org.apache.maven.surefire.booter.ForkedBooter$2.run(ForkedBooter.java:214)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

# Created at 2019-02-12T14:47:59.174
Killing self fork JVM. PING timeout elapsed.

(Это нарушение связи между отказоустойчивым и Maven-процессами?)

Кроме того, мы печатаем трассировку стекакогда вызывается System.exit () и при каждом таком сбое он выглядит следующим образом: 

java.lang.Exception: System.exit() or similar method called:
    at com.app.IntegrationTestSetup$1.checkPermission(IntegrationTestSetup.java:78)
    at java.lang.SecurityManager.checkExit(SecurityManager.java:761)
    at java.lang.Runtime.halt(Runtime.java:273)
    at org.apache.maven.surefire.booter.ForkedBooter.kill(ForkedBooter.java:311)
    at org.apache.maven.surefire.booter.ForkedBooter.kill(ForkedBooter.java:305)
    at org.apache.maven.surefire.booter.ForkedBooter.access$300(ForkedBooter.java:68)
    at org.apache.maven.surefire.booter.ForkedBooter$5.run(ForkedBooter.java:285)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

т.е. некоторый верный код (используемый в этом случае плагином failsafe) завершает отказоустойчивый процесс (JVM, которыйверный / отказоустойчивый запускается для тестов в процессе, который является дочерним процессом Maven).

Мы используем версию 2.22.1 как отказоустойчивой, так и верной. 

# mvn -v
Apache Maven 3.5.4 (1edded0938998edf8bf061f1ceb3cfdeccf443fe; 2018-06-17T18:33:14Z)
Maven home: /usr/share/java/maven-3
Java version: 1.8.0_191, vendor: Oracle Corporation, runtime: /usr/lib/jvm/java-1.8-openjdk/jre
Default locale: en_US, platform encoding: UTF-8
OS name: "linux", version: "4.15.0-45-generic", arch: "amd64", family: "unix"

Ответы [ 2 ]

0 голосов
/ 23 марта 2019

Все это обсуждается в списке рассылки , но я подведу итоги ниже.

Фон

По умолчанию (и в нашем случае) Maven работаетв одной JVM forks дочерний процесс, выполняющий другую JVM для запуска тестов.Родитель дает дочерние команды через дочернюю stdin.В частности, родитель посылает дочернюю команду NOOP, чтобы сообщить ему, что он все еще жив.

Ответ

ForkedBooter.java косвенно устанавливает два потока.commandReader читает команды из родительского процесса через stdin.listenToShutdownCommands добавляет слушателя к commandReader, чтобы установить AtomicBoolean pingDone на true при получении команды NOOP.listenToShutdownCommands также планирует запуск задания каждые 30 секунд, которое выполняет что-то вроде этого (изменено для удобства чтения): 

boolean hasPing = pingDone.getAndSet( false );
if ( !hasPing ) {
    exit( 1 );
    log( "Killing self fork JVM. PING timeout elapsed." );

Таким образом, в сообщении об ошибке утверждается, что ребенок не прочитал NOOP от родителя.

Причина ошибки

Вы можете предсказать, в чем проблема, только из приведенного выше описания.Я добавил запись в журнал, чтобы увидеть, что происходит в моем случае, и обнаружил, что иногда бывают минуты паузы, в течение которых commandReader не будет читать никакие NOOP (и обычно pingJob тоже не будет работать).Когда у них было время для выполнения, pingJob может запускаться дважды подряд, прежде чем commandReader получит свой ход.

Проще говоря, в этом коде нет ничего, что гарантировало бы, что ОС будет запускать поток, который достаточно часто читает из stdin.Возможно, что в одном потоке будет 3-минутная пауза, потому что мы попросили ОС запустить дюжину других потоков с одинаковым приоритетом, и у них есть дела - они не спят, не уступают и не блокируют IO.У нас есть тяжелый тест, который действительно имел пару пауз по 3 м, даже на 4-ядерном процессоре.

0 голосов
/ 01 марта 2019

Я нашел два способа избежать этой проблемы, ни один из них не является действительно удовлетворительным.

  1. Понижение верного значения до 2.18.1
  2. Ограничение выходных данных регистрации в тестах.Например, установите для уровня журнала значение WARN, а не DEBUG.

Мне бы очень хотелось узнать, каким будет истинное решение этой проблемы.

...