[==========] 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:44.088162 27436 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.203.62:43109
I20260812 06:19:44.089140 27436 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:44.089756 27436 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:44.096318 27436 server_base.cc:1061] running on GCE node
W20260812 06:19:44.096371 27448 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:44.096539 27454 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:44.096553 27450 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:44.097061 27436 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:44.097173 27436 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:44.097221 27436 hybrid_clock.cc:648] HybridClock initialized: now 1786515584097219 us; error 0 us; skew 500 ppm
I20260812 06:19:44.098855 27436 webserver.cc:533] Webserver started at http://127.26.203.62:42481/ using document root <none> and password file <none>
I20260812 06:19:44.099428 27436 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:44.099499 27436 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:44.099758 27436 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:44.101346 27436 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/master-0-root/instance:
uuid: "4f583d80472a4f25bdaf82b1b746a3ce"
format_stamp: "Formatted at 2026-08-12 06:19:44 on dist-test-slave-x4qh"
I20260812 06:19:44.104641 27436 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:44.106540 27472 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:44.107565 27436 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:44.107689 27436 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/master-0-root
uuid: "4f583d80472a4f25bdaf82b1b746a3ce"
format_stamp: "Formatted at 2026-08-12 06:19:44 on dist-test-slave-x4qh"
I20260812 06:19:44.107791 27436 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-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:44.129205 27436 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:44.129822 27436 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:44.130005 27436 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:44.137554 27436 rpc_server.cc:307] RPC server started. Bound to: 127.26.203.62:43109
I20260812 06:19:44.137571 27563 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.203.62:43109 every 8 connection(s)
I20260812 06:19:44.139858 27564 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:44.145242 27564 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce: Bootstrap starting.
I20260812 06:19:44.147619 27564 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:44.148542 27564 log.cc:826] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:44.150190 27564 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce: No bootstrap required, opened a new log
I20260812 06:19:44.153012 27564 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f583d80472a4f25bdaf82b1b746a3ce" member_type: VOTER }
I20260812 06:19:44.153175 27564 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:44.153256 27564 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4f583d80472a4f25bdaf82b1b746a3ce, State: Initialized, Role: FOLLOWER
I20260812 06:19:44.153870 27564 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [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: "4f583d80472a4f25bdaf82b1b746a3ce" member_type: VOTER }
I20260812 06:19:44.154039 27564 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:44.154115 27564 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:44.154233 27564 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:44.155011 27564 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f583d80472a4f25bdaf82b1b746a3ce" member_type: VOTER }
I20260812 06:19:44.155469 27564 leader_election.cc:304] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [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: 4f583d80472a4f25bdaf82b1b746a3ce; no voters: 
I20260812 06:19:44.155818 27564 leader_election.cc:290] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:44.155966 27568 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:44.156242 27568 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [term 1 LEADER]: Becoming Leader. State: Replica: 4f583d80472a4f25bdaf82b1b746a3ce, State: Running, Role: LEADER
I20260812 06:19:44.156652 27568 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [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: "4f583d80472a4f25bdaf82b1b746a3ce" member_type: VOTER }
I20260812 06:19:44.156880 27564 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:44.158411 27571 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4f583d80472a4f25bdaf82b1b746a3ce. Latest consensus state: current_term: 1 leader_uuid: "4f583d80472a4f25bdaf82b1b746a3ce" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f583d80472a4f25bdaf82b1b746a3ce" member_type: VOTER } }
I20260812 06:19:44.158540 27571 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:44.158840 27569 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4f583d80472a4f25bdaf82b1b746a3ce" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f583d80472a4f25bdaf82b1b746a3ce" member_type: VOTER } }
I20260812 06:19:44.158918 27569 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:44.159164 27436 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:44.160998 27599 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:44.161094 27599 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:44.161182 27590 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:44.161877 27590 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:44.166316 27590 catalog_manager.cc:1383] Generated new cluster ID: 13637a6390274ff7925034742516f16f
I20260812 06:19:44.166386 27590 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:44.192557 27590 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:44.193746 27590 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:44.204916 27590 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce: Generated new TSK 0
I20260812 06:19:44.205607 27590 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:44.223965 27436 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:44.226763 27612 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:44.226815 27616 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:44.226989 27436 server_base.cc:1061] running on GCE node
W20260812 06:19:44.226783 27613 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:44.227408 27436 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:44.227465 27436 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:44.227491 27436 hybrid_clock.cc:648] HybridClock initialized: now 1786515584227490 us; error 0 us; skew 500 ppm
I20260812 06:19:44.228413 27436 webserver.cc:533] Webserver started at http://127.26.203.1:44763/ using document root <none> and password file <none>
I20260812 06:19:44.228605 27436 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:44.228716 27436 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:44.228799 27436 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:44.229197 27436 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/instance:
uuid: "475a5f8dad8943a0baac6e3a829ed427"
format_stamp: "Formatted at 2026-08-12 06:19:44 on dist-test-slave-x4qh"
I20260812 06:19:44.230758 27436 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:44.231770 27626 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:44.232069 27436 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:44.232136 27436 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root
uuid: "475a5f8dad8943a0baac6e3a829ed427"
format_stamp: "Formatted at 2026-08-12 06:19:44 on dist-test-slave-x4qh"
I20260812 06:19:44.232224 27436 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-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:44.238494 27436 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:44.238932 27436 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:44.239470 27436 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:44.240337 27436 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:44.240391 27436 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:44.240468 27436 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:44.240509 27436 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:44.247262 27436 rpc_server.cc:307] RPC server started. Bound to: 127.26.203.1:46665
I20260812 06:19:44.247295 27741 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.203.1:46665 every 8 connection(s)
I20260812 06:19:44.257543 27742 heartbeater.cc:344] Connected to a master server at 127.26.203.62:43109
I20260812 06:19:44.257790 27742 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:44.258282 27742 heartbeater.cc:507] Master 127.26.203.62:43109 requested a full tablet report, sending...
I20260812 06:19:44.259821 27500 ts_manager.cc:194] Registered new tserver with Master: 475a5f8dad8943a0baac6e3a829ed427 (127.26.203.1:46665)
I20260812 06:19:44.260390 27436 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012425333s
I20260812 06:19:44.261049 27500 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57320
I20260812 06:19:44.269753 27500 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57330:
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:44.283519 27684 tablet_service.cc:1511] Processing CreateTablet for tablet 679c9a55e1724a3bb81087514aaab744 (DEFAULT_TABLE table=heavy-update-compaction-test [id=cb9206543d524b1fad1aa11fca9674fd]), partition=
I20260812 06:19:44.283993 27684 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 679c9a55e1724a3bb81087514aaab744. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:44.286195 27768 tablet_bootstrap.cc:492] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Bootstrap starting.
I20260812 06:19:44.287331 27768 tablet_bootstrap.cc:654] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:44.288555 27768 tablet_bootstrap.cc:492] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: No bootstrap required, opened a new log
I20260812 06:19:44.288687 27768 ts_tablet_manager.cc:1403] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:44.289124 27768 raft_consensus.cc:359] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "475a5f8dad8943a0baac6e3a829ed427" member_type: VOTER last_known_addr { host: "127.26.203.1" port: 46665 } }
I20260812 06:19:44.289247 27768 raft_consensus.cc:385] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:44.289294 27768 raft_consensus.cc:740] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 475a5f8dad8943a0baac6e3a829ed427, State: Initialized, Role: FOLLOWER
I20260812 06:19:44.289450 27768 consensus_queue.cc:260] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [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: "475a5f8dad8943a0baac6e3a829ed427" member_type: VOTER last_known_addr { host: "127.26.203.1" port: 46665 } }
I20260812 06:19:44.289563 27768 raft_consensus.cc:399] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:44.289614 27768 raft_consensus.cc:493] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:44.289669 27768 raft_consensus.cc:3060] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:44.290393 27768 raft_consensus.cc:515] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "475a5f8dad8943a0baac6e3a829ed427" member_type: VOTER last_known_addr { host: "127.26.203.1" port: 46665 } }
I20260812 06:19:44.290553 27768 leader_election.cc:304] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [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: 475a5f8dad8943a0baac6e3a829ed427; no voters: 
I20260812 06:19:44.290796 27768 leader_election.cc:290] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:44.291090 27776 raft_consensus.cc:2804] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:44.291200 27768 ts_tablet_manager.cc:1434] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:44.291342 27776 raft_consensus.cc:697] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [term 1 LEADER]: Becoming Leader. State: Replica: 475a5f8dad8943a0baac6e3a829ed427, State: Running, Role: LEADER
I20260812 06:19:44.291546 27776 consensus_queue.cc:237] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [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: "475a5f8dad8943a0baac6e3a829ed427" member_type: VOTER last_known_addr { host: "127.26.203.1" port: 46665 } }
I20260812 06:19:44.291666 27742 heartbeater.cc:499] Master 127.26.203.62:43109 was elected leader, sending a full tablet report...
I20260812 06:19:44.294391 27500 catalog_manager.cc:5719] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 reported cstate change: term changed from 0 to 1, leader changed from <none> to 475a5f8dad8943a0baac6e3a829ed427 (127.26.203.1). New cstate: current_term: 1 leader_uuid: "475a5f8dad8943a0baac6e3a829ed427" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "475a5f8dad8943a0baac6e3a829ed427" member_type: VOTER last_known_addr { host: "127.26.203.1" port: 46665 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:44.364562 27436 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.016s	sys 0.011s
I20260812 06:19:44.498425 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushMRSOp(679c9a55e1724a3bb81087514aaab744): perf score=19.054940
I20260812 06:19:44.679674 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushMRSOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.181s	user 0.148s	sys 0.031s Metrics: {"bytes_written":12881820,"cfile_init":1,"compiler_manager_pool.queue_time_us":255,"delete_count":0,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":978,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45571,"lbm_writes_lt_1ms":771,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":163712,"thread_start_us":176,"threads_started":1,"update_count":1570}
I20260812 06:19:44.680910 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling LogGCOp(679c9a55e1724a3bb81087514aaab744): free 20743880 bytes of WAL
I20260812 06:19:44.681226 27636 log_reader.cc:385] T 679c9a55e1724a3bb81087514aaab744: removed 2 log segments from log reader
I20260812 06:19:44.681298 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000001 (ops 1-6)
I20260812 06:19:44.681351 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000002 (ops 7-11)
I20260812 06:19:44.686828 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: LogGCOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:44.687309 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling UndoDeltaBlockGCOp(679c9a55e1724a3bb81087514aaab744): 16411391 bytes on disk
I20260812 06:19:44.687912 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: UndoDeltaBlockGCOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:19:44.688323 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=5.165500
I20260812 06:19:44.715792 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.027s	user 0.011s	sys 0.016s Metrics: {"bytes_written":6564119,"delete_count":0,"lbm_write_time_us":9049,"lbm_writes_lt_1ms":163,"reinsert_count":0,"update_count":800}
I20260812 06:19:44.716423 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:44.888720 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.172s	user 0.111s	sys 0.060s Metrics: {"cfile_cache_miss":506,"cfile_cache_miss_bytes":23708061,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":492,"lbm_read_time_us":13408,"lbm_reads_lt_1ms":538,"lbm_write_time_us":28363,"lbm_writes_lt_1ms":517,"peak_mem_usage":59968222,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":351,"threads_started":5,"update_count":2370}
I20260812 06:19:44.889446 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=12.110812
I20260812 06:19:44.921880 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.032s	user 0.014s	sys 0.016s Metrics: {"bytes_written":13784366,"delete_count":0,"lbm_write_time_us":13833,"lbm_writes_lt_1ms":339,"reinsert_count":0,"update_count":1680}
I20260812 06:19:44.922475 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:44.936036 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4822,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.936465 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:45.080996 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.144s	user 0.101s	sys 0.032s Metrics: {"cfile_cache_miss":458,"cfile_cache_miss_bytes":21738899,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":149,"lbm_read_time_us":7578,"lbm_reads_lt_1ms":490,"lbm_write_time_us":26856,"lbm_writes_lt_1ms":469,"mutex_wait_us":40,"peak_mem_usage":53837006,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2130}
I20260812 06:19:45.081610 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=14.095187
I20260812 06:19:45.133673 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.052s	user 0.037s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20781,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.134125 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:45.145151 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3995,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.145622 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:45.305028 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.159s	user 0.128s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":216,"lbm_read_time_us":10547,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32885,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:45.305616 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=11.118625
I20260812 06:19:45.352186 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.046s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18246,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:45.352743 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:45.365367 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4547,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.365867 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:45.379413 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5140,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:45.379884 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:45.547919 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.168s	user 0.136s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":212,"lbm_read_time_us":12860,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33279,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:19:45.552434 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=10.126437
I20260812 06:19:45.594933 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.042s	user 0.007s	sys 0.032s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18623,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.595484 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:45.613691 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.018s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.614208 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:45.625001 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4151,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.625453 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:45.837215 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.212s	user 0.127s	sys 0.071s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1192,"lbm_read_time_us":12305,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35038,"lbm_writes_lt_1ms":543,"mutex_wait_us":507,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:19:45.838013 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=14.095187
I20260812 06:19:45.914304 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.076s	user 0.023s	sys 0.040s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":30538,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.914839 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:45.925133 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.010s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3953,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.925789 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushMRSOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:45.961608 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushMRSOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.036s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":178,"dirs.run_cpu_time_us":285,"dirs.run_wall_time_us":1213,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1692,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:45.962544 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling LogGCOp(679c9a55e1724a3bb81087514aaab744): free 120100352 bytes of WAL
I20260812 06:19:45.962808 27636 log_reader.cc:385] T 679c9a55e1724a3bb81087514aaab744: removed 12 log segments from log reader
I20260812 06:19:45.962855 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000003 (ops 12-16)
I20260812 06:19:45.962883 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000004 (ops 17-21)
I20260812 06:19:45.962944 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000005 (ops 22-26)
I20260812 06:19:45.962987 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000006 (ops 27-31)
I20260812 06:19:45.963047 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000007 (ops 32-36)
I20260812 06:19:45.963084 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000008 (ops 37-40)
I20260812 06:19:45.963137 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000009 (ops 41-45)
I20260812 06:19:45.963178 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000010 (ops 46-50)
I20260812 06:19:45.963225 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000011 (ops 51-54)
I20260812 06:19:45.963266 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000012 (ops 55-59)
I20260812 06:19:45.963304 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000013 (ops 60-64)
I20260812 06:19:45.963352 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000014 (ops 65-68)
I20260812 06:19:45.991344 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: LogGCOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.029s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:45.991811 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:46.013880 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.022s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6648,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.014348 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling UndoDeltaBlockGCOp(679c9a55e1724a3bb81087514aaab744): 462 bytes on disk
I20260812 06:19:46.014762 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: UndoDeltaBlockGCOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:46.015228 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:46.025991 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4138,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.026738 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:46.238765 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.212s	user 0.158s	sys 0.044s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":5639,"dirs.run_cpu_time_us":638,"dirs.run_wall_time_us":2808,"lbm_read_time_us":13901,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37540,"lbm_writes_lt_1ms":743,"mutex_wait_us":2558,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11008,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:19:46.239543 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=18.063937
I20260812 06:19:46.334107 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.094s	user 0.023s	sys 0.032s Metrics: {"bytes_written":20512322,"delete_count":0,"lbm_write_time_us":63204,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:19:46.334638 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:46.353124 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.018s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6361,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.353624 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:46.520900 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.167s	user 0.117s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":651,"lbm_read_time_us":12645,"lbm_reads_lt_1ms":664,"lbm_write_time_us":36907,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":30592,"update_count":3000}
I20260812 06:19:46.522334 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=14.095187
I20260812 06:19:46.568114 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.046s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20326,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.568674 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:46.586503 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6646,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.586999 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:46.739719 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.153s	user 0.119s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":200,"lbm_read_time_us":10699,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27868,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:19:46.740402 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=14.095187
I20260812 06:19:46.785357 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.045s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19353,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.785836 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:46.936097 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.150s	user 0.102s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":536,"lbm_read_time_us":9287,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25436,"lbm_writes_lt_1ms":443,"mutex_wait_us":312,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:46.936801 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=11.118625
I20260812 06:19:46.978076 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.041s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":17359,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:46.978608 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:46.999778 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.021s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4583,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:47.000232 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:47.010723 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4029,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.011214 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:47.203567 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.192s	user 0.119s	sys 0.065s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1006,"lbm_read_time_us":13278,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31266,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:47.204084 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=14.095187
I20260812 06:19:47.256064 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.052s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22519,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.256596 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:47.268486 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4370,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.268988 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:47.423169 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.154s	user 0.127s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1039,"lbm_read_time_us":10368,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29887,"lbm_writes_lt_1ms":543,"mutex_wait_us":267,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2500}
I20260812 06:19:47.423954 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=11.118625
I20260812 06:19:47.453310 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.029s	user 0.024s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12974,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:47.453898 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:47.470966 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5366,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:47.471647 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushMRSOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:47.524721 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushMRSOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.053s	user 0.024s	sys 0.008s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":1058,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1178,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2466,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:47.525650 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling LogGCOp(679c9a55e1724a3bb81087514aaab744): free 129320510 bytes of WAL
I20260812 06:19:47.525950 27636 log_reader.cc:385] T 679c9a55e1724a3bb81087514aaab744: removed 13 log segments from log reader
I20260812 06:19:47.526012 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000015 (ops 69-73)
I20260812 06:19:47.526062 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000016 (ops 74-78)
I20260812 06:19:47.526096 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000017 (ops 79-83)
I20260812 06:19:47.526130 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000018 (ops 84-88)
I20260812 06:19:47.526187 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000019 (ops 89-92)
I20260812 06:19:47.526229 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000020 (ops 93-97)
I20260812 06:19:47.526265 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000021 (ops 98-102)
I20260812 06:19:47.526306 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000022 (ops 103-107)
I20260812 06:19:47.526345 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000023 (ops 108-112)
I20260812 06:19:47.526386 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000024 (ops 113-116)
I20260812 06:19:47.526425 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000025 (ops 117-121)
I20260812 06:19:47.526464 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000026 (ops 122-126)
I20260812 06:19:47.526505 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000027 (ops 127-131)
I20260812 06:19:47.556059 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: LogGCOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:47.556531 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=7.149875
I20260812 06:19:47.593041 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.036s	user 0.023s	sys 0.012s Metrics: {"bytes_written":8574299,"delete_count":0,"lbm_write_time_us":12292,"lbm_writes_lt_1ms":212,"reinsert_count":0,"update_count":1045}
I20260812 06:19:47.593602 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling UndoDeltaBlockGCOp(679c9a55e1724a3bb81087514aaab744): 492 bytes on disk
I20260812 06:19:47.594069 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: UndoDeltaBlockGCOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:19:47.594570 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:47.604671 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":3808,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:19:47.605111 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:47.818826 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.214s	user 0.141s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":284,"lbm_read_time_us":15372,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39290,"lbm_writes_lt_1ms":743,"mutex_wait_us":32,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":75392,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:19:47.819698 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=14.095187
I20260812 06:19:47.876739 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.057s	user 0.015s	sys 0.040s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24403,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:19:47.877532 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:47.892555 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5850,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.892995 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:48.059921 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.167s	user 0.115s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":919,"lbm_read_time_us":12236,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27922,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:19:48.060554 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=14.095187
I20260812 06:19:48.121145 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.060s	user 0.020s	sys 0.039s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24219,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.121655 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:48.140799 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.019s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4637,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.141333 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:48.300473 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.159s	user 0.112s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":285,"lbm_read_time_us":10995,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26544,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2500}
I20260812 06:19:48.301110 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=14.095187
I20260812 06:19:48.353408 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.052s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23906,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.353971 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:48.374804 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.021s	user 0.003s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4946,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.375299 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:48.554196 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.179s	user 0.126s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":13072,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30848,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:19:48.554914 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=14.095187
I20260812 06:19:48.605835 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.051s	user 0.036s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22456,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.606482 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:48.623231 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5418,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.623984 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:48.795581 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.171s	user 0.105s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1257,"dirs.run_cpu_time_us":2618,"dirs.run_wall_time_us":18745,"lbm_read_time_us":10907,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27702,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:19:48.797475 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=14.095187
I20260812 06:19:48.851547 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.054s	user 0.037s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24619,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.852269 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=3.181125
I20260812 06:19:48.869552 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.017s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4716,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:48.870074 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:48.883452 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.013s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5079,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:48.883908 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushMRSOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:48.926258 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushMRSOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.042s	user 0.035s	sys 0.001s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1179,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1441,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:48.927111 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling LogGCOp(679c9a55e1724a3bb81087514aaab744): free 112692617 bytes of WAL
I20260812 06:19:48.927418 27636 log_reader.cc:385] T 679c9a55e1724a3bb81087514aaab744: removed 11 log segments from log reader
I20260812 06:19:48.927495 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000028 (ops 132-136)
I20260812 06:19:48.927553 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000029 (ops 137-141)
I20260812 06:19:48.927592 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000030 (ops 142-146)
I20260812 06:19:48.927629 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000031 (ops 147-151)
I20260812 06:19:48.927666 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000032 (ops 152-156)
I20260812 06:19:48.927778 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000033 (ops 157-161)
I20260812 06:19:48.927827 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000034 (ops 162-166)
I20260812 06:19:48.927867 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000035 (ops 167-171)
I20260812 06:19:48.927907 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000036 (ops 172-176)
I20260812 06:19:48.927946 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000037 (ops 177-181)
I20260812 06:19:48.927984 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000038 (ops 182-186)
I20260812 06:19:48.952548 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: LogGCOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.025s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:19:48.952957 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling UndoDeltaBlockGCOp(679c9a55e1724a3bb81087514aaab744): 447 bytes on disk
I20260812 06:19:48.953415 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: UndoDeltaBlockGCOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:48.953962 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=3.181125
I20260812 06:19:48.978135 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.024s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4512901,"delete_count":0,"lbm_write_time_us":6446,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:48.978632 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling LogGCOp(679c9a55e1724a3bb81087514aaab744): free 11564891 bytes of WAL
I20260812 06:19:48.978852 27636 log_reader.cc:385] T 679c9a55e1724a3bb81087514aaab744: removed 1 log segments from log reader
I20260812 06:19:48.978897 27636 log.cc:1079] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/679c9a55e1724a3bb81087514aaab744/wal-000000039 (ops 187-190)
I20260812 06:19:48.981225 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: LogGCOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:48.981534 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=2.188937
I20260812 06:19:48.991818 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3570,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:48.992282 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:49.232673 27436 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.868s	user 1.763s	sys 0.124s
I20260812 06:19:49.255897 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.263s	user 0.183s	sys 0.080s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082255,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":16527,"lbm_reads_lt_1ms":871,"lbm_write_time_us":48046,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":4000}
I20260812 06:19:49.256666 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744): perf score=18.063937
I20260812 06:19:49.300663 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: FlushDeltaMemStoresOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.044s	user 0.035s	sys 0.008s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":21444,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:19:49.301192 27747 maintenance_manager.cc:419] P 475a5f8dad8943a0baac6e3a829ed427: Scheduling MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744): perf score=1.000000
I20260812 06:19:49.378685 27436 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.145s	user 0.002s	sys 0.000s
I20260812 06:19:49.379508 27436 tablet_server.cc:179] TabletServer@127.26.203.1:0 shutting down...
I20260812 06:19:49.458474 27636 maintenance_manager.cc:643] P 475a5f8dad8943a0baac6e3a829ed427: MajorDeltaCompactionOp(679c9a55e1724a3bb81087514aaab744) complete. Timing: real 0.157s	user 0.089s	sys 0.068s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774571,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":350,"lbm_read_time_us":11991,"lbm_reads_lt_1ms":567,"lbm_write_time_us":30444,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:49.459331 27436 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:49.459789 27436 tablet_replica.cc:333] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427: stopping tablet replica
I20260812 06:19:49.460095 27436 raft_consensus.cc:2243] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:49.460345 27436 raft_consensus.cc:2272] T 679c9a55e1724a3bb81087514aaab744 P 475a5f8dad8943a0baac6e3a829ed427 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:49.467548 27436 tablet_server.cc:196] TabletServer@127.26.203.1:0 shutdown complete.
I20260812 06:19:49.533767 27436 master.cc:562] Master@127.26.203.62:43109 shutting down...
I20260812 06:19:49.537940 27436 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:49.538146 27436 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:49.538252 27436 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4f583d80472a4f25bdaf82b1b746a3ce: stopping tablet replica
I20260812 06:19:49.550834 27436 master.cc:584] Master@127.26.203.62:43109 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5555 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:49.657073 27436 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.203.62:44235
I20260812 06:19:49.657516 27436 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:49.660041 27827 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:49.660192 27830 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:49.660192 27436 server_base.cc:1061] running on GCE node
W20260812 06:19:49.660041 27826 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:49.660589 27436 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:49.660635 27436 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:49.660651 27436 hybrid_clock.cc:648] HybridClock initialized: now 1786515589660651 us; error 0 us; skew 500 ppm
I20260812 06:19:49.661586 27436 webserver.cc:533] Webserver started at http://127.26.203.62:44731/ using document root <none> and password file <none>
I20260812 06:19:49.661725 27436 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:49.661773 27436 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:49.661826 27436 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:49.662186 27436 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/master-0-root/instance:
uuid: "f8bf156716ca48b19eedf2aadab71361"
format_stamp: "Formatted at 2026-08-12 06:19:49 on dist-test-slave-x4qh"
I20260812 06:19:49.663770 27436 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:49.664706 27846 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:49.664968 27436 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:49.665067 27436 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/master-0-root
uuid: "f8bf156716ca48b19eedf2aadab71361"
format_stamp: "Formatted at 2026-08-12 06:19:49 on dist-test-slave-x4qh"
I20260812 06:19:49.665167 27436 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-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:49.675169 27436 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:49.675628 27436 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:49.680055 27436 rpc_server.cc:307] RPC server started. Bound to: 127.26.203.62:44235
I20260812 06:19:49.684906 27938 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.203.62:44235 every 8 connection(s)
I20260812 06:19:49.685356 27939 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:49.687177 27939 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361: Bootstrap starting.
I20260812 06:19:49.688063 27939 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:49.689087 27939 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361: No bootstrap required, opened a new log
I20260812 06:19:49.689517 27939 raft_consensus.cc:359] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f8bf156716ca48b19eedf2aadab71361" member_type: VOTER }
I20260812 06:19:49.689632 27939 raft_consensus.cc:385] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:49.689682 27939 raft_consensus.cc:740] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f8bf156716ca48b19eedf2aadab71361, State: Initialized, Role: FOLLOWER
I20260812 06:19:49.689845 27939 consensus_queue.cc:260] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [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: "f8bf156716ca48b19eedf2aadab71361" member_type: VOTER }
I20260812 06:19:49.689947 27939 raft_consensus.cc:399] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:49.689996 27939 raft_consensus.cc:493] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:49.690055 27939 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:49.690728 27939 raft_consensus.cc:515] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f8bf156716ca48b19eedf2aadab71361" member_type: VOTER }
I20260812 06:19:49.690886 27939 leader_election.cc:304] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [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: f8bf156716ca48b19eedf2aadab71361; no voters: 
I20260812 06:19:49.691102 27939 leader_election.cc:290] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:49.691226 27948 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:49.691457 27948 raft_consensus.cc:697] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [term 1 LEADER]: Becoming Leader. State: Replica: f8bf156716ca48b19eedf2aadab71361, State: Running, Role: LEADER
I20260812 06:19:49.691593 27948 consensus_queue.cc:237] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [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: "f8bf156716ca48b19eedf2aadab71361" member_type: VOTER }
I20260812 06:19:49.691629 27939 sys_catalog.cc:565] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:49.692040 27949 sys_catalog.cc:455] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f8bf156716ca48b19eedf2aadab71361" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f8bf156716ca48b19eedf2aadab71361" member_type: VOTER } }
I20260812 06:19:49.692094 27950 sys_catalog.cc:455] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [sys.catalog]: SysCatalogTable state changed. Reason: New leader f8bf156716ca48b19eedf2aadab71361. Latest consensus state: current_term: 1 leader_uuid: "f8bf156716ca48b19eedf2aadab71361" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f8bf156716ca48b19eedf2aadab71361" member_type: VOTER } }
I20260812 06:19:49.692191 27949 sys_catalog.cc:458] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:49.692220 27950 sys_catalog.cc:458] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:49.692843 27961 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:49.693504 27961 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:49.693660 27436 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:49.695266 27961 catalog_manager.cc:1383] Generated new cluster ID: 4363e297336643b8bf5c9b331e489c9e
I20260812 06:19:49.695330 27961 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:49.707052 27961 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:49.707679 27961 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:49.718724 27961 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361: Generated new TSK 0
I20260812 06:19:49.718936 27961 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:49.726037 27436 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:49.728049 27989 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:49.728092 27984 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:49.728127 27985 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:49.728375 27436 server_base.cc:1061] running on GCE node
I20260812 06:19:49.728567 27436 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:49.728608 27436 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:49.728624 27436 hybrid_clock.cc:648] HybridClock initialized: now 1786515589728625 us; error 0 us; skew 500 ppm
I20260812 06:19:49.729514 27436 webserver.cc:533] Webserver started at http://127.26.203.1:46365/ using document root <none> and password file <none>
I20260812 06:19:49.729650 27436 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:49.729691 27436 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:49.729741 27436 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:49.730149 27436 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/instance:
uuid: "481074a992c742f89794b8dadd356398"
format_stamp: "Formatted at 2026-08-12 06:19:49 on dist-test-slave-x4qh"
I20260812 06:19:49.731791 27436 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:49.732733 27999 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:49.733014 27436 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:49.733090 27436 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root
uuid: "481074a992c742f89794b8dadd356398"
format_stamp: "Formatted at 2026-08-12 06:19:49 on dist-test-slave-x4qh"
I20260812 06:19:49.733146 27436 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-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:49.744439 27436 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:49.744777 27436 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:49.745026 27436 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:49.745541 27436 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:49.745579 27436 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:49.745649 27436 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:49.745697 27436 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:49.749810 27436 rpc_server.cc:307] RPC server started. Bound to: 127.26.203.1:33991
I20260812 06:19:49.749873 28123 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.203.1:33991 every 8 connection(s)
I20260812 06:19:49.758435 28126 heartbeater.cc:344] Connected to a master server at 127.26.203.62:44235
I20260812 06:19:49.758546 28126 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:49.758738 28126 heartbeater.cc:507] Master 127.26.203.62:44235 requested a full tablet report, sending...
I20260812 06:19:49.759457 27869 ts_manager.cc:194] Registered new tserver with Master: 481074a992c742f89794b8dadd356398 (127.26.203.1:33991)
I20260812 06:19:49.760200 27869 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:32888
I20260812 06:19:49.760304 27436 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010053321s
I20260812 06:19:49.767258 27869 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:32904:
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:49.776461 28054 tablet_service.cc:1511] Processing CreateTablet for tablet b6809d4a38644a36a5c1b004a14a0c3b (DEFAULT_TABLE table=heavy-update-compaction-test [id=5903f940bfac4c8c99937a03dfad4077]), partition=
I20260812 06:19:49.776748 28054 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b6809d4a38644a36a5c1b004a14a0c3b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:49.778935 28149 tablet_bootstrap.cc:492] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Bootstrap starting.
I20260812 06:19:49.779803 28149 tablet_bootstrap.cc:654] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:49.780719 28149 tablet_bootstrap.cc:492] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: No bootstrap required, opened a new log
I20260812 06:19:49.780791 28149 ts_tablet_manager.cc:1403] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:19:49.781112 28149 raft_consensus.cc:359] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "481074a992c742f89794b8dadd356398" member_type: VOTER last_known_addr { host: "127.26.203.1" port: 33991 } }
I20260812 06:19:49.781193 28149 raft_consensus.cc:385] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:49.781214 28149 raft_consensus.cc:740] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 481074a992c742f89794b8dadd356398, State: Initialized, Role: FOLLOWER
I20260812 06:19:49.781344 28149 consensus_queue.cc:260] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [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: "481074a992c742f89794b8dadd356398" member_type: VOTER last_known_addr { host: "127.26.203.1" port: 33991 } }
I20260812 06:19:49.781438 28149 raft_consensus.cc:399] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:49.781497 28149 raft_consensus.cc:493] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:49.781579 28149 raft_consensus.cc:3060] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:49.782503 28149 raft_consensus.cc:515] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "481074a992c742f89794b8dadd356398" member_type: VOTER last_known_addr { host: "127.26.203.1" port: 33991 } }
I20260812 06:19:49.782644 28149 leader_election.cc:304] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [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: 481074a992c742f89794b8dadd356398; no voters: 
I20260812 06:19:49.782846 28149 leader_election.cc:290] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:49.782987 28154 raft_consensus.cc:2804] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:49.783227 28149 ts_tablet_manager.cc:1434] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:19:49.783263 28126 heartbeater.cc:499] Master 127.26.203.62:44235 was elected leader, sending a full tablet report...
I20260812 06:19:49.783245 28154 raft_consensus.cc:697] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [term 1 LEADER]: Becoming Leader. State: Replica: 481074a992c742f89794b8dadd356398, State: Running, Role: LEADER
I20260812 06:19:49.783468 28154 consensus_queue.cc:237] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [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: "481074a992c742f89794b8dadd356398" member_type: VOTER last_known_addr { host: "127.26.203.1" port: 33991 } }
I20260812 06:19:49.784696 27869 catalog_manager.cc:5719] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 reported cstate change: term changed from 0 to 1, leader changed from <none> to 481074a992c742f89794b8dadd356398 (127.26.203.1). New cstate: current_term: 1 leader_uuid: "481074a992c742f89794b8dadd356398" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "481074a992c742f89794b8dadd356398" member_type: VOTER last_known_addr { host: "127.26.203.1" port: 33991 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:49.844543 27436 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.010s	sys 0.012s
I20260812 06:19:50.000690 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushMRSOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=19.054940
I20260812 06:19:50.167496 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushMRSOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.167s	user 0.118s	sys 0.047s Metrics: {"bytes_written":13004891,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":922,"drs_written":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43345,"lbm_writes_lt_1ms":784,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":768,"update_count":1585}
I20260812 06:19:50.168130 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling LogGCOp(b6809d4a38644a36a5c1b004a14a0c3b): free 20290830 bytes of WAL
I20260812 06:19:50.168445 28012 log_reader.cc:385] T b6809d4a38644a36a5c1b004a14a0c3b: removed 2 log segments from log reader
I20260812 06:19:50.168510 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000001 (ops 1-6)
I20260812 06:19:50.168551 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000002 (ops 7-10)
I20260812 06:19:50.173902 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: LogGCOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:50.174309 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:50.191715 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.017s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3405234,"delete_count":0,"lbm_write_time_us":5502,"lbm_writes_lt_1ms":86,"reinsert_count":0,"update_count":415}
I20260812 06:19:50.192365 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling UndoDeltaBlockGCOp(b6809d4a38644a36a5c1b004a14a0c3b): 16821649 bytes on disk
I20260812 06:19:50.192866 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: UndoDeltaBlockGCOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:19:50.193328 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:50.203064 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3745,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:50.203513 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:50.389767 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.186s	user 0.137s	sys 0.041s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405525,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":575,"lbm_read_time_us":13083,"lbm_reads_lt_1ms":559,"lbm_write_time_us":29590,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":323,"threads_started":5,"update_count":2450}
I20260812 06:19:50.390301 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=14.095187
I20260812 06:19:50.457739 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.067s	user 0.036s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22968,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.458319 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:50.469409 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4384,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.469945 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:50.668121 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.198s	user 0.125s	sys 0.063s 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":1039,"lbm_read_time_us":13705,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33752,"lbm_writes_lt_1ms":543,"mutex_wait_us":324,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":2500}
I20260812 06:19:50.668773 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=14.095187
I20260812 06:19:50.725153 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.056s	user 0.023s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20131,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.725677 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:50.736706 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4378,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.737155 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:50.918254 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.181s	user 0.106s	sys 0.072s 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":916,"lbm_read_time_us":12494,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30161,"lbm_writes_lt_1ms":543,"mutex_wait_us":323,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:19:50.918874 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=11.118625
I20260812 06:19:50.955222 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.036s	user 0.029s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15584,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:50.955873 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:50.976182 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.020s	user 0.012s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5434,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:50.976632 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:51.112752 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.136s	user 0.100s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":438,"lbm_read_time_us":8023,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28717,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.113440 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=10.126437
I20260812 06:19:51.146970 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.033s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14354,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.147567 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:51.164014 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6250,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.164695 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:51.297143 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.132s	user 0.099s	sys 0.032s 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":214,"lbm_read_time_us":9895,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25579,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:19:51.297847 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=10.126437
I20260812 06:19:51.335587 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.038s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14946,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.336097 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:51.447309 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.111s	user 0.082s	sys 0.029s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":201,"lbm_read_time_us":7232,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22743,"lbm_writes_lt_1ms":343,"mutex_wait_us":42,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":1500}
I20260812 06:19:51.447947 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=10.126437
I20260812 06:19:51.493469 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.045s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14609,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.493955 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:51.504598 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4139,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.505344 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushMRSOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:51.540275 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushMRSOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.035s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":163,"dirs.run_wall_time_us":1186,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1992,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:51.540923 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling LogGCOp(b6809d4a38644a36a5c1b004a14a0c3b): free 124710296 bytes of WAL
I20260812 06:19:51.541180 28012 log_reader.cc:385] T b6809d4a38644a36a5c1b004a14a0c3b: removed 12 log segments from log reader
I20260812 06:19:51.541226 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000003 (ops 11-15)
I20260812 06:19:51.541255 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000004 (ops 16-20)
I20260812 06:19:51.541317 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000005 (ops 21-25)
I20260812 06:19:51.541370 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000006 (ops 26-30)
I20260812 06:19:51.541389 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000007 (ops 31-35)
I20260812 06:19:51.541451 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000008 (ops 36-40)
I20260812 06:19:51.541491 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000009 (ops 41-45)
I20260812 06:19:51.541538 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000010 (ops 46-50)
I20260812 06:19:51.541575 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000011 (ops 51-55)
I20260812 06:19:51.541615 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000012 (ops 56-60)
I20260812 06:19:51.541656 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000013 (ops 61-65)
I20260812 06:19:51.541694 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000014 (ops 66-70)
I20260812 06:19:51.574164 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: LogGCOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:51.574589 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling UndoDeltaBlockGCOp(b6809d4a38644a36a5c1b004a14a0c3b): 462 bytes on disk
I20260812 06:19:51.575090 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: UndoDeltaBlockGCOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:51.575724 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=3.181125
I20260812 06:19:51.591758 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4464,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:51.592185 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:51.601838 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3759,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:51.602313 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:51.804405 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.202s	user 0.124s	sys 0.076s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":719,"lbm_read_time_us":14069,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33707,"lbm_writes_lt_1ms":643,"mutex_wait_us":351,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1152,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:19:51.805158 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=14.095187
I20260812 06:19:51.863161 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.058s	user 0.043s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21852,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.863715 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:51.874300 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4254,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.874778 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:52.082167 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.207s	user 0.127s	sys 0.064s 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":629,"lbm_read_time_us":14381,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32769,"lbm_writes_lt_1ms":543,"mutex_wait_us":392,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:19:52.082710 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=14.095187
I20260812 06:19:52.153214 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.070s	user 0.036s	sys 0.028s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":24367,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.153762 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:52.164687 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4278,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.165182 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:52.345834 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.180s	user 0.104s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":403,"lbm_read_time_us":12453,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27677,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:19:52.346489 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=14.095187
I20260812 06:19:52.399914 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.053s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22077,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.400520 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:52.421361 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.021s	user 0.011s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4202,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.422050 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:52.595697 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.173s	user 0.133s	sys 0.040s 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":799,"lbm_read_time_us":12467,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27660,"lbm_writes_lt_1ms":543,"mutex_wait_us":323,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:52.596318 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=14.095187
I20260812 06:19:52.643599 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.047s	user 0.044s	sys 0.000s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19793,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.644090 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:52.654930 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4210,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.655727 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:52.828411 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.172s	user 0.105s	sys 0.061s 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":219,"lbm_read_time_us":10537,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27551,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:19:52.829071 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=14.095187
I20260812 06:19:52.876246 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.047s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20672,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.876806 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:52.888821 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4518,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.889257 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:53.054188 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.165s	user 0.118s	sys 0.036s 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":88,"lbm_read_time_us":10290,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33261,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2500}
I20260812 06:19:53.056250 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=14.095187
I20260812 06:19:53.108971 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.052s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19978,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.109535 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:53.125093 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5838,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.125824 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushMRSOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:53.164039 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushMRSOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.038s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1214,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2235,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:53.164770 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling LogGCOp(b6809d4a38644a36a5c1b004a14a0c3b): free 129773581 bytes of WAL
I20260812 06:19:53.165068 28012 log_reader.cc:385] T b6809d4a38644a36a5c1b004a14a0c3b: removed 13 log segments from log reader
I20260812 06:19:53.165136 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000015 (ops 71-75)
I20260812 06:19:53.165176 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000016 (ops 76-80)
I20260812 06:19:53.165211 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000017 (ops 81-85)
I20260812 06:19:53.165241 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000018 (ops 86-90)
I20260812 06:19:53.165263 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000019 (ops 91-95)
I20260812 06:19:53.165294 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000020 (ops 96-100)
I20260812 06:19:53.165326 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000021 (ops 101-105)
I20260812 06:19:53.165350 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000022 (ops 106-110)
I20260812 06:19:53.165380 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000023 (ops 111-114)
I20260812 06:19:53.165402 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000024 (ops 115-119)
I20260812 06:19:53.165439 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000025 (ops 120-124)
I20260812 06:19:53.165465 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000026 (ops 125-129)
I20260812 06:19:53.165490 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000027 (ops 130-134)
I20260812 06:19:53.197681 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: LogGCOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:53.198127 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling UndoDeltaBlockGCOp(b6809d4a38644a36a5c1b004a14a0c3b): 492 bytes on disk
I20260812 06:19:53.198743 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: UndoDeltaBlockGCOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:19:53.199275 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=3.181125
I20260812 06:19:53.213115 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4882121,"delete_count":0,"lbm_write_time_us":5495,"lbm_writes_lt_1ms":122,"reinsert_count":0,"update_count":595}
I20260812 06:19:53.213569 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:53.233186 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.019s	user 0.000s	sys 0.018s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":3296,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:19:53.233768 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:53.475685 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.242s	user 0.163s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020729,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3132,"lbm_read_time_us":16064,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40147,"lbm_writes_lt_1ms":743,"mutex_wait_us":64,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:19:53.476373 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=18.063937
I20260812 06:19:53.541173 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.065s	user 0.035s	sys 0.028s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":28908,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:53.541689 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:53.555140 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4862,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.555686 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:53.765610 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.210s	user 0.130s	sys 0.080s 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":989,"lbm_read_time_us":15947,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34376,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":24960,"update_count":3000}
I20260812 06:19:53.766265 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=18.063937
I20260812 06:19:53.831992 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.066s	user 0.030s	sys 0.023s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":24556,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:53.832592 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:53.843736 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4395,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.844537 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:54.046746 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.202s	user 0.128s	sys 0.067s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":267,"lbm_read_time_us":14731,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31897,"lbm_writes_lt_1ms":643,"mutex_wait_us":58,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":3000}
I20260812 06:19:54.047384 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=18.063937
I20260812 06:19:54.123862 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.076s	user 0.045s	sys 0.021s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":30154,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:54.124338 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:54.134696 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.135260 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:54.329756 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.194s	user 0.102s	sys 0.092s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":13214,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34510,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":3000}
I20260812 06:19:54.330458 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=14.095187
I20260812 06:19:54.389252 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.059s	user 0.021s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19350,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.389859 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:54.402791 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4791,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.403337 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:54.591890 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.188s	user 0.129s	sys 0.059s 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":580,"lbm_read_time_us":14259,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33431,"lbm_writes_lt_1ms":543,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:19:54.592535 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=14.095187
I20260812 06:19:54.647307 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.055s	user 0.035s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21536,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.647948 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:54.659978 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4564,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.660449 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushMRSOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:54.688834 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushMRSOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.028s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":315,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1437,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1493,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:54.689472 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling LogGCOp(b6809d4a38644a36a5c1b004a14a0c3b): free 120100531 bytes of WAL
I20260812 06:19:54.689702 28012 log_reader.cc:385] T b6809d4a38644a36a5c1b004a14a0c3b: removed 12 log segments from log reader
I20260812 06:19:54.689747 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000028 (ops 135-138)
I20260812 06:19:54.689805 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000029 (ops 139-143)
I20260812 06:19:54.689851 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000030 (ops 144-148)
I20260812 06:19:54.689913 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000031 (ops 149-152)
I20260812 06:19:54.689955 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000032 (ops 153-157)
I20260812 06:19:54.690009 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000033 (ops 158-162)
I20260812 06:19:54.690045 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000034 (ops 163-167)
I20260812 06:19:54.690085 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000035 (ops 168-172)
I20260812 06:19:54.690125 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000036 (ops 173-176)
I20260812 06:19:54.690168 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000037 (ops 177-181)
I20260812 06:19:54.690208 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000038 (ops 182-186)
I20260812 06:19:54.690248 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000039 (ops 187-191)
I20260812 06:19:54.717334 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: LogGCOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:54.720069 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling UndoDeltaBlockGCOp(b6809d4a38644a36a5c1b004a14a0c3b): 472 bytes on disk
I20260812 06:19:54.720623 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: UndoDeltaBlockGCOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:54.721310 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=3.181125
I20260812 06:19:54.733667 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.012s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4475,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:54.734171 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling LogGCOp(b6809d4a38644a36a5c1b004a14a0c3b): free 12018006 bytes of WAL
I20260812 06:19:54.734385 28012 log_reader.cc:385] T b6809d4a38644a36a5c1b004a14a0c3b: removed 1 log segments from log reader
I20260812 06:19:54.734443 28012 log.cc:1079] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: Deleting log segment in path: /tmp/dist-test-taskABWUZK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515584077551-27436-0/minicluster-data/ts-0-root/wals/b6809d4a38644a36a5c1b004a14a0c3b/wal-000000040 (ops 192-196)
I20260812 06:19:54.736892 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: LogGCOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:54.737190 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=2.188937
I20260812 06:19:54.748458 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: FlushDeltaMemStoresOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3707,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.749140 28127 maintenance_manager.cc:419] P 481074a992c742f89794b8dadd356398: Scheduling MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b): perf score=1.000000
I20260812 06:19:54.835638 27436 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.991s	user 1.818s	sys 0.199s
I20260812 06:19:54.928076 27436 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.092s	user 0.002s	sys 0.000s
I20260812 06:19:54.928651 27436 tablet_server.cc:179] TabletServer@127.26.203.1:0 shutting down...
I20260812 06:19:54.958124 28012 maintenance_manager.cc:643] P 481074a992c742f89794b8dadd356398: MajorDeltaCompactionOp(b6809d4a38644a36a5c1b004a14a0c3b) complete. Timing: real 0.209s	user 0.133s	sys 0.076s 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":394,"lbm_read_time_us":15599,"lbm_reads_lt_1ms":770,"lbm_write_time_us":34164,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":57984,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:19:54.959419 27436 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:54.959883 27436 tablet_replica.cc:333] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398: stopping tablet replica
I20260812 06:19:54.960054 27436 raft_consensus.cc:2243] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:54.960273 27436 raft_consensus.cc:2272] T b6809d4a38644a36a5c1b004a14a0c3b P 481074a992c742f89794b8dadd356398 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:54.966158 27436 tablet_server.cc:196] TabletServer@127.26.203.1:0 shutdown complete.
I20260812 06:19:55.016104 27436 master.cc:562] Master@127.26.203.62:44235 shutting down...
I20260812 06:19:55.019665 27436 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:55.019987 27436 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:55.020145 27436 tablet_replica.cc:333] T 00000000000000000000000000000000 P f8bf156716ca48b19eedf2aadab71361: stopping tablet replica
I20260812 06:19:55.032510 27436 master.cc:584] Master@127.26.203.62:44235 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5481 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11037 ms total)

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