[==========] 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:17:12.020766  5874 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.188.190:33793
I20260812 06:17:12.022085  5874 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:17:12.022733  5874 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:12.029239  5883 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:17:12.029285  5891 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:17:12.029363  5874 server_base.cc:1061] running on GCE node
W20260812 06:17:12.029575  5887 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:17:12.030118  5874 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:12.030251  5874 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:17:12.030296  5874 hybrid_clock.cc:648] HybridClock initialized: now 1786515432030294 us; error 0 us; skew 500 ppm
I20260812 06:17:12.031944  5874 webserver.cc:533] Webserver started at http://127.5.188.190:40387/ using document root <none> and password file <none>
I20260812 06:17:12.032501  5874 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:12.032588  5874 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:12.032913  5874 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:12.034541  5874 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/master-0-root/instance:
uuid: "0399a6a3ab8d4337bc9aecd83800fede"
format_stamp: "Formatted at 2026-08-12 06:17:12 on dist-test-slave-zh2d"
I20260812 06:17:12.037973  5874 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:17:12.039912  5900 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:17:12.040903  5874 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:12.041052  5874 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/master-0-root
uuid: "0399a6a3ab8d4337bc9aecd83800fede"
format_stamp: "Formatted at 2026-08-12 06:17:12 on dist-test-slave-zh2d"
I20260812 06:17:12.041154  5874 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-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:17:12.071915  5874 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:12.072691  5874 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:17:12.072922  5874 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:12.081362  5874 rpc_server.cc:307] RPC server started. Bound to: 127.5.188.190:33793
I20260812 06:17:12.081362  5981 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.188.190:33793 every 8 connection(s)
I20260812 06:17:12.083977  5982 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:17:12.089709  5982 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede: Bootstrap starting.
I20260812 06:17:12.092145  5982 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:12.093072  5982 log.cc:826] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:12.094796  5982 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede: No bootstrap required, opened a new log
I20260812 06:17:12.097570  5982 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0399a6a3ab8d4337bc9aecd83800fede" member_type: VOTER }
I20260812 06:17:12.097738  5982 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:12.097791  5982 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0399a6a3ab8d4337bc9aecd83800fede, State: Initialized, Role: FOLLOWER
I20260812 06:17:12.098459  5982 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [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: "0399a6a3ab8d4337bc9aecd83800fede" member_type: VOTER }
I20260812 06:17:12.098610  5982 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:12.098660  5982 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:12.098752  5982 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:12.099507  5982 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0399a6a3ab8d4337bc9aecd83800fede" member_type: VOTER }
I20260812 06:17:12.099910  5982 leader_election.cc:304] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [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: 0399a6a3ab8d4337bc9aecd83800fede; no voters: 
I20260812 06:17:12.100193  5982 leader_election.cc:290] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:12.100317  5987 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:12.100625  5987 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [term 1 LEADER]: Becoming Leader. State: Replica: 0399a6a3ab8d4337bc9aecd83800fede, State: Running, Role: LEADER
I20260812 06:17:12.101107  5987 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [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: "0399a6a3ab8d4337bc9aecd83800fede" member_type: VOTER }
I20260812 06:17:12.101361  5982 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:12.103169  5988 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0399a6a3ab8d4337bc9aecd83800fede" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0399a6a3ab8d4337bc9aecd83800fede" member_type: VOTER } }
I20260812 06:17:12.103209  5989 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0399a6a3ab8d4337bc9aecd83800fede. Latest consensus state: current_term: 1 leader_uuid: "0399a6a3ab8d4337bc9aecd83800fede" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0399a6a3ab8d4337bc9aecd83800fede" member_type: VOTER } }
I20260812 06:17:12.103339  5988 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:12.103730  6008 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:12.103339  5989 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:12.103906  5874 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:12.106169  6008 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:12.111155  6008 catalog_manager.cc:1383] Generated new cluster ID: ebd08aaab2534898a56de14122813609
I20260812 06:17:12.111222  6008 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:12.122570  6008 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:12.123728  6008 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:12.143177  6008 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede: Generated new TSK 0
I20260812 06:17:12.144073  6008 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:12.168802  5874 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:12.172194  6019 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:17:12.172274  6018 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:17:12.172360  6025 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:17:12.172678  5874 server_base.cc:1061] running on GCE node
I20260812 06:17:12.172914  5874 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:12.172966  5874 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:17:12.172982  5874 hybrid_clock.cc:648] HybridClock initialized: now 1786515432172983 us; error 0 us; skew 500 ppm
I20260812 06:17:12.174181  5874 webserver.cc:533] Webserver started at http://127.5.188.129:40433/ using document root <none> and password file <none>
I20260812 06:17:12.174372  5874 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:12.174423  5874 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:12.174511  5874 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:12.174933  5874 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/instance:
uuid: "9e5ec7ff525f4fd9af666e002e91b3cc"
format_stamp: "Formatted at 2026-08-12 06:17:12 on dist-test-slave-zh2d"
I20260812 06:17:12.176543  5874 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:12.177702  6033 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:17:12.177958  5874 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:12.178036  5874 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root
uuid: "9e5ec7ff525f4fd9af666e002e91b3cc"
format_stamp: "Formatted at 2026-08-12 06:17:12 on dist-test-slave-zh2d"
I20260812 06:17:12.178130  5874 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-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:17:12.208256  5874 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:12.208729  5874 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:12.209322  5874 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:12.210278  5874 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:12.210340  5874 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:12.210414  5874 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:12.210453  5874 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:12.217849  5874 rpc_server.cc:307] RPC server started. Bound to: 127.5.188.129:45997
I20260812 06:17:12.217885  6138 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.188.129:45997 every 8 connection(s)
I20260812 06:17:12.228440  6139 heartbeater.cc:344] Connected to a master server at 127.5.188.190:33793
I20260812 06:17:12.228751  6139 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:12.229363  6139 heartbeater.cc:507] Master 127.5.188.190:33793 requested a full tablet report, sending...
I20260812 06:17:12.231055  5933 ts_manager.cc:194] Registered new tserver with Master: 9e5ec7ff525f4fd9af666e002e91b3cc (127.5.188.129:45997)
I20260812 06:17:12.231539  5874 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013021211s
I20260812 06:17:12.232406  5933 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50268
I20260812 06:17:12.241961  5933 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50284:
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:17:12.257262  6081 tablet_service.cc:1511] Processing CreateTablet for tablet 4142dfa9a2644a5fa0bc65c1ced1dff8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=3ef3fb24a7b04746a8778d2d16ad1730]), partition=
I20260812 06:17:12.257750  6081 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4142dfa9a2644a5fa0bc65c1ced1dff8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:12.260368  6158 tablet_bootstrap.cc:492] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Bootstrap starting.
I20260812 06:17:12.261649  6158 tablet_bootstrap.cc:654] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:12.263084  6158 tablet_bootstrap.cc:492] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: No bootstrap required, opened a new log
I20260812 06:17:12.263207  6158 ts_tablet_manager.cc:1403] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:12.263782  6158 raft_consensus.cc:359] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9e5ec7ff525f4fd9af666e002e91b3cc" member_type: VOTER last_known_addr { host: "127.5.188.129" port: 45997 } }
I20260812 06:17:12.263937  6158 raft_consensus.cc:385] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:12.264045  6158 raft_consensus.cc:740] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9e5ec7ff525f4fd9af666e002e91b3cc, State: Initialized, Role: FOLLOWER
I20260812 06:17:12.264271  6158 consensus_queue.cc:260] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [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: "9e5ec7ff525f4fd9af666e002e91b3cc" member_type: VOTER last_known_addr { host: "127.5.188.129" port: 45997 } }
I20260812 06:17:12.264393  6158 raft_consensus.cc:399] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:12.264485  6158 raft_consensus.cc:493] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:12.264599  6158 raft_consensus.cc:3060] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:12.265652  6158 raft_consensus.cc:515] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9e5ec7ff525f4fd9af666e002e91b3cc" member_type: VOTER last_known_addr { host: "127.5.188.129" port: 45997 } }
I20260812 06:17:12.265811  6158 leader_election.cc:304] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [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: 9e5ec7ff525f4fd9af666e002e91b3cc; no voters: 
I20260812 06:17:12.266040  6158 leader_election.cc:290] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:12.266215  6164 raft_consensus.cc:2804] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:12.266467  6158 ts_tablet_manager.cc:1434] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:12.266768  6139 heartbeater.cc:499] Master 127.5.188.190:33793 was elected leader, sending a full tablet report...
I20260812 06:17:12.266513  6164 raft_consensus.cc:697] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [term 1 LEADER]: Becoming Leader. State: Replica: 9e5ec7ff525f4fd9af666e002e91b3cc, State: Running, Role: LEADER
I20260812 06:17:12.267247  6164 consensus_queue.cc:237] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [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: "9e5ec7ff525f4fd9af666e002e91b3cc" member_type: VOTER last_known_addr { host: "127.5.188.129" port: 45997 } }
I20260812 06:17:12.270191  5933 catalog_manager.cc:5719] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc reported cstate change: term changed from 0 to 1, leader changed from <none> to 9e5ec7ff525f4fd9af666e002e91b3cc (127.5.188.129). New cstate: current_term: 1 leader_uuid: "9e5ec7ff525f4fd9af666e002e91b3cc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9e5ec7ff525f4fd9af666e002e91b3cc" member_type: VOTER last_known_addr { host: "127.5.188.129" port: 45997 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:12.335191  5874 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.021s	sys 0.004s
I20260812 06:17:12.469085  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushMRSOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=15.086190
I20260812 06:17:12.641611  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushMRSOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.172s	user 0.129s	sys 0.041s Metrics: {"bytes_written":12840810,"cfile_init":1,"compiler_manager_pool.queue_time_us":264,"delete_count":0,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":855,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43723,"lbm_writes_lt_1ms":680,"mutex_wait_us":1110,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":167296,"thread_start_us":183,"threads_started":1,"update_count":1565}
I20260812 06:17:12.642946  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling LogGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8): free 20743880 bytes of WAL
I20260812 06:17:12.643272  6042 log_reader.cc:385] T 4142dfa9a2644a5fa0bc65c1ced1dff8: removed 2 log segments from log reader
I20260812 06:17:12.643347  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000001 (ops 1-6)
I20260812 06:17:12.643417  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000002 (ops 7-11)
I20260812 06:17:12.649307  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: LogGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:17:12.649690  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:12.666683  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.017s	user 0.008s	sys 0.006s Metrics: {"bytes_written":3569334,"delete_count":0,"lbm_write_time_us":5962,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:17:12.667145  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling UndoDeltaBlockGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8): 12719213 bytes on disk
I20260812 06:17:12.667750  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: UndoDeltaBlockGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8) 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:17:12.668181  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:12.682197  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.014s	user 0.001s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5515,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.682837  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:12.854815  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.172s	user 0.117s	sys 0.054s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364549,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":684,"lbm_read_time_us":13998,"lbm_reads_lt_1ms":559,"lbm_write_time_us":32725,"lbm_writes_lt_1ms":533,"mutex_wait_us":32,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":337,"threads_started":5,"update_count":2450}
I20260812 06:17:12.855414  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=10.126437
I20260812 06:17:12.900954  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.045s	user 0.012s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16449,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.901561  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:12.920192  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.018s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6950,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.920682  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:13.062995  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.142s	user 0.097s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1233,"lbm_read_time_us":10595,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28774,"lbm_writes_lt_1ms":443,"mutex_wait_us":352,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:17:13.063764  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=10.126437
I20260812 06:17:13.110829  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.046s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17105,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:17:13.111351  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:13.122673  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4355,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.123157  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:13.257493  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.134s	user 0.101s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1602,"lbm_read_time_us":10831,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25280,"lbm_writes_lt_1ms":443,"mutex_wait_us":388,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:17:13.258181  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=10.126437
I20260812 06:17:13.303431  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.045s	user 0.009s	sys 0.033s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15088,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.304045  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:13.321363  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6439,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.321908  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:13.478240  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.156s	user 0.102s	sys 0.054s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":279,"lbm_read_time_us":13713,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26662,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:13.478909  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=10.126437
I20260812 06:17:13.524199  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.045s	user 0.021s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16695,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.524771  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:13.541354  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6138,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.541903  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:13.681886  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.140s	user 0.110s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1149,"lbm_read_time_us":10318,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26986,"lbm_writes_lt_1ms":443,"mutex_wait_us":347,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:17:13.687723  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=10.126437
I20260812 06:17:13.724169  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.036s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16044,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.724702  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:13.741544  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.017s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6561,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.742337  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:13.877750  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.135s	user 0.115s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":583,"lbm_read_time_us":11467,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25441,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:17:13.879065  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=10.126437
I20260812 06:17:13.931396  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.052s	user 0.014s	sys 0.035s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20044,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.932268  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:13.946946  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5377,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.947525  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushMRSOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:13.974041  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushMRSOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.026s	user 0.017s	sys 0.008s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1331,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1979,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:13.974848  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling LogGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8): free 112692374 bytes of WAL
I20260812 06:17:13.975082  6042 log_reader.cc:385] T 4142dfa9a2644a5fa0bc65c1ced1dff8: removed 11 log segments from log reader
I20260812 06:17:13.975126  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000003 (ops 12-16)
I20260812 06:17:13.975157  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000004 (ops 17-21)
I20260812 06:17:13.975217  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000005 (ops 22-26)
I20260812 06:17:13.975272  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000006 (ops 27-31)
I20260812 06:17:13.975311  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000007 (ops 32-36)
I20260812 06:17:13.975353  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000008 (ops 37-41)
I20260812 06:17:13.975394  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000009 (ops 42-46)
I20260812 06:17:13.975433  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000010 (ops 47-51)
I20260812 06:17:13.975471  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000011 (ops 52-56)
I20260812 06:17:13.975509  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000012 (ops 57-61)
I20260812 06:17:13.975558  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000013 (ops 62-66)
I20260812 06:17:14.002614  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: LogGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:14.003132  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling UndoDeltaBlockGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8): 463 bytes on disk
I20260812 06:17:14.003844  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: UndoDeltaBlockGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":141,"lbm_reads_lt_1ms":4}
I20260812 06:17:14.004724  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=3.181125
I20260812 06:17:14.022496  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.018s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5799,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:14.022946  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:14.033131  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.033573  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:14.258553  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.225s	user 0.153s	sys 0.071s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":622,"lbm_read_time_us":16547,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39278,"lbm_writes_lt_1ms":643,"mutex_wait_us":313,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12416,"thread_start_us":108,"threads_started":1,"update_count":3000}
I20260812 06:17:14.259446  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=14.095187
I20260812 06:17:14.320796  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.061s	user 0.036s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24755,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:17:14.321394  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:14.332130  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.332677  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:14.518918  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.186s	user 0.107s	sys 0.078s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":799,"lbm_read_time_us":13125,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32960,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:17:14.519577  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=14.095187
I20260812 06:17:14.580386  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.061s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21851,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:14.581004  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:14.599053  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.018s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6953,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.599799  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:14.831462  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.231s	user 0.159s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2208,"lbm_read_time_us":13574,"lbm_reads_lt_1ms":572,"lbm_write_time_us":39458,"lbm_writes_lt_1ms":543,"mutex_wait_us":1196,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:14.832058  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=14.095187
I20260812 06:17:14.909678  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.077s	user 0.040s	sys 0.032s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26929,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.910380  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:14.930052  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.019s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7587,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.930646  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:15.162462  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.232s	user 0.136s	sys 0.093s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":747,"lbm_read_time_us":22204,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":38515,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:17:15.163139  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=14.095187
I20260812 06:17:15.216807  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.053s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24337,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.217434  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:15.237874  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.020s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.238372  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:15.425652  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.187s	user 0.127s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":783,"lbm_read_time_us":12460,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31924,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:15.426517  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=14.095187
I20260812 06:17:15.482641  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.056s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26066,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.483429  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:15.499030  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5692,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.499549  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:15.700632  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.201s	user 0.110s	sys 0.073s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":346,"lbm_read_time_us":12663,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29375,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24320,"update_count":2500}
I20260812 06:17:15.701330  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=14.095187
I20260812 06:17:15.760542  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.059s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24531,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.761114  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:15.773303  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4285,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.773847  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushMRSOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:15.806123  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushMRSOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.032s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1565,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1603,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:15.806857  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling LogGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8): free 133024372 bytes of WAL
I20260812 06:17:15.807096  6042 log_reader.cc:385] T 4142dfa9a2644a5fa0bc65c1ced1dff8: removed 13 log segments from log reader
I20260812 06:17:15.807142  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000014 (ops 67-71)
I20260812 06:17:15.807190  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000015 (ops 72-76)
I20260812 06:17:15.807236  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000016 (ops 77-81)
I20260812 06:17:15.807266  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000017 (ops 82-86)
I20260812 06:17:15.807305  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000018 (ops 87-91)
I20260812 06:17:15.807350  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000019 (ops 92-96)
I20260812 06:17:15.807396  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000020 (ops 97-101)
I20260812 06:17:15.807437  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000021 (ops 102-106)
I20260812 06:17:15.807477  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000022 (ops 107-111)
I20260812 06:17:15.807519  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000023 (ops 112-116)
I20260812 06:17:15.807559  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000024 (ops 117-120)
I20260812 06:17:15.807600  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000025 (ops 121-125)
I20260812 06:17:15.807639  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000026 (ops 126-130)
I20260812 06:17:15.839875  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: LogGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:15.840333  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=3.181125
I20260812 06:17:15.862790  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.022s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":7558,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:15.863273  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:15.873605  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:15.874066  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling UndoDeltaBlockGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8): 482 bytes on disk
I20260812 06:17:15.874497  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: UndoDeltaBlockGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:15.875018  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:16.133309  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.258s	user 0.156s	sys 0.099s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979743,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":635,"lbm_read_time_us":20246,"lbm_reads_lt_1ms":774,"lbm_write_time_us":43698,"lbm_writes_lt_1ms":743,"mutex_wait_us":27,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":88704,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:17:16.134467  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=18.063937
I20260812 06:17:16.207732  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.073s	user 0.039s	sys 0.025s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":30585,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:16.208390  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:16.220470  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4872,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.221050  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:16.440092  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.219s	user 0.141s	sys 0.077s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":396,"lbm_read_time_us":16357,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36956,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:16.440919  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=14.095187
I20260812 06:17:16.492208  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.051s	user 0.027s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25102,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.492962  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:16.506597  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.507266  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:16.689708  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.182s	user 0.125s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":478,"lbm_read_time_us":13839,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31350,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:17:16.690197  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=14.095187
I20260812 06:17:16.749475  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.059s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22381,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:16.750116  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:16.767153  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.017s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.767915  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:16.952629  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.184s	user 0.112s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":290,"lbm_read_time_us":13715,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31681,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:17:16.953364  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=14.095187
I20260812 06:17:17.027350  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.074s	user 0.037s	sys 0.034s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":28965,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.027966  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:17.039255  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.039757  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:17.226414  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.186s	user 0.122s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":111,"lbm_read_time_us":13954,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31305,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2500}
I20260812 06:17:17.227133  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=11.118625
I20260812 06:17:17.272014  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.045s	user 0.015s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18549,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:17.272718  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:17.301429  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.029s	user 0.012s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4444,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.301947  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:17.312129  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3959,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.312629  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushMRSOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:17.347368  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushMRSOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.035s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1554,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1491,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:17.348121  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:17.529974  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.182s	user 0.111s	sys 0.069s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":185,"lbm_read_time_us":14376,"lbm_reads_lt_1ms":565,"lbm_write_time_us":30860,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:17:17.530617  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling LogGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8): free 120100577 bytes of WAL
I20260812 06:17:17.530855  6042 log_reader.cc:385] T 4142dfa9a2644a5fa0bc65c1ced1dff8: removed 12 log segments from log reader
I20260812 06:17:17.530936  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000027 (ops 131-134)
I20260812 06:17:17.531050  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000028 (ops 135-139)
I20260812 06:17:17.531092  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000029 (ops 140-144)
I20260812 06:17:17.531121  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000030 (ops 145-148)
I20260812 06:17:17.531177  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000031 (ops 149-153)
I20260812 06:17:17.531210  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000032 (ops 154-158)
I20260812 06:17:17.531234  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000033 (ops 159-163)
I20260812 06:17:17.531294  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000034 (ops 164-168)
I20260812 06:17:17.531335  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000035 (ops 169-172)
I20260812 06:17:17.531359  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000036 (ops 173-177)
I20260812 06:17:17.531383  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000037 (ops 178-182)
I20260812 06:17:17.531404  6042 log.cc:1079] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/4142dfa9a2644a5fa0bc65c1ced1dff8/wal-000000038 (ops 183-187)
I20260812 06:17:17.565140  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: LogGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.034s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:17:17.566030  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling UndoDeltaBlockGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8): 448 bytes on disk
I20260812 06:17:17.566803  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: UndoDeltaBlockGCOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:17:17.567641  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=14.095187
I20260812 06:17:17.610565  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.043s	user 0.016s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20005,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.611272  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=2.188937
I20260812 06:17:17.637022  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.026s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4905,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.637763  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=1.000000
I20260812 06:17:17.752293  5874 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.417s	user 1.866s	sys 0.237s
I20260812 06:17:17.804452  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: MajorDeltaCompactionOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.166s	user 0.116s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":213,"lbm_read_time_us":13848,"lbm_reads_lt_1ms":560,"lbm_write_time_us":28187,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:17.805262  6140 maintenance_manager.cc:419] P 9e5ec7ff525f4fd9af666e002e91b3cc: Scheduling FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8): perf score=10.126437
I20260812 06:17:17.824430  5874 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.071s	user 0.003s	sys 0.000s
I20260812 06:17:17.825345  5874 tablet_server.cc:179] TabletServer@127.5.188.129:0 shutting down...
I20260812 06:17:17.842924  6042 maintenance_manager.cc:643] P 9e5ec7ff525f4fd9af666e002e91b3cc: FlushDeltaMemStoresOp(4142dfa9a2644a5fa0bc65c1ced1dff8) complete. Timing: real 0.037s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16672,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.843508  5874 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:17.843928  5874 tablet_replica.cc:333] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc: stopping tablet replica
I20260812 06:17:17.844228  5874 raft_consensus.cc:2243] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:17.844542  5874 raft_consensus.cc:2272] T 4142dfa9a2644a5fa0bc65c1ced1dff8 P 9e5ec7ff525f4fd9af666e002e91b3cc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:17.850790  5874 tablet_server.cc:196] TabletServer@127.5.188.129:0 shutdown complete.
I20260812 06:17:17.858071  5874 master.cc:562] Master@127.5.188.190:33793 shutting down...
I20260812 06:17:17.862052  5874 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:17.862250  5874 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:17.862347  5874 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0399a6a3ab8d4337bc9aecd83800fede: stopping tablet replica
I20260812 06:17:17.874758  5874 master.cc:584] Master@127.5.188.190:33793 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5967 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:18.003297  5874 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.188.190:44301
I20260812 06:17:18.003787  5874 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:18.006089  6189 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:17:18.006108  6191 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:17:18.006155  6188 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:17:18.006150  5874 server_base.cc:1061] running on GCE node
I20260812 06:17:18.006539  5874 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:18.006584  5874 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:17:18.006600  5874 hybrid_clock.cc:648] HybridClock initialized: now 1786515438006601 us; error 0 us; skew 500 ppm
I20260812 06:17:18.007468  5874 webserver.cc:533] Webserver started at http://127.5.188.190:43565/ using document root <none> and password file <none>
I20260812 06:17:18.007613  5874 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:18.007684  5874 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:18.007761  5874 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:18.008147  5874 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/master-0-root/instance:
uuid: "f8824dcb8a474d7c84bf129936df04f6"
format_stamp: "Formatted at 2026-08-12 06:17:18 on dist-test-slave-zh2d"
I20260812 06:17:18.009856  5874 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:18.010823  6196 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:17:18.011089  5874 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:18.011185  5874 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/master-0-root
uuid: "f8824dcb8a474d7c84bf129936df04f6"
format_stamp: "Formatted at 2026-08-12 06:17:18 on dist-test-slave-zh2d"
I20260812 06:17:18.011281  5874 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-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:17:18.041347  5874 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:18.041810  5874 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:18.047000  5874 rpc_server.cc:307] RPC server started. Bound to: 127.5.188.190:44301
I20260812 06:17:18.051163  6271 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.188.190:44301 every 8 connection(s)
I20260812 06:17:18.051671  6274 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:17:18.053671  6274 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6: Bootstrap starting.
I20260812 06:17:18.054459  6274 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:18.055553  6274 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6: No bootstrap required, opened a new log
I20260812 06:17:18.055962  6274 raft_consensus.cc:359] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f8824dcb8a474d7c84bf129936df04f6" member_type: VOTER }
I20260812 06:17:18.056072  6274 raft_consensus.cc:385] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:18.056125  6274 raft_consensus.cc:740] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f8824dcb8a474d7c84bf129936df04f6, State: Initialized, Role: FOLLOWER
I20260812 06:17:18.056289  6274 consensus_queue.cc:260] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [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: "f8824dcb8a474d7c84bf129936df04f6" member_type: VOTER }
I20260812 06:17:18.056383  6274 raft_consensus.cc:399] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:18.056434  6274 raft_consensus.cc:493] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:18.056493  6274 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:18.057199  6274 raft_consensus.cc:515] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f8824dcb8a474d7c84bf129936df04f6" member_type: VOTER }
I20260812 06:17:18.057355  6274 leader_election.cc:304] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [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: f8824dcb8a474d7c84bf129936df04f6; no voters: 
I20260812 06:17:18.057577  6274 leader_election.cc:290] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:18.057744  6277 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:18.058034  6277 raft_consensus.cc:697] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [term 1 LEADER]: Becoming Leader. State: Replica: f8824dcb8a474d7c84bf129936df04f6, State: Running, Role: LEADER
I20260812 06:17:18.058259  6277 consensus_queue.cc:237] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [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: "f8824dcb8a474d7c84bf129936df04f6" member_type: VOTER }
I20260812 06:17:18.058055  6274 sys_catalog.cc:565] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:18.058816  6281 sys_catalog.cc:455] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader f8824dcb8a474d7c84bf129936df04f6. Latest consensus state: current_term: 1 leader_uuid: "f8824dcb8a474d7c84bf129936df04f6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f8824dcb8a474d7c84bf129936df04f6" member_type: VOTER } }
I20260812 06:17:18.058954  6281 sys_catalog.cc:458] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:18.059046  6279 sys_catalog.cc:455] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f8824dcb8a474d7c84bf129936df04f6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f8824dcb8a474d7c84bf129936df04f6" member_type: VOTER } }
I20260812 06:17:18.059155  6279 sys_catalog.cc:458] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:18.059521  6285 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:18.060629  6285 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:18.060881  5874 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:18.062626  6285 catalog_manager.cc:1383] Generated new cluster ID: 95f45dcbefd242809fc29028360191c5
I20260812 06:17:18.062687  6285 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:18.075033  6285 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:18.075603  6285 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:18.083570  6285 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6: Generated new TSK 0
I20260812 06:17:18.083750  6285 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:18.093361  5874 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:18.095577  6308 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:17:18.095548  6313 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:17:18.095717  5874 server_base.cc:1061] running on GCE node
W20260812 06:17:18.095726  6307 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:17:18.096055  5874 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:18.096100  5874 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:17:18.096117  5874 hybrid_clock.cc:648] HybridClock initialized: now 1786515438096116 us; error 0 us; skew 500 ppm
I20260812 06:17:18.096990  5874 webserver.cc:533] Webserver started at http://127.5.188.129:37471/ using document root <none> and password file <none>
I20260812 06:17:18.097137  5874 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:18.097183  5874 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:18.097237  5874 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:18.097621  5874 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/instance:
uuid: "e8916e251d33470982668eff8d3fdb33"
format_stamp: "Formatted at 2026-08-12 06:17:18 on dist-test-slave-zh2d"
I20260812 06:17:18.099074  5874 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:18.099975  6319 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:17:18.100209  5874 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:18.100272  5874 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root
uuid: "e8916e251d33470982668eff8d3fdb33"
format_stamp: "Formatted at 2026-08-12 06:17:18 on dist-test-slave-zh2d"
I20260812 06:17:18.100323  5874 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-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:17:18.145553  5874 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:18.145955  5874 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:18.146270  5874 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:18.146831  5874 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:18.146876  5874 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:18.146938  5874 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:18.146976  5874 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:18.151397  5874 rpc_server.cc:307] RPC server started. Bound to: 127.5.188.129:32951
I20260812 06:17:18.152652  6417 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.188.129:32951 every 8 connection(s)
I20260812 06:17:18.157109  6418 heartbeater.cc:344] Connected to a master server at 127.5.188.190:44301
I20260812 06:17:18.157222  6418 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:18.157467  6418 heartbeater.cc:507] Master 127.5.188.190:44301 requested a full tablet report, sending...
I20260812 06:17:18.158159  6221 ts_manager.cc:194] Registered new tserver with Master: e8916e251d33470982668eff8d3fdb33 (127.5.188.129:32951)
I20260812 06:17:18.158821  6221 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52114
I20260812 06:17:18.159024  5874 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.006682744s
I20260812 06:17:18.165768  6221 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52116:
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:17:18.174959  6362 tablet_service.cc:1511] Processing CreateTablet for tablet 09a566457c994f3eb83130bf55caa88b (DEFAULT_TABLE table=heavy-update-compaction-test [id=376e5233a80c463d8cbad5fcc50a3dd3]), partition=
I20260812 06:17:18.175218  6362 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 09a566457c994f3eb83130bf55caa88b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:18.177415  6439 tablet_bootstrap.cc:492] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Bootstrap starting.
I20260812 06:17:18.178261  6439 tablet_bootstrap.cc:654] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:18.179311  6439 tablet_bootstrap.cc:492] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: No bootstrap required, opened a new log
I20260812 06:17:18.179407  6439 ts_tablet_manager.cc:1403] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:18.179960  6439 raft_consensus.cc:359] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e8916e251d33470982668eff8d3fdb33" member_type: VOTER last_known_addr { host: "127.5.188.129" port: 32951 } }
I20260812 06:17:18.180068  6439 raft_consensus.cc:385] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:18.180110  6439 raft_consensus.cc:740] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e8916e251d33470982668eff8d3fdb33, State: Initialized, Role: FOLLOWER
I20260812 06:17:18.180295  6439 consensus_queue.cc:260] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [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: "e8916e251d33470982668eff8d3fdb33" member_type: VOTER last_known_addr { host: "127.5.188.129" port: 32951 } }
I20260812 06:17:18.180390  6439 raft_consensus.cc:399] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:18.180418  6439 raft_consensus.cc:493] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:18.180456  6439 raft_consensus.cc:3060] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:18.181236  6439 raft_consensus.cc:515] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e8916e251d33470982668eff8d3fdb33" member_type: VOTER last_known_addr { host: "127.5.188.129" port: 32951 } }
I20260812 06:17:18.181354  6439 leader_election.cc:304] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [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: e8916e251d33470982668eff8d3fdb33; no voters: 
I20260812 06:17:18.181500  6439 leader_election.cc:290] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:18.181665  6442 raft_consensus.cc:2804] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:18.181821  6439 ts_tablet_manager.cc:1434] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:18.181860  6418 heartbeater.cc:499] Master 127.5.188.190:44301 was elected leader, sending a full tablet report...
I20260812 06:17:18.181872  6442 raft_consensus.cc:697] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [term 1 LEADER]: Becoming Leader. State: Replica: e8916e251d33470982668eff8d3fdb33, State: Running, Role: LEADER
I20260812 06:17:18.182052  6442 consensus_queue.cc:237] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [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: "e8916e251d33470982668eff8d3fdb33" member_type: VOTER last_known_addr { host: "127.5.188.129" port: 32951 } }
I20260812 06:17:18.183283  6221 catalog_manager.cc:5719] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 reported cstate change: term changed from 0 to 1, leader changed from <none> to e8916e251d33470982668eff8d3fdb33 (127.5.188.129). New cstate: current_term: 1 leader_uuid: "e8916e251d33470982668eff8d3fdb33" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e8916e251d33470982668eff8d3fdb33" member_type: VOTER last_known_addr { host: "127.5.188.129" port: 32951 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:18.246245  5874 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.022s	sys 0.001s
I20260812 06:17:18.403232  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushMRSOp(09a566457c994f3eb83130bf55caa88b): perf score=19.054940
I20260812 06:17:18.572058  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushMRSOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.168s	user 0.106s	sys 0.059s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":859,"drs_written":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39679,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:18.572795  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling LogGCOp(09a566457c994f3eb83130bf55caa88b): free 20743880 bytes of WAL
I20260812 06:17:18.573125  6329 log_reader.cc:385] T 09a566457c994f3eb83130bf55caa88b: removed 2 log segments from log reader
I20260812 06:17:18.573175  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000001 (ops 1-6)
I20260812 06:17:18.573233  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000002 (ops 7-11)
I20260812 06:17:18.577673  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: LogGCOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:18.578086  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling UndoDeltaBlockGCOp(09a566457c994f3eb83130bf55caa88b): 16411392 bytes on disk
I20260812 06:17:18.578541  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: UndoDeltaBlockGCOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:17:18.578948  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:18.590994  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4500,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.592243  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:18.769631  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.177s	user 0.106s	sys 0.071s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":993,"lbm_read_time_us":13758,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29134,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"thread_start_us":615,"threads_started":5,"update_count":2000}
I20260812 06:17:18.770349  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=10.126437
I20260812 06:17:18.803663  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.033s	user 0.014s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15046,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.804176  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:18.822436  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.018s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5919,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.822903  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:18.958626  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.136s	user 0.095s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":400,"lbm_read_time_us":9889,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26507,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.959327  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=11.118625
I20260812 06:17:18.999452  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.040s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16832,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:19.000119  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:19.024091  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.024s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5161,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.024602  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:19.035311  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4284,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.035785  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:19.198906  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.163s	user 0.118s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1140,"lbm_read_time_us":12593,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33407,"lbm_writes_lt_1ms":543,"mutex_wait_us":389,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:19.199435  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=11.118625
I20260812 06:17:19.249480  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.050s	user 0.026s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21735,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:19.250228  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:19.267082  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.017s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5901,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.267670  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:19.409098  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.141s	user 0.086s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2347,"lbm_read_time_us":8923,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28926,"lbm_writes_lt_1ms":443,"mutex_wait_us":2008,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:19.409749  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=11.118625
I20260812 06:17:19.459234  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.049s	user 0.024s	sys 0.023s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":16881,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:19.459928  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:19.487500  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.027s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5720,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.488021  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:19.503389  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.503958  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:19.702097  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.198s	user 0.142s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":393,"lbm_read_time_us":15245,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33172,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2500}
I20260812 06:17:19.702876  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=14.095187
I20260812 06:17:19.771812  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.069s	user 0.035s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26291,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.772459  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:19.786787  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5204,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.787489  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:19.999476  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.212s	user 0.132s	sys 0.080s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":295,"lbm_read_time_us":17815,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35232,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:20.000073  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=14.095187
I20260812 06:17:20.073850  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.074s	user 0.033s	sys 0.038s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25984,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.074651  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:20.086324  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4531,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.086829  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushMRSOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:20.135192  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushMRSOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.048s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1332,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1738,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32,"spinlock_wait_cycles":2944}
I20260812 06:17:20.135895  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling LogGCOp(09a566457c994f3eb83130bf55caa88b): free 133024360 bytes of WAL
I20260812 06:17:20.136140  6329 log_reader.cc:385] T 09a566457c994f3eb83130bf55caa88b: removed 13 log segments from log reader
I20260812 06:17:20.136188  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000003 (ops 12-16)
I20260812 06:17:20.136220  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000004 (ops 17-21)
I20260812 06:17:20.136284  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000005 (ops 22-26)
I20260812 06:17:20.136328  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000006 (ops 27-31)
I20260812 06:17:20.136397  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000007 (ops 32-36)
I20260812 06:17:20.136443  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000008 (ops 37-41)
I20260812 06:17:20.136488  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000009 (ops 42-46)
I20260812 06:17:20.136529  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000010 (ops 47-51)
I20260812 06:17:20.136569  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000011 (ops 52-56)
I20260812 06:17:20.136610  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000012 (ops 57-61)
I20260812 06:17:20.136649  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000013 (ops 62-66)
I20260812 06:17:20.136689  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000014 (ops 67-70)
I20260812 06:17:20.136729  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000015 (ops 71-75)
I20260812 06:17:20.168073  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: LogGCOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:20.168650  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling UndoDeltaBlockGCOp(09a566457c994f3eb83130bf55caa88b): 493 bytes on disk
I20260812 06:17:20.169193  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: UndoDeltaBlockGCOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.169664  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=3.181125
I20260812 06:17:20.186564  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.017s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4831,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:20.187057  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:20.197225  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4002,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:20.197638  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:20.453723  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.256s	user 0.170s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979743,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1241,"lbm_read_time_us":18778,"lbm_reads_lt_1ms":774,"lbm_write_time_us":44946,"lbm_writes_lt_1ms":743,"mutex_wait_us":646,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15872,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:17:20.454303  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=18.063937
I20260812 06:17:20.523814  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.068s	user 0.033s	sys 0.031s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":31623,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:17:20.524667  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:20.540886  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.016s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6465,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.541373  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:20.721875  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.180s	user 0.118s	sys 0.060s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":436,"lbm_read_time_us":13841,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34013,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":3000}
I20260812 06:17:20.722838  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=14.095187
I20260812 06:17:20.767735  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.044s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20197,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.768278  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:20.786032  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.018s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6263,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.786722  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:20.954704  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.168s	user 0.116s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":11773,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31392,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:17:20.955478  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=14.095187
I20260812 06:17:21.019289  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.064s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21776,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.019804  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:21.032931  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4315,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.033708  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:21.232609  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.199s	user 0.147s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":162,"lbm_read_time_us":13888,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34530,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2500}
I20260812 06:17:21.233353  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=14.095187
I20260812 06:17:21.295097  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.062s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19524,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.295710  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:21.308163  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4531,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.308970  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:21.489390  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.180s	user 0.110s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1097,"lbm_read_time_us":13099,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31409,"lbm_writes_lt_1ms":543,"mutex_wait_us":375,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:21.490159  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=14.095187
I20260812 06:17:21.559581  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.069s	user 0.043s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26981,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.560204  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:21.571437  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.571950  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushMRSOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:21.602407  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushMRSOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.030s	user 0.020s	sys 0.008s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":1280,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1594,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:21.603171  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:21.795046  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.192s	user 0.104s	sys 0.086s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":411,"lbm_read_time_us":15196,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30567,"lbm_writes_lt_1ms":543,"mutex_wait_us":92,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2500}
I20260812 06:17:21.795786  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling LogGCOp(09a566457c994f3eb83130bf55caa88b): free 112239266 bytes of WAL
I20260812 06:17:21.797333  6329 log_reader.cc:385] T 09a566457c994f3eb83130bf55caa88b: removed 11 log segments from log reader
I20260812 06:17:21.797446  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000016 (ops 76-80)
I20260812 06:17:21.797545  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000017 (ops 81-85)
I20260812 06:17:21.797647  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000018 (ops 86-90)
I20260812 06:17:21.797727  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000019 (ops 91-95)
I20260812 06:17:21.797806  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000020 (ops 96-100)
I20260812 06:17:21.797885  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000021 (ops 101-104)
I20260812 06:17:21.797973  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000022 (ops 105-109)
I20260812 06:17:21.798049  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000023 (ops 110-114)
I20260812 06:17:21.798156  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000024 (ops 115-119)
I20260812 06:17:21.798224  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000025 (ops 120-124)
I20260812 06:17:21.798321  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000026 (ops 125-129)
I20260812 06:17:21.838285  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: LogGCOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.041s	user 0.000s	sys 0.039s Metrics: {}
I20260812 06:17:21.838810  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling UndoDeltaBlockGCOp(09a566457c994f3eb83130bf55caa88b): 447 bytes on disk
I20260812 06:17:21.839336  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: UndoDeltaBlockGCOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:21.839973  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=18.063937
I20260812 06:17:21.909096  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.069s	user 0.038s	sys 0.031s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25092,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:21.909798  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:21.922173  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.922860  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:22.138885  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.216s	user 0.123s	sys 0.092s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1692,"lbm_read_time_us":17305,"lbm_reads_lt_1ms":672,"lbm_write_time_us":38264,"lbm_writes_lt_1ms":643,"mutex_wait_us":525,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":71296,"update_count":3000}
I20260812 06:17:22.139590  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=14.095187
I20260812 06:17:22.192052  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.052s	user 0.023s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20022,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.192780  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:22.205323  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4505,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.205794  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:22.397046  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.191s	user 0.137s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1137,"lbm_read_time_us":12602,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34441,"lbm_writes_lt_1ms":543,"mutex_wait_us":334,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:17:22.397899  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=14.095187
I20260812 06:17:22.470355  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.071s	user 0.035s	sys 0.035s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":28947,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.470975  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:22.482501  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4387,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.483006  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:22.678990  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.196s	user 0.121s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1267,"lbm_read_time_us":14857,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31924,"lbm_writes_lt_1ms":543,"mutex_wait_us":362,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:17:22.679791  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=14.095187
I20260812 06:17:22.728682  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.049s	user 0.016s	sys 0.027s Metrics: {"bytes_written":16409946,"delete_count":0,"lbm_write_time_us":20794,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.729331  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:22.757120  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.028s	user 0.013s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.757714  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:22.951013  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.193s	user 0.127s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774733,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":463,"lbm_read_time_us":13577,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33809,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:22.951853  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=14.095187
I20260812 06:17:23.007416  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.055s	user 0.033s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23066,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:23.007967  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:23.020215  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4472,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.020704  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:23.228063  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.207s	user 0.122s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1052,"lbm_read_time_us":14028,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33847,"lbm_writes_lt_1ms":543,"mutex_wait_us":352,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:17:23.228917  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=14.095187
I20260812 06:17:23.282994  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.054s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22675,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:23.283555  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:23.295660  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.296476  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushMRSOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:23.330197  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushMRSOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":313,"dirs.run_wall_time_us":1483,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2496,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:23.331055  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling LogGCOp(09a566457c994f3eb83130bf55caa88b): free 129320833 bytes of WAL
I20260812 06:17:23.331324  6329 log_reader.cc:385] T 09a566457c994f3eb83130bf55caa88b: removed 13 log segments from log reader
I20260812 06:17:23.331373  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000027 (ops 130-134)
I20260812 06:17:23.331434  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000028 (ops 135-138)
I20260812 06:17:23.331470  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000029 (ops 139-143)
I20260812 06:17:23.331524  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000030 (ops 144-148)
I20260812 06:17:23.331564  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000031 (ops 149-153)
I20260812 06:17:23.331604  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000032 (ops 154-158)
I20260812 06:17:23.331640  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000033 (ops 159-163)
I20260812 06:17:23.331678  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000034 (ops 164-168)
I20260812 06:17:23.331717  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000035 (ops 169-173)
I20260812 06:17:23.331754  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000036 (ops 174-178)
I20260812 06:17:23.331792  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000037 (ops 179-182)
I20260812 06:17:23.331830  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000038 (ops 183-187)
I20260812 06:17:23.331877  6329 log.cc:1079] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: Deleting log segment in path: /tmp/dist-test-taskWZt8DV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432009877-5874-0/minicluster-data/ts-0-root/wals/09a566457c994f3eb83130bf55caa88b/wal-000000039 (ops 188-192)
I20260812 06:17:23.361469  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: LogGCOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.030s	user 0.004s	sys 0.026s Metrics: {}
I20260812 06:17:23.365545  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:23.384532  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.019s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.385058  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=2.188937
I20260812 06:17:23.400496  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6103,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.401104  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b): perf score=1.000000
I20260812 06:17:23.547842  5874 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.301s	user 1.949s	sys 0.201s
I20260812 06:17:23.630254  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: MajorDeltaCompactionOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.229s	user 0.163s	sys 0.064s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2486,"lbm_read_time_us":18238,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37917,"lbm_writes_lt_1ms":743,"mutex_wait_us":998,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10752,"thread_start_us":110,"threads_started":1,"update_count":3500}
I20260812 06:17:23.631052  6420 maintenance_manager.cc:419] P e8916e251d33470982668eff8d3fdb33: Scheduling FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b): perf score=10.126437
I20260812 06:17:23.642071  5874 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.094s	user 0.002s	sys 0.000s
I20260812 06:17:23.642619  5874 tablet_server.cc:179] TabletServer@127.5.188.129:0 shutting down...
I20260812 06:17:23.687705  6329 maintenance_manager.cc:643] P e8916e251d33470982668eff8d3fdb33: FlushDeltaMemStoresOp(09a566457c994f3eb83130bf55caa88b) complete. Timing: real 0.056s	user 0.027s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18064,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.688405  5874 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:23.688680  5874 tablet_replica.cc:333] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33: stopping tablet replica
I20260812 06:17:23.688860  5874 raft_consensus.cc:2243] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:23.689060  5874 raft_consensus.cc:2272] T 09a566457c994f3eb83130bf55caa88b P e8916e251d33470982668eff8d3fdb33 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:23.692430  5874 tablet_server.cc:196] TabletServer@127.5.188.129:0 shutdown complete.
I20260812 06:17:23.695393  5874 master.cc:562] Master@127.5.188.190:44301 shutting down...
I20260812 06:17:23.699201  5874 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:23.699357  5874 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:23.699409  5874 tablet_replica.cc:333] T 00000000000000000000000000000000 P f8824dcb8a474d7c84bf129936df04f6: stopping tablet replica
I20260812 06:17:23.711483  5874 master.cc:584] Master@127.5.188.190:44301 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5816 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11785 ms total)

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