Add optional logging for timing of VFS operations. (#5278)

[SC-53753](https://app.shortcut.com/tiledb-inc/story/53753/add-optional-logging-for-timing-of-vfs-operations) This PR enables logging of the durations of individual VFS operations. It is enabled by setting `vfs.log_operations` to `true` and `config.logging_level` to `5`. <details> <summary>Example logs from <code>quickstart_dense_cpp</code></summary> ``` [2024-09-04 18:03:19.233] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array started at 2024-09-04 15:03:19.2327924 and lasted 0.0278ms [2024-09-04 18:03:19.247] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__schema started at 2024-09-04 15:03:19.2470214 and lasted 0.0262ms [2024-09-04 18:03:19.247] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_file on mem://quickstart_dense_array/__array_schema.tdb started at 2024-09-04 15:03:19.2471031 and lasted 0.0236ms [2024-09-04 18:03:19.247] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array started at 2024-09-04 15:03:19.2472331 and lasted 0.0109ms [2024-09-04 18:03:19.247] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__schema started at 2024-09-04 15:03:19.2472907 and lasted 0.0142ms [2024-09-04 18:03:19.247] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__schema/__enumerations started at 2024-09-04 15:03:19.2473393 and lasted 0.0133ms [2024-09-04 18:03:19.247] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__commits started at 2024-09-04 15:03:19.2473883 and lasted 0.0107ms [2024-09-04 18:03:19.247] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__fragments started at 2024-09-04 15:03:19.2474433 and lasted 0.0117ms [2024-09-04 18:03:19.247] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__meta started at 2024-09-04 15:03:19.2474884 and lasted 0.0111ms [2024-09-04 18:03:19.247] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__fragment_meta started at 2024-09-04 15:03:19.2475310 and lasted 0.0115ms [2024-09-04 18:03:19.247] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__labels started at 2024-09-04 15:03:19.2475804 and lasted 0.0148ms [2024-09-04 18:03:19.248] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_file on mem://quickstart_dense_array/__schema/__1725462199247_1725462199247_5d57a5625a3486effecaf9fde06ae596 started at 2024-09-04 15:03:19.2484084 and lasted 0.0255ms [2024-09-04 18:03:19.248] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__schema started at 2024-09-04 15:03:19.2484690 and lasted 0.0957ms [2024-09-04 18:03:19.252] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__schema/__1725462199247_1725462199247_5d57a5625a3486effecaf9fde06ae596 started at 2024-09-04 15:03:19.2521478 and lasted 0.0574ms [2024-09-04 18:03:19.252] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__schema/__1725462199247_1725462199247_5d57a5625a3486effecaf9fde06ae596 started at 2024-09-04 15:03:19.2522370 and lasted 0.0221ms [2024-09-04 18:03:19.252] [Process: 26572] [trace] [1725462199092301500-Context: 1] close_file on mem://quickstart_dense_array/__schema/__1725462199247_1725462199247_5d57a5625a3486effecaf9fde06ae596 started at 2024-09-04 15:03:19.2524091 and lasted 0.0039ms [2024-09-04 18:03:19.252] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__schema/__enumerations started at 2024-09-04 15:03:19.2524408 and lasted 0.0189ms [2024-09-04 18:03:19.254] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__schema started at 2024-09-04 15:03:19.2541738 and lasted 0.0223ms [2024-09-04 18:03:19.254] [Process: 26572] [trace] [1725462199092301500-Context: 1] ls on mem://quickstart_dense_array/__schema started at 2024-09-04 15:03:19.2541682 and lasted 0.1173ms [2024-09-04 18:03:19.254] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_file on mem://quickstart_dense_array/__array_schema.tdb started at 2024-09-04 15:03:19.2543741 and lasted 0.0154ms [2024-09-04 18:03:19.254] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__schema/__1725462199247_1725462199247_5d57a5625a3486effecaf9fde06ae596 started at 2024-09-04 15:03:19.2545127 and lasted 0.0234ms [2024-09-04 18:03:19.254] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__schema/__1725462199247_1725462199247_5d57a5625a3486effecaf9fde06ae596 started at 2024-09-04 15:03:19.2545725 and lasted 0.0188ms [2024-09-04 18:03:19.254] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__schema/__1725462199247_1725462199247_5d57a5625a3486effecaf9fde06ae596 started at 2024-09-04 15:03:19.2547623 and lasted 0.0227ms [2024-09-04 18:03:19.265] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__fragments started at 2024-09-04 15:03:19.2657001 and lasted 0.0213ms [2024-09-04 18:03:19.265] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22 started at 2024-09-04 15:03:19.2657613 and lasted 0.0184ms [2024-09-04 18:03:19.265] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__commits started at 2024-09-04 15:03:19.2658344 and lasted 0.0119ms [2024-09-04 18:03:19.271] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/a0.tdb started at 2024-09-04 15:03:19.2714551 and lasted 0.057ms [2024-09-04 18:03:19.271] [Process: 26572] [trace] [1725462199092301500-Context: 1] close_file on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/a0.tdb started at 2024-09-04 15:03:19.2715744 and lasted 0.0031ms [2024-09-04 18:03:19.272] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2721565 and lasted 0.0574ms [2024-09-04 18:03:19.272] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2722498 and lasted 0.025ms [2024-09-04 18:03:19.272] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2725407 and lasted 0.0309ms [2024-09-04 18:03:19.272] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2725945 and lasted 0.0258ms [2024-09-04 18:03:19.272] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2728920 and lasted 0.032ms [2024-09-04 18:03:19.272] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2729496 and lasted 0.0251ms [2024-09-04 18:03:19.273] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2732292 and lasted 0.039ms [2024-09-04 18:03:19.273] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2732936 and lasted 0.0253ms [2024-09-04 18:03:19.273] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2735656 and lasted 0.0287ms [2024-09-04 18:03:19.273] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2736178 and lasted 0.0264ms [2024-09-04 18:03:19.273] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2738945 and lasted 0.0293ms [2024-09-04 18:03:19.273] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2739483 and lasted 0.0254ms [2024-09-04 18:03:19.274] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2742013 and lasted 0.0287ms [2024-09-04 18:03:19.274] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2742532 and lasted 0.0253ms [2024-09-04 18:03:19.274] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2745811 and lasted 0.0388ms [2024-09-04 18:03:19.274] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2746552 and lasted 0.0271ms [2024-09-04 18:03:19.275] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2750014 and lasted 0.0486ms [2024-09-04 18:03:19.275] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2750870 and lasted 0.028ms [2024-09-04 18:03:19.275] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2754571 and lasted 0.0354ms [2024-09-04 18:03:19.275] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2755250 and lasted 0.0469ms [2024-09-04 18:03:19.276] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2759875 and lasted 0.0387ms [2024-09-04 18:03:19.276] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2760622 and lasted 0.0503ms [2024-09-04 18:03:19.276] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2764565 and lasted 0.038ms [2024-09-04 18:03:19.276] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2765296 and lasted 0.0271ms [2024-09-04 18:03:19.276] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2769152 and lasted 0.0558ms [2024-09-04 18:03:19.277] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2770055 and lasted 0.0278ms [2024-09-04 18:03:19.277] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2772968 and lasted 0.0315ms [2024-09-04 18:03:19.277] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2773532 and lasted 0.0262ms [2024-09-04 18:03:19.277] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2777569 and lasted 0.0603ms [2024-09-04 18:03:19.277] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2778592 and lasted 0.0368ms [2024-09-04 18:03:19.278] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2782736 and lasted 0.0497ms [2024-09-04 18:03:19.278] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2783640 and lasted 0.0276ms [2024-09-04 18:03:19.278] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2789022 and lasted 0.0379ms [2024-09-04 18:03:19.279] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2789788 and lasted 0.0259ms [2024-09-04 18:03:19.279] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2793126 and lasted 0.0321ms [2024-09-04 18:03:19.279] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2793719 and lasted 0.025ms [2024-09-04 18:03:19.279] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2797235 and lasted 0.0354ms [2024-09-04 18:03:19.279] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2798230 and lasted 0.0402ms [2024-09-04 18:03:19.280] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2802497 and lasted 0.0382ms [2024-09-04 18:03:19.280] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2803212 and lasted 0.0271ms [2024-09-04 18:03:19.280] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2806757 and lasted 0.0368ms [2024-09-04 18:03:19.280] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2807456 and lasted 0.0572ms [2024-09-04 18:03:19.281] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2811580 and lasted 0.036ms [2024-09-04 18:03:19.281] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2812250 and lasted 0.0682ms [2024-09-04 18:03:19.281] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2816956 and lasted 0.0529ms [2024-09-04 18:03:19.281] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2817883 and lasted 0.0275ms [2024-09-04 18:03:19.282] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2821691 and lasted 0.0471ms [2024-09-04 18:03:19.282] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2822465 and lasted 0.0278ms [2024-09-04 18:03:19.282] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2826874 and lasted 0.0378ms [2024-09-04 18:03:19.282] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2827603 and lasted 0.0255ms [2024-09-04 18:03:19.283] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2830792 and lasted 0.0502ms [2024-09-04 18:03:19.283] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2831701 and lasted 0.034ms [2024-09-04 18:03:19.283] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2835186 and lasted 0.0351ms [2024-09-04 18:03:19.283] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2835960 and lasted 0.0274ms [2024-09-04 18:03:19.284] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2839807 and lasted 0.0364ms [2024-09-04 18:03:19.284] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2840479 and lasted 0.0452ms [2024-09-04 18:03:19.284] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2845042 and lasted 0.0452ms [2024-09-04 18:03:19.284] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2845845 and lasted 0.0581ms [2024-09-04 18:03:19.285] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2851566 and lasted 0.0379ms [2024-09-04 18:03:19.285] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2852853 and lasted 0.029ms [2024-09-04 18:03:19.285] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2856731 and lasted 0.0624ms [2024-09-04 18:03:19.285] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2858133 and lasted 0.0372ms [2024-09-04 18:03:19.286] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2862113 and lasted 0.0379ms [2024-09-04 18:03:19.286] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2862828 and lasted 0.0275ms [2024-09-04 18:03:19.286] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2866521 and lasted 0.0373ms [2024-09-04 18:03:19.286] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2867228 and lasted 0.0273ms [2024-09-04 18:03:19.287] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2871049 and lasted 0.0304ms [2024-09-04 18:03:19.287] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2871574 and lasted 0.0434ms [2024-09-04 18:03:19.287] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2875609 and lasted 0.0498ms [2024-09-04 18:03:19.287] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2876429 and lasted 0.0267ms [2024-09-04 18:03:19.287] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2877533 and lasted 0.1659ms [2024-09-04 18:03:19.287] [Process: 26572] [trace] [1725462199092301500-Context: 1] write on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2879538 and lasted 0.0288ms [2024-09-04 18:03:19.288] [Process: 26572] [trace] [1725462199092301500-Context: 1] close_file on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2880073 and lasted 0.0036ms [2024-09-04 18:03:19.288] [Process: 26572] [trace] [1725462199092301500-Context: 1] touch on mem://quickstart_dense_array/__commits/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22.wrt started at 2024-09-04 15:03:19.2880999 and lasted 0.0271ms [2024-09-04 18:03:19.289] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__fragment_meta started at 2024-09-04 15:03:19.2895800 and lasted 0.0453ms [2024-09-04 18:03:19.289] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__schema started at 2024-09-04 15:03:19.2896226 and lasted 0.023ms [2024-09-04 18:03:19.289] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__commits started at 2024-09-04 15:03:19.2895724 and lasted 0.072ms [2024-09-04 18:03:19.289] [Process: 26572] [trace] [1725462199092301500-Context: 1] ls on mem://quickstart_dense_array/__fragment_meta started at 2024-09-04 15:03:19.2895684 and lasted 0.1742ms [2024-09-04 18:03:19.289] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/ started at 2024-09-04 15:03:19.2897379 and lasted 0.0647ms [2024-09-04 18:03:19.289] [Process: 26572] [trace] [1725462199092301500-Context: 1] ls on mem://quickstart_dense_array/__schema started at 2024-09-04 15:03:19.2896152 and lasted 0.2118ms [2024-09-04 18:03:19.289] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_dir on mem://quickstart_dense_array/__meta started at 2024-09-04 15:03:19.2897556 and lasted 0.0849ms [2024-09-04 18:03:19.289] [Process: 26572] [trace] [1725462199092301500-Context: 1] ls on mem://quickstart_dense_array/__commits started at 2024-09-04 15:03:19.2895624 and lasted 0.2549ms [2024-09-04 18:03:19.290] [Process: 26572] [trace] [1725462199092301500-Context: 1] ls on mem://quickstart_dense_array/__meta started at 2024-09-04 15:03:19.2897221 and lasted 0.3231ms [2024-09-04 18:03:19.290] [Process: 26572] [trace] [1725462199092301500-Context: 1] ls on mem://quickstart_dense_array/ started at 2024-09-04 15:03:19.2897067 and lasted 0.4034ms [2024-09-04 18:03:19.290] [Process: 26572] [trace] [1725462199092301500-Context: 1] is_file on mem://quickstart_dense_array/__labels/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2904285 and lasted 0.0347ms [2024-09-04 18:03:19.290] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__schema/__1725462199247_1725462199247_5d57a5625a3486effecaf9fde06ae596 started at 2024-09-04 15:03:19.2906847 and lasted 0.0485ms [2024-09-04 18:03:19.290] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__schema/__1725462199247_1725462199247_5d57a5625a3486effecaf9fde06ae596 started at 2024-09-04 15:03:19.2908066 and lasted 0.0272ms [2024-09-04 18:03:19.291] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__schema/__1725462199247_1725462199247_5d57a5625a3486effecaf9fde06ae596 started at 2024-09-04 15:03:19.2910065 and lasted 0.0289ms [2024-09-04 18:03:19.292] [Process: 26572] [trace] [1725462199092301500-Context: 1] file_size on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2921234 and lasted 0.0419ms [2024-09-04 18:03:19.292] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2922777 and lasted 0.0262ms [2024-09-04 18:03:19.292] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2923515 and lasted 0.0243ms [2024-09-04 18:03:19.298] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2981683 and lasted 0.0367ms [2024-09-04 18:03:19.298] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2982677 and lasted 0.0257ms [2024-09-04 18:03:19.298] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.2983348 and lasted 0.0239ms [2024-09-04 18:03:19.303] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.3033408 and lasted 0.0315ms [2024-09-04 18:03:19.303] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.3034211 and lasted 0.0249ms [2024-09-04 18:03:19.303] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/__fragment_metadata.tdb started at 2024-09-04 15:03:19.3034785 and lasted 0.0234ms [2024-09-04 18:03:19.306] [Process: 26572] [trace] [1725462199092301500-Context: 1] read on mem://quickstart_dense_array/__fragments/__1725462199264_1725462199264_0a6afc2cfd9ac5fb8f145f70c46844c7_22/a0.tdb started at 2024-09-04 15:03:19.3068123 and lasted 0.0336ms ``` </details> --- TYPE: CONFIG DESC: Add `vfs.log_operations` config option to log in trace level all VFS operations and their duration.
TileDB-Inc · Sep 10, 2024 · 956fecc · 956fecc
1 parent b5bd266
commit 956fecc
Show file tree

Hide file tree

Showing 17 changed files with 307 additions and 13 deletions.
diff --git a/test/src/unit-capi-config.cc b/test/src/unit-capi-config.cc
@@ -316,6 +316,7 @@ void check_save_to_file() {
   ss << "vfs.gcs.multi_part_size 5242880\n";
   ss << "vfs.gcs.request_timeout_ms 3000\n";
   ss << "vfs.gcs.use_multi_part_upload true\n";
+  ss << "vfs.log_operations false\n";
   ss << "vfs.max_batch_size 104857600\n";
   ss << "vfs.min_batch_gap 512000\n";
   ss << "vfs.min_batch_size 20971520\n";
@@ -695,6 +696,7 @@ TEST_CASE("C API: Test config iter", "[capi][config]") {
   all_param_values["vfs.min_parallel_size"] = "10485760";
   all_param_values["vfs.read_ahead_size"] = "102400";
   all_param_values["vfs.read_ahead_cache_size"] = "10485760";
+  all_param_values["vfs.log_operations"] = "false";
   all_param_values["vfs.read_logging_mode"] = "";
   all_param_values["vfs.gcs.endpoint"] = "";
   all_param_values["vfs.gcs.project_id"] = "";
@@ -769,6 +771,7 @@ TEST_CASE("C API: Test config iter", "[capi][config]") {
   vfs_param_values["min_parallel_size"] = "10485760";
   vfs_param_values["read_ahead_size"] = "102400";
   vfs_param_values["read_ahead_cache_size"] = "10485760";
+  vfs_param_values["log_operations"] = "false";
   vfs_param_values["read_logging_mode"] = "";
   vfs_param_values["gcs.endpoint"] = "";
   vfs_param_values["gcs.project_id"] = "";

diff --git a/test/src/unit-cppapi-config.cc b/test/src/unit-cppapi-config.cc
@@ -75,7 +75,7 @@ TEST_CASE("C++ API: Config iterator", "[cppapi][config]") {
     names.push_back(it->first);
   }
   // Check number of VFS params in default config object.
-  CHECK(names.size() == 69);
+  CHECK(names.size() == 70);
 }
 
 TEST_CASE("C++ API: Config Environment Variables", "[cppapi][config]") {

diff --git a/test/src/unit-vfs.cc b/test/src/unit-vfs.cc
@@ -138,7 +138,8 @@ std::string local_path() {
 TEST_CASE("VFS: Test long local paths", "[vfs]") {
   ThreadPool compute_tp(4);
   ThreadPool io_tp(4);
-  VFS vfs{&g_helper_stats, &compute_tp, &io_tp, Config{}};
+  VFS vfs{
+      &g_helper_stats, g_helper_logger().get(), &compute_tp, &io_tp, Config{}};
 
   SECTION("- Deep hierarchy") {
     // Create a nested path with a long total length
@@ -209,7 +210,8 @@ TEMPLATE_LIST_TEST_CASE(
   ThreadPool compute_tp(4);
   ThreadPool io_tp(4);
   Config config = set_config_params();
-  VFS vfs{&g_helper_stats, &compute_tp, &io_tp, config};
+  VFS vfs{
+      &g_helper_stats, g_helper_logger().get(), &compute_tp, &io_tp, config};
 
   URI path = fs.temp_dir_.add_trailing_slash();
 
@@ -443,7 +445,8 @@ TEMPLATE_LIST_TEST_CASE("VFS: File I/O", "[vfs][uri][file_io]", AllBackends) {
   ThreadPool compute_tp(4);
   ThreadPool io_tp(4);
   Config config = set_config_params(disable_multipart, max_parallel_ops);
-  VFS vfs{&g_helper_stats, &compute_tp, &io_tp, config};
+  VFS vfs{
+      &g_helper_stats, g_helper_logger().get(), &compute_tp, &io_tp, config};
 
   // Getting file_size on a nonexistent blob shouldn't crash on Azure
   uint64_t nbytes = 0;
@@ -562,7 +565,8 @@ TEST_CASE("VFS: Test end-to-end", "[.vfs-e2e]") {
   // Will be configured from environment variables.
   Config config;
 
-  VFS vfs{&g_helper_stats, &compute_tp, &io_tp, config};
+  VFS vfs{
+      &g_helper_stats, g_helper_logger().get(), &compute_tp, &io_tp, config};
   REQUIRE(vfs.supports_uri_scheme(test_file));
 
   uint64_t nbytes = 0;
@@ -573,7 +577,8 @@ TEST_CASE("VFS: Test end-to-end", "[.vfs-e2e]") {
 TEST_CASE("VFS: test ls_with_sizes", "[vfs][ls-with-sizes]") {
   ThreadPool compute_tp(4);
   ThreadPool io_tp(4);
-  VFS vfs_ls{&g_helper_stats, &compute_tp, &io_tp, Config{}};
+  VFS vfs_ls{
+      &g_helper_stats, g_helper_logger().get(), &compute_tp, &io_tp, Config{}};
 
   std::string path = local_path();
   std::string dir = path + "ls_dir";
@@ -709,7 +714,7 @@ TEST_CASE(
 
 TEST_CASE("VFS: Test remove_dir_if_empty", "[vfs][remove-dir-if-empty]") {
   ThreadPool tp(1);
-  VFS vfs{&g_helper_stats, &tp, &tp, Config{}};
+  VFS vfs{&g_helper_stats, g_helper_logger().get(), &tp, &tp, Config{}};
 
   std::string path = local_path();
   std::string dir = path + "remove_dir_if_empty/";

diff --git a/test/support/src/vfs_helpers.cc b/test/support/src/vfs_helpers.cc
@@ -443,7 +443,12 @@ VFSTestBase::VFSTestBase(
     : test_tree_(test_tree)
     , compute_(4)
     , io_(4)
-    , vfs_(&tiledb::test::g_helper_stats, &io_, &compute_, create_test_config())
+    , vfs_(
+          &tiledb::test::g_helper_stats,
+          tiledb::test::g_helper_logger().get(),
+          &io_,
+          &compute_,
+          create_test_config())
     , prefix_(prefix)
     , temp_dir_(tiledb::test::test_dir(prefix_))
     , is_supported_(vfs_.supports_uri_scheme(temp_dir_)) {

diff --git a/tiledb/api/c_api/config/config_api_external.h b/tiledb/api/c_api/config/config_api_external.h
@@ -372,6 +372,10 @@ TILEDB_EXPORT void tiledb_config_free(tiledb_config_t** config) TILEDB_NOEXCEPT;
  * - `vfs.read_ahead_cache_size` <br>
  *    The the total maximum size of the read-ahead cache, which is an LRU. <br>
  *    **Default**: 10485760
+ * -  `vfs.log_operations` <br>
+ *    Enables logging all VFS operations in trace mode.
+ *    <br>
+ *    **Default**: false
  * - `vfs.min_parallel_size` <br>
  *    The minimum number of bytes in a parallel VFS operation
  *    (except parallel S3 writes, which are controlled by

diff --git a/tiledb/api/c_api/vfs/vfs_api.cc b/tiledb/api/c_api/vfs/vfs_api.cc
@@ -58,14 +58,16 @@ capi_return_t tiledb_vfs_alloc(
 
   // Create VFS object
   auto& resources{ctx->resources()};
+  auto logger{resources.logger().get()};
   auto& stats{resources.stats()};
   auto& compute_tp{resources.compute_tp()};
   auto& io_tp{resources.io_tp()};
   auto& ctx_config{resources.config()};
   if (config) {
     ctx_config.inherit((config->config()));
   }
-  *vfs = tiledb_vfs_t::make_handle(&stats, &compute_tp, &io_tp, ctx_config);
+  *vfs = tiledb_vfs_t::make_handle(
+      &stats, logger, &compute_tp, &io_tp, ctx_config);
 
   return TILEDB_OK;
 }

diff --git a/tiledb/api/c_api/vfs/vfs_api_internal.h b/tiledb/api/c_api/vfs/vfs_api_internal.h
@@ -56,10 +56,11 @@ struct tiledb_vfs_handle_t
  public:
   explicit tiledb_vfs_handle_t(
       tiledb::sm::stats::Stats* parent_stats,
+      Logger* logger,
       ThreadPool* compute_tp,
       ThreadPool* io_tp,
       const tiledb::sm::Config& config)
-      : vfs_{parent_stats, compute_tp, io_tp, config} {
+      : vfs_{parent_stats, logger, compute_tp, io_tp, config} {
   }
 
   vfs_type* vfs() {

diff --git a/tiledb/common/log_duration_instrument.h b/tiledb/common/log_duration_instrument.h
@@ -0,0 +1,126 @@
+/**
+ * @file   log_duration_instrument.h
+ *
+ * @section LICENSE
+ *
+ * The MIT License
+ *
+ * @copyright Copyright (c) 2024 TileDB, Inc.
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a copy
+ * of this software and associated documentation files (the "Software"), to deal
+ * in the Software without restriction, including without limitation the rights
+ * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+ * copies of the Software, and to permit persons to whom the Software is
+ * furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be included in
+ * all copies or substantial portions of the Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+ * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+ * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+ * THE SOFTWARE.
+ *
+ * @section DESCRIPTION
+ *
+ * This file defines class `LogDurationInstrument`.
+ */
+
+#ifndef TILEDB_LOG_DURATION_INSTRUMENT_H
+#define TILEDB_LOG_DURATION_INSTRUMENT_H
+
+#include <spdlog/fmt/fmt.h>
+
+#include <spdlog/fmt/chrono.h>
+
+#include "tiledb/common/logger.h"
+
+namespace tiledb::common {
+
+/**
+ * Emits log messages on the start and end of a scope, noting the scope's
+ * duration.
+ */
+class LogDurationInstrument {
+ public:
+  LogDurationInstrument() = delete;
+
+  DISABLE_COPY_AND_COPY_ASSIGN(LogDurationInstrument);
+  DISABLE_MOVE_AND_MOVE_ASSIGN(LogDurationInstrument);
+
+  /**
+   * Constructor.
+   *
+   * @param logger The logger to use.
+   * @param fmt The format string to describe the operation.
+   * @param args Arguments for the format string.
+   */
+  template <typename... Args>
+  LogDurationInstrument(
+      Logger* logger,
+      // Ideally this would be a fmt::format_string<Args...> but it fails with
+      // weird constexpr-related compile errors.
+      const std::string& fmt,
+      Args&&... args) {
+    assert(logger);
+
+    if (logger->should_log(DefaultLevel)) {
+      logger_ = logger;
+      // Forwarding args in make_format_args causes an error.
+      event_name_ = fmt::vformat(fmt, fmt::make_format_args(args...));
+      start_ = std::chrono::high_resolution_clock::now();
+      system_time_start_ = std::chrono::system_clock::now();
+    }
+  }
+
+  ~LogDurationInstrument() {
+    try {
+      if (logger_) {
+        auto end = std::chrono::high_resolution_clock::now();
+        std::chrono::duration<float, std::chrono::milliseconds::period>
+            duration = end - start_;
+        logger_->log(
+            DefaultLevel,
+            "{} started at {:%Y-%m-%d %X} and lasted {}",
+            event_name_,
+            system_time_start_,
+            duration);
+      }
+    } catch (...) {
+      // Ignore exceptions inside destructor.
+    }
+  }
+
+ private:
+  /** Level used for logging. */
+  static constexpr Logger::Level DefaultLevel = Logger::Level::TRACE;
+
+  /**
+   * A pointer to the logger to use for logging.
+   *
+   * A null pointer indicates that the logger is not enabled for the given
+   * level and no event should be emitted.
+   */
+  Logger* logger_;
+
+  /** High-resolution time point of the operation's start. */
+  std::chrono::time_point<std::chrono::high_resolution_clock> start_;
+
+  /**
+   * System time point of the operation's start.
+   *
+   * We use it to format the operation's start time.
+   */
+  std::chrono::time_point<std::chrono::system_clock> system_time_start_;
+
+  /** Name of the event that will be logged. */
+  std::string event_name_;
+};
+
+}  // namespace tiledb::common
+
+#endif  // TILEDB_LOG_DURATION_INSTRUMENT_H
diff --git a/tiledb/common/logger.cc b/tiledb/common/logger.cc
@@ -142,6 +142,10 @@ void Logger::fatal(const char* msg) {
   exit(1);
 }
 
+void Logger::log(Logger::Level level, const char* msg) {
+  logger_->log(to_spdlog_level(level), msg);
+}
+
 Status Logger::status(const Status& st) {
   logger_->error(st.message());
   return st;
@@ -176,6 +180,10 @@ void Logger::fatal(const std::string& msg) {
   exit(1);
 }
 
+void Logger::log(Logger::Level level, const std::string& msg) {
+  logger_->log(to_spdlog_level(level), msg);
+}
+
 void Logger::trace(const std::stringstream& msg) {
   logger_->trace(msg.str());
 }
@@ -205,6 +213,10 @@ void Logger::fatal(const std::stringstream& msg) {
   exit(1);
 }
 
+void Logger::log(Logger::Level level, const std::stringstream& msg) {
+  logger_->log(to_spdlog_level(level), msg.str());
+}
+
 bool Logger::should_log(Logger::Level lvl) {
   return logger_->should_log(to_spdlog_level(lvl));
 }

diff --git a/tiledb/common/logger.h b/tiledb/common/logger.h
@@ -335,6 +335,46 @@ class Logger {
    */
   void fatal(const std::stringstream& msg);
 
+  /**
+   * Logs a message at the given level with no formatting.
+   *
+   * @param lvl The level of the log message.
+   * @param msg The message to log.
+   */
+  void log(const Level lvl, const char* msg);
+
+  /**
+   * Logs a message at the given level with no formatting.
+   *
+   * @param lvl The level of the log message.
+   * @param msg The message to log.
+   */
+  void log(const Level lvl, const std::string& msg);
+
+  /**
+   * Logs a message at the given level with no formatting.
+   *
+   * @param lvl The level of the log message.
+   * @param msg The message to log.
+   */
+  void log(const Level lvl, const std::stringstream& msg);
+
+  /**
+   * Logs a formatted message at the given level.
+   *
+   * @param lvl The level of the log message.
+   * @param msg The message to log.
+   */
+  template <typename... Args>
+  void log(const Level lvl, fmt::format_string<Args...> fmt, Args&&... args) {
+    // Check that this level is enabled to avoid needlessly formatting the
+    // string.
+    if (!should_log(lvl)) {
+      return;
+    }
+    log(lvl, fmt::format(fmt, std::forward<Args>(args)...));
+  }
+
   /**
    * Check whether events of a given level are logged.
    *

diff --git a/tiledb/sm/config/config.cc b/tiledb/sm/config/config.cc
@@ -175,6 +175,7 @@ const std::string Config::VFS_FILE_POSIX_FILE_PERMISSIONS = "644";
 const std::string Config::VFS_FILE_POSIX_DIRECTORY_PERMISSIONS = "755";
 const std::string Config::VFS_READ_AHEAD_SIZE = "102400";          // 100KiB
 const std::string Config::VFS_READ_AHEAD_CACHE_SIZE = "10485760";  // 10MiB;
+const std::string VFS_LOG_OPERATIONS = "false";
 const std::string Config::VFS_READ_LOGGING_MODE = "";
 const std::string Config::VFS_AZURE_STORAGE_ACCOUNT_NAME = "";
 const std::string Config::VFS_AZURE_STORAGE_ACCOUNT_KEY = "";
@@ -404,6 +405,7 @@ const std::map<std::string, std::string> default_config_values = {
     std::make_pair("vfs.min_batch_gap", Config::VFS_MIN_BATCH_GAP),
     std::make_pair("vfs.min_batch_size", Config::VFS_MIN_BATCH_SIZE),
     std::make_pair("vfs.read_ahead_size", Config::VFS_READ_AHEAD_SIZE),
+    std::make_pair("vfs.log_operations", VFS_LOG_OPERATIONS),
     std::make_pair(
         "vfs.read_ahead_cache_size", Config::VFS_READ_AHEAD_CACHE_SIZE),
     std::make_pair(

diff --git a/tiledb/sm/cpp_api/config.h b/tiledb/sm/cpp_api/config.h
@@ -545,6 +545,9 @@ class Config {
    *    The the total maximum size of the read-ahead cache, which is an LRU.
    *    <br>
    *    **Default**: 10485760
+   * -  `vfs.log_operations` <br>
+   *    Enables logging all VFS operations in trace mode. <br>
+   *    **Default**: false
    * - `vfs.min_parallel_size` <br>
    *    The minimum number of bytes in a parallel VFS operation
    *    (except parallel S3 writes, which are controlled by

diff --git a/tiledb/sm/filesystem/test/compile_vfs_main.cc b/tiledb/sm/filesystem/test/compile_vfs_main.cc
@@ -27,11 +27,13 @@
  */
 
 #include "../vfs.h"
+#include "tiledb/common/logger.h"
 
 int main() {
   static tiledb::sm::stats::Stats stats("test");
+  static tiledb::common::Logger logger("test");
   ThreadPool compute_tp(4);
   ThreadPool io_tp(4);
-  tiledb::sm::VFS x{&stats, &compute_tp, &io_tp, tiledb::sm::Config{}};
+  tiledb::sm::VFS x{&stats, &logger, &compute_tp, &io_tp, tiledb::sm::Config{}};
   return 0;
 }