You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hive.apache.org by "Stamatis Zampetakis (Jira)" <ji...@apache.org> on 2026/01/15 08:39:00 UTC
[jira] [Commented] (HIVE-29401) Speed-up Derby operations by setting durability mode to test
[ 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 java.base@17.0.17/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)