[
https://issues.apache.org/jira/browse/HIVE-29401?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18052011#comment-18052011
]
Stamatis Zampetakis commented on HIVE-29401:
--------------------------------------------
In a downstream/internal branch of Hive we were getting quite often the
following SQLTimeoutException exception when we were running JDBC storage
handler tests related to Derby (e.g., external_jdbc_table3.q,
external_jdbc_table4.q).
{noformat}
2026-01-09T09:02:53,664 INFO [85439f6d-3169-467a-b1c0-f2cc8915f492 main]
io.NullRowsInputFormat$NullRowsRecordReader: Using null rows input format
2026-01-09T09:03:23,671 ERROR [85439f6d-3169-467a-b1c0-f2cc8915f492 main]
example.GenericUDFDBOutput: Driver loading or connection issue
java.sql.SQLTimeoutException: Login timeout exceeded.
at
org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
~[derby-10.14.3.0-cloudera1.jar:?]
at
org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
~[derby-10.14.3.0-cloudera1.jar:?]
at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown
Source) ~[derby-10.14.3.0-cloudera1.jar:?]
at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown
Source) ~[derby-10.14.3.0-cloudera1.jar:?]
at org.apache.derby.jdbc.InternalDriver.timeLogin(Unknown Source)
~[derby-10.14.3.0-cloudera1.jar:?]
at org.apache.derby.jdbc.InternalDriver.connect(Unknown Source)
~[derby-10.14.3.0-cloudera1.jar:?]
at org.apache.derby.jdbc.InternalDriver.connect(Unknown Source)
~[derby-10.14.3.0-cloudera1.jar:?]
at org.apache.derby.jdbc.AutoloadedDriver.connect(Unknown Source)
~[derby-10.14.3.0-cloudera1.jar:?]
at java.sql.DriverManager.getConnection(DriverManager.java:664)
~[?:1.8.0_472]
at java.sql.DriverManager.getConnection(DriverManager.java:247)
~[?:1.8.0_472]
at
org.apache.hadoop.hive.contrib.genericudf.example.GenericUDFDBOutput.evaluate(GenericUDFDBOutput.java:125)
[hive-contrib-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.ql.exec.ExprNodeGenericFuncEvaluator._evaluate(ExprNodeGenericFuncEvaluator.java:231)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.ql.exec.ExprNodeEvaluator.evaluate(ExprNodeEvaluator.java:80)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.ql.exec.ExprNodeEvaluator.evaluate(ExprNodeEvaluator.java:68)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.ql.exec.SelectOperator.process(SelectOperator.java:88)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at org.apache.hadoop.hive.ql.exec.Operator.forward(Operator.java:937)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.ql.exec.TableScanOperator.process(TableScanOperator.java:174)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.ql.exec.FetchOperator.pushRow(FetchOperator.java:563)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.ql.exec.FetchOperator.pushRow(FetchOperator.java:555)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.ql.exec.FetchTask.executeInner(FetchTask.java:217)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at org.apache.hadoop.hive.ql.exec.FetchTask.execute(FetchTask.java:114)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:805)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at org.apache.hadoop.hive.ql.Driver.run(Driver.java:534)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at org.apache.hadoop.hive.ql.Driver.run(Driver.java:528)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.ql.reexec.ReExecDriver.run(ReExecDriver.java:190)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.ql.reexec.ReExecDriver.run(ReExecDriver.java:235)
[hive-exec-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.cli.CliDriver.processLocalCmd(CliDriver.java:267)
[hive-cli-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at org.apache.hadoop.hive.cli.CliDriver.processCmd1(CliDriver.java:210)
[hive-cli-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at org.apache.hadoop.hive.cli.CliDriver.processCmd(CliDriver.java:136)
[hive-cli-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:436)
[hive-cli-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:367)
[hive-cli-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.ql.QTestUtil.executeClientInternal(QTestUtil.java:901)
[hive-it-util-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.ql.QTestUtil.executeClient(QTestUtil.java:871)
[hive-it-util-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.cli.control.CoreCliDriver.runTest(CoreCliDriver.java:176)
[hive-it-util-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.cli.control.CliAdapter.runTest(CliAdapter.java:156)
[hive-it-util-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at
org.apache.hadoop.hive.cli.split11.TestMiniLlapLocalCliDriver.testCliDriver(TestMiniLlapLocalCliDriver.java:62)
[test-classes/:?]
at sun.reflect.GeneratedMethodAccessor183.invoke(Unknown Source) ~[?:?]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[?:1.8.0_472]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_472]
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
[junit-4.13.2.jar:4.13.2]
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[junit-4.13.2.jar:4.13.2]
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
[junit-4.13.2.jar:4.13.2]
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[junit-4.13.2.jar:4.13.2]
at
org.apache.hadoop.hive.cli.control.CliAdapter$2$1.evaluate(CliAdapter.java:135)
[hive-it-util-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
[junit-4.13.2.jar:4.13.2]
at
org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
[junit-4.13.2.jar:4.13.2]
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
[junit-4.13.2.jar:4.13.2]
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.Suite.runChild(Suite.java:128)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.Suite.runChild(Suite.java:27)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
[junit-4.13.2.jar:4.13.2]
at
org.apache.hadoop.hive.cli.control.CliAdapter$1$1.evaluate(CliAdapter.java:106)
[hive-it-util-3.1.3000.2025.0.21.0-153.jar:3.1.3000.2025.0.21.0-153]
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
[junit-4.13.2.jar:4.13.2]
at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
[junit-4.13.2.jar:4.13.2]
at
org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:316)
[surefire-junit4-3.5.3.jar:3.5.3]
at
org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:240)
[surefire-junit4-3.5.3.jar:3.5.3]
at
org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:214)
[surefire-junit4-3.5.3.jar:3.5.3]
at
org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:155)
[surefire-junit4-3.5.3.jar:3.5.3]
at
org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:385)
[surefire-booter-3.5.3.jar:3.5.3]
at
org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
[surefire-booter-3.5.3.jar:3.5.3]
at
org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:507)
[surefire-booter-3.5.3.jar:3.5.3]
at
org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:495)
[surefire-booter-3.5.3.jar:3.5.3]
Caused by: org.apache.derby.iapi.error.StandardException: Login timeout
exceeded.
at org.apache.derby.iapi.error.StandardException.newException(Unknown
Source) ~[derby-10.14.3.0-cloudera1.jar:?]
at
org.apache.derby.impl.jdbc.SQLExceptionFactory.wrapArgsForTransportAcrossDRDA(Unknown
Source) ~[derby-10.14.3.0-cloudera1.jar:?]
... 74 more
{noformat}
The analysis showed that the timeout was occurring intermittently on the first
connection that creates the Derby database. Further profiling showed that the
creation of the database performs some heavy I/O operations
and lot of time spend on syncing the file-system.
{noformat}
"Thread-553" daemon prio=5 Id=908 RUNNABLE
at [email protected]/java.io.FileDescriptor.sync(Native Method)
at app//org.apache.derby.impl.io.DirRandomAccessFile.sync(Unknown
Source)
at
app//org.apache.derby.impl.store.raw.data.RAFContainer.writeRAFHeader(Unknown
Source)
at app//org.apache.derby.impl.store.raw.data.RAFContainer.clean(Unknown
Source)
- locked org.apache.derby.impl.store.raw.data.RAFContainer4@25c7f483
at
app//org.apache.derby.impl.services.cache.ConcurrentCache.cleanAndUnkeepEntry(Unknown
Source)
at
app//org.apache.derby.impl.services.cache.ConcurrentCache.cleanCache(Unknown
Source)
at
app//org.apache.derby.impl.services.cache.ConcurrentCache.cleanAll(Unknown
Source)
at
app//org.apache.derby.impl.store.raw.data.BaseDataFileFactory.checkpoint(Unknown
Source)
...
Number of locked synchronizers = 1
- java.util.concurrent.ThreadPoolExecutor$Worker@66dbfa89
{noformat}
The problem does not manifestate in environments where I/O is fast (SSD, memory
mapped fs, etc.) and shows up when disks are slow.
The proposed change solves the aforementioned performance issue by removing
some of the expensive I/O operations performed by Derby.
All this investigation was done together with [~abstractdog] so many thanks to
my coding buddy :)
> Speed-up Derby operations by setting durability mode to test
> ------------------------------------------------------------
>
> Key: HIVE-29401
> URL: https://issues.apache.org/jira/browse/HIVE-29401
> Project: Hive
> Issue Type: Task
> Components: Tests
> Reporter: Stamatis Zampetakis
> Assignee: Stamatis Zampetakis
> Priority: Major
> Labels: pull-request-available
>
> Set derby.system.durability property when running tests to speed-up Derby
> operations by avoiding expensive I/O system calls. This change can have
> noticeable impact in CI environments and anywhere where file-system
> operations are slow.
> Local testing shows a performance gain of an order of magnitude when creating
> a new Derby database (times dropped from ~200ms to 20ms). In CI, these times
> are much bigger and reach the order of seconds.
> The property should not be used in production but it is OK for testing where
> we don't care about recovering from JVM crashes and errors.
> See: https://db.apache.org/derby/docs/10.8/ref/rrefproperdurability.html
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
