From c4e3276c6abf42a0a098679c426dca0b9b9b0be7 Mon Sep 17 00:00:00 2001 From: Michael Axiak Date: Fri, 8 Mar 2024 17:15:53 -0500 Subject: [PATCH] Don't call file.length() for every append if we can avoid it This change introduces a way for the ResiliantFileOutputStream to track its own position in the file. This means that instead of calling File.length() (which ends up being a syscall) for each event, we only call it when we're recovering a stream. --- .../ch/qos/logback/core/FileAppender.java | 15 ++++++ .../core/recovery/CountingOutputStream.java | 48 +++++++++++++++++++ .../recovery/ResilientFileOutputStream.java | 23 ++++++++- ...imeBasedFileNamingAndTriggeringPolicy.java | 4 ++ .../core/rolling/RollingFileAppender.java | 2 +- .../core/rolling/SizeAndTimeBasedFNATP.java | 20 ++++---- .../rolling/SizeBasedTriggeringPolicy.java | 9 +++- ...asedFileNamingAndTriggeringPolicyBase.java | 1 + .../core/rolling/TimeBasedRollingPolicy.java | 39 ++++++++++----- .../core/rolling/TriggeringPolicy.java | 2 + .../recovery/ResilientOutputStreamTest.java | 14 ++++++ 11 files changed, 151 insertions(+), 26 deletions(-) create mode 100644 logback-core/src/main/java/ch/qos/logback/core/recovery/CountingOutputStream.java diff --git a/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java b/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java index 2c92a3538b..8a078da8fd 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java +++ b/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java @@ -18,6 +18,7 @@ import java.io.File; import java.io.IOException; +import java.io.OutputStream; import java.nio.channels.FileChannel; import java.nio.channels.FileLock; import java.util.Map; @@ -293,6 +294,20 @@ private void safeWriteBytes(byte[] byteArray) { } } + /* + * Returns the current position in the current file, as counted by + * {@link CountingOutputStream}, or zero if no file has been opened. + */ + protected long getCurrentFilePosition() { + OutputStream outputStream = getOutputStream(); + if (outputStream == null) { + return 0; + } else { + // we already cast to a ResiliantFileOutputStream in #safeWrite() + return ((ResilientFileOutputStream) outputStream).getCount(); + } + } + private void releaseFileLock(FileLock fileLock) { if (fileLock != null && fileLock.isValid()) { try { diff --git a/logback-core/src/main/java/ch/qos/logback/core/recovery/CountingOutputStream.java b/logback-core/src/main/java/ch/qos/logback/core/recovery/CountingOutputStream.java new file mode 100644 index 0000000000..eef889c04f --- /dev/null +++ b/logback-core/src/main/java/ch/qos/logback/core/recovery/CountingOutputStream.java @@ -0,0 +1,48 @@ +package ch.qos.logback.core.recovery; + +import java.io.IOException; +import java.io.OutputStream; + +class CountingOutputStream extends OutputStream { + + private final OutputStream delegate; + + private long count; + + CountingOutputStream(OutputStream delegate) { + this.delegate = delegate; + } + + public long getCount() { + return count; + } + + @Override + public void write(int b) throws IOException { + delegate.write(b); + count++; + } + + @Override + public void write(byte[] b) throws IOException { + delegate.write(b); + count += b.length; + } + + @Override + public void write(byte[] b, int off, int len) throws IOException { + delegate.write(b, off, len); + count += len; + } + + @Override + public void flush() throws IOException { + delegate.flush(); + } + + @Override + public void close() throws IOException { + delegate.close(); + } + +} diff --git a/logback-core/src/main/java/ch/qos/logback/core/recovery/ResilientFileOutputStream.java b/logback-core/src/main/java/ch/qos/logback/core/recovery/ResilientFileOutputStream.java index 199f125fd0..de161281ab 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/recovery/ResilientFileOutputStream.java +++ b/logback-core/src/main/java/ch/qos/logback/core/recovery/ResilientFileOutputStream.java @@ -20,11 +20,16 @@ public class ResilientFileOutputStream extends ResilientOutputStreamBase { private File file; private FileOutputStream fos; + private CountingOutputStream countingOutputStream; + private long originalFileLength; + public ResilientFileOutputStream(File file, boolean append, long bufferSize) throws FileNotFoundException { this.file = file; + this.originalFileLength = append ? getFileLength(file) : 0; fos = new FileOutputStream(file, append); - this.os = new BufferedOutputStream(fos, (int) bufferSize); + countingOutputStream = new CountingOutputStream(new BufferedOutputStream(fos, (int) bufferSize)); + this.os = countingOutputStream; this.presumedClean = true; } @@ -39,6 +44,10 @@ public File getFile() { return file; } + public long getCount() { + return originalFileLength + (countingOutputStream == null ? 0 : countingOutputStream.getCount()); + } + @Override String getDescription() { return "file [" + file + "]"; @@ -46,9 +55,11 @@ String getDescription() { @Override OutputStream openNewOutputStream() throws IOException { + originalFileLength = getFileLength(file); // see LOGBACK-765 fos = new FileOutputStream(file, true); - return new BufferedOutputStream(fos); + countingOutputStream = new CountingOutputStream(new BufferedOutputStream(fos)); + return countingOutputStream; } @Override @@ -56,4 +67,12 @@ public String toString() { return "c.q.l.c.recovery.ResilientFileOutputStream@" + System.identityHashCode(this); } + private static long getFileLength(File file) { + try { + return file.length(); + } catch (Exception ignored) { + // file doesn't exist or we don't have permissions + return 0L; + } + } } diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/DefaultTimeBasedFileNamingAndTriggeringPolicy.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/DefaultTimeBasedFileNamingAndTriggeringPolicy.java index 9e5289bc40..d67be1c324 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/DefaultTimeBasedFileNamingAndTriggeringPolicy.java +++ b/logback-core/src/main/java/ch/qos/logback/core/rolling/DefaultTimeBasedFileNamingAndTriggeringPolicy.java @@ -43,6 +43,10 @@ public void start() { started = true; } + public boolean isTriggeringEvent(final File activeFile, final E event, long currentFilePosition) { + return isTriggeringEvent(activeFile, event); + } + public boolean isTriggeringEvent(File activeFile, final E event) { long currentTime = getCurrentTime(); long localNextCheck = atomicNextCheck.get(); diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java index e041a5f3f0..fd07b68f45 100755 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java +++ b/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java @@ -242,7 +242,7 @@ protected void subAppend(E event) { triggeringPolicyLock.lock(); try { - if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event)) { + if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event, getCurrentFilePosition())) { rollover(); } } finally { diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeAndTimeBasedFNATP.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeAndTimeBasedFNATP.java index 68694f5f6d..40b0b4c3f7 100755 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeAndTimeBasedFNATP.java +++ b/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeAndTimeBasedFNATP.java @@ -15,7 +15,6 @@ import java.io.File; import java.time.Instant; -import java.util.Date; import ch.qos.logback.core.CoreConstants; import ch.qos.logback.core.joran.spi.NoAutoStart; @@ -25,7 +24,6 @@ import ch.qos.logback.core.rolling.helper.SizeAndTimeBasedArchiveRemover; import ch.qos.logback.core.util.Duration; import ch.qos.logback.core.util.FileSize; -import ch.qos.logback.core.util.DefaultInvocationGate; import ch.qos.logback.core.util.InvocationGate; import ch.qos.logback.core.util.SimpleInvocationGate; @@ -141,6 +139,11 @@ void computeCurrentPeriodsHighestCounterValue(final String stemRegex) { @Override public boolean isTriggeringEvent(File activeFile, final E event) { + return isTriggeringEvent(activeFile, event, UNKNOWN_FILE_POSITION); + } + + @Override + public boolean isTriggeringEvent(File activeFile, final E event, long currentFilePosition) { long currentTime = getCurrentTime(); long localNextCheck = atomicNextCheck.get(); @@ -151,17 +154,17 @@ public boolean isTriggeringEvent(File activeFile, final E event) { atomicNextCheck.set(nextCheckCandidate); Instant instantInElapsedPeriod = dateInCurrentPeriod; elapsedPeriodsFileName = tbrp.fileNamePatternWithoutCompSuffix.convertMultipleArguments( - instantInElapsedPeriod, currentPeriodsCounter); + instantInElapsedPeriod, currentPeriodsCounter); currentPeriodsCounter = 0; setDateInCurrentPeriod(currentTime); return true; } - return checkSizeBasedTrigger(activeFile, currentTime); + return checkSizeBasedTrigger(activeFile, currentTime, currentFilePosition); } - private boolean checkSizeBasedTrigger(File activeFile, long currentTime) { + private boolean checkSizeBasedTrigger(File activeFile, long currentTime, long currentFilePosition) { // next check for roll-over based on size if (invocationGate.isTooSoon(currentTime)) { return false; @@ -175,10 +178,11 @@ private boolean checkSizeBasedTrigger(File activeFile, long currentTime) { addWarn("maxFileSize = null"); return false; } - if (activeFile.length() >= maxFileSize.getSize()) { + long activeFileLength = currentFilePosition == UNKNOWN_FILE_POSITION ? activeFile.length() : currentFilePosition; + if (activeFileLength >= maxFileSize.getSize()) { elapsedPeriodsFileName = tbrp.fileNamePatternWithoutCompSuffix.convertMultipleArguments(dateInCurrentPeriod, - currentPeriodsCounter); + currentPeriodsCounter); currentPeriodsCounter++; return true; } @@ -197,7 +201,7 @@ public void setCheckIncrement(Duration checkIncrement) { @Override public String getCurrentPeriodsFileNameWithoutCompressionSuffix() { return tbrp.fileNamePatternWithoutCompSuffix.convertMultipleArguments(dateInCurrentPeriod, - currentPeriodsCounter); + currentPeriodsCounter); } public void setMaxFileSize(FileSize aMaxFileSize) { diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeBasedTriggeringPolicy.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeBasedTriggeringPolicy.java index 6ef9bbcf7b..4d0937814c 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeBasedTriggeringPolicy.java +++ b/logback-core/src/main/java/ch/qos/logback/core/rolling/SizeBasedTriggeringPolicy.java @@ -54,12 +54,17 @@ public void start() { } - public boolean isTriggeringEvent(final File activeFile, final E event) { + @Override + public boolean isTriggeringEvent(File activeFile, E event, long currentFilePosition) { long now = System.currentTimeMillis(); if (invocationGate.isTooSoon(now)) return false; + long activeFileLength = currentFilePosition >= 0 ? currentFilePosition : activeFile.length(); + return (activeFileLength >= maxFileSize.getSize()); + } - return (activeFile.length() >= maxFileSize.getSize()); + public boolean isTriggeringEvent(final File activeFile, final E event) { + return isTriggeringEvent(activeFile, event, -1); } public FileSize getMaxFileSize() { diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedFileNamingAndTriggeringPolicyBase.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedFileNamingAndTriggeringPolicyBase.java index 6a33e7aab5..9e053dcdf3 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedFileNamingAndTriggeringPolicyBase.java +++ b/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedFileNamingAndTriggeringPolicyBase.java @@ -32,6 +32,7 @@ abstract public class TimeBasedFileNamingAndTriggeringPolicyBase extends Cont implements TimeBasedFileNamingAndTriggeringPolicy { static private String COLLIDING_DATE_FORMAT_URL = CODES_URL + "#rfa_collision_in_dateFormat"; + protected static final int UNKNOWN_FILE_POSITION = -1; protected TimeBasedRollingPolicy tbrp; diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.java index e75b4bf83b..f560f11eef 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.java +++ b/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.java @@ -36,11 +36,11 @@ * TimeBasedRollingPolicy is both easy to configure and quite * powerful. It allows the rollover to be made based on time. It is possible to * specify that the rollover occur once per day, per week or per month. - * + * *

* For more information, please refer to the online manual at * http://logback.qos.ch/manual/appenders.html#TimeBasedRollingPolicy - * + * * @author Ceki Gülcü */ public class TimeBasedRollingPolicy extends RollingPolicyBase implements TriggeringPolicy { @@ -81,7 +81,7 @@ public void start() { // wcs : without compression suffix fileNamePatternWithoutCompSuffix = new FileNamePattern( - Compressor.computeFileNameStrWithoutCompSuffix(fileNamePatternStr, compressionMode), this.context); + Compressor.computeFileNameStrWithoutCompSuffix(fileNamePatternStr, compressionMode), this.context); addInfo("Will use the pattern " + fileNamePatternWithoutCompSuffix + " for the active file"); @@ -152,7 +152,7 @@ private String transformFileNamePattern2ZipEntry(String fileNamePatternStr) { } public void setTimeBasedFileNamingAndTriggeringPolicy( - TimeBasedFileNamingAndTriggeringPolicy timeBasedTriggering) { + TimeBasedFileNamingAndTriggeringPolicy timeBasedTriggering) { this.timeBasedFileNamingAndTriggeringPolicy = timeBasedTriggering; } @@ -173,11 +173,11 @@ public void rollover() throws RolloverFailure { if (getParentsRawFileProperty() != null) { renameUtil.rename(getParentsRawFileProperty(), elapsedPeriodsFileName); } // else { nothing to do if CompressionMode == NONE and parentsRawFileProperty == - // null } + // null } } else { if (getParentsRawFileProperty() == null) { compressionFuture = compressor.asyncCompress(elapsedPeriodsFileName, elapsedPeriodsFileName, - elapsedPeriodStem); + elapsedPeriodStem); } else { compressionFuture = renameRawAndAsyncCompress(elapsedPeriodsFileName, elapsedPeriodStem); } @@ -197,26 +197,26 @@ Future renameRawAndAsyncCompress(String nameOfCompressedFile, String innerEnt } /** - * + * * The active log file is determined by the value of the parent's filename * option. However, in case the file name is left blank, then, the active log * file equals the file name for the current period as computed by the * FileNamePattern option. - * + * *

* The RollingPolicy must know whether it is responsible for changing the name * of the active file or not. If the active file name is set by the user via the * configuration file, then the RollingPolicy must let it like it is. If the * user does not specify an active file name, then the RollingPolicy generates * one. - * + * *

* To be sure that the file name used by the parent class has been generated by * the RollingPolicy and not specified by the user, we keep track of the last * generated name object and compare its reference to the parent file name. If * they match, then the RollingPolicy knows it's responsible for the change of * the file name. - * + * */ public String getActiveFileName() { String parentsRawFileProperty = getParentsRawFileProperty(); @@ -238,9 +238,22 @@ public boolean isTriggeringEvent(File activeFile, final E event) { return timeBasedFileNamingAndTriggeringPolicy.isTriggeringEvent(activeFile, event); } + /** + * Delegates to the underlying timeBasedFileNamingAndTriggeringPolicy. + * + * @param activeFile A reference to the currently active log file. + * @param event A reference to the current event. + * @param currentFilePosition The current position in activeFile, if known. + * @return + */ + @Override + public boolean isTriggeringEvent(File activeFile, final E event, long currentFilePosition) { + return timeBasedFileNamingAndTriggeringPolicy.isTriggeringEvent(activeFile, event, currentFilePosition); + } + /** * Get the number of archive files to keep. - * + * * @return number of archive files to keep */ public int getMaxHistory() { @@ -249,7 +262,7 @@ public int getMaxHistory() { /** * Set the maximum number of archive files to keep. - * + * * @param maxHistory number of archive files to keep */ public void setMaxHistory(int maxHistory) { @@ -263,7 +276,7 @@ public boolean isCleanHistoryOnStart() { /** * Should archive removal be attempted on application start up? Default is * false. - * + * * @since 1.0.1 * @param cleanHistoryOnStart */ diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/TriggeringPolicy.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/TriggeringPolicy.java index 29abbc8212..b99fe6b3ef 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/TriggeringPolicy.java +++ b/logback-core/src/main/java/ch/qos/logback/core/rolling/TriggeringPolicy.java @@ -35,4 +35,6 @@ public interface TriggeringPolicy extends LifeCycle { * @return true if a roll-over should occur. */ boolean isTriggeringEvent(final File activeFile, final E event); + + boolean isTriggeringEvent(final File activeFile, final E event, long currentFilePosition); } diff --git a/logback-core/src/test/java/ch/qos/logback/core/recovery/ResilientOutputStreamTest.java b/logback-core/src/test/java/ch/qos/logback/core/recovery/ResilientOutputStreamTest.java index 76a6a2a415..ebc2c58bf6 100644 --- a/logback-core/src/test/java/ch/qos/logback/core/recovery/ResilientOutputStreamTest.java +++ b/logback-core/src/test/java/ch/qos/logback/core/recovery/ResilientOutputStreamTest.java @@ -13,6 +13,7 @@ */ package ch.qos.logback.core.recovery; +import static org.junit.jupiter.api.Assertions.assertEquals; import static org.mockito.Mockito.spy; import static org.mockito.Mockito.verify; @@ -51,15 +52,28 @@ public void verifyRecuperationAfterFailure() throws Exception { spy.write("a".getBytes()); spy.flush(); + assertEquals(1, spy.getCount()); spy.getChannel().close(); spy.write("b".getBytes()); spy.flush(); + // we have 2 in our countingoutput stream + // but the 'b' write failed due to the channel closing + assertEquals(2, spy.getCount()); Thread.sleep(RecoveryCoordinator.BACKOFF_COEFFICIENT_MIN + 10); spy.write("c".getBytes()); spy.flush(); + + // since we recovered the output stream, we recomputed + // our count from the length of the file. both b and c were lost. + assertEquals(1, spy.getCount()); verify(spy).openNewOutputStream(); + Thread.sleep(RecoveryCoordinator.BACKOFF_COEFFICIENT_MIN + 10); + spy.write("d".getBytes()); + spy.flush(); + // the 'd' write succeeds, so we have 2 bytes written + assertEquals(2, spy.getCount()); } }