From 446fb203b2e27807f0cd2ec78447478a1de19773 Mon Sep 17 00:00:00 2001 From: Coleen Phillimore Date: Wed, 18 Mar 2026 16:07:41 +0000 Subject: [PATCH] 8379015: Convert TraceNewOopMapGeneration to unified logging Reviewed-by: dholmes, matsaave --- src/hotspot/share/classfile/classPrinter.cpp | 3 +- src/hotspot/share/classfile/classPrinter.hpp | 3 +- .../share/interpreter/bytecodeTracer.cpp | 8 +- src/hotspot/share/logging/logTag.hpp | 3 +- src/hotspot/share/oops/generateOopMap.cpp | 111 +++++++----------- src/hotspot/share/runtime/globals.hpp | 12 -- .../runtime/logging/GenerateOopMapTest.java | 84 +++++++++++++ 7 files changed, 139 insertions(+), 85 deletions(-) create mode 100644 test/hotspot/jtreg/runtime/logging/GenerateOopMapTest.java diff --git a/src/hotspot/share/classfile/classPrinter.cpp b/src/hotspot/share/classfile/classPrinter.cpp index 3ed0a5e9840..6cf89f7357f 100644 --- a/src/hotspot/share/classfile/classPrinter.cpp +++ b/src/hotspot/share/classfile/classPrinter.cpp @@ -1,5 +1,5 @@ /* - * Copyright (c) 2022, 2025, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2022, 2026, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -224,6 +224,7 @@ void ClassPrinter::print_flags_help(outputStream* os) { os->print_cr(" 0x%02x - print info for invokehandle", PRINT_METHOD_HANDLE); os->print_cr(" 0x%02x - print details of the C++ and Java objects that represent classes", PRINT_CLASS_DETAILS); os->print_cr(" 0x%02x - print details of the C++ objects that represent methods", PRINT_METHOD_DETAILS); + os->print_cr(" 0x%02x - print MethodData", PRINT_METHOD_DATA); os->cr(); } diff --git a/src/hotspot/share/classfile/classPrinter.hpp b/src/hotspot/share/classfile/classPrinter.hpp index 470e82ddc0e..b09a1a1ef3b 100644 --- a/src/hotspot/share/classfile/classPrinter.hpp +++ b/src/hotspot/share/classfile/classPrinter.hpp @@ -1,5 +1,5 @@ /* - * Copyright (c) 2022, 2025, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2022, 2026, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -54,6 +54,7 @@ public: PRINT_METHOD_HANDLE = 1 << 4, // extra information for invokehandle PRINT_CLASS_DETAILS = 1 << 5, // print details of the C++ and Java objects that represent classes PRINT_METHOD_DETAILS = 1 << 6, // print details of the C++ objects that represent methods + PRINT_METHOD_DATA = 1 << 7, // print MethodData - requires MDO lock }; static bool has_mode(int flags, Mode mode) { return (flags & static_cast(mode)) != 0; diff --git a/src/hotspot/share/interpreter/bytecodeTracer.cpp b/src/hotspot/share/interpreter/bytecodeTracer.cpp index 21974218957..2610a8a2bd6 100644 --- a/src/hotspot/share/interpreter/bytecodeTracer.cpp +++ b/src/hotspot/share/interpreter/bytecodeTracer.cpp @@ -78,7 +78,7 @@ class BytecodePrinter { void print_field_or_method(int cp_index, outputStream* st); void print_dynamic(int cp_index, outputStream* st); void print_attributes(int bci, outputStream* st); - void bytecode_epilog(int bci, outputStream* st); + void print_method_data_at(int bci, outputStream* st); public: BytecodePrinter(int flags = 0) : _is_wide(false), _code(Bytecodes::_illegal), _flags(flags) {} @@ -171,7 +171,9 @@ class BytecodePrinter { } _next_pc = is_wide() ? bcp+2 : bcp+1; print_attributes(bci, st); - bytecode_epilog(bci, st); + if (ClassPrinter::has_mode(_flags, ClassPrinter::PRINT_METHOD_DATA)) { + print_method_data_at(bci, st); + } } }; @@ -598,7 +600,7 @@ void BytecodePrinter::print_attributes(int bci, outputStream* st) { } -void BytecodePrinter::bytecode_epilog(int bci, outputStream* st) { +void BytecodePrinter::print_method_data_at(int bci, outputStream* st) { MethodData* mdo = method()->method_data(); if (mdo != nullptr) { diff --git a/src/hotspot/share/logging/logTag.hpp b/src/hotspot/share/logging/logTag.hpp index 3ad6a197d07..20d61b542b0 100644 --- a/src/hotspot/share/logging/logTag.hpp +++ b/src/hotspot/share/logging/logTag.hpp @@ -1,5 +1,5 @@ /* - * Copyright (c) 2015, 2025, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2015, 2026, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -90,6 +90,7 @@ class outputStream; LOG_TAG(freelist) \ LOG_TAG(gc) \ NOT_PRODUCT(LOG_TAG(generate)) \ + LOG_TAG(generateoopmap) \ LOG_TAG(handshake) \ LOG_TAG(hashtables) \ LOG_TAG(heap) \ diff --git a/src/hotspot/share/oops/generateOopMap.cpp b/src/hotspot/share/oops/generateOopMap.cpp index 5e12c57676d..09912aeaf63 100644 --- a/src/hotspot/share/oops/generateOopMap.cpp +++ b/src/hotspot/share/oops/generateOopMap.cpp @@ -400,9 +400,7 @@ void GenerateOopMap::bb_mark_fct(GenerateOopMap *c, int bci, int *data) { if (c->is_bb_header(bci)) return; - if (TraceNewOopMapGeneration) { - tty->print_cr("Basicblock#%d begins at: %d", c->_bb_count, bci); - } + log_debug(generateoopmap)( "Basicblock#%d begins at: %d", c->_bb_count, bci); c->set_bbmark_bit(bci); c->_bb_count++; } @@ -913,13 +911,12 @@ void GenerateOopMap::do_interpretation() // iterated more than once. int i = 0; do { -#ifndef PRODUCT - if (TraceNewOopMapGeneration) { - tty->print("\n\nIteration #%d of do_interpretation loop, method:\n", i); - method()->print_name(tty); - tty->print("\n\n"); + if (log_is_enabled(Trace, generateoopmap)) { + LogStream st(Log(generateoopmap)::trace()); + st.print("Iteration #%d of do_interpretation loop, method:", i); + method()->print_name(&st); + st.print("\n\n"); } -#endif _conflict = false; _monitor_safe = true; // init_state is now called from init_basic_blocks. The length of a @@ -1084,8 +1081,7 @@ void GenerateOopMap::initialize_vars() { void GenerateOopMap::add_to_ref_init_set(int localNo) { - if (TraceNewOopMapGeneration) - tty->print_cr("Added init vars: %d", localNo); + log_debug(generateoopmap)("Added init vars: %d", localNo); // Is it already in the set? if (_init_vars->contains(localNo) ) @@ -1284,13 +1280,13 @@ void GenerateOopMap::report_monitor_mismatch(const char *msg) { void GenerateOopMap::print_states(outputStream *os, CellTypeState* vec, int num) { for (int i = 0; i < num; i++) { - vec[i].print(tty); + vec[i].print(os); } } // Print the state values at the current bytecode. -void GenerateOopMap::print_current_state(outputStream *os, - BytecodeStream *currentBC, +void GenerateOopMap::print_current_state(outputStream* os, + BytecodeStream* currentBC, bool detailed) { if (detailed) { os->print(" %4d vars = ", currentBC->bci()); @@ -1312,6 +1308,7 @@ void GenerateOopMap::print_current_state(outputStream *os, case Bytecodes::_invokestatic: case Bytecodes::_invokedynamic: case Bytecodes::_invokeinterface: { + ResourceMark rm; int idx = currentBC->has_index_u4() ? currentBC->get_index_u4() : currentBC->get_index_u2(); ConstantPool* cp = method()->constants(); int nameAndTypeIdx = cp->name_and_type_ref_index_at(idx, currentBC->code()); @@ -1342,8 +1339,9 @@ void GenerateOopMap::print_current_state(outputStream *os, // Sets the current state to be the state after executing the // current instruction, starting in the current state. void GenerateOopMap::interp1(BytecodeStream *itr) { - if (TraceNewOopMapGeneration) { - print_current_state(tty, itr, TraceNewOopMapGenerationDetailed); + if (log_is_enabled(Trace, generateoopmap)) { + LogStream st(Log(generateoopmap)::trace()); + print_current_state(&st, itr, Verbose); } // Should we report the results? Result is reported *before* the instruction at the current bci is executed. @@ -2026,9 +2024,7 @@ void GenerateOopMap::ret_jump_targets_do(BytecodeStream *bcs, jmpFct_t jmpFct, i DEBUG_ONLY(BasicBlock* target_bb = &jsr_bb[1];) assert(target_bb == get_basic_block_at(target_bci), "wrong calc. of successor basicblock"); bool alive = jsr_bb->is_alive(); - if (TraceNewOopMapGeneration) { - tty->print("pc = %d, ret -> %d alive: %s\n", bci, target_bci, alive ? "true" : "false"); - } + log_debug(generateoopmap)("pc = %d, ret -> %d alive: %s", bci, target_bci, alive ? "true" : "false"); if (alive) jmpFct(this, target_bci, data); } } @@ -2046,6 +2042,7 @@ char* GenerateOopMap::state_vec_to_string(CellTypeState* vec, int len) { return _state_vec_buf; } +#ifndef PRODUCT void GenerateOopMap::print_time() { tty->print_cr ("Accumulated oopmap times:"); tty->print_cr ("---------------------------"); @@ -2053,6 +2050,7 @@ void GenerateOopMap::print_time() { tty->print_cr (" (%3.0f bytecodes per sec) ", (double)GenerateOopMap::_total_byte_count / GenerateOopMap::_total_oopmap_time.seconds()); } +#endif // // ============ Main Entry Point =========== @@ -2062,27 +2060,16 @@ GenerateOopMap::GenerateOopMap(const methodHandle& method) { _method = method; _max_locals=0; _init_vars = nullptr; - -#ifndef PRODUCT - // If we are doing a detailed trace, include the regular trace information. - if (TraceNewOopMapGenerationDetailed) { - TraceNewOopMapGeneration = true; - } -#endif } bool GenerateOopMap::compute_map(Thread* current) { #ifndef PRODUCT - if (TimeOopMap2) { - method()->print_short_name(tty); - tty->print(" "); - } if (TimeOopMap) { _total_byte_count += method()->code_size(); + TraceTime t_all(nullptr, &_total_oopmap_time, TimeOopMap); } #endif - TraceTime t_single("oopmap time", TimeOopMap2); - TraceTime t_all(nullptr, &_total_oopmap_time, TimeOopMap); + TraceTime t_single("oopmap time", TRACETIME_LOG(Debug, generateoopmap)); // Initialize values _got_error = false; @@ -2099,16 +2086,16 @@ bool GenerateOopMap::compute_map(Thread* current) { _did_rewriting = false; _did_relocation = false; - if (TraceNewOopMapGeneration) { - tty->print("Method name: %s\n", method()->name()->as_C_string()); - if (Verbose) { - _method->print_codes(); - tty->print_cr("Exception table:"); - ExceptionTable excps(method()); - for(int i = 0; i < excps.length(); i ++) { - tty->print_cr("[%d - %d] -> %d", - excps.start_pc(i), excps.end_pc(i), excps.handler_pc(i)); - } + if (log_is_enabled(Debug, generateoopmap)) { + ResourceMark rm; + LogStream st(Log(generateoopmap)::debug()); + st.print_cr("Method name: %s\n", method()->name()->as_C_string()); + _method->print_codes_on(&st); + st.print_cr("Exception table:"); + ExceptionTable excps(method()); + for (int i = 0; i < excps.length(); i ++) { + st.print_cr("[%d - %d] -> %d", + excps.start_pc(i), excps.end_pc(i), excps.handler_pc(i)); } } @@ -2175,7 +2162,7 @@ void GenerateOopMap::verify_error(const char *format, ...) { // void GenerateOopMap::report_result() { - if (TraceNewOopMapGeneration) tty->print_cr("Report result pass"); + log_debug(generateoopmap)("Report result pass"); // We now want to report the result of the parse _report_result = true; @@ -2192,7 +2179,7 @@ void GenerateOopMap::report_result() { } void GenerateOopMap::result_for_basicblock(int bci) { - if (TraceNewOopMapGeneration) tty->print_cr("Report result pass for basicblock"); + log_debug(generateoopmap)("Report result pass for basicblock"); // We now want to report the result of the parse _report_result = true; @@ -2200,7 +2187,7 @@ void GenerateOopMap::result_for_basicblock(int bci) { // Find basicblock and report results BasicBlock* bb = get_basic_block_containing(bci); guarantee(bb != nullptr, "no basic block for bci"); - assert(bb->is_reachable(), "getting result from unreachable basicblock"); + assert(bb->is_reachable(), "getting result from unreachable basicblock %d", bci); bb->set_changed(true); interp_bb(bb); } @@ -2212,9 +2199,7 @@ void GenerateOopMap::result_for_basicblock(int bci) { void GenerateOopMap::record_refval_conflict(int varNo) { assert(varNo>=0 && varNo< _max_locals, "index out of range"); - if (TraceOopMapRewrites) { - tty->print("### Conflict detected (local no: %d)\n", varNo); - } + log_trace(generateoopmap)("### Conflict detected (local no: %d)", varNo); if (!_new_var_map) { _new_var_map = NEW_RESOURCE_ARRAY(int, _max_locals); @@ -2253,10 +2238,12 @@ void GenerateOopMap::rewrite_refval_conflicts() // Tracing flag _did_rewriting = true; - if (TraceOopMapRewrites) { - tty->print_cr("ref/value conflict for method %s - bytecodes are getting rewritten", method()->name()->as_C_string()); - method()->print(); - method()->print_codes(); + if (log_is_enabled(Trace, generateoopmap)) { + ResourceMark rm; + LogStream st(Log(generateoopmap)::trace()); + st.print_cr("ref/value conflict for method %s - bytecodes are getting rewritten", method()->name()->as_C_string()); + method()->print_on(&st); + method()->print_codes_on(&st); } assert(_new_var_map!=nullptr, "nothing to rewrite"); @@ -2266,9 +2253,7 @@ void GenerateOopMap::rewrite_refval_conflicts() if (!_got_error) { for (int k = 0; k < _max_locals && !_got_error; k++) { if (_new_var_map[k] != k) { - if (TraceOopMapRewrites) { - tty->print_cr("Rewriting: %d -> %d", k, _new_var_map[k]); - } + log_trace(generateoopmap)("Rewriting: %d -> %d", k, _new_var_map[k]); rewrite_refval_conflict(k, _new_var_map[k]); if (_got_error) return; nof_conflicts++; @@ -2319,22 +2304,16 @@ bool GenerateOopMap::rewrite_refval_conflict_inst(BytecodeStream *itr, int from, int bci = itr->bci(); if (is_aload(itr, &index) && index == from) { - if (TraceOopMapRewrites) { - tty->print_cr("Rewriting aload at bci: %d", bci); - } + log_trace(generateoopmap)("Rewriting aload at bci: %d", bci); return rewrite_load_or_store(itr, Bytecodes::_aload, Bytecodes::_aload_0, to); } if (is_astore(itr, &index) && index == from) { if (!stack_top_holds_ret_addr(bci)) { - if (TraceOopMapRewrites) { - tty->print_cr("Rewriting astore at bci: %d", bci); - } + log_trace(generateoopmap)("Rewriting astore at bci: %d", bci); return rewrite_load_or_store(itr, Bytecodes::_astore, Bytecodes::_astore_0, to); } else { - if (TraceOopMapRewrites) { - tty->print_cr("Suppress rewriting of astore at bci: %d", bci); - } + log_trace(generateoopmap)("Suppress rewriting of astore at bci: %d", bci); } } @@ -2502,9 +2481,7 @@ void GenerateOopMap::compute_ret_adr_at_TOS() { // TDT: should this be is_good_address() ? if (_stack_top > 0 && stack()[_stack_top-1].is_address()) { _ret_adr_tos->append(bcs.bci()); - if (TraceNewOopMapGeneration) { - tty->print_cr("Ret_adr TOS at bci: %d", bcs.bci()); - } + log_debug(generateoopmap)("Ret_adr TOS at bci: %d", bcs.bci()); } interp1(&bcs); } diff --git a/src/hotspot/share/runtime/globals.hpp b/src/hotspot/share/runtime/globals.hpp index 559071cae68..0c627e27209 100644 --- a/src/hotspot/share/runtime/globals.hpp +++ b/src/hotspot/share/runtime/globals.hpp @@ -871,21 +871,9 @@ const int ObjectAlignmentInBytes = 8; develop(bool, VerifyDependencies, trueInDebug, \ "Exercise and verify the compilation dependency mechanism") \ \ - develop(bool, TraceNewOopMapGeneration, false, \ - "Trace OopMapGeneration") \ - \ - develop(bool, TraceNewOopMapGenerationDetailed, false, \ - "Trace OopMapGeneration: print detailed cell states") \ - \ develop(bool, TimeOopMap, false, \ "Time calls to GenerateOopMap::compute_map() in sum") \ \ - develop(bool, TimeOopMap2, false, \ - "Time calls to GenerateOopMap::compute_map() individually") \ - \ - develop(bool, TraceOopMapRewrites, false, \ - "Trace rewriting of methods during oop map generation") \ - \ develop(bool, TraceFinalizerRegistration, false, \ "Trace registration of final references") \ \ diff --git a/test/hotspot/jtreg/runtime/logging/GenerateOopMapTest.java b/test/hotspot/jtreg/runtime/logging/GenerateOopMapTest.java new file mode 100644 index 00000000000..6e114ff6b1d --- /dev/null +++ b/test/hotspot/jtreg/runtime/logging/GenerateOopMapTest.java @@ -0,0 +1,84 @@ +/* + * Copyright (c) 2026, Oracle and/or its affiliates. All rights reserved. + * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. + * + * This code is free software; you can redistribute it and/or modify it + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + */ + + +/* + * @test GenerateOopMap + * @bug 8379015 + * @requires vm.flagless + * @modules java.base/jdk.internal.misc + * @library /test/lib + * @run driver GenerateOopMapTest + */ + +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.regex.Matcher; +import java.util.regex.Pattern; +import jdk.test.lib.process.OutputAnalyzer; +import jdk.test.lib.process.ProcessTools; +import jdk.test.lib.Platform; + +public class GenerateOopMapTest { + + static String infoPattern = "[generateoopmap]"; + static String debugPattern = "[generateoopmap] Basicblock#0 begins at:"; + static String tracePattern = "[trace][generateoopmap] 5 vars = 'r' stack = 'v' monitors = '' \tifne"; + static String traceDetailPattern = "[generateoopmap] 0 vars = ( r |slot0) invokestatic()V"; + + static void test() throws Exception { + // Don't print much with info level. + ProcessBuilder pb = ProcessTools.createLimitedTestJavaProcessBuilder("-Xlog:generateoopmap=info", + "GenerateOopMapTest", "test"); + OutputAnalyzer o = new OutputAnalyzer(pb.start()); + o.shouldNotContain(infoPattern).shouldHaveExitValue(0); + + // Prints bytecodes and BasicBlock information in debug. + pb = ProcessTools.createLimitedTestJavaProcessBuilder("-Xlog:generateoopmap=debug", + "GenerateOopMapTest", "test"); + o = new OutputAnalyzer(pb.start()); + o.shouldContain(debugPattern).shouldHaveExitValue(0); + + // Prints ref/val for each bytecode in trace. + pb = ProcessTools.createLimitedTestJavaProcessBuilder("-Xlog:generateoopmap=trace", + "GenerateOopMapTest", "test"); + o = new OutputAnalyzer(pb.start()); + o.shouldContain(tracePattern).shouldHaveExitValue(0); + + // Prints extra stuff with detailed. Not sure how useful this is but keep it for now. + if (Platform.isDebugBuild()) { + pb = ProcessTools.createLimitedTestJavaProcessBuilder("-Xlog:generateoopmap=trace", + "-XX:+Verbose", + "GenerateOopMapTest", "test"); + o = new OutputAnalyzer(pb.start()); + o.shouldContain(traceDetailPattern).shouldHaveExitValue(0); + } + }; + + public static void main(String... args) throws Exception { + System.gc(); + if (args.length == 0) { + test(); + } + } +}