From 7bebe507cfaaf86bb9bf27ba4bb0f387e7ff87d2 Mon Sep 17 00:00:00 2001 From: Clebert Suconic Date: Thu, 28 Apr 2016 14:26:51 -0400 Subject: [PATCH] Individualizing loggers on journal --- .../core/io/aio/AIOSequentialFileFactory.java | 14 +--- .../artemis/core/io/util/FileIOUtil.java | 5 +- .../journal/impl/JournalFilesRepository.java | 51 +++++------- .../core/journal/impl/JournalImpl.java | 82 ++++++++----------- .../artemis/core/journal/impl/Reclaimer.java | 18 ++-- 5 files changed, 73 insertions(+), 97 deletions(-) diff --git a/artemis-journal/src/main/java/org/apache/activemq/artemis/core/io/aio/AIOSequentialFileFactory.java b/artemis-journal/src/main/java/org/apache/activemq/artemis/core/io/aio/AIOSequentialFileFactory.java index 93c09ee182..2a79e6e3da 100644 --- a/artemis-journal/src/main/java/org/apache/activemq/artemis/core/io/aio/AIOSequentialFileFactory.java +++ b/artemis-journal/src/main/java/org/apache/activemq/artemis/core/io/aio/AIOSequentialFileFactory.java @@ -33,10 +33,11 @@ import org.apache.activemq.artemis.jlibaio.LibaioFile; import org.apache.activemq.artemis.jlibaio.SubmitInfo; import org.apache.activemq.artemis.jlibaio.util.CallbackCache; import org.apache.activemq.artemis.journal.ActiveMQJournalLogger; +import org.jboss.logging.Logger; public final class AIOSequentialFileFactory extends AbstractSequentialFileFactory { - private static final boolean trace = ActiveMQJournalLogger.LOGGER.isTraceEnabled(); + private static final Logger logger = Logger.getLogger(AIOSequentialFileFactory.class); private final ReuseBuffersController buffersControl = new ReuseBuffersController(); @@ -52,13 +53,6 @@ public final class AIOSequentialFileFactory extends AbstractSequentialFileFactor private static final String AIO_TEST_FILE = ".aio-test"; - // This method exists just to make debug easier. - // I could replace log.trace by log.info temporarily while I was debugging - // Journal - private static void trace(final String message) { - ActiveMQJournalLogger.LOGGER.trace(message); - } - public AIOSequentialFileFactory(final File journalDir, int maxIO) { this(journalDir, ArtemisConstants.DEFAULT_JOURNAL_BUFFER_SIZE_AIO, ArtemisConstants.DEFAULT_JOURNAL_BUFFER_TIMEOUT_AIO, maxIO, false, null); } @@ -398,8 +392,8 @@ public final class AIOSequentialFileFactory extends AbstractSequentialFileFactor // This is being done this way as we don't need another Timeout Thread // just to cleanup this if (bufferSize > 0 && System.currentTimeMillis() - bufferReuseLastTime > 10000) { - if (AIOSequentialFileFactory.trace) { - AIOSequentialFileFactory.trace("Clearing reuse buffers queue with " + reuseBuffersQueue.size() + + if (logger.isTraceEnabled()) { + logger.trace("Clearing reuse buffers queue with " + reuseBuffersQueue.size() + " elements"); } diff --git a/artemis-journal/src/main/java/org/apache/activemq/artemis/core/io/util/FileIOUtil.java b/artemis-journal/src/main/java/org/apache/activemq/artemis/core/io/util/FileIOUtil.java index f9d3ab7b6d..70ddb243ac 100644 --- a/artemis-journal/src/main/java/org/apache/activemq/artemis/core/io/util/FileIOUtil.java +++ b/artemis-journal/src/main/java/org/apache/activemq/artemis/core/io/util/FileIOUtil.java @@ -24,8 +24,7 @@ import org.jboss.logging.Logger; public class FileIOUtil { - private static final Logger logger = Logger.getLogger(Logger.class); - private static final boolean isTrace = logger.isTraceEnabled(); + private static final Logger logger = Logger.getLogger(FileIOUtil.class); public static void copyData(SequentialFile from, SequentialFile to, ByteBuffer buffer) throws Exception { @@ -50,7 +49,7 @@ public class FileIOUtil { buffer.clear(); int bytesRead = from.read(buffer); - if (isTrace) { + if (logger.isTraceEnabled()) { logger.trace("appending " + bytesRead + " bytes on " + to.getFileName()); } diff --git a/artemis-journal/src/main/java/org/apache/activemq/artemis/core/journal/impl/JournalFilesRepository.java b/artemis-journal/src/main/java/org/apache/activemq/artemis/core/journal/impl/JournalFilesRepository.java index 5eb269247d..af01b860d4 100644 --- a/artemis-journal/src/main/java/org/apache/activemq/artemis/core/journal/impl/JournalFilesRepository.java +++ b/artemis-journal/src/main/java/org/apache/activemq/artemis/core/journal/impl/JournalFilesRepository.java @@ -36,6 +36,7 @@ import org.apache.activemq.artemis.core.io.SequentialFile; import org.apache.activemq.artemis.core.io.SequentialFileFactory; import org.apache.activemq.artemis.journal.ActiveMQJournalBundle; import org.apache.activemq.artemis.journal.ActiveMQJournalLogger; +import org.jboss.logging.Logger; /** * This is a helper class for the Journal, which will control access to dataFiles, openedFiles and freeFiles @@ -43,7 +44,7 @@ import org.apache.activemq.artemis.journal.ActiveMQJournalLogger; */ public class JournalFilesRepository { - private static final boolean trace = ActiveMQJournalLogger.LOGGER.isTraceEnabled(); + private static final Logger logger = Logger.getLogger(JournalFilesRepository.class); /** * Used to debug the consistency of the journal ordering. @@ -52,13 +53,6 @@ public class JournalFilesRepository { */ private static final boolean CHECK_CONSISTENCE = false; - // This method exists just to make debug easier. - // I could replace log.trace by log.info temporarily while I was debugging - // Journal - private static void trace(final String message) { - ActiveMQJournalLogger.LOGGER.trace(message); - } - private final SequentialFileFactory fileFactory; private final JournalImpl journal; @@ -365,8 +359,8 @@ public class JournalFilesRepository { else if (!checkDelete || (freeFilesCount.get() + dataFiles.size() + 1 + openedFiles.size() < poolSize) || (poolSize < 0)) { // Re-initialise it - if (JournalFilesRepository.trace) { - JournalFilesRepository.trace("Adding free file " + file); + if (logger.isTraceEnabled()) { + logger.trace("Adding free file " + file); } JournalFile jf = reinitializeFile(file); @@ -379,15 +373,14 @@ public class JournalFilesRepository { freeFilesCount.getAndIncrement(); } else { - if (trace) { - ActiveMQJournalLogger.LOGGER.trace("DataFiles.size() = " + dataFiles.size()); - ActiveMQJournalLogger.LOGGER.trace("openedFiles.size() = " + openedFiles.size()); - ActiveMQJournalLogger.LOGGER.trace("minfiles = " + minFiles + ", poolSize = " + poolSize); - ActiveMQJournalLogger.LOGGER.trace("Free Files = " + freeFilesCount.get()); - ActiveMQJournalLogger.LOGGER.trace("File " + file + - " being deleted as freeFiles.size() + dataFiles.size() + 1 + openedFiles.size() (" + - (freeFilesCount.get() + dataFiles.size() + 1 + openedFiles.size()) + - ") < minFiles (" + minFiles + ")"); + if (logger.isTraceEnabled()) { + logger.trace("DataFiles.size() = " + dataFiles.size()); + logger.trace("openedFiles.size() = " + openedFiles.size()); + logger.trace("minfiles = " + minFiles + ", poolSize = " + poolSize); + logger.trace("Free Files = " + freeFilesCount.get()); + logger.trace("File " + file + " being deleted as freeFiles.size() + dataFiles.size() + 1 + openedFiles.size() (" + + (freeFilesCount.get() + dataFiles.size() + 1 + openedFiles.size()) + + ") < minFiles (" + minFiles + ")"); } file.getFile().delete(); } @@ -421,8 +414,8 @@ public class JournalFilesRepository { * @throws ActiveMQIOErrorException In case the file could not be opened */ public JournalFile openFile() throws InterruptedException, ActiveMQIOErrorException { - if (JournalFilesRepository.trace) { - JournalFilesRepository.trace("enqueueOpenFile with openedFiles.size=" + openedFiles.size()); + if (logger.isTraceEnabled()) { + logger.trace("enqueueOpenFile with openedFiles.size=" + openedFiles.size()); } if (openFilesExecutor == null) { @@ -441,8 +434,8 @@ public class JournalFilesRepository { throw ActiveMQJournalBundle.BUNDLE.fileNotOpened(); } - if (JournalFilesRepository.trace) { - JournalFilesRepository.trace("Returning file " + nextFile); + if (logger.isTraceEnabled()) { + logger.trace("Returning file " + nextFile); } return nextFile; @@ -454,8 +447,8 @@ public class JournalFilesRepository { public void pushOpenedFile() throws Exception { JournalFile nextOpenedFile = takeFile(true, true, true, false); - if (JournalFilesRepository.trace) { - JournalFilesRepository.trace("pushing openFile " + nextOpenedFile); + if (logger.isTraceEnabled()) { + logger.trace("pushing openFile " + nextOpenedFile); } if (!openedFiles.offer(nextOpenedFile)) { @@ -580,8 +573,8 @@ public class JournalFilesRepository { final String fileName = createFileName(tmpCompact, fileID); - if (JournalFilesRepository.trace) { - JournalFilesRepository.trace("Creating file " + fileName); + if (logger.isTraceEnabled()) { + logger.trace("Creating file " + fileName); } String tmpFileName = fileName + ".tmp"; @@ -600,8 +593,8 @@ public class JournalFilesRepository { sequentialFile.close(); - if (JournalFilesRepository.trace) { - JournalFilesRepository.trace("Renaming file " + tmpFileName + " as " + fileName); + if (logger.isTraceEnabled()) { + logger.trace("Renaming file " + tmpFileName + " as " + fileName); } sequentialFile.renameTo(fileName); diff --git a/artemis-journal/src/main/java/org/apache/activemq/artemis/core/journal/impl/JournalImpl.java b/artemis-journal/src/main/java/org/apache/activemq/artemis/core/journal/impl/JournalImpl.java index ef6de60312..e19e72889e 100644 --- a/artemis-journal/src/main/java/org/apache/activemq/artemis/core/journal/impl/JournalImpl.java +++ b/artemis-journal/src/main/java/org/apache/activemq/artemis/core/journal/impl/JournalImpl.java @@ -69,6 +69,7 @@ import org.apache.activemq.artemis.journal.ActiveMQJournalBundle; import org.apache.activemq.artemis.journal.ActiveMQJournalLogger; import org.apache.activemq.artemis.utils.ConcurrentHashSet; import org.apache.activemq.artemis.utils.DataConstants; +import org.jboss.logging.Logger; /** *

A circular log implementation.

@@ -84,22 +85,7 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal private static final int[] COMPATIBLE_VERSIONS = new int[]{1}; // Static -------------------------------------------------------- - private static final boolean trace = ActiveMQJournalLogger.LOGGER.isTraceEnabled(); - - // This is useful at debug time... - // if you set it to true, all the appends, deletes, rollbacks, commits, etc.. are sent to System.out - private static final boolean TRACE_RECORDS = trace; - - // This method exists just to make debug easier. - // I could replace log.trace by log.info temporarily while I was debugging - // Journal - private static void trace(final String message) { - ActiveMQJournalLogger.LOGGER.trace(message); - } - - private static void traceRecord(final String message) { - ActiveMQJournalLogger.LOGGER.trace(message); - } + private static final Logger logger = Logger.getLogger(JournalImpl.class); // The sizes of primitive types @@ -550,7 +536,7 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal preparedTransactionExtraDataSize)) { // Avoid a buffer overflow caused by damaged data... continue // scanning for more pendingTransactions... - JournalImpl.trace("Record at position " + pos + + logger.trace("Record at position " + pos + " recordType = " + recordType + " file:" + @@ -583,7 +569,7 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal // This is like testing a hash for the record. (We could replace the // checkSize by some sort of calculated hash) if (checkSize != variableSize + recordSize + preparedTransactionExtraDataSize) { - JournalImpl.trace("Record at position " + pos + + logger.trace("Record at position " + pos + " recordType = " + recordType + " possible transactionID = " + @@ -722,10 +708,11 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal synchronized (lockAppend) { JournalFile usedFile = appendRecord(addRecord, false, sync, null, callback); - if (JournalImpl.TRACE_RECORDS) { - JournalImpl.traceRecord("appendAddRecord::id=" + id + + if (logger.isTraceEnabled()) { + logger.trace("appendAddRecord::id=" + id + ", userRecordType=" + recordType + + ", record = " + record + ", usedFile = " + usedFile); } @@ -766,10 +753,11 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal synchronized (lockAppend) { JournalFile usedFile = appendRecord(updateRecord, false, sync, null, callback); - if (JournalImpl.TRACE_RECORDS) { - JournalImpl.traceRecord("appendUpdateRecord::id=" + id + + if (logger.isTraceEnabled()) { + logger.trace("appendUpdateRecord::id=" + id + ", userRecordType=" + recordType + + ", record = " + record + ", usedFile = " + usedFile); } @@ -820,8 +808,8 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal synchronized (lockAppend) { JournalFile usedFile = appendRecord(deleteRecord, false, sync, null, callback); - if (JournalImpl.TRACE_RECORDS) { - JournalImpl.traceRecord("appendDeleteRecord::id=" + id + ", usedFile = " + usedFile); + if (logger.isTraceEnabled()) { + logger.trace("appendDeleteRecord::id=" + id + ", usedFile = " + usedFile); } // record== null here could only mean there is a compactor, and computing the delete should be done after @@ -857,12 +845,13 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal synchronized (lockAppend) { JournalFile usedFile = appendRecord(addRecord, false, false, tx, null); - if (JournalImpl.TRACE_RECORDS) { - JournalImpl.traceRecord("appendAddRecordTransactional:txID=" + txID + + if (logger.isTraceEnabled()) { + logger.trace("appendAddRecordTransactional:txID=" + txID + ",id=" + id + ", userRecordType=" + recordType + + ", record = " + record + ", usedFile = " + usedFile); } @@ -902,12 +891,13 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal synchronized (lockAppend) { JournalFile usedFile = appendRecord(updateRecordTX, false, false, tx, null); - if (JournalImpl.TRACE_RECORDS) { - JournalImpl.traceRecord("appendUpdateRecordTransactional::txID=" + txID + + if (logger.isTraceEnabled()) { + logger.trace("appendUpdateRecordTransactional::txID=" + txID + ",id=" + id + ", userRecordType=" + recordType + + ", record = " + record + ", usedFile = " + usedFile); } @@ -936,8 +926,8 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal synchronized (lockAppend) { JournalFile usedFile = appendRecord(deleteRecordTX, false, false, tx, null); - if (JournalImpl.TRACE_RECORDS) { - JournalImpl.traceRecord("appendDeleteRecordTransactional::txID=" + txID + + if (logger.isTraceEnabled()) { + logger.trace("appendDeleteRecordTransactional::txID=" + txID + ", id=" + id + ", usedFile = " + @@ -986,8 +976,8 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal synchronized (lockAppend) { JournalFile usedFile = appendRecord(prepareRecord, true, sync, tx, callback); - if (JournalImpl.TRACE_RECORDS) { - JournalImpl.traceRecord("appendPrepareRecord::txID=" + txID + ", usedFile = " + usedFile); + if (logger.isTraceEnabled()) { + logger.trace("appendPrepareRecord::txID=" + txID + ", usedFile = " + usedFile); } tx.prepare(usedFile); @@ -1032,8 +1022,8 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal synchronized (lockAppend) { JournalFile usedFile = appendRecord(commitRecord, true, sync, tx, callback); - if (JournalImpl.TRACE_RECORDS) { - JournalImpl.traceRecord("appendCommitRecord::txID=" + txID + ", usedFile = " + usedFile); + if (logger.isTraceEnabled()) { + logger.trace("appendCommitRecord::txID=" + txID + ", usedFile = " + usedFile); } tx.commit(usedFile); @@ -1301,7 +1291,7 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal filesRepository.clearDataFiles(); if (dataFilesToProcess.size() == 0) { - trace("Finishing compacting, nothing to process"); + logger.trace("Finishing compacting, nothing to process"); return; } @@ -1367,14 +1357,14 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal // Restore compacted dataFiles for (int i = newDatafiles.size() - 1; i >= 0; i--) { JournalFile fileToAdd = newDatafiles.get(i); - if (JournalImpl.trace) { - JournalImpl.trace("Adding file " + fileToAdd + " back as datafile"); + if (logger.isTraceEnabled()) { + logger.trace("Adding file " + fileToAdd + " back as datafile"); } filesRepository.addDataFileOnTop(fileToAdd); } - if (JournalImpl.trace) { - JournalImpl.trace("There are " + filesRepository.getDataFilesCount() + " datafiles Now"); + if (logger.isTraceEnabled()) { + logger.trace("There are " + filesRepository.getDataFilesCount() + " datafiles Now"); } // Replay pending commands (including updates, deletes and commits) @@ -1390,8 +1380,8 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal // that happened during the compacting for (JournalTransaction newTransaction : localCompactor.getNewTransactions().values()) { - if (JournalImpl.trace) { - JournalImpl.trace("Merging pending transaction " + newTransaction + " after compacting the journal"); + if (logger.isTraceEnabled()) { + logger.trace("Merging pending transaction " + newTransaction + " after compacting the journal"); } JournalTransaction liveTransaction = transactions.get(newTransaction.getId()); if (liveTransaction != null) { @@ -1513,7 +1503,7 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal final AtomicLong maxID = new AtomicLong(-1); for (final JournalFile file : orderedFiles) { - JournalImpl.trace("Loading file " + file.getFile().getFileName()); + logger.trace("Loading file " + file.getFile().getFileName()); final AtomicBoolean hasData = new AtomicBoolean(false); @@ -1824,8 +1814,8 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal for (JournalFile file : filesRepository.getDataFiles()) { if (file.isCanReclaim()) { // File can be reclaimed or deleted - if (JournalImpl.trace) { - JournalImpl.trace("Reclaiming file " + file); + if (logger.isTraceEnabled()) { + logger.trace("Reclaiming file " + file); } filesRepository.removeDataFile(file); @@ -2800,8 +2790,8 @@ public class JournalImpl extends JournalBase implements TestableJournal, Journal scheduleReclaim(); } - if (trace) { - ActiveMQJournalLogger.LOGGER.trace("Moving next file " + currentFile); + if (logger.isTraceEnabled()) { + logger.trace("Moving next file " + currentFile); } fileFactory.activateBuffer(currentFile.getFile()); diff --git a/artemis-journal/src/main/java/org/apache/activemq/artemis/core/journal/impl/Reclaimer.java b/artemis-journal/src/main/java/org/apache/activemq/artemis/core/journal/impl/Reclaimer.java index 0f559627a2..2b028ab964 100644 --- a/artemis-journal/src/main/java/org/apache/activemq/artemis/core/journal/impl/Reclaimer.java +++ b/artemis-journal/src/main/java/org/apache/activemq/artemis/core/journal/impl/Reclaimer.java @@ -16,7 +16,7 @@ */ package org.apache.activemq.artemis.core.journal.impl; -import org.apache.activemq.artemis.journal.ActiveMQJournalLogger; +import org.jboss.logging.Logger; /** *

The journal consists of an ordered list of journal files Fn where {@code 0 <= n <= N}

@@ -34,10 +34,10 @@ import org.apache.activemq.artemis.journal.ActiveMQJournalLogger; */ public class Reclaimer { - private static boolean trace = ActiveMQJournalLogger.LOGGER.isTraceEnabled(); + private static final Logger logger = Logger.getLogger(Reclaimer.class); private static void trace(final String message) { - ActiveMQJournalLogger.LOGGER.trace(message); + logger.trace(message); } public void scan(final JournalFile[] files) { @@ -50,14 +50,14 @@ public class Reclaimer { int totNeg = 0; - if (Reclaimer.trace) { - Reclaimer.trace("posCount on " + currentFile + " = " + posCount); + if (logger.isTraceEnabled()) { + logger.trace("posCount on " + currentFile + " = " + posCount); } for (int j = i; j < files.length; j++) { - if (Reclaimer.trace) { + if (logger.isTraceEnabled()) { if (files[j].getNegCount(currentFile) != 0) { - Reclaimer.trace("Negative from " + files[j] + + logger.trace("Negative from " + files[j] + " into " + currentFile + " = " + @@ -83,8 +83,8 @@ public class Reclaimer { // Ok } else { - if (Reclaimer.trace) { - Reclaimer.trace(currentFile + " Can't be reclaimed because " + file + " has negative values"); + if (logger.isTraceEnabled()) { + logger.trace(currentFile + " Can't be reclaimed because " + file + " has negative values"); } currentFile.setCanReclaim(false);