HIVE-29462: Log start/init times for Docker resources (#6321)

Author: abstractdog

itests/util/src/main/java/org/apache/hadoop/hive/ql/externalDB/DockerizedDatabase.java

@@ -96,11 +96,14 @@ private ProcessResults runCmdAndPrintStreams(String[] cmd, long secondsToWait)
 
   public void start() throws Exception {
     runCmdAndPrintStreams(buildRmCmd(), 600);
+    long startTime = System.currentTimeMillis();
     if (runCmdAndPrintStreams(buildRunCmd(), 600).rc != 0) {
       printDockerEvents();
       throw new RuntimeException("Unable to start docker container");
     }
-    long startTime = System.currentTimeMillis();
+    // 1. Time measured for the docker run command to complete.
+    long initStartTime = System.currentTimeMillis();
+    LOG.info("Started docker container in {} ms, waiting for init...", initStartTime - startTime);
     ProcessResults pr;
     do {
       Thread.sleep(1000);
@@ -109,13 +112,15 @@ public void start() throws Exception {
         printDockerEvents();
         throw new RuntimeException("Failed to get docker logs");
       }
-    } while (startTime + MAX_STARTUP_WAIT >= System.currentTimeMillis() && !isContainerReady(pr));
-    if (startTime + MAX_STARTUP_WAIT < System.currentTimeMillis()) {
+    } while (initStartTime + MAX_STARTUP_WAIT >= System.currentTimeMillis() && !isContainerReady(pr));
+    if (initStartTime + MAX_STARTUP_WAIT < System.currentTimeMillis()) {
       printDockerEvents();
       throw new RuntimeException(
           String.format("Container initialization failed within %d seconds. Please check the hive logs.",
               MAX_STARTUP_WAIT / 1000));
     }
+    // 2. Time measured for Docker to be fully initialized (i.e., when the DB is actually ready to use from the start).
+    LOG.info("Initialized docker container in {} ms", System.currentTimeMillis() - initStartTime);
     super.start();
   }
 

standalone-metastore/metastore-server/src/test/java/org/apache/hadoop/hive/metastore/dbinstall/rules/DatabaseRule.java

@@ -65,7 +65,8 @@ public String getDb() {
   public abstract String getInitialJdbcUrl();
 
   @Override
-  public abstract void before() throws Exception;
+  public abstract void before();
+
   @Override
   public abstract void after();
 

standalone-metastore/metastore-server/src/test/java/org/apache/hadoop/hive/metastore/dbinstall/rules/Derby.java

@@ -82,7 +82,7 @@ public String getDb() {
   };
 
   @Override
-  public void before() throws Exception {
+  public void before() {
     MetastoreSchemaTool.setHomeDirForTesting();
   }
 

standalone-metastore/metastore-server/src/test/java/org/apache/hadoop/hive/metastore/dbinstall/rules/Mariadb.java

@@ -21,13 +21,11 @@
 import org.testcontainers.containers.MariaDBContainer;
 import org.testcontainers.utility.DockerImageName;
 
-import java.io.IOException;
-
 public class Mariadb extends DatabaseRule {
   private final MariaDBContainer<?> container = new MariaDBContainer<>(DockerImageName.parse("mariadb:11.4"));
 
   @Override
-  public void before() throws IOException, InterruptedException {
+  public void before() {
     container.start();
   }
 

standalone-metastore/metastore-server/src/test/java/org/apache/hadoop/hive/metastore/dbinstall/rules/Mssql.java

@@ -21,8 +21,6 @@
 import org.testcontainers.containers.MSSQLServerContainer;
 import org.testcontainers.utility.DockerImageName;
 
-import java.io.IOException;
-
 /**
  * JUnit TestRule for Mssql.
  */
@@ -31,7 +29,7 @@ public class Mssql extends DatabaseRule {
       new MSSQLServerContainer<>(DockerImageName.parse("mcr.microsoft.com/mssql/server:2019-latest")).acceptLicense();
 
   @Override
-  public void before() throws IOException, InterruptedException {
+  public void before() {
     container.start();
   }
 

standalone-metastore/metastore-server/src/test/java/org/apache/hadoop/hive/metastore/dbinstall/rules/Mysql.java

@@ -20,16 +20,15 @@
 import org.testcontainers.containers.MySQLContainer;
 import org.testcontainers.utility.DockerImageName;
 
-import java.io.IOException;
-
 /**
  * JUnit TestRule for MySql.
  */
 public class Mysql extends DatabaseRule {
   private final MySQLContainer<?> container =
       new MySQLContainer<>(DockerImageName.parse("mysql:8.4.3")).withConfigurationOverride("");
+
   @Override
-  public void before() throws IOException, InterruptedException {
+  public void before() {
     container.start();
   }
 

standalone-metastore/metastore-server/src/test/java/org/apache/hadoop/hive/metastore/dbinstall/rules/Oracle.java

@@ -20,17 +20,16 @@
 import org.testcontainers.containers.OracleContainer;
 import org.testcontainers.utility.DockerImageName;
 
-import java.io.IOException;
-
 /**
  * JUnit TestRule for Oracle.
  */
 public class Oracle extends DatabaseRule {
   private final DockerImageName name =
       DockerImageName.parse("abstractdog/oracle-xe:18.4.0-slim").asCompatibleSubstituteFor("gvenzl/oracle-xe");
   private final OracleContainer container = new OracleContainer(name).withEnv("ORACLE_PASSWORD", "oracle");
+
   @Override
-  public void before() throws IOException, InterruptedException {
+  public void before() {
     container.start();
   }
 

standalone-metastore/metastore-server/src/test/java/org/apache/hadoop/hive/metastore/dbinstall/rules/Postgres.java

@@ -20,8 +20,6 @@
 import org.testcontainers.containers.PostgreSQLContainer;
 import org.testcontainers.utility.DockerImageName;
 
-import java.io.IOException;
-
 /**
  * JUnit TestRule for Postgres.
  */
@@ -37,7 +35,7 @@ protected Postgres(DockerImageName dockerImageName) {
   }
 
   @Override
-  public void before() throws IOException, InterruptedException {
+  public void before() {
     container.start();
   }