6
（これはSLES11、Java 7、Tomcat 6、log4j-1.2.16にあります）結局、log4jはスレッドセーフではありませんか？
log4jを使用して、異なるログファイルに異なるものを書き出します。私はこのコードを継承しているので、一般的な構造は良いか悪いのために当分の間ここに滞在しています。
ロガーは、2つのログファイル、すなわちmain.logとstats.logを作成します。特定の統計メッセージは、別々の呼び出しを介して両方のロガーに記録されます（下に表示されます）、メインのログには他の多くのものが記録されます。
私たちのコードでは、すべてLog.logMain(someMessageToLog);のようなものが表示されます。 （複数のスレッドによって実行される）我々のコード内の1つの場所では、以下がある：
String statsMessage = createStatsMessage();
Log.logMain(statsMessage);
Log.logStats(statsMessage);
メインロガーの名前は統計ロガーの名前はstatsで、mainです。問題は、負荷がかかっているときに、という文字列を含むmain.logの行が表示されることがあることです。 main.logのすべてはそのファイルにログする唯一のロガーであり、一部の行では混合出力が表示されるため、main INFOしか含まれていません。これはスレッドセーフの問題のようですが、log4jドキュメントはlog4jがスレッドセーフであると言います。ここで私が何を意味するかの例です：
2012-03-21 16:01:34,7742012-03-21 16:01:34,774| | stats main INFO [INFO http-8080-18]: [message redacted].
2012-03-21 16:01:36,380| main 2012-03-21 16:01:36,380| INFO [stats INFO http-8080-15]: [message redacted].
2012-03-21 16:01:37,465| main INFO 2012-03-21 16:01:37,465 [| stats http-8080-1]: [message redacted].
ここでは（唯一の問題でロガーを表示するためにストリップダウン - 他のロガーの束はそれに実際に存在し、これらと同様に設定したすべての）Logクラスです：
import org.apache.log4j.*;
import java.io.IOException;
final public class Log
{
private static final String LOG_IDENTIFIER_MAINLOG = "main";
private static final String LOG_IDENTIFIER_STATSLOG = "stats";
private static final String MAIN_FILENAME = "/var/log/app_main.log";
private static final String STATS_FILENAME = "/var/log/app_stats.log";
private static final int BACKUP_INDEX = 40;
private static final String BACKUP_SIZE = "10MB";
private static final PatternLayout COMMON_LAYOUT =
new PatternLayout("%d| %c %-6p [%t]: %m.%n");
private static Logger mainLogger;
private static Logger statsLogger;
public static void init() {
init(MAIN_FILENAME, STATS_FILENAME);
}
public static void init(String mainLogFilename,
String statsLogFilename) {
mainLogger = initializeMainLogger(mainLogFilename);
statsLogger = initializeStatsLogger(statsLogFilename);
}
public static void logMain(String message) {
if (mainLogger != null) {
mainLogger.info(message);
}
}
public static void logStats(String message) {
if (statsLogger != null) {
statsLogger.info(message);
}
}
private static Logger getLogger(String loggerIdentifier) {
Logger logger = Logger.getLogger(loggerIdentifier);
logger.setAdditivity(false);
return logger;
}
private static boolean addFileAppender(Logger logger,
String logFilename,
int maxBackupIndex,
String maxSize) {
try {
RollingFileAppender appender =
new RollingFileAppender(COMMON_LAYOUT, logFilename);
appender.setMaxBackupIndex(maxBackupIndex);
appender.setMaxFileSize(maxSize);
logger.addAppender(appender);
}
catch (IOException ex) {
ex.printStackTrace();
return false;
}
return true;
}
private static Logger initializeMainLogger(String filename) {
Logger logger = getLogger(LOG_IDENTIFIER_MAINLOG);
addFileAppender(logger, filename, BACKUP_INDEX, BACKUP_SIZE);
logger.setLevel(Level.INFO);
return logger;
}
private static Logger initializeStatsLogger(String filename) {
Logger logger = getLogger(LOG_IDENTIFIER_STATSLOG);
addFileAppender(logger, filename, BACKUP_INDEX, BACKUP_SIZE);
logger.setLevel(Level.INFO);
return logger;
}
}
更新：
ここアルです（少なくとも私にとっては）上記Logクラスで問題を再現しますittleプログラム：
final public class Stress
{
public static void main(String[] args) throws Exception {
if (args.length != 2) {
Log.init();
}
else {
Log.init(args[0], args[1]);
}
for (;;) {
// I know Executors are preferred, but this
// is a quick & dirty test program
Thread t = new Thread(new TestLogging());
t.start();
}
}
private static final class TestLogging implements Runnable
{
private static int counter = 0;
@Override
public void run() {
String msg = new StringBuilder("Count is: ")
.append(counter++).toString();
Log.logMain(msg);
Log.logStats(msg);
try {
Thread.sleep(1);
}
catch (InterruptedException e) {
Log.logMain(e.getMessage());
}
}
}
}
とログでいくつかのサンプル出力：については
$ grep stats main.log
2012-03-23 15:30:35,919| stats 2012-03-23 15:30:35,919| main INFO INFO [ [Thread-313037]: Thread-313036]: Count is: 312987.
2012-03-23 15:30:35,929| stats INFO [Thread-313100]: Count is: 313050.
2012-03-23 15:30:35,937| stats INFO [Thread-313168]: Count is: 313112.
2012-03-23 15:30:35,945| stats INFO [Thread-313240]: Count is: 313190.
2012-03-23 15:30:35,946| stats INFO [Thread-313251]: Count is: 313201.
2012-03-23 15:30:35,949| stats INFO [2012-03-23 15:30:35,949| main INFO Thread-313281]: Count is: 313231.
2012-03-23 15:30:35,954| stats INFO [Thread-313331]: Count is: 313281.
2012-03-23 15:30:35,956| 2012-03-23 15:30:35,956stats | main INFOINFO [ [Thread-313356]: Count is: 313306.
2012-03-23 15:30:35,9562012-03-23 15:30:35,956| main | INFO stats [INFOThread-313359]: Count is: 313309.
2012-03-23 15:30:35,962| stats INFO 2012-03-23 15:30:35,962| main INFO [Thread-313388]: [Count is: 313338.
と
$ grep main stats.log
2012-03-23 15:30:35,913| 2012-03-23 15:30:35,913| main INFO [Thread-312998]: Count is: 312948.
2012-03-23 15:30:35,915| main INFO [Thread-313014]: Count is: 312964.
2012-03-23 15:30:35,919| stats 2012-03-23 15:30:35,919| main INFO INFO [ [Thread-313037]: Thread-313036]: Count is: 312987.
2012-03-23 15:30:35,931| main INFO [Thread-313116]: Count is: 313066.
2012-03-23 15:30:35,947| main INFO [2012-03-23 15:30:35,947Thread-313264]: | Count is: 313214.
2012-03-23 15:30:35,949| stats INFO [2012-03-23 15:30:35,949| main INFO Thread-313281]: Count is: 313231.
2012-03-23 15:30:35,956| 2012-03-23 15:30:35,956stats | main INFOINFO [ [Thread-313356]: Count is: 313306.
2012-03-23 15:30:35,9562012-03-23 15:30:35,956| main | INFO stats [INFOThread-313359]: Count is: 313309.
2012-03-23 15:30:35,962| stats INFO 2012-03-23 15:30:35,962| main INFO [Thread-313388]: [Count is: 313338.
145516行のmain.logファイルのうち、 "stats"が2452回現れました。それは珍しいことではありませんが、それはいつも起こっているようなものではありません（もちろん、このテストはかなり極端です）。
のための新しいPatternLayoutはを作成します。 logMain/logStatsに 'synchronized'を追加してスレッドの戦いを排除しようとすることもできますが、負荷が重いと実行するとパフォーマンスが低下して生産に適さなくなる可能性があります。 – Thomas