java.util.logging (Java 19) - Why isn't the logging written to disk immediately?

Question

I have a small java program that uses logging.

import java.util.logging.*;  
public class Main {     
    static Logger  logger = Logger.getLogger(Main.class.getName());     
    static   {         
         try {             
            System.setProperty( "java.util.logging.SimpleFormatter.format", 
                               "[%1$tF %1$tT] [%4$-7s] %5$s %n");             
            FileHandler fileHandler = new FileHandler("java_%u.log");
            fileHandler.setFormatter(new SimpleFormatter()); 
            logger.addHandler(fileHandler);  
           } catch (Exception e) { 
             logger.severe(e.getMessage()); 
          }         
          logger.info("Static done");     
    }       
    public static void main(String[] args) {         
       logger.info("Main started");         
       for(int i=0;i<10;i++){ 
         logger.info("Sleeping "+ i);             
         try {                 
            Thread.sleep(3000); 
         } catch (InterruptedException e) {                 
            throw new RuntimeException(e);             
         }        
       }     
    }
 }

It doesn't matter whether you use it from a development environment (Intellij 2022.2.3)
or directly as a jar file from the command line.

How logging works is generally clear to me. It's the Java version (jdk 19) that's giving me problems? Why is the logging only written to disk after the program has terminated?

Logging is quite critical. It is non-functional but a huge performance loss when not done carefully. The same holds for System.out and progress bars. Flushing to file, and indeed physical write through to disk are very costly. For rare critical logging you could implement your own handlers, maybe based on level too. And it might help to do `logger.severe(e::getMessage);`. — Joop Eggen, Nov 24 '22 at 18:35
I can't reproduce this with Java 11 or Java 17. (But ... how did you manage to get funky invisible characters into the source code? Did you copy the code from a word-processed document or something?) — Stephen C, Dec 28 '22 at 03:43

jmehrens · Answer 1 · 2022-12-28T15:57:58.343

Why is the logging only written to disk after the program has terminated?

On shutdown the FileHandler is closed by the LogManager which issues a sync to disk. Normal publish of the FileHandler will only issue a flush and not a sync. I think in your test program you are not filling the native buffers to make it sync to disk. I would assume you are going to have to exceed 8K of log data before data is written to disk.

The other possibility is that the contents are written to disk but the way you are observing the log file can't see them. This can happen if you are view this file over a network share from another machine.

Stephen C · Answer 2 · 2022-12-28T03:42:03.913

1

This is peculiar.

I have a copy of the Java 19 source code in front of me, and the JUL code for a FileHandler calls flush after each log record. And I think I can see where it calls flush on the handler's Writer.

When I run your example, the log file seems to be written to each time an event is logged. Immediately ... as far as I can tell.

(I ran the code with Java 11 and Java 17.)

edited Dec 28 '22 at 03:42

answered Dec 28 '22 at 03:21

Stephen C

698,415
94
811
1,216

java.util.logging (Java 19) - Why isn't the logging written to disk immediately?

2 Answers2