[Bug/Question] Experiment.obs.count has long wall clock time - is this normal?

[mdylan2]

Describe the bug
Getting the count of obs from an experiment takes a while for large datasets (~17 seconds here). Is this normal?

I ran the profiling script reported here #1181 on a test script (attached below).

with soma.Experiment.open(<URI>) as exp:
    res = exp.obs.count

Output of profiler:

{
  "command": "python test_obs_count.py",
  "timestamp": 1714999582.266067,
  "stdout": "",
  "stderr": "Command being timed: \"python test_obs_count.py\"\nUser time (seconds): 22.08\nSystem time (seconds): 1.94\nPercent of CPU this job got: 141%\nElapsed (wall clock) time (seconds): 16.96\nAverage shared text size (kbytes): 0\nAverage unshared data size (kbytes): 0\nAverage stack size (kbytes): 0\nAverage total size (kbytes): 0\nMaximum resident set size (kbytes): 1906388\nAverage resident set size (kbytes): 0\nMajor (requiring I/O) page faults: 0\nMinor (reclaiming a frame) page faults: 489891\nVoluntary context switches: 3020\nInvoluntary context switches: 164481\nSwaps: 0\nFile system inputs: 0\nFile system outputs: 0\nSocket messages sent: 0\nSocket messages received: 0\nSignals delivered: 0\nPage size (bytes): 4096\nExit status: 0\n",
  "tiledb_stats": {},
  "somacore_version": "1.0.10",
  "tiledbsoma_version": "1.10.1",
  "host_context": {
    "uname": [
      "Linux",
      "ip-172-31-24-57",
      "6.5.0-1018-aws",
      "#18~22.04.1-Ubuntu SMP Fri Apr  5 17:44:33 UTC 2024",
      "x86_64"
    ],
    "total_virtual_mem_bytes": 33644634112,
    "total_physical_mem_bytes": 33644634112,
    "swap_mem_total_bytes": 0,
    "swap_mem_used_bytes": 0,
    "swap_mem_free_bytes": 0,
    "swap_mem_pct_bytes": 0,
    "swap_mem_sin_bytes": 0,
    "swap_mem_sout_bytes": 0,
    "cpu_count": 8,
    "python_version": [
      3,
      10,
      12,
      "final",
      0
    ],
    "get_git_revision_hash": "e52092ec96eeaf1b7633476da925f89e1b74cadb"
  },
  "user_time_sec": "22.08",
  "system_time_sec": "1.94",
  "pct_of_cpu": 141,
  "elapsed_time_sec": "16.96",
  "avg_shared_text_sz_kb": 0,
  "avg_unshared_text_sz_kb": 0,
  "avg_stack_sz_kb": 0,
  "avg_total_sz_kb": 0,
  "max_res_set_sz_kb": 1906388,
  "avg_res_set_sz_kb": 0,
  "major_page_faults": 0,
  "minor_page_faults": 489891,
  "voluntary_context_switches": 3020,
  "involuntary_context_switches": 164481,
  "swaps": 0,
  "file_system_inputs": 0,
  "file_system_outputs": 0,
  "socket_messages_sent": 0,
  "socket_messages_received": 0,
  "signals_delivered": 0,
  "page_size_bytes": 4096,
  "exit_status": 0,
  "custom_out": [
    null,
    null
  ],
  "command_key": "4e379762d2a949439b7ed5b3da01dd05"
}

[johnkerl]

Hi @mdylan2 !

Can you please share:

• Your URI
• The output from the count query
• If this is a local-disk query or remote (S3, TileDB Cloud)
• If non-local:
  • What & where is the client -- laptop, EC2 instance & if so in what region
  • What region is the data stored in?

[johnkerl]

Also: are you using a soma.init_buffer_bytes setting in your config, and if so, what is it set to?

[mdylan2]

This is a local disk query.

The output is 24,448,693. Not setting soma.init_buffer_bytes so assuming it's default here

[johnkerl]

@mdylan2 can you share the ls -l __fragments output from the local-disk obs subdirectory?

[mdylan2]

total 8
drwxrwxr-x 2 ubuntu ubuntu 4096 May  2 16:50 __1702890011299_1702890011299_a24b5abc82294634aecf6f89989193e0_20
drwxrwxr-x 2 ubuntu ubuntu 4096 May  2 16:50 __1706552148934_1706552148934_fec8c761647b4a4989b26afa2b092c3d_20

[johnkerl]

Thanks @mdylan2 ! Can I also please have you also wrap this as follows and send the output? (Preferably as a gist)

tiledbsoma.pytiledbsoma.tiledbsoma_stats_reset()
tiledbsoma.pytiledbsoma.tiledbsoma_stats_enable()

with soma.Experiment.open(<URI>) as exp:
    res = exp.obs.count

tiledbsoma.pytiledbsoma.tiledbsoma_stats_dump()

[mdylan2]

https://gist.github.com/mdylan2/0b320ab9ca1fc4a4d7ea61b009397d84

[johnkerl]

@mdylan2 one more thing please -- output from

with tiledb.open(<URI>) as A:
    print(A.schema)

if you're willing to share this

(Feel free to leave off attr names for anything you consider sensitive)

[mdylan2]

Included in the gist

[johnkerl]

[sc-46760]

[johnkerl]

@mdylan2 are the dataset_idx, cell_type_idx, and sample_idx permutations of the unique integers 0.. 24,448,692? Or lower cardinality? BTW, happy to hop on a call to look into this with you. :)

[johnkerl]

@mdylan2 one more ask, can you please also gist the output of

tiledbsoma.pytiledbsoma.config_logging('debug')

with soma.Experiment.open(<URI>) as exp:
    res = exp.obs.count

?

[johnkerl]

(Info from Dylan is updated on the ☝️ gist)

[johnkerl]

@mdylan2:

Thanks for the detailed gist! Using this, I've found:

• We are indeed falling into the nnz_slow case here:
  • https://github.com/single-cell-data/TileDB-SOMA/blob/1.10.1/libtiledbsoma/src/soma/soma_array.cc#L391
  • https://github.com/single-cell-data/TileDB-SOMA/blob/1.10.1/libtiledbsoma/src/soma/soma_array.cc#L405
  • https://github.com/single-cell-data/TileDB-SOMA/blob/1.10.1/libtiledbsoma/src/soma/soma_array.cc#L417
• Your extra index dims (cell_type_id et al.) are not at issue here -- I was able to get a repro with and without having extra index dims
• I had thought that perhaps we were overfetching column attributes but the third of three code links above suggests otherwise
• I varied soma.init_buffer_bytes but the effect here was small (as expected for local-disk operations where latency is low)

For the moment, two workarounds:

• Consolidating your two fragments of obs into one (array-fragment consolidation) will resolve this
• A workaround: 1+exp.obs.non_empty_domain()[0][1]. Rationale:
  • SOMA does not assume all soma_joinid values are contiguous starting from zero
  • But in practice they usually are -- the above will be correct, and quicker than exp.obs.count.

We'll brainstorm a couple ideas to get to doing the right thing more often here.

[johnkerl]

Hi @mdylan2 -- as we discussed off GitHub:

• This will be resolved by [python/r/c++] Revisit shape for sparse arrays #2407
• Workaround meanwhile is 1 + exp.obs.non_empty_domain()[0][1]

Thanks for discussing this with us! :)