Minimally-invasive refinement to start-up time calculation

[tjquinno]

Addresses #1099

The end-of-startup log message understated the actual start-up time for the MP server.

This PR simply captures the current system time at class-load-time of ServerImpl (which we now also trigger as early as possible in Server.Builder). This does not include all of the JVM and class loading time but it greatly improves the accuracy of the start-up log message. For example:

2019.10.14 12:43:08 INFO org.jboss.weld.Version Thread[main,5,main]: WELD-000900: 3.1.1 (Final)
...
2019.10.14 12:43:12 INFO io.helidon.microprofile.server.ServerImpl Thread[nioEventLoopGroup-2-1,10,main]: Server started on http://localhost:8080 (and all other host addresses) in 4284 milliseconds.

The reported start-up time in ms much more closely aligns with the log message timestamps.

Another option (I looked into this and @batsatt also mentioned it in slack) would have been to use the RuntimeMXBean which reports the JVM start-up time. In some informal measurements I was seeing a 40-50 ms cost for that.

Yet another option (thanks to @spericas) would have collected the start-up time in the built-in Main class, but users can provide their own Main which would skip that (as Santiago also mentioned).

The changes in the PR give a timing that matches up with the log message timestamps and also gives a reasonable approximation to the full start-up time. The Server.Builder and ServerImpl classes are loaded early during start-up.

[spericas]

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.

[tjquinno]

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.

[tjquinno]

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.

[tjquinno]

The latest commits address, I think, Santiago's comments while reporting the most useful numbers for the by-far most common use case.

The log message now reports server initialization time rather than start-up time given that it encompasses not just server start method execution but all the CDI and other warm-up that occurs before that:

(newlines inserted manually for readability in the comment)

2019.10.16 09:05:26 INFO org.jboss.weld.Version Thread[main,5,main]: 
WELD-000900: 3.1.1 (Final)
...
2019.10.16 09:05:30 INFO io.helidon.microprofile.server.ServerImpl Thread[nioEventLoopGroup-2-1,10,main]: 
Server initialized on http://localhost:8080 (and all other host addresses) in 4940 milliseconds.

Also, the message is logged only during the first invocation of the ServerImpl.start method. Typically only one ServerImpl instance is created, and it is started only once anyway, plus the time spent in the start method is a small part (roughly 10%) of the total initialization time so not reporting the start method time for subsequent restarts of the server instance seems OK.