adding logging for debugging purposes

Author: MarkWolters

.github/workflows/run-bench.yml

@@ -65,12 +65,19 @@ jobs:
           java ${{ matrix.jdk >= 20 && '--enable-native-access=ALL-UNNAMED --add-modules=jdk.incubator.vector' || '' }} \
             ${{ matrix.jdk >= 22 && '-Djvector.experimental.enable_native_vectorization=true' || '' }} \
             -jar jvector-examples/target/jvector-examples-*-jar-with-dependencies.jar io.github.jbellis.jvector.example.AutoBenchYAML --output bench-results.json ${{ inputs.benchmark_config != '' && inputs.benchmark_config || 'jvector-examples/yaml-configs/default.yml' }}
+          
+          # List files in current directory to help with debugging
+          echo "Files in current directory:"
+          ls -la
 
       - name: Upload Bench Results
         uses: actions/upload-artifact@v4
         with:
           name: bench-results-${{ matrix.isa }}-jdk${{ matrix.jdk }}
-          path: bench-results.json
+          path: |
+            bench-results.json
+            bench-results.log
+          if-no-files-found: warn
 
       - name: Download Previous Benchmark Results
         uses: dawidd6/action-download-artifact@v2

jvector-examples/pom.xml

@@ -72,6 +72,17 @@
                 </exclusion>
             </exclusions>
         </dependency>
+        <!-- Add SLF4J and Logback for logging -->
+        <dependency>
+            <groupId>org.slf4j</groupId>
+            <artifactId>slf4j-api</artifactId>
+            <version>2.0.9</version>
+        </dependency>
+        <dependency>
+            <groupId>ch.qos.logback</groupId>
+            <artifactId>logback-classic</artifactId>
+            <version>1.4.11</version>
+        </dependency>
         <dependency>
             <groupId>software.amazon.awssdk</groupId>
             <artifactId>s3-transfer-manager</artifactId>

jvector-examples/src/main/java/io/github/jbellis/jvector/example/AutoBenchYAML.java

@@ -24,6 +24,9 @@
 import io.github.jbellis.jvector.example.yaml.MultiConfig;
 import io.github.jbellis.jvector.graph.disk.feature.FeatureId;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 import java.io.File;
 import java.io.IOException;
 import java.util.ArrayList;
@@ -38,6 +41,8 @@
  * for regression testing in the run-bench.yml workflow.
  */
 public class AutoBenchYAML {
+    private static final Logger logger = LoggerFactory.getLogger(AutoBenchYAML.class);
+
     /**
      * Returns a list of all dataset names.
      * This replaces the need to load datasets.yml which may not be available in all environments.
@@ -83,11 +88,11 @@ public static void main(String[] args) throws IOException {
         }
 
         if (outputPath == null) {
-            System.err.println("Error: --output argument is required for AutoBenchYAML");
+            logger.error("Error: --output argument is required for AutoBenchYAML");
             System.exit(1);
         }
 
-        System.out.println("Heap space available is " + Runtime.getRuntime().maxMemory());
+        logger.info("Heap space available is {}", Runtime.getRuntime().maxMemory());
 
         // Filter out --output and its argument from the args
         String finalOutputPath = outputPath;
@@ -102,18 +107,21 @@ public static void main(String[] args) throws IOException {
 
         var datasetNames = getAllDatasetNames().stream().filter(dn -> pattern.matcher(dn).find()).collect(Collectors.toList());
 
-        System.out.println("Executing the following datasets: " + datasetNames);
+        logger.info("Executing the following datasets: {}", datasetNames);
         List<BenchResult> results = new ArrayList<>();
 
         // Process datasets from regex patterns
         if (!datasetNames.isEmpty()) {
             for (var datasetName : datasetNames) {
+                logger.info("Loading dataset: {}", datasetName);
                 DataSet ds = DataSetLoader.loadDataSet(datasetName);
+                logger.info("Dataset loaded: {} with {} vectors", datasetName, ds.baseVectors.size());
 
                 if (datasetName.endsWith(".hdf5")) {
                     datasetName = datasetName.substring(0, datasetName.length() - ".hdf5".length());
                 }
                 MultiConfig config = MultiConfig.getDefaultConfig(datasetName);
+                logger.info("Using configuration: {}", config);
 
                 results.addAll(Grid.runAllAndCollectResults(ds, 
                         config.construction.outDegree, 
@@ -132,10 +140,14 @@ public static void main(String[] args) throws IOException {
         List<String> configNames = Arrays.stream(filteredArgs).filter(s -> s.endsWith(".yml")).collect(Collectors.toList());
         if (!configNames.isEmpty()) {
             for (var configName : configNames) {
+                logger.info("Processing configuration file: {}", configName);
                 MultiConfig config = MultiConfig.getConfig(configName);
                 String datasetName = config.dataset;
+                logger.info("Configuration specifies dataset: {}", datasetName);
 
+                logger.info("Loading dataset: {}", datasetName);
                 DataSet ds = DataSetLoader.loadDataSet(datasetName);
+                logger.info("Dataset loaded: {} with {} vectors", datasetName, ds.baseVectors.size());
 
                 results.addAll(Grid.runAllAndCollectResults(ds, 
                         config.construction.outDegree, 
@@ -152,11 +164,19 @@ public static void main(String[] args) throws IOException {
 
         // Calculate summary statistics
         SummaryStats stats = BenchmarkSummarizer.summarize(results);
-        System.out.println(stats.toString());
+        logger.info("Benchmark summary: {}", stats.toString());
 
         // Write results to JSON file
         ObjectMapper mapper = new ObjectMapper();
-        mapper.writerWithDefaultPrettyPrinter().writeValue(new File(outputPath), results);
-        System.out.println("Benchmark results written to " + outputPath);
+        File outputFile = new File(outputPath);
+        mapper.writerWithDefaultPrettyPrinter().writeValue(outputFile, results);
+        logger.info("Benchmark results written to {} (file exists: {})", outputPath, outputFile.exists());
+        
+        // Double check that the file was created and log its size
+        if (outputFile.exists()) {
+            logger.info("Output file size: {} bytes", outputFile.length());
+        } else {
+            logger.error("Failed to create output file at {}", outputPath);
+        }
     }
 }

jvector-examples/src/main/resources/logback.xml

@@ -0,0 +1,30 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<configuration>
+    <!-- Console appender configuration -->
+    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
+        <!-- Ensure immediate flushing of logs -->
+        <immediateFlush>true</immediateFlush>
+        <encoder>
+            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
+        </encoder>
+    </appender>
+
+    <!-- File appender configuration -->
+    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
+        <file>bench-results.log</file>
+        <append>true</append>
+        <immediateFlush>true</immediateFlush>
+        <encoder>
+            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
+        </encoder>
+    </appender>
+
+    <!-- Root logger configuration -->
+    <root level="INFO">
+        <appender-ref ref="CONSOLE" />
+        <appender-ref ref="FILE" />
+    </root>
+
+    <!-- Set specific logger levels -->
+    <logger name="io.github.jbellis.jvector.example" level="DEBUG" />
+</configuration>