Concurrency issues after upgrade to 0.11.0

[chris-allan]

Thanks to all for the quick turnaround resolving #301.

Unfortunately we've hit a much deeper snag performing an upgrade starting with 0.11.0. Nearly as soon as we re-open in read mode an Array we had previously been writing to we get native code errors or what appears to be a deadlock. This only happens after writing many, many overlapping chunks. This does not happen with 0.10.1.

With our production code this is the behaviour:

TileDB-Java 0.11.0 (TileDB 2.9.0)

[2023-07-25 17:49:14.391] [Process: 2565256] [error] [Global] [TileDB::FragmentMetadata] Error: Trying to access metadata that's not loaded
Caused by: io.tiledb.java.api.TileDBError: [TileDB::FragmentMetadata] Error: Trying to access metadata that's not loaded
	at io.tiledb.java.api.ContextCallback.call(ContextCallback.java:56)
	at io.tiledb.java.api.Context.handleError(Context.java:142)
	at io.tiledb.java.api.Query.submit(Query.java:130)
...

TileDB-Java 0.13.0 (TileDB 2.11.0)

[2023-07-25 13:57:01.358] [Process: 889580] [error] [Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 13:57:03.753] [Process: 889580] [error] [Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 13:57:08.940] [Process: 889580] [error] [Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 13:57:08.942] [Process: 889580] [error] [Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 13:57:08.943] [Process: 889580] [error] [Global] [TileDB::FragmentMetadata] Error: Trying to access metadata that's not loaded
[2023-07-25 13:57:09.289] [Process: 889580] [error] [Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 13:57:11.144] [Process: 889580] [error] [Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
...
Caused by: io.tiledb.java.api.TileDBError: [TileDB::FragmentMetadata] Error: Trying to access metadata that's not loaded
	at io.tiledb.java.api.ContextCallback.call(ContextCallback.java:56)
	at io.tiledb.java.api.Context.handleError(Context.java:142)
	at io.tiledb.java.api.Query.submit(Query.java:130)
...

TileDB-Java 0.14.1 (TileDB 2.12)

[2023-07-25 13:43:49.710] [Process: 1772240] [error] [1690288813910863900-Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 13:43:49.712] [Process: 1772240] [error] [1690288813910863900-Global] Error: Internal TileDB uncaught exception; device or resource busy: device or resource busy
[2023-07-25 13:43:50.810] [Process: 1772240] [error] [1690288813910863900-Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 13:43:50.811] [Process: 1772240] [error] [1690288813910863900-Global] Error: Internal TileDB uncaught exception; device or resource busy: device or resource busy
...
Caused by: io.tiledb.java.api.TileDBError: Error: Internal TileDB uncaught exception; device or resource busy: device or resource busy
	at io.tiledb.java.api.ContextCallback.call(ContextCallback.java:56)
	at io.tiledb.java.api.Context.handleError(Context.java:142)
	at io.tiledb.java.api.Query.submit(Query.java:130)
...

TileDB-Java 0.15.2 (TileDB 2.13.2)

Hang or deadlock. Worker stack traces (collected via jstack) are:

"pool-1-thread-1" #23 prio=5 os_prio=0 cpu=89546.88ms elapsed=340.37s tid=0x0000020972a92800 nid=0x3d32c runnable  [0x000000be392fe000]
   java.lang.Thread.State: RUNNABLE
        at io.tiledb.libtiledb.tiledbJNI.tiledb_query_submit(Native Method)
        at io.tiledb.libtiledb.tiledb.tiledb_query_submit(tiledb.java:2853)
        at io.tiledb.java.api.Query.submit(Query.java:130)
...

TileDB-Java 0.16.1 (TileDB 2.14.1)

Works for a while, dies later.

[2023-07-25 14:20:19.628] [Process: 1313796] [error] [1690290969279989200-Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 14:20:19.632] [Process: 1313796] [error] [1690290969279989200-Global] C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
[2023-07-25 14:20:20.317] [Process: 1313796] [error] [1690290969279989200-Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 14:20:20.317] [Process: 1313796] [error] [1690290969279989200-Global] C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
...
Caused by: io.tiledb.java.api.TileDBError: C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
	at io.tiledb.java.api.ContextCallback.call(ContextCallback.java:56)
	at io.tiledb.java.api.Context.handleError(Context.java:144)
	at io.tiledb.java.api.Query.submit(Query.java:130)
...

TileDB-Java 0.17.8 (TileDB 2.15.4)

[2023-07-25 16:45:09.726] [Process: 452168] [error] [1690299697002774900-Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 16:45:09.729] [Process: 452168] [error] [1690299697002774900-Global] C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
[2023-07-25 16:45:09.921] [Process: 452168] [error] [1690299697002774900-Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 16:45:09.922] [Process: 452168] [error] [1690299697002774900-Global] C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
[2023-07-25 16:45:10.401] [Process: 452168] [error] [1690299697002774900-Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 16:45:10.402] [Process: 452168] [error] [1690299697002774900-Global] C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
[2023-07-25 16:45:10.617] [Process: 452168] [error] [1690299697002774900-Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 16:45:10.617] [Process: 452168] [error] [1690299697002774900-Global] C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
[2023-07-25 16:45:10.762] [Process: 452168] [error] [1690299697002774900-Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 16:45:10.763] [Process: 452168] [error] [1690299697002774900-Global] C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
[2023-07-25 16:45:11.033] [Process: 452168] [error] [1690299697002774900-Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 16:45:11.034] [Process: 452168] [error] [1690299697002774900-Global] C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
[2023-07-25 16:45:11.776] [Process: 452168] [error] [1690299697002774900-Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-25 16:45:11.777] [Process: 452168] [error] [1690299697002774900-Global] C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
...
Caused by: io.tiledb.java.api.TileDBError: C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
	at io.tiledb.java.api.ContextCallback.call(ContextCallback.java:56)
	at io.tiledb.java.api.Context.handleError(Context.java:144)
	at io.tiledb.java.api.Query.submit(Query.java:130)
...

I've put together a limited example which reproduces this:

• https://github.com/chris-allan/tiledb-java-torture

It fails like this:

...
Inserting rectangle: [11078, 21057]
Inserting rectangle: [12093, 21090]
Not consolidating H:\code\tiledb-java-torture\tiledb_14210934035379110573\0
Creating TileDB array: H:\code\tiledb-java-torture\tiledb_14210934035379110573\1
[2023-07-26 13:28:54.114] [Process: 2200528] [error] [1690373955299503400-Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-26 13:28:54.114] [Process: 2200528] [error] [1690373955299503400-Global] C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
Exception during execution
java.util.concurrent.CompletionException: io.tiledb.java.api.TileDBError: C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
	at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331)
	at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346)
	at java.base/java.util.concurrent.CompletableFuture$BiRelay.tryFire(CompletableFuture.java:1423)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073)
	at com.glencoesoftware.tiledb.Main.lambda$2(Main.java:404)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: io.tiledb.java.api.TileDBError: C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
	at io.tiledb.java.api.ContextCallback.call(ContextCallback.java:56)
	at io.tiledb.java.api.Context.handleError(Context.java:144)
	at io.tiledb.java.api.Query.submit(Query.java:130)
	at com.glencoesoftware.tiledb.Main.processTile(Main.java:359)
	at com.glencoesoftware.tiledb.Main.lambda$2(Main.java:402)
	... 3 more

That above output snippet from Windows 10. Linux behaves similarly but not identically.

The code reflects the pattern from our production code that relies on TileDB fairly well:

1. Process a large number of tiles writing them in a non-adjacent fashion from multiple workers to a 5-dimensional TileDB Array
2. Downsample from the Array [1] and write to new 5-dimensional Array for each new "resolution"

20 channels is about right to produce the errors; ~11000 fragments. If less data is processed, things proceed as normal. The issue occurs with or without consolidation.

[ihnorton]

Hi @chris-allan, thanks for opening the story and providing a reproduction. We are investigating.

[chris-allan]

Thanks, @ihnorton.

Just an FYI for the team that I've been running the test case a few more times trying to pick apart what might be going wrong and so far about half the time things block on Query.submit() for a very long time. So you may or may not get those native code exceptions and a clean exit depending on how patient you are.

[chris-allan]

At time of original submission we were at chris-allan/tiledb-java-torture@d2e71cb. I've just pushed chris-allan/tiledb-java-torture@009b39c which does more logging and has explanations for the intent of each instance variable configuration options. While making these improvements and doing a few runs I noticed, just once, what appears to be a non-fatal log line being printed out during execution:

...
Read rectangle: [0, 1000]; status: TILEDB_COMPLETED
Read rectangle: [1000, 1000]; status: TILEDB_COMPLETED
[2023-07-28 11:47:11.266] [Process: 370504] [error] [1690541212777298500-Global] [TileDB::Task] Error: Caught std::exception: device or resource busy: device or resource busy
[2023-07-28 11:47:11.266] [Process: 370504] [error] [1690541212777298500-Global] C API: TileDB Internal, std::exception; device or resource busy: device or resource busy
Read rectangle: [2000, 1000]; status: TILEDB_COMPLETED
Read rectangle: [4000, 1000]; status: TILEDB_COMPLETED
...

This occurred when processing a single channel.

[ihnorton]

Hi @chris-allan, updating that we are still actively working on this -- @DimitrisStaratzis has reproduced and is working through with @KiterLuc.

[chris-allan]

Thanks, @ihnorton. I'll be out of the office for a couple weeks starting Monday but will try to keep an eye on things and answer any questions that come up as quickly as I can.

[KiterLuc]

Hi @chris-allan, we've identified the root cause of your issue, and we've prepared a pull request to address it. We anticipate being able to merge the solution within the next couple of days. We'll keep you updated on our progress.

[KiterLuc]

Hi @chris-allan, this release includes the fix: https://github.com/TileDB-Inc/TileDB/releases/tag/2.16.3. Let us know if it works for you. Thanks, Luc.

[DimitrisStaratzis]

TileDB-Java 0.18.0 has been released to support the latest core version.

[chris-allan]

Thanks to everyone for all the work that went into TileDB-Inc/TileDB#4256! We've successfully managed to upgrade our codebase to 0.18.0 but have noticed a ~10x performance degradation vs. 0.10.1 in our production codebase during the copy phase. This results in a job which takes ~18 minutes with 0.10.1 to take over 3 hours with 0.18.0. It seems to be localized particularly to invoking Query.close() which can take longer than the read or write itself in some cases which is particularly noticeable where we have operations that have to complete serially.

To try and illustrate this for everyone I have updated the torture example with logging and some stop watches where we are seeing issues as of chris-allan/tiledb-java-torture@4211931. You will need to switch debug to true if you want the timings. Here is summary run on Linux against an NVMe SSD:

callan@behemoth:~/code/tiledb-java-torture$ java -jar build/install/*/lib/perf4j-0.9.16.jar debug.log
Performance Statistics   2023-08-23 11:50:00 - 2023-08-23 11:50:30
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
Query.close()                                            0.1           0           1         0.2        1373
Subarray.close()                                         0.0           0           0         0.0        1373
TileDB.writeBlock()                                     45.2          11         185        37.1        1374

Performance Statistics   2023-08-23 11:50:30 - 2023-08-23 11:51:00
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
Query.close()                                            1.3           0          89         3.6        3905
Subarray.close()                                         0.0           0           0         0.0        3904
TileDB.writeBlock()                                     24.3          11         112         4.7        3904

Performance Statistics   2023-08-23 11:51:00 - 2023-08-23 11:51:30
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
DestinationQuery.close()                                 2.3           0          28         1.9        1540
DestinationSubarray.close()                              0.0           0           1         0.0        1540
Query.close()                                            0.5           0           2         0.6         442
SourceQuery.close()                                      5.8           0          97         5.8        1540
SourceSubarray.close()                                   0.0           0           1         0.0        1540
Subarray.close()                                         0.0           0           0         0.0         443
TileDB.readBlock()                                      13.2           4          25         4.4        1540
TileDB.writeBlock()                                     21.6           9          62         5.9        1982

Comparing like with like is hard due to the subarray API differences between 0.10.1 and 0.18.0 but I don't think I can recall a time with 0.10.1 where we ever saw native memory cleanup of Query be millisecond measurable.

I can open another issue if that's preferred. Happy to provide any further information that's helpful.

[KiterLuc]

Thanks for the update @chris-allan. We will start our investigation and see where the time is being spent.