From 3568a5ed6ffec6b8a36e9497cc777b5059f7794d Mon Sep 17 00:00:00 2001 From: Henning Baldersheim Date: Mon, 24 Jun 2019 12:50:51 +0200 Subject: Drop file continously from cache as we read it. --- .../yahoo/container/logging/LogFileHandler.java | 48 +++++----------------- vespajlib/src/main/java/com/yahoo/io/NativeIO.java | 23 +++++++---- 2 files changed, 27 insertions(+), 44 deletions(-) diff --git a/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java b/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java index fb21626cc41..4f3713d3842 100644 --- a/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java +++ b/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java @@ -2,7 +2,6 @@ package com.yahoo.container.logging; import com.yahoo.concurrent.ThreadFactoryFactory; -import com.yahoo.container.core.AccessLogConfig; import com.yahoo.io.NativeIO; import com.yahoo.log.LogFileDb; import com.yahoo.system.ProcessExecuter; @@ -41,8 +40,6 @@ public class LogFileHandler extends StreamHandler { private final boolean compressOnRotation; private long[] rotationTimes = {0}; //default to one log per day, at midnight private String filePattern = "./log.%T"; // default to current directory, ms time stamp - private long lastRotationTime = -1; // absolute time (millis since epoch) of current file start - private int numberOfRecords = -1; private long nextRotationTime = 0; private OutputStream currentOutputStream = null; private String fileName; @@ -122,7 +119,7 @@ public class LogFileHandler extends StreamHandler { } } - private void internalPublish(LogRecord r) throws InterruptedException { + private void internalPublish(LogRecord r) { // first check to see if new file needed. // if so, use this.internalRotateNow() to do it @@ -133,8 +130,6 @@ public class LogFileHandler extends StreamHandler { if (now > nextRotationTime || currentOutputStream == null) { internalRotateNow(); } - // count records, and publish - numberOfRecords++; super.publish(r); } @@ -177,9 +172,9 @@ public class LogFileHandler extends StreamHandler { } long nowTod = timeOfDayMillis(now); long next = 0; - for (int i = 0; i 0; read = inputStream.read(buffer)) { compressor.write(buffer, 0, read); + nativeIO.dropPartialFileFromCache(inputStream.getFD(), totalBytesRead, read, false); + totalBytesRead += read; } compressor.finish(); compressor.flush(); - NativeIO nativeIO = new NativeIO(); - nativeIO.dropFileFromCache(oldFile); // Drop from cache in case somebody else has a reference to it preventing from dying quickly. oldFile.delete(); nativeIO.dropFileFromCache(gzippedFile); } catch (IOException e) { @@ -306,28 +302,6 @@ public class LogFileHandler extends StreamHandler { } } - /** - * Name the current file to "name.n" where n - * 1+ the largest integer in existing file names - */ - private void moveCurrentFile() { - File file=new File(fileName); - if ( ! file.exists()) return; // no current file - File dir=file.getParentFile(); - Pattern logFilePattern=Pattern.compile(".*\\.(\\d+)"); - long largestN=0; - for (File existingFile : dir.listFiles()) { - Matcher matcher=logFilePattern.matcher(existingFile.getName()); - if (!matcher.matches()) continue; - long thisN=Long.parseLong(matcher.group(1)); - if (thisN>largestN) - largestN=thisN; - } - File newFn = new File(dir, file.getName() + "." + (largestN + 1)); - LogFileDb.nowLoggingTo(newFn.getAbsolutePath()); - file.renameTo(newFn); - } - /** * Calculate rotation times array, given times in minutes, as "0 60 ..." * diff --git a/vespajlib/src/main/java/com/yahoo/io/NativeIO.java b/vespajlib/src/main/java/com/yahoo/io/NativeIO.java index f69bdb4e3dd..109b7ff7943 100644 --- a/vespajlib/src/main/java/com/yahoo/io/NativeIO.java +++ b/vespajlib/src/main/java/com/yahoo/io/NativeIO.java @@ -54,19 +54,28 @@ public class NativeIO { } /** - * Will hint the OS that this is will not be accessed again and should hence be dropped from the buffer cache. + * Will hint the OS that data read so far will not be accessed again and should hence be dropped from the buffer cache. * @param fd The file descriptor to drop from buffer cache. */ - public void dropFileFromCache(FileDescriptor fd) { - try { - fd.sync(); - } catch (SyncFailedException e) { - logger.warning("Sync failed while dropping cache: " + e.getMessage()); + public void dropPartialFileFromCache(FileDescriptor fd, long offset, long len, boolean sync) { + if (sync) { + try { + fd.sync(); + } catch (SyncFailedException e) { + logger.warning("Sync failed while dropping cache: " + e.getMessage()); + } } if (initialized) { - posix_fadvise(getNativeFD(fd), 0, 0, POSIX_FADV_DONTNEED); + posix_fadvise(getNativeFD(fd), offset, len, POSIX_FADV_DONTNEED); } } + /** + * Will hint the OS that this is will not be accessed again and should hence be dropped from the buffer cache. + * @param fd The file descriptor to drop from buffer cache. + */ + public void dropFileFromCache(FileDescriptor fd) { + dropPartialFileFromCache(fd, 0, 0, true); + } /** * Will hint the OS that this is will not be accessed again and should hence be dropped from the buffer cache. -- cgit v1.2.3 From 9b78209e4383041219994f00255e4a1c573c2353 Mon Sep 17 00:00:00 2001 From: Henning Baldersheim Date: Mon, 24 Jun 2019 16:01:39 +0200 Subject: A utillity for manual testing on continous dropping from cache. --- .../main/java/com/yahoo/container/logging/LogFileHandler.java | 2 +- .../java/com/yahoo/container/logging/CompressWhileDrop.java | 10 ++++++++++ 2 files changed, 11 insertions(+), 1 deletion(-) create mode 100644 container-accesslogging/src/test/java/com/yahoo/container/logging/CompressWhileDrop.java diff --git a/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java b/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java index 4f3713d3842..e7e8d931d9e 100644 --- a/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java +++ b/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java @@ -253,7 +253,7 @@ public class LogFileHandler extends StreamHandler { } - private void runCompression(File oldFile) { + static void runCompression(File oldFile) { File gzippedFile = new File(oldFile.getPath() + ".gz"); try (GZIPOutputStream compressor = new GZIPOutputStream(new FileOutputStream(gzippedFile), 0x100000); FileInputStream inputStream = new FileInputStream(oldFile)) diff --git a/container-accesslogging/src/test/java/com/yahoo/container/logging/CompressWhileDrop.java b/container-accesslogging/src/test/java/com/yahoo/container/logging/CompressWhileDrop.java new file mode 100644 index 00000000000..3ac1e00b1a0 --- /dev/null +++ b/container-accesslogging/src/test/java/com/yahoo/container/logging/CompressWhileDrop.java @@ -0,0 +1,10 @@ +package com.yahoo.container.logging; + +import java.io.File; + +public class CompressWhileDrop { + public static void main(String [] args) { + System.out.println("Start compressing file " + args[0]); + LogFileHandler.runCompression(new File(args[0])); + } +} -- cgit v1.2.3 From 468d42ee9a1be6a239f1fefa1bea6b214729c96b Mon Sep 17 00:00:00 2001 From: Henning Baldersheim Date: Tue, 25 Jun 2019 16:41:10 +0200 Subject: Continously drop from cache what you have written to the log. --- .../yahoo/container/logging/LogFileHandler.java | 26 +++++++++++++++++----- 1 file changed, 20 insertions(+), 6 deletions(-) diff --git a/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java b/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java index e7e8d931d9e..7d079cc1b55 100644 --- a/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java +++ b/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java @@ -5,6 +5,7 @@ import com.yahoo.concurrent.ThreadFactoryFactory; import com.yahoo.io.NativeIO; import com.yahoo.log.LogFileDb; import com.yahoo.system.ProcessExecuter; +import com.yahoo.yolean.Exceptions; import java.io.File; import java.io.FileInputStream; @@ -21,8 +22,6 @@ import java.util.logging.Level; import java.util.logging.LogRecord; import java.util.logging.Logger; import java.util.logging.StreamHandler; -import java.util.regex.Matcher; -import java.util.regex.Pattern; import java.util.zip.GZIPOutputStream; /** @@ -41,12 +40,14 @@ public class LogFileHandler extends StreamHandler { private long[] rotationTimes = {0}; //default to one log per day, at midnight private String filePattern = "./log.%T"; // default to current directory, ms time stamp private long nextRotationTime = 0; - private OutputStream currentOutputStream = null; + private FileOutputStream currentOutputStream = null; private String fileName; private String symlinkName = null; private ArrayBlockingQueue logQueue = new ArrayBlockingQueue<>(100000); private LogRecord rotateCmd = new LogRecord(Level.SEVERE, "rotateNow"); private ExecutorService executor = Executors.newCachedThreadPool(ThreadFactoryFactory.getDaemonThreadFactory("logfilehandler.compression")); + private final NativeIO nativeIO = new NativeIO(); + private long lastDropPosition = 0; static private class LogThread extends Thread { LogFileHandler logFileHandler; @@ -119,6 +120,20 @@ public class LogFileHandler extends StreamHandler { } } + @Override + public synchronized void flush() { + super.flush(); + try { + if (currentOutputStream != null) { + long newPos = currentOutputStream.getChannel().position(); + nativeIO.dropPartialFileFromCache(currentOutputStream.getFD(), lastDropPosition, newPos, true); + lastDropPosition = newPos; + } + } catch (IOException e) { + logger.warning("Failed dropping from cache : " + Exceptions.toMessageString(e)); + } + } + private void internalPublish(LogRecord r) { // first check to see if new file needed. // if so, use this.internalRotateNow() to do it @@ -192,7 +207,7 @@ public class LogFileHandler extends StreamHandler { } catch (InterruptedException e) { } } - super.flush(); + flush(); } private void checkAndCreateDir(String pathname) { @@ -245,7 +260,6 @@ public class LogFileHandler extends StreamHandler { if (compressOnRotation) { executor.execute(() -> runCompression(oldFile)); } else { - NativeIO nativeIO = new NativeIO(); nativeIO.dropFileFromCache(oldFile); } } @@ -260,8 +274,8 @@ public class LogFileHandler extends StreamHandler { { byte [] buffer = new byte[0x400000]; // 4M buffer - NativeIO nativeIO = new NativeIO(); long totalBytesRead = 0; + NativeIO nativeIO = new NativeIO(); for (int read = inputStream.read(buffer); read > 0; read = inputStream.read(buffer)) { compressor.write(buffer, 0, read); nativeIO.dropPartialFileFromCache(inputStream.getFD(), totalBytesRead, read, false); -- cgit v1.2.3 From b50300f23de1d61b2ec2cd6a17d7956fc453b01e Mon Sep 17 00:00:00 2001 From: Henning Baldersheim Date: Tue, 25 Jun 2019 16:53:18 +0200 Subject: Only run super.flush in flush method. Also reset lastDropPosition when there is a new file. --- .../src/main/java/com/yahoo/container/logging/LogFileHandler.java | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java b/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java index 7d079cc1b55..82c89276319 100644 --- a/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java +++ b/container-accesslogging/src/main/java/com/yahoo/container/logging/LogFileHandler.java @@ -237,7 +237,7 @@ public class LogFileHandler extends StreamHandler { String oldFileName = fileName; long now = System.currentTimeMillis(); fileName = LogFormatter.insertDate(filePattern, now); - super.flush(); + flush(); super.close(); try { @@ -245,6 +245,7 @@ public class LogFileHandler extends StreamHandler { FileOutputStream os = new FileOutputStream(fileName, true); // append mode, for safety super.setOutputStream(os); currentOutputStream = os; + lastDropPosition = 0; LogFileDb.nowLoggingTo(fileName); } catch (IOException e) { -- cgit v1.2.3