Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Minimally-invasive refinement to start-up time calculation #1100

Merged
merged 3 commits into from
Oct 16, 2019
Merged

Minimally-invasive refinement to start-up time calculation #1100

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
0085219
Minimally-invasive refinement to start-up time calculation
tjquinno Oct 14, 2019
11ee365
Change wording in start-up timing message to emphasize initialization…
tjquinno Oct 16, 2019
34e3d22
Remove stray semicolon in log message
tjquinno Oct 16, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions microprofile/server/src/main/java/io/helidon/microprofile/server/Server.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -148,6 +148,8 @@ static Builder builder() {
* Builder to build {@link Server} instance.
*/
final class Builder {
private static final long STARTUP_TIME = ServerImpl.STARTUP_TIME;

spericas marked this conversation as resolved.
Show resolved Hide resolved
// there should only be one
private static final AtomicInteger MP_SERVER_COUNTER = new AtomicInteger(1);
private static final Logger LOGGER = Logger.getLogger(Builder.class.getName());
Expand Down
4 changes: 2 additions & 2 deletions microprofile/server/src/main/java/io/helidon/microprofile/server/ServerImpl.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -67,6 +67,7 @@
* Server to handle lifecycle of microprofile implementation.
*/
public class ServerImpl implements Server {
static final long STARTUP_TIME = System.nanoTime();
private static final Logger LOGGER = Logger.getLogger(ServerImpl.class.getName());
private static final Logger JERSEY_LOGGER = Logger.getLogger(ServerImpl.class.getName() + ".jersey");
private static final Logger STARTUP_LOGGER = Logger.getLogger("io.helidon.microprofile.startup.server");
Expand Down Expand Up @@ -446,14 +447,13 @@ public Server start() {
CountDownLatch cdl = new CountDownLatch(1);
AtomicReference<Throwable> throwRef = new AtomicReference<>();

long beforeT = System.nanoTime();
server.start()
.whenComplete((webServer, throwable) -> {
if (null != throwable) {
STARTUP_LOGGER.log(Level.FINEST, "Startup failed", throwable);
throwRef.set(throwable);
} else {
long t = TimeUnit.MILLISECONDS.convert(System.nanoTime() - beforeT, TimeUnit.NANOSECONDS);
long t = TimeUnit.MILLISECONDS.convert(System.nanoTime() - STARTUP_TIME, TimeUnit.NANOSECONDS);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't it technically possible for a server to be started, stopped and started again? I think we may need to redefine what we call startup time here. It should really be the elapsed time of calling server.start(), trying to calculate anything else in this method would be inaccurate; any such calculation needs to happen elsewhere IMO.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd originally noticed that, after some code was added to the start method, the point where the start time was captured fell after that added work. In the slack discussion Tomas expressed the opinion that the reported time should include as much work as possible -- he mentioned CDI + the server start time.

Yes, it is conceivable that a server would be started, stopped, and restarted again although that's not the usual use case. Recording the system time at the very beginning of the start method results in a reported start-up time of 100 to 300 ms (in informal experiments). That's significantly under the log message timestamp delta, and that kind of mismatch is what prompted this issue originally.

The CDI initialization occurs in Server.Builder.build() (unless the caller to Builder passes a previously-init'd CDI container which is not our usual case).

We could separately record the "initialization" time (which would include the CDI initialization) and the server start-up time. During the first start-up the log message could report the overall time and the two components; during a subsequent server restart it could report only the time in ServerImpl.start because the other initialization is not repeated in that case.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Or, because the server start-up time itself seems to be a relatively small part of the overall initialization time, we could report the overall initialization time only once, at the end of the first invocation of start. Rereading what I wrote above it might be overly confusing to users to try to concisely convey the two separate times.


port = webServer.port();
STARTUP_LOGGER.finest("Started up");
Expand Down