8327495: Print more warning with -Xshare:auto when CDS fails to use archive

Reviewed-by: iklam, matsaave

Author: calvinccheung

src/hotspot/share/cds/aotClassLocation.cpp

@@ -1030,6 +1030,7 @@ bool AOTClassLocationConfig::validate(bool has_aot_linked_classes, bool* has_ext
       }
     } else {
       log_warning(cds)("%s%s", mismatch_msg, hint_msg);
+      MetaspaceShared::report_loading_error(nullptr);
     }
   }
   return success;

src/hotspot/share/cds/cdsConfig.cpp

@@ -647,6 +647,14 @@ bool CDSConfig::is_using_archive() {
   return UseSharedSpaces;
 }
 
+bool CDSConfig::is_using_only_default_archive() {
+  return is_using_archive() &&
+         input_static_archive_path() != nullptr &&
+         default_archive_path() != nullptr &&
+         strcmp(input_static_archive_path(), default_archive_path()) == 0 &&
+         input_dynamic_archive_path() == nullptr;
+}
+
 bool CDSConfig::is_logging_lambda_form_invokers() {
   return ClassListWriter::is_enabled() || is_dumping_dynamic_archive();
 }

src/hotspot/share/cds/cdsConfig.hpp

@@ -103,6 +103,7 @@ class CDSConfig : public AllStatic {
 
   // input archive(s)
   static bool is_using_archive()                             NOT_CDS_RETURN_(false);
+  static bool is_using_only_default_archive()                NOT_CDS_RETURN_(false);
 
   // static_archive
   static bool is_dumping_static_archive()                    { return CDS_ONLY(_is_dumping_static_archive) NOT_CDS(false); }

src/hotspot/share/cds/filemap.cpp

@@ -326,7 +326,7 @@ bool FileMapInfo::validate_class_location() {
 
   if (header()->has_full_module_graph() && has_extra_module_paths) {
     CDSConfig::stop_using_optimized_module_handling();
-    log_info(cds)("optimized module handling: disabled because extra module path(s) are specified");
+    MetaspaceShared::report_loading_error("optimized module handling: disabled because extra module path(s) are specified");
   }
 
   if (CDSConfig::is_dumping_dynamic_archive()) {
@@ -1256,7 +1256,7 @@ char* FileMapInfo::map_bitmap_region() {
   char* bitmap_base = map_memory(_fd, _full_path, r->file_offset(),
                                  requested_addr, r->used_aligned(), read_only, allow_exec, mtClassShared);
   if (bitmap_base == nullptr) {
-    log_info(cds)("failed to map relocation bitmap");
+    MetaspaceShared::report_loading_error("failed to map relocation bitmap");
     return nullptr;
   }
 
@@ -1454,9 +1454,9 @@ void FileMapInfo::map_or_load_heap_region() {
       success = ArchiveHeapLoader::load_heap_region(this);
     } else {
       if (!UseCompressedOops && !ArchiveHeapLoader::can_map()) {
-        log_info(cds)("Cannot use CDS heap data. Selected GC not compatible -XX:-UseCompressedOops");
+        MetaspaceShared::report_loading_error("Cannot use CDS heap data. Selected GC not compatible -XX:-UseCompressedOops");
       } else {
-        log_info(cds)("Cannot use CDS heap data. UseEpsilonGC, UseG1GC, UseSerialGC, UseParallelGC, or UseShenandoahGC are required.");
+        MetaspaceShared::report_loading_error("Cannot use CDS heap data. UseEpsilonGC, UseG1GC, UseSerialGC, UseParallelGC, or UseShenandoahGC are required.");
       }
     }
   }
@@ -1468,8 +1468,10 @@ void FileMapInfo::map_or_load_heap_region() {
       // all AOT-linked classes are visible.
       //
       // We get here because the heap is too small. The app will fail anyway. So let's quit.
-      MetaspaceShared::unrecoverable_loading_error("CDS archive has aot-linked classes but the archived "
-                                                   "heap objects cannot be loaded. Try increasing your heap size.");
+      log_error(cds)("%s has aot-linked classes but the archived "
+                     "heap objects cannot be loaded. Try increasing your heap size.",
+                     CDSConfig::type_of_archive_being_loaded());
+      MetaspaceShared::unrecoverable_loading_error();
     }
     CDSConfig::stop_using_full_module_graph("archive heap loading failed");
   }
@@ -1635,7 +1637,7 @@ bool FileMapInfo::map_heap_region_impl() {
   // allocate from java heap
   HeapWord* start = G1CollectedHeap::heap()->alloc_archive_region(word_size, (HeapWord*)requested_start);
   if (start == nullptr) {
-    log_info(cds)("UseSharedSpaces: Unable to allocate java heap region for archive heap.");
+    MetaspaceShared::report_loading_error("UseSharedSpaces: Unable to allocate java heap region for archive heap.");
     return false;
   }
 
@@ -1670,7 +1672,7 @@ bool FileMapInfo::map_heap_region_impl() {
 
     if (VerifySharedSpaces && !r->check_region_crc(base)) {
       dealloc_heap_region();
-      log_info(cds)("UseSharedSpaces: mapped heap region is corrupt");
+      MetaspaceShared::report_loading_error("UseSharedSpaces: mapped heap region is corrupt");
       return false;
     }
   }
@@ -1694,7 +1696,7 @@ bool FileMapInfo::map_heap_region_impl() {
   if (_heap_pointers_need_patching) {
     char* bitmap_base = map_bitmap_region();
     if (bitmap_base == nullptr) {
-      log_info(cds)("CDS heap cannot be used because bitmap region cannot be mapped");
+      MetaspaceShared::report_loading_error("CDS heap cannot be used because bitmap region cannot be mapped");
       dealloc_heap_region();
       _heap_pointers_need_patching = false;
       return false;
@@ -1807,16 +1809,16 @@ bool FileMapInfo::open_as_input() {
     // are replaced at runtime by JVMTI ClassFileLoadHook. All of those classes are resolved
     // during the JVMTI "early" stage, so we can still use CDS if
     // JvmtiExport::has_early_class_hook_env() is false.
-    log_info(cds)("CDS is disabled because early JVMTI ClassFileLoadHook is in use.");
+    MetaspaceShared::report_loading_error("CDS is disabled because early JVMTI ClassFileLoadHook is in use.");
     return false;
   }
 
   if (!open_for_read() || !init_from_file(_fd) || !validate_header()) {
     if (_is_static) {
-      log_info(cds)("Loading static archive failed.");
+      MetaspaceShared::report_loading_error("Loading static archive failed.");
       return false;
     } else {
-      log_info(cds)("Loading dynamic archive failed.");
+      MetaspaceShared::report_loading_error("Loading dynamic archive failed.");
       if (AutoCreateSharedArchive) {
         CDSConfig::enable_dumping_dynamic_archive(_full_path);
       }
@@ -1831,29 +1833,34 @@ bool FileMapInfo::validate_aot_class_linking() {
   // These checks need to be done after FileMapInfo::initialize(), which gets called before Universe::heap()
   // is available.
   if (header()->has_aot_linked_classes()) {
+    const char* archive_type = CDSConfig::type_of_archive_being_loaded();
     CDSConfig::set_has_aot_linked_classes(true);
     if (JvmtiExport::should_post_class_file_load_hook()) {
-      log_error(cds)("CDS archive has aot-linked classes. It cannot be used when JVMTI ClassFileLoadHook is in use.");
+      log_error(cds)("%s has aot-linked classes. It cannot be used when JVMTI ClassFileLoadHook is in use.",
+                     archive_type);
       return false;
     }
     if (JvmtiExport::has_early_vmstart_env()) {
-      log_error(cds)("CDS archive has aot-linked classes. It cannot be used when JVMTI early vm start is in use.");
+      log_error(cds)("%s has aot-linked classes. It cannot be used when JVMTI early vm start is in use.",
+                     archive_type);
       return false;
     }
     if (!CDSConfig::is_using_full_module_graph()) {
-      log_error(cds)("CDS archive has aot-linked classes. It cannot be used when archived full module graph is not used.");
+      log_error(cds)("%s has aot-linked classes. It cannot be used when archived full module graph is not used.",
+                     archive_type);
       return false;
     }
 
     const char* prop = Arguments::get_property("java.security.manager");
     if (prop != nullptr && strcmp(prop, "disallow") != 0) {
-      log_error(cds)("CDS archive has aot-linked classes. It cannot be used with -Djava.security.manager=%s.", prop);
+      log_error(cds)("%s has aot-linked classes. It cannot be used with -Djava.security.manager=%s.",
+                     archive_type, prop);
       return false;
     }
 
 #if INCLUDE_JVMTI
     if (Arguments::has_jdwp_agent()) {
-      log_error(cds)("CDS archive has aot-linked classes. It cannot be used with JDWP agent");
+      log_error(cds)("%s has aot-linked classes. It cannot be used with JDWP agent", archive_type);
       return false;
     }
 #endif
@@ -1913,8 +1920,8 @@ bool FileMapHeader::validate() {
   const char* prop = Arguments::get_property("java.system.class.loader");
   if (prop != nullptr) {
     if (has_aot_linked_classes()) {
-      log_error(cds)("CDS archive has aot-linked classes. It cannot be used when the "
-                     "java.system.class.loader property is specified.");
+      log_error(cds)("%s has aot-linked classes. It cannot be used when the "
+                     "java.system.class.loader property is specified.", CDSConfig::type_of_archive_being_loaded());
       return false;
     }
     log_warning(cds)("Archived non-system classes are disabled because the "

src/hotspot/share/cds/metaspaceShared.cpp

@@ -937,7 +937,7 @@ void MetaspaceShared::preload_and_dump_impl(StaticArchiveBuilder& builder, TRAPS
   if (CDSConfig::is_dumping_heap()) {
     assert(CDSConfig::allow_only_single_java_thread(), "Required");
     if (!HeapShared::is_archived_boot_layer_available(THREAD)) {
-      log_info(cds)("archivedBootLayer not available, disabling full module graph");
+      report_loading_error("archivedBootLayer not available, disabling full module graph");
       CDSConfig::stop_dumping_full_module_graph();
     }
     // Do this before link_shared_classes(), as the following line may load new classes.
@@ -1118,10 +1118,7 @@ bool MetaspaceShared::is_shared_static(void* p) {
 // - When -XX:+RequireSharedSpaces is specified, AND the JVM cannot load the archive(s) due
 //   to version or classpath mismatch.
 void MetaspaceShared::unrecoverable_loading_error(const char* message) {
-  log_error(cds)("An error has occurred while processing the %s.", CDSConfig::type_of_archive_being_loaded());
-  if (message != nullptr) {
-    log_error(cds)("%s", message);
-  }
+  report_loading_error(message);
 
   if (CDSConfig::is_dumping_final_static_archive()) {
     vm_exit_during_initialization("Must be a valid AOT configuration generated by the current JVM", AOTConfiguration);
@@ -1132,6 +1129,30 @@ void MetaspaceShared::unrecoverable_loading_error(const char* message) {
   }
 }
 
+void MetaspaceShared::report_loading_error(const char* format, ...) {
+  // If the user doesn't specify any CDS options, we will try to load the default CDS archive, which
+  // may fail due to incompatible VM options. Print at the info level to avoid excessive verbosity.
+  // However, if the user has specified a CDS archive (or AOT cache), they would be interested in
+  // knowing that the loading fails, so we print at the error level.
+  Log(cds) log;
+  LogStream ls_error(log.error());
+  LogStream ls_info(log.info());
+  LogStream& ls = (!CDSConfig::is_using_archive()) || CDSConfig::is_using_only_default_archive() ? ls_info : ls_error;
+
+  static bool printed_error = false;
+  if (!printed_error) { // No need for locks. Loading error checks happen only in main thread.
+    ls.print_cr("An error has occurred while processing the %s. Run with -Xlog:cds for details.", CDSConfig::type_of_archive_being_loaded());
+    printed_error = true;
+  }
+
+  if (format != nullptr) {
+    va_list ap;
+    va_start(ap, format);
+    ls.vprint_cr(format, ap);
+    va_end(ap);
+  }
+}
+
 // This function is called when the JVM is unable to write the specified CDS archive due to an
 // unrecoverable error.
 void MetaspaceShared::unrecoverable_writing_error(const char* message) {
@@ -1193,11 +1214,14 @@ void MetaspaceShared::initialize_runtime_shared_and_meta_spaces() {
     // The base archive cannot be mapped. We cannot dump the dynamic shared archive.
     AutoCreateSharedArchive = false;
     CDSConfig::disable_dumping_dynamic_archive();
-    log_info(cds)("Unable to map shared spaces");
     if (PrintSharedArchiveAndExit) {
       MetaspaceShared::unrecoverable_loading_error("Unable to use shared archive.");
-    } else if (RequireSharedSpaces) {
-      MetaspaceShared::unrecoverable_loading_error("Unable to map shared spaces");
+    } else {
+      if (RequireSharedSpaces) {
+        MetaspaceShared::unrecoverable_loading_error("Unable to map shared spaces");
+      } else {
+        report_loading_error("Unable to map shared spaces");
+      }
     }
   }
 
@@ -1712,8 +1736,8 @@ MapArchiveResult MetaspaceShared::map_archive(FileMapInfo* mapinfo, char* mapped
 
   mapinfo->set_is_mapped(false);
   if (mapinfo->core_region_alignment() != (size_t)core_region_alignment()) {
-    log_info(cds)("Unable to map CDS archive -- core_region_alignment() expected: %zu"
-                  " actual: %zu", mapinfo->core_region_alignment(), core_region_alignment());
+    report_loading_error("Unable to map CDS archive -- core_region_alignment() expected: %zu"
+                         " actual: %zu", mapinfo->core_region_alignment(), core_region_alignment());
     return MAP_ARCHIVE_OTHER_FAILURE;
   }
 

src/hotspot/share/cds/metaspaceShared.hpp

@@ -110,7 +110,8 @@ class MetaspaceShared : AllStatic {
   static bool is_shared_dynamic(void* p) NOT_CDS_RETURN_(false);
   static bool is_shared_static(void* p) NOT_CDS_RETURN_(false);
 
-  static void unrecoverable_loading_error(const char* message = nullptr);
+  static void unrecoverable_loading_error(const char* message = nullptr) ATTRIBUTE_PRINTF(1, 0);
+  static void report_loading_error(const char* format, ...) ATTRIBUTE_PRINTF(1, 0);
   static void unrecoverable_writing_error(const char* message = nullptr);
   static void writing_error(const char* message = nullptr);
 

src/hotspot/share/classfile/modules.cpp

@@ -604,21 +604,21 @@ void Modules::ArchivedProperty::runtime_check() const {
   bool disable = false;
   if (runtime_value == nullptr) {
     if (_archived_value != nullptr) {
-      log_info(cds)("Mismatched values for property %s: %s specified during dump time but not during runtime", _prop, _archived_value);
+      MetaspaceShared::report_loading_error("Mismatched values for property %s: %s specified during dump time but not during runtime", _prop, _archived_value);
       disable = true;
     }
   } else {
     if (_archived_value == nullptr) {
-      log_info(cds)("Mismatched values for property %s: %s specified during runtime but not during dump time", _prop, runtime_value);
+      MetaspaceShared::report_loading_error("Mismatched values for property %s: %s specified during runtime but not during dump time", _prop, runtime_value);
       disable = true;
     } else if (strcmp(runtime_value, _archived_value) != 0) {
-      log_info(cds)("Mismatched values for property %s: runtime %s dump time %s", _prop, runtime_value, _archived_value);
+      MetaspaceShared::report_loading_error("Mismatched values for property %s: runtime %s dump time %s", _prop, runtime_value, _archived_value);
       disable = true;
     }
   }
 
   if (disable) {
-    log_info(cds)("Disabling optimized module handling");
+    MetaspaceShared::report_loading_error("Disabling optimized module handling");
     CDSConfig::stop_using_optimized_module_handling();
   }
 }

test/hotspot/jtreg/runtime/cds/appcds/SharedArchiveConsistency.java

@@ -54,6 +54,7 @@ public class SharedArchiveConsistency {
     };
 
     public static final String HELLO_WORLD = "Hello World";
+    public static final String errMsg = "An error has occurred while processing the shared archive file.";
 
     public static int num_regions = shared_region_name.length;
     public static String[] matchMessages = {
@@ -170,6 +171,7 @@ public static void main(String... args) throws Exception {
         output = shareAuto ? TestCommon.execAuto(execArgs) : TestCommon.execCommon(execArgs);
         output.shouldContain("The shared archive file was created by a different version or build of HotSpot");
         output.shouldNotContain("Checksum verification failed");
+        output.shouldContain(errMsg);
         if (shareAuto) {
             output.shouldContain(HELLO_WORLD);
         }
@@ -194,6 +196,7 @@ public static void main(String... args) throws Exception {
         CDSArchiveUtils.modifyHeaderIntField(copiedJsa, CDSArchiveUtils.offsetVersion(), version);
         output = shareAuto ? TestCommon.execAuto(execArgs) : TestCommon.execCommon(execArgs);
         output.shouldContain("The shared archive file version " + hex(version) + " does not match the required version " + hex(currentCDSArchiveVersion));
+        output.shouldContain(errMsg);
         if (shareAuto) {
             output.shouldContain(HELLO_WORLD);
         }
@@ -237,26 +240,26 @@ public static void main(String... args) throws Exception {
         System.out.println("\n5. Insert bytes at beginning of data section, should fail\n");
         String insertBytes = startNewArchive("insert-bytes");
         CDSArchiveUtils.insertBytesRandomlyAfterHeader(orgJsaFile, insertBytes);
-        testAndCheck(verifyExecArgs);
+        testAndCheck(verifyExecArgs, errMsg);
 
         // delete bytes in data section forward
         System.out.println("\n6a. Delete bytes at beginning of data section, should fail\n");
         String deleteBytes = startNewArchive("delete-bytes");
         CDSArchiveUtils.deleteBytesAtRandomPositionAfterHeader(orgJsaFile, deleteBytes, 4096 /*bytes*/);
-        testAndCheck(verifyExecArgs);
+        testAndCheck(verifyExecArgs, errMsg);
 
         // delete bytes at the end
         System.out.println("\n6b. Delete bytes at the end, should fail\n");
         deleteBytes = startNewArchive("delete-bytes-end");
         CDSArchiveUtils.deleteBytesAtTheEnd(orgJsaFile, deleteBytes);
-        testAndCheck(verifyExecArgs, "The shared archive file has been truncated.");
+        testAndCheck(verifyExecArgs, "The shared archive file has been truncated.", errMsg);
 
         // modify contents in random area
         System.out.println("\n7. modify Content in random areas, should fail\n");
         String randomAreas = startNewArchive("random-areas");
         copiedJsa = CDSArchiveUtils.copyArchiveFile(orgJsaFile, randomAreas);
         CDSArchiveUtils.modifyRegionContentRandomly(copiedJsa);
-        testAndCheck(verifyExecArgs);
+        testAndCheck(verifyExecArgs, errMsg);
 
         // modify _base_archive_name_offet to non-zero
         System.out.println("\n8. modify _base_archive_name_offset to non-zero\n");