DRILL-2638: Regularize startup/shutdown logging a bit in/near Drillbit.

In Drillbit:
- Added shutdown time (ms).
- Regularized to have bracketing "starting" and "finished" messages (when DEBUG
  enabled; include only messages with times at INFO level).  (See examples below.)
- Edited text.

In FunctionImplementationRegistry
- DEBUG -> INFO for message with startup time.
- Edited text.

(Examples:
At DEBUG level:

... DEBUG o.apache.drill.exec.server.Drillbit - Starting new Drillbit.
... DEBUG o.apache.drill.exec.server.Drillbit - Construction started.
... INFO  o.apache.drill.exec.server.Drillbit - Construction completed (1259 ms).
... DEBUG o.apache.drill.exec.server.Drillbit - Startup begun.
... INFO  o.apache.drill.exec.server.Drillbit - Startup completed (5359 ms).
... DEBUG o.apache.drill.exec.server.Drillbit - Started new Drillbit.
...
... DEBUG o.apache.drill.exec.server.Drillbit - Shutdown begun.
... INFO  o.apache.drill.exec.server.Drillbit - Shutdown completed (6346 ms).

At INFO level:

... INFO  o.apache.drill.exec.server.Drillbit - Construction completed (1259 ms).
... INFO  o.apache.drill.exec.server.Drillbit - Startup completed (5359 ms).
...
... INFO  o.apache.drill.exec.server.Drillbit - Shutdown completed (6346 ms).
)

2 files changed, 15 insertions, 6 deletions

diff --git a/exec/java-exec/src/main/java/org/apache/drill/exec/expr/fn/FunctionImplementationRegistry.java b/exec/java-exec/src/main/java/org/apache/drill/exec/expr/fn/FunctionImplementationRegistry.java
index e96fa606e..05d59ff7e 100644
--- a/exec/java-exec/src/main/java/org/apache/drill/exec/expr/fn/FunctionImplementationRegistry.java
+++ b/exec/java-exec/src/main/java/org/apache/drill/exec/expr/fn/FunctionImplementationRegistry.java
@@ -47,7 +47,7 @@ public class FunctionImplementationRegistry {
   public FunctionImplementationRegistry(DrillConfig config){
     Stopwatch w = new Stopwatch().start();
 
-    logger.debug("Generating Function Registry.");
+    logger.debug("Generating function registry.");
     drillFuncRegistry = new DrillFunctionRegistry(config);
 
     Set<Class<? extends PluggableFunctionRegistry>> registryClasses = PathScanner.scanForImplementations(
@@ -72,7 +72,7 @@ public class FunctionImplementationRegistry {
         break;
       }
     }
-    logger.debug("Function registry loaded.  {} functions loaded in {}ms.", drillFuncRegistry.size(), w.elapsed(TimeUnit.MILLISECONDS));
+    logger.info("Function registry loaded.  {} functions loaded in {} ms.", drillFuncRegistry.size(), w.elapsed(TimeUnit.MILLISECONDS));
   }
 
   public FunctionImplementationRegistry(DrillConfig config, OptionManager optionManager) {
diff --git a/exec/java-exec/src/main/java/org/apache/drill/exec/server/Drillbit.java b/exec/java-exec/src/main/java/org/apache/drill/exec/server/Drillbit.java
index 958f2dc4e..c15bb7cab 100644
--- a/exec/java-exec/src/main/java/org/apache/drill/exec/server/Drillbit.java
+++ b/exec/java-exec/src/main/java/org/apache/drill/exec/server/Drillbit.java
@@ -57,7 +57,7 @@ import com.google.common.io.Closeables;
 public class Drillbit implements AutoCloseable {
   private static final org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger(Drillbit.class);
   static {
-    Environment.logEnv("Drillbit environment:.", logger);
+    Environment.logEnv("Drillbit environment: ", logger);
   }
 
   private boolean isClosed = false;
@@ -72,7 +72,7 @@ public class Drillbit implements AutoCloseable {
 
   public static Drillbit start(final DrillConfig config, final RemoteServiceSet remoteServiceSet)
       throws DrillbitStartupException {
-    logger.debug("Setting up Drillbit.");
+    logger.debug("Starting new Drillbit.");
     Drillbit bit;
     try {
       bit = new Drillbit(config, remoteServiceSet);
@@ -80,13 +80,13 @@ public class Drillbit implements AutoCloseable {
       throw new DrillbitStartupException("Failure while initializing values in Drillbit.", ex);
     }
 
-    logger.debug("Starting Drillbit.");
     try {
       bit.run();
     } catch (Exception e) {
       bit.close();
       throw new DrillbitStartupException("Failure during initial startup of Drillbit.", e);
     }
+    logger.debug("Started new Drillbit.");
     return bit;
   }
 
@@ -175,6 +175,8 @@ public class Drillbit implements AutoCloseable {
   private RegistrationHandle registrationHandle;
 
   public Drillbit(DrillConfig config, RemoteServiceSet serviceSet) throws Exception {
+    final long startTime = System.currentTimeMillis();
+    logger.debug("Construction started.");
     final boolean allowPortHunting = serviceSet != null;
     final boolean enableHttp = config.getBoolean(ExecConstants.HTTP_ENABLE);
     context = new BootStrapContext(config);
@@ -195,6 +197,7 @@ public class Drillbit implements AutoCloseable {
       coord = new ZKClusterCoordinator(config);
       storeProvider = new PStoreRegistry(this.coord, config).newPStoreProvider();
     }
+    logger.info("Construction completed ({} ms).", System.currentTimeMillis() - startTime);
   }
 
   private void startJetty() throws Exception {
@@ -231,6 +234,8 @@ public class Drillbit implements AutoCloseable {
   }
 
   public void run() throws Exception {
+    final long startTime = System.currentTimeMillis();
+    logger.debug("Startup begun.");
     coord.start(10000);
     storeProvider.start();
     final DrillbitEndpoint md = engine.start();
@@ -243,6 +248,7 @@ public class Drillbit implements AutoCloseable {
     startJetty();
 
     Runtime.getRuntime().addShutdownHook(new ShutdownThread(this, new StackTrace()));
+    logger.info("Startup completed ({} ms).", System.currentTimeMillis() - startTime);
   }
 
   @Override
@@ -251,6 +257,8 @@ public class Drillbit implements AutoCloseable {
     if (isClosed) {
       return;
     }
+    final long startTime = System.currentTimeMillis();
+    logger.debug("Shutdown begun.");
 
     // wait for anything that is running to complete
     manager.waitToExit();
@@ -279,7 +287,7 @@ public class Drillbit implements AutoCloseable {
     AutoCloseables.close(manager, logger);
     Closeables.closeQuietly(context);
 
-    logger.info("Shutdown completed.");
+    logger.info("Shutdown completed ({} ms).", System.currentTimeMillis() - startTime);
     isClosed = true;
   }
 
@@ -324,4 +332,5 @@ public class Drillbit implements AutoCloseable {
   public DrillbitContext getContext() {
     return manager.getContext();
   }
+
 }