2024/11/23-06:42:37.882660 140024844146240 DEBG dcompact_worker.cpp:2214: /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00: fork to child time = 0.010260 sec 2024/11/23-06:42:37.883471 140024844146240 DEBG dcompact_worker.cpp:1013: Beg SerDeRead: /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00 2024/11/23-06:42:37.889132 140024844146240 DEBG dcompact_worker.cpp:1033: End SerDeRead: /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00 2024/11/23-06:42:37.890430 140024844146240 TRAC dcompact_worker.cpp:1083: INFO_LOG_LEVEL: rpc = INFO_LEVEL, env_var = undefined 2024/11/23-06:42:37.890696 140024844146240 [WARN] [column_family.cc:386] multiple cf_paths/db_paths and level_compaction_dynamic_level_bytes can't be used together 2024/11/23-06:42:37.942029 140024844146240 [version_set.cc:6208] Recovering from manifest file: /worker/dcompact-log/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/2024-11-22T14.14.14/.rocksdb/job-21232/att-00/MANIFEST-206347 2024/11/23-06:42:37.956213 140024844146240 [version_set.cc:6251] Recovered from manifest file:/worker/dcompact-log/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/2024-11-22T14.14.14/.rocksdb/job-21232/att-00/MANIFEST-206347 succeeded,manifest_file_number is 206347, next_file_number is 249037, last_sequence is 3841896843, log_number is 0,prev_log_number is 0,max_column_family is 0,min_log_number_to_keep is 248888 2024/11/23-06:42:37.956220 140024844146240 [version_set.cc:6266] Column family [default] (ID 0), log number is 0 2024/11/23-06:42:37.956328 140024844146240 [version_set.cc:5721] Creating manifest 249037 2024/11/23-06:42:37.985589 140024844146240 DEBG dcompact_worker.cpp:1218: /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00: bottommost_level: fake = 1, rpc = 0 2024/11/23-06:42:38.005434 140024844146240 [compaction_job.cc:2437] [default] [JOB 21232] Compacting 1@2 + 4@3 files to L3, score 0.99, subcompactions 1 : 1 2024/11/23-06:42:38.005449 140024844146240 [compaction_job.cc:2445] [default]: Compaction start summary: Base version 15899 Base level 2, inputs: [249028(21MB)], [248934(124MB) 248935(124MB) 248936(100MB) 248937(18MB)] 2024/11/23-06:42:38.012101 140024844146240 [top_zip_table.cc:59] core git_version_hash_info_is:commit fc4ab4f2fbfdcdfa23a955d69e26d2fc533b902d Author: leipeng Date: 2024-04-16 20:29:43 +0800 test_sso.cpp: test swap g++ (GCC) 12.1.0 Copyright (C) 2022 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. INCS = -Isrc -I3rdparty/re2 -I3rdparty/zstd -Iboost-include CXXFLAGS = -D TOPLING_IO_WITH_URING=1 -fPIC -time -Wno-class-memaccess -fdiagnostics-color -Wformat=2 -Wcomment -Wall -Wextra -Wno-unused-parameter -Wno-alloc-size-larger-than -mcx16 -Wno-deprecated-declarations -Wstrict-aliasing=3 -DCLIENT_LICENSE_ID="public" -DNO_THREADS -ftls-model=initial-exec -DDIVSUFSORT_API= -fno-stack-protector RLS_FLAGS = -O3 -DNDEBUG -g3 WITH_BMI2 = 1 compile_cpu_flag: -march=haswell -mbmi -mbmi2 2024/11/23-06:42:38.012140 140024844146240 [top_zip_table.cc:60] fsa git_version_hash_info_is:commit fc4ab4f2fbfdcdfa23a955d69e26d2fc533b902d Author: leipeng Date: 2024-04-16 20:29:43 +0800 test_sso.cpp: test swap g++ (GCC) 12.1.0 Copyright (C) 2022 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. INCS = -Isrc -I3rdparty/re2 -I3rdparty/zstd -Iboost-include CXXFLAGS = -D TOPLING_IO_WITH_URING=1 -fPIC -time -Wno-class-memaccess -fdiagnostics-color -Wformat=2 -Wcomment -Wall -Wextra -Wno-unused-parameter -Wno-alloc-size-larger-than -mcx16 -Wno-deprecated-declarations -Wstrict-aliasing=3 -DCLIENT_LICENSE_ID="public" -DNO_THREADS -ftls-model=initial-exec -DDIVSUFSORT_API= -fno-stack-protector RLS_FLAGS = -O3 -DNDEBUG -g3 WITH_BMI2 = 1 compile_cpu_flag: -march=haswell -mbmi -mbmi2 2024/11/23-06:42:38.012161 140024844146240 [top_zip_table.cc:61] zbs git_version_hash_info_is:commit fc4ab4f2fbfdcdfa23a955d69e26d2fc533b902d Author: leipeng Date: 2024-04-16 20:29:43 +0800 test_sso.cpp: test swap g++ (GCC) 12.1.0 Copyright (C) 2022 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. INCS = -Isrc -I3rdparty/re2 -I3rdparty/zstd -Iboost-include CXXFLAGS = -D TOPLING_IO_WITH_URING=1 -fPIC -time -Wno-class-memaccess -fdiagnostics-color -Wformat=2 -Wcomment -Wall -Wextra -Wno-unused-parameter -Wno-alloc-size-larger-than -mcx16 -Wno-deprecated-declarations -Wstrict-aliasing=3 -DCLIENT_LICENSE_ID="public" -DNO_THREADS -ftls-model=initial-exec -DDIVSUFSORT_API= -fno-stack-protector RLS_FLAGS = -O3 -DNDEBUG -g3 WITH_BMI2 = 1 compile_cpu_flag: -march=haswell -mbmi -mbmi2 2024/11/23-06:42:38.012167 140024844146240 [top_zip_table.cc:62] topling-zip_table_reader: git_version_hash_info_is: commit a4a382006cb82713acf5b3425835f22711877681 Author: leipeng Date: 2024-04-11 19:44:14 +0800 fixed_len_hole_index.cc: Add env bool FixedLenHoleIndexUseAVX512 for ut & debug 1. FixedLenHoleIndexUseAVX512 is only in unit tests or debug 2. In release mode, use avx512 by compile options(-march=) g++ (GCC) 12.1.0 Copyright (C) 2022 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. cpu_flag: -march=native -mbmi -mbmi2 2024/11/23-06:42:38.012178 140024844146240 [top_zip_table.cc:64] topling-rocks git_version_hash_info_is: commit feab587e468621ba0204d47b4ffacc52e7c4290d Author: leipeng Date: 2024-03-22 13:35:06 +0800 ToplingZipTableBuilder::Add: immediately return after error This function returns void, and caller does not check builder->status() after calling this function and graceful abandon. So immediately return after error, and return error status in Finish(). g++ (GCC) 12.1.0 Copyright (C) 2022 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. cpu_flag: -march=native -mbmi -mbmi2 2024/11/23-06:42:39.182090 140024844146240 [top_zip_table_builder.cc:934] ToplingZipTableBuilder(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249038.sst) /dev/shm/ToplingTemp/Topling-437615-zbVPqC 2024/11/23-06:42:39.334296 140024844146240 [top_zip_table_builder.cc:1352] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249038.sst): first pass time = 0.15's, 882.062'MB/sec 2024/11/23-06:42:41.293075 140024844146240 [top_zip_table_builder.cc:2726] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249038.sst): part-0: reject ZipStore ratio = 0.810 2024/11/23-06:42:41.571749 140024844146240 [top_zip_table_builder.cc:2772] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249038.sst): old prealloc_size = 147639500, real_size = 130071888 2024/11/23-06:42:41.571920 140024844146240 [top_zip_table_builder.cc:1773] BuildReorderMap(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249038.sst): index type = NestLoudsTrieDAWG_Mixed_XL_256_32_FL, store type = ZipOffsetBlobStore usrkeys = 198561 prefix = 4 raw-key = 0.0024 GB zip-key = 0.0004 GB avg-key = 12.00 avg-zkey = 1.81 raw-val = 0.1295 GB zip-val = 0.1297 GB avg-val = 651.95 avg-zval = 653.01 2024/11/23-06:42:41.572142 140024844146240 [top_zip_table_builder.cc:1299] /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249038.sst: sumWaitingMem = 0.000 GB, sumWorkingMem = 0.000 GB, reorder workingMem = 0.0004 GB, waited 0.000 sec, Key+Value = 0.134 GB 2024/11/23-06:42:41.858078 140024844146240 [top_zip_table_builder.cc:3100] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249038.sst): second pass time = 1.96's, 66.174'MB/sec, value only(96.4% of KV) wait indexing time = 0.28's, remap KeyValue time = 0.29's, 456.702'MB/sec (all stages of remap) Get OrderMap time = 0.00's, 2340.365'MB/sec (index lex order gen) rebuild zvType time = 0.22's, 0.222'MB/sec write SST data time = 0.06's, 2082.252'MB/sec dict compress time = 4356233619.02's, 0.000'MB/sec z-dict build time = 0.00's, sample length = 0.000'MB, throughput = 0.000'MB/sec zip my value time = 1.96's, unzip length = 0.129'GB zip my value throughput = 66.174'MB/sec zip pipeline throughput = 74.891'MB/sec entries = 198561 avg-key = 24.00 avg-zkey = 1.81 avg-val = 651.95 avg-zval = 653.01 usrkeys = 198561 avg-key = 16.00 avg-zkey = 1.81 avg-val = 658.95 avg-zval = 653.01 TagRS{ kinds = RS_Key0_Tag1 bytes = 0 } TagArray{ size = 198561 bytes = 744624 } seq expand size = 1389927 multi value expand size = 0 cnt WriteAppend = 15812 UnZipSize{ index = 0.0032 GB value = 0.1295 GB dict = 0.00 MB all = 0.1342 GB } __ZipSize{ index = 0.0004 GB value = 0.1297 GB dict = 0.00 MB all = 0.1308 GB } UnZip/Zip{ index = 8.8485 value = 0.9984 dict = 0.00 all = 1.0264 } Zip/UnZip{ index = 0.1130 value = 1.0016 dict = 0.00 all = 0.9743 } ---------------------------- total value len = 0.130842 GB avg = 0.659 KB (by entry num) total key len = 0.004765 GB avg = 0.024 KB total ukey len = 0.003177 GB avg = 0.016 KB total ukey num = 0.000198561 Billion total entry num = 0.000198561 Billion write speed all = 0.001724878 MB/sec (with seq num) write speed all = 0.001704673 MB/sec (without seq num) 2024/11/23-06:42:41.960294 140024844146240 [compaction_job.cc:1948] [default] [JOB 21232] Generated table #249038: 198561 keys, 130768991 bytes, temperature: kWarm 2024/11/23-06:42:41.960402 140024844146240 EVENT_LOG_v1 {"time_micros": 1732315361960331, "cf_name": "default", "job": 21232, "event": "table_file_creation", "file_number": 249038, "file_size": 130768991, "file_checksum": "", "file_checksum_func_name": "Unknown", "smallest_seqno": 3237870352, "largest_seqno": 3841879591, "table_properties": {"data_size": 129663040, "index_size": 359040, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 0, "index_value_is_delta_encoded": 0, "filter_size": 0, "raw_key_size": 4765464, "raw_average_key_size": 24, "raw_value_size": 129452380, "raw_average_value_size": 651, "num_data_blocks": 1, "num_entries": 198561, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 24, "fixed_value_len": 18446744073709551615, "filter_policy": "", "column_family_name": "default", "column_family_id": 0, "comparator": "leveldb.BytewiseComparator", "merge_operator": "nullptr", "prefix_extractor_name": "nullptr", "property_collectors": "[Rdb_tbl_prop_coll_factory]", "compression": "FlatZip", "compression_options": "RS_Key0_Tag1-NestLoudsTrieDAWG_Mixed_XL_256_32_FL-ZipOffsetBlobStore", "creation_time": 1732315359, "oldest_key_time": 0, "file_creation_time": 1732315359, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "d89b4006-2803-486e-b7a2-759bcf348921", "db_session_id": "U1ECJGOXSO4Y1P7ZZXV1", "orig_file_number": 249038, "seqno_to_time_mapping": "N/A", "__indexstats__": "[...1 records...]"}} 2024/11/23-06:42:42.043496 140024844146240 [top_zip_table_builder.cc:934] ToplingZipTableBuilder(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249039.sst) /dev/shm/ToplingTemp/Topling-437615-SNMnbz 2024/11/23-06:42:43.178469 140024844146240 [top_zip_table_builder.cc:1352] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249039.sst): first pass time = 1.13's, 118.261'MB/sec 2024/11/23-06:42:45.395917 140024844146240 [top_zip_table_builder.cc:2726] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249039.sst): part-0: reject ZipStore ratio = 0.805 2024/11/23-06:42:45.739437 140024844146240 [top_zip_table_builder.cc:2772] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249039.sst): old prealloc_size = 147639500, real_size = 130072480 2024/11/23-06:42:45.739607 140024844146240 [top_zip_table_builder.cc:1773] BuildReorderMap(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249039.sst): index type = NestLoudsTrieDAWG_Mixed_XL_256_32_FL, store type = ZipOffsetBlobStore usrkeys = 198373 prefix = 4 raw-key = 0.0024 GB zip-key = 0.0004 GB avg-key = 12.00 avg-zkey = 1.79 raw-val = 0.1295 GB zip-val = 0.1297 GB avg-val = 652.59 avg-zval = 653.66 2024/11/23-06:42:45.739832 140024844146240 [top_zip_table_builder.cc:1299] /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249039.sst: sumWaitingMem = 0.000 GB, sumWorkingMem = 0.000 GB, reorder workingMem = 0.0004 GB, waited 0.000 sec, Key+Value = 0.134 GB 2024/11/23-06:42:46.024946 140024844146240 [top_zip_table_builder.cc:3100] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249039.sst): second pass time = 2.22's, 58.428'MB/sec, value only(96.5% of KV) wait indexing time = 0.34's, remap KeyValue time = 0.29's, 457.874'MB/sec (all stages of remap) Get OrderMap time = 0.00's, 2292.162'MB/sec (index lex order gen) rebuild zvType time = 0.22's, 0.223'MB/sec write SST data time = 0.06's, 2084.943'MB/sec dict compress time = 4356233619.02's, 0.000'MB/sec z-dict build time = 0.00's, sample length = 0.000'MB, throughput = 0.000'MB/sec zip my value time = 2.22's, unzip length = 0.129'GB zip my value throughput = 58.428'MB/sec zip pipeline throughput = 91.106'MB/sec entries = 198373 avg-key = 24.00 avg-zkey = 1.79 avg-val = 652.59 avg-zval = 653.66 usrkeys = 198373 avg-key = 16.00 avg-zkey = 1.79 avg-val = 659.59 avg-zval = 653.66 TagRS{ kinds = RS_Key0_Tag1 bytes = 0 } TagArray{ size = 198373 bytes = 694320 } seq expand size = 1388611 multi value expand size = 0 cnt WriteAppend = 15812 UnZipSize{ index = 0.0032 GB value = 0.1295 GB dict = 0.00 MB all = 0.1342 GB } __ZipSize{ index = 0.0004 GB value = 0.1297 GB dict = 0.00 MB all = 0.1307 GB } UnZip/Zip{ index = 8.9389 value = 0.9984 dict = 0.00 all = 1.0268 } Zip/UnZip{ index = 0.1119 value = 1.0016 dict = 0.00 all = 0.9739 } ---------------------------- total value len = 0.261688 GB avg = 0.659 KB (by entry num) total key len = 0.009526 GB avg = 0.024 KB total ukey len = 0.006351 GB avg = 0.016 KB total ukey num = 0.000396934 Billion total entry num = 0.000396934 Billion write speed all = 0.003449559 MB/sec (with seq num) write speed all = 0.003409171 MB/sec (without seq num) 2024/11/23-06:42:46.126769 140024844146240 [compaction_job.cc:1948] [default] [JOB 21232] Generated table #249039: 198373 keys, 130719903 bytes, temperature: kWarm 2024/11/23-06:42:46.126835 140024844146240 EVENT_LOG_v1 {"time_micros": 1732315366126804, "cf_name": "default", "job": 21232, "event": "table_file_creation", "file_number": 249039, "file_size": 130719903, "file_checksum": "", "file_checksum_func_name": "Unknown", "smallest_seqno": 3613588684, "largest_seqno": 3841880110, "table_properties": {"data_size": 129667600, "index_size": 355072, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 0, "index_value_is_delta_encoded": 0, "filter_size": 0, "raw_key_size": 4760952, "raw_average_key_size": 24, "raw_value_size": 129457117, "raw_average_value_size": 652, "num_data_blocks": 1, "num_entries": 198373, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 24, "fixed_value_len": 18446744073709551615, "filter_policy": "", "column_family_name": "default", "column_family_id": 0, "comparator": "leveldb.BytewiseComparator", "merge_operator": "nullptr", "prefix_extractor_name": "nullptr", "property_collectors": "[Rdb_tbl_prop_coll_factory]", "compression": "FlatZip", "compression_options": "RS_Key0_Tag1-NestLoudsTrieDAWG_Mixed_XL_256_32_FL-ZipOffsetBlobStore", "creation_time": 1732315362, "oldest_key_time": 0, "file_creation_time": 1732315362, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "d89b4006-2803-486e-b7a2-759bcf348921", "db_session_id": "U1ECJGOXSO4Y1P7ZZXV1", "orig_file_number": 249039, "seqno_to_time_mapping": "N/A", "__indexstats__": "[...1 records...]"}} 2024/11/23-06:42:46.189990 140024844146240 [top_zip_table_builder.cc:934] ToplingZipTableBuilder(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249040.sst) /dev/shm/ToplingTemp/Topling-437615-JyVA8C 2024/11/23-06:42:47.388854 140024844146240 [top_zip_table_builder.cc:1352] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249040.sst): first pass time = 1.20's, 111.958'MB/sec 2024/11/23-06:42:49.483227 140024844146240 [top_zip_table_builder.cc:2772] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249040.sst): old prealloc_size = 147639500, real_size = 103429296 2024/11/23-06:42:49.483417 140024844146240 [top_zip_table_builder.cc:1773] BuildReorderMap(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249040.sst): index type = NestLoudsTrieDAWG_Mixed_XL_256_32_FL, store type = DictZipBlobStore usrkeys = 198228 prefix = 4 raw-key = 0.0024 GB zip-key = 0.0004 GB avg-key = 12.00 avg-zkey = 1.80 raw-val = 0.1295 GB zip-val = 0.1030 GB avg-val = 653.09 avg-zval = 519.72 2024/11/23-06:42:49.483682 140024844146240 [top_zip_table_builder.cc:1299] /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249040.sst: sumWaitingMem = 0.000 GB, sumWorkingMem = 0.000 GB, reorder workingMem = 0.0004 GB, waited 0.000 sec, Key+Value = 0.134 GB 2024/11/23-06:42:49.866898 140024844146240 [top_zip_table_builder.cc:3100] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249040.sst): second pass time = 2.09's, 61.877'MB/sec, value only(96.5% of KV) wait indexing time = 0.00's, remap KeyValue time = 0.38's, 274.933'MB/sec (all stages of remap) Get OrderMap time = 0.00's, 2133.321'MB/sec (index lex order gen) rebuild zvType time = 0.29's, 0.171'MB/sec write SST data time = 0.09's, 1121.959'MB/sec dict compress time = 4356233619.02's, 0.000'MB/sec z-dict build time = 0.00's, sample length = 1.349'MB, throughput = 41377.488'MB/sec zip my value time = 2.09's, unzip length = 0.129'GB zip my value throughput = 61.877'MB/sec zip pipeline throughput = 74.119'MB/sec entries = 198228 avg-key = 24.00 avg-zkey = 1.80 avg-val = 653.09 avg-zval = 519.72 usrkeys = 198228 avg-key = 16.00 avg-zkey = 1.80 avg-val = 660.09 avg-zval = 519.72 TagRS{ kinds = RS_Key0_Tag1 bytes = 0 } TagArray{ size = 198228 bytes = 743376 } seq expand size = 1387596 multi value expand size = 0 cnt WriteAppend = 13 UnZipSize{ index = 0.0032 GB value = 0.1295 GB dict = 1.35 MB all = 0.1342 GB } __ZipSize{ index = 0.0004 GB value = 0.1030 GB dict = 1.35 MB all = 0.1055 GB } UnZip/Zip{ index = 8.9099 value = 1.2566 dict = 1.00 all = 1.2725 } Zip/UnZip{ index = 0.1122 value = 0.7958 dict = 1.00 all = 0.7859 } ---------------------------- total value len = 0.392536 GB avg = 0.660 KB (by entry num) total key len = 0.014284 GB avg = 0.024 KB total ukey len = 0.009523 GB avg = 0.016 KB total ukey num = 0.000595162 Billion total entry num = 0.000595162 Billion write speed all = 0.005174068 MB/sec (with seq num) write speed all = 0.005113512 MB/sec (without seq num) 2024/11/23-06:42:49.959757 140024844146240 [compaction_job.cc:1948] [default] [JOB 21232] Generated table #249040: 198228 keys, 105475595 bytes, temperature: kWarm 2024/11/23-06:42:49.959855 140024844146240 EVENT_LOG_v1 {"time_micros": 1732315369959809, "cf_name": "default", "job": 21232, "event": "table_file_creation", "file_number": 249040, "file_size": 105475595, "file_checksum": "", "file_checksum_func_name": "Unknown", "smallest_seqno": 3184145272, "largest_seqno": 3841880023, "table_properties": {"data_size": 103023584, "index_size": 355968, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 0, "index_value_is_delta_encoded": 0, "filter_size": 0, "raw_key_size": 4757472, "raw_average_key_size": 24, "raw_value_size": 129460746, "raw_average_value_size": 653, "num_data_blocks": 1, "num_entries": 198228, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 24, "fixed_value_len": 18446744073709551615, "filter_policy": "", "column_family_name": "default", "column_family_id": 0, "comparator": "leveldb.BytewiseComparator", "merge_operator": "nullptr", "prefix_extractor_name": "nullptr", "property_collectors": "[Rdb_tbl_prop_coll_factory]", "compression": "FlatZip", "compression_options": "RS_Key0_Tag1-NestLoudsTrieDAWG_Mixed_XL_256_32_FL-DictZipBlobStore", "creation_time": 1732315366, "oldest_key_time": 0, "file_creation_time": 1732315366, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "d89b4006-2803-486e-b7a2-759bcf348921", "db_session_id": "U1ECJGOXSO4Y1P7ZZXV1", "orig_file_number": 249040, "seqno_to_time_mapping": "N/A", "__indexstats__": "[...1 records...]"}} 2024/11/23-06:42:50.021805 140024844146240 [top_zip_table_builder.cc:934] ToplingZipTableBuilder(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249041.sst) /dev/shm/ToplingTemp/Topling-437615-gxRUvA 2024/11/23-06:42:50.235911 140024844146240 [top_zip_table_builder.cc:1352] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249041.sst): first pass time = 0.21's, 101.908'MB/sec 2024/11/23-06:42:50.576452 140024844146240 [top_zip_table_builder.cc:2726] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249041.sst): part-0: reject ZipStore ratio = 0.822 2024/11/23-06:42:50.617762 140024844146240 [top_zip_table_builder.cc:2772] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249041.sst): old prealloc_size = 147639500, real_size = 21143440 2024/11/23-06:42:50.617837 140024844146240 [top_zip_table_builder.cc:1773] BuildReorderMap(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249041.sst): index type = NestLoudsTrieDAWG_Mixed_XL_256_32_FL, store type = ZipOffsetBlobStore usrkeys = 32269 prefix = 4 raw-key = 0.0004 GB zip-key = 0.0001 GB avg-key = 12.00 avg-zkey = 1.87 raw-val = 0.0210 GB zip-val = 0.0211 GB avg-val = 652.03 avg-zval = 653.10 2024/11/23-06:42:50.617904 140024844146240 [top_zip_table_builder.cc:1299] /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249041.sst: sumWaitingMem = 0.000 GB, sumWorkingMem = 0.000 GB, reorder workingMem = 0.0001 GB, waited 0.000 sec, Key+Value = 0.022 GB 2024/11/23-06:42:50.665051 140024844146240 [top_zip_table_builder.cc:3100] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00/249041.sst): second pass time = 0.34's, 61.883'MB/sec, value only(96.4% of KV) wait indexing time = 0.04's, remap KeyValue time = 0.05's, 449.659'MB/sec (all stages of remap) Get OrderMap time = 0.00's, 1149.839'MB/sec (index lex order gen) rebuild zvType time = 0.04's, 0.219'MB/sec write SST data time = 0.01's, 2054.551'MB/sec dict compress time = 4356233619.02's, 0.000'MB/sec z-dict build time = 0.00's, sample length = 0.000'MB, throughput = 0.000'MB/sec zip my value time = 0.34's, unzip length = 0.021'GB zip my value throughput = 61.883'MB/sec zip pipeline throughput = 61.883'MB/sec entries = 32269 avg-key = 24.00 avg-zkey = 1.87 avg-val = 652.03 avg-zval = 653.10 usrkeys = 32269 avg-key = 16.00 avg-zkey = 1.87 avg-val = 659.03 avg-zval = 653.10 TagRS{ kinds = RS_Key0_Tag1 bytes = 0 } TagArray{ size = 32269 bytes = 121024 } seq expand size = 225883 multi value expand size = 0 cnt WriteAppend = 2578 UnZipSize{ index = 0.0005 GB value = 0.0210 GB dict = 0.00 MB all = 0.0218 GB } __ZipSize{ index = 0.0001 GB value = 0.0211 GB dict = 0.00 MB all = 0.0213 GB } UnZip/Zip{ index = 8.5458 value = 0.9984 dict = 0.00 all = 1.0262 } Zip/UnZip{ index = 0.1170 value = 1.0016 dict = 0.00 all = 0.9745 } ---------------------------- total value len = 0.413803 GB avg = 0.660 KB (by entry num) total key len = 0.015058 GB avg = 0.024 KB total ukey len = 0.010039 GB avg = 0.016 KB total ukey num = 0.000627431 Billion total entry num = 0.000627431 Billion write speed all = 0.005454334 MB/sec (with seq num) write speed all = 0.005390496 MB/sec (without seq num) 2024/11/23-06:42:50.685226 140024844146240 [compaction_job.cc:1948] [default] [JOB 21232] Generated table #249041: 32269 keys, 21257694 bytes, temperature: kWarm 2024/11/23-06:42:50.685286 140024844146240 EVENT_LOG_v1 {"time_micros": 1732315370685256, "cf_name": "default", "job": 21232, "event": "table_file_creation", "file_number": 249041, "file_size": 21257694, "file_checksum": "", "file_checksum_func_name": "Unknown", "smallest_seqno": 3237868515, "largest_seqno": 3841857253, "table_properties": {"data_size": 21074752, "index_size": 60416, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 0, "index_value_is_delta_encoded": 0, "filter_size": 0, "raw_key_size": 774456, "raw_average_key_size": 24, "raw_value_size": 21040427, "raw_average_value_size": 652, "num_data_blocks": 1, "num_entries": 32269, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 24, "fixed_value_len": 18446744073709551615, "filter_policy": "", "column_family_name": "default", "column_family_id": 0, "comparator": "leveldb.BytewiseComparator", "merge_operator": "nullptr", "prefix_extractor_name": "nullptr", "property_collectors": "[Rdb_tbl_prop_coll_factory]", "compression": "FlatZip", "compression_options": "RS_Key0_Tag1-NestLoudsTrieDAWG_Mixed_XL_256_32_FL-ZipOffsetBlobStore", "creation_time": 1732315370, "oldest_key_time": 0, "file_creation_time": 1732315370, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "d89b4006-2803-486e-b7a2-759bcf348921", "db_session_id": "U1ECJGOXSO4Y1P7ZZXV1", "orig_file_number": 249041, "seqno_to_time_mapping": "N/A", "__indexstats__": "[...1 records...]"}} 2024/11/23-06:42:50.701448 140024844146240 [compaction_job.cc:703] job-21232: subcompact[0], size: 0.388222 G, files: /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-21232/att-00 [249038,249039,249040,249041] 2024/11/23-06:42:50.769123 140024844146240 (Original Log Time 2024/11/23-06:42:38.005510) EVENT_LOG_v1 {"time_micros": 1732315358005464, "job": 21232, "event": "compaction_started", "compaction_reason": "FilesMarkedForCompaction", "files_L2": [249028], "files_L3": [248934, 248935, 248936, 248937], "score": 0.99341, "input_data_size": 408763638, "oldest_snapshot_seqno": 3841896804} 2024/11/23-06:42:50.769126 140024844146240 (Original Log Time 2024/11/23-06:42:50.768539) [compaction_job.cc:2022] [default] [JOB 21232] Compacted 1@2 + 4@3 files to L3 => 388222183 bytes 2024/11/23-06:42:50.769128 140024844146240 (Original Log Time 2024/11/23-06:42:50.769061) [compaction_job.cc:1224] [default] compacted to: files[0 0 0 4 0 0 0] max score 0.01, MB/sec: 32.2 rd, 30.6 wr, level 3, files in(1, 4) out(4 +0 blob) MB in(21.6, 368.2 +0.0 blob) out(370.2 +0.0 blob), read-write-amplify(35.2) write-amplify(17.1) OK, records in: 658422, records dropped: 30991 output_compression: Snappy 2024/11/23-06:42:50.769135 140024844146240 (Original Log Time 2024/11/23-06:42:50.769102) EVENT_LOG_v1 {"time_micros": 1732315370769084, "cf": "default", "job": 21232, "event": "compaction_finished", "compaction_time_micros": 12695958, "compaction_time_cpu_micros": 2465734, "output_level": 3, "num_output_files": 4, "total_output_size": 388222183, "num_input_records": 658422, "num_output_records": 627431, "num_subcompactions": 1, "output_compression": "Snappy", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "file_write_nanos": 241089585, "file_range_sync_nanos": 0, "file_fsync_nanos": 3402, "file_prepare_write_nanos": 1177493, "lsm_state": [0, 0, 0, 4, 0, 0, 0]} 2024/11/23-06:42:50.901563 140024844146240 DEBG dcompact_worker.cpp:240: HttpPost: 200 OK: url = http://nlb-7zny4kaa1poal01o64.cn-shenzhen.nlb.aliyuncs.com:8443, body = {"instanceId":"nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137","labourId":"","dbId":"d89b4006-2803-486e-b7a2-759bcf348921","dbStarts":1732256054,"starts":1732315357,"executesMs":12880,"compactionJobId":21232,"attempt":0,"compactionInputRawBytes":445506305,"compactionInputZipBytes":408763638,"compactionOutputRawBytes":0,"compactionOutputZipBytes":388222183,"headers":{"Accept":"*/*","Connection":"close","Host":"aliyun-topling-saas.topling.cn:18443","RemoteIp":"120.24.192.169","X-Forwarded-For":"120.24.192.169","region":"cn-shenzhen","token":"e6474c481bd4415abc537135cc03626b","instance-token":"e6474c481bd4415abc537135cc03626b","provider":"aliyun","CloudMarketInstanceId":"si-59c0ae5c955845588903","MeteringAssit":"","Transfer-Encoding":"chunked","traceparent":"00-6b2cf870f93b6a6963fa9928fb3b00b0-9eaf7968a40c4a9b-00"}}, response = 2024/11/23-06:42:50.901637 140024844146240 INFO dcompact_worker.cpp:1459: finish /worker/dcompact-log/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/2024-11-22T14.14.14/.rocksdb/job-21232/att-00: olev 3, work 12.881 s, result 5.055 ms, install 0.617 ms, input{raw 424.868 MiB zip 389.827 MiB}