[==========] 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:20:08.736263 18353 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.236.126:44031
I20260812 06:20:08.737304 18353 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:20:08.737929 18353 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:20:08.744462 18353 server_base.cc:1061] running on GCE node
W20260812 06:20:08.744560 18358 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:20:08.744573 18361 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:20:08.744900 18359 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:20:08.745402 18353 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:08.745503 18353 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:20:08.745550 18353 hybrid_clock.cc:648] HybridClock initialized: now 1786515608745548 us; error 0 us; skew 500 ppm
I20260812 06:20:08.747334 18353 webserver.cc:533] Webserver started at http://127.17.236.126:37019/ using document root <none> and password file <none>
I20260812 06:20:08.747877 18353 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:08.747941 18353 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:08.748180 18353 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:08.749893 18353 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/master-0-root/instance:
uuid: "ca92dd0defdd4e0ea73ef68084893c3d"
format_stamp: "Formatted at 2026-08-12 06:20:08 on dist-test-slave-vq2q"
I20260812 06:20:08.753785 18353 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:20:08.755959 18368 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:20:08.756981 18353 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:08.757089 18353 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/master-0-root
uuid: "ca92dd0defdd4e0ea73ef68084893c3d"
format_stamp: "Formatted at 2026-08-12 06:20:08 on dist-test-slave-vq2q"
I20260812 06:20:08.757203 18353 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-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:20:08.776716 18353 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:08.777402 18353 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:20:08.777556 18353 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:08.784979 18429 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.236.126:44031 every 8 connection(s)
I20260812 06:20:08.784993 18353 rpc_server.cc:307] RPC server started. Bound to: 127.17.236.126:44031
I20260812 06:20:08.787405 18430 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:20:08.792810 18430 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d: Bootstrap starting.
I20260812 06:20:08.795205 18430 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:08.796121 18430 log.cc:826] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:08.797914 18430 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d: No bootstrap required, opened a new log
I20260812 06:20:08.800684 18430 raft_consensus.cc:359] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca92dd0defdd4e0ea73ef68084893c3d" member_type: VOTER }
I20260812 06:20:08.800846 18430 raft_consensus.cc:385] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:08.800908 18430 raft_consensus.cc:740] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ca92dd0defdd4e0ea73ef68084893c3d, State: Initialized, Role: FOLLOWER
I20260812 06:20:08.801543 18430 consensus_queue.cc:260] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [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: "ca92dd0defdd4e0ea73ef68084893c3d" member_type: VOTER }
I20260812 06:20:08.801684 18430 raft_consensus.cc:399] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:08.801751 18430 raft_consensus.cc:493] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:08.801875 18430 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:08.802662 18430 raft_consensus.cc:515] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca92dd0defdd4e0ea73ef68084893c3d" member_type: VOTER }
I20260812 06:20:08.803078 18430 leader_election.cc:304] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [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: ca92dd0defdd4e0ea73ef68084893c3d; no voters: 
I20260812 06:20:08.803391 18430 leader_election.cc:290] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:08.803519 18433 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:08.803733 18433 raft_consensus.cc:697] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [term 1 LEADER]: Becoming Leader. State: Replica: ca92dd0defdd4e0ea73ef68084893c3d, State: Running, Role: LEADER
I20260812 06:20:08.804071 18433 consensus_queue.cc:237] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [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: "ca92dd0defdd4e0ea73ef68084893c3d" member_type: VOTER }
I20260812 06:20:08.804334 18430 sys_catalog.cc:565] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:08.805877 18434 sys_catalog.cc:455] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ca92dd0defdd4e0ea73ef68084893c3d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca92dd0defdd4e0ea73ef68084893c3d" member_type: VOTER } }
I20260812 06:20:08.806005 18434 sys_catalog.cc:458] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:08.806236 18435 sys_catalog.cc:455] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [sys.catalog]: SysCatalogTable state changed. Reason: New leader ca92dd0defdd4e0ea73ef68084893c3d. Latest consensus state: current_term: 1 leader_uuid: "ca92dd0defdd4e0ea73ef68084893c3d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca92dd0defdd4e0ea73ef68084893c3d" member_type: VOTER } }
I20260812 06:20:08.806317 18435 sys_catalog.cc:458] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:08.806380 18442 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:08.808586 18442 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:08.808897 18353 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:08.813030 18442 catalog_manager.cc:1383] Generated new cluster ID: 206a4f53a0bf49d69e6a982ca14ab02a
I20260812 06:20:08.813088 18442 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:08.841660 18442 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:08.842836 18442 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:08.852167 18442 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d: Generated new TSK 0
I20260812 06:20:08.852932 18442 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:08.873726 18353 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:08.876468 18455 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:20:08.876564 18353 server_base.cc:1061] running on GCE node
W20260812 06:20:08.876688 18457 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:20:08.876689 18454 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:08.876983 18353 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:08.877027 18353 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:20:08.877043 18353 hybrid_clock.cc:648] HybridClock initialized: now 1786515608877042 us; error 0 us; skew 500 ppm
I20260812 06:20:08.877918 18353 webserver.cc:533] Webserver started at http://127.17.236.65:41477/ using document root <none> and password file <none>
I20260812 06:20:08.878090 18353 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:08.878136 18353 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:08.878211 18353 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:08.878578 18353 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/instance:
uuid: "160c9d72774241c8bc8f048e2ed332b3"
format_stamp: "Formatted at 2026-08-12 06:20:08 on dist-test-slave-vq2q"
I20260812 06:20:08.880026 18353 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:08.880992 18462 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:20:08.881299 18353 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:08.881371 18353 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root
uuid: "160c9d72774241c8bc8f048e2ed332b3"
format_stamp: "Formatted at 2026-08-12 06:20:08 on dist-test-slave-vq2q"
I20260812 06:20:08.881438 18353 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-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:20:08.894341 18353 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:08.894984 18353 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:08.895493 18353 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:08.896364 18353 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:08.896417 18353 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:08.896473 18353 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:08.896497 18353 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:08.902549 18353 rpc_server.cc:307] RPC server started. Bound to: 127.17.236.65:36311
I20260812 06:20:08.902700 18535 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.236.65:36311 every 8 connection(s)
I20260812 06:20:08.912942 18536 heartbeater.cc:344] Connected to a master server at 127.17.236.126:44031
I20260812 06:20:08.913255 18536 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:08.913800 18536 heartbeater.cc:507] Master 127.17.236.126:44031 requested a full tablet report, sending...
I20260812 06:20:08.915418 18387 ts_manager.cc:194] Registered new tserver with Master: 160c9d72774241c8bc8f048e2ed332b3 (127.17.236.65:36311)
I20260812 06:20:08.915676 18353 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012508213s
I20260812 06:20:08.916684 18387 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59566
I20260812 06:20:08.925460 18387 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59576:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:08.939400 18497 tablet_service.cc:1511] Processing CreateTablet for tablet c245778e90f14a3ba53708d2611ad555 (DEFAULT_TABLE table=heavy-update-compaction-test [id=4ec1f494b9d440abb972d0f23c4586bd]), partition=
I20260812 06:20:08.939890 18497 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c245778e90f14a3ba53708d2611ad555. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:08.942610 18550 tablet_bootstrap.cc:492] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Bootstrap starting.
I20260812 06:20:08.943811 18550 tablet_bootstrap.cc:654] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:08.945676 18550 tablet_bootstrap.cc:492] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: No bootstrap required, opened a new log
I20260812 06:20:08.945816 18550 ts_tablet_manager.cc:1403] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:08.946412 18550 raft_consensus.cc:359] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "160c9d72774241c8bc8f048e2ed332b3" member_type: VOTER last_known_addr { host: "127.17.236.65" port: 36311 } }
I20260812 06:20:08.946557 18550 raft_consensus.cc:385] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:08.946592 18550 raft_consensus.cc:740] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 160c9d72774241c8bc8f048e2ed332b3, State: Initialized, Role: FOLLOWER
I20260812 06:20:08.946733 18550 consensus_queue.cc:260] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [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: "160c9d72774241c8bc8f048e2ed332b3" member_type: VOTER last_known_addr { host: "127.17.236.65" port: 36311 } }
I20260812 06:20:08.946842 18550 raft_consensus.cc:399] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:08.946935 18550 raft_consensus.cc:493] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:08.947000 18550 raft_consensus.cc:3060] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:08.948078 18550 raft_consensus.cc:515] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "160c9d72774241c8bc8f048e2ed332b3" member_type: VOTER last_known_addr { host: "127.17.236.65" port: 36311 } }
I20260812 06:20:08.948235 18550 leader_election.cc:304] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [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: 160c9d72774241c8bc8f048e2ed332b3; no voters: 
I20260812 06:20:08.948474 18550 leader_election.cc:290] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:08.948632 18552 raft_consensus.cc:2804] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:08.948850 18552 raft_consensus.cc:697] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [term 1 LEADER]: Becoming Leader. State: Replica: 160c9d72774241c8bc8f048e2ed332b3, State: Running, Role: LEADER
I20260812 06:20:08.948899 18550 ts_tablet_manager.cc:1434] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:08.949235 18552 consensus_queue.cc:237] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [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: "160c9d72774241c8bc8f048e2ed332b3" member_type: VOTER last_known_addr { host: "127.17.236.65" port: 36311 } }
I20260812 06:20:08.949316 18536 heartbeater.cc:499] Master 127.17.236.126:44031 was elected leader, sending a full tablet report...
I20260812 06:20:08.952510 18387 catalog_manager.cc:5719] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 reported cstate change: term changed from 0 to 1, leader changed from <none> to 160c9d72774241c8bc8f048e2ed332b3 (127.17.236.65). New cstate: current_term: 1 leader_uuid: "160c9d72774241c8bc8f048e2ed332b3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "160c9d72774241c8bc8f048e2ed332b3" member_type: VOTER last_known_addr { host: "127.17.236.65" port: 36311 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:09.012152 18353 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.023s	sys 0.000s
I20260812 06:20:09.153812 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushMRSOp(c245778e90f14a3ba53708d2611ad555): perf score=19.054940
I20260812 06:20:09.292923 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushMRSOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.139s	user 0.110s	sys 0.024s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":225,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":841,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34969,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":130,"threads_started":1,"update_count":1450}
I20260812 06:20:09.294415 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:09.408586 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.114s	user 0.084s	sys 0.029s Metrics: {"cfile_cache_miss":321,"cfile_cache_miss_bytes":16200500,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":393,"lbm_read_time_us":6711,"lbm_reads_lt_1ms":353,"lbm_write_time_us":20024,"lbm_writes_lt_1ms":333,"mutex_wait_us":28,"peak_mem_usage":36812022,"reinsert_count":0,"thread_start_us":353,"threads_started":5,"update_count":1450}
I20260812 06:20:09.409273 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling LogGCOp(c245778e90f14a3ba53708d2611ad555): free 20743880 bytes of WAL
I20260812 06:20:09.409592 18468 log_reader.cc:385] T c245778e90f14a3ba53708d2611ad555: removed 2 log segments from log reader
I20260812 06:20:09.409668 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000001 (ops 1-6)
I20260812 06:20:09.409731 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000002 (ops 7-11)
I20260812 06:20:09.415443 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: LogGCOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:09.415828 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling UndoDeltaBlockGCOp(c245778e90f14a3ba53708d2611ad555): 16821650 bytes on disk
I20260812 06:20:09.416297 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: UndoDeltaBlockGCOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:20:09.416718 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=11.118625
I20260812 06:20:09.445719 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.029s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12273,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:09.446267 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:09.461128 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4946,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:09.461652 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:09.588045 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.126s	user 0.105s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":261,"lbm_read_time_us":6828,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24470,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:09.588711 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=10.126437
I20260812 06:20:09.624395 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.036s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15077,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:09.624905 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:09.636970 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4100,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.637478 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:09.784973 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.147s	user 0.091s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":664,"lbm_read_time_us":11319,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24427,"lbm_writes_lt_1ms":443,"mutex_wait_us":332,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:20:09.785616 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=10.126437
I20260812 06:20:09.825657 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.040s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18373,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:09.826218 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:09.841862 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.842443 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:09.981572 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.139s	user 0.101s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":765,"lbm_read_time_us":9411,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21403,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:20:09.983615 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=11.118625
I20260812 06:20:10.025457 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.042s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":20015,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:20:10.026067 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:10.047638 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.021s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3447,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:10.048139 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:10.057957 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3461,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.058571 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:10.202294 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.143s	user 0.124s	sys 0.019s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":896,"lbm_read_time_us":11170,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26530,"lbm_writes_lt_1ms":543,"mutex_wait_us":260,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:20:10.203298 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=10.126437
I20260812 06:20:10.235033 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.032s	user 0.023s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":11960,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.235553 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:10.248085 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4348,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.248623 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:10.369807 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.121s	user 0.085s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":123,"lbm_read_time_us":8924,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22057,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:20:10.370301 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=10.126437
I20260812 06:20:10.421228 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.051s	user 0.014s	sys 0.031s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14277,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.421841 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:10.432271 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3848,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.432855 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:10.570962 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.138s	user 0.094s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":128,"lbm_read_time_us":9913,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22285,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:20:10.571591 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=10.126437
I20260812 06:20:10.616225 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.044s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14982,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.616757 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:10.626832 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3729,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.627558 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushMRSOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:10.655333 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushMRSOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.027s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1383,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1301,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:10.656282 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling LogGCOp(c245778e90f14a3ba53708d2611ad555): free 129320497 bytes of WAL
I20260812 06:20:10.656522 18468 log_reader.cc:385] T c245778e90f14a3ba53708d2611ad555: removed 13 log segments from log reader
I20260812 06:20:10.656579 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000003 (ops 12-16)
I20260812 06:20:10.656625 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000004 (ops 17-21)
I20260812 06:20:10.656661 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000005 (ops 22-26)
I20260812 06:20:10.656689 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000006 (ops 27-31)
I20260812 06:20:10.656718 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000007 (ops 32-36)
I20260812 06:20:10.656744 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000008 (ops 37-41)
I20260812 06:20:10.656775 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000009 (ops 42-46)
I20260812 06:20:10.656807 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000010 (ops 47-50)
I20260812 06:20:10.656836 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000011 (ops 51-55)
I20260812 06:20:10.656863 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000012 (ops 56-60)
I20260812 06:20:10.656890 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000013 (ops 61-64)
I20260812 06:20:10.656929 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000014 (ops 65-69)
I20260812 06:20:10.656962 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000015 (ops 70-74)
I20260812 06:20:10.680696 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: LogGCOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:20:10.681089 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling UndoDeltaBlockGCOp(c245778e90f14a3ba53708d2611ad555): 482 bytes on disk
I20260812 06:20:10.681560 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: UndoDeltaBlockGCOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:20:10.682096 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:10.704064 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.022s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3788,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.704567 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:10.719087 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.014s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5791,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.719561 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:10.900301 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.181s	user 0.125s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918334,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":768,"lbm_read_time_us":12932,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30876,"lbm_writes_lt_1ms":643,"mutex_wait_us":82,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:20:10.901078 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=11.118625
I20260812 06:20:10.937292 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.036s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":14587,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:10.937880 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:10.969506 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.031s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4684,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:10.970034 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:10.980105 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3821,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.980509 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:11.144790 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.164s	user 0.114s	sys 0.045s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":817,"lbm_read_time_us":11438,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26869,"lbm_writes_lt_1ms":543,"mutex_wait_us":82,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:11.145666 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=11.118625
I20260812 06:20:11.174508 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.029s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":11265,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:11.175137 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:11.199472 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.024s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4375,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:11.200019 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:11.216006 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4006,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.216631 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:11.386953 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.170s	user 0.130s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":290,"lbm_read_time_us":12290,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27535,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:11.387539 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=11.118625
I20260812 06:20:11.421933 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.034s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14197,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:11.422623 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:11.448171 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.025s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5006,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:11.448661 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:11.462692 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.463222 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:11.610905 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.148s	user 0.121s	sys 0.024s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":108,"lbm_read_time_us":10086,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26847,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:11.611627 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=10.126437
I20260812 06:20:11.648134 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.036s	user 0.010s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15745,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:11.648711 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:11.662420 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4921,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.662963 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:11.789057 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.126s	user 0.097s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":814,"lbm_read_time_us":9485,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21240,"lbm_writes_lt_1ms":443,"mutex_wait_us":254,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:20:11.789613 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=10.126437
I20260812 06:20:11.828581 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.039s	user 0.013s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15922,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:11.829167 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:11.842864 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5168,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.843504 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:11.966897 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.123s	user 0.098s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":590,"lbm_read_time_us":8071,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25024,"lbm_writes_lt_1ms":443,"mutex_wait_us":290,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":672000,"update_count":2000}
I20260812 06:20:11.967489 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=10.126437
I20260812 06:20:12.016594 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.049s	user 0.032s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13654,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.017277 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:12.032682 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.015s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5880,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.033281 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushMRSOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:12.073167 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushMRSOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.040s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":36,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1298,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1390,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:12.074043 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling LogGCOp(c245778e90f14a3ba53708d2611ad555): free 123804207 bytes of WAL
I20260812 06:20:12.074285 18468 log_reader.cc:385] T c245778e90f14a3ba53708d2611ad555: removed 12 log segments from log reader
I20260812 06:20:12.074342 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000016 (ops 75-78)
I20260812 06:20:12.074389 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000017 (ops 79-83)
I20260812 06:20:12.074424 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000018 (ops 84-88)
I20260812 06:20:12.074450 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000019 (ops 89-93)
I20260812 06:20:12.074479 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000020 (ops 94-98)
I20260812 06:20:12.074507 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000021 (ops 99-103)
I20260812 06:20:12.074538 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000022 (ops 104-108)
I20260812 06:20:12.074569 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000023 (ops 109-113)
I20260812 06:20:12.074597 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000024 (ops 114-118)
I20260812 06:20:12.074625 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000025 (ops 119-123)
I20260812 06:20:12.074654 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000026 (ops 124-128)
I20260812 06:20:12.074685 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000027 (ops 129-132)
I20260812 06:20:12.100232 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: LogGCOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:20:12.100718 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling UndoDeltaBlockGCOp(c245778e90f14a3ba53708d2611ad555): 463 bytes on disk
I20260812 06:20:12.101227 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: UndoDeltaBlockGCOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:20:12.101753 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=3.181125
I20260812 06:20:12.124547 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.023s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6494,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:12.125064 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:12.134285 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3200,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:12.134733 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:12.321496 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.187s	user 0.119s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":5747,"lbm_read_time_us":13668,"lbm_reads_lt_1ms":674,"lbm_write_time_us":27930,"lbm_writes_lt_1ms":643,"mutex_wait_us":2615,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":24192,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:20:12.322149 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=14.095187
I20260812 06:20:12.380514 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.058s	user 0.026s	sys 0.014s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22637,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:20:12.380988 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:12.391346 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3603,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.391930 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:12.560866 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.169s	user 0.105s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":968,"lbm_read_time_us":12150,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26807,"lbm_writes_lt_1ms":543,"mutex_wait_us":225,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:20:12.561406 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=14.095187
I20260812 06:20:12.610113 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.049s	user 0.026s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16704,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:12.610698 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:12.626736 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.016s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.627393 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:12.786336 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.159s	user 0.098s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":120,"lbm_read_time_us":11037,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27059,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:20:12.786906 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=11.118625
I20260812 06:20:12.820286 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.033s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13587,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:12.827503 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:12.856895 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.029s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5277,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:12.857471 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:12.867749 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3649,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.868311 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:13.034209 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.166s	user 0.106s	sys 0.050s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":129,"lbm_read_time_us":11619,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24292,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:20:13.034865 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=14.095187
I20260812 06:20:13.086495 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.051s	user 0.022s	sys 0.025s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":17261,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:13.087081 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:13.097255 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3779,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.097692 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:13.258517 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.161s	user 0.109s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":703,"lbm_read_time_us":11179,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26228,"lbm_writes_lt_1ms":543,"mutex_wait_us":308,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:20:13.259155 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=11.118625
I20260812 06:20:13.292217 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.033s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13523,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:13.293334 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:13.306381 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4284,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:13.306852 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:13.426569 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.120s	user 0.082s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":363,"lbm_read_time_us":6831,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23127,"lbm_writes_lt_1ms":443,"mutex_wait_us":74,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:13.427194 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=10.126437
I20260812 06:20:13.461086 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.034s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12982,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:13.461624 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:13.472987 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.473632 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushMRSOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:13.506933 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushMRSOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.033s	user 0.028s	sys 0.005s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1351,"drs_written":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1523,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:13.507802 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling LogGCOp(c245778e90f14a3ba53708d2611ad555): free 121459753 bytes of WAL
I20260812 06:20:13.508044 18468 log_reader.cc:385] T c245778e90f14a3ba53708d2611ad555: removed 12 log segments from log reader
I20260812 06:20:13.508090 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000028 (ops 133-137)
I20260812 06:20:13.508129 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000029 (ops 138-142)
I20260812 06:20:13.508162 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000030 (ops 143-147)
I20260812 06:20:13.508194 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000031 (ops 148-152)
I20260812 06:20:13.508224 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000032 (ops 153-157)
I20260812 06:20:13.508255 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000033 (ops 158-162)
I20260812 06:20:13.508286 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000034 (ops 163-167)
I20260812 06:20:13.508323 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000035 (ops 168-172)
I20260812 06:20:13.508354 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000036 (ops 173-177)
I20260812 06:20:13.508383 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000037 (ops 178-182)
I20260812 06:20:13.508414 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000038 (ops 183-187)
I20260812 06:20:13.508442 18468 log.cc:1079] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/c245778e90f14a3ba53708d2611ad555/wal-000000039 (ops 188-192)
I20260812 06:20:13.531260 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: LogGCOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:20:13.531754 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=3.181125
I20260812 06:20:13.543468 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4718026,"delete_count":0,"lbm_write_time_us":4460,"lbm_writes_lt_1ms":118,"reinsert_count":0,"update_count":575}
I20260812 06:20:13.543963 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=2.188937
I20260812 06:20:13.553345 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3487280,"delete_count":0,"lbm_write_time_us":3195,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:20:13.554225 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling UndoDeltaBlockGCOp(c245778e90f14a3ba53708d2611ad555): 472 bytes on disk
I20260812 06:20:13.554823 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: UndoDeltaBlockGCOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4}
I20260812 06:20:13.555575 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:13.670740 18353 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.658s	user 1.692s	sys 0.181s
I20260812 06:20:13.708935 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.153s	user 0.140s	sys 0.011s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":11207,"lbm_reads_lt_1ms":670,"lbm_write_time_us":31528,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":3000}
I20260812 06:20:13.709604 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555): perf score=10.126437
I20260812 06:20:13.737150 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: FlushDeltaMemStoresOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.027s	user 0.019s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":10854,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:13.737821 18537 maintenance_manager.cc:419] P 160c9d72774241c8bc8f048e2ed332b3: Scheduling MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555): perf score=1.000000
I20260812 06:20:13.738231 18353 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.004s	sys 0.000s
I20260812 06:20:13.738953 18353 tablet_server.cc:179] TabletServer@127.17.236.65:0 shutting down...
I20260812 06:20:13.836582 18468 maintenance_manager.cc:643] P 160c9d72774241c8bc8f048e2ed332b3: MajorDeltaCompactionOp(c245778e90f14a3ba53708d2611ad555) complete. Timing: real 0.099s	user 0.070s	sys 0.025s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":384,"lbm_read_time_us":6191,"lbm_reads_lt_1ms":367,"lbm_write_time_us":19823,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":2,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:20:13.837539 18353 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:13.838011 18353 tablet_replica.cc:333] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3: stopping tablet replica
I20260812 06:20:13.838294 18353 raft_consensus.cc:2243] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:13.838583 18353 raft_consensus.cc:2272] T c245778e90f14a3ba53708d2611ad555 P 160c9d72774241c8bc8f048e2ed332b3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:13.854543 18353 tablet_server.cc:196] TabletServer@127.17.236.65:0 shutdown complete.
I20260812 06:20:13.868876 18353 master.cc:562] Master@127.17.236.126:44031 shutting down...
I20260812 06:20:13.872337 18353 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:13.872505 18353 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:13.872565 18353 tablet_replica.cc:333] T 00000000000000000000000000000000 P ca92dd0defdd4e0ea73ef68084893c3d: stopping tablet replica
I20260812 06:20:13.884711 18353 master.cc:584] Master@127.17.236.126:44031 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5220 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:13.964327 18353 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.236.126:36839
I20260812 06:20:13.964708 18353 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:13.966740 18576 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:20:13.966813 18353 server_base.cc:1061] running on GCE node
W20260812 06:20:13.966777 18575 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:20:13.967043 18578 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:20:13.967236 18353 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:13.967289 18353 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:20:13.967311 18353 hybrid_clock.cc:648] HybridClock initialized: now 1786515613967310 us; error 0 us; skew 500 ppm
I20260812 06:20:13.968077 18353 webserver.cc:533] Webserver started at http://127.17.236.126:33945/ using document root <none> and password file <none>
I20260812 06:20:13.968235 18353 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:13.968278 18353 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:13.968355 18353 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:13.968725 18353 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/master-0-root/instance:
uuid: "d4746a6942724a1f885504a9b806a2fd"
format_stamp: "Formatted at 2026-08-12 06:20:13 on dist-test-slave-vq2q"
I20260812 06:20:13.970259 18353 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:13.971148 18583 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:20:13.971352 18353 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:13.971421 18353 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/master-0-root
uuid: "d4746a6942724a1f885504a9b806a2fd"
format_stamp: "Formatted at 2026-08-12 06:20:13 on dist-test-slave-vq2q"
I20260812 06:20:13.971489 18353 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-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:20:13.987146 18353 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:13.987545 18353 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:13.991925 18353 rpc_server.cc:307] RPC server started. Bound to: 127.17.236.126:36839
I20260812 06:20:13.998494 18643 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.236.126:36839 every 8 connection(s)
I20260812 06:20:13.999035 18644 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:20:14.000880 18644 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd: Bootstrap starting.
I20260812 06:20:14.001704 18644 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:14.002730 18644 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd: No bootstrap required, opened a new log
I20260812 06:20:14.003135 18644 raft_consensus.cc:359] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d4746a6942724a1f885504a9b806a2fd" member_type: VOTER }
I20260812 06:20:14.003222 18644 raft_consensus.cc:385] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:14.003243 18644 raft_consensus.cc:740] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d4746a6942724a1f885504a9b806a2fd, State: Initialized, Role: FOLLOWER
I20260812 06:20:14.003365 18644 consensus_queue.cc:260] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [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: "d4746a6942724a1f885504a9b806a2fd" member_type: VOTER }
I20260812 06:20:14.003451 18644 raft_consensus.cc:399] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:14.003480 18644 raft_consensus.cc:493] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:14.003516 18644 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:14.004192 18644 raft_consensus.cc:515] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d4746a6942724a1f885504a9b806a2fd" member_type: VOTER }
I20260812 06:20:14.004311 18644 leader_election.cc:304] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [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: d4746a6942724a1f885504a9b806a2fd; no voters: 
I20260812 06:20:14.004467 18644 leader_election.cc:290] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:14.004591 18648 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:14.004796 18648 raft_consensus.cc:697] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [term 1 LEADER]: Becoming Leader. State: Replica: d4746a6942724a1f885504a9b806a2fd, State: Running, Role: LEADER
I20260812 06:20:14.004912 18644 sys_catalog.cc:565] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:14.004937 18648 consensus_queue.cc:237] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [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: "d4746a6942724a1f885504a9b806a2fd" member_type: VOTER }
I20260812 06:20:14.005472 18649 sys_catalog.cc:455] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d4746a6942724a1f885504a9b806a2fd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d4746a6942724a1f885504a9b806a2fd" member_type: VOTER } }
I20260812 06:20:14.005499 18651 sys_catalog.cc:455] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [sys.catalog]: SysCatalogTable state changed. Reason: New leader d4746a6942724a1f885504a9b806a2fd. Latest consensus state: current_term: 1 leader_uuid: "d4746a6942724a1f885504a9b806a2fd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d4746a6942724a1f885504a9b806a2fd" member_type: VOTER } }
I20260812 06:20:14.005636 18649 sys_catalog.cc:458] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:14.005712 18651 sys_catalog.cc:458] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:14.006265 18657 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:14.006927 18657 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:14.007156 18353 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:14.008697 18657 catalog_manager.cc:1383] Generated new cluster ID: f61dc0aa85d746478f942f51f1313253
I20260812 06:20:14.008754 18657 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:14.014557 18657 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:14.015118 18657 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:14.019588 18657 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd: Generated new TSK 0
I20260812 06:20:14.019748 18657 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:14.023187 18353 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:14.025200 18670 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:20:14.025287 18353 server_base.cc:1061] running on GCE node
W20260812 06:20:14.025324 18667 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:20:14.025378 18668 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:20:14.025600 18353 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:14.025643 18353 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:20:14.025663 18353 hybrid_clock.cc:648] HybridClock initialized: now 1786515614025663 us; error 0 us; skew 500 ppm
I20260812 06:20:14.026518 18353 webserver.cc:533] Webserver started at http://127.17.236.65:37559/ using document root <none> and password file <none>
I20260812 06:20:14.026679 18353 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:14.026727 18353 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:14.026805 18353 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:14.027207 18353 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/instance:
uuid: "22ba7f6fb65649e4a673cd5cccbcb056"
format_stamp: "Formatted at 2026-08-12 06:20:14 on dist-test-slave-vq2q"
I20260812 06:20:14.028712 18353 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:14.029744 18675 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:20:14.030004 18353 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:20:14.030077 18353 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root
uuid: "22ba7f6fb65649e4a673cd5cccbcb056"
format_stamp: "Formatted at 2026-08-12 06:20:14 on dist-test-slave-vq2q"
I20260812 06:20:14.030146 18353 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-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:20:14.040261 18353 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:14.040619 18353 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:14.040910 18353 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:14.041435 18353 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:14.041474 18353 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:14.041520 18353 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:14.041548 18353 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:14.045749 18353 rpc_server.cc:307] RPC server started. Bound to: 127.17.236.65:33979
I20260812 06:20:14.046926 18747 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.236.65:33979 every 8 connection(s)
I20260812 06:20:14.051190 18748 heartbeater.cc:344] Connected to a master server at 127.17.236.126:36839
I20260812 06:20:14.051282 18748 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:14.051484 18748 heartbeater.cc:507] Master 127.17.236.126:36839 requested a full tablet report, sending...
I20260812 06:20:14.052094 18601 ts_manager.cc:194] Registered new tserver with Master: 22ba7f6fb65649e4a673cd5cccbcb056 (127.17.236.65:33979)
I20260812 06:20:14.052758 18601 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33348
I20260812 06:20:14.053047 18353 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.006664205s
I20260812 06:20:14.060176 18601 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33356:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:14.071306 18706 tablet_service.cc:1511] Processing CreateTablet for tablet 1ee961c3da044b77af8af73128749730 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7b0e8638cc47405881119294e9e5c791]), partition=
I20260812 06:20:14.071625 18706 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1ee961c3da044b77af8af73128749730. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:14.073942 18762 tablet_bootstrap.cc:492] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Bootstrap starting.
I20260812 06:20:14.074880 18762 tablet_bootstrap.cc:654] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:14.075924 18762 tablet_bootstrap.cc:492] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: No bootstrap required, opened a new log
I20260812 06:20:14.076012 18762 ts_tablet_manager.cc:1403] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:14.076465 18762 raft_consensus.cc:359] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "22ba7f6fb65649e4a673cd5cccbcb056" member_type: VOTER last_known_addr { host: "127.17.236.65" port: 33979 } }
I20260812 06:20:14.076560 18762 raft_consensus.cc:385] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:14.076589 18762 raft_consensus.cc:740] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 22ba7f6fb65649e4a673cd5cccbcb056, State: Initialized, Role: FOLLOWER
I20260812 06:20:14.076737 18762 consensus_queue.cc:260] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [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: "22ba7f6fb65649e4a673cd5cccbcb056" member_type: VOTER last_known_addr { host: "127.17.236.65" port: 33979 } }
I20260812 06:20:14.076825 18762 raft_consensus.cc:399] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:14.076866 18762 raft_consensus.cc:493] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:14.076915 18762 raft_consensus.cc:3060] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:14.077677 18762 raft_consensus.cc:515] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "22ba7f6fb65649e4a673cd5cccbcb056" member_type: VOTER last_known_addr { host: "127.17.236.65" port: 33979 } }
I20260812 06:20:14.077813 18762 leader_election.cc:304] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [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: 22ba7f6fb65649e4a673cd5cccbcb056; no voters: 
I20260812 06:20:14.077979 18762 leader_election.cc:290] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:14.078100 18764 raft_consensus.cc:2804] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:14.078282 18762 ts_tablet_manager.cc:1434] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:14.078305 18764 raft_consensus.cc:697] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [term 1 LEADER]: Becoming Leader. State: Replica: 22ba7f6fb65649e4a673cd5cccbcb056, State: Running, Role: LEADER
I20260812 06:20:14.078333 18748 heartbeater.cc:499] Master 127.17.236.126:36839 was elected leader, sending a full tablet report...
I20260812 06:20:14.078487 18764 consensus_queue.cc:237] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [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: "22ba7f6fb65649e4a673cd5cccbcb056" member_type: VOTER last_known_addr { host: "127.17.236.65" port: 33979 } }
I20260812 06:20:14.079823 18601 catalog_manager.cc:5719] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 reported cstate change: term changed from 0 to 1, leader changed from <none> to 22ba7f6fb65649e4a673cd5cccbcb056 (127.17.236.65). New cstate: current_term: 1 leader_uuid: "22ba7f6fb65649e4a673cd5cccbcb056" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "22ba7f6fb65649e4a673cd5cccbcb056" member_type: VOTER last_known_addr { host: "127.17.236.65" port: 33979 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:14.137152 18353 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.022s	sys 0.000s
I20260812 06:20:14.297421 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushMRSOp(1ee961c3da044b77af8af73128749730): perf score=23.023690
I20260812 06:20:14.451910 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushMRSOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.154s	user 0.123s	sys 0.029s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":173,"dirs.run_wall_time_us":814,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41392,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":3328,"update_count":1500}
I20260812 06:20:14.452564 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling LogGCOp(1ee961c3da044b77af8af73128749730): free 20743880 bytes of WAL
I20260812 06:20:14.452780 18680 log_reader.cc:385] T 1ee961c3da044b77af8af73128749730: removed 2 log segments from log reader
I20260812 06:20:14.452827 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000001 (ops 1-6)
I20260812 06:20:14.452860 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000002 (ops 7-11)
I20260812 06:20:14.456498 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: LogGCOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:14.456880 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:14.474639 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5050,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.475122 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling UndoDeltaBlockGCOp(1ee961c3da044b77af8af73128749730): 20513813 bytes on disk
I20260812 06:20:14.475533 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: UndoDeltaBlockGCOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:20:14.476078 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:14.642238 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.166s	user 0.104s	sys 0.050s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1300,"lbm_read_time_us":10554,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23784,"lbm_writes_lt_1ms":443,"mutex_wait_us":327,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":156928,"thread_start_us":362,"threads_started":5,"update_count":2000}
I20260812 06:20:14.642915 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=14.095187
I20260812 06:20:14.683408 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.040s	user 0.022s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18385,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:14.684006 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:14.838584 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.154s	user 0.110s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1150,"lbm_read_time_us":11387,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23016,"lbm_writes_lt_1ms":443,"mutex_wait_us":1063,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:20:14.839226 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=11.118625
I20260812 06:20:14.873490 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.034s	user 0.018s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14438,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:14.874305 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:14.888978 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5381,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:14.889508 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:15.001950 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.112s	user 0.078s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":509,"lbm_read_time_us":7293,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20716,"lbm_writes_lt_1ms":443,"mutex_wait_us":98,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25216,"update_count":2000}
I20260812 06:20:15.002542 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=10.126437
I20260812 06:20:15.036978 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.034s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13453,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:15.037462 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:15.047824 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3760,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.048381 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:15.168135 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.120s	user 0.099s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":279,"lbm_read_time_us":8120,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20909,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:20:15.168610 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=10.126437
I20260812 06:20:15.208474 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.040s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14633,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:15.209057 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:15.219456 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3789,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.220091 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:15.341327 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.121s	user 0.109s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":355,"lbm_read_time_us":8441,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23600,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:20:15.341940 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=10.126437
I20260812 06:20:15.386705 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.045s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13243,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:15.387254 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:15.397974 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3851,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.398525 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:15.534770 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.136s	user 0.104s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":654,"lbm_read_time_us":9970,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20724,"lbm_writes_lt_1ms":443,"mutex_wait_us":295,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":2000}
I20260812 06:20:15.535327 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=10.126437
I20260812 06:20:15.583923 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.048s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15756,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:15.584398 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:15.594355 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3768,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.594972 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushMRSOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:15.623097 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushMRSOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.028s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":259,"dirs.run_wall_time_us":1404,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1204,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:15.623790 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling LogGCOp(1ee961c3da044b77af8af73128749730): free 112692361 bytes of WAL
I20260812 06:20:15.624017 18680 log_reader.cc:385] T 1ee961c3da044b77af8af73128749730: removed 11 log segments from log reader
I20260812 06:20:15.624065 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000003 (ops 12-16)
I20260812 06:20:15.624104 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000004 (ops 17-21)
I20260812 06:20:15.624140 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000005 (ops 22-26)
I20260812 06:20:15.624164 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000006 (ops 27-31)
I20260812 06:20:15.624195 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000007 (ops 32-36)
I20260812 06:20:15.624226 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000008 (ops 37-41)
I20260812 06:20:15.624262 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000009 (ops 42-46)
I20260812 06:20:15.624297 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000010 (ops 47-51)
I20260812 06:20:15.624328 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000011 (ops 52-56)
I20260812 06:20:15.624361 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000012 (ops 57-61)
I20260812 06:20:15.624392 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000013 (ops 62-66)
I20260812 06:20:15.643481 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: LogGCOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.020s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:20:15.643899 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=3.181125
I20260812 06:20:15.668577 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.025s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4297,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:15.669025 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:15.678239 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3435,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:15.678702 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling UndoDeltaBlockGCOp(1ee961c3da044b77af8af73128749730): 447 bytes on disk
I20260812 06:20:15.679072 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: UndoDeltaBlockGCOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:20:15.679514 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:15.878254 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.199s	user 0.143s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":662,"lbm_read_time_us":14279,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33220,"lbm_writes_lt_1ms":643,"mutex_wait_us":57,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5376,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:20:15.879992 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=14.095187
I20260812 06:20:15.928998 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.049s	user 0.014s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17004,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:15.929531 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:15.939895 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3834,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.940323 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:16.129309 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.189s	user 0.124s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1108,"lbm_read_time_us":13834,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27649,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:20:16.129809 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=14.095187
I20260812 06:20:16.181222 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.051s	user 0.029s	sys 0.015s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":19056,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:16.181811 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:16.205711 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.024s	user 0.011s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.206358 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:16.383922 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.177s	user 0.115s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":159,"lbm_read_time_us":11703,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26599,"lbm_writes_lt_1ms":543,"mutex_wait_us":79,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:16.384452 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=14.095187
I20260812 06:20:16.434667 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.050s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18306,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:16.435254 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:16.445530 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3751,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.446246 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:16.620193 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.174s	user 0.133s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":11576,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26640,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:20:16.620728 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=14.095187
I20260812 06:20:16.667599 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.047s	user 0.028s	sys 0.011s Metrics: {"bytes_written":16409941,"delete_count":0,"lbm_write_time_us":17583,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:16.668200 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:16.683653 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.015s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5789,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.684231 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:16.830062 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.146s	user 0.106s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":414,"lbm_read_time_us":9381,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28823,"lbm_writes_lt_1ms":543,"mutex_wait_us":259,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:20:16.830631 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=11.118625
I20260812 06:20:16.866209 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.035s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15081,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:16.866688 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:16.877218 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.010s	user 0.009s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:16.877806 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:16.992133 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.114s	user 0.067s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":551,"lbm_read_time_us":6773,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23561,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":269,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:20:16.992925 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=10.126437
I20260812 06:20:17.031030 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.037s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14278,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.031508 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:17.046499 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.015s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5494,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.047044 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushMRSOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:17.075446 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushMRSOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.028s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1162,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1486,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:17.076099 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling LogGCOp(1ee961c3da044b77af8af73128749730): free 124257190 bytes of WAL
I20260812 06:20:17.076325 18680 log_reader.cc:385] T 1ee961c3da044b77af8af73128749730: removed 12 log segments from log reader
I20260812 06:20:17.076375 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000014 (ops 67-71)
I20260812 06:20:17.076404 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000015 (ops 72-76)
I20260812 06:20:17.076435 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000016 (ops 77-81)
I20260812 06:20:17.076472 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000017 (ops 82-86)
I20260812 06:20:17.076496 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000018 (ops 87-91)
I20260812 06:20:17.076527 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000019 (ops 92-96)
I20260812 06:20:17.076560 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000020 (ops 97-101)
I20260812 06:20:17.076591 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000021 (ops 102-106)
I20260812 06:20:17.076622 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000022 (ops 107-110)
I20260812 06:20:17.076651 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000023 (ops 111-115)
I20260812 06:20:17.076681 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000024 (ops 116-120)
I20260812 06:20:17.076712 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000025 (ops 121-125)
I20260812 06:20:17.098479 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: LogGCOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:20:17.098940 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=3.181125
I20260812 06:20:17.112349 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.013s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4228,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:17.112815 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling LogGCOp(1ee961c3da044b77af8af73128749730): free 12017991 bytes of WAL
I20260812 06:20:17.113022 18680 log_reader.cc:385] T 1ee961c3da044b77af8af73128749730: removed 1 log segments from log reader
I20260812 06:20:17.113078 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000026 (ops 126-130)
I20260812 06:20:17.115603 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: LogGCOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:17.115901 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling UndoDeltaBlockGCOp(1ee961c3da044b77af8af73128749730): 472 bytes on disk
I20260812 06:20:17.116297 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: UndoDeltaBlockGCOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:20:17.116801 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:17.127457 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3445,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:17.128110 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:17.297487 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.169s	user 0.140s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3304,"lbm_read_time_us":12346,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32508,"lbm_writes_lt_1ms":643,"mutex_wait_us":1294,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":104,"threads_started":1,"update_count":3000}
I20260812 06:20:17.298056 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=14.095187
I20260812 06:20:17.342334 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.044s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":18743,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:17.342842 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:17.352909 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3844,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.353368 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:17.525646 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.172s	user 0.123s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":870,"dirs.run_cpu_time_us":1085,"dirs.run_wall_time_us":6990,"lbm_read_time_us":11436,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27069,"lbm_writes_lt_1ms":543,"mutex_wait_us":220,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:20:17.526408 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=14.095187
I20260812 06:20:17.579362 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.053s	user 0.024s	sys 0.021s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":20139,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.579941 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:17.733546 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.153s	user 0.103s	sys 0.041s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713150,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1220,"lbm_read_time_us":8787,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23206,"lbm_writes_lt_1ms":443,"mutex_wait_us":396,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:17.734097 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=14.095187
I20260812 06:20:17.785934 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.052s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23854,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.786579 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:17.797365 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3779,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.797923 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:17.968971 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.171s	user 0.106s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":824,"lbm_read_time_us":11561,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24933,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:20:17.969462 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=14.095187
I20260812 06:20:18.011299 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.042s	user 0.024s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16318,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.011958 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:18.028426 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6382,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.028873 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:18.184376 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.155s	user 0.107s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":759,"lbm_read_time_us":9486,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25665,"lbm_writes_lt_1ms":543,"mutex_wait_us":274,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:20:18.184980 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=14.095187
I20260812 06:20:18.241686 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.057s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21919,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.242209 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:18.252560 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3660,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.253212 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:18.397838 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.144s	user 0.096s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":525,"lbm_read_time_us":10473,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27312,"lbm_writes_lt_1ms":543,"mutex_wait_us":269,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2500}
I20260812 06:20:18.398437 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=11.118625
I20260812 06:20:18.427275 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.029s	user 0.023s	sys 0.004s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":11914,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:18.427793 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:18.441776 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4261,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.442303 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushMRSOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:18.479828 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushMRSOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.037s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":269,"dirs.run_wall_time_us":1509,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1581,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:18.480639 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=3.181125
I20260812 06:20:18.493292 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3901,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:18.493711 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling LogGCOp(1ee961c3da044b77af8af73128749730): free 121006640 bytes of WAL
I20260812 06:20:18.493937 18680 log_reader.cc:385] T 1ee961c3da044b77af8af73128749730: removed 12 log segments from log reader
I20260812 06:20:18.493994 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000027 (ops 131-135)
I20260812 06:20:18.494037 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000028 (ops 136-140)
I20260812 06:20:18.494068 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000029 (ops 141-145)
I20260812 06:20:18.494102 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000030 (ops 146-150)
I20260812 06:20:18.494132 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000031 (ops 151-155)
I20260812 06:20:18.494160 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000032 (ops 156-160)
I20260812 06:20:18.494187 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000033 (ops 161-164)
I20260812 06:20:18.494215 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000034 (ops 165-169)
I20260812 06:20:18.494257 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000035 (ops 170-174)
I20260812 06:20:18.494287 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000036 (ops 175-179)
I20260812 06:20:18.494314 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000037 (ops 180-184)
I20260812 06:20:18.494342 18680 log.cc:1079] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: Deleting log segment in path: /tmp/dist-test-taskJfsx57/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515608725414-18353-0/minicluster-data/ts-0-root/wals/1ee961c3da044b77af8af73128749730/wal-000000038 (ops 185-189)
I20260812 06:20:18.519029 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: LogGCOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.025s	user 0.006s	sys 0.018s Metrics: {}
I20260812 06:20:18.519542 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:18.536573 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.017s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.537034 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=2.188937
I20260812 06:20:18.555258 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.018s	user 0.008s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3363,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.555809 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling UndoDeltaBlockGCOp(1ee961c3da044b77af8af73128749730): 483 bytes on disk
I20260812 06:20:18.556298 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: UndoDeltaBlockGCOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:20:18.556877 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:18.750751 18353 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.613s	user 1.669s	sys 0.160s
I20260812 06:20:18.761778 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.205s	user 0.136s	sys 0.068s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020845,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":14287,"lbm_reads_lt_1ms":771,"lbm_write_time_us":33901,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:20:18.762346 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730): perf score=14.095187
I20260812 06:20:18.792693 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: FlushDeltaMemStoresOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.030s	user 0.025s	sys 0.004s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":13963,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:18.793248 18749 maintenance_manager.cc:419] P 22ba7f6fb65649e4a673cd5cccbcb056: Scheduling MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730): perf score=1.000000
I20260812 06:20:18.833922 18353 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.083s	user 0.003s	sys 0.000s
I20260812 06:20:18.834532 18353 tablet_server.cc:179] TabletServer@127.17.236.65:0 shutting down...
I20260812 06:20:18.927676 18680 maintenance_manager.cc:643] P 22ba7f6fb65649e4a673cd5cccbcb056: MajorDeltaCompactionOp(1ee961c3da044b77af8af73128749730) complete. Timing: real 0.134s	user 0.089s	sys 0.042s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713155,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":718,"lbm_read_time_us":6670,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21278,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":252,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.928292 18353 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:18.928557 18353 tablet_replica.cc:333] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056: stopping tablet replica
I20260812 06:20:18.928691 18353 raft_consensus.cc:2243] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:18.928849 18353 raft_consensus.cc:2272] T 1ee961c3da044b77af8af73128749730 P 22ba7f6fb65649e4a673cd5cccbcb056 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:18.933233 18353 tablet_server.cc:196] TabletServer@127.17.236.65:0 shutdown complete.
I20260812 06:20:18.966776 18353 master.cc:562] Master@127.17.236.126:36839 shutting down...
I20260812 06:20:18.970148 18353 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:18.970340 18353 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:18.970413 18353 tablet_replica.cc:333] T 00000000000000000000000000000000 P d4746a6942724a1f885504a9b806a2fd: stopping tablet replica
I20260812 06:20:18.982577 18353 master.cc:584] Master@127.17.236.126:36839 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5097 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10318 ms total)

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