Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add optional logging for timing of VFS operations. #5278

Merged
merged 14 commits into from
Sep 10, 2024
Merged

Conversation

teo-tsirpanis
Copy link
Member

@teo-tsirpanis teo-tsirpanis commented Sep 3, 2024

SC-53753

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.

Example logs from quickstart_dense_cpp
[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

TYPE: CONFIG
DESC: Add vfs.log_operations config option to log in trace level all VFS operations and their duration.

@teo-tsirpanis teo-tsirpanis requested a review from a team as a code owner September 3, 2024 18:50
Copy link
Contributor

@nickvigilante nickvigilante left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Approved tiledb/api/c_api/config/config_api_external.h and tiledb/sm/cpp_api/config.h only.

tiledb/common/log_duration.h Outdated Show resolved Hide resolved
tiledb/common/log_duration.h Outdated Show resolved Hide resolved
tiledb/sm/filesystem/vfs.cc Outdated Show resolved Hide resolved
tiledb/sm/filesystem/vfs.cc Outdated Show resolved Hide resolved
tiledb/common/log_duration.h Outdated Show resolved Hide resolved
tiledb/common/log_duration.h Outdated Show resolved Hide resolved
tiledb/api/c_api/config/config_api_external.h Outdated Show resolved Hide resolved
tiledb/common/logger.h Outdated Show resolved Hide resolved
tiledb/common/log_duration.h Outdated Show resolved Hide resolved
tiledb/sm/filesystem/vfs.cc Show resolved Hide resolved
tiledb/common/log_duration_instrument.h Outdated Show resolved Hide resolved
tiledb/sm/filesystem/vfs.cc Outdated Show resolved Hide resolved
tiledb/sm/filesystem/vfs.cc Outdated Show resolved Hide resolved
KiterLuc
KiterLuc previously approved these changes Sep 6, 2024
@KiterLuc KiterLuc self-requested a review September 6, 2024 10:16
@KiterLuc KiterLuc dismissed their stale review September 6, 2024 10:17

Didn't mean to approve

@KiterLuc KiterLuc merged commit 956fecc into dev Sep 10, 2024
62 checks passed
@KiterLuc KiterLuc deleted the teo/vfs-stats branch September 10, 2024 12:53
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants