Logging in ASTE

[davidscn]

The logging in ASTE may pose problems for massively parallel runs. In particular, the logging configuration is currently hard-coded in ASTE

aste/src/logger.cpp

Lines 30 to 75 in 81d8774

	void addLogSink(LogLevel ll, LogRankFilter lrf)
	{
	int loglevel = (ll == LogLevel::Verbose) ? logging::trivial::debug : logging::trivial::info;
	auto filter = [&]() -> logging::filter {
	if (lrf == LogRankFilter::OnlyPrimary) {
	return (logging::trivial::severity >= loglevel) & (expr::attr<int>("Rank").or_default(0) == 0);
	} else {
	return logging::trivial::severity >= loglevel;
	}
	}();
	// Either "ASTE" or "preCICE"
	auto origin = expr::if_(expr::has_attr<bool>("ASTE"))[expr::stream << "ASTE"].else_[expr::stream << "preCICE"];
	// For preCICE logs "(Module in Function)" if verbose
	auto location = expr::if_((ll == LogLevel::Verbose) && !expr::has_attr<bool>("ASTE"))
	[expr::stream << "(" << expr::attr<std::string>("Module") << " in " << expr::attr<std::string>("Function") << ") "];
	// Format the severity
	auto blankSeverity =
	expr::if_(logging::trivial::error == logging::trivial::severity)
	[expr::stream << "ERROR"]
	.else_[expr::stream << expr::if_(logging::trivial::warning == logging::trivial::severity)
	[expr::stream << "WARNING"]
	.else_[expr::stream << expr::if_(logging::trivial::info == logging::trivial::severity)
	[expr::stream << "INFO"]
	.else_[expr::stream << expr::if_(logging::trivial::debug == logging::trivial::severity)
	[expr::stream << "DEBUG"]
	.else_[expr::stream << logging::trivial::severity]]]];
	auto formatter = expr::stream
	<< "---["
	<< origin
	<< ':' << expr::attr<std::string>("Participant")
	<< ':' << expr::attr<int>("Rank")
	<< "] "
	<< location
	<< blankSeverity
	<< " : " << expr::smessage;
	logging::add_console_log(
	std::clog,
	keywords::format = formatter,
	keywords::filter = filter);
	}

Similar to preCICE, the implementation uses boost log. From the user perspective, this comes with the following issues:

• the ASTE logging cannot be switched off entirely. Although this may be performance-critical, depending on the filesystem
• in the experiments, the performance difference between runs with and without logging in ASTE were significant (for massively-large cases). It is an open question whether this is solely related to the filesystem, or if the ASTE logger clashes with the preCICE logger. It is worth mentioning that the boost logging seems to be unsuited for performance-critical logging.
• ASTE duplicates error messages from preCICE, only switching off the logging entirely in the preCICE XML prevents this duplication. This contradicts the user perspective of preCICE. The logging in ASTE should be independent of preCICE.
• we advertise the mapping tester and the generator scripts quite a bit. Therein, we enable verbose logging by default

aste/tools/mapping-tester/generate.py

Line 151 in 81d8774

acmd = f'env {time_command} -f %M -a -o memory-A.log precice-aste-run -v -a -p A --data "{case["function"]}" --mesh {ameshLocation} || kill 0 &'

We should be more conscious about the logging implementation, how we use it, and how we configure it. Maybe logging initial mesh loadings on the primary rank by default is more than enough (and it can still be switched off). Anything else should be really only for debug purposes. Another alternative would be to entirely remove boost log and come up with a simpler solution. A tiny logging with C++20 and formatlib could also be a very easy option here. I think most of the boost logging features such as advanced filtering for modules etc are not needed here in the first place.