[==========] 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:49.391057 27206 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.145.190:44245
I20260812 06:19:49.391995 27206 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:49.392550 27206 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:49.398236 27214 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:49.398305 27206 server_base.cc:1061] running on GCE node
W20260812 06:19:49.398204 27218 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:49.398468 27215 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:49.398933 27206 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:49.399037 27206 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:49.399080 27206 hybrid_clock.cc:648] HybridClock initialized: now 1786515589399077 us; error 0 us; skew 500 ppm
I20260812 06:19:49.400724 27206 webserver.cc:533] Webserver started at http://127.26.145.190:45489/ using document root <none> and password file <none>
I20260812 06:19:49.401212 27206 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:49.401273 27206 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:49.401505 27206 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:49.403034 27206 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/master-0-root/instance:
uuid: "19905c5cece249d4acb2f9d308e88c7a"
format_stamp: "Formatted at 2026-08-12 06:19:49 on dist-test-slave-42z9"
I20260812 06:19:49.406174 27206 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:49.408034 27236 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:49.408939 27206 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:19:49.409037 27206 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/master-0-root
uuid: "19905c5cece249d4acb2f9d308e88c7a"
format_stamp: "Formatted at 2026-08-12 06:19:49 on dist-test-slave-42z9"
I20260812 06:19:49.409121 27206 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:49.442592 27206 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:49.443246 27206 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:49.443404 27206 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:49.451205 27317 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.145.190:44245 every 8 connection(s)
I20260812 06:19:49.451201 27206 rpc_server.cc:307] RPC server started. Bound to: 127.26.145.190:44245
I20260812 06:19:49.453539 27319 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:49.458864 27319 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a: Bootstrap starting.
I20260812 06:19:49.461330 27319 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:49.462255 27319 log.cc:826] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:49.463871 27319 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a: No bootstrap required, opened a new log
I20260812 06:19:49.466635 27319 raft_consensus.cc:359] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "19905c5cece249d4acb2f9d308e88c7a" member_type: VOTER }
I20260812 06:19:49.466804 27319 raft_consensus.cc:385] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:49.466859 27319 raft_consensus.cc:740] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 19905c5cece249d4acb2f9d308e88c7a, State: Initialized, Role: FOLLOWER
I20260812 06:19:49.467459 27319 consensus_queue.cc:260] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [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: "19905c5cece249d4acb2f9d308e88c7a" member_type: VOTER }
I20260812 06:19:49.467612 27319 raft_consensus.cc:399] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:49.467677 27319 raft_consensus.cc:493] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:49.467797 27319 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:49.468554 27319 raft_consensus.cc:515] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "19905c5cece249d4acb2f9d308e88c7a" member_type: VOTER }
I20260812 06:19:49.468973 27319 leader_election.cc:304] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [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: 19905c5cece249d4acb2f9d308e88c7a; no voters: 
I20260812 06:19:49.469257 27319 leader_election.cc:290] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:49.469359 27325 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:49.469607 27325 raft_consensus.cc:697] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [term 1 LEADER]: Becoming Leader. State: Replica: 19905c5cece249d4acb2f9d308e88c7a, State: Running, Role: LEADER
I20260812 06:19:49.469986 27325 consensus_queue.cc:237] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [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: "19905c5cece249d4acb2f9d308e88c7a" member_type: VOTER }
I20260812 06:19:49.470206 27319 sys_catalog.cc:565] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:49.471674 27329 sys_catalog.cc:455] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [sys.catalog]: SysCatalogTable state changed. Reason: New leader 19905c5cece249d4acb2f9d308e88c7a. Latest consensus state: current_term: 1 leader_uuid: "19905c5cece249d4acb2f9d308e88c7a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "19905c5cece249d4acb2f9d308e88c7a" member_type: VOTER } }
I20260812 06:19:49.471702 27327 sys_catalog.cc:455] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "19905c5cece249d4acb2f9d308e88c7a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "19905c5cece249d4acb2f9d308e88c7a" member_type: VOTER } }
I20260812 06:19:49.471810 27327 sys_catalog.cc:458] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:49.471810 27329 sys_catalog.cc:458] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:49.472229 27349 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:49.472293 27206 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:49.474500 27349 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:49.478914 27349 catalog_manager.cc:1383] Generated new cluster ID: f894e46bff1c4dd1bdf60b65f7f418a8
I20260812 06:19:49.478976 27349 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:49.498790 27349 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:49.499912 27349 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:49.511231 27349 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a: Generated new TSK 0
I20260812 06:19:49.511984 27349 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:49.537168 27206 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:49.539664 27358 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:49.539757 27362 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:49.539788 27359 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:49.540295 27206 server_base.cc:1061] running on GCE node
I20260812 06:19:49.540449 27206 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:49.540485 27206 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:49.540504 27206 hybrid_clock.cc:648] HybridClock initialized: now 1786515589540505 us; error 0 us; skew 500 ppm
I20260812 06:19:49.541307 27206 webserver.cc:533] Webserver started at http://127.26.145.129:35139/ using document root <none> and password file <none>
I20260812 06:19:49.541492 27206 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:49.541555 27206 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:49.541630 27206 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:49.541975 27206 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/instance:
uuid: "fceb7e176f494aa9bff8a85ac1edac40"
format_stamp: "Formatted at 2026-08-12 06:19:49 on dist-test-slave-42z9"
I20260812 06:19:49.543349 27206 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:49.544232 27371 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:49.544493 27206 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:49.544581 27206 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root
uuid: "fceb7e176f494aa9bff8a85ac1edac40"
format_stamp: "Formatted at 2026-08-12 06:19:49 on dist-test-slave-42z9"
I20260812 06:19:49.544648 27206 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:49.566265 27206 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:49.566748 27206 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:49.567256 27206 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:49.568261 27206 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:49.568327 27206 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:49.568382 27206 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:49.568423 27206 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:49.575172 27206 rpc_server.cc:307] RPC server started. Bound to: 127.26.145.129:42929
I20260812 06:19:49.575232 27477 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.145.129:42929 every 8 connection(s)
I20260812 06:19:49.587038 27478 heartbeater.cc:344] Connected to a master server at 127.26.145.190:44245
I20260812 06:19:49.587242 27478 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:49.587618 27478 heartbeater.cc:507] Master 127.26.145.190:44245 requested a full tablet report, sending...
I20260812 06:19:49.588896 27264 ts_manager.cc:194] Registered new tserver with Master: fceb7e176f494aa9bff8a85ac1edac40 (127.26.145.129:42929)
I20260812 06:19:49.589138 27206 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013329034s
I20260812 06:19:49.590286 27264 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33894
I20260812 06:19:49.597587 27264 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33898:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:49.610801 27428 tablet_service.cc:1511] Processing CreateTablet for tablet fd47efb918d34343b7b2011baf77a1d8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7259ec520df64a8c8d7a326714cf86d5]), partition=
I20260812 06:19:49.611173 27428 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet fd47efb918d34343b7b2011baf77a1d8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:49.613432 27501 tablet_bootstrap.cc:492] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Bootstrap starting.
I20260812 06:19:49.614385 27501 tablet_bootstrap.cc:654] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:49.615855 27501 tablet_bootstrap.cc:492] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: No bootstrap required, opened a new log
I20260812 06:19:49.615948 27501 ts_tablet_manager.cc:1403] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:49.616387 27501 raft_consensus.cc:359] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fceb7e176f494aa9bff8a85ac1edac40" member_type: VOTER last_known_addr { host: "127.26.145.129" port: 42929 } }
I20260812 06:19:49.616489 27501 raft_consensus.cc:385] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:49.616513 27501 raft_consensus.cc:740] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fceb7e176f494aa9bff8a85ac1edac40, State: Initialized, Role: FOLLOWER
I20260812 06:19:49.616637 27501 consensus_queue.cc:260] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [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: "fceb7e176f494aa9bff8a85ac1edac40" member_type: VOTER last_known_addr { host: "127.26.145.129" port: 42929 } }
I20260812 06:19:49.616707 27501 raft_consensus.cc:399] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:49.616734 27501 raft_consensus.cc:493] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:49.616779 27501 raft_consensus.cc:3060] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:49.617479 27501 raft_consensus.cc:515] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fceb7e176f494aa9bff8a85ac1edac40" member_type: VOTER last_known_addr { host: "127.26.145.129" port: 42929 } }
I20260812 06:19:49.617615 27501 leader_election.cc:304] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [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: fceb7e176f494aa9bff8a85ac1edac40; no voters: 
I20260812 06:19:49.617797 27501 leader_election.cc:290] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:49.617934 27504 raft_consensus.cc:2804] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:49.618155 27501 ts_tablet_manager.cc:1434] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:49.618183 27504 raft_consensus.cc:697] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [term 1 LEADER]: Becoming Leader. State: Replica: fceb7e176f494aa9bff8a85ac1edac40, State: Running, Role: LEADER
I20260812 06:19:49.618376 27478 heartbeater.cc:499] Master 127.26.145.190:44245 was elected leader, sending a full tablet report...
I20260812 06:19:49.618377 27504 consensus_queue.cc:237] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [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: "fceb7e176f494aa9bff8a85ac1edac40" member_type: VOTER last_known_addr { host: "127.26.145.129" port: 42929 } }
I20260812 06:19:49.621295 27264 catalog_manager.cc:5719] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 reported cstate change: term changed from 0 to 1, leader changed from <none> to fceb7e176f494aa9bff8a85ac1edac40 (127.26.145.129). New cstate: current_term: 1 leader_uuid: "fceb7e176f494aa9bff8a85ac1edac40" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fceb7e176f494aa9bff8a85ac1edac40" member_type: VOTER last_known_addr { host: "127.26.145.129" port: 42929 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:49.678058 27206 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.019s	sys 0.005s
I20260812 06:19:49.826268 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushMRSOp(fd47efb918d34343b7b2011baf77a1d8): perf score=19.054940
I20260812 06:19:49.971102 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushMRSOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.144s	user 0.092s	sys 0.050s Metrics: {"bytes_written":12307493,"cfile_init":1,"compiler_manager_pool.queue_time_us":218,"delete_count":0,"dirs.queue_time_us":1733,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":3486,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":33293,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":205184,"thread_start_us":134,"threads_started":1,"update_count":1500}
I20260812 06:19:49.972151 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling LogGCOp(fd47efb918d34343b7b2011baf77a1d8): free 20743880 bytes of WAL
I20260812 06:19:49.972456 27383 log_reader.cc:385] T fd47efb918d34343b7b2011baf77a1d8: removed 2 log segments from log reader
I20260812 06:19:49.972527 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000001 (ops 1-6)
I20260812 06:19:49.972587 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000002 (ops 7-11)
I20260812 06:19:49.976286 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: LogGCOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:49.976679 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling UndoDeltaBlockGCOp(fd47efb918d34343b7b2011baf77a1d8): 16821648 bytes on disk
I20260812 06:19:49.977222 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: UndoDeltaBlockGCOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:49.977638 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:49.994930 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5590,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:49.995389 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:50.126930 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.131s	user 0.090s	sys 0.037s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20303021,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":759,"lbm_read_time_us":6821,"lbm_reads_lt_1ms":450,"lbm_write_time_us":21139,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":272,"threads_started":5,"update_count":1950}
I20260812 06:19:50.127401 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=10.126437
I20260812 06:19:50.159853 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.032s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13512,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.160987 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:50.263365 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.102s	user 0.067s	sys 0.035s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":139,"lbm_read_time_us":6694,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17746,"lbm_writes_lt_1ms":343,"mutex_wait_us":27,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:19:50.263856 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=10.126437
I20260812 06:19:50.294814 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.031s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13428,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.295253 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:50.415751 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.120s	user 0.084s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":171,"lbm_read_time_us":6607,"lbm_reads_lt_1ms":367,"lbm_write_time_us":20273,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:19:50.416240 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=10.126437
I20260812 06:19:50.458107 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.041s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14487,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.458667 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:50.469058 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3783,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.469619 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:50.586129 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.116s	user 0.080s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":142,"lbm_read_time_us":7782,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22404,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2000}
I20260812 06:19:50.586719 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=10.126437
I20260812 06:19:50.630054 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.043s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13775,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.630594 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:50.645804 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.646251 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:50.765512 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.119s	user 0.097s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":728,"lbm_read_time_us":9388,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20579,"lbm_writes_lt_1ms":443,"mutex_wait_us":16,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:19:50.765970 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=10.126437
I20260812 06:19:50.812716 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.047s	user 0.015s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12988,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.813257 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:50.823172 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3727,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.823567 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:50.964881 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.141s	user 0.101s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":239,"lbm_read_time_us":9727,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22091,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:19:50.965466 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=10.126437
I20260812 06:19:51.003149 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.038s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16203,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.003620 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:51.097747 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.094s	user 0.069s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610743,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":667,"lbm_read_time_us":5605,"lbm_reads_lt_1ms":367,"lbm_write_time_us":16790,"lbm_writes_lt_1ms":343,"mutex_wait_us":271,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:19:51.098202 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=10.126437
I20260812 06:19:51.145701 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.047s	user 0.020s	sys 0.017s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15868,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":1500}
I20260812 06:19:51.146274 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:51.158007 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.158504 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushMRSOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:51.190407 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushMRSOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.032s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":181,"dirs.run_wall_time_us":1113,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1342,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:51.191215 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling LogGCOp(fd47efb918d34343b7b2011baf77a1d8): free 112692367 bytes of WAL
I20260812 06:19:51.191447 27383 log_reader.cc:385] T fd47efb918d34343b7b2011baf77a1d8: removed 11 log segments from log reader
I20260812 06:19:51.191507 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000003 (ops 12-16)
I20260812 06:19:51.191547 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000004 (ops 17-21)
I20260812 06:19:51.191591 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000005 (ops 22-26)
I20260812 06:19:51.191620 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000006 (ops 27-31)
I20260812 06:19:51.191648 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000007 (ops 32-36)
I20260812 06:19:51.191677 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000008 (ops 37-41)
I20260812 06:19:51.191710 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000009 (ops 42-46)
I20260812 06:19:51.191740 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000010 (ops 47-51)
I20260812 06:19:51.191768 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000011 (ops 52-56)
I20260812 06:19:51.191797 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000012 (ops 57-61)
I20260812 06:19:51.191825 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000013 (ops 62-66)
I20260812 06:19:51.214653 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: LogGCOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:51.215075 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=3.181125
I20260812 06:19:51.230142 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.015s	user 0.008s	sys 0.002s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3920,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:51.230551 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling UndoDeltaBlockGCOp(fd47efb918d34343b7b2011baf77a1d8): 448 bytes on disk
I20260812 06:19:51.230960 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: UndoDeltaBlockGCOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:51.231390 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:51.240388 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3343,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:51.240770 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:51.393589 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.153s	user 0.119s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918322,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":402,"lbm_read_time_us":10929,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29578,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5248,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:19:51.396066 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=14.095187
I20260812 06:19:51.442185 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.046s	user 0.023s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19765,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.442691 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:51.460265 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.017s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6128,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.460737 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:51.608646 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.148s	user 0.115s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":9088,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26749,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:19:51.609189 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=14.095187
I20260812 06:19:51.674579 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.065s	user 0.041s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25773,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.675071 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:51.685187 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3761,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.685739 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:51.865895 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.180s	user 0.129s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":748,"dirs.run_cpu_time_us":817,"dirs.run_wall_time_us":9347,"lbm_read_time_us":11224,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30141,"lbm_writes_lt_1ms":543,"mutex_wait_us":294,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":74368,"update_count":2500}
I20260812 06:19:51.866376 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=14.095187
I20260812 06:19:51.912256 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.046s	user 0.030s	sys 0.013s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":18268,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.912875 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:51.924647 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4523,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.925243 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:52.088243 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.163s	user 0.108s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815679,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":577,"lbm_read_time_us":11359,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26091,"lbm_writes_lt_1ms":543,"mutex_wait_us":261,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:19:52.088850 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=14.095187
I20260812 06:19:52.145311 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.056s	user 0.016s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18602,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.145853 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:52.155942 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3794,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.156385 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:52.326560 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.170s	user 0.096s	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":3351,"lbm_read_time_us":11932,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26714,"lbm_writes_lt_1ms":543,"mutex_wait_us":2743,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:19:52.327091 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=14.095187
I20260812 06:19:52.378329 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.051s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19268,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.378926 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:52.389235 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3789,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.389756 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:52.543855 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.154s	user 0.107s	sys 0.047s 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":253,"lbm_read_time_us":11249,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26560,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2500}
I20260812 06:19:52.544521 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=10.126437
I20260812 06:19:52.574554 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.030s	user 0.012s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12348,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.575062 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:52.589866 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.590507 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushMRSOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:52.619096 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushMRSOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":42,"dirs.run_cpu_time_us":282,"dirs.run_wall_time_us":1235,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1668,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:52.619903 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling LogGCOp(fd47efb918d34343b7b2011baf77a1d8): free 136728237 bytes of WAL
I20260812 06:19:52.620143 27383 log_reader.cc:385] T fd47efb918d34343b7b2011baf77a1d8: removed 13 log segments from log reader
I20260812 06:19:52.620205 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000014 (ops 67-71)
I20260812 06:19:52.620251 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000015 (ops 72-76)
I20260812 06:19:52.620285 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000016 (ops 77-81)
I20260812 06:19:52.620311 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000017 (ops 82-86)
I20260812 06:19:52.620337 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000018 (ops 87-91)
I20260812 06:19:52.620368 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000019 (ops 92-96)
I20260812 06:19:52.620398 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000020 (ops 97-101)
I20260812 06:19:52.620426 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000021 (ops 102-106)
I20260812 06:19:52.620447 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000022 (ops 107-111)
I20260812 06:19:52.620482 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000023 (ops 112-116)
I20260812 06:19:52.620515 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000024 (ops 117-121)
I20260812 06:19:52.620545 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000025 (ops 122-126)
I20260812 06:19:52.620571 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000026 (ops 127-131)
I20260812 06:19:52.648578 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: LogGCOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:52.649113 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=3.181125
I20260812 06:19:52.668612 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.019s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4841094,"delete_count":0,"lbm_write_time_us":7457,"lbm_writes_lt_1ms":121,"reinsert_count":0,"update_count":590}
I20260812 06:19:52.669070 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling UndoDeltaBlockGCOp(fd47efb918d34343b7b2011baf77a1d8): 482 bytes on disk
I20260812 06:19:52.669561 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: UndoDeltaBlockGCOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:19:52.670109 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:52.683025 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3364205,"delete_count":0,"lbm_write_time_us":4622,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:19:52.683498 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:52.859303 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.176s	user 0.143s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":716,"lbm_read_time_us":12594,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29916,"lbm_writes_lt_1ms":643,"mutex_wait_us":313,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28160,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:19:52.859774 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=14.095187
I20260812 06:19:52.911141 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.051s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18789,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.911713 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:52.921810 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3824,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.922272 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:53.081748 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.159s	user 0.094s	sys 0.063s 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":181,"lbm_read_time_us":11143,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25828,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:53.082361 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=11.118625
I20260812 06:19:53.116246 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.034s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13883,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:53.116904 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:53.129936 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4620,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:53.130438 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:53.282385 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.152s	user 0.082s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":715,"lbm_read_time_us":8128,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21365,"lbm_writes_lt_1ms":443,"mutex_wait_us":266,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:19:53.282855 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=14.095187
I20260812 06:19:53.330821 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.048s	user 0.034s	sys 0.003s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16704,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.331400 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:53.341353 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3404,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.342002 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:53.484108 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.142s	user 0.108s	sys 0.028s 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":506,"lbm_read_time_us":8384,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26857,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:19:53.484704 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=14.095187
I20260812 06:19:53.533313 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.048s	user 0.022s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22437,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.533802 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:53.546471 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4388,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.546897 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:53.690546 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.144s	user 0.115s	sys 0.020s 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":833,"lbm_read_time_us":10355,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26095,"lbm_writes_lt_1ms":543,"mutex_wait_us":247,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:19:53.693069 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=14.095187
I20260812 06:19:53.737309 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.044s	user 0.036s	sys 0.004s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18567,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.737865 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:53.752915 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5397,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.753561 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:53.895208 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.141s	user 0.108s	sys 0.032s 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":779,"lbm_read_time_us":8629,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28131,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21888,"update_count":2500}
I20260812 06:19:53.895896 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=11.118625
I20260812 06:19:53.926026 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.030s	user 0.018s	sys 0.012s Metrics: {"bytes_written":13415137,"delete_count":0,"lbm_write_time_us":13045,"lbm_writes_lt_1ms":330,"reinsert_count":0,"update_count":1635}
I20260812 06:19:53.926605 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.196750
I20260812 06:19:53.941620 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":2994980,"delete_count":0,"lbm_write_time_us":4272,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:19:53.942165 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushMRSOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:53.984442 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushMRSOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.042s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1302,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1991,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:53.985150 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=3.181125
I20260812 06:19:54.003641 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6438,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:54.004146 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling LogGCOp(fd47efb918d34343b7b2011baf77a1d8): free 121006705 bytes of WAL
I20260812 06:19:54.004356 27383 log_reader.cc:385] T fd47efb918d34343b7b2011baf77a1d8: removed 12 log segments from log reader
I20260812 06:19:54.004402 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000027 (ops 132-136)
I20260812 06:19:54.004429 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000028 (ops 137-141)
I20260812 06:19:54.004460 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000029 (ops 142-146)
I20260812 06:19:54.004490 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000030 (ops 147-151)
I20260812 06:19:54.004523 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000031 (ops 152-156)
I20260812 06:19:54.004555 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000032 (ops 157-160)
I20260812 06:19:54.004586 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000033 (ops 161-165)
I20260812 06:19:54.004618 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000034 (ops 166-170)
I20260812 06:19:54.004648 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000035 (ops 171-175)
I20260812 06:19:54.004679 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000036 (ops 176-180)
I20260812 06:19:54.004710 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000037 (ops 181-185)
I20260812 06:19:54.004740 27383 log.cc:1079] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/fd47efb918d34343b7b2011baf77a1d8/wal-000000038 (ops 186-190)
I20260812 06:19:54.025815 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: LogGCOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:54.026214 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:54.045421 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.019s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5247,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.045886 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=2.188937
I20260812 06:19:54.060803 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.015s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5461,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.061499 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8): perf score=1.000000
I20260812 06:19:54.191305 27206 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.513s	user 1.680s	sys 0.108s
I20260812 06:19:54.258616 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: MajorDeltaCompactionOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.197s	user 0.118s	sys 0.078s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020820,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":14466,"lbm_reads_lt_1ms":771,"lbm_write_time_us":35033,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:19:54.259138 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling UndoDeltaBlockGCOp(fd47efb918d34343b7b2011baf77a1d8): 482 bytes on disk
I20260812 06:19:54.259553 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: UndoDeltaBlockGCOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4}
I20260812 06:19:54.260159 27480 maintenance_manager.cc:419] P fceb7e176f494aa9bff8a85ac1edac40: Scheduling FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8): perf score=10.126437
I20260812 06:19:54.283533 27206 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.092s	user 0.003s	sys 0.000s
I20260812 06:19:54.284231 27206 tablet_server.cc:179] TabletServer@127.26.145.129:0 shutting down...
I20260812 06:19:54.294402 27383 maintenance_manager.cc:643] P fceb7e176f494aa9bff8a85ac1edac40: FlushDeltaMemStoresOp(fd47efb918d34343b7b2011baf77a1d8) complete. Timing: real 0.034s	user 0.028s	sys 0.005s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14807,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:54.294919 27206 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:54.295301 27206 tablet_replica.cc:333] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40: stopping tablet replica
I20260812 06:19:54.295498 27206 raft_consensus.cc:2243] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:54.295704 27206 raft_consensus.cc:2272] T fd47efb918d34343b7b2011baf77a1d8 P fceb7e176f494aa9bff8a85ac1edac40 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:54.300215 27206 tablet_server.cc:196] TabletServer@127.26.145.129:0 shutdown complete.
I20260812 06:19:54.315378 27206 master.cc:562] Master@127.26.145.190:44245 shutting down...
I20260812 06:19:54.318567 27206 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:54.318718 27206 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:54.318790 27206 tablet_replica.cc:333] T 00000000000000000000000000000000 P 19905c5cece249d4acb2f9d308e88c7a: stopping tablet replica
I20260812 06:19:54.330809 27206 master.cc:584] Master@127.26.145.190:44245 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5009 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:54.400872 27206 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.145.190:34489
I20260812 06:19:54.401248 27206 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:54.403333 27535 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:54.403306 27206 server_base.cc:1061] running on GCE node
W20260812 06:19:54.403389 27534 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.403290 27538 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.403698 27206 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:54.403741 27206 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.403755 27206 hybrid_clock.cc:648] HybridClock initialized: now 1786515594403755 us; error 0 us; skew 500 ppm
I20260812 06:19:54.404507 27206 webserver.cc:533] Webserver started at http://127.26.145.190:38675/ using document root <none> and password file <none>
I20260812 06:19:54.404657 27206 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:54.404702 27206 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:54.404776 27206 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:54.405143 27206 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/master-0-root/instance:
uuid: "29ec67c27767414e87731c3830583364"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-42z9"
I20260812 06:19:54.406584 27206 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:54.407392 27551 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.407591 27206 fs_manager.cc:730] Time spent opening block manager: real 0.000s	user 0.001s	sys 0.000s
I20260812 06:19:54.407655 27206 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/master-0-root
uuid: "29ec67c27767414e87731c3830583364"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-42z9"
I20260812 06:19:54.407723 27206 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-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.411639 27206 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:54.411922 27206 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:54.415715 27206 rpc_server.cc:307] RPC server started. Bound to: 127.26.145.190:34489
I20260812 06:19:54.428782 27653 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.428776 27650 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.145.190:34489 every 8 connection(s)
I20260812 06:19:54.430598 27653 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364: Bootstrap starting.
I20260812 06:19:54.431319 27653 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:54.432246 27653 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364: No bootstrap required, opened a new log
I20260812 06:19:54.432595 27653 raft_consensus.cc:359] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "29ec67c27767414e87731c3830583364" member_type: VOTER }
I20260812 06:19:54.432675 27653 raft_consensus.cc:385] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:54.432700 27653 raft_consensus.cc:740] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 29ec67c27767414e87731c3830583364, State: Initialized, Role: FOLLOWER
I20260812 06:19:54.432817 27653 consensus_queue.cc:260] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [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: "29ec67c27767414e87731c3830583364" member_type: VOTER }
I20260812 06:19:54.432901 27653 raft_consensus.cc:399] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:54.432930 27653 raft_consensus.cc:493] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:54.432964 27653 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:54.433602 27653 raft_consensus.cc:515] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "29ec67c27767414e87731c3830583364" member_type: VOTER }
I20260812 06:19:54.433713 27653 leader_election.cc:304] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [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: 29ec67c27767414e87731c3830583364; no voters: 
I20260812 06:19:54.433863 27653 leader_election.cc:290] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:54.433980 27657 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:54.434177 27657 raft_consensus.cc:697] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [term 1 LEADER]: Becoming Leader. State: Replica: 29ec67c27767414e87731c3830583364, State: Running, Role: LEADER
I20260812 06:19:54.434310 27653 sys_catalog.cc:565] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:54.434336 27657 consensus_queue.cc:237] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [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: "29ec67c27767414e87731c3830583364" member_type: VOTER }
I20260812 06:19:54.434741 27660 sys_catalog.cc:455] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 29ec67c27767414e87731c3830583364. Latest consensus state: current_term: 1 leader_uuid: "29ec67c27767414e87731c3830583364" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "29ec67c27767414e87731c3830583364" member_type: VOTER } }
I20260812 06:19:54.434726 27658 sys_catalog.cc:455] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "29ec67c27767414e87731c3830583364" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "29ec67c27767414e87731c3830583364" member_type: VOTER } }
I20260812 06:19:54.434859 27660 sys_catalog.cc:458] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:54.434918 27658 sys_catalog.cc:458] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:54.435396 27669 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:54.436115 27669 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:54.436242 27206 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:54.437764 27669 catalog_manager.cc:1383] Generated new cluster ID: bf7d8b82bd5b4fbaa49af8f8138cd114
I20260812 06:19:54.437808 27669 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:54.446606 27669 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:54.447117 27669 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:54.454391 27669 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364: Generated new TSK 0
I20260812 06:19:54.454557 27669 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:54.468555 27206 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:54.470384 27697 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.470520 27206 server_base.cc:1061] running on GCE node
W20260812 06:19:54.470616 27692 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.470572 27691 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.470853 27206 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:54.470898 27206 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.470913 27206 hybrid_clock.cc:648] HybridClock initialized: now 1786515594470913 us; error 0 us; skew 500 ppm
I20260812 06:19:54.471695 27206 webserver.cc:533] Webserver started at http://127.26.145.129:34953/ using document root <none> and password file <none>
I20260812 06:19:54.471829 27206 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:54.471872 27206 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:54.471928 27206 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:54.472271 27206 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/instance:
uuid: "8fbccaa440654497ae106f78aaae3e73"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-42z9"
I20260812 06:19:54.473688 27206 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:54.474560 27704 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.474771 27206 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:54.474838 27206 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root
uuid: "8fbccaa440654497ae106f78aaae3e73"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-42z9"
I20260812 06:19:54.474905 27206 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-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.484488 27206 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:54.484854 27206 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:54.485148 27206 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:54.485671 27206 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:54.485716 27206 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:54.485759 27206 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:54.485788 27206 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:54.489594 27206 rpc_server.cc:307] RPC server started. Bound to: 127.26.145.129:35487
I20260812 06:19:54.489651 27816 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.145.129:35487 every 8 connection(s)
I20260812 06:19:54.493993 27819 heartbeater.cc:344] Connected to a master server at 127.26.145.190:34489
I20260812 06:19:54.494098 27819 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:54.494306 27819 heartbeater.cc:507] Master 127.26.145.190:34489 requested a full tablet report, sending...
I20260812 06:19:54.494949 27591 ts_manager.cc:194] Registered new tserver with Master: 8fbccaa440654497ae106f78aaae3e73 (127.26.145.129:35487)
I20260812 06:19:54.495607 27206 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.00561892s
I20260812 06:19:54.495654 27591 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40796
I20260812 06:19:54.501868 27591 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40800:
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.509668 27752 tablet_service.cc:1511] Processing CreateTablet for tablet 9b50531043da483bbe9c0ccbf1f8932b (DEFAULT_TABLE table=heavy-update-compaction-test [id=e2f600aa21714a69a9366daefe78a221]), partition=
I20260812 06:19:54.509919 27752 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9b50531043da483bbe9c0ccbf1f8932b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:54.511715 27846 tablet_bootstrap.cc:492] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Bootstrap starting.
I20260812 06:19:54.512584 27846 tablet_bootstrap.cc:654] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:54.513581 27846 tablet_bootstrap.cc:492] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: No bootstrap required, opened a new log
I20260812 06:19:54.513657 27846 ts_tablet_manager.cc:1403] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:54.514045 27846 raft_consensus.cc:359] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8fbccaa440654497ae106f78aaae3e73" member_type: VOTER last_known_addr { host: "127.26.145.129" port: 35487 } }
I20260812 06:19:54.514135 27846 raft_consensus.cc:385] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:54.514156 27846 raft_consensus.cc:740] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8fbccaa440654497ae106f78aaae3e73, State: Initialized, Role: FOLLOWER
I20260812 06:19:54.514268 27846 consensus_queue.cc:260] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [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: "8fbccaa440654497ae106f78aaae3e73" member_type: VOTER last_known_addr { host: "127.26.145.129" port: 35487 } }
I20260812 06:19:54.514338 27846 raft_consensus.cc:399] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:54.514360 27846 raft_consensus.cc:493] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:54.514402 27846 raft_consensus.cc:3060] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:54.515169 27846 raft_consensus.cc:515] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8fbccaa440654497ae106f78aaae3e73" member_type: VOTER last_known_addr { host: "127.26.145.129" port: 35487 } }
I20260812 06:19:54.515291 27846 leader_election.cc:304] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [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: 8fbccaa440654497ae106f78aaae3e73; no voters: 
I20260812 06:19:54.515470 27846 leader_election.cc:290] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:54.515571 27849 raft_consensus.cc:2804] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:54.515758 27849 raft_consensus.cc:697] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [term 1 LEADER]: Becoming Leader. State: Replica: 8fbccaa440654497ae106f78aaae3e73, State: Running, Role: LEADER
I20260812 06:19:54.515801 27846 ts_tablet_manager.cc:1434] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:54.515909 27819 heartbeater.cc:499] Master 127.26.145.190:34489 was elected leader, sending a full tablet report...
I20260812 06:19:54.515909 27849 consensus_queue.cc:237] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [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: "8fbccaa440654497ae106f78aaae3e73" member_type: VOTER last_known_addr { host: "127.26.145.129" port: 35487 } }
I20260812 06:19:54.517150 27591 catalog_manager.cc:5719] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8fbccaa440654497ae106f78aaae3e73 (127.26.145.129). New cstate: current_term: 1 leader_uuid: "8fbccaa440654497ae106f78aaae3e73" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8fbccaa440654497ae106f78aaae3e73" member_type: VOTER last_known_addr { host: "127.26.145.129" port: 35487 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:54.569797 27206 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.049s	user 0.018s	sys 0.004s
I20260812 06:19:54.740484 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushMRSOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=23.023690
I20260812 06:19:54.900300 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushMRSOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.160s	user 0.125s	sys 0.031s Metrics: {"bytes_written":12717738,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":826,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42171,"lbm_writes_lt_1ms":867,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":1408,"update_count":1550}
I20260812 06:19:54.900979 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling LogGCOp(9b50531043da483bbe9c0ccbf1f8932b): free 20743880 bytes of WAL
I20260812 06:19:54.901192 27712 log_reader.cc:385] T 9b50531043da483bbe9c0ccbf1f8932b: removed 2 log segments from log reader
I20260812 06:19:54.901252 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000001 (ops 1-6)
I20260812 06:19:54.901364 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000002 (ops 7-11)
I20260812 06:19:54.906602 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: LogGCOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:54.906939 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling UndoDeltaBlockGCOp(9b50531043da483bbe9c0ccbf1f8932b): 20513816 bytes on disk
I20260812 06:19:54.907514 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: UndoDeltaBlockGCOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:19:54.907886 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:54.929232 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.021s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":4278,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:19:54.929725 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:54.944686 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":5548,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:19:54.945182 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:55.105643 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.160s	user 0.101s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815801,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":497,"lbm_read_time_us":10207,"lbm_reads_lt_1ms":569,"lbm_write_time_us":26198,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":328,"threads_started":5,"update_count":2500}
I20260812 06:19:55.106109 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=14.095187
I20260812 06:19:55.154670 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.048s	user 0.038s	sys 0.004s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18000,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.155174 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:55.170148 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5694,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.170617 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:55.316672 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.146s	user 0.122s	sys 0.024s 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":130,"lbm_read_time_us":11278,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27717,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:19:55.317165 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=10.126437
I20260812 06:19:55.343876 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.027s	user 0.012s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":11319,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.344365 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:55.358381 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3469,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.359088 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:55.479166 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.120s	user 0.083s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":256,"lbm_read_time_us":7041,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24705,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:19:55.479700 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=10.126437
I20260812 06:19:55.514765 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.035s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13701,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.515225 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:55.525646 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3847,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.526126 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:55.647274 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.121s	user 0.097s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":338,"lbm_read_time_us":8296,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22245,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:19:55.647854 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=10.126437
I20260812 06:19:55.691993 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.044s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16463,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.692564 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:55.702641 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3813,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.703123 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:55.843950 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.141s	user 0.093s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":10133,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20612,"lbm_writes_lt_1ms":443,"mutex_wait_us":16,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:19:55.844489 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=10.126437
I20260812 06:19:55.888185 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.044s	user 0.028s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14505,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.888749 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:55.898851 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3687,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.899536 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:56.015261 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.115s	user 0.100s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":172,"lbm_read_time_us":7978,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21626,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:56.015784 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=10.126437
I20260812 06:19:56.052305 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.036s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13512,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:56.052814 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:56.062557 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3621,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.062978 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushMRSOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:56.091718 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushMRSOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.029s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1310,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1305,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:56.092341 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling LogGCOp(9b50531043da483bbe9c0ccbf1f8932b): free 121006431 bytes of WAL
I20260812 06:19:56.092566 27712 log_reader.cc:385] T 9b50531043da483bbe9c0ccbf1f8932b: removed 12 log segments from log reader
I20260812 06:19:56.092626 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000003 (ops 12-16)
I20260812 06:19:56.092661 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000004 (ops 17-21)
I20260812 06:19:56.092687 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000005 (ops 22-26)
I20260812 06:19:56.092720 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000006 (ops 27-31)
I20260812 06:19:56.092741 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000007 (ops 32-36)
I20260812 06:19:56.092768 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000008 (ops 37-41)
I20260812 06:19:56.092796 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000009 (ops 42-46)
I20260812 06:19:56.092828 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000010 (ops 47-51)
I20260812 06:19:56.092859 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000011 (ops 52-56)
I20260812 06:19:56.092880 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000012 (ops 57-60)
I20260812 06:19:56.092909 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000013 (ops 61-65)
I20260812 06:19:56.092937 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000014 (ops 66-70)
I20260812 06:19:56.118084 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: LogGCOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.026s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:56.118469 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling UndoDeltaBlockGCOp(9b50531043da483bbe9c0ccbf1f8932b): 472 bytes on disk
I20260812 06:19:56.118892 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: UndoDeltaBlockGCOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:56.119421 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=3.181125
I20260812 06:19:56.132829 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3950,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:56.133236 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:56.142688 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3410,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.143105 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:56.317292 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.174s	user 0.142s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":332,"lbm_read_time_us":13791,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31603,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:19:56.317909 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=14.095187
I20260812 06:19:56.368749 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.051s	user 0.019s	sys 0.029s Metrics: {"bytes_written":16409939,"delete_count":0,"lbm_write_time_us":23147,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.369308 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:56.387720 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6620,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.388159 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:56.538898 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.151s	user 0.110s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815721,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":8651,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28233,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":41344,"update_count":2500}
I20260812 06:19:56.539525 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=14.095187
I20260812 06:19:56.585229 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.046s	user 0.028s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17529,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.585738 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:56.734624 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.149s	user 0.105s	sys 0.037s 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":873,"lbm_read_time_us":9682,"lbm_reads_lt_1ms":463,"lbm_write_time_us":21017,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":103808,"update_count":2000}
I20260812 06:19:56.735100 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=14.095187
I20260812 06:19:56.782657 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.047s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20127,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.783169 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:56.798377 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5653,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.798970 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:56.978873 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.180s	user 0.104s	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":328,"lbm_read_time_us":11099,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25045,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:19:56.981729 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=14.095187
I20260812 06:19:57.023257 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.041s	user 0.026s	sys 0.014s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18536,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.023896 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:57.039417 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.039923 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:57.189052 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.149s	user 0.106s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":517,"lbm_read_time_us":8405,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26740,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:19:57.189594 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=14.095187
I20260812 06:19:57.235049 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.045s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22234,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.235569 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:57.247051 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4371,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.247524 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:57.392911 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.145s	user 0.138s	sys 0.000s 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":198,"lbm_read_time_us":8762,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27936,"lbm_writes_lt_1ms":543,"mutex_wait_us":4,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:19:57.393589 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=14.095187
I20260812 06:19:57.443610 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.050s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20548,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.444164 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:57.459179 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5763,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.459671 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushMRSOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:57.485790 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushMRSOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.026s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1131,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1464,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:57.486503 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling LogGCOp(9b50531043da483bbe9c0ccbf1f8932b): free 136275199 bytes of WAL
I20260812 06:19:57.486740 27712 log_reader.cc:385] T 9b50531043da483bbe9c0ccbf1f8932b: removed 13 log segments from log reader
I20260812 06:19:57.486792 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000015 (ops 71-75)
I20260812 06:19:57.486831 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000016 (ops 76-80)
I20260812 06:19:57.486864 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000017 (ops 81-85)
I20260812 06:19:57.486897 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000018 (ops 86-90)
I20260812 06:19:57.486929 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000019 (ops 91-95)
I20260812 06:19:57.486959 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000020 (ops 96-100)
I20260812 06:19:57.486990 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000021 (ops 101-104)
I20260812 06:19:57.487021 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000022 (ops 105-109)
I20260812 06:19:57.487051 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000023 (ops 110-114)
I20260812 06:19:57.487074 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000024 (ops 115-119)
I20260812 06:19:57.487100 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000025 (ops 120-124)
I20260812 06:19:57.487131 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000026 (ops 125-129)
I20260812 06:19:57.487162 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000027 (ops 130-134)
I20260812 06:19:57.511653 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: LogGCOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.025s	user 0.004s	sys 0.019s Metrics: {}
I20260812 06:19:57.512161 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling UndoDeltaBlockGCOp(9b50531043da483bbe9c0ccbf1f8932b): 483 bytes on disk
I20260812 06:19:57.512755 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: UndoDeltaBlockGCOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:19:57.513307 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=4.173312
I20260812 06:19:57.531492 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":5866704,"delete_count":0,"lbm_write_time_us":7191,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:19:57.531903 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.196750
I20260812 06:19:57.539610 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.008s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2338579,"delete_count":0,"lbm_write_time_us":2425,"lbm_writes_lt_1ms":60,"reinsert_count":0,"update_count":285}
I20260812 06:19:57.540175 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:57.766774 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.226s	user 0.176s	sys 0.038s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020706,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":129,"lbm_read_time_us":13738,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37379,"lbm_writes_lt_1ms":743,"mutex_wait_us":47,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":68,"threads_started":1,"update_count":3500}
I20260812 06:19:57.767334 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=18.063937
I20260812 06:19:57.834467 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.067s	user 0.037s	sys 0.028s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26068,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:57.834977 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:57.845139 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3777,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.845726 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:58.028519 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.183s	user 0.122s	sys 0.060s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1034,"lbm_read_time_us":14026,"lbm_reads_lt_1ms":672,"lbm_write_time_us":28236,"lbm_writes_lt_1ms":643,"mutex_wait_us":253,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":3000}
I20260812 06:19:58.029012 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=14.095187
I20260812 06:19:58.070233 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.041s	user 0.033s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18041,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.070779 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:58.081984 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4442,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.082469 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:58.245078 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.162s	user 0.106s	sys 0.052s 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":691,"lbm_read_time_us":12016,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25781,"lbm_writes_lt_1ms":543,"mutex_wait_us":278,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:19:58.245587 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=14.095187
I20260812 06:19:58.303418 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.058s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18724,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.303982 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:58.318706 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5697,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.319178 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:58.484519 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.165s	user 0.118s	sys 0.040s 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":162,"lbm_read_time_us":11370,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26413,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:19:58.485066 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=14.095187
I20260812 06:19:58.541198 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.056s	user 0.033s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18971,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.541710 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:58.551225 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3634,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.551591 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:58.712879 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.161s	user 0.130s	sys 0.029s 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":752,"lbm_read_time_us":10687,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25494,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:58.713697 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=11.118625
I20260812 06:19:58.745539 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.032s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":12970,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1550}
I20260812 06:19:58.746142 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:58.759765 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5175,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:58.760367 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushMRSOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:58.783710 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushMRSOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.023s	user 0.022s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1180,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1329,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:58.784459 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling LogGCOp(9b50531043da483bbe9c0ccbf1f8932b): free 112692615 bytes of WAL
I20260812 06:19:58.784677 27712 log_reader.cc:385] T 9b50531043da483bbe9c0ccbf1f8932b: removed 11 log segments from log reader
I20260812 06:19:58.784726 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000028 (ops 135-139)
I20260812 06:19:58.784763 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000029 (ops 140-144)
I20260812 06:19:58.784795 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000030 (ops 145-149)
I20260812 06:19:58.784827 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000031 (ops 150-154)
I20260812 06:19:58.784858 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000032 (ops 155-159)
I20260812 06:19:58.784889 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000033 (ops 160-164)
I20260812 06:19:58.784920 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000034 (ops 165-169)
I20260812 06:19:58.784951 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000035 (ops 170-174)
I20260812 06:19:58.784981 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000036 (ops 175-179)
I20260812 06:19:58.785013 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000037 (ops 180-184)
I20260812 06:19:58.785043 27712 log.cc:1079] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: Deleting log segment in path: /tmp/dist-test-taskGqlX9M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515589380697-27206-0/minicluster-data/ts-0-root/wals/9b50531043da483bbe9c0ccbf1f8932b/wal-000000038 (ops 185-189)
I20260812 06:19:58.807690 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: LogGCOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:58.808167 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling UndoDeltaBlockGCOp(9b50531043da483bbe9c0ccbf1f8932b): 447 bytes on disk
I20260812 06:19:58.808599 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: UndoDeltaBlockGCOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:58.809268 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=3.181125
I20260812 06:19:58.828272 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.019s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4282,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:58.828665 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:58.837639 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3369,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:58.838037 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:59.013407 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.175s	user 0.123s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":284,"lbm_read_time_us":11992,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29129,"lbm_writes_lt_1ms":643,"mutex_wait_us":42,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11008,"thread_start_us":70,"threads_started":1,"update_count":3000}
I20260812 06:19:59.014005 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=14.095187
I20260812 06:19:59.048763 27206 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.479s	user 1.751s	sys 0.118s
I20260812 06:19:59.060752 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.047s	user 0.016s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16620,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.061385 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=2.188937
I20260812 06:19:59.076587 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: FlushDeltaMemStoresOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6140,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":500}
I20260812 06:19:59.077077 27823 maintenance_manager.cc:419] P 8fbccaa440654497ae106f78aaae3e73: Scheduling MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b): perf score=1.000000
I20260812 06:19:59.136196 27206 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.087s	user 0.001s	sys 0.000s
I20260812 06:19:59.136662 27206 tablet_server.cc:179] TabletServer@127.26.145.129:0 shutting down...
I20260812 06:19:59.203835 27712 maintenance_manager.cc:643] P 8fbccaa440654497ae106f78aaae3e73: MajorDeltaCompactionOp(9b50531043da483bbe9c0ccbf1f8932b) complete. Timing: real 0.127s	user 0.090s	sys 0.036s Metrics: {"cfile_cache_hit":263,"cfile_cache_hit_bytes":10750250,"cfile_cache_miss":269,"cfile_cache_miss_bytes":14065434,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":589,"lbm_read_time_us":8605,"lbm_reads_lt_1ms":301,"lbm_write_time_us":22346,"lbm_writes_lt_1ms":543,"mutex_wait_us":247,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":69888,"update_count":2500}
I20260812 06:19:59.204398 27206 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:59.204627 27206 tablet_replica.cc:333] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73: stopping tablet replica
I20260812 06:19:59.204735 27206 raft_consensus.cc:2243] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.204886 27206 raft_consensus.cc:2272] T 9b50531043da483bbe9c0ccbf1f8932b P 8fbccaa440654497ae106f78aaae3e73 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.219569 27206 tablet_server.cc:196] TabletServer@127.26.145.129:0 shutdown complete.
I20260812 06:19:59.247718 27206 master.cc:562] Master@127.26.145.190:34489 shutting down...
I20260812 06:19:59.250614 27206 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.250777 27206 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.250842 27206 tablet_replica.cc:333] T 00000000000000000000000000000000 P 29ec67c27767414e87731c3830583364: stopping tablet replica
I20260812 06:19:59.262782 27206 master.cc:584] Master@127.26.145.190:34489 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4930 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9941 ms total)

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