[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:54.164026 32343 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.149.254:38529
I20260812 06:19:54.165271 32343 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:54.165925 32343 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:54.172931 32350 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:54.172931 32343 server_base.cc:1061] running on GCE node
W20260812 06:19:54.173292 32349 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:54.173471 32354 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:54.174073 32343 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:54.174228 32343 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:54.174305 32343 hybrid_clock.cc:648] HybridClock initialized: now 1786515594174301 us; error 0 us; skew 500 ppm
I20260812 06:19:54.176493 32343 webserver.cc:533] Webserver started at http://127.31.149.254:38807/ using document root <none> and password file <none>
I20260812 06:19:54.177126 32343 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:54.177230 32343 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:54.177500 32343 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:54.179306 32343 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/master-0-root/instance:
uuid: "7000cf1f0ecf4f64bbdc36175a04f6e5"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-njxd"
I20260812 06:19:54.183108 32343 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:19:54.185680 32359 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:54.186866 32343 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:54.187059 32343 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/master-0-root
uuid: "7000cf1f0ecf4f64bbdc36175a04f6e5"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-njxd"
I20260812 06:19:54.187198 32343 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:54.204123 32343 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:54.204886 32343 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:54.205106 32343 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:54.213631 32343 rpc_server.cc:307] RPC server started. Bound to: 127.31.149.254:38529
I20260812 06:19:54.213711 32420 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.149.254:38529 every 8 connection(s)
I20260812 06:19:54.216127 32421 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:54.222169 32421 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5: Bootstrap starting.
I20260812 06:19:54.224743 32421 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:54.225889 32421 log.cc:826] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:54.227777 32421 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5: No bootstrap required, opened a new log
I20260812 06:19:54.230842 32421 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7000cf1f0ecf4f64bbdc36175a04f6e5" member_type: VOTER }
I20260812 06:19:54.231029 32421 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:54.231134 32421 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7000cf1f0ecf4f64bbdc36175a04f6e5, State: Initialized, Role: FOLLOWER
I20260812 06:19:54.231813 32421 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7000cf1f0ecf4f64bbdc36175a04f6e5" member_type: VOTER }
I20260812 06:19:54.231997 32421 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:54.232074 32421 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:54.232272 32421 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:54.233160 32421 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7000cf1f0ecf4f64bbdc36175a04f6e5" member_type: VOTER }
I20260812 06:19:54.233712 32421 leader_election.cc:304] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: 7000cf1f0ecf4f64bbdc36175a04f6e5; no voters: 
I20260812 06:19:54.234071 32421 leader_election.cc:290] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:54.234216 32424 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:54.234542 32424 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [term 1 LEADER]: Becoming Leader. State: Replica: 7000cf1f0ecf4f64bbdc36175a04f6e5, State: Running, Role: LEADER
I20260812 06:19:54.234983 32424 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7000cf1f0ecf4f64bbdc36175a04f6e5" member_type: VOTER }
I20260812 06:19:54.235278 32421 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:54.237118 32426 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7000cf1f0ecf4f64bbdc36175a04f6e5. Latest consensus state: current_term: 1 leader_uuid: "7000cf1f0ecf4f64bbdc36175a04f6e5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7000cf1f0ecf4f64bbdc36175a04f6e5" member_type: VOTER } }
I20260812 06:19:54.237860 32426 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:54.237788 32343 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:54.237149 32425 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7000cf1f0ecf4f64bbdc36175a04f6e5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7000cf1f0ecf4f64bbdc36175a04f6e5" member_type: VOTER } }
I20260812 06:19:54.238135 32425 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [sys.catalog]: This master's current role is: LEADER
W20260812 06:19:54.240039 32440 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:54.240109 32440 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:54.240211 32441 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:54.240978 32441 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:54.246592 32441 catalog_manager.cc:1383] Generated new cluster ID: ade699107ae340af898f2b62a27c94a4
I20260812 06:19:54.246687 32441 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:54.255704 32441 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:54.256923 32441 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:54.266002 32441 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5: Generated new TSK 0
I20260812 06:19:54.266850 32441 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:54.270901 32343 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:54.274200 32449 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:54.274222 32446 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:54.274214 32447 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:54.274323 32343 server_base.cc:1061] running on GCE node
I20260812 06:19:54.274698 32343 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:54.274748 32343 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:54.274770 32343 hybrid_clock.cc:648] HybridClock initialized: now 1786515594274770 us; error 0 us; skew 500 ppm
I20260812 06:19:54.275753 32343 webserver.cc:533] Webserver started at http://127.31.149.193:36939/ using document root <none> and password file <none>
I20260812 06:19:54.275929 32343 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:54.275987 32343 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:54.276087 32343 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:54.276546 32343 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/instance:
uuid: "8dcc9668e08941f4930e969e1c4c99ef"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-njxd"
I20260812 06:19:54.278533 32343 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:19:54.279729 32454 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:54.280076 32343 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:54.280146 32343 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root
uuid: "8dcc9668e08941f4930e969e1c4c99ef"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-njxd"
I20260812 06:19:54.280247 32343 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:54.286334 32343 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:54.286834 32343 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:54.287351 32343 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:54.288275 32343 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:54.288331 32343 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:54.288405 32343 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:54.288445 32343 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:54.295558 32343 rpc_server.cc:307] RPC server started. Bound to: 127.31.149.193:34289
I20260812 06:19:54.295588 32529 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.149.193:34289 every 8 connection(s)
I20260812 06:19:54.311987 32530 heartbeater.cc:344] Connected to a master server at 127.31.149.254:38529
I20260812 06:19:54.312330 32530 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:54.312844 32530 heartbeater.cc:507] Master 127.31.149.254:38529 requested a full tablet report, sending...
I20260812 06:19:54.314414 32375 ts_manager.cc:194] Registered new tserver with Master: 8dcc9668e08941f4930e969e1c4c99ef (127.31.149.193:34289)
I20260812 06:19:54.314507 32343 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.018205583s
I20260812 06:19:54.315783 32375 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48864
I20260812 06:19:54.325021 32375 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48866:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:54.340298 32487 tablet_service.cc:1511] Processing CreateTablet for tablet 7ae91e47a04541fc8deb1862fafcaffe (DEFAULT_TABLE table=heavy-update-compaction-test [id=012e4afff9ca43318b39f7b55be9cbdb]), partition=
I20260812 06:19:54.340801 32487 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7ae91e47a04541fc8deb1862fafcaffe. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:54.343616 32542 tablet_bootstrap.cc:492] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Bootstrap starting.
I20260812 06:19:54.344798 32542 tablet_bootstrap.cc:654] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:54.346206 32542 tablet_bootstrap.cc:492] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: No bootstrap required, opened a new log
I20260812 06:19:54.346323 32542 ts_tablet_manager.cc:1403] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:54.346814 32542 raft_consensus.cc:359] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8dcc9668e08941f4930e969e1c4c99ef" member_type: VOTER last_known_addr { host: "127.31.149.193" port: 34289 } }
I20260812 06:19:54.346948 32542 raft_consensus.cc:385] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:54.346983 32542 raft_consensus.cc:740] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8dcc9668e08941f4930e969e1c4c99ef, State: Initialized, Role: FOLLOWER
I20260812 06:19:54.347160 32542 consensus_queue.cc:260] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8dcc9668e08941f4930e969e1c4c99ef" member_type: VOTER last_known_addr { host: "127.31.149.193" port: 34289 } }
I20260812 06:19:54.347268 32542 raft_consensus.cc:399] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:54.347306 32542 raft_consensus.cc:493] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:54.347357 32542 raft_consensus.cc:3060] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:54.348349 32542 raft_consensus.cc:515] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8dcc9668e08941f4930e969e1c4c99ef" member_type: VOTER last_known_addr { host: "127.31.149.193" port: 34289 } }
I20260812 06:19:54.348497 32542 leader_election.cc:304] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: 8dcc9668e08941f4930e969e1c4c99ef; no voters: 
I20260812 06:19:54.348716 32542 leader_election.cc:290] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:54.348877 32544 raft_consensus.cc:2804] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:54.349089 32542 ts_tablet_manager.cc:1434] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:54.349195 32544 raft_consensus.cc:697] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [term 1 LEADER]: Becoming Leader. State: Replica: 8dcc9668e08941f4930e969e1c4c99ef, State: Running, Role: LEADER
I20260812 06:19:54.349723 32530 heartbeater.cc:499] Master 127.31.149.254:38529 was elected leader, sending a full tablet report...
I20260812 06:19:54.350055 32544 consensus_queue.cc:237] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8dcc9668e08941f4930e969e1c4c99ef" member_type: VOTER last_known_addr { host: "127.31.149.193" port: 34289 } }
I20260812 06:19:54.352916 32375 catalog_manager.cc:5719] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef reported cstate change: term changed from 0 to 1, leader changed from <none> to 8dcc9668e08941f4930e969e1c4c99ef (127.31.149.193). New cstate: current_term: 1 leader_uuid: "8dcc9668e08941f4930e969e1c4c99ef" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8dcc9668e08941f4930e969e1c4c99ef" member_type: VOTER last_known_addr { host: "127.31.149.193" port: 34289 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:54.433429 32343 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.070s	user 0.025s	sys 0.008s
I20260812 06:19:54.546840 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushMRSOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=15.086190
I20260812 06:19:54.703687 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushMRSOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.156s	user 0.114s	sys 0.040s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":74,"delete_count":0,"dirs.queue_time_us":40,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":987,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38080,"lbm_writes_lt_1ms":567,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1050}
I20260812 06:19:54.704797 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling LogGCOp(7ae91e47a04541fc8deb1862fafcaffe): free 11976772 bytes of WAL
I20260812 06:19:54.705140 32459 log_reader.cc:385] T 7ae91e47a04541fc8deb1862fafcaffe: removed 1 log segments from log reader
I20260812 06:19:54.705231 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000001 (ops 1-6)
I20260812 06:19:54.707976 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: LogGCOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:54.708361 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling UndoDeltaBlockGCOp(7ae91e47a04541fc8deb1862fafcaffe): 12308958 bytes on disk
I20260812 06:19:54.709084 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: UndoDeltaBlockGCOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:19:54.709807 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:54.727927 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5527,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.728468 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:54.840727 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.112s	user 0.088s	sys 0.024s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":646,"lbm_read_time_us":7315,"lbm_reads_lt_1ms":360,"lbm_write_time_us":19279,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":348,"threads_started":5,"update_count":1500}
I20260812 06:19:54.841316 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=10.126437
I20260812 06:19:54.887667 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.046s	user 0.027s	sys 0.009s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":16503,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:54.888264 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:54.899348 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4198,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.899961 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:55.035045 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.135s	user 0.110s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1164,"lbm_read_time_us":7470,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27836,"lbm_writes_lt_1ms":443,"mutex_wait_us":281,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:55.035606 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=10.126437
I20260812 06:19:55.095772 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.060s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15720,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.096341 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:55.107343 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.107939 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:55.272264 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.164s	user 0.102s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":370,"lbm_read_time_us":10597,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26217,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.272899 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=10.126437
I20260812 06:19:55.326378 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.053s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17176,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.326975 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:55.342585 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5894,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.343179 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:55.482080 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.139s	user 0.107s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":60,"lbm_read_time_us":10924,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24646,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:19:55.482755 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=10.126437
I20260812 06:19:55.523738 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.041s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17754,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.524376 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:55.538215 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4675,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.538748 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:55.672586 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.134s	user 0.114s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1287,"lbm_read_time_us":9720,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26064,"lbm_writes_lt_1ms":443,"mutex_wait_us":111,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:19:55.673347 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=10.126437
I20260812 06:19:55.723860 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.050s	user 0.014s	sys 0.031s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16421,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.724529 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:55.735670 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.736261 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:55.886353 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.150s	user 0.117s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":479,"lbm_read_time_us":10477,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24003,"lbm_writes_lt_1ms":443,"mutex_wait_us":96,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2000}
I20260812 06:19:55.887151 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=10.126437
I20260812 06:19:55.929877 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.043s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21686,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.930373 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:55.945425 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5622,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.945946 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:56.079954 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.134s	user 0.104s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":799,"lbm_read_time_us":9602,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28621,"lbm_writes_lt_1ms":443,"mutex_wait_us":116,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23808,"update_count":2000}
I20260812 06:19:56.080884 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=10.126437
I20260812 06:19:56.126055 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.045s	user 0.034s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18649,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:56.126626 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:56.138147 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.138671 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushMRSOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:56.170957 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushMRSOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.032s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":104,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1478,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1873,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:56.171809 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling LogGCOp(7ae91e47a04541fc8deb1862fafcaffe): free 129773541 bytes of WAL
I20260812 06:19:56.172060 32459 log_reader.cc:385] T 7ae91e47a04541fc8deb1862fafcaffe: removed 13 log segments from log reader
I20260812 06:19:56.172106 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000002 (ops 7-11)
I20260812 06:19:56.172133 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000003 (ops 12-16)
I20260812 06:19:56.172185 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000004 (ops 17-21)
I20260812 06:19:56.172235 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000005 (ops 22-26)
I20260812 06:19:56.172256 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000006 (ops 27-30)
I20260812 06:19:56.172314 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000007 (ops 31-35)
I20260812 06:19:56.172365 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000008 (ops 36-40)
I20260812 06:19:56.172403 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000009 (ops 41-45)
I20260812 06:19:56.172443 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000010 (ops 46-50)
I20260812 06:19:56.172482 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000011 (ops 51-55)
I20260812 06:19:56.172521 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000012 (ops 56-60)
I20260812 06:19:56.172559 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000013 (ops 61-65)
I20260812 06:19:56.172596 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000014 (ops 66-70)
I20260812 06:19:56.200559 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: LogGCOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:56.200992 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=4.173312
I20260812 06:19:56.218744 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":5620561,"delete_count":0,"lbm_write_time_us":6800,"lbm_writes_lt_1ms":140,"reinsert_count":0,"update_count":685}
I20260812 06:19:56.219321 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.196750
I20260812 06:19:56.232218 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2584729,"delete_count":0,"lbm_write_time_us":4100,"lbm_writes_lt_1ms":66,"reinsert_count":0,"update_count":315}
I20260812 06:19:56.232801 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling UndoDeltaBlockGCOp(7ae91e47a04541fc8deb1862fafcaffe): 481 bytes on disk
I20260812 06:19:56.233393 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: UndoDeltaBlockGCOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4}
I20260812 06:19:56.233981 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:56.408258 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.174s	user 0.128s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836339,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1346,"lbm_read_time_us":12144,"lbm_reads_lt_1ms":666,"lbm_write_time_us":37163,"lbm_writes_lt_1ms":643,"mutex_wait_us":534,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9472,"thread_start_us":93,"threads_started":1,"update_count":3000}
I20260812 06:19:56.409931 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=14.095187
I20260812 06:19:56.465634 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.055s	user 0.039s	sys 0.013s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24652,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.466239 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:56.482740 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.483393 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:56.655766 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.172s	user 0.141s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":273,"lbm_read_time_us":9858,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33494,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:19:56.656502 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=14.095187
I20260812 06:19:56.712090 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.055s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24358,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.712692 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:56.876879 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.164s	user 0.096s	sys 0.064s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631195,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":303,"lbm_read_time_us":12164,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27967,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":78464,"update_count":2000}
I20260812 06:19:56.877530 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=11.118625
I20260812 06:19:56.908396 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.031s	user 0.015s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13687,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:56.909278 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:56.926479 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5910,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.927155 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:57.060102 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.133s	user 0.108s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":677,"lbm_read_time_us":7761,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27721,"lbm_writes_lt_1ms":443,"mutex_wait_us":324,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26112,"update_count":2000}
I20260812 06:19:57.060869 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=11.118625
I20260812 06:19:57.103354 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.042s	user 0.037s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19024,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:57.103899 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:57.122370 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.018s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5840,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:57.122954 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:57.253352 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.130s	user 0.097s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":532,"lbm_read_time_us":8283,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27543,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:19:57.254145 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=10.126437
I20260812 06:19:57.290740 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.035s	user 0.015s	sys 0.019s Metrics: {"bytes_written":12635684,"delete_count":0,"lbm_write_time_us":15481,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1540}
I20260812 06:19:57.291314 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:57.301832 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":3968,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:57.302325 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:57.440928 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.138s	user 0.109s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631306,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1180,"lbm_read_time_us":9260,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27316,"lbm_writes_lt_1ms":443,"mutex_wait_us":445,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:19:57.441859 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=10.126437
I20260812 06:19:57.489542 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.047s	user 0.017s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15064,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.490145 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:57.501441 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.502103 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:57.666165 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.164s	user 0.114s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1173,"lbm_read_time_us":11751,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23654,"lbm_writes_lt_1ms":443,"mutex_wait_us":861,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:19:57.666867 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=10.126437
I20260812 06:19:57.710346 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.043s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18964,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.710973 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:57.728538 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.017s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6077,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.729048 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushMRSOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:57.781230 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushMRSOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.052s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1489,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1779,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:57.782099 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling LogGCOp(7ae91e47a04541fc8deb1862fafcaffe): free 132571290 bytes of WAL
I20260812 06:19:57.782346 32459 log_reader.cc:385] T 7ae91e47a04541fc8deb1862fafcaffe: removed 13 log segments from log reader
I20260812 06:19:57.782389 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000015 (ops 71-74)
I20260812 06:19:57.782420 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000016 (ops 75-79)
I20260812 06:19:57.782490 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000017 (ops 80-84)
I20260812 06:19:57.782533 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000018 (ops 85-89)
I20260812 06:19:57.782574 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000019 (ops 90-94)
I20260812 06:19:57.782612 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000020 (ops 95-98)
I20260812 06:19:57.782648 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000021 (ops 99-103)
I20260812 06:19:57.782684 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000022 (ops 104-108)
I20260812 06:19:57.782725 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000023 (ops 109-113)
I20260812 06:19:57.782776 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000024 (ops 114-118)
I20260812 06:19:57.782816 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000025 (ops 119-123)
I20260812 06:19:57.782856 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000026 (ops 124-128)
I20260812 06:19:57.782896 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000027 (ops 129-133)
I20260812 06:19:57.813994 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: LogGCOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.032s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:19:57.814396 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=7.149875
I20260812 06:19:57.839922 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.025s	user 0.010s	sys 0.013s Metrics: {"bytes_written":8861468,"delete_count":0,"lbm_write_time_us":10866,"lbm_writes_lt_1ms":219,"reinsert_count":0,"update_count":1080}
I20260812 06:19:57.840515 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling UndoDeltaBlockGCOp(7ae91e47a04541fc8deb1862fafcaffe): 493 bytes on disk
I20260812 06:19:57.840989 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: UndoDeltaBlockGCOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:19:57.841547 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:57.857409 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.016s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3446255,"delete_count":0,"lbm_write_time_us":4860,"lbm_writes_lt_1ms":87,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":420}
I20260812 06:19:57.857965 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:58.097908 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.240s	user 0.151s	sys 0.082s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938773,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1177,"lbm_read_time_us":15312,"lbm_reads_lt_1ms":770,"lbm_write_time_us":41463,"lbm_writes_lt_1ms":743,"mutex_wait_us":359,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":54272,"thread_start_us":111,"threads_started":1,"update_count":3500}
I20260812 06:19:58.099748 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=16.079562
I20260812 06:19:58.149144 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.049s	user 0.033s	sys 0.012s Metrics: {"bytes_written":17722676,"delete_count":0,"lbm_write_time_us":21942,"lbm_writes_lt_1ms":435,"reinsert_count":0,"update_count":2160}
I20260812 06:19:58.149715 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.196750
I20260812 06:19:58.169385 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.019s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:19:58.169915 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:58.180907 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4226,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.181553 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:58.395167 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.213s	user 0.156s	sys 0.052s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836225,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":614,"lbm_read_time_us":14643,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33052,"lbm_writes_lt_1ms":643,"mutex_wait_us":314,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":3000}
I20260812 06:19:58.396535 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=16.079562
I20260812 06:19:58.471318 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.075s	user 0.019s	sys 0.044s Metrics: {"bytes_written":17763701,"delete_count":0,"lbm_write_time_us":32509,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":432,"reinsert_count":0,"update_count":2165}
I20260812 06:19:58.471913 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=5.165500
I20260812 06:19:58.490933 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.019s	user 0.012s	sys 0.005s Metrics: {"bytes_written":6851285,"delete_count":0,"lbm_write_time_us":8211,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:19:58.491477 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:58.708823 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.217s	user 0.139s	sys 0.077s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836143,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":187,"lbm_read_time_us":16455,"lbm_reads_lt_1ms":672,"lbm_write_time_us":38451,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":3000}
I20260812 06:19:58.710039 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=14.095187
I20260812 06:19:58.751853 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.042s	user 0.023s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18821,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.752836 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:58.781726 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.029s	user 0.004s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.782238 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:58.793365 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4246,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.794090 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:59.003705 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.209s	user 0.150s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836253,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":137,"lbm_read_time_us":14186,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37216,"lbm_writes_lt_1ms":643,"mutex_wait_us":61,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":3000}
I20260812 06:19:59.004570 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=14.095187
I20260812 06:19:59.057152 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.052s	user 0.016s	sys 0.032s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":23300,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.057806 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:59.068719 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.069267 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:59.256371 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.187s	user 0.128s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733728,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":283,"lbm_read_time_us":14995,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29421,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:19:59.257129 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=14.095187
I20260812 06:19:59.318885 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.062s	user 0.037s	sys 0.016s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":23238,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.319482 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:59.330446 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4292,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.331017 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushMRSOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:59.365417 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushMRSOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.034s	user 0.027s	sys 0.002s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":300,"dirs.run_wall_time_us":1642,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1575,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:59.366375 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling LogGCOp(7ae91e47a04541fc8deb1862fafcaffe): free 120553710 bytes of WAL
I20260812 06:19:59.366638 32459 log_reader.cc:385] T 7ae91e47a04541fc8deb1862fafcaffe: removed 12 log segments from log reader
I20260812 06:19:59.366704 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000028 (ops 134-138)
I20260812 06:19:59.366756 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000029 (ops 139-143)
I20260812 06:19:59.366829 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000030 (ops 144-148)
I20260812 06:19:59.366904 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000031 (ops 149-152)
I20260812 06:19:59.366973 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000032 (ops 153-157)
I20260812 06:19:59.367041 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000033 (ops 158-162)
I20260812 06:19:59.367103 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000034 (ops 163-166)
I20260812 06:19:59.367156 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000035 (ops 167-171)
I20260812 06:19:59.367199 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000036 (ops 172-176)
I20260812 06:19:59.367244 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000037 (ops 177-181)
I20260812 06:19:59.367285 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000038 (ops 182-186)
I20260812 06:19:59.367312 32459 log.cc:1079] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/7ae91e47a04541fc8deb1862fafcaffe/wal-000000039 (ops 187-191)
I20260812 06:19:59.392041 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: LogGCOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:59.392586 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:59.414119 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.021s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5747,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.414631 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=2.188937
I20260812 06:19:59.425247 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: FlushDeltaMemStoresOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3954,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.425810 32531 maintenance_manager.cc:419] P 8dcc9668e08941f4930e969e1c4c99ef: Scheduling MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe): perf score=1.000000
I20260812 06:19:59.517134 32343 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.084s	user 1.860s	sys 0.164s
I20260812 06:19:59.616963 32343 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.099s	user 0.002s	sys 0.000s
I20260812 06:19:59.617832 32343 tablet_server.cc:179] TabletServer@127.31.149.193:0 shutting down...
I20260812 06:19:59.647883 32459 maintenance_manager.cc:643] P 8dcc9668e08941f4930e969e1c4c99ef: MajorDeltaCompactionOp(7ae91e47a04541fc8deb1862fafcaffe) complete. Timing: real 0.222s	user 0.144s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938782,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":778,"lbm_read_time_us":16205,"lbm_reads_lt_1ms":770,"lbm_write_time_us":36169,"lbm_writes_lt_1ms":743,"mutex_wait_us":27,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":34304,"thread_start_us":106,"threads_started":1,"update_count":3500}
I20260812 06:19:59.648602 32343 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:59.649077 32343 tablet_replica.cc:333] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef: stopping tablet replica
I20260812 06:19:59.649355 32343 raft_consensus.cc:2243] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.649693 32343 raft_consensus.cc:2272] T 7ae91e47a04541fc8deb1862fafcaffe P 8dcc9668e08941f4930e969e1c4c99ef [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.669020 32343 tablet_server.cc:196] TabletServer@127.31.149.193:0 shutdown complete.
I20260812 06:19:59.712958 32343 master.cc:562] Master@127.31.149.254:38529 shutting down...
I20260812 06:19:59.722086 32343 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.722285 32343 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.722407 32343 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7000cf1f0ecf4f64bbdc36175a04f6e5: stopping tablet replica
I20260812 06:19:59.735045 32343 master.cc:584] Master@127.31.149.254:38529 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5663 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:59.827329 32343 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.149.254:33273
I20260812 06:19:59.827764 32343 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:59.830571 32563 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:59.830588 32343 server_base.cc:1061] running on GCE node
W20260812 06:19:59.830683 32561 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:59.830683 32560 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:59.831073 32343 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:59.831122 32343 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:59.831138 32343 hybrid_clock.cc:648] HybridClock initialized: now 1786515599831138 us; error 0 us; skew 500 ppm
I20260812 06:19:59.832173 32343 webserver.cc:533] Webserver started at http://127.31.149.254:38831/ using document root <none> and password file <none>
I20260812 06:19:59.832376 32343 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:59.832427 32343 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:59.832536 32343 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:59.832985 32343 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/master-0-root/instance:
uuid: "ba7de3ecd65c4688b2d45c00e64ba0e7"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-njxd"
I20260812 06:19:59.834786 32343 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:59.835857 32568 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:59.836155 32343 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:59.836262 32343 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/master-0-root
uuid: "ba7de3ecd65c4688b2d45c00e64ba0e7"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-njxd"
I20260812 06:19:59.836359 32343 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:59.852547 32343 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:59.853024 32343 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:59.857648 32343 rpc_server.cc:307] RPC server started. Bound to: 127.31.149.254:33273
I20260812 06:19:59.862516 32630 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:59.870707 32629 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.149.254:33273 every 8 connection(s)
I20260812 06:19:59.871934 32630 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7: Bootstrap starting.
I20260812 06:19:59.872854 32630 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:59.873994 32630 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7: No bootstrap required, opened a new log
I20260812 06:19:59.874428 32630 raft_consensus.cc:359] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ba7de3ecd65c4688b2d45c00e64ba0e7" member_type: VOTER }
I20260812 06:19:59.874550 32630 raft_consensus.cc:385] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:59.874653 32630 raft_consensus.cc:740] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ba7de3ecd65c4688b2d45c00e64ba0e7, State: Initialized, Role: FOLLOWER
I20260812 06:19:59.874836 32630 consensus_queue.cc:260] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ba7de3ecd65c4688b2d45c00e64ba0e7" member_type: VOTER }
I20260812 06:19:59.874940 32630 raft_consensus.cc:399] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:59.874987 32630 raft_consensus.cc:493] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:59.875046 32630 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:59.875800 32630 raft_consensus.cc:515] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ba7de3ecd65c4688b2d45c00e64ba0e7" member_type: VOTER }
I20260812 06:19:59.875960 32630 leader_election.cc:304] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: ba7de3ecd65c4688b2d45c00e64ba0e7; no voters: 
I20260812 06:19:59.876180 32630 leader_election.cc:290] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:59.876312 32633 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:59.876580 32633 raft_consensus.cc:697] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [term 1 LEADER]: Becoming Leader. State: Replica: ba7de3ecd65c4688b2d45c00e64ba0e7, State: Running, Role: LEADER
I20260812 06:19:59.876713 32630 sys_catalog.cc:565] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:59.876760 32633 consensus_queue.cc:237] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ba7de3ecd65c4688b2d45c00e64ba0e7" member_type: VOTER }
I20260812 06:19:59.877246 32635 sys_catalog.cc:455] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ba7de3ecd65c4688b2d45c00e64ba0e7. Latest consensus state: current_term: 1 leader_uuid: "ba7de3ecd65c4688b2d45c00e64ba0e7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ba7de3ecd65c4688b2d45c00e64ba0e7" member_type: VOTER } }
I20260812 06:19:59.877409 32635 sys_catalog.cc:458] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:59.877276 32634 sys_catalog.cc:455] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ba7de3ecd65c4688b2d45c00e64ba0e7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ba7de3ecd65c4688b2d45c00e64ba0e7" member_type: VOTER } }
I20260812 06:19:59.877704 32639 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:59.877705 32634 sys_catalog.cc:458] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:59.878561 32639 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:59.878829 32343 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:59.880550 32639 catalog_manager.cc:1383] Generated new cluster ID: efefff1672d7438cad0d9de122c77d48
I20260812 06:19:59.880622 32639 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:59.891683 32639 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:59.892321 32639 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:59.912756 32639 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7: Generated new TSK 0
I20260812 06:19:59.913025 32639 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:59.943653 32343 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:59.945966 32653 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:59.946044 32652 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:59.946065 32655 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:59.946323 32343 server_base.cc:1061] running on GCE node
I20260812 06:19:59.946492 32343 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:59.946528 32343 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:59.946552 32343 hybrid_clock.cc:648] HybridClock initialized: now 1786515599946552 us; error 0 us; skew 500 ppm
I20260812 06:19:59.947415 32343 webserver.cc:533] Webserver started at http://127.31.149.193:35359/ using document root <none> and password file <none>
I20260812 06:19:59.947563 32343 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:59.947609 32343 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:59.947665 32343 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:59.948036 32343 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/instance:
uuid: "4ce43f2806eb40c3b4afa7e070ae67b2"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-njxd"
I20260812 06:19:59.949628 32343 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:59.950570 32660 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:59.950862 32343 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:59.950932 32343 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root
uuid: "4ce43f2806eb40c3b4afa7e070ae67b2"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-njxd"
I20260812 06:19:59.951042 32343 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:59.972705 32343 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:59.973181 32343 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:59.973553 32343 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:59.974136 32343 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:59.974207 32343 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:59.974313 32343 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:59.974370 32343 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:59.979240 32343 rpc_server.cc:307] RPC server started. Bound to: 127.31.149.193:34039
I20260812 06:19:59.979789 32734 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.149.193:34039 every 8 connection(s)
I20260812 06:19:59.990015 32735 heartbeater.cc:344] Connected to a master server at 127.31.149.254:33273
I20260812 06:19:59.990185 32735 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:59.990471 32735 heartbeater.cc:507] Master 127.31.149.254:33273 requested a full tablet report, sending...
I20260812 06:19:59.991250 32588 ts_manager.cc:194] Registered new tserver with Master: 4ce43f2806eb40c3b4afa7e070ae67b2 (127.31.149.193:34039)
I20260812 06:19:59.991961 32588 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40194
I20260812 06:19:59.992157 32343 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012166994s
I20260812 06:19:59.999801 32588 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40200:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:00.009697 32692 tablet_service.cc:1511] Processing CreateTablet for tablet be2fc76d21984055a2cdf2412a24d532 (DEFAULT_TABLE table=heavy-update-compaction-test [id=13481b8595ae448bbc0542bb0604ce84]), partition=
I20260812 06:20:00.010010 32692 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet be2fc76d21984055a2cdf2412a24d532. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:00.012501 32748 tablet_bootstrap.cc:492] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Bootstrap starting.
I20260812 06:20:00.013435 32748 tablet_bootstrap.cc:654] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:00.014591 32748 tablet_bootstrap.cc:492] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: No bootstrap required, opened a new log
I20260812 06:20:00.014675 32748 ts_tablet_manager.cc:1403] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:20:00.015131 32748 raft_consensus.cc:359] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ce43f2806eb40c3b4afa7e070ae67b2" member_type: VOTER last_known_addr { host: "127.31.149.193" port: 34039 } }
I20260812 06:20:00.015229 32748 raft_consensus.cc:385] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:00.015296 32748 raft_consensus.cc:740] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4ce43f2806eb40c3b4afa7e070ae67b2, State: Initialized, Role: FOLLOWER
I20260812 06:20:00.015441 32748 consensus_queue.cc:260] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ce43f2806eb40c3b4afa7e070ae67b2" member_type: VOTER last_known_addr { host: "127.31.149.193" port: 34039 } }
I20260812 06:20:00.015535 32748 raft_consensus.cc:399] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:00.015561 32748 raft_consensus.cc:493] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:00.015646 32748 raft_consensus.cc:3060] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:00.016505 32748 raft_consensus.cc:515] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ce43f2806eb40c3b4afa7e070ae67b2" member_type: VOTER last_known_addr { host: "127.31.149.193" port: 34039 } }
I20260812 06:20:00.016665 32748 leader_election.cc:304] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: 4ce43f2806eb40c3b4afa7e070ae67b2; no voters: 
I20260812 06:20:00.016940 32748 leader_election.cc:290] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:00.017185 32750 raft_consensus.cc:2804] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:00.017320 32750 raft_consensus.cc:697] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [term 1 LEADER]: Becoming Leader. State: Replica: 4ce43f2806eb40c3b4afa7e070ae67b2, State: Running, Role: LEADER
I20260812 06:20:00.017269 32748 ts_tablet_manager.cc:1434] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:00.017307 32735 heartbeater.cc:499] Master 127.31.149.254:33273 was elected leader, sending a full tablet report...
I20260812 06:20:00.017496 32750 consensus_queue.cc:237] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ce43f2806eb40c3b4afa7e070ae67b2" member_type: VOTER last_known_addr { host: "127.31.149.193" port: 34039 } }
I20260812 06:20:00.019042 32588 catalog_manager.cc:5719] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4ce43f2806eb40c3b4afa7e070ae67b2 (127.31.149.193). New cstate: current_term: 1 leader_uuid: "4ce43f2806eb40c3b4afa7e070ae67b2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ce43f2806eb40c3b4afa7e070ae67b2" member_type: VOTER last_known_addr { host: "127.31.149.193" port: 34039 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:00.080793 32343 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.014s	sys 0.008s
I20260812 06:20:00.230602 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushMRSOp(be2fc76d21984055a2cdf2412a24d532): perf score=19.054940
I20260812 06:20:00.397306 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushMRSOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.166s	user 0.109s	sys 0.050s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":901,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43329,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:00.398042 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling LogGCOp(be2fc76d21984055a2cdf2412a24d532): free 20743880 bytes of WAL
I20260812 06:20:00.398296 32665 log_reader.cc:385] T be2fc76d21984055a2cdf2412a24d532: removed 2 log segments from log reader
I20260812 06:20:00.398342 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000001 (ops 1-6)
I20260812 06:20:00.398375 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000002 (ops 7-11)
I20260812 06:20:00.402832 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: LogGCOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:20:00.403261 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:00.421707 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.422166 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:00.576452 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.154s	user 0.109s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":707,"lbm_read_time_us":11269,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24302,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":366,"threads_started":5,"update_count":2000}
I20260812 06:20:00.577042 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling UndoDeltaBlockGCOp(be2fc76d21984055a2cdf2412a24d532): 16411393 bytes on disk
I20260812 06:20:00.577526 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: UndoDeltaBlockGCOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:20:00.578105 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=14.095187
I20260812 06:20:00.638604 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.060s	user 0.028s	sys 0.019s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":21526,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:20:00.639137 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:00.650597 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.651080 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:00.845566 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.194s	user 0.133s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774694,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":464,"lbm_read_time_us":14728,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30518,"lbm_writes_lt_1ms":543,"mutex_wait_us":120,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:20:00.846244 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=14.095187
I20260812 06:20:00.900291 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.054s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409910,"delete_count":0,"lbm_write_time_us":23281,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.900882 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:01.055266 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.154s	user 0.116s	sys 0.035s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672166,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":287,"lbm_read_time_us":11670,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24018,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2000}
I20260812 06:20:01.056007 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=14.095187
I20260812 06:20:01.107575 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.051s	user 0.026s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22245,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.108110 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:01.119922 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4317,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.120436 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:01.327560 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.207s	user 0.137s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":263,"lbm_read_time_us":12175,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33940,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2500}
I20260812 06:20:01.328125 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=14.095187
I20260812 06:20:01.379272 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.051s	user 0.015s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20235,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.379815 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:01.392359 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4420,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.393008 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:01.568753 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.176s	user 0.110s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":260,"lbm_read_time_us":9973,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34232,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27776,"update_count":2500}
I20260812 06:20:01.569434 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=14.095187
I20260812 06:20:01.625464 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.056s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23174,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.626005 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:01.637785 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4215,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.638309 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushMRSOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:01.665369 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushMRSOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.027s	user 0.023s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1307,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1431,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:01.666038 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling LogGCOp(be2fc76d21984055a2cdf2412a24d532): free 111786255 bytes of WAL
I20260812 06:20:01.666289 32665 log_reader.cc:385] T be2fc76d21984055a2cdf2412a24d532: removed 11 log segments from log reader
I20260812 06:20:01.666358 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000003 (ops 12-16)
I20260812 06:20:01.666414 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000004 (ops 17-21)
I20260812 06:20:01.666474 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000005 (ops 22-26)
I20260812 06:20:01.666517 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000006 (ops 27-31)
I20260812 06:20:01.666550 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000007 (ops 32-36)
I20260812 06:20:01.666584 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000008 (ops 37-41)
I20260812 06:20:01.666622 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000009 (ops 42-46)
I20260812 06:20:01.666658 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000010 (ops 47-50)
I20260812 06:20:01.666694 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000011 (ops 51-55)
I20260812 06:20:01.666740 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000012 (ops 56-60)
I20260812 06:20:01.666777 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000013 (ops 61-64)
I20260812 06:20:01.692011 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: LogGCOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.026s	user 0.004s	sys 0.019s Metrics: {}
I20260812 06:20:01.692637 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling UndoDeltaBlockGCOp(be2fc76d21984055a2cdf2412a24d532): 448 bytes on disk
I20260812 06:20:01.693199 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: UndoDeltaBlockGCOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:20:01.693750 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=3.181125
I20260812 06:20:01.726130 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.032s	user 0.016s	sys 0.012s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":6771,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:01.726692 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:01.737058 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:01.737720 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:01.993796 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.256s	user 0.156s	sys 0.094s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":664,"lbm_read_time_us":16595,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41714,"lbm_writes_lt_1ms":743,"mutex_wait_us":2,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":140,"threads_started":1,"update_count":3500}
I20260812 06:20:01.994725 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=18.063937
I20260812 06:20:02.065426 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.070s	user 0.022s	sys 0.039s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28862,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:02.066085 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:02.078202 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4501,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.078970 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:02.287983 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.209s	user 0.145s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1289,"lbm_read_time_us":13555,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34896,"lbm_writes_lt_1ms":643,"mutex_wait_us":269,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":3000}
I20260812 06:20:02.288815 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=16.079562
I20260812 06:20:02.367678 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.079s	user 0.033s	sys 0.032s Metrics: {"bytes_written":17804726,"delete_count":0,"lbm_write_time_us":31067,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":436,"reinsert_count":0,"update_count":2170}
I20260812 06:20:02.368189 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=5.165500
I20260812 06:20:02.386564 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":6810261,"delete_count":0,"lbm_write_time_us":7798,"lbm_writes_lt_1ms":169,"reinsert_count":0,"update_count":830}
I20260812 06:20:02.387048 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:02.609989 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.223s	user 0.134s	sys 0.078s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1063,"lbm_read_time_us":15090,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34153,"lbm_writes_lt_1ms":643,"mutex_wait_us":578,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":3000}
I20260812 06:20:02.610656 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=18.063937
I20260812 06:20:02.680507 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.070s	user 0.018s	sys 0.036s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":25663,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:02.681025 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:02.691594 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3977,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.692169 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:02.908183 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.216s	user 0.144s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":402,"lbm_read_time_us":13646,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37653,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:20:02.908957 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=14.095187
I20260812 06:20:02.964733 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.056s	user 0.041s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22834,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.965528 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:03.119395 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.154s	user 0.118s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":317,"lbm_read_time_us":11198,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23911,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:20:03.120121 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=14.095187
I20260812 06:20:03.173801 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.053s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20023,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.174412 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:03.190668 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.191340 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushMRSOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:03.225899 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushMRSOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.034s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":259,"dirs.run_wall_time_us":1476,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1577,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:03.226621 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling LogGCOp(be2fc76d21984055a2cdf2412a24d532): free 121006390 bytes of WAL
I20260812 06:20:03.226872 32665 log_reader.cc:385] T be2fc76d21984055a2cdf2412a24d532: removed 12 log segments from log reader
I20260812 06:20:03.226919 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000014 (ops 65-69)
I20260812 06:20:03.226949 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000015 (ops 70-74)
I20260812 06:20:03.227017 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000016 (ops 75-79)
I20260812 06:20:03.227051 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000017 (ops 80-84)
I20260812 06:20:03.227088 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000018 (ops 85-89)
I20260812 06:20:03.227149 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000019 (ops 90-94)
I20260812 06:20:03.227185 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000020 (ops 95-99)
I20260812 06:20:03.227224 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000021 (ops 100-104)
I20260812 06:20:03.227264 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000022 (ops 105-109)
I20260812 06:20:03.227303 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000023 (ops 110-114)
I20260812 06:20:03.227347 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000024 (ops 115-118)
I20260812 06:20:03.227388 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000025 (ops 119-123)
I20260812 06:20:03.253219 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: LogGCOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.026s	user 0.004s	sys 0.019s Metrics: {}
I20260812 06:20:03.253744 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling UndoDeltaBlockGCOp(be2fc76d21984055a2cdf2412a24d532): 462 bytes on disk
I20260812 06:20:03.254205 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: UndoDeltaBlockGCOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:20:03.254729 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=3.181125
I20260812 06:20:03.276084 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.021s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4594,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:03.276612 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:03.286875 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3729,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:03.287354 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:03.536000 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.248s	user 0.168s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":747,"lbm_read_time_us":17738,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39636,"lbm_writes_lt_1ms":743,"mutex_wait_us":56,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11392,"thread_start_us":95,"threads_started":1,"update_count":3500}
I20260812 06:20:03.536846 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=18.063937
I20260812 06:20:03.602633 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.066s	user 0.036s	sys 0.026s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":33571,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":500,"reinsert_count":0,"update_count":2500}
I20260812 06:20:03.603246 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:03.624435 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.021s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5562,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.625182 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:03.830669 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.205s	user 0.126s	sys 0.079s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1039,"lbm_read_time_us":13577,"lbm_reads_lt_1ms":664,"lbm_write_time_us":36765,"lbm_writes_lt_1ms":643,"mutex_wait_us":341,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23808,"update_count":3000}
I20260812 06:20:03.831526 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=18.063937
I20260812 06:20:03.903637 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.072s	user 0.045s	sys 0.011s Metrics: {"bytes_written":20512312,"delete_count":0,"lbm_write_time_us":26860,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:03.904234 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:03.915912 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.916414 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:04.120898 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.204s	user 0.152s	sys 0.052s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":145,"lbm_read_time_us":13662,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35184,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":3000}
I20260812 06:20:04.121693 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=14.095187
I20260812 06:20:04.175218 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.053s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21828,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.175812 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=3.181125
I20260812 06:20:04.189030 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5096,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:04.189698 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:04.199779 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3706,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:04.200606 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:04.412940 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.212s	user 0.116s	sys 0.096s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":323,"lbm_read_time_us":14342,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35596,"lbm_writes_lt_1ms":643,"mutex_wait_us":33,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":24320,"update_count":3000}
I20260812 06:20:04.413764 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=14.095187
I20260812 06:20:04.500114 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.086s	user 0.025s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":55722,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.500631 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=6.157687
I20260812 06:20:04.526085 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.025s	user 0.005s	sys 0.015s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9110,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:04.526746 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:04.741389 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.214s	user 0.154s	sys 0.049s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":179,"lbm_read_time_us":14802,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35003,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":3000}
I20260812 06:20:04.742069 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=18.063937
I20260812 06:20:04.809998 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.068s	user 0.034s	sys 0.027s Metrics: {"bytes_written":20512313,"delete_count":0,"lbm_write_time_us":28463,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:04.810585 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=2.188937
I20260812 06:20:04.822702 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4520,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.823246 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushMRSOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:04.853820 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushMRSOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.030s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1984,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1968,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:04.854660 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling LogGCOp(be2fc76d21984055a2cdf2412a24d532): free 132571619 bytes of WAL
I20260812 06:20:04.854923 32665 log_reader.cc:385] T be2fc76d21984055a2cdf2412a24d532: removed 13 log segments from log reader
I20260812 06:20:04.854995 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000026 (ops 124-128)
I20260812 06:20:04.855046 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000027 (ops 129-132)
I20260812 06:20:04.855106 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000028 (ops 133-137)
I20260812 06:20:04.855150 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000029 (ops 138-142)
I20260812 06:20:04.855196 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000030 (ops 143-146)
I20260812 06:20:04.855237 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000031 (ops 147-151)
I20260812 06:20:04.855276 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000032 (ops 152-156)
I20260812 06:20:04.855316 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000033 (ops 157-161)
I20260812 06:20:04.855355 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000034 (ops 162-166)
I20260812 06:20:04.855393 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000035 (ops 167-171)
I20260812 06:20:04.855433 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000036 (ops 172-176)
I20260812 06:20:04.855472 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000037 (ops 177-181)
I20260812 06:20:04.855512 32665 log.cc:1079] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: Deleting log segment in path: /tmp/dist-test-taskRrY_Fd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594152930-32343-0/minicluster-data/ts-0-root/wals/be2fc76d21984055a2cdf2412a24d532/wal-000000038 (ops 182-186)
I20260812 06:20:04.884027 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: LogGCOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:04.885692 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling UndoDeltaBlockGCOp(be2fc76d21984055a2cdf2412a24d532): 493 bytes on disk
I20260812 06:20:04.886189 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: UndoDeltaBlockGCOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:20:04.886929 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=5.165500
I20260812 06:20:04.903692 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":6933327,"delete_count":0,"lbm_write_time_us":6968,"lbm_writes_lt_1ms":172,"reinsert_count":0,"update_count":845}
I20260812 06:20:04.904222 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:04.911201 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1271927,"delete_count":0,"lbm_write_time_us":1843,"lbm_writes_lt_1ms":34,"reinsert_count":0,"update_count":155}
I20260812 06:20:04.911686 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532): perf score=1.000000
I20260812 06:20:05.126379 32343 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.045s	user 1.827s	sys 0.173s
I20260812 06:20:05.152004 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: MajorDeltaCompactionOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.240s	user 0.156s	sys 0.082s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082093,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":17536,"lbm_reads_lt_1ms":870,"lbm_write_time_us":45943,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":4000}
I20260812 06:20:05.152547 32736 maintenance_manager.cc:419] P 4ce43f2806eb40c3b4afa7e070ae67b2: Scheduling FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532): perf score=18.063937
I20260812 06:20:05.215962 32343 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.089s	user 0.001s	sys 0.000s
I20260812 06:20:05.216539 32343 tablet_server.cc:179] TabletServer@127.31.149.193:0 shutting down...
I20260812 06:20:05.246764 32665 maintenance_manager.cc:643] P 4ce43f2806eb40c3b4afa7e070ae67b2: FlushDeltaMemStoresOp(be2fc76d21984055a2cdf2412a24d532) complete. Timing: real 0.094s	user 0.038s	sys 0.019s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26000,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:05.247460 32343 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:05.247721 32343 tablet_replica.cc:333] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2: stopping tablet replica
I20260812 06:20:05.247877 32343 raft_consensus.cc:2243] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:05.248127 32343 raft_consensus.cc:2272] T be2fc76d21984055a2cdf2412a24d532 P 4ce43f2806eb40c3b4afa7e070ae67b2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:05.251876 32343 tablet_server.cc:196] TabletServer@127.31.149.193:0 shutdown complete.
I20260812 06:20:05.277771 32343 master.cc:562] Master@127.31.149.254:33273 shutting down...
I20260812 06:20:05.281134 32343 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:05.281308 32343 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:05.281360 32343 tablet_replica.cc:333] T 00000000000000000000000000000000 P ba7de3ecd65c4688b2d45c00e64ba0e7: stopping tablet replica
I20260812 06:20:05.293893 32343 master.cc:584] Master@127.31.149.254:33273 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5557 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11222 ms total)

[----------] Global test environment tear-down
[==========] 2 tests from 1 test suite ran. (11222 ms total)
[  PASSED  ] 2 tests.
