I’m facing an issue where repeatedly reading over the dataset gets slower with each read. I’ve included stats below, which are generated by repeatedly calculating the mean over the entire Array. Note that this is specifically a sparse array, and I’m using dask to load data chunks in a multi-threaded and lazy manner (but only ever opening the array once, and using that same handle for all reads).
As far as I can tell, the majority of time increase seems to be coming from py.core_read_query_initial_submit_time / Context.Query.Reader.unfilter_coord_tiles / Context.Query.Reader.read_and_unfilter_coords - but I’m not really sure how to interpret what those metrics are referring to, or how I would go about diagnosing the problem further.
Here are the stats for the very first run, which completes in ~26 seconds:
TileDB Embedded Version: (2, 28, 1)
TileDB-Py Version: 0.34.2
[
{
"timers": {
"Context.subSubarray.sort_and_merge_ranges.sum": 0.0033182,
"Context.subSubarray.sort_and_merge_ranges.avg": 1.6591e-05,
"Context.subSubarray.read_load_relevant_rtrees.sum": 0.224074,
"Context.subSubarray.read_load_relevant_rtrees.avg": 0.000560185,
"Context.subSubarray.read_compute_simple_tile_overlap.sum": 0.452798,
"Context.subSubarray.read_compute_simple_tile_overlap.avg": 0.00226399,
"Context.subSubarray.compute_relevant_frags.sum": 0.196859,
"Context.subSubarray.compute_relevant_frags.avg": 0.000984295,
"Context.Query.Reader.unfilter_coord_tiles.sum": 63.5281,
"Context.Query.Reader.unfilter_coord_tiles.avg": 0.0715406,
"Context.Query.Reader.unfilter_attr_tiles.sum": 1.67535,
"Context.Query.Reader.unfilter_attr_tiles.avg": 0.00420942,
"Context.Query.Reader.tile_offset_sizes.sum": 0.0020725,
"Context.Query.Reader.tile_offset_sizes.avg": 1.03625e-05,
"Context.Query.Reader.read_tiles.sum": 6.55026,
"Context.Query.Reader.read_tiles.avg": 0.00777941,
"Context.Query.Reader.read_coordinate_tiles.sum": 4.12362,
"Context.Query.Reader.read_coordinate_tiles.avg": 0.0139311,
"Context.Query.Reader.read_attribute_tiles.sum": 2.4297,
"Context.Query.Reader.read_attribute_tiles.avg": 0.00445,
"Context.Query.Reader.read_and_unfilter_coords.sum": 67.82,
"Context.Query.Reader.read_and_unfilter_coords.avg": 0.458243,
"Context.Query.Reader.read_and_unfilter_attributes.sum": 4.46067,
"Context.Query.Reader.read_and_unfilter_attributes.avg": 0.0112077,
"Context.Query.Reader.process_slabs.sum": 12.4013,
"Context.Query.Reader.process_slabs.avg": 0.0311591,
"Context.Query.Reader.preprocess_result_tile_order_compute.sum": 0.0126704,
"Context.Query.Reader.preprocess_result_tile_order_await.sum": 0.0242102,
"Context.Query.Reader.preprocess_result_tile_order_await.avg": 0.000163582,
"Context.Query.Reader.merge_result_cell_slabs.sum": 0.433601,
"Context.Query.Reader.merge_result_cell_slabs.avg": 0.000963558,
"Context.Query.Reader.max_num_cells_to_copy.sum": 0.0007035,
"Context.Query.Reader.max_num_cells_to_copy.avg": 1.56333e-06,
"Context.Query.Reader.load_tile_var_sizes.sum": 0.002053,
"Context.Query.Reader.load_tile_var_sizes.avg": 1.0265e-05,
"Context.Query.Reader.load_tile_offsets.sum": 0.638117,
"Context.Query.Reader.load_tile_offsets.avg": 0.00106353,
"Context.Query.Reader.load_tile_metadata.sum": 0.0013539,
"Context.Query.Reader.load_tile_metadata.avg": 6.7695e-06,
"Context.Query.Reader.load_initial_data.sum": 0.459506,
"Context.Query.Reader.load_initial_data.avg": 0.00229753,
"Context.Query.Reader.dowork.sum": 90.0947,
"Context.Query.Reader.dowork.avg": 0.200211,
"Context.Query.Reader.dedup_tiles_with_timestamps.sum": 0.0095729,
"Context.Query.Reader.dedup_tiles_with_timestamps.avg": 6.46818e-05,
"Context.Query.Reader.dedup_fragments_with_timestamps.sum": 0.121247,
"Context.Query.Reader.dedup_fragments_with_timestamps.avg": 0.000269437,
"Context.Query.Reader.create_result_tiles.sum": 0.458211,
"Context.Query.Reader.create_result_tiles.avg": 0.00101825,
"Context.Query.Reader.copy_fixed_data_tiles.sum": 6.84797,
"Context.Query.Reader.copy_fixed_data_tiles.avg": 0.00430149,
"Context.Query.Reader.compute_tile_bitmaps.sum": 0.992752,
"Context.Query.Reader.compute_tile_bitmaps.avg": 0.00670778,
"Context.Query.Reader.apply_query_condition.sum": 0.0281985,
"Context.Query.Reader.apply_query_condition.avg": 0.00019053
},
"counters": {
"Context.subSubarray.add_range_dim_2": 200,
"Context.subSubarray.add_range_dim_1": 200,
"Context.subSubarray.add_range_dim_0": 200,
"Context.read_unfiltered_byte_num": 5344568,
"Context.read_tile_offsets_size": 2001056,
"Context.read_rtree_size": 3343512,
"Context.VFS.read_ops_num": 3062,
"Context.VFS.read_byte_num": 3378873488,
"Context.Query.Reader.tiles_unfiltered": 249790,
"Context.Query.Reader.tiles_allocated": 249790,
"Context.Query.Reader.result_num": 623074473,
"Context.Query.Reader.read_unfiltered_byte_num": 14953787352,
"Context.Query.Reader.num_tiles_read": 249790,
"Context.Query.Reader.loop_num": 450,
"Context.Query.Reader.internal_loop_num": 450,
"Context.Query.Reader.ignored_tiles": 0,
"Context.Query.Reader.dim_num": 1350,
"Context.Query.Reader.dim_fixed_num": 1350,
"Context.Query.Reader.cell_num": 623074473,
"Context.Query.Reader.attr_num": 450,
"Context.Query.Reader.attr_fixed_num": 450
}
}
]
==== Python Stats ====
py.core_read_query_incomplete_retry_time : 34.896
py.core_read_query_initial_submit_time : 83.7326
py.core_read_query_total_time : 118.775
py.query_retries_count : 250
py.read_query_incomplete_buffer_resize_time : 10.8366
Here are the stats for the second run, completing in ~32 seconds:
TileDB Embedded Version: (2, 28, 1)
TileDB-Py Version: 0.34.2
[
{
"timers": {
"Context.subSubarray.sort_and_merge_ranges.sum": 0.0027584,
"Context.subSubarray.sort_and_merge_ranges.avg": 1.3792e-05,
"Context.subSubarray.read_load_relevant_rtrees.sum": 0.0029139,
"Context.subSubarray.read_load_relevant_rtrees.avg": 7.28475e-06,
"Context.subSubarray.read_compute_simple_tile_overlap.sum": 0.0267101,
"Context.subSubarray.read_compute_simple_tile_overlap.avg": 0.00013355,
"Context.subSubarray.compute_relevant_frags.sum": 0.016316,
"Context.subSubarray.compute_relevant_frags.avg": 8.158e-05,
"Context.Query.Reader.unfilter_coord_tiles.sum": 162.711,
"Context.Query.Reader.unfilter_coord_tiles.avg": 0.183234,
"Context.Query.Reader.unfilter_attr_tiles.sum": 1.22643,
"Context.Query.Reader.unfilter_attr_tiles.avg": 0.00308149,
"Context.Query.Reader.tile_offset_sizes.sum": 0.0014247,
"Context.Query.Reader.tile_offset_sizes.avg": 7.1235e-06,
"Context.Query.Reader.read_tiles.sum": 10.5934,
"Context.Query.Reader.read_tiles.avg": 0.0125813,
"Context.Query.Reader.read_coordinate_tiles.sum": 6.40722,
"Context.Query.Reader.read_coordinate_tiles.avg": 0.021646,
"Context.Query.Reader.read_attribute_tiles.sum": 4.18842,
"Context.Query.Reader.read_attribute_tiles.avg": 0.00767111,
"Context.Query.Reader.read_and_unfilter_coords.sum": 169.307,
"Context.Query.Reader.read_and_unfilter_coords.avg": 1.14397,
"Context.Query.Reader.read_and_unfilter_attributes.sum": 5.8425,
"Context.Query.Reader.read_and_unfilter_attributes.avg": 0.0146797,
"Context.Query.Reader.process_slabs.avg": 0.0354497,
"Context.Query.Reader.preprocess_result_tile_order_compute.sum": 0.0184764,
"Context.Query.Reader.preprocess_result_tile_order_compute.avg": 9.2382e-05,
"Context.Query.Reader.preprocess_result_tile_order_await.sum": 0.0343453,
"Context.Query.Reader.preprocess_result_tile_order_await.avg": 0.000232063,
"Context.Query.Reader.merge_result_cell_slabs.sum": 0.409445,
"Context.Query.Reader.merge_result_cell_slabs.avg": 0.000909879,
"Context.Query.Reader.max_num_cells_to_copy.sum": 0.0006482,
"Context.Query.Reader.max_num_cells_to_copy.avg": 1.44044e-06,
"Context.Query.Reader.load_tile_var_sizes.sum": 0.0005834,
"Context.Query.Reader.load_tile_var_sizes.avg": 2.917e-06,
"Context.Query.Reader.load_tile_offsets.sum": 0.0037809,
"Context.Query.Reader.load_tile_offsets.avg": 6.3015e-06,
"Context.Query.Reader.load_tile_metadata.sum": 0.0007296,
"Context.Query.Reader.load_tile_metadata.avg": 3.648e-06,
"Context.Query.Reader.load_initial_data.sum": 0.0317057,
"Context.Query.Reader.load_initial_data.avg": 0.000158528,
"Context.Query.Reader.dowork.sum": 194.852,
"Context.Query.Reader.dowork.avg": 0.433003,
"Context.Query.Reader.dedup_tiles_with_timestamps.sum": 0.0021229,
"Context.Query.Reader.dedup_tiles_with_timestamps.avg": 1.43439e-05,
"Context.Query.Reader.dedup_fragments_with_timestamps.sum": 0.0090134,
"Context.Query.Reader.dedup_fragments_with_timestamps.avg": 2.00298e-05,
"Context.Query.Reader.create_result_tiles.sum": 0.472864,
"Context.Query.Reader.create_result_tiles.avg": 0.00105081,
"Context.Query.Reader.copy_fixed_data_tiles.sum": 5.80704,
"Context.Query.Reader.copy_fixed_data_tiles.avg": 0.00364764,
"Context.Query.Reader.compute_tile_bitmaps.sum": 1.16422,
"Context.Query.Reader.compute_tile_bitmaps.avg": 0.00786634,
"Context.Query.Reader.apply_query_condition.sum": 0.0114803,
"Context.Query.Reader.apply_query_condition.avg": 7.75696e-05
},
"counters": {
"Context.subSubarray.add_range_dim_2": 200,
"Context.subSubarray.add_range_dim_1": 200,
"Context.subSubarray.add_range_dim_0": 200,
"Context.VFS.read_ops_num": 842,
"Context.VFS.read_byte_num": 3377790867,
"Context.Query.Reader.tiles_unfiltered": 249790,
"Context.Query.Reader.tiles_allocated": 249790,
"Context.Query.Reader.result_num": 623074473,
"Context.Query.Reader.read_unfiltered_byte_num": 14953787352,
"Context.Query.Reader.num_tiles_read": 249790,
"Context.Query.Reader.loop_num": 450,
"Context.Query.Reader.internal_loop_num": 450,
"Context.Query.Reader.ignored_tiles": 0,
"Context.Query.Reader.dim_num": 1350,
"Context.Query.Reader.dim_fixed_num": 1350,
"Context.Query.Reader.cell_num": 623074473,
"Context.Query.Reader.attr_num": 450,
"Context.Query.Reader.attr_fixed_num": 450
}
}
]
==== Python Stats ====
py.core_read_query_incomplete_retry_time : 36.1667
py.core_read_query_initial_submit_time : 183.842
py.core_read_query_total_time : 220.451
py.query_retries_count : 250
py.read_query_incomplete_buffer_resize_time : 11.2947
Here are the stats for the third run, completing in ~42 seconds:
TileDB Embedded Version: (2, 28, 1)
TileDB-Py Version: 0.34.2
[
{
"timers": {
"Context.subSubarray.sort_and_merge_ranges.sum": 0.0024212,
"Context.subSubarray.sort_and_merge_ranges.avg": 1.2106e-05,
"Context.subSubarray.read_load_relevant_rtrees.sum": 0.0026652,
"Context.subSubarray.read_load_relevant_rtrees.avg": 6.663e-06,
"Context.subSubarray.read_compute_simple_tile_overlap.sum": 0.0278905,
"Context.subSubarray.read_compute_simple_tile_overlap.avg": 0.000139452,
"Context.subSubarray.compute_relevant_frags.sum": 0.0129456,
"Context.subSubarray.compute_relevant_frags.avg": 6.4728e-05,
"Context.Query.Reader.unfilter_coord_tiles.sum": 288.984,
"Context.Query.Reader.unfilter_coord_tiles.avg": 0.325433,
"Context.Query.Reader.unfilter_attr_tiles.sum": 1.59908,
"Context.Query.Reader.unfilter_attr_tiles.avg": 0.00401779,
"Context.Query.Reader.tile_offset_sizes.sum": 0.0014742,
"Context.Query.Reader.tile_offset_sizes.avg": 7.371e-06,
"Context.Query.Reader.read_tiles.sum": 17.0711,
"Context.Query.Reader.read_tiles.avg": 0.0202744,
"Context.Query.Reader.read_coordinate_tiles.sum": 11.9749,
"Context.Query.Reader.read_coordinate_tiles.avg": 0.0404558,
"Context.Query.Reader.read_attribute_tiles.sum": 5.09821,
"Context.Query.Reader.read_attribute_tiles.avg": 0.00933738,
"Context.Query.Reader.read_and_unfilter_coords.sum": 301.264,
"Context.Query.Reader.read_and_unfilter_coords.avg": 2.03557,
"Context.Query.Reader.read_and_unfilter_attributes.sum": 7.14813,
"Context.Query.Reader.read_and_unfilter_attributes.avg": 0.0179601,
"Context.Query.Reader.process_slabs.avg": 0.047321,
"Context.Query.Reader.preprocess_result_tile_order_compute.sum": 0.0621346,
"Context.Query.Reader.preprocess_result_tile_order_compute.avg": 0.000310673,
"Context.Query.Reader.preprocess_result_tile_order_await.sum": 0.0595024,
"Context.Query.Reader.preprocess_result_tile_order_await.avg": 0.000402043,
"Context.Query.Reader.merge_result_cell_slabs.sum": 0.433102,
"Context.Query.Reader.merge_result_cell_slabs.avg": 0.000962448,
"Context.Query.Reader.max_num_cells_to_copy.sum": 0.0006613,
"Context.Query.Reader.max_num_cells_to_copy.avg": 1.46956e-06,
"Context.Query.Reader.load_tile_var_sizes.sum": 0.000643,
"Context.Query.Reader.load_tile_var_sizes.avg": 3.215e-06,
"Context.Query.Reader.load_tile_offsets.sum": 0.0903459,
"Context.Query.Reader.load_tile_offsets.avg": 0.000150576,
"Context.Query.Reader.load_tile_metadata.sum": 0.0007987,
"Context.Query.Reader.load_tile_metadata.avg": 3.9935e-06,
"Context.Query.Reader.load_initial_data.sum": 0.0325859,
"Context.Query.Reader.load_initial_data.avg": 0.000162929,
"Context.Query.Reader.dowork.sum": 346.123,
"Context.Query.Reader.dowork.avg": 0.769163,
"Context.Query.Reader.dedup_tiles_with_timestamps.sum": 0.0022991,
"Context.Query.Reader.dedup_tiles_with_timestamps.avg": 1.55345e-05,
"Context.Query.Reader.dedup_fragments_with_timestamps.sum": 0.0074518,
"Context.Query.Reader.dedup_fragments_with_timestamps.avg": 1.65596e-05,
"Context.Query.Reader.create_result_tiles.sum": 0.476647,
"Context.Query.Reader.create_result_tiles.avg": 0.00105922,
"Context.Query.Reader.copy_fixed_data_tiles.sum": 6.71934,
"Context.Query.Reader.copy_fixed_data_tiles.avg": 0.00422069,
"Context.Query.Reader.compute_tile_bitmaps.sum": 2.18789,
"Context.Query.Reader.compute_tile_bitmaps.avg": 0.0147831,
"Context.Query.Reader.apply_query_condition.sum": 0.0060774,
"Context.Query.Reader.apply_query_condition.avg": 4.10635e-05
},
"counters": {
"Context.subSubarray.add_range_dim_2": 200,
"Context.subSubarray.add_range_dim_1": 200,
"Context.subSubarray.add_range_dim_0": 200,
"Context.VFS.read_ops_num": 842,
"Context.VFS.read_byte_num": 3377790867,
"Context.Query.Reader.tiles_unfiltered": 249790,
"Context.Query.Reader.tiles_allocated": 249790,
"Context.Query.Reader.result_num": 623074473,
"Context.Query.Reader.read_unfiltered_byte_num": 14953787352,
"Context.Query.Reader.num_tiles_read": 249790,
"Context.Query.Reader.loop_num": 450,
"Context.Query.Reader.internal_loop_num": 450,
"Context.Query.Reader.ignored_tiles": 0,
"Context.Query.Reader.dim_num": 1350,
"Context.Query.Reader.dim_fixed_num": 1350,
"Context.Query.Reader.cell_num": 623074473,
"Context.Query.Reader.attr_num": 450,
"Context.Query.Reader.attr_fixed_num": 450
}
}
]
==== Python Stats ====
py.core_read_query_incomplete_retry_time : 47.6455
py.core_read_query_initial_submit_time : 323.716
py.core_read_query_total_time : 372.57
py.query_retries_count : 250
py.read_query_incomplete_buffer_resize_time : 12.3532
Subsequent runtimes continue to increase in a similar fashion, though possibly plateauing around 60s: [47s, 55s, 57s, 59s, …].