JDK-8349968 : NMT should never use tty for error logging
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: runtime
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • Submitted: 2025-02-13
  • Updated: 2025-08-15
  • Resolved: 2025-08-15
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 26
26Resolved
Related Reports
Duplicate :  
Description
see e.g. VirtualMemoryTracker::add_reserved_region

While working on JDK-8330174, I get this:

```
  1 #                                                                                                                                                                                                                                                    
  2 # A fatal error has been detected by the Java Runtime Environment:
  3 #
  4 #  Internal Error (/shared/projects/openjdk/jdk-jdk/source/src/hotspot/share/runtime/mutex.cpp:457), pid=363333, tid=363334
  5 #  assert(false) failed: Attempting to acquire lock tty_lock/tty out of order with lock NmtVirtualMemory_lock/service-4 -- possible deadlock
  6 #
  7 # JRE version:  (25.0) (slowdebug build )
  8 # Java VM: OpenJDK 64-Bit Server VM (slowdebug 25-internal-adhoc.thomas.source, mixed mode, sharing, tiered, compressed oops, compressed class ptrs, g1 gc, linux-amd64)
  9 # Problematic frame:
 10 # V  [libjvm.so+0x13c54eb]  Mutex::check_rank(Thread*)+0x3c1
 11 #
 12 # Core dump will be written. Default location: Core dumps may be processed with "/usr/share/apport/apport -p%p -s%s -c%c -d%d -P%P -u%u -g%g -- %E" (or dumping to /shared/projects/openjdk/jdk-jdk/output-slowdebug/core.363333)
 13 #
 14 #
 15 
 16 ---------------  S U M M A R Y ------------
 17 
 18 Command Line: -Xshare:on -XX:+UseNewCode -Xlog:metaspace* -Xlog:cds+map
 19 
 20 Host: starfish, AMD Ryzen 9 3900X 12-Core Processor, 24 cores, 62G, Ubuntu 20.04.6 LTS
 21 Time: Thu Feb 13 09:26:33 2025 CET elapsed time: 0.062652 seconds (0d 0h 0m 0s)
 22 
 23 ---------------  T H R E A D  ---------------
 24 
 25 Current thread (0x00007f8b1c02d480):  JavaThread "Unknown thread" [_thread_in_vm, id=363334, stack(0x00007f8b20866000,0x00007f8b20967000) (1028K)]
 26 
 27 Stack: [0x00007f8b20866000,0x00007f8b20967000],  sp=0x00007f8b20962900,  free space=1010k
 28 Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
 29 V  [libjvm.so+0x13c54eb]  Mutex::check_rank(Thread*)+0x3c1  (mutex.cpp:457)
 30 V  [libjvm.so+0x13c4219]  Mutex::lock_without_safepoint_check(Thread*)+0x99  (mutex.cpp:145)
 31 V  [libjvm.so+0x13c4277]  Mutex::lock_without_safepoint_check()+0x27  (mutex.cpp:153)
 32 V  [libjvm.so+0x145e5d9]  defaultStream::hold(long)+0xc3  (ostream.cpp:871)
 33 V  [libjvm.so+0x145e6c6]  defaultStream::write(char const*, unsigned long)+0x34  (ostream.cpp:899)
 34 V  [libjvm.so+0x145c047]  outputStream::do_vsnprintf_and_write_with_automatic_buffer(char const*, __va_list_tag*, bool)+0xa7  (ostream.cpp:144)
 35 V  [libjvm.so+0x145c153]  outputStream::do_vsnprintf_and_write(char const*, __va_list_tag*, bool)+0x7f  (ostream.cpp:160)
 36 V  [libjvm.so+0x145c2b2]  outputStream::print_cr(char const*, ...)+0xac  (ostream.cpp:174)
 37 V  [libjvm.so+0x18ab25d]  VirtualMemoryTracker::add_reserved_region(unsigned char*, unsigned long, NativeCallStack const&, MemTag)+0x70d  (virtualMemoryTracker.cpp:400)
 38 V  [libjvm.so+0x144047e]  MemTracker::record_virtual_memory_reserve_and_commit(void*, unsigned long, NativeCallStack const&, MemTag)+0x59  (memTracker.hpp:160)
 39 V  [libjvm.so+0x143ec48]  os::map_memory(int, char const*, unsigned long, char*, unsigned long, bool, bool, MemTag)+0xae  (os.cpp:2303)
 40 V  [libjvm.so+0xcd1119]  map_memory(int, char const*, unsigned long, char*, unsigned long, bool, bool, MemTag)+0x78  (filemap.cpp:1782)
 41 V  [libjvm.so+0xcd1bb1]  FileMapInfo::map_region(int, long, char*, ReservedSpace)+0x35d  (filemap.cpp:1931)
 42 V  [libjvm.so+0xcd13db]  FileMapInfo::map_regions(int*, int, char*, ReservedSpace)+0xb9  (filemap.cpp:1838)
 43 V  [libjvm.so+0x13787d8]  MetaspaceShared::map_archive(FileMapInfo*, char*, ReservedSpace)+0x124  (metaspaceShared.cpp:1651)
 44 V  [libjvm.so+0x13773f3]  MetaspaceShared::map_archives(FileMapInfo*, FileMapInfo*, bool)+0x61d  (metaspaceShared.cpp:1302)
 45 V  [libjvm.so+0x137697f]  MetaspaceShared::initialize_runtime_shared_and_meta_spaces()+0xdb  (metaspaceShared.cpp:1122)
 46 V  [libjvm.so+0x136a4a4]  Metaspace::global_initialize()+0xce  (metaspace.cpp:739)
 47 V  [libjvm.so+0x1848f81]  universe_init()+0xd7  (universe.cpp:887)
 48 V  [libjvm.so+0xea1c62]  init_globals()+0x60  (init.cpp:132)
 49 V  [libjvm.so+0x1820ff4]  Threads::create_vm(JavaVMInitArgs*, bool*)+0x3fe  (threads.cpp:576)
 50 V  [libjvm.so+0xff8c19]  JNI_CreateJavaVM_inner(JavaVM_**, void**, void*)+0xbb  (jni.cpp:3588)
 51 V  [libjvm.so+0xff9081]  JNI_CreateJavaVM+0x36  (jni.cpp:3679)
 52 C  [libjli.so+0x8d8f]  InitializeJVM+0x141  (java.c:1499)
 53 C  [libjli.so+0x5882]  JavaMain+0xec  (java.c:494)
 54 C  [libjli.so+0xc808]  ThreadJavaMain+0x2b  (java_md.c:649)
```

Okay, its a rank problem, but NMT should really never use tty to begin with. It should consistently use UL (log_error or log_warning).

Comments
[~stuefe], to be clear: log_error and log_warning does not print unconditionally, but I think you know that (so this is for other readers). Of course, log_error and log_warning does not print to stdout :-). They, like all UL messages, print to whatever outputs are associated with that logging level and tagsets and you are free to set the output to stderr if so desired!
18-02-2025

Transitioning away from use of tty is a "Good Thing" - as long as it will work reliably. I'm not sure what you are saying about log_error and log_warning - the way those macros expand would make it very heavyweight to allow for printing direct to stderr/stdout if UL was not initialized. I prefer if the UL logging APIs are limited to UL. If we need something before UL is initialized I'd prefer to see that clearly observable at the call-site.
17-02-2025

[~dholmes] I don't think so. UL gets initialized before argument parsing. We don't do mmaps that early. Even if they were to happen, note that we won't crash, we would "just" miss the output. Also note that I always thought log_error and log_warning - which print unconditionally and which I would use in cases like these - should print to stderr (not even tty, that is not safe either this early) as long as UL is not initialized. We never want to miss them, even if they happen very early. This would be useful, you agree? Good starter issue, too.
14-02-2025

Right in this crashing case, but more generally can VirtualMemoryTracker::add_reserved_region be called before UL is initialized?
14-02-2025

No, this is not one of those places. UL is initialized earlier.
14-02-2025

Isn't this a case where UL is not yet initialized so NMT can't use it?
14-02-2025