[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:47.769279 12496 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.52.62:34545
I20260812 06:19:47.770164 12496 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:47.770709 12496 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:47.776521 12509 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:47.776554 12496 server_base.cc:1061] running on GCE node
W20260812 06:19:47.776782 12506 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:47.776854 12512 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:47.777323 12496 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:47.777419 12496 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:47.777463 12496 hybrid_clock.cc:648] HybridClock initialized: now 1786515587777461 us; error 0 us; skew 500 ppm
I20260812 06:19:47.779016 12496 webserver.cc:533] Webserver started at http://127.12.52.62:42819/ using document root <none> and password file <none>
I20260812 06:19:47.779488 12496 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:47.779546 12496 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:47.779754 12496 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:47.781324 12496 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/master-0-root/instance:
uuid: "c36bbfe04f654e5c9afb691aa483dccf"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-266d"
I20260812 06:19:47.784416 12496 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:47.786275 12521 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.787179 12496 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:47.787281 12496 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/master-0-root
uuid: "c36bbfe04f654e5c9afb691aa483dccf"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-266d"
I20260812 06:19:47.787360 12496 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:47.806226 12496 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:47.806772 12496 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:47.806916 12496 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:47.813884 12607 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.52.62:34545 every 8 connection(s)
I20260812 06:19:47.813887 12496 rpc_server.cc:307] RPC server started. Bound to: 127.12.52.62:34545
I20260812 06:19:47.815969 12611 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:47.821120 12611 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf: Bootstrap starting.
I20260812 06:19:47.823336 12611 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:47.824148 12611 log.cc:826] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:47.825701 12611 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf: No bootstrap required, opened a new log
I20260812 06:19:47.828312 12611 raft_consensus.cc:359] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c36bbfe04f654e5c9afb691aa483dccf" member_type: VOTER }
I20260812 06:19:47.828465 12611 raft_consensus.cc:385] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:47.828532 12611 raft_consensus.cc:740] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c36bbfe04f654e5c9afb691aa483dccf, State: Initialized, Role: FOLLOWER
I20260812 06:19:47.829077 12611 consensus_queue.cc:260] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [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: "c36bbfe04f654e5c9afb691aa483dccf" member_type: VOTER }
I20260812 06:19:47.829238 12611 raft_consensus.cc:399] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:47.829309 12611 raft_consensus.cc:493] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:47.829430 12611 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:47.830137 12611 raft_consensus.cc:515] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c36bbfe04f654e5c9afb691aa483dccf" member_type: VOTER }
I20260812 06:19:47.830545 12611 leader_election.cc:304] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [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: c36bbfe04f654e5c9afb691aa483dccf; no voters: 
I20260812 06:19:47.830842 12611 leader_election.cc:290] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:47.830935 12615 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:47.831117 12615 raft_consensus.cc:697] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [term 1 LEADER]: Becoming Leader. State: Replica: c36bbfe04f654e5c9afb691aa483dccf, State: Running, Role: LEADER
I20260812 06:19:47.831519 12615 consensus_queue.cc:237] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [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: "c36bbfe04f654e5c9afb691aa483dccf" member_type: VOTER }
I20260812 06:19:47.831723 12611 sys_catalog.cc:565] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:47.833237 12616 sys_catalog.cc:455] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c36bbfe04f654e5c9afb691aa483dccf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c36bbfe04f654e5c9afb691aa483dccf" member_type: VOTER } }
I20260812 06:19:47.833388 12616 sys_catalog.cc:458] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:47.833253 12617 sys_catalog.cc:455] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [sys.catalog]: SysCatalogTable state changed. Reason: New leader c36bbfe04f654e5c9afb691aa483dccf. Latest consensus state: current_term: 1 leader_uuid: "c36bbfe04f654e5c9afb691aa483dccf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c36bbfe04f654e5c9afb691aa483dccf" member_type: VOTER } }
I20260812 06:19:47.833606 12617 sys_catalog.cc:458] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:47.833711 12640 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:47.833932 12496 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:47.836042 12640 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:47.841917 12640 catalog_manager.cc:1383] Generated new cluster ID: 57c58ccb8f134daf8e57163de58c0e5e
I20260812 06:19:47.842022 12640 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:47.866040 12640 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:47.867491 12640 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:47.882341 12640 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf: Generated new TSK 0
I20260812 06:19:47.883198 12640 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:47.898586 12496 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:47.901566 12658 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:47.901717 12663 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:47.901718 12660 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:47.902087 12496 server_base.cc:1061] running on GCE node
I20260812 06:19:47.902257 12496 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:47.902298 12496 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:47.902313 12496 hybrid_clock.cc:648] HybridClock initialized: now 1786515587902313 us; error 0 us; skew 500 ppm
I20260812 06:19:47.903148 12496 webserver.cc:533] Webserver started at http://127.12.52.1:37503/ using document root <none> and password file <none>
I20260812 06:19:47.903304 12496 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:47.903353 12496 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:47.903429 12496 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:47.903786 12496 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/instance:
uuid: "37f76889e5f044f78bb5fc97ce4f352a"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-266d"
I20260812 06:19:47.905244 12496 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:19:47.906152 12669 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.906394 12496 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:47.906461 12496 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root
uuid: "37f76889e5f044f78bb5fc97ce4f352a"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-266d"
I20260812 06:19:47.906528 12496 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:47.923306 12496 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:47.923687 12496 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:47.924109 12496 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:47.924901 12496 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:47.924952 12496 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.924998 12496 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:47.925027 12496 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.931362 12496 rpc_server.cc:307] RPC server started. Bound to: 127.12.52.1:37255
I20260812 06:19:47.931413 12779 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.52.1:37255 every 8 connection(s)
I20260812 06:19:47.941990 12780 heartbeater.cc:344] Connected to a master server at 127.12.52.62:34545
I20260812 06:19:47.942234 12780 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:47.942701 12780 heartbeater.cc:507] Master 127.12.52.62:34545 requested a full tablet report, sending...
I20260812 06:19:47.944041 12550 ts_manager.cc:194] Registered new tserver with Master: 37f76889e5f044f78bb5fc97ce4f352a (127.12.52.1:37255)
I20260812 06:19:47.944236 12496 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012311283s
I20260812 06:19:47.945214 12550 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46226
I20260812 06:19:47.953720 12550 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46240:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:47.967260 12712 tablet_service.cc:1511] Processing CreateTablet for tablet e3dc574aa3db4fa8a520d8b8e185fd1b (DEFAULT_TABLE table=heavy-update-compaction-test [id=4b48516fb4ab42bb82d86ada18350767]), partition=
I20260812 06:19:47.967665 12712 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e3dc574aa3db4fa8a520d8b8e185fd1b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:47.969975 12798 tablet_bootstrap.cc:492] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Bootstrap starting.
I20260812 06:19:47.971421 12798 tablet_bootstrap.cc:654] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:47.972653 12798 tablet_bootstrap.cc:492] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: No bootstrap required, opened a new log
I20260812 06:19:47.972764 12798 ts_tablet_manager.cc:1403] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:47.973325 12798 raft_consensus.cc:359] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "37f76889e5f044f78bb5fc97ce4f352a" member_type: VOTER last_known_addr { host: "127.12.52.1" port: 37255 } }
I20260812 06:19:47.973449 12798 raft_consensus.cc:385] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:47.973488 12798 raft_consensus.cc:740] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 37f76889e5f044f78bb5fc97ce4f352a, State: Initialized, Role: FOLLOWER
I20260812 06:19:47.973615 12798 consensus_queue.cc:260] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [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: "37f76889e5f044f78bb5fc97ce4f352a" member_type: VOTER last_known_addr { host: "127.12.52.1" port: 37255 } }
I20260812 06:19:47.974082 12798 raft_consensus.cc:399] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:47.974148 12798 raft_consensus.cc:493] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:47.974198 12798 raft_consensus.cc:3060] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:47.975154 12798 raft_consensus.cc:515] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "37f76889e5f044f78bb5fc97ce4f352a" member_type: VOTER last_known_addr { host: "127.12.52.1" port: 37255 } }
I20260812 06:19:47.975319 12798 leader_election.cc:304] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [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: 37f76889e5f044f78bb5fc97ce4f352a; no voters: 
I20260812 06:19:47.975564 12798 leader_election.cc:290] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:47.975682 12800 raft_consensus.cc:2804] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:47.975910 12798 ts_tablet_manager.cc:1434] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:47.975935 12800 raft_consensus.cc:697] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [term 1 LEADER]: Becoming Leader. State: Replica: 37f76889e5f044f78bb5fc97ce4f352a, State: Running, Role: LEADER
I20260812 06:19:47.976086 12780 heartbeater.cc:499] Master 127.12.52.62:34545 was elected leader, sending a full tablet report...
I20260812 06:19:47.976226 12800 consensus_queue.cc:237] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [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: "37f76889e5f044f78bb5fc97ce4f352a" member_type: VOTER last_known_addr { host: "127.12.52.1" port: 37255 } }
I20260812 06:19:47.978744 12550 catalog_manager.cc:5719] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a reported cstate change: term changed from 0 to 1, leader changed from <none> to 37f76889e5f044f78bb5fc97ce4f352a (127.12.52.1). New cstate: current_term: 1 leader_uuid: "37f76889e5f044f78bb5fc97ce4f352a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "37f76889e5f044f78bb5fc97ce4f352a" member_type: VOTER last_known_addr { host: "127.12.52.1" port: 37255 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:48.040066 12496 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.019s	sys 0.007s
I20260812 06:19:48.182494 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushMRSOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=19.054940
I20260812 06:19:48.341642 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushMRSOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.159s	user 0.137s	sys 0.020s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":205,"delete_count":0,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":1656,"drs_written":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36279,"lbm_writes_lt_1ms":767,"mutex_wait_us":1114,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":103,"threads_started":1,"update_count":1500}
I20260812 06:19:48.342796 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling LogGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b): free 20743880 bytes of WAL
I20260812 06:19:48.343144 12682 log_reader.cc:385] T e3dc574aa3db4fa8a520d8b8e185fd1b: removed 2 log segments from log reader
I20260812 06:19:48.343230 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000001 (ops 1-6)
I20260812 06:19:48.343299 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000002 (ops 7-11)
I20260812 06:19:48.348587 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: LogGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:48.348909 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:48.378079 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.029s	user 0.003s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5292,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.378508 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:48.391378 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4793,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:48.391777 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:48.549602 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.158s	user 0.094s	sys 0.060s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405549,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":494,"lbm_read_time_us":10531,"lbm_reads_lt_1ms":563,"lbm_write_time_us":26326,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":287,"threads_started":5,"update_count":2450}
I20260812 06:19:48.550135 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=10.126437
I20260812 06:19:48.580039 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.030s	user 0.018s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12551,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.580554 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling UndoDeltaBlockGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b): 16821646 bytes on disk
I20260812 06:19:48.581180 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: UndoDeltaBlockGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:48.581637 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:48.683575 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.102s	user 0.082s	sys 0.019s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610742,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":960,"lbm_read_time_us":7029,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17840,"lbm_writes_lt_1ms":343,"mutex_wait_us":296,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":1500}
I20260812 06:19:48.684008 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=10.126437
I20260812 06:19:48.723368 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.039s	user 0.029s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13507,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.723889 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:48.733263 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3483,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.733690 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:48.860378 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.127s	user 0.094s	sys 0.032s 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":619,"lbm_read_time_us":9804,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24060,"lbm_writes_lt_1ms":443,"mutex_wait_us":289,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:19:48.861004 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=10.126437
I20260812 06:19:48.906982 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.046s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13741,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.907460 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:48.916986 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3576,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.917366 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:49.052558 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.135s	user 0.081s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":158,"lbm_read_time_us":9474,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21976,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:49.053071 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=10.126437
I20260812 06:19:49.092447 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.039s	user 0.018s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12567,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.092928 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:49.102430 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3566,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.103108 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:49.221580 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.118s	user 0.092s	sys 0.026s 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":395,"lbm_read_time_us":8780,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20812,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2000}
I20260812 06:19:49.222039 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=10.126437
I20260812 06:19:49.260238 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.038s	user 0.012s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13053,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.260726 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:49.270345 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3658,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.270869 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:49.387656 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.117s	user 0.085s	sys 0.031s 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":275,"lbm_read_time_us":7394,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23402,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.388196 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=10.126437
I20260812 06:19:49.429886 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.042s	user 0.024s	sys 0.014s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14134,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.430455 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:49.440101 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.440558 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:49.570132 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.129s	user 0.077s	sys 0.052s 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":158,"lbm_read_time_us":9165,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20823,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:49.570755 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=10.126437
I20260812 06:19:49.605602 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.035s	user 0.027s	sys 0.003s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":13060,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.606168 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:49.615759 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3656,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.616271 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushMRSOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:49.646627 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushMRSOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.030s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":44,"dirs.run_cpu_time_us":176,"dirs.run_wall_time_us":1179,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1922,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:49.647374 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling LogGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b): free 133024309 bytes of WAL
I20260812 06:19:49.647585 12682 log_reader.cc:385] T e3dc574aa3db4fa8a520d8b8e185fd1b: removed 13 log segments from log reader
I20260812 06:19:49.647634 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000003 (ops 12-16)
I20260812 06:19:49.647663 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000004 (ops 17-21)
I20260812 06:19:49.647701 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000005 (ops 22-26)
I20260812 06:19:49.647725 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000006 (ops 27-31)
I20260812 06:19:49.647756 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000007 (ops 32-36)
I20260812 06:19:49.647787 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000008 (ops 37-41)
I20260812 06:19:49.647820 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000009 (ops 42-46)
I20260812 06:19:49.647853 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000010 (ops 47-51)
I20260812 06:19:49.647886 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000011 (ops 52-56)
I20260812 06:19:49.647918 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000012 (ops 57-61)
I20260812 06:19:49.647951 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000013 (ops 62-66)
I20260812 06:19:49.647984 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000014 (ops 67-70)
I20260812 06:19:49.648015 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000015 (ops 71-75)
I20260812 06:19:49.673134 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: LogGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.026s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:19:49.673484 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling UndoDeltaBlockGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b): 482 bytes on disk
I20260812 06:19:49.673914 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: UndoDeltaBlockGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:19:49.674369 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=4.173312
I20260812 06:19:49.697073 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.023s	user 0.011s	sys 0.008s Metrics: {"bytes_written":5866705,"delete_count":0,"lbm_write_time_us":6606,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:19:49.697427 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.196750
I20260812 06:19:49.703683 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2338579,"delete_count":0,"lbm_write_time_us":2061,"lbm_writes_lt_1ms":60,"reinsert_count":0,"update_count":285}
I20260812 06:19:49.703992 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:49.896067 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.192s	user 0.126s	sys 0.061s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918297,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1280,"lbm_read_time_us":12057,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33088,"lbm_writes_lt_1ms":643,"mutex_wait_us":243,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5504,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:19:49.896631 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=14.095187
I20260812 06:19:49.946483 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.049s	user 0.025s	sys 0.022s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16357,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.947002 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:49.961459 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5564,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.961903 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:50.130720 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.169s	user 0.110s	sys 0.059s 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":213,"lbm_read_time_us":11910,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29572,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:50.131242 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=11.118625
I20260812 06:19:50.161623 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.030s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11708,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:50.162200 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:50.189332 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.027s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5721,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:50.189760 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:50.205758 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.016s	user 0.001s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3677,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.206171 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:50.373616 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.167s	user 0.110s	sys 0.052s 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":262,"lbm_read_time_us":11673,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25725,"lbm_writes_lt_1ms":543,"mutex_wait_us":83,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:19:50.374207 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=11.118625
I20260812 06:19:50.408906 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.035s	user 0.024s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12785,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:50.409494 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:50.424692 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.015s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4395,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:50.425213 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:50.436187 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.011s	user 0.007s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3499,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.436657 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:50.633863 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.197s	user 0.123s	sys 0.056s 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":780,"lbm_read_time_us":10570,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31662,"lbm_writes_lt_1ms":543,"mutex_wait_us":277,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:19:50.634379 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=14.095187
I20260812 06:19:50.678874 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.044s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19185,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.679392 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:50.690627 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.691110 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:50.844945 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.153s	user 0.117s	sys 0.030s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":12209,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27553,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:19:50.845578 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=14.095187
I20260812 06:19:50.888540 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.043s	user 0.019s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16037,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.889020 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:50.903891 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5695,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.904516 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:51.053363 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.149s	user 0.120s	sys 0.019s 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":208,"lbm_read_time_us":8997,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28117,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2500}
I20260812 06:19:51.053892 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=14.095187
I20260812 06:19:51.099591 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.046s	user 0.034s	sys 0.003s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":16908,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.100097 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:51.115026 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.116178 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushMRSOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:51.149235 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushMRSOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.033s	user 0.029s	sys 0.003s Metrics: {"bytes_written":1316415,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1260,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1562,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:51.149904 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling LogGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b): free 124710386 bytes of WAL
I20260812 06:19:51.150118 12682 log_reader.cc:385] T e3dc574aa3db4fa8a520d8b8e185fd1b: removed 12 log segments from log reader
I20260812 06:19:51.150166 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000016 (ops 76-80)
I20260812 06:19:51.150192 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000017 (ops 81-85)
I20260812 06:19:51.150219 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000018 (ops 86-90)
I20260812 06:19:51.150250 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000019 (ops 91-95)
I20260812 06:19:51.150280 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000020 (ops 96-100)
I20260812 06:19:51.150313 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000021 (ops 101-105)
I20260812 06:19:51.150344 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000022 (ops 106-110)
I20260812 06:19:51.150377 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000023 (ops 111-115)
I20260812 06:19:51.150409 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000024 (ops 116-120)
I20260812 06:19:51.150442 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000025 (ops 121-125)
I20260812 06:19:51.150475 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000026 (ops 126-130)
I20260812 06:19:51.150506 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000027 (ops 131-135)
I20260812 06:19:51.171734 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: LogGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:19:51.172106 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling UndoDeltaBlockGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b): 493 bytes on disk
I20260812 06:19:51.172659 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: UndoDeltaBlockGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:51.173297 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=4.173312
I20260812 06:19:51.185657 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":5374417,"delete_count":0,"lbm_write_time_us":4745,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:19:51.186010 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.196750
I20260812 06:19:51.194036 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.008s	user 0.002s	sys 0.005s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":2530,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:19:51.194525 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:51.419200 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.224s	user 0.148s	sys 0.061s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020721,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":444,"lbm_read_time_us":13844,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41317,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":742,"mutex_wait_us":288,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5888,"thread_start_us":67,"threads_started":1,"update_count":3500}
I20260812 06:19:51.419764 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=18.063937
I20260812 06:19:51.482139 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.062s	user 0.034s	sys 0.027s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":22863,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:51.482609 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:51.492120 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3589,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.492486 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:51.679430 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.187s	user 0.127s	sys 0.060s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":114,"lbm_read_time_us":13516,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31198,"lbm_writes_lt_1ms":643,"mutex_wait_us":18,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":3000}
I20260812 06:19:51.680351 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=14.095187
I20260812 06:19:51.732666 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.052s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19671,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.733168 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:51.742973 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3714,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.743451 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:51.911859 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.168s	user 0.112s	sys 0.056s 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":188,"lbm_read_time_us":11367,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30254,"lbm_writes_lt_1ms":543,"mutex_wait_us":17,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:19:51.912465 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=14.095187
I20260812 06:19:51.958487 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.046s	user 0.018s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15651,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.958983 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:51.968788 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3736,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.969219 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:52.143383 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.174s	user 0.111s	sys 0.057s 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":1657,"lbm_read_time_us":11091,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29446,"lbm_writes_lt_1ms":543,"mutex_wait_us":316,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:52.144106 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=11.118625
I20260812 06:19:52.182512 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.038s	user 0.016s	sys 0.015s Metrics: {"bytes_written":13251054,"delete_count":0,"lbm_write_time_us":13247,"lbm_writes_lt_1ms":326,"reinsert_count":0,"update_count":1615}
I20260812 06:19:52.183116 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:52.204175 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.021s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3569334,"delete_count":0,"lbm_write_time_us":3210,"lbm_writes_lt_1ms":90,"mutex_wait_us":1,"reinsert_count":0,"update_count":435}
I20260812 06:19:52.204636 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:52.214464 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3726,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:52.214895 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:52.385912 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.171s	user 0.108s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815788,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":964,"lbm_read_time_us":12498,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29587,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:19:52.386483 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=14.095187
I20260812 06:19:52.430699 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.044s	user 0.028s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17974,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.431239 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:52.446358 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.446928 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushMRSOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:52.482604 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushMRSOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.036s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":1160,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1332,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:52.483347 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling LogGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b): free 120553600 bytes of WAL
I20260812 06:19:52.483578 12682 log_reader.cc:385] T e3dc574aa3db4fa8a520d8b8e185fd1b: removed 12 log segments from log reader
I20260812 06:19:52.483640 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000028 (ops 136-140)
I20260812 06:19:52.483687 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000029 (ops 141-144)
I20260812 06:19:52.483717 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000030 (ops 145-149)
I20260812 06:19:52.483739 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000031 (ops 150-154)
I20260812 06:19:52.483768 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000032 (ops 155-159)
I20260812 06:19:52.483793 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000033 (ops 160-164)
I20260812 06:19:52.483824 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000034 (ops 165-169)
I20260812 06:19:52.483853 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000035 (ops 170-174)
I20260812 06:19:52.483878 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000036 (ops 175-179)
I20260812 06:19:52.483902 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000037 (ops 180-184)
I20260812 06:19:52.483933 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000038 (ops 185-188)
I20260812 06:19:52.483965 12682 log.cc:1079] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/e3dc574aa3db4fa8a520d8b8e185fd1b/wal-000000039 (ops 189-193)
I20260812 06:19:52.510015 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: LogGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:52.510391 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling UndoDeltaBlockGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b): 447 bytes on disk
I20260812 06:19:52.510776 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: UndoDeltaBlockGCOp(e3dc574aa3db4fa8a520d8b8e185fd1b) 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:19:52.511282 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=3.181125
I20260812 06:19:52.528908 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.017s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3918,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:52.529292 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=2.188937
I20260812 06:19:52.537824 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: FlushDeltaMemStoresOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3123,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:52.538213 12781 maintenance_manager.cc:419] P 37f76889e5f044f78bb5fc97ce4f352a: Scheduling MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b): perf score=1.000000
I20260812 06:19:52.625566 12496 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.585s	user 1.629s	sys 0.183s
I20260812 06:19:52.713395 12496 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.087s	user 0.003s	sys 0.000s
I20260812 06:19:52.714010 12496 tablet_server.cc:179] TabletServer@127.12.52.1:0 shutting down...
I20260812 06:19:52.730666 12682 maintenance_manager.cc:643] P 37f76889e5f044f78bb5fc97ce4f352a: MajorDeltaCompactionOp(e3dc574aa3db4fa8a520d8b8e185fd1b) complete. Timing: real 0.192s	user 0.107s	sys 0.085s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020731,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":167,"lbm_read_time_us":14570,"lbm_reads_lt_1ms":770,"lbm_write_time_us":30594,"lbm_writes_lt_1ms":743,"mutex_wait_us":19,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":88576,"thread_start_us":62,"threads_started":1,"update_count":3500}
I20260812 06:19:52.731518 12496 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:52.731894 12496 tablet_replica.cc:333] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a: stopping tablet replica
I20260812 06:19:52.732128 12496 raft_consensus.cc:2243] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:52.732364 12496 raft_consensus.cc:2272] T e3dc574aa3db4fa8a520d8b8e185fd1b P 37f76889e5f044f78bb5fc97ce4f352a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:52.758366 12496 tablet_server.cc:196] TabletServer@127.12.52.1:0 shutdown complete.
I20260812 06:19:52.788081 12496 master.cc:562] Master@127.12.52.62:34545 shutting down...
I20260812 06:19:52.791519 12496 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:52.791682 12496 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:52.791754 12496 tablet_replica.cc:333] T 00000000000000000000000000000000 P c36bbfe04f654e5c9afb691aa483dccf: stopping tablet replica
I20260812 06:19:52.803654 12496 master.cc:584] Master@127.12.52.62:34545 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5104 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:52.873647 12496 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.52.62:36885
I20260812 06:19:52.874030 12496 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:52.875834 12835 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:52.875891 12836 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:52.876003 12839 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:52.875901 12496 server_base.cc:1061] running on GCE node
I20260812 06:19:52.876216 12496 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:52.876248 12496 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:52.876261 12496 hybrid_clock.cc:648] HybridClock initialized: now 1786515592876261 us; error 0 us; skew 500 ppm
I20260812 06:19:52.877027 12496 webserver.cc:533] Webserver started at http://127.12.52.62:39385/ using document root <none> and password file <none>
I20260812 06:19:52.877208 12496 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:52.877254 12496 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:52.877306 12496 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:52.877622 12496 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/master-0-root/instance:
uuid: "9a9293f05c6a40ec9d3712fcb976c522"
format_stamp: "Formatted at 2026-08-12 06:19:52 on dist-test-slave-266d"
I20260812 06:19:52.878964 12496 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:52.879777 12854 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:52.879974 12496 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:52.880039 12496 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/master-0-root
uuid: "9a9293f05c6a40ec9d3712fcb976c522"
format_stamp: "Formatted at 2026-08-12 06:19:52 on dist-test-slave-266d"
I20260812 06:19:52.880107 12496 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:52.892656 12496 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:52.892958 12496 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:52.896718 12496 rpc_server.cc:307] RPC server started. Bound to: 127.12.52.62:36885
I20260812 06:19:52.904379 12948 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.52.62:36885 every 8 connection(s)
I20260812 06:19:52.904784 12950 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:52.906410 12950 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522: Bootstrap starting.
I20260812 06:19:52.907150 12950 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:52.908012 12950 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522: No bootstrap required, opened a new log
I20260812 06:19:52.908355 12950 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9a9293f05c6a40ec9d3712fcb976c522" member_type: VOTER }
I20260812 06:19:52.908433 12950 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:52.908459 12950 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9a9293f05c6a40ec9d3712fcb976c522, State: Initialized, Role: FOLLOWER
I20260812 06:19:52.908556 12950 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [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: "9a9293f05c6a40ec9d3712fcb976c522" member_type: VOTER }
I20260812 06:19:52.908612 12950 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:52.908638 12950 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:52.908670 12950 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:52.909299 12950 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9a9293f05c6a40ec9d3712fcb976c522" member_type: VOTER }
I20260812 06:19:52.909408 12950 leader_election.cc:304] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [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: 9a9293f05c6a40ec9d3712fcb976c522; no voters: 
I20260812 06:19:52.909544 12950 leader_election.cc:290] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:52.909657 12955 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:52.909828 12955 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [term 1 LEADER]: Becoming Leader. State: Replica: 9a9293f05c6a40ec9d3712fcb976c522, State: Running, Role: LEADER
I20260812 06:19:52.909960 12955 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [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: "9a9293f05c6a40ec9d3712fcb976c522" member_type: VOTER }
I20260812 06:19:52.909991 12950 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:52.910370 12961 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9a9293f05c6a40ec9d3712fcb976c522. Latest consensus state: current_term: 1 leader_uuid: "9a9293f05c6a40ec9d3712fcb976c522" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9a9293f05c6a40ec9d3712fcb976c522" member_type: VOTER } }
I20260812 06:19:52.910354 12956 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9a9293f05c6a40ec9d3712fcb976c522" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9a9293f05c6a40ec9d3712fcb976c522" member_type: VOTER } }
I20260812 06:19:52.910485 12961 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:52.910545 12956 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:52.911063 12969 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:52.911746 12969 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:52.911911 12496 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:52.913434 12969 catalog_manager.cc:1383] Generated new cluster ID: 9bb88d265c3947bfa65b6104101b7e6f
I20260812 06:19:52.913480 12969 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:52.927744 12969 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:52.928222 12969 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:52.939576 12969 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522: Generated new TSK 0
I20260812 06:19:52.939709 12969 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:52.943950 12496 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:52.945567 12992 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:52.945605 12993 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:52.945572 12995 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:52.945722 12496 server_base.cc:1061] running on GCE node
I20260812 06:19:52.945891 12496 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:52.945928 12496 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:52.945942 12496 hybrid_clock.cc:648] HybridClock initialized: now 1786515592945942 us; error 0 us; skew 500 ppm
I20260812 06:19:52.946700 12496 webserver.cc:533] Webserver started at http://127.12.52.1:36935/ using document root <none> and password file <none>
I20260812 06:19:52.946851 12496 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:52.946897 12496 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:52.946967 12496 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:52.947283 12496 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/instance:
uuid: "6f5114703f9f4deca346311b407b76a3"
format_stamp: "Formatted at 2026-08-12 06:19:52 on dist-test-slave-266d"
I20260812 06:19:52.948585 12496 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:52.949450 13002 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:52.949658 12496 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:52.949719 12496 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root
uuid: "6f5114703f9f4deca346311b407b76a3"
format_stamp: "Formatted at 2026-08-12 06:19:52 on dist-test-slave-266d"
I20260812 06:19:52.949807 12496 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:52.958160 12496 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:52.958425 12496 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:52.958662 12496 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:52.959054 12496 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:52.959089 12496 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:52.959120 12496 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:52.959148 12496 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:52.963081 12496 rpc_server.cc:307] RPC server started. Bound to: 127.12.52.1:44181
I20260812 06:19:52.964562 13114 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.52.1:44181 every 8 connection(s)
I20260812 06:19:52.977077 13115 heartbeater.cc:344] Connected to a master server at 127.12.52.62:36885
I20260812 06:19:52.977208 13115 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:52.977411 13115 heartbeater.cc:507] Master 127.12.52.62:36885 requested a full tablet report, sending...
I20260812 06:19:52.978050 12889 ts_manager.cc:194] Registered new tserver with Master: 6f5114703f9f4deca346311b407b76a3 (127.12.52.1:44181)
I20260812 06:19:52.978744 12889 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55058
I20260812 06:19:52.979019 12496 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015303455s
I20260812 06:19:52.985149 12889 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55066:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:52.993052 13058 tablet_service.cc:1511] Processing CreateTablet for tablet a6f25d7355044112a3a7d6df13ccd819 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1f151c9f7c914691b1dc5aa8ca7fbd7e]), partition=
I20260812 06:19:52.993307 13058 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a6f25d7355044112a3a7d6df13ccd819. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:52.995132 13134 tablet_bootstrap.cc:492] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Bootstrap starting.
I20260812 06:19:52.995982 13134 tablet_bootstrap.cc:654] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:52.997068 13134 tablet_bootstrap.cc:492] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: No bootstrap required, opened a new log
I20260812 06:19:52.997185 13134 ts_tablet_manager.cc:1403] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:52.997555 13134 raft_consensus.cc:359] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f5114703f9f4deca346311b407b76a3" member_type: VOTER last_known_addr { host: "127.12.52.1" port: 44181 } }
I20260812 06:19:52.997638 13134 raft_consensus.cc:385] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:52.997669 13134 raft_consensus.cc:740] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6f5114703f9f4deca346311b407b76a3, State: Initialized, Role: FOLLOWER
I20260812 06:19:52.997803 13134 consensus_queue.cc:260] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [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: "6f5114703f9f4deca346311b407b76a3" member_type: VOTER last_known_addr { host: "127.12.52.1" port: 44181 } }
I20260812 06:19:52.997880 13134 raft_consensus.cc:399] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:52.997908 13134 raft_consensus.cc:493] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:52.997941 13134 raft_consensus.cc:3060] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:52.998796 13134 raft_consensus.cc:515] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f5114703f9f4deca346311b407b76a3" member_type: VOTER last_known_addr { host: "127.12.52.1" port: 44181 } }
I20260812 06:19:52.998914 13134 leader_election.cc:304] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [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: 6f5114703f9f4deca346311b407b76a3; no voters: 
I20260812 06:19:52.999054 13134 leader_election.cc:290] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:52.999145 13136 raft_consensus.cc:2804] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:52.999329 13134 ts_tablet_manager.cc:1434] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:52.999358 13136 raft_consensus.cc:697] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [term 1 LEADER]: Becoming Leader. State: Replica: 6f5114703f9f4deca346311b407b76a3, State: Running, Role: LEADER
I20260812 06:19:52.999387 13115 heartbeater.cc:499] Master 127.12.52.62:36885 was elected leader, sending a full tablet report...
I20260812 06:19:52.999480 13136 consensus_queue.cc:237] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [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: "6f5114703f9f4deca346311b407b76a3" member_type: VOTER last_known_addr { host: "127.12.52.1" port: 44181 } }
I20260812 06:19:53.000638 12889 catalog_manager.cc:5719] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6f5114703f9f4deca346311b407b76a3 (127.12.52.1). New cstate: current_term: 1 leader_uuid: "6f5114703f9f4deca346311b407b76a3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f5114703f9f4deca346311b407b76a3" member_type: VOTER last_known_addr { host: "127.12.52.1" port: 44181 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:53.050900 12496 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.047s	user 0.016s	sys 0.005s
I20260812 06:19:53.214995 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushMRSOp(a6f25d7355044112a3a7d6df13ccd819): perf score=23.023690
I20260812 06:19:53.369328 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushMRSOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.154s	user 0.102s	sys 0.052s Metrics: {"bytes_written":13210027,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":763,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43080,"lbm_writes_lt_1ms":879,"mutex_wait_us":181,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":17536,"update_count":1610}
I20260812 06:19:53.369899 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:53.391644 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.022s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3610359,"delete_count":0,"lbm_write_time_us":4587,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:19:53.392052 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling LogGCOp(a6f25d7355044112a3a7d6df13ccd819): free 20743880 bytes of WAL
I20260812 06:19:53.392241 13013 log_reader.cc:385] T a6f25d7355044112a3a7d6df13ccd819: removed 2 log segments from log reader
I20260812 06:19:53.392285 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000001 (ops 1-6)
I20260812 06:19:53.392313 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000002 (ops 7-11)
I20260812 06:19:53.395800 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: LogGCOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:53.396113 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling UndoDeltaBlockGCOp(a6f25d7355044112a3a7d6df13ccd819): 20513815 bytes on disk
I20260812 06:19:53.396490 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: UndoDeltaBlockGCOp(a6f25d7355044112a3a7d6df13ccd819) 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:19:53.396891 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:53.406591 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3526,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:53.407052 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:53.566957 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.160s	user 0.126s	sys 0.034s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815786,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":485,"lbm_read_time_us":13177,"lbm_reads_lt_1ms":569,"lbm_write_time_us":29307,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":316,"threads_started":5,"update_count":2500}
I20260812 06:19:53.567498 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=14.095187
I20260812 06:19:53.606588 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.039s	user 0.026s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16630,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.607059 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:53.621640 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5403,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.622138 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:53.772991 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.151s	user 0.115s	sys 0.029s 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":196,"lbm_read_time_us":9215,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27145,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2500}
I20260812 06:19:53.773624 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=14.095187
I20260812 06:19:53.816254 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.042s	user 0.023s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18768,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.816694 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:53.965190 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.148s	user 0.110s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":84,"lbm_read_time_us":9352,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25639,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.966238 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=10.126437
I20260812 06:19:54.007426 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.039s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15676,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:54.008004 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:54.033618 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.025s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5323,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.034045 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:54.043955 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.044375 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:54.231565 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.187s	user 0.130s	sys 0.044s 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":513,"lbm_read_time_us":12108,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25281,"lbm_writes_lt_1ms":543,"mutex_wait_us":274,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:19:54.232120 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=14.095187
I20260812 06:19:54.277997 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.046s	user 0.034s	sys 0.007s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":18201,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.278532 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:54.293529 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5556,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.294027 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:54.442993 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.149s	user 0.104s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":815,"lbm_read_time_us":9270,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28525,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2500}
I20260812 06:19:54.443523 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=11.118625
I20260812 06:19:54.476959 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.033s	user 0.027s	sys 0.003s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14092,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:54.477681 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:54.492777 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.015s	user 0.009s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4774,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.493377 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushMRSOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:54.528092 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushMRSOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.035s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1287,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1628,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:54.528676 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=3.181125
I20260812 06:19:54.541359 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":3774,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:54.541838 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling LogGCOp(a6f25d7355044112a3a7d6df13ccd819): free 124257248 bytes of WAL
I20260812 06:19:54.542055 13013 log_reader.cc:385] T a6f25d7355044112a3a7d6df13ccd819: removed 12 log segments from log reader
I20260812 06:19:54.542114 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000003 (ops 12-16)
I20260812 06:19:54.542160 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000004 (ops 17-20)
I20260812 06:19:54.542189 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000005 (ops 21-25)
I20260812 06:19:54.542220 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000006 (ops 26-30)
I20260812 06:19:54.542253 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000007 (ops 31-35)
I20260812 06:19:54.542284 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000008 (ops 36-40)
I20260812 06:19:54.542312 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000009 (ops 41-45)
I20260812 06:19:54.542339 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000010 (ops 46-50)
I20260812 06:19:54.542368 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000011 (ops 51-55)
I20260812 06:19:54.542400 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000012 (ops 56-60)
I20260812 06:19:54.542429 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000013 (ops 61-65)
I20260812 06:19:54.542457 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000014 (ops 66-70)
I20260812 06:19:54.568849 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: LogGCOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.027s	user 0.001s	sys 0.022s Metrics: {}
I20260812 06:19:54.569300 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:54.589635 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.020s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3622,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.590088 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:54.598984 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3318,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.599516 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling UndoDeltaBlockGCOp(a6f25d7355044112a3a7d6df13ccd819): 462 bytes on disk
I20260812 06:19:54.600046 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: UndoDeltaBlockGCOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:19:54.600509 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:54.837340 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.237s	user 0.110s	sys 0.115s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020843,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":198,"lbm_read_time_us":16028,"lbm_reads_lt_1ms":775,"lbm_write_time_us":35534,"lbm_writes_lt_1ms":743,"mutex_wait_us":30,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16640,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:19:54.838039 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=18.063937
I20260812 06:19:54.905856 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.068s	user 0.040s	sys 0.012s Metrics: {"bytes_written":20512312,"delete_count":0,"lbm_write_time_us":23865,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:54.906329 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:54.916185 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.916706 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:55.110909 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.194s	user 0.134s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918094,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":196,"lbm_read_time_us":13875,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31373,"lbm_writes_lt_1ms":643,"mutex_wait_us":1,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":3000}
I20260812 06:19:55.111486 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=14.095187
I20260812 06:19:55.158206 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.046s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20510,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.158640 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:55.170221 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4361,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.170636 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:55.328917 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.158s	user 0.102s	sys 0.056s 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":793,"lbm_read_time_us":11478,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25669,"lbm_writes_lt_1ms":543,"mutex_wait_us":251,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:55.329473 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=14.095187
I20260812 06:19:55.381342 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.052s	user 0.020s	sys 0.030s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18663,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.381847 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:55.391749 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3744,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.392158 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:55.570007 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.178s	user 0.133s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":249,"lbm_read_time_us":12993,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30434,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2500}
I20260812 06:19:55.570539 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=11.118625
I20260812 06:19:55.604729 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.034s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14080,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:55.605316 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:55.623885 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.018s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5954,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:55.624388 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:55.772082 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.147s	user 0.118s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":935,"lbm_read_time_us":10078,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23734,"lbm_writes_lt_1ms":443,"mutex_wait_us":277,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:19:55.772746 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=11.118625
I20260812 06:19:55.804781 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.032s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13216,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:55.805400 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:55.817736 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4608,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:55.818172 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:55.934572 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.116s	user 0.092s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":151,"lbm_read_time_us":6857,"lbm_reads_lt_1ms":468,"lbm_write_time_us":22650,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:55.935555 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=10.126437
I20260812 06:19:55.967308 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.031s	user 0.017s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13068,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.967782 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:55.979557 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4533,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.979948 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushMRSOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:56.012779 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushMRSOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1116,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1540,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:56.013567 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling LogGCOp(a6f25d7355044112a3a7d6df13ccd819): free 121459497 bytes of WAL
I20260812 06:19:56.013806 13013 log_reader.cc:385] T a6f25d7355044112a3a7d6df13ccd819: removed 12 log segments from log reader
I20260812 06:19:56.013855 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000015 (ops 71-75)
I20260812 06:19:56.013892 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000016 (ops 76-80)
I20260812 06:19:56.013924 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000017 (ops 81-85)
I20260812 06:19:56.013957 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000018 (ops 86-90)
I20260812 06:19:56.013989 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000019 (ops 91-95)
I20260812 06:19:56.014021 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000020 (ops 96-100)
I20260812 06:19:56.014050 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000021 (ops 101-105)
I20260812 06:19:56.014082 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000022 (ops 106-110)
I20260812 06:19:56.014114 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000023 (ops 111-115)
I20260812 06:19:56.014145 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000024 (ops 116-120)
I20260812 06:19:56.014179 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000025 (ops 121-125)
I20260812 06:19:56.014210 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000026 (ops 126-130)
I20260812 06:19:56.035765 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: LogGCOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:19:56.036248 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=3.181125
I20260812 06:19:56.052488 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6567,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:56.052929 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling UndoDeltaBlockGCOp(a6f25d7355044112a3a7d6df13ccd819): 472 bytes on disk
I20260812 06:19:56.053333 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: UndoDeltaBlockGCOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4}
I20260812 06:19:56.053867 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:56.063493 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3279,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.063977 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:56.211071 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.147s	user 0.116s	sys 0.030s 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":272,"lbm_read_time_us":9950,"lbm_reads_lt_1ms":674,"lbm_write_time_us":28263,"lbm_writes_lt_1ms":643,"mutex_wait_us":64,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8960,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:19:56.211639 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=14.095187
I20260812 06:19:56.262730 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.051s	user 0.024s	sys 0.025s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22324,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.263162 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:56.273957 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3944,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.274382 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:56.422928 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.148s	user 0.109s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":173,"lbm_read_time_us":8661,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27727,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:19:56.423848 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=12.110812
I20260812 06:19:56.462524 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.039s	user 0.013s	sys 0.024s Metrics: {"bytes_written":13579241,"delete_count":0,"lbm_write_time_us":16184,"lbm_writes_lt_1ms":334,"reinsert_count":0,"update_count":1655}
I20260812 06:19:56.463114 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:56.478212 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.015s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":3405,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:19:56.478638 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:56.487453 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.009s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3406,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.487893 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:56.654340 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.166s	user 0.116s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815775,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":546,"lbm_read_time_us":12228,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27009,"lbm_writes_lt_1ms":543,"mutex_wait_us":291,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:56.654903 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=14.095187
I20260812 06:19:56.713474 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.058s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22974,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.713974 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:56.723718 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.010s	user 0.000s	sys 0.008s 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:19:56.724149 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:56.880405 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.156s	user 0.097s	sys 0.056s 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":556,"lbm_read_time_us":11255,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27166,"lbm_writes_lt_1ms":543,"mutex_wait_us":272,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":52352,"update_count":2500}
I20260812 06:19:56.880961 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=14.095187
I20260812 06:19:56.936753 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.056s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":18028,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.937340 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:56.952060 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5647,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.952514 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:57.130877 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.178s	user 0.114s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":700,"lbm_read_time_us":11777,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28530,"lbm_writes_lt_1ms":543,"mutex_wait_us":231,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:19:57.131456 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=14.095187
I20260812 06:19:57.180464 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.049s	user 0.026s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16817,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.181015 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:57.195005 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5651,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.195406 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:57.367151 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.172s	user 0.118s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":505,"lbm_read_time_us":10590,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26697,"lbm_writes_lt_1ms":543,"mutex_wait_us":282,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:19:57.367653 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=14.095187
I20260812 06:19:57.407970 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.040s	user 0.028s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16563,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.408404 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:57.427300 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3932,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.427907 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushMRSOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:57.467214 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushMRSOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.039s	user 0.031s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":126,"dirs.run_wall_time_us":1088,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2199,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:57.467885 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling LogGCOp(a6f25d7355044112a3a7d6df13ccd819): free 132571541 bytes of WAL
I20260812 06:19:57.468101 13013 log_reader.cc:385] T a6f25d7355044112a3a7d6df13ccd819: removed 13 log segments from log reader
I20260812 06:19:57.468144 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000027 (ops 131-134)
I20260812 06:19:57.468171 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000028 (ops 135-139)
I20260812 06:19:57.468199 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000029 (ops 140-144)
I20260812 06:19:57.468231 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000030 (ops 145-149)
I20260812 06:19:57.468264 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000031 (ops 150-154)
I20260812 06:19:57.468298 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000032 (ops 155-158)
I20260812 06:19:57.468322 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000033 (ops 159-163)
I20260812 06:19:57.468354 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000034 (ops 164-168)
I20260812 06:19:57.468387 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000035 (ops 169-173)
I20260812 06:19:57.468420 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000036 (ops 174-178)
I20260812 06:19:57.468451 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000037 (ops 179-183)
I20260812 06:19:57.468483 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000038 (ops 184-188)
I20260812 06:19:57.468515 13013 log.cc:1079] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: Deleting log segment in path: /tmp/dist-test-taskdZyNJl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515587759163-12496-0/minicluster-data/ts-0-root/wals/a6f25d7355044112a3a7d6df13ccd819/wal-000000039 (ops 189-193)
I20260812 06:19:57.490010 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: LogGCOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:57.490389 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling UndoDeltaBlockGCOp(a6f25d7355044112a3a7d6df13ccd819): 493 bytes on disk
I20260812 06:19:57.490785 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: UndoDeltaBlockGCOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:57.491447 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:57.510483 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.019s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3657,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.510989 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819): perf score=2.188937
I20260812 06:19:57.520570 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: FlushDeltaMemStoresOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3590,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.521170 13116 maintenance_manager.cc:419] P 6f5114703f9f4deca346311b407b76a3: Scheduling MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819): perf score=1.000000
I20260812 06:19:57.593479 12496 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.542s	user 1.682s	sys 0.133s
I20260812 06:19:57.696450 12496 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.103s	user 0.001s	sys 0.000s
I20260812 06:19:57.696928 12496 tablet_server.cc:179] TabletServer@127.12.52.1:0 shutting down...
I20260812 06:19:57.722303 13013 maintenance_manager.cc:643] P 6f5114703f9f4deca346311b407b76a3: MajorDeltaCompactionOp(a6f25d7355044112a3a7d6df13ccd819) complete. Timing: real 0.201s	user 0.126s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020747,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":617,"lbm_read_time_us":11773,"lbm_reads_lt_1ms":770,"lbm_write_time_us":35264,"lbm_writes_lt_1ms":743,"mutex_wait_us":235,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15744,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:19:57.723306 12496 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:57.723773 12496 tablet_replica.cc:333] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3: stopping tablet replica
I20260812 06:19:57.723892 12496 raft_consensus.cc:2243] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:57.733187 12496 raft_consensus.cc:2272] T a6f25d7355044112a3a7d6df13ccd819 P 6f5114703f9f4deca346311b407b76a3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:57.747514 12496 tablet_server.cc:196] TabletServer@127.12.52.1:0 shutdown complete.
I20260812 06:19:57.778402 12496 master.cc:562] Master@127.12.52.62:36885 shutting down...
I20260812 06:19:57.781493 12496 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:57.781666 12496 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:57.781733 12496 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9a9293f05c6a40ec9d3712fcb976c522: stopping tablet replica
I20260812 06:19:57.793800 12496 master.cc:584] Master@127.12.52.62:36885 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4991 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10096 ms total)

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