Skip to content

Commit d581adb

Browse files
Neenu1995Neenu1995
authored
fix(bigquery-jdbc): lazy caller inference and zero-overhead coercion logging (#13365)
### Problem When the BigQuery JDBC driver is run with JUL-to-SLF4J bridges (like `SLF4JBridgeHandler` in Spring Boot environments), JUL's logging level is configured to `ALL` to allow filtering to occur at the SLF4J/Logback layer. As a result, the driver's custom logger always proceeded to log, eagerly capturing and walking stack traces (`new Throwable().getStackTrace()`) to find the caller class and method. On hot paths (such as `BigQueryTypeCoercer.coerceTo` converting values for millions of rows), this caused severe CPU and memory overhead (representing up to ~99% CPU time in profile runs), even if SLF4J immediately discarded the logs. ### Summary of Changes * **Lazy Caller Inference (`BigQueryJdbcLogRecord`)**: * Introduced `BigQueryJdbcLogRecord` (a custom subclass of `LogRecord`) inside `BigQueryJdbcCustomLogger` to defer caller stack-trace walking until requested by formatters/bridges. * Ensures zero stack-walk overhead when logging is disabled under SLF4J bridges. * Added framework packages (like `org.slf4j.bridge.*`) to the caller skipper list to maintain inference correctness. * **Coercion Hot Path Optimization (`BigQueryTypeCoercer`)**: * Switched type coercion logger to the specialized `BigQueryJdbcResultSetLogger`. * Replaced generic `effectiveLog.finest` with explicit context passing using `effectiveLog.finestTrace("coerceTo", ...)`. * Avoids stack walks entirely on the result set coercion hot path, regardless of whether logging is enabled. * **Unit Testing**: * Added `testLazyCallerInference` in `BigQueryJdbcCustomLoggerTest` to verify that stack-trace walking is deferred until queried and accurately resolves the correct caller class/method. ### Performance Impact * **Benchmark results**: Query execution on 100k rows × 5 cols with high-throughput enabled yielded a **~5.9% end-to-end execution time reduction** (and up to 3.3× speedup on larger 2M × 34 datasets where JDBC coercion overhead is the main bottleneck). * Eliminated millions of garbage collection allocations of `StackTraceElement[]` on the JDBC data retrieval hot paths.
1 parent 86ebaf6 commit d581adb

3 files changed

Lines changed: 102 additions & 23 deletions

File tree

‎java-bigquery-jdbc/src/main/java/com/google/cloud/bigquery/jdbc/BigQueryJdbcCustomLogger.java‎

Lines changed: 72 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -42,28 +42,81 @@ private void logWithCaller(Level level, Throwable thrown, Supplier<String> msgSu
4242
return;
4343
}
4444

45-
StackTraceElement[] stackTrace = new Throwable().getStackTrace();
46-
String sourceClass = "unknown";
47-
String sourceMethod = "unknown";
48-
49-
for (StackTraceElement element : stackTrace) {
50-
String className = element.getClassName();
51-
if (!className.equals(BigQueryJdbcCustomLogger.class.getName())
52-
&& !className.startsWith("com.google.cloud.bigquery.exception.")) {
53-
sourceClass = className;
54-
sourceMethod = element.getMethodName();
55-
break;
45+
LogRecord record = new BigQueryJdbcLogRecord(level, msgSupplier.get());
46+
record.setThrown(thrown);
47+
log(record);
48+
}
49+
50+
static class BigQueryJdbcLogRecord extends LogRecord {
51+
private boolean callerInferred = false;
52+
private String sourceClass;
53+
private String sourceMethod;
54+
55+
public BigQueryJdbcLogRecord(Level level, String msg) {
56+
super(level, msg);
57+
}
58+
59+
synchronized boolean isCallerInferred() {
60+
return callerInferred;
61+
}
62+
63+
@Override
64+
public synchronized String getSourceClassName() {
65+
inferCaller();
66+
return sourceClass;
67+
}
68+
69+
@Override
70+
public synchronized void setSourceClassName(String sourceClassName) {
71+
super.setSourceClassName(sourceClassName);
72+
this.sourceClass = sourceClassName;
73+
this.callerInferred = true;
74+
}
75+
76+
@Override
77+
public synchronized String getSourceMethodName() {
78+
inferCaller();
79+
return sourceMethod;
80+
}
81+
82+
@Override
83+
public synchronized void setSourceMethodName(String sourceMethodName) {
84+
super.setSourceMethodName(sourceMethodName);
85+
this.sourceMethod = sourceMethodName;
86+
this.callerInferred = true;
87+
}
88+
89+
private synchronized void inferCaller() {
90+
if (callerInferred) {
91+
return;
92+
}
93+
callerInferred = true;
94+
StackTraceElement[] stackTrace = new Throwable().getStackTrace();
95+
sourceClass = "unknown";
96+
sourceMethod = "unknown";
97+
98+
for (StackTraceElement element : stackTrace) {
99+
String className = element.getClassName();
100+
if (isDriverClass(className) && !isLoggerClass(className)) {
101+
sourceClass = className;
102+
sourceMethod = element.getMethodName();
103+
break;
104+
}
56105
}
106+
super.setSourceClassName(sourceClass);
107+
super.setSourceMethodName(sourceMethod);
108+
}
109+
110+
private static boolean isDriverClass(String className) {
111+
return className.startsWith("com.google.cloud.bigquery.jdbc.")
112+
|| className.startsWith("com.google.cloud.bigquery.exception.");
57113
}
58114

59-
if (thrown == null) {
60-
logp(level, sourceClass, sourceMethod, msgSupplier);
61-
} else {
62-
LogRecord record = new LogRecord(level, msgSupplier.get());
63-
record.setSourceClassName(sourceClass);
64-
record.setSourceMethodName(sourceMethod);
65-
record.setThrown(thrown);
66-
log(record);
115+
private static boolean isLoggerClass(String className) {
116+
return className.equals("com.google.cloud.bigquery.jdbc.BigQueryJdbcCustomLogger")
117+
|| className.equals("com.google.cloud.bigquery.jdbc.BigQueryJdbcResultSetLogger")
118+
|| className.startsWith("com.google.cloud.bigquery.jdbc.BigQueryJdbcRootLogger")
119+
|| className.equals(BigQueryJdbcLogRecord.class.getName());
67120
}
68121
}
69122

‎java-bigquery-jdbc/src/main/java/com/google/cloud/bigquery/jdbc/BigQueryTypeCoercer.java‎

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -67,8 +67,8 @@
6767
*/
6868
@InternalApi
6969
class BigQueryTypeCoercer {
70-
private static final BigQueryJdbcCustomLogger LOG =
71-
new BigQueryJdbcCustomLogger(BigQueryTypeCoercer.class.getName());
70+
private static final BigQueryJdbcResultSetLogger LOG =
71+
BigQueryJdbcResultSetLogger.getLogger(BigQueryTypeCoercer.class);
7272

7373
/** A {@link BigQueryTypeCoercer} instance with all the inbuilt {@link BigQueryCoercion}s */
7474
static BigQueryTypeCoercer INSTANCE;
@@ -108,8 +108,9 @@ <T> T coerceTo(Class<T> targetClass, Object value, BigQueryJdbcResultSetLogger l
108108
return targetClass.cast(value);
109109
}
110110
BigQueryCoercion<Object, T> coercion = findCoercion(sourceClass, targetClass);
111-
BigQueryJdbcCustomLogger effectiveLog = log != null ? log : LOG;
112-
effectiveLog.finest("%s coercion for %s", coercion, value);
111+
BigQueryJdbcResultSetLogger effectiveLog = log != null ? log : LOG;
112+
effectiveLog.finestTrace(
113+
"coerceTo", () -> String.format("%s coercion for %s", coercion, value));
113114
// Value is null case & no explicit coercion
114115
if (sourceClass == Void.class && coercion == null) {
115116
return null;

‎java-bigquery-jdbc/src/test/java/com/google/cloud/bigquery/jdbc/BigQueryJdbcCustomLoggerTest.java‎

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -93,6 +93,31 @@ public void testLogWithCallerInference() {
9393
assertEquals(BigQueryJdbcCustomLoggerTest.class.getName(), record.getSourceClassName());
9494
}
9595

96+
@Test
97+
public void testLazyCallerInference() {
98+
logger.fine("Lazy log message");
99+
100+
List<LogRecord> records = testHandler.getRecords();
101+
assertEquals(1, records.size());
102+
LogRecord record = records.get(0);
103+
104+
assertTrue(record instanceof BigQueryJdbcCustomLogger.BigQueryJdbcLogRecord);
105+
BigQueryJdbcCustomLogger.BigQueryJdbcLogRecord lazyRecord =
106+
(BigQueryJdbcCustomLogger.BigQueryJdbcLogRecord) record;
107+
108+
// Verify stack walk has not been executed yet
109+
assertTrue(!lazyRecord.isCallerInferred());
110+
111+
// Trigger stack walk
112+
String className = record.getSourceClassName();
113+
String methodName = record.getSourceMethodName();
114+
115+
// Verify stack walk has executed and correct caller was inferred
116+
assertTrue(lazyRecord.isCallerInferred());
117+
assertEquals(BigQueryJdbcCustomLoggerTest.class.getName(), className);
118+
assertEquals("testLazyCallerInference", methodName);
119+
}
120+
96121
@Test
97122
public void testHotPathLoggerLogToDefaultWhenContextIsNull() {
98123
BigQueryJdbcCustomLogger hotpathLogger =

0 commit comments

Comments
 (0)