Skip to content

Commit

Permalink
Clean up timing stuff
Browse files Browse the repository at this point in the history
  • Loading branch information
@dmlloyd
dmlloyd committed Jul 2, 2019
1 parent e164c4e commit 0f07493
Show file tree
Hide file tree
Showing 6 changed files with 58 additions and 43 deletions.
2 changes: 1 addition & 1 deletion core/devmode/src/main/java/io/quarkus/dev/DevModeMain.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -57,7 +57,7 @@ public class DevModeMain {
static final Map<Class<?>, Object> liveReloadContext = new ConcurrentHashMap<>();

public static void main(String... args) throws Exception {
Timing.staticInitStarted();
Timing.markStart();

try (InputStream devModeCp = DevModeMain.class.getClassLoader().getResourceAsStream(DEV_MODE_CONTEXT)) {
context = (DevModeContext) new ObjectInputStream(new DataInputStream(devModeCp)).readObject();
Expand Down
49 changes: 32 additions & 17 deletions core/runtime/src/main/java/io/quarkus/runtime/Timing.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,28 +6,28 @@

/**
* Class that is responsible for printing out timing results.
* <p>
* It is modified on substrate by {@link io.quarkus.runtime.graal.TimingReplacement}, in that mainStarted it rewritten to
* actually update the start time.
*/
public class Timing {

private static volatile long bootStartTime = -1;
private static volatile long bootStartTime;

private static volatile long bootStopTime = -1;
private static volatile long bootStopTime;

private static volatile String httpServerInfo = "";

public static void staticInitStarted() {
if (bootStartTime < 0) {
bootStartTime = System.nanoTime();
}
/**
* Mark the point when the server has begun starting.
*/
public static void markStart() {
marked = true;
bootStartTime = System.nanoTime();
}

public static void staticInitStopped() {
if (bootStopTime < 0) {
bootStopTime = System.nanoTime();
}
/**
* Mark the point when the server has begun stopping.
*/
public static void markStop() {
bootStopTime = System.nanoTime();
}

/**
Expand All @@ -40,10 +40,27 @@ public static void setHttpServer(String info) {
httpServerInfo = info;
}

private static volatile boolean marked;

/**
* Mark the point when the server has begun the main method for the first time.
*/
public static void markFirstStart() {
// For dev mode and unit tests, subsequent restarts will be recorded from the main method.
if (marked) {
marked = false;
} else {
markStart();
}
}

/**
* This method is replaced by substrate
* Mark the point when the server has begun the main method for the first time. Prevents the next
* main method start from recording a time.
*/
public static void mainStarted() {
public static void markStaticInitStart() {
marked = true;
markStart();
}

public static void restart() {
Expand All @@ -57,15 +74,13 @@ public static void printStartupTime(String version, String features) {
final BigDecimal secondsRepresentation = convertToBigDecimalSeconds(bootTimeNanoSeconds);
logger.infof("Quarkus %s started in %ss. %s", version, secondsRepresentation, httpServerInfo);
logger.infof("Installed features: [%s]", features);
bootStartTime = -1;
}

public static void printStopTime() {
final long stopTimeNanoSeconds = System.nanoTime() - bootStopTime;
final Logger logger = Logger.getLogger("io.quarkus");
final BigDecimal secondsRepresentation = convertToBigDecimalSeconds(stopTimeNanoSeconds);
logger.infof("Quarkus stopped in %ss", secondsRepresentation);
bootStopTime = -1;
}

public static BigDecimal convertToBigDecimalSeconds(final long timeNanoSeconds) {
Expand Down
20 changes: 20 additions & 0 deletions core/runtime/src/main/java/io/quarkus/runtime/execution/Execution.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,8 @@
import org.wildfly.common.lock.ExtendedLock;
import org.wildfly.common.lock.Locks;

import io.quarkus.runtime.Timing;

/**
*
*/
Expand Down Expand Up @@ -265,6 +267,8 @@ static void firstStart(final boolean async) throws AsynchronousExitException {
int oldVal = state;
int status = statusOf(oldVal);
if (status == STATUS_ASYNC_EXIT || status == STATUS_DEAD) {
Timing.markFirstStart();
Timing.markStop();
throw asyncExitException();
} else if (status != STATUS_IDLE) {
throw new IllegalStateException("A Quarkus instance is already running");
Expand All @@ -273,6 +277,7 @@ static void firstStart(final boolean async) throws AsynchronousExitException {
oldVal = withAsync(oldVal);
}
state = withStatus(oldVal, STATUS_START);
Timing.markFirstStart();
return;
} finally {
lock.unlock();
Expand All @@ -296,10 +301,12 @@ static int starting() throws AsynchronousExitException {
if (status == STATUS_START) {
return -1;
} else if (status == STATUS_ASYNC_EXIT || status == STATUS_DEAD) {
Timing.markStop();
throw asyncExitException();
} else if (status == STATUS_EXIT) {
// restart
state = withExitCode(withStatus(oldVal, STATUS_START), 0);
Timing.markStart();
termCond.signalAll();
return -1;
} else if (status == STATUS_RUN || status == STATUS_EXIT_WAIT) {
Expand Down Expand Up @@ -339,10 +346,12 @@ static void stopping(int exitCode) throws AsynchronousExitException {
} else if (status == STATUS_ASYNC_EXIT) {
throw asyncExitException();
} else if (status == STATUS_START || status == STATUS_START_EXIT) {
Timing.markStop();
upCond.signalAll();
state = withExitCode(withStatus(oldVal, STATUS_EXIT), exitCode);
return;
} else if (status == STATUS_RUN) {
Timing.markStop();
state = withExitCode(withStatus(oldVal, STATUS_EXIT), exitCode);
return;
} else if (status == STATUS_EXIT) {
Expand Down Expand Up @@ -385,10 +394,12 @@ static <E extends Throwable> E stoppingException(final E ex) throws Asynchronous
throw asyncExitException(ex);
}
} else if (status == STATUS_START || status == STATUS_START_EXIT) {
Timing.markStop();
state = withExitCode(withStatus(oldVal, STATUS_EXIT), EXIT_EXCEPTION);
upCond.signalAll();
return ex;
} else if (status == STATUS_RUN) {
Timing.markStop();
state = withExitCode(withStatus(oldVal, STATUS_EXIT), EXIT_EXCEPTION);
return ex;
} else if (status == STATUS_EXIT && exitCodeOf(oldVal) == EXIT_OK) {
Expand Down Expand Up @@ -444,15 +455,18 @@ static int signalUpAndAwaitStop() throws AsynchronousExitException {
upCond.signalAll();
} else if (status == STATUS_START_EXIT) {
// we shut down before we started up
Timing.markStop();
state = withStatus(oldVal, STATUS_EXIT);
upCond.signalAll();
return exitCodeOf(oldVal);
} else if (status == STATUS_EXIT) {
// we shut down before we started up
Timing.markStop();
upCond.signalAll();
return exitCodeOf(oldVal);
} else if (status == STATUS_ASYNC_EXIT) {
// we shut down before we started up
Timing.markStop();
upCond.signalAll();
throw asyncExitException();
} else {
Expand All @@ -465,8 +479,10 @@ static int signalUpAndAwaitStop() throws AsynchronousExitException {
oldVal = state;
status = statusOf(oldVal);
if (status == STATUS_ASYNC_EXIT) {
Timing.markStop();
throw asyncExitException();
} else if (status == STATUS_EXIT) {
Timing.markStop();
return exitCodeOf(oldVal);
} else if (status == STATUS_RUN || status == STATUS_START_WAIT) {
// spurious wakeup
Expand All @@ -488,9 +504,11 @@ static void signalAsyncExitAndAwaitTerm() {
if (status == STATUS_ASYNC_EXIT) {
// already signalled; do nothing
} else if (status == STATUS_START) {
Timing.markStop();
state = withStatus(0, status = STATUS_ASYNC_EXIT);
upCond.signalAll();
} else if (status == STATUS_RUN) {
Timing.markStop();
state = withStatus(0, status = STATUS_ASYNC_EXIT);
stopCond.signalAll();
} else if (status == STATUS_EXIT) {
Expand Down Expand Up @@ -530,9 +548,11 @@ static void signalAsyncExit() {
if (status == STATUS_ASYNC_EXIT) {
// already signalled; do nothing
} else if (status == STATUS_START) {
Timing.markStop();
state = withStatus(0, STATUS_ASYNC_EXIT);
upCond.signalAll();
} else if (status == STATUS_RUN) {
Timing.markStop();
state = withStatus(0, STATUS_ASYNC_EXIT);
stopCond.signalAll();
} else if (status == STATUS_EXIT) {
Expand Down
7 changes: 4 additions & 3 deletions core/runtime/src/main/java/io/quarkus/runtime/execution/ExecutionChain.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -96,18 +96,20 @@ public void run() {
} catch (Throwable t) {
Execution.thrown = t;
Execution.lastStop();
Timing.printStopTime();
return;
}
Execution.lastStop();
Timing.printStopTime();
}
};
Execution.firstStart(true);
Timing.mainStarted();
Thread thread = new Thread(task, "Quarkus Thread");
try {
thread.start();
} catch (Throwable t) {
Execution.lastStop();
Timing.printStopTime();
throw t;
}
Execution.awaitServerUp();
Expand All @@ -130,7 +132,6 @@ public void startAndExit(ExecutionContext initialContext) {
safeFlush(System.err);
System.exit(Execution.EXIT_EXCEPTION);
}
Timing.mainStarted();
final int res;
try {
res = run(initialContext);
Expand All @@ -155,7 +156,7 @@ public void startAndExit(ExecutionContext initialContext) {
}
safeFlush(System.out);
safeFlush(System.err);
Execution.lastStop();
Timing.printStopTime();
System.exit(res);
throw Assert.unreachableCode();
}
Expand Down
20 changes: 0 additions & 20 deletions core/runtime/src/main/java/io/quarkus/runtime/graal/TimingReplacement.java
View file

This file was deleted.

3 changes: 1 addition & 2 deletions core/runtime/src/main/quarkus/io/quarkus/runtime/Quarkus.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -14,10 +14,9 @@
public class Quarkus {

static {
Timing.staticInitStarted();
Timing.markStaticInitStart();
INITIAL_CONTEXT = Init.getInitialContext();
STARTUP_CHAIN = Init.getInitialChain();
Timing.staticInitStopped();
}

private static final ExecutionContext INITIAL_CONTEXT;
Expand Down

0 comments on commit 0f07493

Please sign in to comment.