[==========] 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:18:24.290501 31100 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.95.62:33895
I20260812 06:18:24.291509 31100 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:18:24.292129 31100 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:24.298488 31106 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:18:24.298509 31107 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:18:24.298583 31100 server_base.cc:1061] running on GCE node
W20260812 06:18:24.298797 31109 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:18:24.299343 31100 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:24.299489 31100 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:18:24.299538 31100 hybrid_clock.cc:648] HybridClock initialized: now 1786515504299535 us; error 0 us; skew 500 ppm
I20260812 06:18:24.301402 31100 webserver.cc:533] Webserver started at http://127.30.95.62:43179/ using document root <none> and password file <none>
I20260812 06:18:24.301957 31100 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:24.302050 31100 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:24.302310 31100 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:24.303992 31100 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/master-0-root/instance:
uuid: "dbf81998823f496495411b4410a58e19"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-10pc"
I20260812 06:18:24.307494 31100 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:24.309638 31114 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:18:24.310629 31100 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:24.310770 31100 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/master-0-root
uuid: "dbf81998823f496495411b4410a58e19"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-10pc"
I20260812 06:18:24.310871 31100 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-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:18:24.330579 31100 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:24.331287 31100 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:18:24.331491 31100 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:24.339911 31100 rpc_server.cc:307] RPC server started. Bound to: 127.30.95.62:33895
I20260812 06:18:24.339968 31173 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.95.62:33895 every 8 connection(s)
I20260812 06:18:24.342291 31174 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:18:24.348165 31174 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19: Bootstrap starting.
I20260812 06:18:24.350735 31174 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:24.351697 31174 log.cc:826] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:24.353575 31174 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19: No bootstrap required, opened a new log
I20260812 06:18:24.356416 31174 raft_consensus.cc:359] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dbf81998823f496495411b4410a58e19" member_type: VOTER }
I20260812 06:18:24.356612 31174 raft_consensus.cc:385] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:24.356704 31174 raft_consensus.cc:740] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: dbf81998823f496495411b4410a58e19, State: Initialized, Role: FOLLOWER
I20260812 06:18:24.357322 31174 consensus_queue.cc:260] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [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: "dbf81998823f496495411b4410a58e19" member_type: VOTER }
I20260812 06:18:24.357470 31174 raft_consensus.cc:399] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:24.357596 31174 raft_consensus.cc:493] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:24.357748 31174 raft_consensus.cc:3060] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:24.358649 31174 raft_consensus.cc:515] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dbf81998823f496495411b4410a58e19" member_type: VOTER }
I20260812 06:18:24.359125 31174 leader_election.cc:304] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [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: dbf81998823f496495411b4410a58e19; no voters: 
I20260812 06:18:24.359462 31174 leader_election.cc:290] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:24.359661 31179 raft_consensus.cc:2804] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:24.359964 31179 raft_consensus.cc:697] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [term 1 LEADER]: Becoming Leader. State: Replica: dbf81998823f496495411b4410a58e19, State: Running, Role: LEADER
I20260812 06:18:24.360399 31179 consensus_queue.cc:237] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [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: "dbf81998823f496495411b4410a58e19" member_type: VOTER }
I20260812 06:18:24.360570 31174 sys_catalog.cc:565] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:24.362560 31180 sys_catalog.cc:455] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "dbf81998823f496495411b4410a58e19" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dbf81998823f496495411b4410a58e19" member_type: VOTER } }
I20260812 06:18:24.362571 31181 sys_catalog.cc:455] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [sys.catalog]: SysCatalogTable state changed. Reason: New leader dbf81998823f496495411b4410a58e19. Latest consensus state: current_term: 1 leader_uuid: "dbf81998823f496495411b4410a58e19" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dbf81998823f496495411b4410a58e19" member_type: VOTER } }
I20260812 06:18:24.362715 31180 sys_catalog.cc:458] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:24.362715 31181 sys_catalog.cc:458] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:24.362890 31100 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:24.364961 31197 catalog_manager.cc:1594] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:24.365029 31197 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:24.365108 31198 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:24.365861 31198 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:24.371107 31198 catalog_manager.cc:1383] Generated new cluster ID: 74df6647ef4645b6ad1ee336e9ca75d1
I20260812 06:18:24.371209 31198 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:24.380270 31198 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:24.381227 31198 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:24.392234 31198 catalog_manager.cc:6092] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19: Generated new TSK 0
I20260812 06:18:24.392977 31198 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:24.395624 31100 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:24.398679 31202 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:18:24.398770 31100 server_base.cc:1061] running on GCE node
W20260812 06:18:24.398644 31203 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:18:24.398648 31207 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:18:24.399216 31100 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:24.399269 31100 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:18:24.399292 31100 hybrid_clock.cc:648] HybridClock initialized: now 1786515504399293 us; error 0 us; skew 500 ppm
I20260812 06:18:24.400301 31100 webserver.cc:533] Webserver started at http://127.30.95.1:45323/ using document root <none> and password file <none>
I20260812 06:18:24.400506 31100 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:24.400569 31100 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:24.400638 31100 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:24.401072 31100 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/instance:
uuid: "25d26246d79441d49bf6892923ca3587"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-10pc"
I20260812 06:18:24.402932 31100 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:24.404062 31214 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:18:24.404354 31100 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:24.404430 31100 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root
uuid: "25d26246d79441d49bf6892923ca3587"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-10pc"
I20260812 06:18:24.404568 31100 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-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:18:24.415555 31100 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:24.416018 31100 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:24.416898 31100 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:24.417825 31100 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:24.417881 31100 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:24.417951 31100 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:24.417995 31100 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:24.424824 31100 rpc_server.cc:307] RPC server started. Bound to: 127.30.95.1:33507
I20260812 06:18:24.424889 31290 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.95.1:33507 every 8 connection(s)
I20260812 06:18:24.435786 31291 heartbeater.cc:344] Connected to a master server at 127.30.95.62:33895
I20260812 06:18:24.436067 31291 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:24.436658 31291 heartbeater.cc:507] Master 127.30.95.62:33895 requested a full tablet report, sending...
I20260812 06:18:24.438261 31131 ts_manager.cc:194] Registered new tserver with Master: 25d26246d79441d49bf6892923ca3587 (127.30.95.1:33507)
I20260812 06:18:24.439004 31100 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013447822s
I20260812 06:18:24.440104 31131 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59050
I20260812 06:18:24.449117 31131 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59060:
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:18:24.465559 31248 tablet_service.cc:1511] Processing CreateTablet for tablet c7b9cf3c92344c58affdde273dcae28a (DEFAULT_TABLE table=heavy-update-compaction-test [id=35dc330eeeaf48928f622c8c7fb358e3]), partition=
I20260812 06:18:24.466042 31248 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c7b9cf3c92344c58affdde273dcae28a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:24.468838 31305 tablet_bootstrap.cc:492] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Bootstrap starting.
I20260812 06:18:24.469739 31305 tablet_bootstrap.cc:654] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:24.470871 31305 tablet_bootstrap.cc:492] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: No bootstrap required, opened a new log
I20260812 06:18:24.471000 31305 ts_tablet_manager.cc:1403] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:24.471436 31305 raft_consensus.cc:359] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "25d26246d79441d49bf6892923ca3587" member_type: VOTER last_known_addr { host: "127.30.95.1" port: 33507 } }
I20260812 06:18:24.471558 31305 raft_consensus.cc:385] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:24.471627 31305 raft_consensus.cc:740] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 25d26246d79441d49bf6892923ca3587, State: Initialized, Role: FOLLOWER
I20260812 06:18:24.471809 31305 consensus_queue.cc:260] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [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: "25d26246d79441d49bf6892923ca3587" member_type: VOTER last_known_addr { host: "127.30.95.1" port: 33507 } }
I20260812 06:18:24.471937 31305 raft_consensus.cc:399] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:24.471997 31305 raft_consensus.cc:493] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:24.472096 31305 raft_consensus.cc:3060] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:24.473150 31305 raft_consensus.cc:515] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "25d26246d79441d49bf6892923ca3587" member_type: VOTER last_known_addr { host: "127.30.95.1" port: 33507 } }
I20260812 06:18:24.473302 31305 leader_election.cc:304] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [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: 25d26246d79441d49bf6892923ca3587; no voters: 
I20260812 06:18:24.473536 31305 leader_election.cc:290] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:24.473631 31307 raft_consensus.cc:2804] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:24.473889 31307 raft_consensus.cc:697] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [term 1 LEADER]: Becoming Leader. State: Replica: 25d26246d79441d49bf6892923ca3587, State: Running, Role: LEADER
I20260812 06:18:24.473915 31305 ts_tablet_manager.cc:1434] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:24.474131 31291 heartbeater.cc:499] Master 127.30.95.62:33895 was elected leader, sending a full tablet report...
I20260812 06:18:24.474478 31307 consensus_queue.cc:237] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [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: "25d26246d79441d49bf6892923ca3587" member_type: VOTER last_known_addr { host: "127.30.95.1" port: 33507 } }
I20260812 06:18:24.477746 31131 catalog_manager.cc:5719] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 reported cstate change: term changed from 0 to 1, leader changed from <none> to 25d26246d79441d49bf6892923ca3587 (127.30.95.1). New cstate: current_term: 1 leader_uuid: "25d26246d79441d49bf6892923ca3587" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "25d26246d79441d49bf6892923ca3587" member_type: VOTER last_known_addr { host: "127.30.95.1" port: 33507 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:24.547922 31100 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.019s	sys 0.008s
I20260812 06:18:24.676061 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushMRSOp(c7b9cf3c92344c58affdde273dcae28a): perf score=15.086190
I20260812 06:18:24.847244 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushMRSOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.171s	user 0.131s	sys 0.027s Metrics: {"bytes_written":11897255,"cfile_init":1,"compiler_manager_pool.queue_time_us":247,"delete_count":0,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":910,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38925,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":156,"threads_started":1,"update_count":1450}
I20260812 06:18:24.848429 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling LogGCOp(c7b9cf3c92344c58affdde273dcae28a): free 20743880 bytes of WAL
I20260812 06:18:24.848783 31220 log_reader.cc:385] T c7b9cf3c92344c58affdde273dcae28a: removed 2 log segments from log reader
I20260812 06:18:24.848858 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000001 (ops 1-6)
I20260812 06:18:24.848973 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000002 (ops 7-11)
I20260812 06:18:24.855037 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: LogGCOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:24.855433 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:24.873800 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.874423 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling UndoDeltaBlockGCOp(c7b9cf3c92344c58affdde273dcae28a): 12719216 bytes on disk
I20260812 06:18:24.875087 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: UndoDeltaBlockGCOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:18:24.875608 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:25.008278 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.133s	user 0.104s	sys 0.028s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262042,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1104,"lbm_read_time_us":7660,"lbm_reads_lt_1ms":450,"lbm_write_time_us":25142,"lbm_writes_lt_1ms":433,"mutex_wait_us":149,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":13440,"thread_start_us":352,"threads_started":5,"update_count":1950}
I20260812 06:18:25.008992 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=10.126437
I20260812 06:18:25.047932 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.039s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19198,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.048375 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:25.059784 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4263,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.060218 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:25.184526 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.124s	user 0.096s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":7410,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25481,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:18:25.184995 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=10.126437
I20260812 06:18:25.232422 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.047s	user 0.015s	sys 0.024s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17151,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.232985 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:25.243770 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.244418 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:25.374511 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.130s	user 0.097s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":704,"lbm_read_time_us":8773,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25588,"lbm_writes_lt_1ms":443,"mutex_wait_us":340,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2000}
I20260812 06:18:25.375294 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=10.126437
I20260812 06:18:25.428238 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.053s	user 0.018s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17669,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.428814 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:25.439460 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4069,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.439908 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:25.592060 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.152s	user 0.126s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":11786,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23521,"lbm_writes_lt_1ms":443,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.592864 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=10.126437
I20260812 06:18:25.639715 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.047s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14256,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.640266 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:25.651012 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.651746 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:25.777328 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.125s	user 0.105s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":797,"lbm_read_time_us":8883,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24173,"lbm_writes_lt_1ms":443,"mutex_wait_us":416,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:18:25.778014 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=10.126437
I20260812 06:18:25.816051 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.038s	user 0.028s	sys 0.003s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14813,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.816644 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:25.827873 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.828398 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:25.948657 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.120s	user 0.094s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1981,"lbm_read_time_us":8235,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23395,"lbm_writes_lt_1ms":443,"mutex_wait_us":1463,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.949401 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=10.126437
I20260812 06:18:25.991510 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.042s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15973,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.992026 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:26.003722 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4223,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.004325 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:26.127156 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.123s	user 0.090s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":422,"lbm_read_time_us":8529,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24175,"lbm_writes_lt_1ms":443,"mutex_wait_us":104,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22784,"update_count":2000}
I20260812 06:18:26.127851 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=10.126437
I20260812 06:18:26.179657 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.052s	user 0.028s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17247,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:26.180318 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:26.191437 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4423,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.191882 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushMRSOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:26.234290 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushMRSOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.042s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":308,"dirs.run_wall_time_us":1350,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1958,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:26.235296 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling LogGCOp(c7b9cf3c92344c58affdde273dcae28a): free 121006437 bytes of WAL
I20260812 06:18:26.235608 31220 log_reader.cc:385] T c7b9cf3c92344c58affdde273dcae28a: removed 12 log segments from log reader
I20260812 06:18:26.235692 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000003 (ops 12-16)
I20260812 06:18:26.235747 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000004 (ops 17-21)
I20260812 06:18:26.235788 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000005 (ops 22-26)
I20260812 06:18:26.235828 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000006 (ops 27-31)
I20260812 06:18:26.235867 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000007 (ops 32-36)
I20260812 06:18:26.235908 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000008 (ops 37-40)
I20260812 06:18:26.235945 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000009 (ops 41-45)
I20260812 06:18:26.235983 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000010 (ops 46-50)
I20260812 06:18:26.236090 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000011 (ops 51-55)
I20260812 06:18:26.236136 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000012 (ops 56-60)
I20260812 06:18:26.236173 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000013 (ops 61-65)
I20260812 06:18:26.236212 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000014 (ops 66-70)
I20260812 06:18:26.268097 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: LogGCOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.033s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:26.268592 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:26.289856 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.021s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5979,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.290407 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:26.301450 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4117,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.302016 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling UndoDeltaBlockGCOp(c7b9cf3c92344c58affdde273dcae28a): 483 bytes on disk
I20260812 06:18:26.302627 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: UndoDeltaBlockGCOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:18:26.303351 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:26.501340 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.198s	user 0.130s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877341,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":272,"lbm_read_time_us":12745,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33151,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16512,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:18:26.502166 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=14.095187
I20260812 06:18:26.546924 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.045s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20146,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.547433 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:26.696972 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.149s	user 0.115s	sys 0.034s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":627,"lbm_read_time_us":11310,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26266,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:18:26.698159 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=10.126437
I20260812 06:18:26.730139 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.032s	user 0.025s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13606,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:26.730768 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:26.742709 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.743376 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:26.871836 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.128s	user 0.108s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1074,"lbm_read_time_us":10335,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24011,"lbm_writes_lt_1ms":443,"mutex_wait_us":332,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:18:26.872613 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=10.126437
I20260812 06:18:26.916128 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.043s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16619,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:26.916700 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:26.928341 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.929064 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:27.053617 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.123s	user 0.103s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1132,"lbm_read_time_us":7500,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24953,"lbm_writes_lt_1ms":443,"mutex_wait_us":279,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":50304,"update_count":2000}
I20260812 06:18:27.054291 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=10.126437
I20260812 06:18:27.097815 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.043s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17239,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.098336 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:27.109197 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4301,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.109977 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:27.236503 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.126s	user 0.119s	sys 0.007s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":635,"lbm_read_time_us":8929,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24091,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:18:27.237574 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=10.126437
I20260812 06:18:27.285279 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.047s	user 0.027s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16455,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.285830 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:27.298435 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4887,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.298874 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:27.452637 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.154s	user 0.123s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":347,"lbm_read_time_us":9730,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23404,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":660352,"update_count":2000}
I20260812 06:18:27.453604 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=11.118625
I20260812 06:18:27.488824 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.035s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15074,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:27.489398 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:27.507369 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.018s	user 0.012s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6754,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:18:27.507884 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:27.639034 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.131s	user 0.098s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":832,"lbm_read_time_us":7329,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28153,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25600,"update_count":2000}
I20260812 06:18:27.639731 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=10.126437
I20260812 06:18:27.680546 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.041s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17954,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.681118 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:27.697067 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.697548 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushMRSOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:27.747232 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushMRSOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.050s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":1433,"drs_written":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1602,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:27.748050 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling LogGCOp(c7b9cf3c92344c58affdde273dcae28a): free 127961115 bytes of WAL
I20260812 06:18:27.748311 31220 log_reader.cc:385] T c7b9cf3c92344c58affdde273dcae28a: removed 12 log segments from log reader
I20260812 06:18:27.748358 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000015 (ops 71-75)
I20260812 06:18:27.748389 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000016 (ops 76-80)
I20260812 06:18:27.748481 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000017 (ops 81-85)
I20260812 06:18:27.748528 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000018 (ops 86-90)
I20260812 06:18:27.748567 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000019 (ops 91-95)
I20260812 06:18:27.748616 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000020 (ops 96-100)
I20260812 06:18:27.748644 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000021 (ops 101-105)
I20260812 06:18:27.748687 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000022 (ops 106-110)
I20260812 06:18:27.748728 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000023 (ops 111-115)
I20260812 06:18:27.748768 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000024 (ops 116-120)
I20260812 06:18:27.748807 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000025 (ops 121-125)
I20260812 06:18:27.748855 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000026 (ops 126-130)
I20260812 06:18:27.774750 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: LogGCOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.027s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:18:27.775295 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=7.149875
I20260812 06:18:27.800930 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.025s	user 0.013s	sys 0.012s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11164,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:27.801537 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling LogGCOp(c7b9cf3c92344c58affdde273dcae28a): free 8767088 bytes of WAL
I20260812 06:18:27.801746 31220 log_reader.cc:385] T c7b9cf3c92344c58affdde273dcae28a: removed 1 log segments from log reader
I20260812 06:18:27.801792 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000027 (ops 131-135)
I20260812 06:18:27.803530 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: LogGCOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:27.803879 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling UndoDeltaBlockGCOp(c7b9cf3c92344c58affdde273dcae28a): 481 bytes on disk
I20260812 06:18:27.804288 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: UndoDeltaBlockGCOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:27.804827 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:27.823076 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5782,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:27.823625 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:28.015728 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.192s	user 0.153s	sys 0.036s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":896,"lbm_read_time_us":14384,"lbm_reads_lt_1ms":766,"lbm_write_time_us":39707,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:18:28.016609 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=14.095187
I20260812 06:18:28.063108 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.046s	user 0.037s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20592,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.063632 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:28.086839 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.023s	user 0.009s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.087622 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:28.268471 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.181s	user 0.121s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":790,"lbm_read_time_us":10956,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31963,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":65152,"update_count":2500}
I20260812 06:18:28.269096 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=14.095187
I20260812 06:18:28.327064 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.058s	user 0.032s	sys 0.018s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23707,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.327559 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:28.339789 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3989,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.340541 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:28.529419 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.189s	user 0.119s	sys 0.052s 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":303,"lbm_read_time_us":10421,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30443,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:18:28.530086 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=14.095187
I20260812 06:18:28.575915 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.046s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19329,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.576546 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:28.587378 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4098,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.588162 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:28.728885 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.140s	user 0.106s	sys 0.032s 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":450,"lbm_read_time_us":9101,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27345,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:28.729650 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=11.118625
I20260812 06:18:28.768237 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.038s	user 0.013s	sys 0.021s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":16016,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:28.769130 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:28.786144 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.017s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4081,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.786700 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:28.795950 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3450,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:28.796538 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:28.956133 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.159s	user 0.112s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":409,"lbm_read_time_us":9631,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30041,"lbm_writes_lt_1ms":543,"mutex_wait_us":88,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:28.956730 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=14.095187
I20260812 06:18:29.009527 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.053s	user 0.032s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21969,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.010044 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:29.021054 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4106,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.021544 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:29.172573 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.151s	user 0.123s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":152,"lbm_read_time_us":10664,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28386,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:29.173439 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=14.095187
I20260812 06:18:29.224499 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.051s	user 0.021s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22223,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.225059 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=2.188937
I20260812 06:18:29.236352 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.236925 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushMRSOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:29.270833 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushMRSOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":1773,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1771,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:29.271508 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling LogGCOp(c7b9cf3c92344c58affdde273dcae28a): free 124710562 bytes of WAL
I20260812 06:18:29.271757 31220 log_reader.cc:385] T c7b9cf3c92344c58affdde273dcae28a: removed 12 log segments from log reader
I20260812 06:18:29.271806 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000028 (ops 136-140)
I20260812 06:18:29.271835 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000029 (ops 141-145)
I20260812 06:18:29.271899 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000030 (ops 146-150)
I20260812 06:18:29.271930 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000031 (ops 151-155)
I20260812 06:18:29.271970 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000032 (ops 156-160)
I20260812 06:18:29.272022 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000033 (ops 161-165)
I20260812 06:18:29.272063 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000034 (ops 166-170)
I20260812 06:18:29.272102 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000035 (ops 171-175)
I20260812 06:18:29.272142 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000036 (ops 176-180)
I20260812 06:18:29.272181 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000037 (ops 181-185)
I20260812 06:18:29.272219 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000038 (ops 186-190)
I20260812 06:18:29.272257 31220 log.cc:1079] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/c7b9cf3c92344c58affdde273dcae28a/wal-000000039 (ops 191-195)
I20260812 06:18:29.297446 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: LogGCOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:29.297884 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=4.173312
I20260812 06:18:29.303730 31100 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.756s	user 1.810s	sys 0.076s
I20260812 06:18:29.314958 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.017s	user 0.006s	sys 0.010s Metrics: {"bytes_written":5784656,"delete_count":0,"lbm_write_time_us":7265,"lbm_writes_lt_1ms":144,"reinsert_count":0,"update_count":705}
I20260812 06:18:29.315447 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling UndoDeltaBlockGCOp(c7b9cf3c92344c58affdde273dcae28a): 492 bytes on disk
I20260812 06:18:29.315862 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: UndoDeltaBlockGCOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4}
I20260812 06:18:29.316393 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.196750
I20260812 06:18:29.323343 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: FlushDeltaMemStoresOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2420629,"delete_count":0,"lbm_write_time_us":2390,"lbm_writes_lt_1ms":62,"reinsert_count":0,"update_count":295}
I20260812 06:18:29.323800 31292 maintenance_manager.cc:419] P 25d26246d79441d49bf6892923ca3587: Scheduling MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a): perf score=1.000000
I20260812 06:18:29.368121 31100 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.064s	user 0.001s	sys 0.000s
I20260812 06:18:29.368830 31100 tablet_server.cc:179] TabletServer@127.30.95.1:0 shutting down...
I20260812 06:18:29.469956 31220 maintenance_manager.cc:643] P 25d26246d79441d49bf6892923ca3587: MajorDeltaCompactionOp(c7b9cf3c92344c58affdde273dcae28a) complete. Timing: real 0.146s	user 0.102s	sys 0.044s Metrics: {"cfile_cache_hit":407,"cfile_cache_hit_bytes":16616253,"cfile_cache_miss":327,"cfile_cache_miss_bytes":16363458,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":477,"lbm_read_time_us":6592,"lbm_reads_lt_1ms":363,"lbm_write_time_us":32572,"lbm_writes_lt_1ms":743,"mutex_wait_us":102,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":81536,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:18:29.471140 31100 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:29.471719 31100 tablet_replica.cc:333] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587: stopping tablet replica
I20260812 06:18:29.472005 31100 raft_consensus.cc:2243] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:29.472319 31100 raft_consensus.cc:2272] T c7b9cf3c92344c58affdde273dcae28a P 25d26246d79441d49bf6892923ca3587 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:29.488262 31100 tablet_server.cc:196] TabletServer@127.30.95.1:0 shutdown complete.
I20260812 06:18:29.529475 31100 master.cc:562] Master@127.30.95.62:33895 shutting down...
I20260812 06:18:29.533919 31100 raft_consensus.cc:2243] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:29.534099 31100 raft_consensus.cc:2272] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:29.534154 31100 tablet_replica.cc:333] T 00000000000000000000000000000000 P dbf81998823f496495411b4410a58e19: stopping tablet replica
I20260812 06:18:29.546893 31100 master.cc:584] Master@127.30.95.62:33895 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5348 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:29.639282 31100 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.95.62:46195
I20260812 06:18:29.639786 31100 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:29.642026 31330 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:18:29.642071 31328 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:18:29.642237 31100 server_base.cc:1061] running on GCE node
W20260812 06:18:29.642266 31332 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:18:29.642544 31100 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:29.642611 31100 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:18:29.642638 31100 hybrid_clock.cc:648] HybridClock initialized: now 1786515509642638 us; error 0 us; skew 500 ppm
I20260812 06:18:29.643532 31100 webserver.cc:533] Webserver started at http://127.30.95.62:46369/ using document root <none> and password file <none>
I20260812 06:18:29.643734 31100 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:29.643808 31100 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:29.643891 31100 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:29.644300 31100 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/master-0-root/instance:
uuid: "337458dded82473a9c99112045aa52e4"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-10pc"
I20260812 06:18:29.645931 31100 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:29.647033 31339 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:18:29.647324 31100 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:29.647428 31100 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/master-0-root
uuid: "337458dded82473a9c99112045aa52e4"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-10pc"
I20260812 06:18:29.647526 31100 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-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:18:29.662420 31100 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:29.662911 31100 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:29.667515 31100 rpc_server.cc:307] RPC server started. Bound to: 127.30.95.62:46195
I20260812 06:18:29.669592 31402 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.95.62:46195 every 8 connection(s)
I20260812 06:18:29.678360 31403 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:18:29.687275 31403 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4: Bootstrap starting.
I20260812 06:18:29.688172 31403 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:29.689306 31403 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4: No bootstrap required, opened a new log
I20260812 06:18:29.689695 31403 raft_consensus.cc:359] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "337458dded82473a9c99112045aa52e4" member_type: VOTER }
I20260812 06:18:29.689783 31403 raft_consensus.cc:385] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:29.689806 31403 raft_consensus.cc:740] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 337458dded82473a9c99112045aa52e4, State: Initialized, Role: FOLLOWER
I20260812 06:18:29.689909 31403 consensus_queue.cc:260] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [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: "337458dded82473a9c99112045aa52e4" member_type: VOTER }
I20260812 06:18:29.689965 31403 raft_consensus.cc:399] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:29.689987 31403 raft_consensus.cc:493] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:29.690016 31403 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:29.690685 31403 raft_consensus.cc:515] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "337458dded82473a9c99112045aa52e4" member_type: VOTER }
I20260812 06:18:29.690797 31403 leader_election.cc:304] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [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: 337458dded82473a9c99112045aa52e4; no voters: 
I20260812 06:18:29.690965 31403 leader_election.cc:290] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:29.691143 31406 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:29.691367 31406 raft_consensus.cc:697] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [term 1 LEADER]: Becoming Leader. State: Replica: 337458dded82473a9c99112045aa52e4, State: Running, Role: LEADER
I20260812 06:18:29.691497 31403 sys_catalog.cc:565] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:29.691548 31406 consensus_queue.cc:237] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [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: "337458dded82473a9c99112045aa52e4" member_type: VOTER }
I20260812 06:18:29.692041 31407 sys_catalog.cc:455] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "337458dded82473a9c99112045aa52e4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "337458dded82473a9c99112045aa52e4" member_type: VOTER } }
I20260812 06:18:29.692059 31408 sys_catalog.cc:455] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 337458dded82473a9c99112045aa52e4. Latest consensus state: current_term: 1 leader_uuid: "337458dded82473a9c99112045aa52e4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "337458dded82473a9c99112045aa52e4" member_type: VOTER } }
I20260812 06:18:29.692181 31408 sys_catalog.cc:458] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:29.692474 31407 sys_catalog.cc:458] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:29.692520 31413 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:29.693636 31413 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:29.693900 31100 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:29.695720 31413 catalog_manager.cc:1383] Generated new cluster ID: cee3d71272ff4c129d8740b014e70fd6
I20260812 06:18:29.695785 31413 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:29.718935 31413 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:29.719579 31413 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:29.724313 31413 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4: Generated new TSK 0
I20260812 06:18:29.724545 31413 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:29.726454 31100 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:29.728490 31429 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:18:29.728569 31432 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:18:29.728700 31428 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:18:29.728848 31100 server_base.cc:1061] running on GCE node
I20260812 06:18:29.729020 31100 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:29.729059 31100 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:18:29.729075 31100 hybrid_clock.cc:648] HybridClock initialized: now 1786515509729075 us; error 0 us; skew 500 ppm
I20260812 06:18:29.729913 31100 webserver.cc:533] Webserver started at http://127.30.95.1:43309/ using document root <none> and password file <none>
I20260812 06:18:29.730049 31100 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:29.730094 31100 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:29.730145 31100 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:29.730520 31100 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/instance:
uuid: "f3719dfd91ae4bb284555991f3e22bfb"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-10pc"
I20260812 06:18:29.732046 31100 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:18:29.733055 31437 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:18:29.733330 31100 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:29.733420 31100 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root
uuid: "f3719dfd91ae4bb284555991f3e22bfb"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-10pc"
I20260812 06:18:29.733511 31100 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-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:18:29.745095 31100 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:29.745532 31100 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:29.745884 31100 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:29.746368 31100 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:29.746430 31100 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:29.746495 31100 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:29.746541 31100 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:29.751144 31100 rpc_server.cc:307] RPC server started. Bound to: 127.30.95.1:34897
I20260812 06:18:29.751220 31508 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.95.1:34897 every 8 connection(s)
I20260812 06:18:29.761188 31509 heartbeater.cc:344] Connected to a master server at 127.30.95.62:46195
I20260812 06:18:29.761318 31509 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:29.761610 31509 heartbeater.cc:507] Master 127.30.95.62:46195 requested a full tablet report, sending...
I20260812 06:18:29.762351 31361 ts_manager.cc:194] Registered new tserver with Master: f3719dfd91ae4bb284555991f3e22bfb (127.30.95.1:34897)
I20260812 06:18:29.762956 31100 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011331392s
I20260812 06:18:29.763239 31361 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38536
I20260812 06:18:29.771065 31361 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38538:
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:18:29.780694 31467 tablet_service.cc:1511] Processing CreateTablet for tablet 73f17cd45ffd41aabf106ee50eb4a482 (DEFAULT_TABLE table=heavy-update-compaction-test [id=6ef213d4db3f4bd8aba2a99fc209828f]), partition=
I20260812 06:18:29.780982 31467 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 73f17cd45ffd41aabf106ee50eb4a482. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:29.783500 31522 tablet_bootstrap.cc:492] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Bootstrap starting.
I20260812 06:18:29.784430 31522 tablet_bootstrap.cc:654] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:29.785704 31522 tablet_bootstrap.cc:492] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: No bootstrap required, opened a new log
I20260812 06:18:29.785801 31522 ts_tablet_manager.cc:1403] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:29.786319 31522 raft_consensus.cc:359] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f3719dfd91ae4bb284555991f3e22bfb" member_type: VOTER last_known_addr { host: "127.30.95.1" port: 34897 } }
I20260812 06:18:29.786415 31522 raft_consensus.cc:385] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:29.786437 31522 raft_consensus.cc:740] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f3719dfd91ae4bb284555991f3e22bfb, State: Initialized, Role: FOLLOWER
I20260812 06:18:29.786540 31522 consensus_queue.cc:260] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [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: "f3719dfd91ae4bb284555991f3e22bfb" member_type: VOTER last_known_addr { host: "127.30.95.1" port: 34897 } }
I20260812 06:18:29.786603 31522 raft_consensus.cc:399] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:29.786638 31522 raft_consensus.cc:493] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:29.786665 31522 raft_consensus.cc:3060] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:29.787398 31522 raft_consensus.cc:515] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f3719dfd91ae4bb284555991f3e22bfb" member_type: VOTER last_known_addr { host: "127.30.95.1" port: 34897 } }
I20260812 06:18:29.787552 31522 leader_election.cc:304] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [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: f3719dfd91ae4bb284555991f3e22bfb; no voters: 
I20260812 06:18:29.787719 31522 leader_election.cc:290] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:29.787887 31524 raft_consensus.cc:2804] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:29.788041 31522 ts_tablet_manager.cc:1434] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:29.788146 31509 heartbeater.cc:499] Master 127.30.95.62:46195 was elected leader, sending a full tablet report...
I20260812 06:18:29.788424 31524 raft_consensus.cc:697] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [term 1 LEADER]: Becoming Leader. State: Replica: f3719dfd91ae4bb284555991f3e22bfb, State: Running, Role: LEADER
I20260812 06:18:29.788611 31524 consensus_queue.cc:237] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [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: "f3719dfd91ae4bb284555991f3e22bfb" member_type: VOTER last_known_addr { host: "127.30.95.1" port: 34897 } }
I20260812 06:18:29.790153 31361 catalog_manager.cc:5719] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb reported cstate change: term changed from 0 to 1, leader changed from <none> to f3719dfd91ae4bb284555991f3e22bfb (127.30.95.1). New cstate: current_term: 1 leader_uuid: "f3719dfd91ae4bb284555991f3e22bfb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f3719dfd91ae4bb284555991f3e22bfb" member_type: VOTER last_known_addr { host: "127.30.95.1" port: 34897 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:29.851809 31100 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.020s	sys 0.004s
I20260812 06:18:30.002305 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushMRSOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=19.054940
I20260812 06:18:30.171150 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushMRSOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.168s	user 0.142s	sys 0.024s Metrics: {"bytes_written":12717735,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":872,"drs_written":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39540,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1550}
I20260812 06:18:30.171897 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling LogGCOp(73f17cd45ffd41aabf106ee50eb4a482): free 20743880 bytes of WAL
I20260812 06:18:30.172173 31442 log_reader.cc:385] T 73f17cd45ffd41aabf106ee50eb4a482: removed 2 log segments from log reader
I20260812 06:18:30.172250 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000001 (ops 1-6)
I20260812 06:18:30.172343 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000002 (ops 7-11)
I20260812 06:18:30.177742 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: LogGCOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:18:30.178246 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling UndoDeltaBlockGCOp(73f17cd45ffd41aabf106ee50eb4a482): 16411393 bytes on disk
I20260812 06:18:30.178808 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: UndoDeltaBlockGCOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:18:30.179276 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:30.200896 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.021s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7132,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.201381 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:30.211268 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3806,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:30.211733 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:30.385355 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.173s	user 0.130s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":809,"lbm_read_time_us":13443,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31319,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":421,"threads_started":5,"update_count":2500}
I20260812 06:18:30.386066 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=14.095187
I20260812 06:18:30.436721 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.050s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19254,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.437461 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:30.448871 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.449581 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:30.606422 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.157s	user 0.112s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":491,"lbm_read_time_us":10458,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31277,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:18:30.607018 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=10.126437
I20260812 06:18:30.645874 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.039s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17602,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.646401 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:30.660372 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5395,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.660863 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:30.823611 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.163s	user 0.108s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":716,"lbm_read_time_us":11545,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25108,"lbm_writes_lt_1ms":443,"mutex_wait_us":315,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:18:30.824150 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=14.095187
I20260812 06:18:30.874434 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.050s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19457,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.874955 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:30.895309 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.020s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4030,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.895954 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:31.071424 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.175s	user 0.096s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":187,"lbm_read_time_us":13187,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26960,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":2500}
I20260812 06:18:31.072055 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=11.118625
I20260812 06:18:31.106416 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.034s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14852,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:31.106987 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:31.122023 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5778,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.122570 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:31.259137 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.136s	user 0.096s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":154,"lbm_read_time_us":7804,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26307,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24960,"update_count":2000}
I20260812 06:18:31.259917 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=10.126437
I20260812 06:18:31.310343 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.050s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16064,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.310954 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:31.322974 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4301,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.323474 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:31.455300 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.132s	user 0.096s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":242,"lbm_read_time_us":10607,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25670,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:18:31.455953 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=10.126437
I20260812 06:18:31.501925 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.046s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16746,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.502418 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:31.512300 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3802,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.512799 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushMRSOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:31.545867 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushMRSOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.033s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":1400,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1708,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:31.546458 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling LogGCOp(73f17cd45ffd41aabf106ee50eb4a482): free 120553323 bytes of WAL
I20260812 06:18:31.546703 31442 log_reader.cc:385] T 73f17cd45ffd41aabf106ee50eb4a482: removed 12 log segments from log reader
I20260812 06:18:31.546753 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000003 (ops 12-16)
I20260812 06:18:31.546783 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000004 (ops 17-21)
I20260812 06:18:31.546847 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000005 (ops 22-26)
I20260812 06:18:31.546908 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000006 (ops 27-30)
I20260812 06:18:31.546947 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000007 (ops 31-35)
I20260812 06:18:31.546989 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000008 (ops 36-40)
I20260812 06:18:31.547034 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000009 (ops 41-45)
I20260812 06:18:31.547079 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000010 (ops 46-50)
I20260812 06:18:31.547106 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000011 (ops 51-55)
I20260812 06:18:31.547145 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000012 (ops 56-60)
I20260812 06:18:31.547184 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000013 (ops 61-64)
I20260812 06:18:31.547222 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000014 (ops 65-69)
I20260812 06:18:31.574501 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: LogGCOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:31.575094 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling UndoDeltaBlockGCOp(73f17cd45ffd41aabf106ee50eb4a482): 483 bytes on disk
I20260812 06:18:31.575625 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: UndoDeltaBlockGCOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.576206 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=4.173312
I20260812 06:18:31.590166 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":5825681,"delete_count":0,"lbm_write_time_us":5746,"lbm_writes_lt_1ms":145,"reinsert_count":0,"update_count":710}
I20260812 06:18:31.590631 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling LogGCOp(73f17cd45ffd41aabf106ee50eb4a482): free 12017983 bytes of WAL
I20260812 06:18:31.590857 31442 log_reader.cc:385] T 73f17cd45ffd41aabf106ee50eb4a482: removed 1 log segments from log reader
I20260812 06:18:31.590917 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000015 (ops 70-74)
I20260812 06:18:31.593439 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: LogGCOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:31.593776 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.196750
I20260812 06:18:31.607076 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.013s	user 0.006s	sys 0.002s Metrics: {"bytes_written":2379604,"delete_count":0,"lbm_write_time_us":3496,"lbm_writes_lt_1ms":61,"reinsert_count":0,"update_count":290}
I20260812 06:18:31.607586 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:31.779806 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.172s	user 0.115s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877300,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":643,"lbm_read_time_us":12586,"lbm_reads_lt_1ms":670,"lbm_write_time_us":33703,"lbm_writes_lt_1ms":643,"mutex_wait_us":30,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13824,"thread_start_us":106,"threads_started":1,"update_count":3000}
I20260812 06:18:31.780786 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=14.095187
I20260812 06:18:31.834368 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.053s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23760,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.834959 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:31.851790 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.017s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5870,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.852228 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:32.015501 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.163s	user 0.123s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":936,"lbm_read_time_us":10968,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29044,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:18:32.016261 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=14.095187
I20260812 06:18:32.075788 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.059s	user 0.048s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24951,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.076321 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:32.243422 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.167s	user 0.139s	sys 0.028s 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":41,"lbm_read_time_us":10615,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26780,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2000}
I20260812 06:18:32.244024 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=14.095187
I20260812 06:18:32.293419 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.049s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20876,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.294027 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:32.305377 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4160,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.306087 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:32.489759 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.183s	user 0.124s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":12748,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29791,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":2500}
I20260812 06:18:32.490451 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=14.095187
I20260812 06:18:32.546037 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.055s	user 0.016s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18690,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.546588 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:32.562783 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6143,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.563524 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:32.721020 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.157s	user 0.116s	sys 0.036s 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":695,"lbm_read_time_us":9701,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32071,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:18:32.721906 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=11.118625
I20260812 06:18:32.756024 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.034s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14982,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:32.756702 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:32.771757 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5161,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.772671 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:32.902004 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.129s	user 0.098s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":976,"lbm_read_time_us":7847,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24167,"lbm_writes_lt_1ms":443,"mutex_wait_us":346,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:32.904915 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=10.126437
I20260812 06:18:32.949262 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.044s	user 0.026s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17334,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:32.949847 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:32.960734 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4205,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.961344 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushMRSOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:32.992273 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushMRSOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.031s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1534,"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:18:32.993062 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling LogGCOp(73f17cd45ffd41aabf106ee50eb4a482): free 112692325 bytes of WAL
I20260812 06:18:32.993328 31442 log_reader.cc:385] T 73f17cd45ffd41aabf106ee50eb4a482: removed 11 log segments from log reader
I20260812 06:18:32.993407 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000016 (ops 75-79)
I20260812 06:18:32.993500 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000017 (ops 80-84)
I20260812 06:18:32.993552 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000018 (ops 85-89)
I20260812 06:18:32.993597 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000019 (ops 90-94)
I20260812 06:18:32.993633 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000020 (ops 95-99)
I20260812 06:18:32.993669 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000021 (ops 100-104)
I20260812 06:18:32.993721 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000022 (ops 105-109)
I20260812 06:18:32.993759 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000023 (ops 110-114)
I20260812 06:18:32.993798 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000024 (ops 115-119)
I20260812 06:18:32.993842 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000025 (ops 120-124)
I20260812 06:18:32.993870 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000026 (ops 125-129)
I20260812 06:18:33.016899 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: LogGCOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.024s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:18:33.017350 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:33.034253 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.017s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4589,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.034771 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling UndoDeltaBlockGCOp(73f17cd45ffd41aabf106ee50eb4a482): 462 bytes on disk
I20260812 06:18:33.035216 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: UndoDeltaBlockGCOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:33.035692 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:33.046701 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4263,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.047493 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:33.227243 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.180s	user 0.123s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":575,"lbm_read_time_us":14614,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34817,"lbm_writes_lt_1ms":643,"mutex_wait_us":91,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9856,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:18:33.227983 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=14.095187
I20260812 06:18:33.289376 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.061s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23691,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.289938 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:33.303061 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.303604 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:33.461047 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.157s	user 0.120s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":763,"lbm_read_time_us":11022,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30176,"lbm_writes_lt_1ms":543,"mutex_wait_us":342,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:33.461757 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=11.118625
I20260812 06:18:33.502784 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.041s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17782,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:33.503382 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:33.523818 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.020s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5880,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.524390 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:33.679374 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.155s	user 0.107s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":557,"lbm_read_time_us":10514,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24478,"lbm_writes_lt_1ms":443,"mutex_wait_us":118,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:33.680138 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=11.118625
I20260812 06:18:33.724231 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.044s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19270,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:33.724782 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:33.743742 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.019s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4151,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.744274 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:33.765738 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.021s	user 0.003s	sys 0.016s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4170,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.766427 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:33.954032 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.187s	user 0.125s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":257,"lbm_read_time_us":11270,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29006,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:18:33.954733 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=14.095187
I20260812 06:18:34.011161 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.056s	user 0.031s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18192,"lbm_writes_lt_1ms":403,"mutex_wait_us":3,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.011693 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:34.024040 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4550,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.024870 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:34.214738 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.190s	user 0.130s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":253,"lbm_read_time_us":11717,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29175,"lbm_writes_lt_1ms":543,"mutex_wait_us":90,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:18:34.215260 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=14.095187
I20260812 06:18:34.268821 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.053s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21351,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.269373 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:34.280807 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.281320 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:34.440582 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.159s	user 0.110s	sys 0.040s 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":1062,"lbm_read_time_us":10906,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29599,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:18:34.441164 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=14.095187
I20260812 06:18:34.497197 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.056s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21579,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.497725 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:34.508958 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4104,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.509455 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushMRSOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:34.537986 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushMRSOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.028s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1438,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1569,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:34.538810 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling LogGCOp(73f17cd45ffd41aabf106ee50eb4a482): free 124710562 bytes of WAL
I20260812 06:18:34.539105 31442 log_reader.cc:385] T 73f17cd45ffd41aabf106ee50eb4a482: removed 12 log segments from log reader
I20260812 06:18:34.539188 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000027 (ops 130-134)
I20260812 06:18:34.539242 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000028 (ops 135-139)
I20260812 06:18:34.539280 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000029 (ops 140-144)
I20260812 06:18:34.539352 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000030 (ops 145-149)
I20260812 06:18:34.539389 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000031 (ops 150-154)
I20260812 06:18:34.539429 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000032 (ops 155-159)
I20260812 06:18:34.539470 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000033 (ops 160-164)
I20260812 06:18:34.539517 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000034 (ops 165-169)
I20260812 06:18:34.539558 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000035 (ops 170-174)
I20260812 06:18:34.539598 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000036 (ops 175-179)
I20260812 06:18:34.539637 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000037 (ops 180-184)
I20260812 06:18:34.539678 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000038 (ops 185-189)
I20260812 06:18:34.568145 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: LogGCOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:34.568666 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=3.181125
I20260812 06:18:34.586853 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.018s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7381,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:34.587427 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling LogGCOp(73f17cd45ffd41aabf106ee50eb4a482): free 12018006 bytes of WAL
I20260812 06:18:34.587728 31442 log_reader.cc:385] T 73f17cd45ffd41aabf106ee50eb4a482: removed 1 log segments from log reader
I20260812 06:18:34.587807 31442 log.cc:1079] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: Deleting log segment in path: /tmp/dist-test-task3I1IZZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515504279585-31100-0/minicluster-data/ts-0-root/wals/73f17cd45ffd41aabf106ee50eb4a482/wal-000000039 (ops 190-194)
I20260812 06:18:34.590245 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: LogGCOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:34.590562 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling UndoDeltaBlockGCOp(73f17cd45ffd41aabf106ee50eb4a482): 483 bytes on disk
I20260812 06:18:34.590957 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: UndoDeltaBlockGCOp(73f17cd45ffd41aabf106ee50eb4a482) 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:18:34.591429 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=2.188937
I20260812 06:18:34.611014 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.019s	user 0.005s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3761,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.611501 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=1.000000
I20260812 06:18:34.742808 31100 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.891s	user 1.864s	sys 0.164s
I20260812 06:18:34.848042 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: MajorDeltaCompactionOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.236s	user 0.136s	sys 0.097s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979740,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3318,"lbm_read_time_us":16179,"lbm_reads_lt_1ms":770,"lbm_write_time_us":40767,"lbm_writes_lt_1ms":743,"mutex_wait_us":262,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:18:34.848855 31511 maintenance_manager.cc:419] P f3719dfd91ae4bb284555991f3e22bfb: Scheduling FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482): perf score=10.126437
I20260812 06:18:34.855625 31100 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.112s	user 0.000s	sys 0.001s
I20260812 06:18:34.856202 31100 tablet_server.cc:179] TabletServer@127.30.95.1:0 shutting down...
I20260812 06:18:34.884603 31442 maintenance_manager.cc:643] P f3719dfd91ae4bb284555991f3e22bfb: FlushDeltaMemStoresOp(73f17cd45ffd41aabf106ee50eb4a482) complete. Timing: real 0.035s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15375,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.886528 31100 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:34.886775 31100 tablet_replica.cc:333] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb: stopping tablet replica
I20260812 06:18:34.886947 31100 raft_consensus.cc:2243] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:34.887108 31100 raft_consensus.cc:2272] T 73f17cd45ffd41aabf106ee50eb4a482 P f3719dfd91ae4bb284555991f3e22bfb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:34.890489 31100 tablet_server.cc:196] TabletServer@127.30.95.1:0 shutdown complete.
I20260812 06:18:34.904412 31100 master.cc:562] Master@127.30.95.62:46195 shutting down...
I20260812 06:18:34.908053 31100 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:34.908246 31100 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:34.908340 31100 tablet_replica.cc:333] T 00000000000000000000000000000000 P 337458dded82473a9c99112045aa52e4: stopping tablet replica
I20260812 06:18:34.920814 31100 master.cc:584] Master@127.30.95.62:46195 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5368 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10718 ms total)

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