|
| 1 | +/* |
| 2 | + * Licensed to the Apache Software Foundation (ASF) under one or more |
| 3 | + * contributor license agreements. See the NOTICE file distributed with |
| 4 | + * this work for additional information regarding copyright ownership. |
| 5 | + * The ASF licenses this file to you under the Apache License, Version 2.0 |
| 6 | + * (the "License"); you may not use this file except in compliance with |
| 7 | + * the License. You may obtain a copy of the License at |
| 8 | + * |
| 9 | + * http://www.apache.org/licenses/LICENSE-2.0 |
| 10 | + * |
| 11 | + * Unless required by applicable law or agreed to in writing, software |
| 12 | + * distributed under the License is distributed on an "AS IS" BASIS, |
| 13 | + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| 14 | + * See the License for the specific language governing permissions and |
| 15 | + * limitations under the License. |
| 16 | + */ |
| 17 | +package org.apache.logging.log4j.iceberg; |
| 18 | + |
| 19 | +import static org.assertj.core.api.Assertions.assertThat; |
| 20 | + |
| 21 | +import java.io.BufferedReader; |
| 22 | +import java.io.File; |
| 23 | +import java.io.FileReader; |
| 24 | +import java.io.IOException; |
| 25 | +import java.nio.file.Files; |
| 26 | +import java.nio.file.Path; |
| 27 | +import java.util.Comparator; |
| 28 | +import java.util.HashMap; |
| 29 | +import java.util.HashSet; |
| 30 | +import java.util.Map; |
| 31 | +import java.util.Set; |
| 32 | +import java.util.concurrent.TimeUnit; |
| 33 | +import org.apache.iceberg.Snapshot; |
| 34 | +import org.apache.iceberg.data.IcebergGenerics; |
| 35 | +import org.apache.iceberg.data.Record; |
| 36 | +import org.apache.iceberg.io.CloseableIterable; |
| 37 | +import org.apache.logging.log4j.Level; |
| 38 | +import org.apache.logging.log4j.core.LogEvent; |
| 39 | +import org.apache.logging.log4j.core.appender.FileAppender; |
| 40 | +import org.apache.logging.log4j.core.impl.Log4jLogEvent; |
| 41 | +import org.apache.logging.log4j.core.layout.PatternLayout; |
| 42 | +import org.apache.logging.log4j.message.SimpleMessage; |
| 43 | +import org.junit.jupiter.api.AfterEach; |
| 44 | +import org.junit.jupiter.api.BeforeEach; |
| 45 | +import org.junit.jupiter.api.Test; |
| 46 | + |
| 47 | +class IcebergPerformanceTest { |
| 48 | + |
| 49 | + private static final int TOTAL_RECORDS = 1_000_000; |
| 50 | + private static final int RECORDS_PER_COMMIT = 100_000; |
| 51 | + |
| 52 | + private Path tempDir; |
| 53 | + private IcebergManager manager; |
| 54 | + |
| 55 | + @BeforeEach |
| 56 | + void setUp() throws IOException { |
| 57 | + tempDir = Files.createTempDirectory("iceberg-perf-test"); |
| 58 | + } |
| 59 | + |
| 60 | + @AfterEach |
| 61 | + void tearDown() throws IOException { |
| 62 | + if (manager != null) { |
| 63 | + manager.stop(30, TimeUnit.SECONDS); |
| 64 | + } |
| 65 | + Files.walk(tempDir).sorted(Comparator.reverseOrder()).map(Path::toFile).forEach(File::delete); |
| 66 | + } |
| 67 | + |
| 68 | + private static final Level[] LEVELS = {Level.TRACE, Level.DEBUG, Level.INFO, Level.WARN, Level.ERROR}; |
| 69 | + |
| 70 | + private LogEvent buildEvent(final int i) { |
| 71 | + return Log4jLogEvent.newBuilder() |
| 72 | + .setLoggerName("com.example.perf.Logger" + (i % 100)) |
| 73 | + .setLevel(LEVELS[i % LEVELS.length]) |
| 74 | + .setMessage(new SimpleMessage("perf-message-" + i)) |
| 75 | + .setThreadName("perf-thread-" + (i % 10)) |
| 76 | + .setTimeMillis(1700000000000L + i) |
| 77 | + .build(); |
| 78 | + } |
| 79 | + |
| 80 | + @Test |
| 81 | + void writeOneMillionRecordsWithPeriodicCommits() throws IOException { |
| 82 | + |
| 83 | + // ============================================================ |
| 84 | + // Phase 1: File Appender benchmark |
| 85 | + // ============================================================ |
| 86 | + final Path logFile = tempDir.resolve("perf-test.log"); |
| 87 | + final PatternLayout layout = PatternLayout.newBuilder() |
| 88 | + .withPattern("%d %-5level [%t] %logger - %msg%n") |
| 89 | + .build(); |
| 90 | + final FileAppender fileAppender = FileAppender.newBuilder() |
| 91 | + .setName("filePerf") |
| 92 | + .withFileName(logFile.toString()) |
| 93 | + .withImmediateFlush(false) |
| 94 | + .withBufferedIo(true) |
| 95 | + .withBufferSize(8192) |
| 96 | + .setLayout(layout) |
| 97 | + .build(); |
| 98 | + fileAppender.start(); |
| 99 | + |
| 100 | + final long fileWriteStart = System.nanoTime(); |
| 101 | + for (int i = 0; i < TOTAL_RECORDS; i++) { |
| 102 | + fileAppender.append(buildEvent(i)); |
| 103 | + } |
| 104 | + fileAppender.stop(30, TimeUnit.SECONDS); |
| 105 | + final long fileWriteMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - fileWriteStart); |
| 106 | + final double fileWriteThroughput = (double) TOTAL_RECORDS / fileWriteMs * 1000.0; |
| 107 | + |
| 108 | + int fileLineCount = 0; |
| 109 | + try (BufferedReader reader = new BufferedReader(new FileReader(logFile.toFile()))) { |
| 110 | + while (reader.readLine() != null) { |
| 111 | + fileLineCount++; |
| 112 | + } |
| 113 | + } |
| 114 | + assertThat(fileLineCount).isEqualTo(TOTAL_RECORDS); |
| 115 | + final long fileSizeBytes = Files.size(logFile); |
| 116 | + |
| 117 | + // ============================================================ |
| 118 | + // Phase 2: Iceberg Appender benchmark |
| 119 | + // ============================================================ |
| 120 | + final Path warehouseDir = tempDir.resolve("warehouse"); |
| 121 | + Files.createDirectories(warehouseDir); |
| 122 | + manager = new IcebergManager( |
| 123 | + "perf_test", |
| 124 | + "perf_catalog", |
| 125 | + "hadoop", |
| 126 | + null, |
| 127 | + warehouseDir.toAbsolutePath().toString(), |
| 128 | + "perf_ns", |
| 129 | + "perf_table", |
| 130 | + RECORDS_PER_COMMIT, |
| 131 | + 3600); |
| 132 | + manager.startup(); |
| 133 | + |
| 134 | + final long icebergWriteStart = System.nanoTime(); |
| 135 | + for (int i = 0; i < TOTAL_RECORDS; i++) { |
| 136 | + manager.write(buildEvent(i).toImmutable()); |
| 137 | + } |
| 138 | + manager.flush(); |
| 139 | + final long icebergWriteMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - icebergWriteStart); |
| 140 | + final double icebergWriteThroughput = (double) TOTAL_RECORDS / icebergWriteMs * 1000.0; |
| 141 | + |
| 142 | + manager.table.refresh(); |
| 143 | + int snapshotCount = 0; |
| 144 | + for (final Snapshot ignored : manager.table.snapshots()) { |
| 145 | + snapshotCount++; |
| 146 | + } |
| 147 | + final int expectedCommits = (TOTAL_RECORDS + RECORDS_PER_COMMIT - 1) / RECORDS_PER_COMMIT; |
| 148 | + assertThat(snapshotCount).isEqualTo(expectedCommits); |
| 149 | + |
| 150 | + // Iceberg read-back |
| 151 | + final long icebergReadStart = System.nanoTime(); |
| 152 | + final Map<String, Integer> levelCounts = new HashMap<>(); |
| 153 | + final Set<String> seenMessages = new HashSet<>(); |
| 154 | + int totalRead = 0; |
| 155 | + |
| 156 | + try (CloseableIterable<Record> records = |
| 157 | + IcebergGenerics.read(manager.table).build()) { |
| 158 | + for (final Record record : records) { |
| 159 | + final String level = (String) record.getField("level"); |
| 160 | + final String message = (String) record.getField("message"); |
| 161 | + |
| 162 | + assertThat(level).isNotNull(); |
| 163 | + assertThat(message).startsWith("perf-message-"); |
| 164 | + assertThat(record.getField("logger_name").toString()).startsWith("com.example.perf.Logger"); |
| 165 | + assertThat(record.getField("thread_name").toString()).startsWith("perf-thread-"); |
| 166 | + assertThat(record.getField("timestamp")).isNotNull(); |
| 167 | + assertThat(record.getField("event_date")).isNotNull(); |
| 168 | + |
| 169 | + levelCounts.merge(level, 1, Integer::sum); |
| 170 | + seenMessages.add(message); |
| 171 | + totalRead++; |
| 172 | + } |
| 173 | + } |
| 174 | + final long icebergReadMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - icebergReadStart); |
| 175 | + final double icebergReadThroughput = (double) totalRead / icebergReadMs * 1000.0; |
| 176 | + |
| 177 | + assertThat(totalRead).isEqualTo(TOTAL_RECORDS); |
| 178 | + assertThat(seenMessages).hasSize(TOTAL_RECORDS); |
| 179 | + final int expectedPerLevel = TOTAL_RECORDS / LEVELS.length; |
| 180 | + for (final Level level : LEVELS) { |
| 181 | + assertThat(levelCounts.get(level.name())) |
| 182 | + .as("Count for level %s", level.name()) |
| 183 | + .isEqualTo(expectedPerLevel); |
| 184 | + } |
| 185 | + |
| 186 | + long icebergSizeBytes = 0; |
| 187 | + try (java.util.stream.Stream<Path> paths = Files.walk(warehouseDir)) { |
| 188 | + icebergSizeBytes = paths.filter(Files::isRegularFile) |
| 189 | + .mapToLong(p -> p.toFile().length()) |
| 190 | + .sum(); |
| 191 | + } |
| 192 | + |
| 193 | + // ============================================================ |
| 194 | + // Results |
| 195 | + // ============================================================ |
| 196 | + System.out.println(); |
| 197 | + System.out.println("========== Performance Comparison (1M records) =========="); |
| 198 | + System.out.println(); |
| 199 | + System.out.printf("%-25s %15s %15s%n", "", "File Appender", "Iceberg"); |
| 200 | + System.out.printf("%-25s %15s %15s%n", "-------------------------", "---------------", "---------------"); |
| 201 | + System.out.printf("%-25s %12d ms %12d ms%n", "Write time", fileWriteMs, icebergWriteMs); |
| 202 | + System.out.printf("%-25s %12.0f/s %12.0f/s%n", "Write throughput", fileWriteThroughput, icebergWriteThroughput); |
| 203 | + System.out.printf("%-25s %15s %12d ms%n", "Read time", "n/a", icebergReadMs); |
| 204 | + System.out.printf("%-25s %15s %12.0f/s%n", "Read throughput", "n/a", icebergReadThroughput); |
| 205 | + System.out.printf( |
| 206 | + "%-25s %12.1f MB %12.1f MB%n", |
| 207 | + "Disk size", fileSizeBytes / (1024.0 * 1024.0), icebergSizeBytes / (1024.0 * 1024.0)); |
| 208 | + System.out.printf("%-25s %15d %15d%n", "Commits/flushes", 1, snapshotCount); |
| 209 | + System.out.printf("%-25s %12.1fx %15s%n", "Iceberg overhead", (double) icebergWriteMs / fileWriteMs, ""); |
| 210 | + System.out.printf("%-25s %12.1fx %15s%n", "Iceberg compression", (double) fileSizeBytes / icebergSizeBytes, ""); |
| 211 | + System.out.println(); |
| 212 | + System.out.println("Level distribution: " + levelCounts); |
| 213 | + System.out.println("All " + TOTAL_RECORDS + " records verified correct in both appenders."); |
| 214 | + System.out.println("========================================================="); |
| 215 | + } |
| 216 | +} |
0 commit comments