2024/07/08-15:52:31.566802 139818822035008 DEBG dcompact_worker.cpp:2211: /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00: fork to child time = 0.010064 sec 2024/07/08-15:52:31.567809 139818822035008 DEBG dcompact_worker.cpp:1011: Beg SerDeRead: /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00 2024/07/08-15:52:31.575441 139818822035008 DEBG dcompact_worker.cpp:1031: End SerDeRead: /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00 2024/07/08-15:52:31.581483 139818822035008 TRAC dcompact_worker.cpp:1081: INFO_LOG_LEVEL: rpc = INFO_LEVEL, env_var = undefined 2024/07/08-15:52:31.581857 139818822035008 [WARN] [column_family.cc:386] multiple cf_paths/db_paths and level_compaction_dynamic_level_bytes can't be used together 2024/07/08-15:52:31.628379 139818822035008 [version_set.cc:6139] Recovering from manifest file: /worker/dcompact-log/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/2024-07-08T14.41.36/.rocksdb/job-04460/att-00/MANIFEST-12625661 2024/07/08-15:52:31.655156 139818822035008 [version_set.cc:6182] Recovered from manifest file:/worker/dcompact-log/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/2024-07-08T14.41.36/.rocksdb/job-04460/att-00/MANIFEST-12625661 succeeded,manifest_file_number is 12625661, next_file_number is 12629400, last_sequence is 147255645899, log_number is 0,prev_log_number is 0,max_column_family is 0,min_log_number_to_keep is 12629216 2024/07/08-15:52:31.655171 139818822035008 [version_set.cc:6197] Column family [default] (ID 0), log number is 0 2024/07/08-15:52:31.655285 139818822035008 [version_set.cc:5652] Creating manifest 12629400 2024/07/08-15:52:31.683037 139818822035008 DEBG dcompact_worker.cpp:1215: /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00: bottommost_level: fake = 1, rpc = 0 2024/07/08-15:52:31.698488 139818822035008 [compaction_job.cc:2433] [default] [JOB 4460] Compacting 1@1 + 5@2 files to L2, score 0.70, subcompactions 1 : 1 2024/07/08-15:52:31.698512 139818822035008 [compaction_job.cc:2441] [default]: Compaction start summary: Base version 2755 Base level 1, inputs: [12629379(31MB)], [12629354(20MB) 12629355(20MB) 12629356(20MB) 12629357(8593KB) 12629314(20MB)] 2024/07/08-15:52:31.953397 139818822035008 [top_zip_table.cc:59] core git_version_hash_info_is:commit 7517bad5c1a147474c3830831b9a22c996321ae8 Author: leipeng Date: 2024-01-08 19:18:17 +0800 vfork_cmd: call close before wait_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. 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/07/08-15:52:31.953424 139818822035008 [top_zip_table.cc:60] fsa git_version_hash_info_is:commit 7517bad5c1a147474c3830831b9a22c996321ae8 Author: leipeng Date: 2024-01-08 19:18:17 +0800 vfork_cmd: call close before wait_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. 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/07/08-15:52:31.953441 139818822035008 [top_zip_table.cc:61] zbs git_version_hash_info_is:commit 7517bad5c1a147474c3830831b9a22c996321ae8 Author: leipeng Date: 2024-01-08 19:18:17 +0800 vfork_cmd: call close before wait_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. 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/07/08-15:52:31.953456 139818822035008 [top_zip_table.cc:62] topling-zip_table_reader: git_version_hash_info_is: commit 7f80399bfbd2071b6e0f5683e8ab7225b8e6e394 Author: leipeng Date: 2024-01-19 14:52:30 +0800 Change ToplingZipTableOptions::sampleRatio to vector 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/07/08-15:52:31.953466 139818822035008 [top_zip_table.cc:64] topling-rocks git_version_hash_info_is: commit 1240987ca13d0fe562c9b9c037155079f0877840 Author: leipeng Date: 2024-01-19 15:07:04 +0800 Change ToplingZipTableOptions::sampleRatio to vector 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/07/08-15:52:32.119476 139818822035008 [top_zip_table_builder.cc:934] ToplingZipTableBuilder(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629401.sst) /dev/shm/ToplingTemp/Topling-30251-s46ZMD 2024/07/08-15:52:32.631858 139818822035008 [top_zip_table_builder.cc:1344] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629401.sst): first pass time = 0.51's, 130.988'MB/sec 2024/07/08-15:52:33.602838 139818822035008 [top_zip_table_builder.cc:2764] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629401.sst): old prealloc_size = 73819750, real_size = 19433680 2024/07/08-15:52:33.603184 139818822035008 [top_zip_table_builder.cc:1765] BuildReorderMap(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629401.sst): index type = NestLoudsTrieDAWG_Mixed_XL_256_32_FL, store type = DictZipBlobStore usrkeys = 463463 prefix = 4 raw-key = 0.0074 GB zip-key = 0.0009 GB avg-key = 16.00 avg-zkey = 1.90 raw-val = 0.0541 GB zip-val = 0.0184 GB avg-val = 116.80 avg-zval = 39.78 2024/07/08-15:52:33.603671 139818822035008 [top_zip_table_builder.cc:1295] /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629401.sst: sumWaitingMem = 0.001 GB, sumWorkingMem = 0.007 GB, reorder workingMem = 0.0011 GB, waited 0.000 sec, Key+Value = 0.067 GB 2024/07/08-15:52:34.247918 139818822035008 [top_zip_table_builder.cc:3092] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629401.sst): second pass time = 0.97's, 55.806'MB/sec, value only(80.7% of KV) wait indexing time = 0.00's, remap KeyValue time = 0.65's, 33.131'MB/sec (all stages of remap) Get OrderMap time = 0.00's, 2638.548'MB/sec (index lex order gen) rebuild zvType time = 0.57's, 0.204'MB/sec write SST data time = 0.08's, 277.241'MB/sec dict compress time = 4356233619.02's, 0.000'MB/sec z-dict build time = 0.00's, sample length = 0.545'MB, throughput = 11826.332'MB/sec zip my value time = 0.97's, unzip length = 0.054'GB zip my value throughput = 55.806'MB/sec zip pipeline throughput = 67.220'MB/sec entries = 463463 avg-key = 28.00 avg-zkey = 1.90 avg-val = 116.80 avg-zval = 39.78 usrkeys = 463463 avg-key = 20.00 avg-zkey = 1.90 avg-val = 123.80 avg-zval = 39.78 TagRS{ kinds = RS_Key0_Tag1 bytes = 0 } TagArray{ size = 463463 bytes = 1506272 } seq expand size = 3244241 multi value expand size = 0 cnt WriteAppend = 13 UnZipSize{ index = 0.0093 GB value = 0.0541 GB dict = 0.54 MB all = 0.0671 GB } __ZipSize{ index = 0.0009 GB value = 0.0184 GB dict = 0.54 MB all = 0.0214 GB } UnZip/Zip{ index = 10.5027 value = 2.9364 dict = 1.00 all = 3.1400 } Zip/UnZip{ index = 0.0952 value = 0.3406 dict = 1.00 all = 0.3185 } ---------------------------- total value len = 207.937005 GB avg = 0.175 KB (by entry num) total key len = 24.884789 GB avg = 0.021 KB total ukey len = 13.390866 GB avg = 0.010 KB total ukey num = 1.398841159 Billion total entry num = 1.188992438 Billion write speed all = 55.025989455 MB/sec (with seq num) write speed all = 52.777901450 MB/sec (without seq num) 2024/07/08-15:52:34.276534 139818822035008 [compaction_job.cc:1944] [default] [JOB 4460] Generated table #12629401: 463463 keys, 21372380 bytes, temperature: kWarm 2024/07/08-15:52:34.276613 139818822035008 EVENT_LOG_v1 {"time_micros": 1720425154276568, "cf_name": "default", "job": 4460, "event": "table_file_creation", "file_number": 12629401, "file_size": 21372380, "file_checksum": "", "file_checksum_func_name": "Unknown", "smallest_seqno": 147218678906, "largest_seqno": 147254998070, "table_properties": {"data_size": 18435072, "index_size": 882560, "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": 12976964, "raw_average_key_size": 28, "raw_value_size": 54131986, "raw_average_value_size": 116, "num_data_blocks": 1, "num_entries": 463463, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 28, "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": 1720425152, "oldest_key_time": 0, "file_creation_time": 1720425152, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "a007a635-5c0a-4b4a-be96-b9c695cb016b", "db_session_id": "465QC0QPK7Q93426EREI", "orig_file_number": 12629401, "seqno_to_time_mapping": "N/A", "__indexstats__": "[...1 records...]"}} 2024/07/08-15:52:34.299520 139818822035008 [top_zip_table_builder.cc:934] ToplingZipTableBuilder(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629402.sst) /dev/shm/ToplingTemp/Topling-30251-rEZyoF 2024/07/08-15:52:35.080178 139818822035008 [top_zip_table_builder.cc:1344] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629402.sst): first pass time = 0.78's, 85.969'MB/sec 2024/07/08-15:52:35.959998 139818822035008 [top_zip_table_builder.cc:2764] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629402.sst): old prealloc_size = 73819750, real_size = 19817136 2024/07/08-15:52:35.960423 139818822035008 [top_zip_table_builder.cc:1765] BuildReorderMap(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629402.sst): index type = NestLoudsTrieDAWG_Mixed_XL_256_32_FL, store type = DictZipBlobStore usrkeys = 463760 prefix = 4 raw-key = 0.0074 GB zip-key = 0.0009 GB avg-key = 16.00 avg-zkey = 1.89 raw-val = 0.0541 GB zip-val = 0.0188 GB avg-val = 116.71 avg-zval = 40.59 2024/07/08-15:52:35.960846 139818822035008 [top_zip_table_builder.cc:1295] /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629402.sst: sumWaitingMem = 0.001 GB, sumWorkingMem = 0.007 GB, reorder workingMem = 0.0011 GB, waited 0.000 sec, Key+Value = 0.067 GB 2024/07/08-15:52:36.502574 139818822035008 [top_zip_table_builder.cc:3092] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629402.sst): second pass time = 0.88's, 61.575'MB/sec, value only(80.7% of KV) wait indexing time = 0.00's, remap KeyValue time = 0.54's, 40.103'MB/sec (all stages of remap) Get OrderMap time = 0.00's, 2206.192'MB/sec (index lex order gen) rebuild zvType time = 0.41's, 0.283'MB/sec write SST data time = 0.13's, 164.028'MB/sec dict compress time = 4356233619.02's, 0.000'MB/sec z-dict build time = 0.00's, sample length = 0.545'MB, throughput = 15915.259'MB/sec zip my value time = 0.88's, unzip length = 0.054'GB zip my value throughput = 61.575'MB/sec zip pipeline throughput = 62.914'MB/sec entries = 463760 avg-key = 28.00 avg-zkey = 1.89 avg-val = 116.71 avg-zval = 40.59 usrkeys = 463760 avg-key = 20.00 avg-zkey = 1.89 avg-val = 123.71 avg-zval = 40.59 TagRS{ kinds = RS_Key0_Tag1 bytes = 0 } TagArray{ size = 463760 bytes = 1507232 } seq expand size = 3246320 multi value expand size = 0 cnt WriteAppend = 13 UnZipSize{ index = 0.0093 GB value = 0.0541 GB dict = 0.54 MB all = 0.0671 GB } __ZipSize{ index = 0.0009 GB value = 0.0188 GB dict = 0.54 MB all = 0.0218 GB } UnZip/Zip{ index = 10.5746 value = 2.8753 dict = 1.00 all = 3.0843 } Zip/UnZip{ index = 0.0946 value = 0.3478 dict = 1.00 all = 0.3242 } ---------------------------- total value len = 207.994375 GB avg = 0.175 KB (by entry num) total key len = 24.897774 GB avg = 0.021 KB total ukey len = 13.400141 GB avg = 0.010 KB total ukey num = 1.399304919 Billion total entry num = 1.189456198 Billion write speed all = 55.013302522 MB/sec (with seq num) write speed all = 52.765535431 MB/sec (without seq num) 2024/07/08-15:52:36.534251 139818822035008 [compaction_job.cc:1944] [default] [JOB 4460] Generated table #12629402: 463760 keys, 21758492 bytes, temperature: kWarm 2024/07/08-15:52:36.534318 139818822035008 EVENT_LOG_v1 {"time_micros": 1720425156534284, "cf_name": "default", "job": 4460, "event": "table_file_creation", "file_number": 12629402, "file_size": 21758492, "file_checksum": "", "file_checksum_func_name": "Unknown", "smallest_seqno": 147218677593, "largest_seqno": 147254997923, "table_properties": {"data_size": 18823904, "index_size": 877120, "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": 12985280, "raw_average_key_size": 28, "raw_value_size": 54123636, "raw_average_value_size": 116, "num_data_blocks": 1, "num_entries": 463760, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 28, "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": 1720425154, "oldest_key_time": 0, "file_creation_time": 1720425154, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "a007a635-5c0a-4b4a-be96-b9c695cb016b", "db_session_id": "465QC0QPK7Q93426EREI", "orig_file_number": 12629402, "seqno_to_time_mapping": "N/A", "__indexstats__": "[...1 records...]"}} 2024/07/08-15:52:36.559402 139818822035008 [top_zip_table_builder.cc:934] ToplingZipTableBuilder(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629403.sst) /dev/shm/ToplingTemp/Topling-30251-L65tnE 2024/07/08-15:52:37.059579 139818822035008 [top_zip_table_builder.cc:1344] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629403.sst): first pass time = 0.50's, 134.184'MB/sec 2024/07/08-15:52:37.773704 139818822035008 [top_zip_table_builder.cc:2764] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629403.sst): old prealloc_size = 73819750, real_size = 19433936 2024/07/08-15:52:37.774049 139818822035008 [top_zip_table_builder.cc:1765] BuildReorderMap(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629403.sst): index type = NestLoudsTrieDAWG_Mixed_XL_256_32_FL, store type = DictZipBlobStore usrkeys = 463720 prefix = 4 raw-key = 0.0074 GB zip-key = 0.0009 GB avg-key = 16.00 avg-zkey = 1.90 raw-val = 0.0541 GB zip-val = 0.0184 GB avg-val = 116.72 avg-zval = 39.75 2024/07/08-15:52:37.774480 139818822035008 [top_zip_table_builder.cc:1295] /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629403.sst: sumWaitingMem = 0.001 GB, sumWorkingMem = 0.007 GB, reorder workingMem = 0.0011 GB, waited 0.000 sec, Key+Value = 0.067 GB 2024/07/08-15:52:38.140218 139818822035008 [top_zip_table_builder.cc:3092] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629403.sst): second pass time = 0.71's, 75.866'MB/sec, value only(80.7% of KV) wait indexing time = 0.00's, remap KeyValue time = 0.37's, 58.325'MB/sec (all stages of remap) Get OrderMap time = 0.00's, 2778.110'MB/sec (index lex order gen) rebuild zvType time = 0.30's, 0.389'MB/sec write SST data time = 0.07's, 315.186'MB/sec dict compress time = 4356233619.02's, 0.000'MB/sec z-dict build time = 0.00's, sample length = 0.545'MB, throughput = 12913.663'MB/sec zip my value time = 0.71's, unzip length = 0.054'GB zip my value throughput = 75.866'MB/sec zip pipeline throughput = 75.866'MB/sec entries = 463720 avg-key = 28.00 avg-zkey = 1.90 avg-val = 116.72 avg-zval = 39.75 usrkeys = 463720 avg-key = 20.00 avg-zkey = 1.90 avg-val = 123.72 avg-zval = 39.75 TagRS{ kinds = RS_Key0_Tag1 bytes = 0 } TagArray{ size = 463720 bytes = 1507104 } seq expand size = 3246040 multi value expand size = 0 cnt WriteAppend = 15 UnZipSize{ index = 0.0093 GB value = 0.0541 GB dict = 0.54 MB all = 0.0671 GB } __ZipSize{ index = 0.0009 GB value = 0.0184 GB dict = 0.54 MB all = 0.0214 GB } UnZip/Zip{ index = 10.5001 value = 2.9360 dict = 1.00 all = 3.1396 } Zip/UnZip{ index = 0.0952 value = 0.3406 dict = 1.00 all = 0.3185 } ---------------------------- total value len = 208.051746 GB avg = 0.175 KB (by entry num) total key len = 24.910759 GB avg = 0.021 KB total ukey len = 13.409415 GB avg = 0.010 KB total ukey num = 1.399768639 Billion total entry num = 1.189919918 Billion write speed all = 55.008642129 MB/sec (with seq num) write speed all = 52.760868253 MB/sec (without seq num) 2024/07/08-15:52:38.177094 139818822035008 [compaction_job.cc:1944] [default] [JOB 4460] Generated table #12629403: 463720 keys, 21375308 bytes, temperature: kWarm 2024/07/08-15:52:38.177167 139818822035008 EVENT_LOG_v1 {"time_micros": 1720425158177132, "cf_name": "default", "job": 4460, "event": "table_file_creation", "file_number": 12629403, "file_size": 21375308, "file_checksum": "", "file_checksum_func_name": "Unknown", "smallest_seqno": 147189446149, "largest_seqno": 147254997022, "table_properties": {"data_size": 18434560, "index_size": 883264, "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": 12984160, "raw_average_key_size": 28, "raw_value_size": 54124760, "raw_average_value_size": 116, "num_data_blocks": 1, "num_entries": 463720, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 28, "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": 1720425156, "oldest_key_time": 0, "file_creation_time": 1720425156, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "a007a635-5c0a-4b4a-be96-b9c695cb016b", "db_session_id": "465QC0QPK7Q93426EREI", "orig_file_number": 12629403, "seqno_to_time_mapping": "N/A", "__indexstats__": "[...1 records...]"}} 2024/07/08-15:52:38.204088 139818822035008 [top_zip_table_builder.cc:934] ToplingZipTableBuilder(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629404.sst) /dev/shm/ToplingTemp/Topling-30251-pc3CLD 2024/07/08-15:52:38.883285 139818822035008 [top_zip_table_builder.cc:1344] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629404.sst): first pass time = 0.68's, 98.814'MB/sec 2024/07/08-15:52:39.968059 139818822035008 [top_zip_table_builder.cc:2764] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629404.sst): old prealloc_size = 73819750, real_size = 19470864 2024/07/08-15:52:39.968420 139818822035008 [top_zip_table_builder.cc:1765] BuildReorderMap(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629404.sst): index type = NestLoudsTrieDAWG_Mixed_XL_256_32_FL, store type = DictZipBlobStore usrkeys = 465297 prefix = 4 raw-key = 0.0074 GB zip-key = 0.0009 GB avg-key = 16.00 avg-zkey = 1.93 raw-val = 0.0541 GB zip-val = 0.0185 GB avg-val = 116.23 avg-zval = 39.67 2024/07/08-15:52:39.968839 139818822035008 [top_zip_table_builder.cc:1295] /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629404.sst: sumWaitingMem = 0.001 GB, sumWorkingMem = 0.007 GB, reorder workingMem = 0.0011 GB, waited 0.000 sec, Key+Value = 0.067 GB 2024/07/08-15:52:40.333159 139818822035008 [top_zip_table_builder.cc:3092] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629404.sst): second pass time = 1.08's, 49.887'MB/sec, value only(80.6% of KV) wait indexing time = 0.00's, remap KeyValue time = 0.37's, 58.818'MB/sec (all stages of remap) Get OrderMap time = 0.00's, 2643.407'MB/sec (index lex order gen) rebuild zvType time = 0.30's, 0.390'MB/sec write SST data time = 0.07's, 323.350'MB/sec dict compress time = 4356233619.02's, 0.000'MB/sec z-dict build time = 0.00's, sample length = 0.544'MB, throughput = 13826.405'MB/sec zip my value time = 1.08's, unzip length = 0.054'GB zip my value throughput = 49.887'MB/sec zip pipeline throughput = 99.483'MB/sec entries = 465297 avg-key = 28.00 avg-zkey = 1.93 avg-val = 116.23 avg-zval = 39.67 usrkeys = 465297 avg-key = 20.00 avg-zkey = 1.93 avg-val = 123.23 avg-zval = 39.67 TagRS{ kinds = RS_Key0_Tag1 bytes = 0 } TagArray{ size = 465297 bytes = 1570400 } seq expand size = 3257079 multi value expand size = 0 cnt WriteAppend = 14 UnZipSize{ index = 0.0093 GB value = 0.0541 GB dict = 0.54 MB all = 0.0671 GB } __ZipSize{ index = 0.0009 GB value = 0.0185 GB dict = 0.54 MB all = 0.0215 GB } UnZip/Zip{ index = 10.3668 value = 2.9301 dict = 1.00 all = 3.1251 } Zip/UnZip{ index = 0.0965 value = 0.3413 dict = 1.00 all = 0.3200 } ---------------------------- total value len = 208.109084 GB avg = 0.175 KB (by entry num) total key len = 24.923787 GB avg = 0.021 KB total ukey len = 13.418721 GB avg = 0.010 KB total ukey num = 1.400233936 Billion total entry num = 1.190385215 Billion write speed all = 54.996779220 MB/sec (with seq num) write speed all = 52.749290178 MB/sec (without seq num) 2024/07/08-15:52:40.367364 139818822035008 [compaction_job.cc:1944] [default] [JOB 4460] Generated table #12629404: 465297 keys, 21474090 bytes, temperature: kWarm 2024/07/08-15:52:40.367433 139818822035008 EVENT_LOG_v1 {"time_micros": 1720425160367399, "cf_name": "default", "job": 4460, "event": "table_file_creation", "file_number": 12629404, "file_size": 21474090, "file_checksum": "", "file_checksum_func_name": "Unknown", "smallest_seqno": 147186400866, "largest_seqno": 147254998036, "table_properties": {"data_size": 18456704, "index_size": 897664, "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": 13028316, "raw_average_key_size": 28, "raw_value_size": 54080642, "raw_average_value_size": 116, "num_data_blocks": 1, "num_entries": 465297, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 28, "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": 1720425158, "oldest_key_time": 0, "file_creation_time": 1720425158, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "a007a635-5c0a-4b4a-be96-b9c695cb016b", "db_session_id": "465QC0QPK7Q93426EREI", "orig_file_number": 12629404, "seqno_to_time_mapping": "N/A", "__indexstats__": "[...1 records...]"}} 2024/07/08-15:52:40.391908 139818822035008 [top_zip_table_builder.cc:934] ToplingZipTableBuilder(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629405.sst) /dev/shm/ToplingTemp/Topling-30251-BepCcF 2024/07/08-15:52:40.601369 139818822035008 [top_zip_table_builder.cc:1344] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629405.sst): first pass time = 0.21's, 256.262'MB/sec 2024/07/08-15:52:41.138937 139818822035008 [top_zip_table_builder.cc:2764] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629405.sst): old prealloc_size = 73819750, real_size = 15635872 2024/07/08-15:52:41.139229 139818822035008 [top_zip_table_builder.cc:1765] BuildReorderMap(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629405.sst): index type = NestLoudsTrieDAWG_Mixed_XL_256_32_FL, store type = DictZipBlobStore usrkeys = 370528 prefix = 4 raw-key = 0.0059 GB zip-key = 0.0007 GB avg-key = 16.00 avg-zkey = 1.90 raw-val = 0.0433 GB zip-val = 0.0148 GB avg-val = 116.83 avg-zval = 40.04 2024/07/08-15:52:41.139577 139818822035008 [top_zip_table_builder.cc:1295] /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629405.sst: sumWaitingMem = 0.001 GB, sumWorkingMem = 0.007 GB, reorder workingMem = 0.0009 GB, waited 0.000 sec, Key+Value = 0.054 GB 2024/07/08-15:52:41.432103 139818822035008 [top_zip_table_builder.cc:3092] ToplingZipTableBuilder::Finish(/storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00/12629405.sst): second pass time = 0.54's, 80.655'MB/sec, value only(80.7% of KV) wait indexing time = 0.00's, remap KeyValue time = 0.29's, 58.628'MB/sec (all stages of remap) Get OrderMap time = 0.00's, 2669.248'MB/sec (index lex order gen) rebuild zvType time = 0.24's, 0.387'MB/sec write SST data time = 0.05's, 319.931'MB/sec dict compress time = 4356233619.02's, 0.000'MB/sec z-dict build time = 0.00's, sample length = 0.437'MB, throughput = 11370.000'MB/sec zip my value time = 0.54's, unzip length = 0.043'GB zip my value throughput = 80.655'MB/sec zip pipeline throughput = 80.655'MB/sec entries = 370528 avg-key = 28.00 avg-zkey = 1.90 avg-val = 116.83 avg-zval = 40.04 usrkeys = 370528 avg-key = 20.00 avg-zkey = 1.90 avg-val = 123.83 avg-zval = 40.04 TagRS{ kinds = RS_Key0_Tag1 bytes = 0 } TagArray{ size = 370528 bytes = 1204224 } seq expand size = 2593696 multi value expand size = 0 cnt WriteAppend = 12 UnZipSize{ index = 0.0074 GB value = 0.0433 GB dict = 0.44 MB all = 0.0537 GB } __ZipSize{ index = 0.0007 GB value = 0.0148 GB dict = 0.44 MB all = 0.0172 GB } UnZip/Zip{ index = 10.4996 value = 2.9176 dict = 1.00 all = 3.1224 } Zip/UnZip{ index = 0.0952 value = 0.3427 dict = 1.00 all = 0.3203 } ---------------------------- total value len = 208.154967 GB avg = 0.175 KB (by entry num) total key len = 24.934162 GB avg = 0.021 KB total ukey len = 13.426132 GB avg = 0.010 KB total ukey num = 1.400604464 Billion total entry num = 1.190755743 Billion write speed all = 54.995792972 MB/sec (with seq num) write speed all = 52.748187289 MB/sec (without seq num) 2024/07/08-15:52:41.460568 139818822035008 [compaction_job.cc:1944] [default] [JOB 4460] Generated table #12629405: 370528 keys, 17187152 bytes, temperature: kWarm 2024/07/08-15:52:41.460637 139818822035008 EVENT_LOG_v1 {"time_micros": 1720425161460602, "cf_name": "default", "job": 4460, "event": "table_file_creation", "file_number": 12629405, "file_size": 17187152, "file_checksum": "", "file_checksum_func_name": "Unknown", "smallest_seqno": 147186686589, "largest_seqno": 147253259378, "table_properties": {"data_size": 14837264, "index_size": 705792, "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": 10374784, "raw_average_key_size": 28, "raw_value_size": 43289896, "raw_average_value_size": 116, "num_data_blocks": 1, "num_entries": 370528, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 28, "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": 1720425160, "oldest_key_time": 0, "file_creation_time": 1720425160, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "a007a635-5c0a-4b4a-be96-b9c695cb016b", "db_session_id": "465QC0QPK7Q93426EREI", "orig_file_number": 12629405, "seqno_to_time_mapping": "N/A", "__indexstats__": "[...1 records...]"}} 2024/07/08-15:52:41.472943 139818822035008 [compaction_job.cc:699] job-04460: subcompact[0], size: 0.103167 G, files: /storage/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/mytopling/.rocksdb/job-04460/att-00 [12629401,12629402,12629403,12629404,12629405] 2024/07/08-15:52:41.501692 139818822035008 (Original Log Time 2024/07/08-15:52:31.698595) EVENT_LOG_v1 {"time_micros": 1720425151698532, "job": 4460, "event": "compaction_started", "compaction_reason": "FilesMarkedForCompaction", "files_L1": [12629379], "files_L2": [12629354, 12629355, 12629356, 12629357, 12629314], "score": 0.703677, "input_data_size": 128143929, "oldest_snapshot_seqno": 147255645164} 2024/07/08-15:52:41.501696 139818822035008 (Original Log Time 2024/07/08-15:52:41.501126) [compaction_job.cc:2018] [default] [JOB 4460] Compacted 1@1 + 5@2 files to L2 => 103167422 bytes 2024/07/08-15:52:41.501697 139818822035008 (Original Log Time 2024/07/08-15:52:41.501626) [compaction_job.cc:1220] [default] compacted to: files[0 0 5 0 0 0 0] max score 0.04, MB/sec: 13.1 rd, 10.6 wr, level 2, files in(1, 5) out(5 +0 blob) MB in(31.8, 90.4 +0.0 blob) out(98.4 +0.0 blob), read-write-amplify(6.9) write-amplify(3.1) OK, records in: 2273185, records dropped: 46417 output_compression: Snappy 2024/07/08-15:52:41.501704 139818822035008 (Original Log Time 2024/07/08-15:52:41.501671) EVENT_LOG_v1 {"time_micros": 1720425161501652, "cf": "default", "job": 4460, "event": "compaction_finished", "compaction_time_micros": 9774354, "compaction_time_cpu_micros": 3985107, "output_level": 2, "num_output_files": 5, "total_output_size": 103167422, "num_input_records": 2273185, "num_output_records": 2226768, "num_subcompactions": 1, "output_compression": "Snappy", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "file_write_nanos": 69533011, "file_range_sync_nanos": 0, "file_fsync_nanos": 4652, "file_prepare_write_nanos": 16232, "lsm_state": [0, 0, 5, 0, 0, 0, 0]} 2024/07/08-15:52:41.632038 139818822035008 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":"a007a635-5c0a-4b4a-be96-b9c695cb016b","dbStarts":1720420896,"starts":1720425151,"executesMs":9928,"compactionJobId":4460,"attempt":0,"compactionInputRawBytes":328691638,"compactionInputZipBytes":128143929,"compactionOutputRawBytes":0,"compactionOutputZipBytes":103167422,"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-d12a8d2d3267188a5e6469258e9a61d3-be48fe71d5cbec81-00"}}, response = 2024/07/08-15:52:41.632138 139818822035008 INFO dcompact_worker.cpp:1456: finish /worker/dcompact-log/nfs/i-wz9deglxdazgiryp6ltb_10.57.5.137/2024-07-08T14.41.36/.rocksdb/job-04460/att-00: olev 2, work 9.929 s, result 5.170 ms, install 0.603 ms, input{raw 313.465 MiB zip 122.208 MiB}