[==========] 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:17:53.988797 24241 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.172.126:39463
I20260812 06:17:53.990012 24241 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:17:53.990747 24241 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:53.997165 24241 server_base.cc:1061] running on GCE node
W20260812 06:17:53.997172 24247 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:17:53.997190 24249 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:17:53.997454 24251 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:17:53.997969 24241 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:53.998060 24241 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:17:53.998090 24241 hybrid_clock.cc:648] HybridClock initialized: now 1786515473998089 us; error 0 us; skew 500 ppm
I20260812 06:17:53.999783 24241 webserver.cc:533] Webserver started at http://127.23.172.126:33855/ using document root <none> and password file <none>
I20260812 06:17:54.000324 24241 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:54.000380 24241 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:54.000571 24241 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:54.002218 24241 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/master-0-root/instance:
uuid: "a023d7bd546542398debfeedc34c646e"
format_stamp: "Formatted at 2026-08-12 06:17:53 on dist-test-slave-jpj1"
I20260812 06:17:54.005782 24241 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:17:54.007913 24264 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:17:54.008941 24241 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:54.009055 24241 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/master-0-root
uuid: "a023d7bd546542398debfeedc34c646e"
format_stamp: "Formatted at 2026-08-12 06:17:53 on dist-test-slave-jpj1"
I20260812 06:17:54.009147 24241 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-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:17:54.029816 24241 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:54.030503 24241 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:17:54.030665 24241 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:54.038255 24356 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.172.126:39463 every 8 connection(s)
I20260812 06:17:54.038259 24241 rpc_server.cc:307] RPC server started. Bound to: 127.23.172.126:39463
I20260812 06:17:54.040686 24358 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:17:54.046224 24358 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e: Bootstrap starting.
I20260812 06:17:54.048622 24358 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:54.049511 24358 log.cc:826] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:54.051158 24358 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e: No bootstrap required, opened a new log
I20260812 06:17:54.053956 24358 raft_consensus.cc:359] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a023d7bd546542398debfeedc34c646e" member_type: VOTER }
I20260812 06:17:54.054127 24358 raft_consensus.cc:385] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:54.054184 24358 raft_consensus.cc:740] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a023d7bd546542398debfeedc34c646e, State: Initialized, Role: FOLLOWER
I20260812 06:17:54.054724 24358 consensus_queue.cc:260] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [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: "a023d7bd546542398debfeedc34c646e" member_type: VOTER }
I20260812 06:17:54.054857 24358 raft_consensus.cc:399] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:54.054903 24358 raft_consensus.cc:493] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:54.054993 24358 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:54.055775 24358 raft_consensus.cc:515] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a023d7bd546542398debfeedc34c646e" member_type: VOTER }
I20260812 06:17:54.056164 24358 leader_election.cc:304] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [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: a023d7bd546542398debfeedc34c646e; no voters: 
I20260812 06:17:54.056435 24358 leader_election.cc:290] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:54.056588 24362 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:54.056792 24362 raft_consensus.cc:697] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [term 1 LEADER]: Becoming Leader. State: Replica: a023d7bd546542398debfeedc34c646e, State: Running, Role: LEADER
I20260812 06:17:54.057207 24362 consensus_queue.cc:237] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [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: "a023d7bd546542398debfeedc34c646e" member_type: VOTER }
I20260812 06:17:54.057348 24358 sys_catalog.cc:565] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:54.059151 24364 sys_catalog.cc:455] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [sys.catalog]: SysCatalogTable state changed. Reason: New leader a023d7bd546542398debfeedc34c646e. Latest consensus state: current_term: 1 leader_uuid: "a023d7bd546542398debfeedc34c646e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a023d7bd546542398debfeedc34c646e" member_type: VOTER } }
I20260812 06:17:54.059186 24363 sys_catalog.cc:455] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a023d7bd546542398debfeedc34c646e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a023d7bd546542398debfeedc34c646e" member_type: VOTER } }
I20260812 06:17:54.059275 24364 sys_catalog.cc:458] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:54.059275 24363 sys_catalog.cc:458] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:54.059582 24241 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:54.059634 24389 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:54.061792 24389 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:54.066403 24389 catalog_manager.cc:1383] Generated new cluster ID: 2588106552f34ae0959efe380e397597
I20260812 06:17:54.066470 24389 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:54.077293 24389 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:54.078446 24389 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:54.095548 24389 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e: Generated new TSK 0
I20260812 06:17:54.096395 24389 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:54.124472 24241 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:54.127094 24395 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:17:54.127130 24400 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:17:54.127111 24396 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:17:54.127673 24241 server_base.cc:1061] running on GCE node
I20260812 06:17:54.127858 24241 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:54.127908 24241 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:17:54.127938 24241 hybrid_clock.cc:648] HybridClock initialized: now 1786515474127937 us; error 0 us; skew 500 ppm
I20260812 06:17:54.128882 24241 webserver.cc:533] Webserver started at http://127.23.172.65:40701/ using document root <none> and password file <none>
I20260812 06:17:54.129053 24241 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:54.129113 24241 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:54.129191 24241 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:54.129655 24241 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/instance:
uuid: "689d19170d974e3991a99b8b06b7e8dc"
format_stamp: "Formatted at 2026-08-12 06:17:54 on dist-test-slave-jpj1"
I20260812 06:17:54.131453 24241 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:17:54.132588 24408 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:17:54.132869 24241 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:54.132951 24241 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root
uuid: "689d19170d974e3991a99b8b06b7e8dc"
format_stamp: "Formatted at 2026-08-12 06:17:54 on dist-test-slave-jpj1"
I20260812 06:17:54.133023 24241 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-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:17:54.146962 24241 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:54.147511 24241 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:54.148075 24241 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:54.149094 24241 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:54.149163 24241 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:54.149227 24241 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:54.149259 24241 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:54.156308 24241 rpc_server.cc:307] RPC server started. Bound to: 127.23.172.65:42117
I20260812 06:17:54.156368 24529 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.172.65:42117 every 8 connection(s)
I20260812 06:17:54.168797 24532 heartbeater.cc:344] Connected to a master server at 127.23.172.126:39463
I20260812 06:17:54.169049 24532 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:54.169517 24532 heartbeater.cc:507] Master 127.23.172.126:39463 requested a full tablet report, sending...
I20260812 06:17:54.170986 24296 ts_manager.cc:194] Registered new tserver with Master: 689d19170d974e3991a99b8b06b7e8dc (127.23.172.65:42117)
I20260812 06:17:54.171598 24241 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014623497s
I20260812 06:17:54.172456 24296 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53138
I20260812 06:17:54.180536 24296 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53140:
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:17:54.196777 24462 tablet_service.cc:1511] Processing CreateTablet for tablet 2a5f78d76cc14a40981810d1257f3e34 (DEFAULT_TABLE table=heavy-update-compaction-test [id=de39e436dfad401ba39793bf167c381b]), partition=
I20260812 06:17:54.197259 24462 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2a5f78d76cc14a40981810d1257f3e34. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:54.199743 24560 tablet_bootstrap.cc:492] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Bootstrap starting.
I20260812 06:17:54.201058 24560 tablet_bootstrap.cc:654] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:54.202160 24560 tablet_bootstrap.cc:492] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: No bootstrap required, opened a new log
I20260812 06:17:54.202255 24560 ts_tablet_manager.cc:1403] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:54.202786 24560 raft_consensus.cc:359] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "689d19170d974e3991a99b8b06b7e8dc" member_type: VOTER last_known_addr { host: "127.23.172.65" port: 42117 } }
I20260812 06:17:54.202927 24560 raft_consensus.cc:385] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:54.203020 24560 raft_consensus.cc:740] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 689d19170d974e3991a99b8b06b7e8dc, State: Initialized, Role: FOLLOWER
I20260812 06:17:54.203207 24560 consensus_queue.cc:260] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [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: "689d19170d974e3991a99b8b06b7e8dc" member_type: VOTER last_known_addr { host: "127.23.172.65" port: 42117 } }
I20260812 06:17:54.203325 24560 raft_consensus.cc:399] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:54.203368 24560 raft_consensus.cc:493] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:54.203419 24560 raft_consensus.cc:3060] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:54.204226 24560 raft_consensus.cc:515] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "689d19170d974e3991a99b8b06b7e8dc" member_type: VOTER last_known_addr { host: "127.23.172.65" port: 42117 } }
I20260812 06:17:54.204362 24560 leader_election.cc:304] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [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: 689d19170d974e3991a99b8b06b7e8dc; no voters: 
I20260812 06:17:54.204569 24560 leader_election.cc:290] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:54.204887 24563 raft_consensus.cc:2804] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:54.204952 24560 ts_tablet_manager.cc:1434] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:54.205173 24563 raft_consensus.cc:697] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [term 1 LEADER]: Becoming Leader. State: Replica: 689d19170d974e3991a99b8b06b7e8dc, State: Running, Role: LEADER
I20260812 06:17:54.205168 24532 heartbeater.cc:499] Master 127.23.172.126:39463 was elected leader, sending a full tablet report...
I20260812 06:17:54.205351 24563 consensus_queue.cc:237] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [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: "689d19170d974e3991a99b8b06b7e8dc" member_type: VOTER last_known_addr { host: "127.23.172.65" port: 42117 } }
I20260812 06:17:54.208168 24296 catalog_manager.cc:5719] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc reported cstate change: term changed from 0 to 1, leader changed from <none> to 689d19170d974e3991a99b8b06b7e8dc (127.23.172.65). New cstate: current_term: 1 leader_uuid: "689d19170d974e3991a99b8b06b7e8dc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "689d19170d974e3991a99b8b06b7e8dc" member_type: VOTER last_known_addr { host: "127.23.172.65" port: 42117 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:54.278461 24241 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.023s	sys 0.008s
I20260812 06:17:54.407582 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushMRSOp(2a5f78d76cc14a40981810d1257f3e34): perf score=16.078378
I20260812 06:17:54.570926 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushMRSOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.163s	user 0.119s	sys 0.037s Metrics: {"bytes_written":9599900,"cfile_init":1,"compiler_manager_pool.queue_time_us":401,"delete_count":0,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":960,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39043,"lbm_writes_lt_1ms":691,"mutex_wait_us":1146,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":157,"threads_started":1,"update_count":1170}
I20260812 06:17:54.572271 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling LogGCOp(2a5f78d76cc14a40981810d1257f3e34): free 20743880 bytes of WAL
I20260812 06:17:54.572607 24417 log_reader.cc:385] T 2a5f78d76cc14a40981810d1257f3e34: removed 2 log segments from log reader
I20260812 06:17:54.572745 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000001 (ops 1-6)
I20260812 06:17:54.572844 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000002 (ops 7-11)
I20260812 06:17:54.578372 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: LogGCOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:54.578742 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling UndoDeltaBlockGCOp(2a5f78d76cc14a40981810d1257f3e34): 16411399 bytes on disk
I20260812 06:17:54.579427 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: UndoDeltaBlockGCOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:17:54.579879 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.196750
I20260812 06:17:54.592077 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.012s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3118059,"delete_count":0,"lbm_write_time_us":4383,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:17:54.592607 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:54.605261 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4628,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:54.605897 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:54.735330 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.129s	user 0.093s	sys 0.036s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672364,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":588,"lbm_read_time_us":8289,"lbm_reads_lt_1ms":465,"lbm_write_time_us":23427,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":270,"threads_started":5,"update_count":2000}
I20260812 06:17:54.735891 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=10.126437
I20260812 06:17:54.779155 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.043s	user 0.004s	sys 0.028s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14891,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:54.779773 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:54.790515 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3857,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.791258 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:54.910799 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.119s	user 0.100s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":154,"lbm_read_time_us":8698,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22405,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:17:54.911449 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=10.126437
I20260812 06:17:54.948735 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.037s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15311,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:54.949331 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:54.960330 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3831,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.960865 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:55.080546 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.119s	user 0.093s	sys 0.026s 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":790,"lbm_read_time_us":8694,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22620,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:55.081378 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=10.126437
I20260812 06:17:55.129618 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.048s	user 0.034s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16610,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.130263 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:55.145828 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.146328 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:55.291754 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.145s	user 0.084s	sys 0.061s 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":959,"lbm_read_time_us":11180,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24778,"lbm_writes_lt_1ms":443,"mutex_wait_us":342,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:17:55.292217 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=10.126437
I20260812 06:17:55.334365 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.042s	user 0.027s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14472,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.334852 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:55.350073 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5639,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.350647 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:55.472069 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.121s	user 0.099s	sys 0.021s 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":1521,"lbm_read_time_us":8796,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23627,"lbm_writes_lt_1ms":443,"mutex_wait_us":324,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:55.472580 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=10.126437
I20260812 06:17:55.513473 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.041s	user 0.026s	sys 0.010s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16249,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.514038 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:55.525308 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3923,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.525818 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:55.637272 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.111s	user 0.091s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":400,"lbm_read_time_us":7657,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20660,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":121472,"update_count":2000}
I20260812 06:17:55.637981 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=10.126437
I20260812 06:17:55.684113 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.046s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14164,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.684716 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:55.700156 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.700703 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushMRSOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:55.738987 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushMRSOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.038s	user 0.024s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":1198,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1911,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:55.739892 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling LogGCOp(2a5f78d76cc14a40981810d1257f3e34): free 112239311 bytes of WAL
I20260812 06:17:55.740110 24417 log_reader.cc:385] T 2a5f78d76cc14a40981810d1257f3e34: removed 11 log segments from log reader
I20260812 06:17:55.740157 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000003 (ops 12-16)
I20260812 06:17:55.740186 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000004 (ops 17-21)
I20260812 06:17:55.740218 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000005 (ops 22-26)
I20260812 06:17:55.740250 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000006 (ops 27-31)
I20260812 06:17:55.740273 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000007 (ops 32-36)
I20260812 06:17:55.740314 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000008 (ops 37-41)
I20260812 06:17:55.740348 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000009 (ops 42-46)
I20260812 06:17:55.740381 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000010 (ops 47-50)
I20260812 06:17:55.740411 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000011 (ops 51-55)
I20260812 06:17:55.740442 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000012 (ops 56-60)
I20260812 06:17:55.740473 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000013 (ops 61-65)
I20260812 06:17:55.760823 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: LogGCOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.021s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:55.761227 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:55.781860 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.020s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4107,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.782373 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling UndoDeltaBlockGCOp(2a5f78d76cc14a40981810d1257f3e34): 447 bytes on disk
I20260812 06:17:55.782853 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: UndoDeltaBlockGCOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:17:55.783372 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:55.793862 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3750,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.794515 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:55.992522 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.198s	user 0.126s	sys 0.069s 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":6064,"lbm_read_time_us":12161,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34664,"lbm_writes_lt_1ms":643,"mutex_wait_us":2856,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":67456,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:17:55.993116 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=14.095187
I20260812 06:17:56.049135 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.055s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22028,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.049649 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:56.059880 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3719,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.060446 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:56.232508 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.172s	user 0.119s	sys 0.052s 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":197,"lbm_read_time_us":11850,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30347,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2500}
I20260812 06:17:56.233180 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=14.095187
I20260812 06:17:56.295735 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.062s	user 0.034s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24954,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.296265 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:56.306886 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.307344 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:56.480137 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.173s	user 0.137s	sys 0.035s 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":124,"lbm_read_time_us":12480,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28589,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:17:56.480696 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=11.118625
I20260812 06:17:56.535785 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.055s	user 0.023s	sys 0.031s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":22460,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:17:56.536239 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:56.552423 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.016s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.552887 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:56.562206 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.009s	user 0.006s	sys 0.001s 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:17:56.562703 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:56.737923 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.175s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":625,"lbm_read_time_us":12147,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27185,"lbm_writes_lt_1ms":543,"mutex_wait_us":321,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":41856,"update_count":2500}
I20260812 06:17:56.738479 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=14.095187
I20260812 06:17:56.796044 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.057s	user 0.026s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21736,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.796577 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:56.807090 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3893,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.807660 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:56.972230 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.164s	user 0.106s	sys 0.057s 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":683,"lbm_read_time_us":11700,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27533,"lbm_writes_lt_1ms":543,"mutex_wait_us":340,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:56.972862 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=10.126437
I20260812 06:17:57.004277 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.031s	user 0.025s	sys 0.005s Metrics: {"bytes_written":12389540,"delete_count":0,"lbm_write_time_us":13691,"lbm_writes_lt_1ms":305,"reinsert_count":0,"update_count":1510}
I20260812 06:17:57.005012 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:57.019820 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":5775,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:57.020327 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:57.138849 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.118s	user 0.097s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1218,"lbm_read_time_us":7302,"lbm_reads_lt_1ms":468,"lbm_write_time_us":22580,"lbm_writes_lt_1ms":443,"mutex_wait_us":480,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2000}
I20260812 06:17:57.139472 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=10.126437
I20260812 06:17:57.179720 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.040s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15138,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.180249 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:57.190610 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3732,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.191370 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushMRSOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:57.222908 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushMRSOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":301,"dirs.run_wall_time_us":1327,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1888,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:57.223682 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling LogGCOp(2a5f78d76cc14a40981810d1257f3e34): free 125163362 bytes of WAL
I20260812 06:17:57.223904 24417 log_reader.cc:385] T 2a5f78d76cc14a40981810d1257f3e34: removed 12 log segments from log reader
I20260812 06:17:57.223953 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000014 (ops 66-70)
I20260812 06:17:57.223984 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000015 (ops 71-75)
I20260812 06:17:57.224015 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000016 (ops 76-80)
I20260812 06:17:57.224047 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000017 (ops 81-85)
I20260812 06:17:57.224080 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000018 (ops 86-91)
I20260812 06:17:57.224112 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000019 (ops 92-96)
I20260812 06:17:57.224143 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000020 (ops 97-101)
I20260812 06:17:57.224175 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000021 (ops 102-106)
I20260812 06:17:57.224206 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000022 (ops 107-111)
I20260812 06:17:57.224244 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000023 (ops 112-116)
I20260812 06:17:57.224283 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000024 (ops 117-121)
I20260812 06:17:57.224318 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000025 (ops 122-126)
I20260812 06:17:57.250866 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: LogGCOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:57.251389 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling UndoDeltaBlockGCOp(2a5f78d76cc14a40981810d1257f3e34): 472 bytes on disk
I20260812 06:17:57.252055 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: UndoDeltaBlockGCOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:17:57.252645 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=3.181125
I20260812 06:17:57.269580 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4594953,"delete_count":0,"lbm_write_time_us":6738,"lbm_writes_lt_1ms":115,"reinsert_count":0,"update_count":560}
I20260812 06:17:57.270042 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:57.279642 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":3319,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:17:57.280277 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:57.454407 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.174s	user 0.136s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1266,"lbm_read_time_us":12346,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34348,"lbm_writes_lt_1ms":643,"mutex_wait_us":353,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5504,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:17:57.455107 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=14.095187
I20260812 06:17:57.509976 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.055s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20728,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.510521 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:57.521618 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.522111 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:57.673509 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.151s	user 0.105s	sys 0.035s 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":1037,"lbm_read_time_us":9417,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27765,"lbm_writes_lt_1ms":543,"mutex_wait_us":348,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:57.674162 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=14.095187
I20260812 06:17:57.729552 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.055s	user 0.025s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20971,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.730086 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:57.741559 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3975,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.742246 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:57.885327 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.143s	user 0.119s	sys 0.024s 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":282,"lbm_read_time_us":8994,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29978,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:57.885998 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=11.118625
I20260812 06:17:57.921037 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.035s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14074,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:57.921751 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:57.943351 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.021s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5270,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:57.943873 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:57.954077 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3765,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.954545 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:58.112362 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.158s	user 0.111s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":301,"lbm_read_time_us":10140,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28983,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:17:58.113018 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=14.095187
I20260812 06:17:58.160274 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.047s	user 0.027s	sys 0.014s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18979,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.160964 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:58.306169 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.145s	user 0.111s	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":1318,"lbm_read_time_us":9684,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23969,"lbm_writes_lt_1ms":443,"mutex_wait_us":295,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.306833 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=14.095187
I20260812 06:17:58.370074 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.063s	user 0.028s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25537,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.370656 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:58.381062 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3849,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.381904 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:58.572347 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.190s	user 0.127s	sys 0.051s 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":526,"lbm_read_time_us":12512,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28765,"lbm_writes_lt_1ms":543,"mutex_wait_us":260,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:58.573019 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=14.095187
I20260812 06:17:58.627238 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.054s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19324,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.627966 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=2.188937
I20260812 06:17:58.638506 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3944,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.639107 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushMRSOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:58.669396 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushMRSOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.030s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1295,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1409,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:58.670177 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:58.830219 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.160s	user 0.099s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":982,"lbm_read_time_us":12011,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26033,"lbm_writes_lt_1ms":543,"mutex_wait_us":311,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29440,"update_count":2500}
I20260812 06:17:58.830828 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling LogGCOp(2a5f78d76cc14a40981810d1257f3e34): free 132571582 bytes of WAL
I20260812 06:17:58.831071 24417 log_reader.cc:385] T 2a5f78d76cc14a40981810d1257f3e34: removed 13 log segments from log reader
I20260812 06:17:58.831127 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000026 (ops 127-131)
I20260812 06:17:58.831182 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000027 (ops 132-136)
I20260812 06:17:58.831213 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000028 (ops 137-140)
I20260812 06:17:58.831290 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000029 (ops 141-145)
I20260812 06:17:58.831331 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000030 (ops 146-150)
I20260812 06:17:58.831353 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000031 (ops 151-155)
I20260812 06:17:58.831377 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000032 (ops 156-160)
I20260812 06:17:58.831424 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000033 (ops 161-165)
I20260812 06:17:58.831459 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000034 (ops 166-170)
I20260812 06:17:58.831516 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000035 (ops 171-174)
I20260812 06:17:58.831599 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000036 (ops 175-179)
I20260812 06:17:58.831640 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000037 (ops 180-184)
I20260812 06:17:58.831697 24417 log.cc:1079] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/2a5f78d76cc14a40981810d1257f3e34/wal-000000038 (ops 185-189)
I20260812 06:17:58.862216 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: LogGCOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.031s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:17:58.862650 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling UndoDeltaBlockGCOp(2a5f78d76cc14a40981810d1257f3e34): 482 bytes on disk
I20260812 06:17:58.863062 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: UndoDeltaBlockGCOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:58.863771 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=17.071750
I20260812 06:17:58.927804 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.064s	user 0.036s	sys 0.024s Metrics: {"bytes_written":18789302,"delete_count":0,"lbm_write_time_us":22878,"lbm_writes_lt_1ms":461,"reinsert_count":0,"update_count":2290}
I20260812 06:17:58.928387 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34): perf score=4.173312
I20260812 06:17:58.949072 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: FlushDeltaMemStoresOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.020s	user 0.006s	sys 0.013s Metrics: {"bytes_written":5825685,"delete_count":0,"lbm_write_time_us":8048,"lbm_writes_lt_1ms":145,"reinsert_count":0,"update_count":710}
I20260812 06:17:58.949718 24534 maintenance_manager.cc:419] P 689d19170d974e3991a99b8b06b7e8dc: Scheduling MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34): perf score=1.000000
I20260812 06:17:58.994752 24241 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.716s	user 1.700s	sys 0.135s
I20260812 06:17:59.074157 24241 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.079s	user 0.001s	sys 0.000s
I20260812 06:17:59.074839 24241 tablet_server.cc:179] TabletServer@127.23.172.65:0 shutting down...
I20260812 06:17:59.117115 24417 maintenance_manager.cc:643] P 689d19170d974e3991a99b8b06b7e8dc: MajorDeltaCompactionOp(2a5f78d76cc14a40981810d1257f3e34) complete. Timing: real 0.167s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":243,"lbm_read_time_us":14810,"lbm_reads_lt_1ms":668,"lbm_write_time_us":27253,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":3000}
I20260812 06:17:59.117796 24241 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:59.118227 24241 tablet_replica.cc:333] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc: stopping tablet replica
I20260812 06:17:59.118470 24241 raft_consensus.cc:2243] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:59.118737 24241 raft_consensus.cc:2272] T 2a5f78d76cc14a40981810d1257f3e34 P 689d19170d974e3991a99b8b06b7e8dc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:59.135090 24241 tablet_server.cc:196] TabletServer@127.23.172.65:0 shutdown complete.
I20260812 06:17:59.170117 24241 master.cc:562] Master@127.23.172.126:39463 shutting down...
I20260812 06:17:59.173918 24241 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:59.174108 24241 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:59.174165 24241 tablet_replica.cc:333] T 00000000000000000000000000000000 P a023d7bd546542398debfeedc34c646e: stopping tablet replica
I20260812 06:17:59.186466 24241 master.cc:584] Master@127.23.172.126:39463 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5286 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:59.279844 24241 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.172.126:43407
I20260812 06:17:59.280249 24241 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:59.282320 24605 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:17:59.282352 24608 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:17:59.282320 24611 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:17:59.282491 24241 server_base.cc:1061] running on GCE node
I20260812 06:17:59.282688 24241 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:59.282735 24241 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:17:59.282750 24241 hybrid_clock.cc:648] HybridClock initialized: now 1786515479282750 us; error 0 us; skew 500 ppm
I20260812 06:17:59.283586 24241 webserver.cc:533] Webserver started at http://127.23.172.126:34157/ using document root <none> and password file <none>
I20260812 06:17:59.283737 24241 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:59.283780 24241 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:59.283838 24241 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:59.284185 24241 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/master-0-root/instance:
uuid: "e3beb07d3b5c46e8b63b816c2be3b414"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-jpj1"
I20260812 06:17:59.285703 24241 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:59.286578 24619 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:17:59.286787 24241 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:59.286854 24241 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/master-0-root
uuid: "e3beb07d3b5c46e8b63b816c2be3b414"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-jpj1"
I20260812 06:17:59.286927 24241 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-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:17:59.307960 24241 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:59.308399 24241 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:59.312738 24241 rpc_server.cc:307] RPC server started. Bound to: 127.23.172.126:43407
I20260812 06:17:59.317679 24702 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.172.126:43407 every 8 connection(s)
I20260812 06:17:59.318081 24703 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:17:59.319938 24703 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414: Bootstrap starting.
I20260812 06:17:59.320724 24703 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:59.321830 24703 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414: No bootstrap required, opened a new log
I20260812 06:17:59.322243 24703 raft_consensus.cc:359] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3beb07d3b5c46e8b63b816c2be3b414" member_type: VOTER }
I20260812 06:17:59.322337 24703 raft_consensus.cc:385] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:59.322371 24703 raft_consensus.cc:740] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e3beb07d3b5c46e8b63b816c2be3b414, State: Initialized, Role: FOLLOWER
I20260812 06:17:59.322515 24703 consensus_queue.cc:260] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [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: "e3beb07d3b5c46e8b63b816c2be3b414" member_type: VOTER }
I20260812 06:17:59.322592 24703 raft_consensus.cc:399] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:59.322640 24703 raft_consensus.cc:493] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:59.322696 24703 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:59.323393 24703 raft_consensus.cc:515] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3beb07d3b5c46e8b63b816c2be3b414" member_type: VOTER }
I20260812 06:17:59.323566 24703 leader_election.cc:304] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [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: e3beb07d3b5c46e8b63b816c2be3b414; no voters: 
I20260812 06:17:59.323758 24703 leader_election.cc:290] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:59.323865 24707 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:59.324054 24707 raft_consensus.cc:697] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [term 1 LEADER]: Becoming Leader. State: Replica: e3beb07d3b5c46e8b63b816c2be3b414, State: Running, Role: LEADER
I20260812 06:17:59.324206 24703 sys_catalog.cc:565] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:59.324187 24707 consensus_queue.cc:237] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [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: "e3beb07d3b5c46e8b63b816c2be3b414" member_type: VOTER }
I20260812 06:17:59.324663 24711 sys_catalog.cc:455] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e3beb07d3b5c46e8b63b816c2be3b414. Latest consensus state: current_term: 1 leader_uuid: "e3beb07d3b5c46e8b63b816c2be3b414" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3beb07d3b5c46e8b63b816c2be3b414" member_type: VOTER } }
I20260812 06:17:59.324642 24708 sys_catalog.cc:455] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e3beb07d3b5c46e8b63b816c2be3b414" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3beb07d3b5c46e8b63b816c2be3b414" member_type: VOTER } }
I20260812 06:17:59.324831 24711 sys_catalog.cc:458] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:59.324853 24708 sys_catalog.cc:458] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:59.325400 24716 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:59.326295 24716 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:59.326458 24241 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:59.328099 24716 catalog_manager.cc:1383] Generated new cluster ID: 679bea8d8d02481687b9e07a3a798ab5
I20260812 06:17:59.328161 24716 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:59.334295 24716 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:59.334828 24716 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:59.349267 24716 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414: Generated new TSK 0
I20260812 06:17:59.349469 24716 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:59.358915 24241 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:59.360987 24735 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:17:59.361038 24741 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:17:59.361234 24241 server_base.cc:1061] running on GCE node
W20260812 06:17:59.361078 24736 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:17:59.361485 24241 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:59.361528 24241 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:17:59.361549 24241 hybrid_clock.cc:648] HybridClock initialized: now 1786515479361549 us; error 0 us; skew 500 ppm
I20260812 06:17:59.362416 24241 webserver.cc:533] Webserver started at http://127.23.172.65:46735/ using document root <none> and password file <none>
I20260812 06:17:59.362577 24241 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:59.362632 24241 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:59.362709 24241 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:59.363101 24241 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/instance:
uuid: "bf2f6f5af4ab4988b29e9105e826437e"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-jpj1"
I20260812 06:17:59.364655 24241 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:59.365760 24752 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:17:59.366008 24241 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:59.366083 24241 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root
uuid: "bf2f6f5af4ab4988b29e9105e826437e"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-jpj1"
I20260812 06:17:59.366156 24241 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-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:17:59.375837 24241 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:59.376272 24241 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:59.376603 24241 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:59.377095 24241 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:59.377136 24241 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.377187 24241 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:59.377211 24241 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.381482 24241 rpc_server.cc:307] RPC server started. Bound to: 127.23.172.65:38635
I20260812 06:17:59.381518 24875 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.172.65:38635 every 8 connection(s)
I20260812 06:17:59.389011 24876 heartbeater.cc:344] Connected to a master server at 127.23.172.126:43407
I20260812 06:17:59.389127 24876 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:59.389379 24876 heartbeater.cc:507] Master 127.23.172.126:43407 requested a full tablet report, sending...
I20260812 06:17:59.390061 24643 ts_manager.cc:194] Registered new tserver with Master: bf2f6f5af4ab4988b29e9105e826437e (127.23.172.65:38635)
I20260812 06:17:59.390740 24241 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008809936s
I20260812 06:17:59.390847 24643 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45614
I20260812 06:17:59.397696 24643 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45624:
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:17:59.414233 24811 tablet_service.cc:1511] Processing CreateTablet for tablet 64ab4f1af142440e861c94d3394fa89d (DEFAULT_TABLE table=heavy-update-compaction-test [id=1bcf0a43b4a849e29f4c32499086c1b5]), partition=
I20260812 06:17:59.414585 24811 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 64ab4f1af142440e861c94d3394fa89d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:59.417153 24900 tablet_bootstrap.cc:492] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Bootstrap starting.
I20260812 06:17:59.418234 24900 tablet_bootstrap.cc:654] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:59.419584 24900 tablet_bootstrap.cc:492] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: No bootstrap required, opened a new log
I20260812 06:17:59.419718 24900 ts_tablet_manager.cc:1403] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:59.420243 24900 raft_consensus.cc:359] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf2f6f5af4ab4988b29e9105e826437e" member_type: VOTER last_known_addr { host: "127.23.172.65" port: 38635 } }
I20260812 06:17:59.420382 24900 raft_consensus.cc:385] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:59.420433 24900 raft_consensus.cc:740] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bf2f6f5af4ab4988b29e9105e826437e, State: Initialized, Role: FOLLOWER
I20260812 06:17:59.420588 24900 consensus_queue.cc:260] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [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: "bf2f6f5af4ab4988b29e9105e826437e" member_type: VOTER last_known_addr { host: "127.23.172.65" port: 38635 } }
I20260812 06:17:59.420698 24900 raft_consensus.cc:399] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:59.420758 24900 raft_consensus.cc:493] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:59.420840 24900 raft_consensus.cc:3060] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:59.421761 24900 raft_consensus.cc:515] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf2f6f5af4ab4988b29e9105e826437e" member_type: VOTER last_known_addr { host: "127.23.172.65" port: 38635 } }
I20260812 06:17:59.421912 24900 leader_election.cc:304] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [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: bf2f6f5af4ab4988b29e9105e826437e; no voters: 
I20260812 06:17:59.422106 24900 leader_election.cc:290] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:59.422271 24902 raft_consensus.cc:2804] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:59.422379 24900 ts_tablet_manager.cc:1434] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:59.422431 24876 heartbeater.cc:499] Master 127.23.172.126:43407 was elected leader, sending a full tablet report...
I20260812 06:17:59.422540 24902 raft_consensus.cc:697] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [term 1 LEADER]: Becoming Leader. State: Replica: bf2f6f5af4ab4988b29e9105e826437e, State: Running, Role: LEADER
I20260812 06:17:59.422696 24902 consensus_queue.cc:237] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [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: "bf2f6f5af4ab4988b29e9105e826437e" member_type: VOTER last_known_addr { host: "127.23.172.65" port: 38635 } }
I20260812 06:17:59.424250 24643 catalog_manager.cc:5719] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e reported cstate change: term changed from 0 to 1, leader changed from <none> to bf2f6f5af4ab4988b29e9105e826437e (127.23.172.65). New cstate: current_term: 1 leader_uuid: "bf2f6f5af4ab4988b29e9105e826437e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf2f6f5af4ab4988b29e9105e826437e" member_type: VOTER last_known_addr { host: "127.23.172.65" port: 38635 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:59.487248 24241 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.018s	sys 0.008s
I20260812 06:17:59.632530 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushMRSOp(64ab4f1af142440e861c94d3394fa89d): perf score=19.054940
I20260812 06:17:59.800499 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushMRSOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.168s	user 0.119s	sys 0.048s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":42,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":836,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42598,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:59.801206 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling LogGCOp(64ab4f1af142440e861c94d3394fa89d): free 20743880 bytes of WAL
I20260812 06:17:59.801442 24762 log_reader.cc:385] T 64ab4f1af142440e861c94d3394fa89d: removed 2 log segments from log reader
I20260812 06:17:59.801492 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000001 (ops 1-6)
I20260812 06:17:59.801523 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000002 (ops 7-11)
I20260812 06:17:59.805352 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: LogGCOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:59.805742 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:17:59.817040 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3861,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.817612 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:17:59.963342 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.146s	user 0.093s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":454,"lbm_read_time_us":11001,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23807,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":288,"threads_started":5,"update_count":2000}
I20260812 06:17:59.963912 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=11.118625
I20260812 06:17:59.995707 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.032s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13694,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:59.996465 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:00.012188 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5607,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:00.012763 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:00.146965 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.134s	user 0.084s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2347,"lbm_read_time_us":8710,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24563,"lbm_writes_lt_1ms":443,"mutex_wait_us":655,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.147713 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling UndoDeltaBlockGCOp(64ab4f1af142440e861c94d3394fa89d): 16411394 bytes on disk
I20260812 06:18:00.148244 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: UndoDeltaBlockGCOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:18:00.149842 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=10.126437
I20260812 06:18:00.185565 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.035s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14269,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.186110 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:00.203984 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.018s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6522,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.204613 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:00.334785 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.130s	user 0.082s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":727,"lbm_read_time_us":8531,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25444,"lbm_writes_lt_1ms":443,"mutex_wait_us":341,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:18:00.335317 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=10.126437
I20260812 06:18:00.378295 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.043s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18633,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.378810 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:00.389884 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3984,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.390529 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:00.518932 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.128s	user 0.104s	sys 0.024s 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":230,"lbm_read_time_us":9026,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23836,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:18:00.519718 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=10.126437
I20260812 06:18:00.562423 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.042s	user 0.013s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13049,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.562920 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:00.573839 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4129,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.574318 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:00.724090 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.150s	user 0.117s	sys 0.032s 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":467,"lbm_read_time_us":10703,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23781,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":59776,"update_count":2000}
I20260812 06:18:00.724687 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=10.126437
I20260812 06:18:00.768771 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.044s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15230,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.769255 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:00.780989 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.781509 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:00.912166 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.130s	user 0.099s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1258,"lbm_read_time_us":9020,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26576,"lbm_writes_lt_1ms":443,"mutex_wait_us":343,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:00.912824 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=10.126437
I20260812 06:18:00.952087 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.039s	user 0.033s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17220,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.952626 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:00.963498 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.964229 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushMRSOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:00.991433 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushMRSOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.027s	user 0.024s	sys 0.002s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1581,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1480,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:00.992142 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling LogGCOp(64ab4f1af142440e861c94d3394fa89d): free 112692367 bytes of WAL
I20260812 06:18:00.992396 24762 log_reader.cc:385] T 64ab4f1af142440e861c94d3394fa89d: removed 11 log segments from log reader
I20260812 06:18:00.992447 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000003 (ops 12-16)
I20260812 06:18:00.992486 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000004 (ops 17-21)
I20260812 06:18:00.992518 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000005 (ops 22-26)
I20260812 06:18:00.992550 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000006 (ops 27-31)
I20260812 06:18:00.992583 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000007 (ops 32-36)
I20260812 06:18:00.992623 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000008 (ops 37-41)
I20260812 06:18:00.992655 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000009 (ops 42-46)
I20260812 06:18:00.992753 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000010 (ops 47-51)
I20260812 06:18:00.992779 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000011 (ops 52-56)
I20260812 06:18:00.992810 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000012 (ops 57-61)
I20260812 06:18:00.992841 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000013 (ops 62-66)
I20260812 06:18:01.017027 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: LogGCOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:01.017519 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=3.181125
I20260812 06:18:01.036494 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.019s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6015,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:01.037029 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling UndoDeltaBlockGCOp(64ab4f1af142440e861c94d3394fa89d): 448 bytes on disk
I20260812 06:18:01.037520 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: UndoDeltaBlockGCOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:01.038038 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:01.048056 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3408,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:01.048725 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:01.220830 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.172s	user 0.112s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":738,"lbm_read_time_us":13691,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32297,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5760,"thread_start_us":122,"threads_started":1,"update_count":3000}
I20260812 06:18:01.221417 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=14.095187
I20260812 06:18:01.270570 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.049s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20340,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.271195 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:01.283386 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4403,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.283897 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:01.453198 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.169s	user 0.100s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":668,"lbm_read_time_us":11671,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28971,"lbm_writes_lt_1ms":543,"mutex_wait_us":369,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:18:01.453845 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=14.095187
I20260812 06:18:01.495111 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.041s	user 0.029s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18140,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.495631 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:01.635965 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.140s	user 0.099s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":168,"lbm_read_time_us":9030,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24165,"lbm_writes_lt_1ms":443,"mutex_wait_us":95,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2000}
I20260812 06:18:01.636590 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=11.118625
I20260812 06:18:01.674381 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.038s	user 0.035s	sys 0.000s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15967,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:01.675042 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:01.699384 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.024s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4704,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:01.699941 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:01.710450 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3796,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.710942 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:01.893740 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.183s	user 0.111s	sys 0.056s 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":191,"lbm_read_time_us":9916,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27860,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:18:01.894311 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=14.095187
I20260812 06:18:01.941644 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.047s	user 0.035s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17772,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.942306 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:01.958745 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.016s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6361,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.959321 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:02.120679 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.161s	user 0.116s	sys 0.043s 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":984,"lbm_read_time_us":9942,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30069,"lbm_writes_lt_1ms":543,"mutex_wait_us":280,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:18:02.121210 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=11.118625
I20260812 06:18:02.165279 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.044s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19829,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:02.165856 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:02.189652 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.024s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3605,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.190194 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:02.201050 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3777,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.201798 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:02.360154 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.158s	user 0.123s	sys 0.031s 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":201,"lbm_read_time_us":12074,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28721,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":90880,"update_count":2500}
I20260812 06:18:02.360854 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=11.118625
I20260812 06:18:02.399246 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.038s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16380,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:02.401930 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:02.419015 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4779,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.420495 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushMRSOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:02.462618 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushMRSOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.042s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1315,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1631,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:02.463305 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=3.181125
I20260812 06:18:02.476924 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:02.477414 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling LogGCOp(64ab4f1af142440e861c94d3394fa89d): free 132118257 bytes of WAL
I20260812 06:18:02.477653 24762 log_reader.cc:385] T 64ab4f1af142440e861c94d3394fa89d: removed 13 log segments from log reader
I20260812 06:18:02.477717 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000014 (ops 67-71)
I20260812 06:18:02.477766 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000015 (ops 72-76)
I20260812 06:18:02.477797 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000016 (ops 77-81)
I20260812 06:18:02.477824 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000017 (ops 82-86)
I20260812 06:18:02.477854 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000018 (ops 87-91)
I20260812 06:18:02.477885 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000019 (ops 92-96)
I20260812 06:18:02.477916 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000020 (ops 97-100)
I20260812 06:18:02.477942 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000021 (ops 101-105)
I20260812 06:18:02.477970 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000022 (ops 106-110)
I20260812 06:18:02.477999 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000023 (ops 111-114)
I20260812 06:18:02.478030 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000024 (ops 115-119)
I20260812 06:18:02.478070 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000025 (ops 120-124)
I20260812 06:18:02.478098 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000026 (ops 125-128)
I20260812 06:18:02.508556 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: LogGCOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:02.509116 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling UndoDeltaBlockGCOp(64ab4f1af142440e861c94d3394fa89d): 482 bytes on disk
I20260812 06:18:02.509620 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: UndoDeltaBlockGCOp(64ab4f1af142440e861c94d3394fa89d) 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:02.510224 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:02.521068 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4143686,"delete_count":0,"lbm_write_time_us":4105,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:18:02.521551 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:02.540854 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.019s	user 0.004s	sys 0.013s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":3463,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:18:02.541599 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:02.758114 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.216s	user 0.143s	sys 0.072s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979853,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":941,"lbm_read_time_us":16557,"lbm_reads_lt_1ms":775,"lbm_write_time_us":34230,"lbm_writes_lt_1ms":743,"mutex_wait_us":442,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":22656,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:18:02.758740 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=14.095187
I20260812 06:18:02.826669 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.068s	user 0.038s	sys 0.017s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25330,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.827205 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=3.181125
I20260812 06:18:02.844139 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4553933,"delete_count":0,"lbm_write_time_us":6958,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:18:02.844588 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:02.854133 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":3429,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:18:02.854638 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:03.055702 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.201s	user 0.144s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877213,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1114,"lbm_read_time_us":13865,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32738,"lbm_writes_lt_1ms":643,"mutex_wait_us":352,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":3000}
I20260812 06:18:03.056384 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=15.087375
I20260812 06:18:03.096369 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":17251,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:03.096983 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:03.109517 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4616,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:03.110006 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:03.271898 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.162s	user 0.120s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774677,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1218,"lbm_read_time_us":11462,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26021,"lbm_writes_lt_1ms":543,"mutex_wait_us":550,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:18:03.272568 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=14.095187
I20260812 06:18:03.327059 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.054s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19814,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.327680 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:03.338443 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.338999 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:03.518606 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.179s	user 0.114s	sys 0.061s 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":140,"lbm_read_time_us":12063,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29456,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:03.519229 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=14.095187
I20260812 06:18:03.573928 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.055s	user 0.029s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17966,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.574453 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:03.585119 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3974,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.585635 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:03.768950 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.183s	user 0.093s	sys 0.082s 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":186,"lbm_read_time_us":12723,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29324,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24064,"update_count":2500}
I20260812 06:18:03.769565 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=14.095187
I20260812 06:18:03.821754 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.052s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21314,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.822309 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:03.847021 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.025s	user 0.011s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.847702 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushMRSOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:03.880728 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushMRSOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.033s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1353,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1806,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:03.881528 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling LogGCOp(64ab4f1af142440e861c94d3394fa89d): free 112239560 bytes of WAL
I20260812 06:18:03.881772 24762 log_reader.cc:385] T 64ab4f1af142440e861c94d3394fa89d: removed 11 log segments from log reader
I20260812 06:18:03.881841 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000027 (ops 129-133)
I20260812 06:18:03.881886 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000028 (ops 134-138)
I20260812 06:18:03.881915 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000029 (ops 139-142)
I20260812 06:18:03.881937 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000030 (ops 143-147)
I20260812 06:18:03.881969 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000031 (ops 148-152)
I20260812 06:18:03.881999 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000032 (ops 153-157)
I20260812 06:18:03.882026 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000033 (ops 158-162)
I20260812 06:18:03.882056 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000034 (ops 163-167)
I20260812 06:18:03.882084 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000035 (ops 168-172)
I20260812 06:18:03.882117 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000036 (ops 173-177)
I20260812 06:18:03.882145 24762 log.cc:1079] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: Deleting log segment in path: /tmp/dist-test-taskKJxoay/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515473970776-24241-0/minicluster-data/ts-0-root/wals/64ab4f1af142440e861c94d3394fa89d/wal-000000037 (ops 178-182)
I20260812 06:18:03.909135 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: LogGCOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:03.909581 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=3.181125
I20260812 06:18:03.933485 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.024s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6774,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:03.933987 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling UndoDeltaBlockGCOp(64ab4f1af142440e861c94d3394fa89d): 447 bytes on disk
I20260812 06:18:03.934396 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: UndoDeltaBlockGCOp(64ab4f1af142440e861c94d3394fa89d) 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:03.934952 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:03.944375 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3439,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:03.944833 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:04.179684 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.235s	user 0.152s	sys 0.071s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2936,"lbm_read_time_us":15135,"lbm_reads_lt_1ms":774,"lbm_write_time_us":33595,"lbm_writes_lt_1ms":743,"mutex_wait_us":331,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":114,"threads_started":1,"update_count":3500}
I20260812 06:18:04.180380 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=18.063937
I20260812 06:18:04.276432 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.096s	user 0.053s	sys 0.026s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":35947,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:04.277287 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d): perf score=2.188937
I20260812 06:18:04.298135 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: FlushDeltaMemStoresOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.021s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.298839 24878 maintenance_manager.cc:419] P bf2f6f5af4ab4988b29e9105e826437e: Scheduling MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d): perf score=1.000000
I20260812 06:18:04.355264 24241 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.868s	user 1.762s	sys 0.180s
I20260812 06:18:04.478912 24241 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.123s	user 0.000s	sys 0.001s
I20260812 06:18:04.479744 24241 tablet_server.cc:179] TabletServer@127.23.172.65:0 shutting down...
I20260812 06:18:04.693431 24762 maintenance_manager.cc:643] P bf2f6f5af4ab4988b29e9105e826437e: MajorDeltaCompactionOp(64ab4f1af142440e861c94d3394fa89d) complete. Timing: real 0.394s	user 0.334s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2956,"lbm_read_time_us":24597,"lbm_reads_lt_1ms":668,"lbm_write_time_us":64898,"lbm_writes_1-10_ms":9,"lbm_writes_lt_1ms":634,"mutex_wait_us":80,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":69376,"thread_start_us":563,"threads_started":1,"update_count":3000}
I20260812 06:18:04.698262 24241 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:04.700023 24241 tablet_replica.cc:333] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e: stopping tablet replica
I20260812 06:18:04.700778 24241 raft_consensus.cc:2243] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:04.701448 24241 raft_consensus.cc:2272] T 64ab4f1af142440e861c94d3394fa89d P bf2f6f5af4ab4988b29e9105e826437e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:04.732225 24241 tablet_server.cc:196] TabletServer@127.23.172.65:0 shutdown complete.
I20260812 06:18:04.774973 24241 master.cc:562] Master@127.23.172.126:43407 shutting down...
I20260812 06:18:04.793080 24241 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:04.793848 24241 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:04.793955 24241 tablet_replica.cc:333] T 00000000000000000000000000000000 P e3beb07d3b5c46e8b63b816c2be3b414: stopping tablet replica
I20260812 06:18:04.808076 24241 master.cc:584] Master@127.23.172.126:43407 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5659 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10947 ms total)

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