Path: blob/master/src/hotspot/share/logging/logConfiguration.cpp
64440 views
/*1* Copyright (c) 2015, 2022, Oracle and/or its affiliates. All rights reserved.2* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.3*4* This code is free software; you can redistribute it and/or modify it5* under the terms of the GNU General Public License version 2 only, as6* published by the Free Software Foundation.7*8* This code is distributed in the hope that it will be useful, but WITHOUT9* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or10* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License11* version 2 for more details (a copy is included in the LICENSE file that12* accompanied this code).13*14* You should have received a copy of the GNU General Public License version15* 2 along with this work; if not, write to the Free Software Foundation,16* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.17*18* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA19* or visit www.oracle.com if you need additional information or have any20* questions.21*22*/23#include "precompiled.hpp"24#include "jvm.h"25#include "logging/log.hpp"26#include "logging/logAsyncWriter.hpp"27#include "logging/logConfiguration.hpp"28#include "logging/logDecorations.hpp"29#include "logging/logDecorators.hpp"30#include "logging/logDiagnosticCommand.hpp"31#include "logging/logFileOutput.hpp"32#include "logging/logOutput.hpp"33#include "logging/logSelectionList.hpp"34#include "logging/logStream.hpp"35#include "logging/logTagSet.hpp"36#include "memory/allocation.inline.hpp"37#include "memory/resourceArea.hpp"38#include "runtime/os.hpp"39#include "runtime/semaphore.hpp"40#include "utilities/globalDefinitions.hpp"4142LogOutput** LogConfiguration::_outputs = NULL;43size_t LogConfiguration::_n_outputs = 0;4445LogConfiguration::UpdateListenerFunction* LogConfiguration::_listener_callbacks = NULL;46size_t LogConfiguration::_n_listener_callbacks = 0;4748// LogFileOutput is the default type of output, its type prefix should be used if no type was specified49static const char* implicit_output_prefix = LogFileOutput::Prefix;5051// Stack object to take the lock for configuring the logging.52// Should only be held during the critical parts of the configuration53// (when calling configure_output or reading/modifying the outputs array).54// Thread must never block when holding this lock.55class ConfigurationLock : public StackObj {56private:57// Semaphore used as lock58static Semaphore _semaphore;59debug_only(static intx _locking_thread_id;)60public:61ConfigurationLock() {62_semaphore.wait();63debug_only(_locking_thread_id = os::current_thread_id());64}65~ConfigurationLock() {66debug_only(_locking_thread_id = -1);67_semaphore.signal();68}69debug_only(static bool current_thread_has_lock();)70};7172Semaphore ConfigurationLock::_semaphore(1);73#ifdef ASSERT74intx ConfigurationLock::_locking_thread_id = -1;75bool ConfigurationLock::current_thread_has_lock() {76return _locking_thread_id == os::current_thread_id();77}78#endif7980void LogConfiguration::post_initialize() {81// Reset the reconfigured status of all outputs82for (size_t i = 0; i < _n_outputs; i++) {83_outputs[i]->_reconfigured = false;84}8586LogDiagnosticCommand::registerCommand();87Log(logging) log;88if (log.is_info()) {89log.info("Log configuration fully initialized.");90log_develop_info(logging)("Develop logging is available.");9192LogStream info_stream(log.info());93describe_available(&info_stream);9495LogStream debug_stream(log.debug());96LogTagSet::list_all_tagsets(&debug_stream);9798ConfigurationLock cl;99describe_current_configuration(&info_stream);100}101}102103void LogConfiguration::initialize(jlong vm_start_time) {104LogFileOutput::set_file_name_parameters(vm_start_time);105assert(_outputs == NULL, "Should not initialize _outputs before this function, initialize called twice?");106_outputs = NEW_C_HEAP_ARRAY(LogOutput*, 2, mtLogging);107_outputs[0] = &StdoutLog;108_outputs[1] = &StderrLog;109_n_outputs = 2;110}111112void LogConfiguration::finalize() {113disable_outputs();114FREE_C_HEAP_ARRAY(LogOutput*, _outputs);115}116117// Normalizes the given LogOutput name to type=name form.118// For example, foo, "foo", file="foo", will all be normalized to file=foo (no quotes, prefixed).119static bool normalize_output_name(const char* full_name, char* buffer, size_t len, outputStream* errstream) {120const char* start_quote = strchr(full_name, '"');121const char* equals = strchr(full_name, '=');122const bool quoted = start_quote != NULL;123const bool is_stdout_or_stderr = (strcmp(full_name, "stdout") == 0 || strcmp(full_name, "stderr") == 0);124125// ignore equals sign within quotes126if (quoted && equals > start_quote) {127equals = NULL;128}129130const char* prefix = "";131size_t prefix_len = 0;132const char* name = full_name;133if (equals != NULL) {134// split on equals sign135name = equals + 1;136prefix = full_name;137prefix_len = equals - full_name + 1;138} else if (!is_stdout_or_stderr) {139prefix = implicit_output_prefix;140prefix_len = strlen(prefix);141}142size_t name_len = strlen(name);143144if (quoted) {145const char* end_quote = strchr(start_quote + 1, '"');146if (end_quote == NULL) {147errstream->print_cr("Output name has opening quote but is missing a terminating quote.");148return false;149}150if (start_quote != name || end_quote[1] != '\0') {151errstream->print_cr("Output name can not be partially quoted."152" Either surround the whole name with quotation marks,"153" or do not use quotation marks at all.");154return false;155}156// strip start and end quote157name++;158name_len -= 2;159}160161int ret = jio_snprintf(buffer, len, "%.*s%.*s", prefix_len, prefix, name_len, name);162assert(ret > 0, "buffer issue");163return true;164}165166size_t LogConfiguration::find_output(const char* name) {167for (size_t i = 0; i < _n_outputs; i++) {168if (strcmp(_outputs[i]->name(), name) == 0) {169return i;170}171}172return SIZE_MAX;173}174175LogOutput* LogConfiguration::new_output(const char* name,176const char* options,177outputStream* errstream) {178LogOutput* output;179if (strncmp(name, LogFileOutput::Prefix, strlen(LogFileOutput::Prefix)) == 0) {180output = new LogFileOutput(name);181} else {182errstream->print_cr("Unsupported log output type: %s", name);183return NULL;184}185186bool success = output->initialize(options, errstream);187if (!success) {188errstream->print_cr("Initialization of output '%s' using options '%s' failed.", name, options);189delete output;190return NULL;191}192return output;193}194195size_t LogConfiguration::add_output(LogOutput* output) {196size_t idx = _n_outputs++;197_outputs = REALLOC_C_HEAP_ARRAY(LogOutput*, _outputs, _n_outputs, mtLogging);198_outputs[idx] = output;199return idx;200}201202void LogConfiguration::delete_output(size_t idx) {203assert(idx > 1 && idx < _n_outputs,204"idx must be in range 1 < idx < _n_outputs, but idx = " SIZE_FORMAT205" and _n_outputs = " SIZE_FORMAT, idx, _n_outputs);206LogOutput* output = _outputs[idx];207// Swap places with the last output and shrink the array208_outputs[idx] = _outputs[--_n_outputs];209_outputs = REALLOC_C_HEAP_ARRAY(LogOutput*, _outputs, _n_outputs, mtLogging);210delete output;211}212213// MT-SAFETY214//215// The ConfigurationLock guarantees that only one thread is performing reconfiguration. This function still needs216// to be MT-safe because logsites in other threads may be executing in parallel. Reconfiguration means unified217// logging allows users to dynamically change tags and decorators of a log output via DCMD(logDiagnosticCommand.hpp).218//219// A RCU-style synchronization 'wait_until_no_readers()' is used inside of 'ts->set_output_level(output, level)'220// if a setting has changed. It guarantees that all logs, either synchronous writes or enqueuing to the async buffer221// see the new tags and decorators. It's worth noting that the synchronization occurs even if the level does not change.222//223// LogDecorator is a set of decorators represented in a uint. ts->update_decorators(decorators) is a union of the224// current decorators and new_decorators. It's safe to do output->set_decorators(decorators) because new_decorators225// is a subset of relevant tagsets decorators. After updating output's decorators, it is still safe to shrink all226// decorators of tagsets.227//228void LogConfiguration::configure_output(size_t idx, const LogSelectionList& selections, const LogDecorators& decorators) {229assert(ConfigurationLock::current_thread_has_lock(), "Must hold configuration lock to call this function.");230assert(idx < _n_outputs, "Invalid index, idx = " SIZE_FORMAT " and _n_outputs = " SIZE_FORMAT, idx, _n_outputs);231LogOutput* output = _outputs[idx];232233output->_reconfigured = true;234235size_t on_level[LogLevel::Count] = {0};236237bool enabled = false;238for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {239LogLevelType level = selections.level_for(*ts);240241// Ignore tagsets that do not, and will not log on the output242if (!ts->has_output(output) && (level == LogLevel::NotMentioned || level == LogLevel::Off)) {243on_level[LogLevel::Off]++;244continue;245}246247// Update decorators before adding/updating output level,248// so that the tagset will have the necessary decorators when requiring them.249if (level != LogLevel::Off) {250ts->update_decorators(decorators);251}252253// Set the new level, if it changed254if (level != LogLevel::NotMentioned) {255ts->set_output_level(output, level);256} else {257// Look up the previously set level for this output on this tagset258level = ts->level_for(output);259}260261if (level != LogLevel::Off) {262// Keep track of whether or not the output is ever used by some tagset263enabled = true;264}265266// Track of the number of tag sets on each level267on_level[level]++;268}269270// For async logging we have to ensure that all enqueued messages, which may refer to previous decorators,271// or a soon-to-be-deleted output, are written out first. The flush() call ensures this.272AsyncLogWriter::flush();273274// It is now safe to set the new decorators for the actual output275output->set_decorators(decorators);276277// Update the decorators on all tagsets to get rid of unused decorators278for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {279ts->update_decorators();280}281282if (!enabled && idx > 1) {283// Output is unused and should be removed, unless it is stdout/stderr (idx < 2)284delete_output(idx);285return;286}287288output->update_config_string(on_level);289assert(strlen(output->config_string()) > 0, "should always have a config description");290}291292void LogConfiguration::disable_outputs() {293size_t idx = _n_outputs;294295// Remove all outputs from all tagsets.296for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {297ts->disable_outputs();298}299300// Handle 'jcmd VM.log disable' and JVM termination.301// ts->disable_outputs() above has disabled all output_lists with RCU synchronization.302// Therefore, no new logging message can enter the async buffer for the time being.303// flush out all pending messages before LogOutput instances die.304AsyncLogWriter::flush();305306while (idx > 0) {307LogOutput* out = _outputs[--idx];308// Delete the output unless stdout or stderr (idx 0 or 1)309if (idx > 1) {310delete_output(idx);311} else {312out->set_config_string("all=off");313}314}315}316317void LogConfiguration::disable_logging() {318ConfigurationLock cl;319disable_outputs();320// Update the decorators on all tagsets to get rid of unused decorators321for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {322ts->update_decorators();323}324notify_update_listeners();325}326327void LogConfiguration::configure_stdout(LogLevelType level, int exact_match, ...) {328size_t i;329va_list ap;330LogTagType tags[LogTag::MaxTags];331va_start(ap, exact_match);332for (i = 0; i < LogTag::MaxTags; i++) {333LogTagType tag = static_cast<LogTagType>(va_arg(ap, int));334tags[i] = tag;335if (tag == LogTag::__NO_TAG) {336assert(i > 0, "Must specify at least one tag!");337break;338}339}340assert(i < LogTag::MaxTags || static_cast<LogTagType>(va_arg(ap, int)) == LogTag::__NO_TAG,341"Too many tags specified! Can only have up to " SIZE_FORMAT " tags in a tag set.", LogTag::MaxTags);342va_end(ap);343344LogSelection selection(tags, !exact_match, level);345assert(selection.tag_sets_selected() > 0,346"configure_stdout() called with invalid/non-existing log selection");347LogSelectionList list(selection);348349// Apply configuration to stdout (output #0), with the same decorators as before.350ConfigurationLock cl;351configure_output(0, list, _outputs[0]->decorators());352notify_update_listeners();353}354355bool LogConfiguration::parse_command_line_arguments(const char* opts) {356char* copy = os::strdup_check_oom(opts, mtLogging);357358// Split the option string to its colon separated components.359char* str = copy;360char* substrings[4] = {0};361for (int i = 0 ; i < 4; i++) {362substrings[i] = str;363364// Find the next colon or quote365char* next = strpbrk(str, ":\"");366#ifdef _WINDOWS367// Skip over Windows paths such as "C:\..." and "C:/...".368// Handles both "C:\..." and "file=C:\...".369if (next != NULL && next[0] == ':' && (next[1] == '\\' || next[1] == '/')) {370if (next == str + 1 || (strncmp(str, "file=", 5) == 0)) {371next = strpbrk(next + 1, ":\"");372}373}374#endif375while (next != NULL && *next == '"') {376char* end_quote = strchr(next + 1, '"');377if (end_quote == NULL) {378log_error(logging)("Missing terminating quote in -Xlog option '%s'", str);379os::free(copy);380return false;381}382// Keep searching after the quoted substring383next = strpbrk(end_quote + 1, ":\"");384}385386if (next != NULL) {387*next = '\0';388str = next + 1;389} else {390str = NULL;391break;392}393}394395if (str != NULL) {396log_warning(logging)("Ignoring excess -Xlog options: \"%s\"", str);397}398399// Parse and apply the separated configuration options400char* what = substrings[0];401char* output = substrings[1];402char* decorators = substrings[2];403char* output_options = substrings[3];404char errbuf[512];405stringStream ss(errbuf, sizeof(errbuf));406bool success = parse_log_arguments(output, what, decorators, output_options, &ss);407408if (ss.size() > 0) {409// If it failed, log the error. If it didn't fail, but something was written410// to the stream, log it as a warning.411LogLevelType level = success ? LogLevel::Warning : LogLevel::Error;412413Log(logging) log;414char* start = errbuf;415char* end = strchr(start, '\n');416assert(end != NULL, "line must end with newline '%s'", start);417do {418assert(start < errbuf + sizeof(errbuf) &&419end < errbuf + sizeof(errbuf),420"buffer overflow");421*end = '\0';422log.write(level, "%s", start);423start = end + 1;424end = strchr(start, '\n');425assert(end != NULL || *start == '\0', "line must end with newline '%s'", start);426} while (end != NULL);427}428429os::free(copy);430return success;431}432433bool LogConfiguration::parse_log_arguments(const char* outputstr,434const char* selectionstr,435const char* decoratorstr,436const char* output_options,437outputStream* errstream) {438assert(errstream != NULL, "errstream can not be NULL");439if (outputstr == NULL || strlen(outputstr) == 0) {440outputstr = "stdout";441}442443LogSelectionList selections;444if (!selections.parse(selectionstr, errstream)) {445return false;446}447448LogDecorators decorators;449if (!decorators.parse(decoratorstr, errstream)) {450return false;451}452453ConfigurationLock cl;454size_t idx;455bool added = false;456if (outputstr[0] == '#') { // Output specified using index457int ret = sscanf(outputstr + 1, SIZE_FORMAT, &idx);458if (ret != 1 || idx >= _n_outputs) {459errstream->print_cr("Invalid output index '%s'", outputstr);460return false;461}462} else { // Output specified using name463// Normalize the name, stripping quotes and ensures it includes type prefix464size_t len = strlen(outputstr) + strlen(implicit_output_prefix) + 1;465char* normalized = NEW_C_HEAP_ARRAY(char, len, mtLogging);466if (!normalize_output_name(outputstr, normalized, len, errstream)) {467return false;468}469470idx = find_output(normalized);471if (idx == SIZE_MAX) {472// Attempt to create and add the output473LogOutput* output = new_output(normalized, output_options, errstream);474if (output != NULL) {475idx = add_output(output);476added = true;477}478}479480FREE_C_HEAP_ARRAY(char, normalized);481if (idx == SIZE_MAX) {482return false;483}484}485if (!added && output_options != NULL && strlen(output_options) > 0) {486errstream->print_cr("Output options for existing outputs are ignored.");487}488configure_output(idx, selections, decorators);489notify_update_listeners();490selections.verify_selections(errstream);491return true;492}493494void LogConfiguration::describe_available(outputStream* out) {495out->print("Available log levels:");496for (size_t i = 0; i < LogLevel::Count; i++) {497out->print("%s %s", (i == 0 ? "" : ","), LogLevel::name(static_cast<LogLevelType>(i)));498}499out->cr();500501out->print("Available log decorators:");502for (size_t i = 0; i < LogDecorators::Count; i++) {503LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i);504out->print("%s %s (%s)", (i == 0 ? "" : ","), LogDecorators::name(d), LogDecorators::abbreviation(d));505}506out->cr();507508out->print("Available log tags:");509LogTag::list_tags(out);510511LogTagSet::describe_tagsets(out);512}513514void LogConfiguration::describe_current_configuration(outputStream* out) {515out->print_cr("Log output configuration:");516for (size_t i = 0; i < _n_outputs; i++) {517out->print(" #" SIZE_FORMAT ": ", i);518_outputs[i]->describe(out);519if (_outputs[i]->is_reconfigured()) {520out->print(" (reconfigured)");521}522out->cr();523}524}525526void LogConfiguration::describe(outputStream* out) {527describe_available(out);528ConfigurationLock cl;529describe_current_configuration(out);530}531532void LogConfiguration::print_command_line_help(outputStream* out) {533out->print_cr("-Xlog Usage: -Xlog[:[selections][:[output][:[decorators][:output-options]]]]");534out->print_cr("\t where 'selections' are combinations of tags and levels of the form tag1[+tag2...][*][=level][,...]");535out->print_cr("\t NOTE: Unless wildcard (*) is specified, only log messages tagged with exactly the tags specified will be matched.");536out->cr();537538out->print_cr("Available log levels:");539for (size_t i = 0; i < LogLevel::Count; i++) {540out->print("%s %s", (i == 0 ? "" : ","), LogLevel::name(static_cast<LogLevelType>(i)));541}542out->cr();543out->cr();544545out->print_cr("Available log decorators: ");546for (size_t i = 0; i < LogDecorators::Count; i++) {547LogDecorators::Decorator d = static_cast<LogDecorators::Decorator>(i);548out->print("%s %s (%s)", (i == 0 ? "" : ","), LogDecorators::name(d), LogDecorators::abbreviation(d));549}550out->cr();551out->print_cr(" Decorators can also be specified as 'none' for no decoration.");552out->cr();553554out->print_cr("Available log tags:");555LogTag::list_tags(out);556out->print_cr(" Specifying 'all' instead of a tag combination matches all tag combinations.");557out->cr();558559LogTagSet::describe_tagsets(out);560561out->print_cr("\nAvailable log outputs:");562out->print_cr(" stdout/stderr");563out->print_cr(" file=<filename>");564out->print_cr(" If the filename contains %%p and/or %%t, they will expand to the JVM's PID and startup timestamp, respectively.");565out->print_cr(" Additional output-options for file outputs:");566out->print_cr(" filesize=.. - Target byte size for log rotation (supports K/M/G suffix)."567" If set to 0, log rotation will not trigger automatically,"568" but can be performed manually (see the VM.log DCMD).");569out->print_cr(" filecount=.. - Number of files to keep in rotation (not counting the active file)."570" If set to 0, log rotation is disabled."571" This will cause existing log files to be overwritten.");572out->cr();573out->print_cr("\nAsynchronous logging (off by default):");574out->print_cr(" -Xlog:async");575out->print_cr(" All log messages are written to an intermediate buffer first and will then be flushed"576" to the corresponding log outputs by a standalone thread. Write operations at logsites are"577" guaranteed non-blocking.");578out->cr();579580out->print_cr("Some examples:");581out->print_cr(" -Xlog");582out->print_cr("\t Log all messages up to 'info' level to stdout with 'uptime', 'levels' and 'tags' decorations.");583out->print_cr("\t (Equivalent to -Xlog:all=info:stdout:uptime,levels,tags).");584out->cr();585586out->print_cr(" -Xlog:gc");587out->print_cr("\t Log messages tagged with 'gc' tag up to 'info' level to stdout, with default decorations.");588out->cr();589590out->print_cr(" -Xlog:gc,safepoint");591out->print_cr("\t Log messages tagged either with 'gc' or 'safepoint' tags, both up to 'info' level, to stdout, with default decorations.");592out->print_cr("\t (Messages tagged with both 'gc' and 'safepoint' will not be logged.)");593out->cr();594595out->print_cr(" -Xlog:gc+ref=debug");596out->print_cr("\t Log messages tagged with both 'gc' and 'ref' tags, up to 'debug' level, to stdout, with default decorations.");597out->print_cr("\t (Messages tagged only with one of the two tags will not be logged.)");598out->cr();599600out->print_cr(" -Xlog:gc=debug:file=gc.txt:none");601out->print_cr("\t Log messages tagged with 'gc' tag up to 'debug' level to file 'gc.txt' with no decorations.");602out->cr();603604out->print_cr(" -Xlog:gc=trace:file=gctrace.txt:uptimemillis,pid:filecount=5,filesize=1m");605out->print_cr("\t Log messages tagged with 'gc' tag up to 'trace' level to a rotating fileset of 5 files of size 1MB,");606out->print_cr("\t using the base name 'gctrace.txt', with 'uptimemillis' and 'pid' decorations.");607out->cr();608609out->print_cr(" -Xlog:gc::uptime,tid");610out->print_cr("\t Log messages tagged with 'gc' tag up to 'info' level to output 'stdout', using 'uptime' and 'tid' decorations.");611out->cr();612613out->print_cr(" -Xlog:gc*=info,safepoint*=off");614out->print_cr("\t Log messages tagged with at least 'gc' up to 'info' level, but turn off logging of messages tagged with 'safepoint'.");615out->print_cr("\t (Messages tagged with both 'gc' and 'safepoint' will not be logged.)");616out->cr();617618out->print_cr(" -Xlog:disable -Xlog:safepoint=trace:safepointtrace.txt");619out->print_cr("\t Turn off all logging, including warnings and errors,");620out->print_cr("\t and then enable messages tagged with 'safepoint' up to 'trace' level to file 'safepointtrace.txt'.");621622out->print_cr(" -Xlog:async -Xlog:gc=debug:file=gc.log -Xlog:safepoint=trace");623out->print_cr("\t Write logs asynchronously. Enable messages tagged with 'safepoint' up to 'trace' level to stdout ");624out->print_cr("\t and messages tagged with 'gc' up to 'debug' level to file 'gc.log'.");625}626627void LogConfiguration::rotate_all_outputs() {628// Start from index 2 since neither stdout nor stderr can be rotated.629for (size_t idx = 2; idx < _n_outputs; idx++) {630_outputs[idx]->force_rotate();631}632}633634void LogConfiguration::register_update_listener(UpdateListenerFunction cb) {635assert(cb != NULL, "Should not register NULL as listener");636ConfigurationLock cl;637size_t idx = _n_listener_callbacks++;638_listener_callbacks = REALLOC_C_HEAP_ARRAY(UpdateListenerFunction,639_listener_callbacks,640_n_listener_callbacks,641mtLogging);642_listener_callbacks[idx] = cb;643}644645void LogConfiguration::notify_update_listeners() {646assert(ConfigurationLock::current_thread_has_lock(), "notify_update_listeners must be called in ConfigurationLock scope (lock held)");647for (size_t i = 0; i < _n_listener_callbacks; i++) {648_listener_callbacks[i]();649}650}651652bool LogConfiguration::_async_mode = false;653654655