[==========] 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:54.221684 14286 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.243.190:36169
I20260812 06:19:54.222599 14286 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:54.223155 14286 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:54.229131 14286 server_base.cc:1061] running on GCE node
W20260812 06:19:54.229216 14296 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:54.229348 14293 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:54.229521 14292 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:54.230063 14286 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:54.230186 14286 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:54.230229 14286 hybrid_clock.cc:648] HybridClock initialized: now 1786515594230227 us; error 0 us; skew 500 ppm
I20260812 06:19:54.231980 14286 webserver.cc:533] Webserver started at http://127.13.243.190:43789/ using document root <none> and password file <none>
I20260812 06:19:54.232482 14286 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:54.232537 14286 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:54.232745 14286 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:54.234390 14286 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/master-0-root/instance:
uuid: "1d738a4d567b4b5f897b61c4e5ffcf82"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-zj8q"
I20260812 06:19:54.237641 14286 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:19:54.239562 14304 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:54.240468 14286 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:54.240561 14286 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/master-0-root
uuid: "1d738a4d567b4b5f897b61c4e5ffcf82"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-zj8q"
I20260812 06:19:54.240667 14286 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-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:54.251639 14286 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:54.252177 14286 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:54.252303 14286 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:54.259287 14286 rpc_server.cc:307] RPC server started. Bound to: 127.13.243.190:36169
I20260812 06:19:54.259291 14392 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.243.190:36169 every 8 connection(s)
I20260812 06:19:54.261412 14393 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:54.266664 14393 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82: Bootstrap starting.
I20260812 06:19:54.268824 14393 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:54.269644 14393 log.cc:826] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:54.271207 14393 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82: No bootstrap required, opened a new log
I20260812 06:19:54.273798 14393 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d738a4d567b4b5f897b61c4e5ffcf82" member_type: VOTER }
I20260812 06:19:54.273957 14393 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:54.274025 14393 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1d738a4d567b4b5f897b61c4e5ffcf82, State: Initialized, Role: FOLLOWER
I20260812 06:19:54.274582 14393 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [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: "1d738a4d567b4b5f897b61c4e5ffcf82" member_type: VOTER }
I20260812 06:19:54.274724 14393 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:54.274797 14393 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:54.274915 14393 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:54.275621 14393 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d738a4d567b4b5f897b61c4e5ffcf82" member_type: VOTER }
I20260812 06:19:54.276031 14393 leader_election.cc:304] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [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: 1d738a4d567b4b5f897b61c4e5ffcf82; no voters: 
I20260812 06:19:54.276297 14393 leader_election.cc:290] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:54.276386 14398 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:54.276607 14398 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [term 1 LEADER]: Becoming Leader. State: Replica: 1d738a4d567b4b5f897b61c4e5ffcf82, State: Running, Role: LEADER
I20260812 06:19:54.277019 14398 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [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: "1d738a4d567b4b5f897b61c4e5ffcf82" member_type: VOTER }
I20260812 06:19:54.277168 14393 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:54.278765 14403 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1d738a4d567b4b5f897b61c4e5ffcf82. Latest consensus state: current_term: 1 leader_uuid: "1d738a4d567b4b5f897b61c4e5ffcf82" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d738a4d567b4b5f897b61c4e5ffcf82" member_type: VOTER } }
I20260812 06:19:54.278774 14401 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1d738a4d567b4b5f897b61c4e5ffcf82" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d738a4d567b4b5f897b61c4e5ffcf82" member_type: VOTER } }
I20260812 06:19:54.278901 14401 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:54.278901 14403 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:54.279285 14417 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:54.279306 14286 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:54.281499 14417 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:54.285485 14417 catalog_manager.cc:1383] Generated new cluster ID: 0aac9d4566fa4e1da1799113a0f73603
I20260812 06:19:54.285559 14417 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:54.294853 14417 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:54.295601 14417 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:54.300292 14417 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82: Generated new TSK 0
I20260812 06:19:54.300834 14417 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:54.311750 14286 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:54.314254 14430 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:54.314347 14429 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:54.314347 14435 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:54.314867 14286 server_base.cc:1061] running on GCE node
I20260812 06:19:54.315055 14286 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:54.315097 14286 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:54.315114 14286 hybrid_clock.cc:648] HybridClock initialized: now 1786515594315113 us; error 0 us; skew 500 ppm
I20260812 06:19:54.315913 14286 webserver.cc:533] Webserver started at http://127.13.243.129:42631/ using document root <none> and password file <none>
I20260812 06:19:54.316066 14286 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:54.316118 14286 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:54.316205 14286 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:54.316560 14286 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/instance:
uuid: "d5aceefaa5004882a5722b72eee3b3b2"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-zj8q"
I20260812 06:19:54.317988 14286 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:54.319008 14444 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:54.319275 14286 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:54.319343 14286 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root
uuid: "d5aceefaa5004882a5722b72eee3b3b2"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-zj8q"
I20260812 06:19:54.319407 14286 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-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:54.326824 14286 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:54.327389 14286 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:54.327793 14286 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:54.328573 14286 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:54.328624 14286 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:54.328675 14286 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:54.328706 14286 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:54.334532 14286 rpc_server.cc:307] RPC server started. Bound to: 127.13.243.129:41641
I20260812 06:19:54.334579 14554 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.243.129:41641 every 8 connection(s)
I20260812 06:19:54.346431 14555 heartbeater.cc:344] Connected to a master server at 127.13.243.190:36169
I20260812 06:19:54.346632 14555 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:54.347014 14555 heartbeater.cc:507] Master 127.13.243.190:36169 requested a full tablet report, sending...
I20260812 06:19:54.348431 14336 ts_manager.cc:194] Registered new tserver with Master: d5aceefaa5004882a5722b72eee3b3b2 (127.13.243.129:41641)
I20260812 06:19:54.348541 14286 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013458631s
I20260812 06:19:54.351435 14336 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60152
I20260812 06:19:54.358920 14336 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60154:
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:54.373337 14487 tablet_service.cc:1511] Processing CreateTablet for tablet 1aa0f55018d6427fb752770d15e08a3b (DEFAULT_TABLE table=heavy-update-compaction-test [id=880b112345a542fc8d1ce8238420e4a3]), partition=
I20260812 06:19:54.373769 14487 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1aa0f55018d6427fb752770d15e08a3b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:54.376106 14573 tablet_bootstrap.cc:492] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Bootstrap starting.
I20260812 06:19:54.376951 14573 tablet_bootstrap.cc:654] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:54.377969 14573 tablet_bootstrap.cc:492] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: No bootstrap required, opened a new log
I20260812 06:19:54.378053 14573 ts_tablet_manager.cc:1403] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:54.378484 14573 raft_consensus.cc:359] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d5aceefaa5004882a5722b72eee3b3b2" member_type: VOTER last_known_addr { host: "127.13.243.129" port: 41641 } }
I20260812 06:19:54.378580 14573 raft_consensus.cc:385] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:54.378611 14573 raft_consensus.cc:740] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d5aceefaa5004882a5722b72eee3b3b2, State: Initialized, Role: FOLLOWER
I20260812 06:19:54.378767 14573 consensus_queue.cc:260] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [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: "d5aceefaa5004882a5722b72eee3b3b2" member_type: VOTER last_known_addr { host: "127.13.243.129" port: 41641 } }
I20260812 06:19:54.378849 14573 raft_consensus.cc:399] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:54.379038 14573 raft_consensus.cc:493] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:54.379097 14573 raft_consensus.cc:3060] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:54.379892 14573 raft_consensus.cc:515] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d5aceefaa5004882a5722b72eee3b3b2" member_type: VOTER last_known_addr { host: "127.13.243.129" port: 41641 } }
I20260812 06:19:54.380023 14573 leader_election.cc:304] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [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: d5aceefaa5004882a5722b72eee3b3b2; no voters: 
I20260812 06:19:54.380209 14573 leader_election.cc:290] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:54.380316 14575 raft_consensus.cc:2804] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:54.380491 14575 raft_consensus.cc:697] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [term 1 LEADER]: Becoming Leader. State: Replica: d5aceefaa5004882a5722b72eee3b3b2, State: Running, Role: LEADER
I20260812 06:19:54.380533 14573 ts_tablet_manager.cc:1434] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:54.380774 14555 heartbeater.cc:499] Master 127.13.243.190:36169 was elected leader, sending a full tablet report...
I20260812 06:19:54.381037 14575 consensus_queue.cc:237] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [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: "d5aceefaa5004882a5722b72eee3b3b2" member_type: VOTER last_known_addr { host: "127.13.243.129" port: 41641 } }
I20260812 06:19:54.383530 14336 catalog_manager.cc:5719] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 reported cstate change: term changed from 0 to 1, leader changed from <none> to d5aceefaa5004882a5722b72eee3b3b2 (127.13.243.129). New cstate: current_term: 1 leader_uuid: "d5aceefaa5004882a5722b72eee3b3b2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d5aceefaa5004882a5722b72eee3b3b2" member_type: VOTER last_known_addr { host: "127.13.243.129" port: 41641 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:54.445717 14286 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.020s	sys 0.005s
I20260812 06:19:54.585688 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushMRSOp(1aa0f55018d6427fb752770d15e08a3b): perf score=19.054940
I20260812 06:19:54.792760 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushMRSOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.207s	user 0.139s	sys 0.058s Metrics: {"bytes_written":16656049,"cfile_init":1,"compiler_manager_pool.queue_time_us":207,"delete_count":0,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":793,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":48257,"lbm_writes_lt_1ms":873,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":362880,"thread_start_us":105,"threads_started":1,"update_count":2030}
I20260812 06:19:54.793891 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling LogGCOp(1aa0f55018d6427fb752770d15e08a3b): free 20743880 bytes of WAL
I20260812 06:19:54.794219 14455 log_reader.cc:385] T 1aa0f55018d6427fb752770d15e08a3b: removed 2 log segments from log reader
I20260812 06:19:54.794297 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000001 (ops 1-6)
I20260812 06:19:54.794354 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000002 (ops 7-11)
I20260812 06:19:54.799459 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: LogGCOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.005s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:19:54.799791 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling UndoDeltaBlockGCOp(1aa0f55018d6427fb752770d15e08a3b): 16821649 bytes on disk
I20260812 06:19:54.800446 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: UndoDeltaBlockGCOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:19:54.800879 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=6.157687
I20260812 06:19:54.823621 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.023s	user 0.009s	sys 0.012s Metrics: {"bytes_written":7548697,"delete_count":0,"lbm_write_time_us":9730,"lbm_writes_lt_1ms":187,"reinsert_count":0,"update_count":920}
I20260812 06:19:54.824198 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:55.001915 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.178s	user 0.114s	sys 0.064s Metrics: {"cfile_cache_miss":622,"cfile_cache_miss_bytes":28507863,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":261,"lbm_read_time_us":11495,"lbm_reads_lt_1ms":654,"lbm_write_time_us":31671,"lbm_writes_lt_1ms":633,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":269,"threads_started":5,"update_count":2950}
I20260812 06:19:55.002450 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=14.095187
I20260812 06:19:55.059255 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.057s	user 0.040s	sys 0.007s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":21570,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.059743 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:55.069567 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3667,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.069990 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:55.242256 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.172s	user 0.124s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":610,"lbm_read_time_us":12101,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27916,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:19:55.242756 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=14.095187
I20260812 06:19:55.300001 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.057s	user 0.027s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22525,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.300565 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:55.310705 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3751,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.311143 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:55.474417 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.163s	user 0.099s	sys 0.060s 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":330,"lbm_read_time_us":13299,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26848,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:55.474952 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=11.118625
I20260812 06:19:55.509526 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.034s	user 0.022s	sys 0.010s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14060,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:55.510010 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:55.534745 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.025s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4496,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.535218 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:55.544190 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3319,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:55.544569 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:55.705763 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.161s	user 0.111s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1131,"lbm_read_time_us":11322,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29308,"lbm_writes_lt_1ms":543,"mutex_wait_us":342,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:55.706338 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=11.118625
I20260812 06:19:55.741392 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.035s	user 0.031s	sys 0.001s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14812,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:55.741966 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:55.765702 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.024s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4430,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:55.766130 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:55.782881 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3660,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.783304 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:55.951989 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.169s	user 0.123s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1378,"lbm_read_time_us":13401,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28458,"lbm_writes_lt_1ms":543,"mutex_wait_us":1158,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:55.952725 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=11.118625
I20260812 06:19:55.986939 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.034s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12652,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:55.987607 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:56.001283 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4998,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.001832 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushMRSOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:56.040066 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushMRSOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.038s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":335,"dirs.run_wall_time_us":1469,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1488,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:56.041021 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=3.181125
I20260812 06:19:56.060637 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.019s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:56.061048 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling LogGCOp(1aa0f55018d6427fb752770d15e08a3b): free 124710316 bytes of WAL
I20260812 06:19:56.061246 14455 log_reader.cc:385] T 1aa0f55018d6427fb752770d15e08a3b: removed 12 log segments from log reader
I20260812 06:19:56.061290 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000003 (ops 12-16)
I20260812 06:19:56.061317 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000004 (ops 17-21)
I20260812 06:19:56.061344 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000005 (ops 22-26)
I20260812 06:19:56.061374 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000006 (ops 27-31)
I20260812 06:19:56.061406 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000007 (ops 32-36)
I20260812 06:19:56.061439 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000008 (ops 37-41)
I20260812 06:19:56.061471 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000009 (ops 42-46)
I20260812 06:19:56.061502 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000010 (ops 47-51)
I20260812 06:19:56.061535 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000011 (ops 52-56)
I20260812 06:19:56.061566 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000012 (ops 57-61)
I20260812 06:19:56.061599 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000013 (ops 62-66)
I20260812 06:19:56.061630 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000014 (ops 67-71)
I20260812 06:19:56.084611 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: LogGCOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:56.084992 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:56.099895 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.015s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3976,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.100368 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:56.288695 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.188s	user 0.127s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":607,"lbm_read_time_us":11591,"lbm_reads_lt_1ms":666,"lbm_write_time_us":31767,"lbm_writes_lt_1ms":643,"mutex_wait_us":57,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:19:56.289258 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=15.087375
I20260812 06:19:56.342093 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.052s	user 0.020s	sys 0.023s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":16752,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:56.342722 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=3.181125
I20260812 06:19:56.356575 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4964166,"delete_count":0,"lbm_write_time_us":5377,"lbm_writes_lt_1ms":124,"reinsert_count":0,"update_count":605}
I20260812 06:19:56.356987 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling UndoDeltaBlockGCOp(1aa0f55018d6427fb752770d15e08a3b): 472 bytes on disk
I20260812 06:19:56.357463 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: UndoDeltaBlockGCOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:19:56.357904 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.196750
I20260812 06:19:56.367869 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":3751,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:19:56.368196 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:56.551872 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.184s	user 0.120s	sys 0.063s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918185,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":856,"lbm_read_time_us":13033,"lbm_reads_lt_1ms":673,"lbm_write_time_us":29944,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":83968,"update_count":3000}
I20260812 06:19:56.552495 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=14.095187
I20260812 06:19:56.596854 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.044s	user 0.020s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18950,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.597358 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:56.742839 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.145s	user 0.096s	sys 0.047s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":439,"lbm_read_time_us":10216,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25179,"lbm_writes_lt_1ms":443,"mutex_wait_us":283,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2000}
I20260812 06:19:56.743367 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=11.118625
I20260812 06:19:56.771740 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.028s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":11865,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:56.772187 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:56.785202 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.013s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4273,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.785706 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:56.908923 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.123s	user 0.080s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":347,"lbm_read_time_us":7010,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23915,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:56.909618 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=10.126437
I20260812 06:19:56.945719 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.036s	user 0.029s	sys 0.005s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15127,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:56.946385 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:56.960296 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.014s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3955,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.960752 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:57.099997 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.139s	user 0.100s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1020,"lbm_read_time_us":8080,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27006,"lbm_writes_lt_1ms":443,"mutex_wait_us":512,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2000}
I20260812 06:19:57.100611 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=10.126437
I20260812 06:19:57.142341 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.042s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18837,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.142920 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:57.165309 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.022s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4225732,"delete_count":0,"lbm_write_time_us":4911,"lbm_writes_lt_1ms":106,"mutex_wait_us":72,"reinsert_count":0,"update_count":515}
I20260812 06:19:57.165831 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:57.175171 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":3446,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:19:57.175608 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:57.330963 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.155s	user 0.109s	sys 0.041s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":682,"lbm_read_time_us":10809,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27369,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:57.331503 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=12.110812
I20260812 06:19:57.376057 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.044s	user 0.026s	sys 0.016s Metrics: {"bytes_written":13702314,"delete_count":0,"lbm_write_time_us":17566,"lbm_writes_lt_1ms":337,"reinsert_count":0,"update_count":1670}
I20260812 06:19:57.376510 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.196750
I20260812 06:19:57.396894 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.020s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3118059,"delete_count":0,"lbm_write_time_us":3193,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:19:57.397372 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:57.406201 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3189,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:57.406607 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushMRSOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:57.436621 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushMRSOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.030s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1126,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1249,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:57.437314 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling LogGCOp(1aa0f55018d6427fb752770d15e08a3b): free 120553348 bytes of WAL
I20260812 06:19:57.437515 14455 log_reader.cc:385] T 1aa0f55018d6427fb752770d15e08a3b: removed 12 log segments from log reader
I20260812 06:19:57.437556 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000015 (ops 72-76)
I20260812 06:19:57.437583 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000016 (ops 77-81)
I20260812 06:19:57.437615 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000017 (ops 82-86)
I20260812 06:19:57.437646 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000018 (ops 87-91)
I20260812 06:19:57.437677 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000019 (ops 92-96)
I20260812 06:19:57.437711 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000020 (ops 97-100)
I20260812 06:19:57.437739 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000021 (ops 101-105)
I20260812 06:19:57.437770 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000022 (ops 106-110)
I20260812 06:19:57.437801 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000023 (ops 111-115)
I20260812 06:19:57.437831 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000024 (ops 116-120)
I20260812 06:19:57.437862 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000025 (ops 121-124)
I20260812 06:19:57.437893 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000026 (ops 125-129)
I20260812 06:19:57.460915 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: LogGCOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:57.461319 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=3.181125
I20260812 06:19:57.480485 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.019s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":6438,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:57.480903 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:57.493647 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4882,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:57.494051 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling UndoDeltaBlockGCOp(1aa0f55018d6427fb752770d15e08a3b): 463 bytes on disk
I20260812 06:19:57.494444 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: UndoDeltaBlockGCOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:19:57.494915 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:57.700120 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.205s	user 0.141s	sys 0.064s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020821,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":441,"lbm_read_time_us":15536,"lbm_reads_lt_1ms":775,"lbm_write_time_us":36941,"lbm_writes_lt_1ms":743,"mutex_wait_us":38,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":84,"threads_started":1,"update_count":3500}
I20260812 06:19:57.700637 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=15.087375
I20260812 06:19:57.761523 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.060s	user 0.035s	sys 0.019s Metrics: {"bytes_written":16779118,"delete_count":0,"lbm_write_time_us":22878,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2045}
I20260812 06:19:57.761945 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:57.772271 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4143687,"delete_count":0,"lbm_write_time_us":3736,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:19:57.772723 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:57.786195 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.013s	user 0.011s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5009,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:57.786690 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:57.948979 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.162s	user 0.121s	sys 0.041s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918205,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":219,"lbm_read_time_us":11547,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32345,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":3000}
I20260812 06:19:57.949662 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=14.095187
I20260812 06:19:58.001974 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.052s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22899,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.002476 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:58.022279 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.020s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5726,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.022822 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:58.175882 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.153s	user 0.128s	sys 0.023s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":126,"lbm_read_time_us":8880,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28436,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":52352,"update_count":2500}
I20260812 06:19:58.176445 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=14.095187
I20260812 06:19:58.218227 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.042s	user 0.030s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18508,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.218766 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:58.369920 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.151s	user 0.085s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":591,"lbm_read_time_us":10233,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24668,"lbm_writes_lt_1ms":443,"mutex_wait_us":263,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:19:58.370570 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=14.095187
I20260812 06:19:58.418007 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.047s	user 0.020s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19837,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.418443 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:58.428763 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.429378 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:58.601141 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.171s	user 0.097s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":557,"lbm_read_time_us":10969,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24967,"lbm_writes_lt_1ms":543,"mutex_wait_us":317,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:58.601678 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=14.095187
I20260812 06:19:58.643903 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.042s	user 0.031s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17610,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.644433 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:58.656716 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4317,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.657308 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:58.817667 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.160s	user 0.111s	sys 0.037s 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":129,"lbm_read_time_us":11022,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28428,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:19:58.818259 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=14.095187
I20260812 06:19:58.866976 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.048s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21306,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.867472 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=2.188937
I20260812 06:19:58.877382 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3683,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.878015 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushMRSOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:58.912781 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushMRSOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.035s	user 0.031s	sys 0.002s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":173,"dirs.run_wall_time_us":1209,"drs_written":1,"lbm_read_time_us":34,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1606,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:58.913411 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling LogGCOp(1aa0f55018d6427fb752770d15e08a3b): free 129320842 bytes of WAL
I20260812 06:19:58.913625 14455 log_reader.cc:385] T 1aa0f55018d6427fb752770d15e08a3b: removed 13 log segments from log reader
I20260812 06:19:58.913671 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000027 (ops 130-134)
I20260812 06:19:58.913698 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000028 (ops 135-138)
I20260812 06:19:58.913729 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000029 (ops 139-143)
I20260812 06:19:58.913762 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000030 (ops 144-148)
I20260812 06:19:58.913786 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000031 (ops 149-153)
I20260812 06:19:58.913818 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000032 (ops 154-158)
I20260812 06:19:58.913849 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000033 (ops 159-163)
I20260812 06:19:58.913882 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000034 (ops 164-168)
I20260812 06:19:58.913913 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000035 (ops 169-172)
I20260812 06:19:58.913944 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000036 (ops 173-177)
I20260812 06:19:58.913976 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000037 (ops 178-182)
I20260812 06:19:58.914016 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000038 (ops 183-187)
I20260812 06:19:58.914047 14455 log.cc:1079] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/1aa0f55018d6427fb752770d15e08a3b/wal-000000039 (ops 188-192)
I20260812 06:19:58.943094 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: LogGCOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:58.943472 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling UndoDeltaBlockGCOp(1aa0f55018d6427fb752770d15e08a3b): 492 bytes on disk
I20260812 06:19:58.943962 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: UndoDeltaBlockGCOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:58.944538 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b): perf score=6.157687
I20260812 06:19:58.975754 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: FlushDeltaMemStoresOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.031s	user 0.008s	sys 0.020s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8533,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:58.976421 14556 maintenance_manager.cc:419] P d5aceefaa5004882a5722b72eee3b3b2: Scheduling MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b): perf score=1.000000
I20260812 06:19:59.057317 14286 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.612s	user 1.680s	sys 0.130s
I20260812 06:19:59.149595 14286 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.092s	user 0.001s	sys 0.000s
I20260812 06:19:59.150295 14286 tablet_server.cc:179] TabletServer@127.13.243.129:0 shutting down...
I20260812 06:19:59.176805 14455 maintenance_manager.cc:643] P d5aceefaa5004882a5722b72eee3b3b2: MajorDeltaCompactionOp(1aa0f55018d6427fb752770d15e08a3b) complete. Timing: real 0.200s	user 0.148s	sys 0.052s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020627,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":614,"lbm_read_time_us":16648,"lbm_reads_lt_1ms":761,"lbm_write_time_us":28889,"lbm_writes_lt_1ms":743,"mutex_wait_us":261,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6784,"thread_start_us":66,"threads_started":1,"update_count":3500}
I20260812 06:19:59.177847 14286 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:59.178328 14286 tablet_replica.cc:333] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2: stopping tablet replica
I20260812 06:19:59.178551 14286 raft_consensus.cc:2243] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.178828 14286 raft_consensus.cc:2272] T 1aa0f55018d6427fb752770d15e08a3b P d5aceefaa5004882a5722b72eee3b3b2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.184285 14286 tablet_server.cc:196] TabletServer@127.13.243.129:0 shutdown complete.
I20260812 06:19:59.233762 14286 master.cc:562] Master@127.13.243.190:36169 shutting down...
I20260812 06:19:59.237521 14286 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.237679 14286 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.237732 14286 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1d738a4d567b4b5f897b61c4e5ffcf82: stopping tablet replica
I20260812 06:19:59.249769 14286 master.cc:584] Master@127.13.243.190:36169 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5103 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:59.336155 14286 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.243.190:33139
I20260812 06:19:59.336522 14286 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:59.338325 14604 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:59.338369 14602 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:59.338390 14601 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:59.338500 14286 server_base.cc:1061] running on GCE node
I20260812 06:19:59.338637 14286 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:59.338673 14286 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:59.338687 14286 hybrid_clock.cc:648] HybridClock initialized: now 1786515599338687 us; error 0 us; skew 500 ppm
I20260812 06:19:59.339401 14286 webserver.cc:533] Webserver started at http://127.13.243.190:43635/ using document root <none> and password file <none>
I20260812 06:19:59.339529 14286 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:59.339571 14286 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:59.339627 14286 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:59.339972 14286 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/master-0-root/instance:
uuid: "7837df8b091e4e9d9ba6645e258ad5c9"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-zj8q"
I20260812 06:19:59.341321 14286 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:59.342131 14625 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:59.342411 14286 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:59.342476 14286 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/master-0-root
uuid: "7837df8b091e4e9d9ba6645e258ad5c9"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-zj8q"
I20260812 06:19:59.342545 14286 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-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:59.366806 14286 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:59.367136 14286 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:59.371019 14286 rpc_server.cc:307] RPC server started. Bound to: 127.13.243.190:33139
I20260812 06:19:59.375808 14708 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.243.190:33139 every 8 connection(s)
I20260812 06:19:59.375813 14712 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:59.377611 14712 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9: Bootstrap starting.
I20260812 06:19:59.378387 14712 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:59.379289 14712 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9: No bootstrap required, opened a new log
I20260812 06:19:59.379655 14712 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7837df8b091e4e9d9ba6645e258ad5c9" member_type: VOTER }
I20260812 06:19:59.379739 14712 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:59.379769 14712 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7837df8b091e4e9d9ba6645e258ad5c9, State: Initialized, Role: FOLLOWER
I20260812 06:19:59.379904 14712 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [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: "7837df8b091e4e9d9ba6645e258ad5c9" member_type: VOTER }
I20260812 06:19:59.379972 14712 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:59.380009 14712 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:59.380055 14712 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:59.380687 14712 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7837df8b091e4e9d9ba6645e258ad5c9" member_type: VOTER }
I20260812 06:19:59.380810 14712 leader_election.cc:304] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [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: 7837df8b091e4e9d9ba6645e258ad5c9; no voters: 
I20260812 06:19:59.380971 14712 leader_election.cc:290] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:59.381073 14717 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:59.381263 14717 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [term 1 LEADER]: Becoming Leader. State: Replica: 7837df8b091e4e9d9ba6645e258ad5c9, State: Running, Role: LEADER
I20260812 06:19:59.381372 14712 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:59.381412 14717 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [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: "7837df8b091e4e9d9ba6645e258ad5c9" member_type: VOTER }
I20260812 06:19:59.381850 14719 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7837df8b091e4e9d9ba6645e258ad5c9. Latest consensus state: current_term: 1 leader_uuid: "7837df8b091e4e9d9ba6645e258ad5c9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7837df8b091e4e9d9ba6645e258ad5c9" member_type: VOTER } }
I20260812 06:19:59.381827 14718 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7837df8b091e4e9d9ba6645e258ad5c9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7837df8b091e4e9d9ba6645e258ad5c9" member_type: VOTER } }
I20260812 06:19:59.381938 14718 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:59.381928 14719 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:59.382467 14725 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:59.383183 14725 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:59.383344 14286 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:59.384857 14725 catalog_manager.cc:1383] Generated new cluster ID: 95f5692f3d684d26b0f80729e730cd56
I20260812 06:19:59.384907 14725 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:59.395717 14725 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:59.396212 14725 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:59.409339 14725 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9: Generated new TSK 0
I20260812 06:19:59.409480 14725 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:59.415359 14286 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:59.416988 14749 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:59.417052 14752 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:59.417135 14286 server_base.cc:1061] running on GCE node
W20260812 06:19:59.417128 14750 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:59.417399 14286 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:59.417445 14286 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:59.417465 14286 hybrid_clock.cc:648] HybridClock initialized: now 1786515599417465 us; error 0 us; skew 500 ppm
I20260812 06:19:59.418283 14286 webserver.cc:533] Webserver started at http://127.13.243.129:44987/ using document root <none> and password file <none>
I20260812 06:19:59.418437 14286 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:59.418486 14286 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:59.418558 14286 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:59.418905 14286 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/instance:
uuid: "905fede469ec4e1da97a4d43b9e87fd8"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-zj8q"
I20260812 06:19:59.420266 14286 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:59.421080 14766 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:59.421269 14286 fs_manager.cc:730] Time spent opening block manager: real 0.000s	user 0.000s	sys 0.001s
I20260812 06:19:59.421335 14286 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root
uuid: "905fede469ec4e1da97a4d43b9e87fd8"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-zj8q"
I20260812 06:19:59.421401 14286 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-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:59.433442 14286 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:59.433753 14286 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:59.434003 14286 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:59.434460 14286 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:59.434499 14286 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:59.434541 14286 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:59.434568 14286 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:59.438653 14286 rpc_server.cc:307] RPC server started. Bound to: 127.13.243.129:39505
I20260812 06:19:59.439698 14882 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.243.129:39505 every 8 connection(s)
I20260812 06:19:59.447914 14883 heartbeater.cc:344] Connected to a master server at 127.13.243.190:33139
I20260812 06:19:59.448004 14883 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:59.448206 14883 heartbeater.cc:507] Master 127.13.243.190:33139 requested a full tablet report, sending...
I20260812 06:19:59.448779 14648 ts_manager.cc:194] Registered new tserver with Master: 905fede469ec4e1da97a4d43b9e87fd8 (127.13.243.129:39505)
I20260812 06:19:59.449148 14286 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009836226s
I20260812 06:19:59.449646 14648 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53110
I20260812 06:19:59.455379 14648 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53112:
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:59.463227 14815 tablet_service.cc:1511] Processing CreateTablet for tablet d67a03b96ba945e3bdbc9a1d60a2c6cb (DEFAULT_TABLE table=heavy-update-compaction-test [id=5699cbfbd4e8447b82a692efd2da77c2]), partition=
I20260812 06:19:59.463481 14815 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d67a03b96ba945e3bdbc9a1d60a2c6cb. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:59.466714 14898 tablet_bootstrap.cc:492] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Bootstrap starting.
I20260812 06:19:59.467566 14898 tablet_bootstrap.cc:654] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:59.468554 14898 tablet_bootstrap.cc:492] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: No bootstrap required, opened a new log
I20260812 06:19:59.468638 14898 ts_tablet_manager.cc:1403] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:59.469098 14898 raft_consensus.cc:359] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "905fede469ec4e1da97a4d43b9e87fd8" member_type: VOTER last_known_addr { host: "127.13.243.129" port: 39505 } }
I20260812 06:19:59.469192 14898 raft_consensus.cc:385] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:59.469214 14898 raft_consensus.cc:740] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 905fede469ec4e1da97a4d43b9e87fd8, State: Initialized, Role: FOLLOWER
I20260812 06:19:59.469310 14898 consensus_queue.cc:260] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [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: "905fede469ec4e1da97a4d43b9e87fd8" member_type: VOTER last_known_addr { host: "127.13.243.129" port: 39505 } }
I20260812 06:19:59.469367 14898 raft_consensus.cc:399] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:59.469393 14898 raft_consensus.cc:493] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:59.469424 14898 raft_consensus.cc:3060] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:59.470052 14898 raft_consensus.cc:515] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "905fede469ec4e1da97a4d43b9e87fd8" member_type: VOTER last_known_addr { host: "127.13.243.129" port: 39505 } }
I20260812 06:19:59.470211 14898 leader_election.cc:304] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [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: 905fede469ec4e1da97a4d43b9e87fd8; no voters: 
I20260812 06:19:59.470366 14898 leader_election.cc:290] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:59.470472 14902 raft_consensus.cc:2804] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:59.470644 14898 ts_tablet_manager.cc:1434] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:59.470666 14902 raft_consensus.cc:697] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [term 1 LEADER]: Becoming Leader. State: Replica: 905fede469ec4e1da97a4d43b9e87fd8, State: Running, Role: LEADER
I20260812 06:19:59.470695 14883 heartbeater.cc:499] Master 127.13.243.190:33139 was elected leader, sending a full tablet report...
I20260812 06:19:59.470862 14902 consensus_queue.cc:237] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [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: "905fede469ec4e1da97a4d43b9e87fd8" member_type: VOTER last_known_addr { host: "127.13.243.129" port: 39505 } }
I20260812 06:19:59.472087 14648 catalog_manager.cc:5719] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 reported cstate change: term changed from 0 to 1, leader changed from <none> to 905fede469ec4e1da97a4d43b9e87fd8 (127.13.243.129). New cstate: current_term: 1 leader_uuid: "905fede469ec4e1da97a4d43b9e87fd8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "905fede469ec4e1da97a4d43b9e87fd8" member_type: VOTER last_known_addr { host: "127.13.243.129" port: 39505 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:59.526345 14286 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.012s	sys 0.009s
I20260812 06:19:59.690284 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushMRSOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=23.023690
I20260812 06:19:59.843107 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushMRSOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.153s	user 0.119s	sys 0.032s Metrics: {"bytes_written":13702313,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":860,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39354,"lbm_writes_lt_1ms":891,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":1280,"update_count":1670}
I20260812 06:19:59.843819 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling LogGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): free 20743880 bytes of WAL
I20260812 06:19:59.844048 14776 log_reader.cc:385] T d67a03b96ba945e3bdbc9a1d60a2c6cb: removed 2 log segments from log reader
I20260812 06:19:59.844103 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000001 (ops 1-6)
I20260812 06:19:59.844142 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000002 (ops 7-11)
I20260812 06:19:59.849478 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: LogGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:59.849877 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.196750
I20260812 06:19:59.867255 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.017s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":3697,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:19:59.867657 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling UndoDeltaBlockGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): 20513813 bytes on disk
I20260812 06:19:59.868048 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: UndoDeltaBlockGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:19:59.868417 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:19:59.877499 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.009s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3466,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.877816 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:00.036260 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.158s	user 0.113s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815772,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":520,"lbm_read_time_us":11525,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28522,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":336,"threads_started":5,"update_count":2500}
I20260812 06:20:00.036761 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=14.095187
I20260812 06:20:00.083369 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.046s	user 0.025s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16192,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.083868 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:00.098775 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5718,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.099226 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:00.257190 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.158s	user 0.117s	sys 0.032s 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":628,"lbm_read_time_us":11731,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26877,"lbm_writes_lt_1ms":543,"mutex_wait_us":294,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:20:00.257753 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=14.095187
I20260812 06:20:00.304461 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.047s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21190,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.304947 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:00.450518 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.145s	user 0.106s	sys 0.029s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":890,"lbm_read_time_us":9371,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23701,"lbm_writes_lt_1ms":443,"mutex_wait_us":314,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2000}
I20260812 06:20:00.451045 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=14.095187
I20260812 06:20:00.496500 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.045s	user 0.019s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19445,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.496953 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:00.506951 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3759,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.507850 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:00.676543 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.168s	user 0.097s	sys 0.066s 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":113,"lbm_read_time_us":10870,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25347,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:20:00.677045 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=14.095187
I20260812 06:20:00.723369 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.046s	user 0.033s	sys 0.009s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18476,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.723913 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:00.734699 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.735716 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:00.888144 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.152s	user 0.120s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":488,"lbm_read_time_us":12019,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27450,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:20:00.888660 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=11.118625
I20260812 06:20:00.924629 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.036s	user 0.016s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15115,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:00.925109 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:00.949571 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.024s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4914,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:00.950059 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:00.959566 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3544,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.959934 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushMRSOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:00.989557 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushMRSOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.029s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1252,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1367,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:00.990178 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling LogGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): free 120553317 bytes of WAL
I20260812 06:20:00.990404 14776 log_reader.cc:385] T d67a03b96ba945e3bdbc9a1d60a2c6cb: removed 12 log segments from log reader
I20260812 06:20:00.990468 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000003 (ops 12-16)
I20260812 06:20:00.990512 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000004 (ops 17-21)
I20260812 06:20:00.990545 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000005 (ops 22-26)
I20260812 06:20:00.990569 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000006 (ops 27-31)
I20260812 06:20:00.990600 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000007 (ops 32-36)
I20260812 06:20:00.990629 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000008 (ops 37-40)
I20260812 06:20:00.990656 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000009 (ops 41-45)
I20260812 06:20:00.990685 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000010 (ops 46-50)
I20260812 06:20:00.990717 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000011 (ops 51-54)
I20260812 06:20:00.990746 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000012 (ops 55-59)
I20260812 06:20:00.990774 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000013 (ops 60-64)
I20260812 06:20:00.990801 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000014 (ops 65-69)
I20260812 06:20:01.018564 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: LogGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:20:01.018924 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling UndoDeltaBlockGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): 462 bytes on disk
I20260812 06:20:01.019420 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: UndoDeltaBlockGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:20:01.019950 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=3.181125
I20260812 06:20:01.046088 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.026s	user 0.011s	sys 0.011s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":6820,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:01.046543 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:01.055619 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.009s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3400,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:01.056110 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:01.267984 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.212s	user 0.155s	sys 0.055s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020841,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":243,"lbm_read_time_us":14325,"lbm_reads_lt_1ms":775,"lbm_write_time_us":34892,"lbm_writes_lt_1ms":743,"mutex_wait_us":28,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":20224,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:20:01.268824 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=16.079562
I20260812 06:20:01.337294 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.068s	user 0.043s	sys 0.015s Metrics: {"bytes_written":17599605,"delete_count":0,"lbm_write_time_us":26795,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":430,"reinsert_count":0,"update_count":2145}
I20260812 06:20:01.337772 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=5.165500
I20260812 06:20:01.354781 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.017s	user 0.009s	sys 0.008s Metrics: {"bytes_written":7015382,"delete_count":0,"lbm_write_time_us":6820,"lbm_writes_lt_1ms":174,"reinsert_count":0,"update_count":855}
I20260812 06:20:01.355235 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:01.558322 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.203s	user 0.136s	sys 0.055s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":894,"lbm_read_time_us":14059,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33139,"lbm_writes_lt_1ms":643,"mutex_wait_us":33,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":3000}
I20260812 06:20:01.559746 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=18.063937
I20260812 06:20:01.620652 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.061s	user 0.038s	sys 0.008s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":21976,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:01.621104 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:01.631539 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3716,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.631958 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:01.820839 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.189s	user 0.117s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918100,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":117,"lbm_read_time_us":13284,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31742,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":3000}
I20260812 06:20:01.821436 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=15.087375
I20260812 06:20:01.858125 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.036s	user 0.012s	sys 0.020s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":15758,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:01.858659 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:01.868014 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3469,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:01.868394 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:02.038090 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.170s	user 0.112s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815670,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":213,"lbm_read_time_us":13425,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27280,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:20:02.038616 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=14.095187
I20260812 06:20:02.091198 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.052s	user 0.035s	sys 0.005s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17021,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.091713 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:02.101720 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3729,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.102327 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:02.270555 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.168s	user 0.106s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":629,"lbm_read_time_us":11756,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28697,"lbm_writes_lt_1ms":543,"mutex_wait_us":302,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:20:02.271040 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=14.095187
I20260812 06:20:02.327975 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.057s	user 0.015s	sys 0.040s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20114,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.328573 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:02.338621 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3745,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.339094 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushMRSOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:02.378404 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushMRSOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.039s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":42,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1315,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1412,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:02.379097 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling LogGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): free 120100387 bytes of WAL
I20260812 06:20:02.379323 14776 log_reader.cc:385] T d67a03b96ba945e3bdbc9a1d60a2c6cb: removed 12 log segments from log reader
I20260812 06:20:02.379381 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000015 (ops 70-74)
I20260812 06:20:02.379423 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000016 (ops 75-79)
I20260812 06:20:02.379458 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000017 (ops 80-84)
I20260812 06:20:02.379488 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000018 (ops 85-88)
I20260812 06:20:02.379515 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000019 (ops 89-93)
I20260812 06:20:02.379544 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000020 (ops 94-98)
I20260812 06:20:02.379575 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000021 (ops 99-102)
I20260812 06:20:02.379606 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000022 (ops 103-107)
I20260812 06:20:02.379635 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000023 (ops 108-112)
I20260812 06:20:02.379662 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000024 (ops 113-117)
I20260812 06:20:02.379690 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000025 (ops 118-122)
I20260812 06:20:02.379724 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000026 (ops 123-126)
I20260812 06:20:02.406992 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: LogGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:02.407498 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=3.181125
I20260812 06:20:02.432468 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.025s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6365,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:02.432920 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:02.441434 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3105,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:02.441802 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling UndoDeltaBlockGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): 462 bytes on disk
I20260812 06:20:02.442185 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: UndoDeltaBlockGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:20:02.442636 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:02.644717 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.202s	user 0.128s	sys 0.063s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020732,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":237,"lbm_read_time_us":13901,"lbm_reads_lt_1ms":774,"lbm_write_time_us":32970,"lbm_writes_lt_1ms":743,"mutex_wait_us":39,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":44544,"thread_start_us":67,"threads_started":1,"update_count":3500}
I20260812 06:20:02.645328 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=18.063937
I20260812 06:20:02.703001 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.057s	user 0.033s	sys 0.023s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":28232,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:20:02.703730 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:02.720633 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5722,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.721159 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:02.878254 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.157s	user 0.119s	sys 0.038s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":708,"lbm_read_time_us":10710,"lbm_reads_lt_1ms":664,"lbm_write_time_us":31091,"lbm_writes_lt_1ms":643,"mutex_wait_us":1,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":3000}
I20260812 06:20:02.878782 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=14.095187
I20260812 06:20:02.930382 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.051s	user 0.026s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22549,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.930953 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:02.955443 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.024s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.955902 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:02.970476 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5297,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.970913 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:03.128932 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.158s	user 0.124s	sys 0.031s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918214,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":235,"lbm_read_time_us":11036,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32579,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:20:03.129477 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=14.095187
I20260812 06:20:03.174077 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.044s	user 0.030s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19699,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.174641 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:03.187860 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4768,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.188335 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:03.344761 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.156s	user 0.116s	sys 0.030s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":478,"lbm_read_time_us":10717,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27778,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:20:03.345372 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=14.095187
I20260812 06:20:03.390851 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.045s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19784,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.391314 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:03.523840 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.132s	user 0.098s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":153,"lbm_read_time_us":8512,"lbm_reads_lt_1ms":463,"lbm_write_time_us":21463,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2000}
I20260812 06:20:03.524436 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=14.095187
I20260812 06:20:03.574615 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.050s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20711,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.575117 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:03.599483 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.024s	user 0.014s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7056,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.600008 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushMRSOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:03.641861 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushMRSOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.042s	user 0.024s	sys 0.001s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":41,"dirs.run_cpu_time_us":161,"dirs.run_wall_time_us":1192,"drs_written":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1985,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:03.642656 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=3.181125
I20260812 06:20:03.661476 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.019s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6363,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:03.661962 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling LogGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): free 121006684 bytes of WAL
I20260812 06:20:03.662211 14776 log_reader.cc:385] T d67a03b96ba945e3bdbc9a1d60a2c6cb: removed 12 log segments from log reader
I20260812 06:20:03.662261 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000027 (ops 127-131)
I20260812 06:20:03.662302 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000028 (ops 132-136)
I20260812 06:20:03.662334 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000029 (ops 137-141)
I20260812 06:20:03.662365 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000030 (ops 142-146)
I20260812 06:20:03.662396 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000031 (ops 147-151)
I20260812 06:20:03.662426 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000032 (ops 152-156)
I20260812 06:20:03.662457 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000033 (ops 157-161)
I20260812 06:20:03.662487 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000034 (ops 162-166)
I20260812 06:20:03.662518 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000035 (ops 167-170)
I20260812 06:20:03.662555 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000036 (ops 171-175)
I20260812 06:20:03.662582 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000037 (ops 176-180)
I20260812 06:20:03.662612 14776 log.cc:1079] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: Deleting log segment in path: /tmp/dist-test-taskvCjqbI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594211665-14286-0/minicluster-data/ts-0-root/wals/d67a03b96ba945e3bdbc9a1d60a2c6cb/wal-000000038 (ops 181-185)
I20260812 06:20:03.683336 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: LogGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.021s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:20:03.683825 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling UndoDeltaBlockGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): 463 bytes on disk
I20260812 06:20:03.684257 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: UndoDeltaBlockGCOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:20:03.684863 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:03.700563 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4298,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:03.700937 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:03.710331 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.009s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3603,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.710698 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=1.000000
I20260812 06:20:03.934396 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: MajorDeltaCompactionOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.224s	user 0.157s	sys 0.064s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123262,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":564,"lbm_read_time_us":17430,"lbm_reads_lt_1ms":875,"lbm_write_time_us":39756,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"thread_start_us":72,"threads_started":1,"update_count":4000}
I20260812 06:20:03.934899 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=18.063937
I20260812 06:20:03.970822 14286 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.444s	user 1.596s	sys 0.148s
I20260812 06:20:03.991344 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.056s	user 0.023s	sys 0.032s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":24019,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:03.991837 14885 maintenance_manager.cc:419] P 905fede469ec4e1da97a4d43b9e87fd8: Scheduling FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb): perf score=2.188937
I20260812 06:20:03.993397 14286 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.022s	user 0.001s	sys 0.000s
I20260812 06:20:03.993818 14286 tablet_server.cc:179] TabletServer@127.13.243.129:0 shutting down...
I20260812 06:20:04.004974 14776 maintenance_manager.cc:643] P 905fede469ec4e1da97a4d43b9e87fd8: FlushDeltaMemStoresOp(d67a03b96ba945e3bdbc9a1d60a2c6cb) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4789,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.005409 14286 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:04.005599 14286 tablet_replica.cc:333] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8: stopping tablet replica
I20260812 06:20:04.005726 14286 raft_consensus.cc:2243] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:04.005892 14286 raft_consensus.cc:2272] T d67a03b96ba945e3bdbc9a1d60a2c6cb P 905fede469ec4e1da97a4d43b9e87fd8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:04.018821 14286 tablet_server.cc:196] TabletServer@127.13.243.129:0 shutdown complete.
I20260812 06:20:04.021309 14286 master.cc:562] Master@127.13.243.190:33139 shutting down...
I20260812 06:20:04.024151 14286 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:04.024286 14286 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:04.024353 14286 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7837df8b091e4e9d9ba6645e258ad5c9: stopping tablet replica
I20260812 06:20:04.036190 14286 master.cc:584] Master@127.13.243.190:33139 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4788 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9892 ms total)

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