[==========] 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:20:24.022905 23955 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.100.254:37549
I20260812 06:20:24.024034 23955 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:20:24.024714 23955 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:24.032007 23963 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:20:24.032017 23967 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:20:24.032294 23972 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:20:24.032362 23955 server_base.cc:1061] running on GCE node
I20260812 06:20:24.032986 23955 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:24.033125 23955 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:20:24.033195 23955 hybrid_clock.cc:648] HybridClock initialized: now 1786515624033191 us; error 0 us; skew 500 ppm
I20260812 06:20:24.035305 23955 webserver.cc:533] Webserver started at http://127.23.100.254:35093/ using document root <none> and password file <none>
I20260812 06:20:24.035959 23955 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:24.036057 23955 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:24.036350 23955 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:24.038177 23955 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/master-0-root/instance:
uuid: "ad71bed7a545455f978796a20ab73e2b"
format_stamp: "Formatted at 2026-08-12 06:20:24 on dist-test-slave-twwt"
I20260812 06:20:24.042254 23955 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:20:24.044694 23979 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:20:24.045874 23955 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:24.046017 23955 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/master-0-root
uuid: "ad71bed7a545455f978796a20ab73e2b"
format_stamp: "Formatted at 2026-08-12 06:20:24 on dist-test-slave-twwt"
I20260812 06:20:24.046134 23955 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-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:20:24.060051 23955 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:24.060757 23955 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:20:24.060964 23955 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:24.069466 23955 rpc_server.cc:307] RPC server started. Bound to: 127.23.100.254:37549
I20260812 06:20:24.069464 24078 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.100.254:37549 every 8 connection(s)
I20260812 06:20:24.072119 24079 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:20:24.077881 24079 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b: Bootstrap starting.
I20260812 06:20:24.080564 24079 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:24.081532 24079 log.cc:826] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:24.083442 24079 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b: No bootstrap required, opened a new log
I20260812 06:20:24.086380 24079 raft_consensus.cc:359] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad71bed7a545455f978796a20ab73e2b" member_type: VOTER }
I20260812 06:20:24.086560 24079 raft_consensus.cc:385] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:24.086679 24079 raft_consensus.cc:740] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ad71bed7a545455f978796a20ab73e2b, State: Initialized, Role: FOLLOWER
I20260812 06:20:24.087324 24079 consensus_queue.cc:260] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [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: "ad71bed7a545455f978796a20ab73e2b" member_type: VOTER }
I20260812 06:20:24.087479 24079 raft_consensus.cc:399] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:24.087528 24079 raft_consensus.cc:493] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:24.087625 24079 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:24.088426 24079 raft_consensus.cc:515] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad71bed7a545455f978796a20ab73e2b" member_type: VOTER }
I20260812 06:20:24.088861 24079 leader_election.cc:304] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [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: ad71bed7a545455f978796a20ab73e2b; no voters: 
I20260812 06:20:24.089184 24079 leader_election.cc:290] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:24.089345 24085 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:24.089623 24085 raft_consensus.cc:697] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [term 1 LEADER]: Becoming Leader. State: Replica: ad71bed7a545455f978796a20ab73e2b, State: Running, Role: LEADER
I20260812 06:20:24.090106 24085 consensus_queue.cc:237] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [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: "ad71bed7a545455f978796a20ab73e2b" member_type: VOTER }
I20260812 06:20:24.090411 24079 sys_catalog.cc:565] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:24.092216 24092 sys_catalog.cc:455] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [sys.catalog]: SysCatalogTable state changed. Reason: New leader ad71bed7a545455f978796a20ab73e2b. Latest consensus state: current_term: 1 leader_uuid: "ad71bed7a545455f978796a20ab73e2b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad71bed7a545455f978796a20ab73e2b" member_type: VOTER } }
I20260812 06:20:24.092254 24086 sys_catalog.cc:455] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ad71bed7a545455f978796a20ab73e2b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad71bed7a545455f978796a20ab73e2b" member_type: VOTER } }
I20260812 06:20:24.092347 24092 sys_catalog.cc:458] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:24.092350 24086 sys_catalog.cc:458] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:24.092727 24107 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:24.093101 23955 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:24.095314 24107 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:24.100579 24107 catalog_manager.cc:1383] Generated new cluster ID: a61ae9a0b9674c8db40c45f60010843a
I20260812 06:20:24.100660 24107 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:24.135778 24107 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:24.137115 24107 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:24.156471 24107 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b: Generated new TSK 0
I20260812 06:20:24.157265 24107 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:24.222714 23955 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:24.225642 24123 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:20:24.225853 23955 server_base.cc:1061] running on GCE node
W20260812 06:20:24.225715 24120 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:20:24.226007 24121 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:20:24.226312 23955 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:24.226382 23955 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:20:24.226424 23955 hybrid_clock.cc:648] HybridClock initialized: now 1786515624226423 us; error 0 us; skew 500 ppm
I20260812 06:20:24.227504 23955 webserver.cc:533] Webserver started at http://127.23.100.193:36153/ using document root <none> and password file <none>
I20260812 06:20:24.227708 23955 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:24.227783 23955 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:24.227869 23955 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:24.228318 23955 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/instance:
uuid: "62193eb90a8a48d9af656d319008521b"
format_stamp: "Formatted at 2026-08-12 06:20:24 on dist-test-slave-twwt"
I20260812 06:20:24.230111 23955 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:20:24.231236 24132 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:20:24.231498 23955 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:20:24.231572 23955 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root
uuid: "62193eb90a8a48d9af656d319008521b"
format_stamp: "Formatted at 2026-08-12 06:20:24 on dist-test-slave-twwt"
I20260812 06:20:24.231668 23955 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-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:20:24.247627 23955 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:24.248152 23955 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:24.248709 23955 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:24.249678 23955 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:24.249732 23955 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:24.249778 23955 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:24.249815 23955 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:24.257289 23955 rpc_server.cc:307] RPC server started. Bound to: 127.23.100.193:34115
I20260812 06:20:24.257318 24241 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.100.193:34115 every 8 connection(s)
I20260812 06:20:24.268302 24242 heartbeater.cc:344] Connected to a master server at 127.23.100.254:37549
I20260812 06:20:24.268592 24242 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:24.269073 24242 heartbeater.cc:507] Master 127.23.100.254:37549 requested a full tablet report, sending...
I20260812 06:20:24.270511 24008 ts_manager.cc:194] Registered new tserver with Master: 62193eb90a8a48d9af656d319008521b (127.23.100.193:34115)
I20260812 06:20:24.270628 23955 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012602498s
I20260812 06:20:24.271797 24008 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41186
I20260812 06:20:24.280475 24008 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41192:
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:20:24.293888 24180 tablet_service.cc:1511] Processing CreateTablet for tablet c8b8a2dd486640299a159e47bd9e6d1a (DEFAULT_TABLE table=heavy-update-compaction-test [id=02442c4f3c844022a0d0ac971630a268]), partition=
I20260812 06:20:24.294413 24180 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c8b8a2dd486640299a159e47bd9e6d1a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:24.296655 24256 tablet_bootstrap.cc:492] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Bootstrap starting.
I20260812 06:20:24.297521 24256 tablet_bootstrap.cc:654] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:24.298705 24256 tablet_bootstrap.cc:492] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: No bootstrap required, opened a new log
I20260812 06:20:24.298831 24256 ts_tablet_manager.cc:1403] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:24.299263 24256 raft_consensus.cc:359] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "62193eb90a8a48d9af656d319008521b" member_type: VOTER last_known_addr { host: "127.23.100.193" port: 34115 } }
I20260812 06:20:24.299394 24256 raft_consensus.cc:385] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:24.299443 24256 raft_consensus.cc:740] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 62193eb90a8a48d9af656d319008521b, State: Initialized, Role: FOLLOWER
I20260812 06:20:24.299593 24256 consensus_queue.cc:260] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [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: "62193eb90a8a48d9af656d319008521b" member_type: VOTER last_known_addr { host: "127.23.100.193" port: 34115 } }
I20260812 06:20:24.299693 24256 raft_consensus.cc:399] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:24.299741 24256 raft_consensus.cc:493] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:24.299796 24256 raft_consensus.cc:3060] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:24.300506 24256 raft_consensus.cc:515] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "62193eb90a8a48d9af656d319008521b" member_type: VOTER last_known_addr { host: "127.23.100.193" port: 34115 } }
I20260812 06:20:24.300669 24256 leader_election.cc:304] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [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: 62193eb90a8a48d9af656d319008521b; no voters: 
I20260812 06:20:24.300899 24256 leader_election.cc:290] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:24.301074 24259 raft_consensus.cc:2804] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:24.301301 24259 raft_consensus.cc:697] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [term 1 LEADER]: Becoming Leader. State: Replica: 62193eb90a8a48d9af656d319008521b, State: Running, Role: LEADER
I20260812 06:20:24.301342 24256 ts_tablet_manager.cc:1434] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:24.301717 24242 heartbeater.cc:499] Master 127.23.100.254:37549 was elected leader, sending a full tablet report...
I20260812 06:20:24.302178 24259 consensus_queue.cc:237] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [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: "62193eb90a8a48d9af656d319008521b" member_type: VOTER last_known_addr { host: "127.23.100.193" port: 34115 } }
I20260812 06:20:24.304868 24008 catalog_manager.cc:5719] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b reported cstate change: term changed from 0 to 1, leader changed from <none> to 62193eb90a8a48d9af656d319008521b (127.23.100.193). New cstate: current_term: 1 leader_uuid: "62193eb90a8a48d9af656d319008521b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "62193eb90a8a48d9af656d319008521b" member_type: VOTER last_known_addr { host: "127.23.100.193" port: 34115 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:24.371219 23955 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.017s	sys 0.009s
I20260812 06:20:24.508610 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushMRSOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=15.086190
I20260812 06:20:24.682852 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushMRSOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.174s	user 0.134s	sys 0.040s Metrics: {"bytes_written":11897251,"cfile_init":1,"compiler_manager_pool.queue_time_us":227,"delete_count":0,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":967,"drs_written":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40605,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":122,"threads_started":1,"update_count":1450}
I20260812 06:20:24.684069 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling LogGCOp(c8b8a2dd486640299a159e47bd9e6d1a): free 20743880 bytes of WAL
I20260812 06:20:24.684415 24146 log_reader.cc:385] T c8b8a2dd486640299a159e47bd9e6d1a: removed 2 log segments from log reader
I20260812 06:20:24.684505 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000001 (ops 1-6)
I20260812 06:20:24.684584 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000002 (ops 7-11)
I20260812 06:20:24.690748 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: LogGCOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:20:24.691191 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:24.721383 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.030s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5482,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.721850 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:24.732553 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4100,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.733106 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:24.901466 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.168s	user 0.124s	sys 0.041s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364569,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":715,"lbm_read_time_us":12336,"lbm_reads_lt_1ms":563,"lbm_write_time_us":28933,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":299,"threads_started":5,"update_count":2450}
I20260812 06:20:24.902122 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling UndoDeltaBlockGCOp(c8b8a2dd486640299a159e47bd9e6d1a): 12719217 bytes on disk
I20260812 06:20:24.902731 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: UndoDeltaBlockGCOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4}
I20260812 06:20:24.903321 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=10.126437
I20260812 06:20:24.950958 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.047s	user 0.027s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20560,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.951551 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:24.967516 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.968142 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:25.094712 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.126s	user 0.100s	sys 0.026s 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":841,"lbm_read_time_us":9260,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26918,"lbm_writes_lt_1ms":443,"mutex_wait_us":365,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:20:25.095413 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=10.126437
I20260812 06:20:25.145246 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.050s	user 0.021s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22133,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.145816 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:25.157618 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4353,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.158313 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:25.290524 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.132s	user 0.120s	sys 0.012s 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":174,"lbm_read_time_us":10544,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25915,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.291571 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=10.126437
I20260812 06:20:25.343130 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.051s	user 0.016s	sys 0.035s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19893,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.343797 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:25.361500 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.362016 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:25.520694 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.158s	user 0.113s	sys 0.043s 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":172,"lbm_read_time_us":10483,"lbm_reads_lt_1ms":468,"lbm_write_time_us":28201,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:20:25.521327 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=11.118625
I20260812 06:20:25.562489 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.041s	user 0.013s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17552,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:25.563148 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:25.580246 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.017s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5825,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:25.580783 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:25.712589 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.132s	user 0.091s	sys 0.040s 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":1050,"lbm_read_time_us":9883,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26787,"lbm_writes_lt_1ms":443,"mutex_wait_us":354,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2000}
I20260812 06:20:25.713241 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=10.126437
I20260812 06:20:25.752832 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.039s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17391,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.753484 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:25.775655 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.022s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5988,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.776445 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:25.913635 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.137s	user 0.106s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":554,"lbm_read_time_us":9362,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27274,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.914549 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=10.126437
I20260812 06:20:25.956892 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.042s	user 0.019s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18394,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.957496 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:25.971499 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5315,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.972054 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushMRSOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:26.006897 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushMRSOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.035s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":192,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":1314,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2031,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:26.007769 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling LogGCOp(c8b8a2dd486640299a159e47bd9e6d1a): free 112239312 bytes of WAL
I20260812 06:20:26.008044 24146 log_reader.cc:385] T c8b8a2dd486640299a159e47bd9e6d1a: removed 11 log segments from log reader
I20260812 06:20:26.008093 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000003 (ops 12-16)
I20260812 06:20:26.008126 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000004 (ops 17-21)
I20260812 06:20:26.008191 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000005 (ops 22-26)
I20260812 06:20:26.008235 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000006 (ops 27-31)
I20260812 06:20:26.008296 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000007 (ops 32-36)
I20260812 06:20:26.008335 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000008 (ops 37-40)
I20260812 06:20:26.008392 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000009 (ops 41-45)
I20260812 06:20:26.008430 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000010 (ops 46-50)
I20260812 06:20:26.008468 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000011 (ops 51-55)
I20260812 06:20:26.008507 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000012 (ops 56-60)
I20260812 06:20:26.008544 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000013 (ops 61-65)
I20260812 06:20:26.036787 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: LogGCOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:26.037375 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=5.165500
I20260812 06:20:26.061748 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.024s	user 0.005s	sys 0.016s Metrics: {"bytes_written":7015375,"delete_count":0,"lbm_write_time_us":9487,"lbm_writes_lt_1ms":174,"reinsert_count":0,"update_count":855}
I20260812 06:20:26.062393 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling UndoDeltaBlockGCOp(c8b8a2dd486640299a159e47bd9e6d1a): 463 bytes on disk
I20260812 06:20:26.063012 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: UndoDeltaBlockGCOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:20:26.063552 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:26.070988 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.007s	user 0.007s	sys 0.000s Metrics: {"bytes_written":1189877,"delete_count":0,"lbm_write_time_us":1857,"lbm_writes_lt_1ms":32,"reinsert_count":0,"update_count":145}
I20260812 06:20:26.071412 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling LogGCOp(c8b8a2dd486640299a159e47bd9e6d1a): free 12017932 bytes of WAL
I20260812 06:20:26.071641 24146 log_reader.cc:385] T c8b8a2dd486640299a159e47bd9e6d1a: removed 1 log segments from log reader
I20260812 06:20:26.071698 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000014 (ops 66-70)
I20260812 06:20:26.075312 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: LogGCOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.004s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:20:26.075652 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:26.257448 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.182s	user 0.128s	sys 0.053s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":336,"lbm_read_time_us":12496,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36683,"lbm_writes_lt_1ms":643,"mutex_wait_us":68,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:20:26.258677 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=14.095187
I20260812 06:20:26.317850 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.059s	user 0.038s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25445,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.318324 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:26.330470 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4358,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.330996 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:26.506773 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.176s	user 0.129s	sys 0.036s 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":1805,"lbm_read_time_us":12878,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30443,"lbm_writes_lt_1ms":543,"mutex_wait_us":599,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":2500}
I20260812 06:20:26.507640 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=14.095187
I20260812 06:20:26.581939 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.074s	user 0.029s	sys 0.028s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":26638,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.582479 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:26.593811 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4303,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.594311 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:26.772396 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.178s	user 0.109s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1181,"lbm_read_time_us":13630,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31876,"lbm_writes_lt_1ms":543,"mutex_wait_us":893,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25472,"update_count":2500}
I20260812 06:20:26.773240 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=14.095187
I20260812 06:20:26.832800 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.059s	user 0.038s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22216,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.833370 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:26.853039 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.019s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7656,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.853670 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:27.043541 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.190s	user 0.135s	sys 0.044s 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":879,"lbm_read_time_us":13989,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32722,"lbm_writes_lt_1ms":543,"mutex_wait_us":262,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:20:27.044286 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=14.095187
I20260812 06:20:27.108276 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.064s	user 0.026s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20787,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.108887 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:27.120316 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.120854 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:27.338860 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.218s	user 0.145s	sys 0.066s 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":565,"lbm_read_time_us":15127,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36204,"lbm_writes_lt_1ms":543,"mutex_wait_us":202,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:20:27.339596 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=14.095187
I20260812 06:20:27.402295 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.062s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23795,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.402869 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:27.431203 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.028s	user 0.012s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6022,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.432155 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:27.621362 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.189s	user 0.109s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":720,"lbm_read_time_us":14271,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31576,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:20:27.622145 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=11.118625
I20260812 06:20:27.657660 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.035s	user 0.015s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15171,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:27.658198 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:27.682969 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.025s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5078,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:27.683467 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:27.694460 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4198,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.695022 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushMRSOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:27.736155 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushMRSOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.041s	user 0.036s	sys 0.002s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1297,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1532,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:27.737116 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling LogGCOp(c8b8a2dd486640299a159e47bd9e6d1a): free 117302580 bytes of WAL
I20260812 06:20:27.737391 24146 log_reader.cc:385] T c8b8a2dd486640299a159e47bd9e6d1a: removed 12 log segments from log reader
I20260812 06:20:27.737464 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000015 (ops 71-75)
I20260812 06:20:27.737524 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000016 (ops 76-80)
I20260812 06:20:27.737582 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000017 (ops 81-84)
I20260812 06:20:27.737623 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000018 (ops 85-89)
I20260812 06:20:27.737679 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000019 (ops 90-94)
I20260812 06:20:27.737717 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000020 (ops 95-98)
I20260812 06:20:27.737756 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000021 (ops 99-103)
I20260812 06:20:27.737792 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000022 (ops 104-108)
I20260812 06:20:27.737828 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000023 (ops 109-113)
I20260812 06:20:27.737872 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000024 (ops 114-118)
I20260812 06:20:27.737908 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000025 (ops 119-123)
I20260812 06:20:27.737946 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000026 (ops 124-128)
I20260812 06:20:27.763685 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: LogGCOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:20:27.764145 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:27.786827 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.022s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 06:20:27.787361 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling LogGCOp(c8b8a2dd486640299a159e47bd9e6d1a): free 11564891 bytes of WAL
I20260812 06:20:27.787596 24146 log_reader.cc:385] T c8b8a2dd486640299a159e47bd9e6d1a: removed 1 log segments from log reader
I20260812 06:20:27.787643 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000027 (ops 129-132)
I20260812 06:20:27.790035 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: LogGCOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:27.790385 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:27.803208 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.803757 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:28.064507 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.261s	user 0.153s	sys 0.097s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979859,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":374,"lbm_read_time_us":17542,"lbm_reads_lt_1ms":775,"lbm_write_time_us":44406,"lbm_writes_lt_1ms":743,"mutex_wait_us":50,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:20:28.065263 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=18.063937
I20260812 06:20:28.146152 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.081s	user 0.044s	sys 0.019s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":30597,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:28.146775 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:28.158582 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4209,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.159173 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling UndoDeltaBlockGCOp(c8b8a2dd486640299a159e47bd9e6d1a): 482 bytes on disk
I20260812 06:20:28.159679 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: UndoDeltaBlockGCOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:20:28.160246 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:28.375429 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.215s	user 0.138s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":909,"lbm_read_time_us":14940,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36121,"lbm_writes_lt_1ms":643,"mutex_wait_us":381,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3000}
I20260812 06:20:28.376320 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=16.079562
I20260812 06:20:28.434049 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.057s	user 0.037s	sys 0.016s Metrics: {"bytes_written":17968823,"delete_count":0,"lbm_write_time_us":25848,"lbm_writes_lt_1ms":441,"reinsert_count":0,"update_count":2190}
I20260812 06:20:28.434695 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.196750
I20260812 06:20:28.444242 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.009s	user 0.006s	sys 0.001s Metrics: {"bytes_written":2953959,"delete_count":0,"lbm_write_time_us":3019,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:20:28.444758 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:28.616186 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.171s	user 0.099s	sys 0.072s Metrics: {"cfile_cache_miss":542,"cfile_cache_miss_bytes":25184910,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1213,"lbm_read_time_us":12735,"lbm_reads_lt_1ms":574,"lbm_write_time_us":29423,"lbm_writes_lt_1ms":553,"mutex_wait_us":364,"peak_mem_usage":63526250,"reinsert_count":0,"update_count":2550}
I20260812 06:20:28.616910 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=14.095187
I20260812 06:20:28.680186 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.063s	user 0.026s	sys 0.035s Metrics: {"bytes_written":15999657,"delete_count":0,"lbm_write_time_us":22501,"lbm_writes_lt_1ms":393,"reinsert_count":0,"update_count":1950}
I20260812 06:20:28.680967 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:28.699918 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.019s	user 0.004s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7086,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.700580 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:28.891292 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.190s	user 0.123s	sys 0.052s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24364444,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":870,"lbm_read_time_us":14734,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":561,"lbm_write_time_us":30755,"lbm_writes_lt_1ms":533,"mutex_wait_us":23,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":827264,"update_count":2450}
I20260812 06:20:28.892031 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=14.095187
I20260812 06:20:28.956648 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.064s	user 0.031s	sys 0.031s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24912,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.957242 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:28.968397 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.968963 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:29.148960 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.180s	user 0.139s	sys 0.040s 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":755,"lbm_read_time_us":14193,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30446,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2500}
I20260812 06:20:29.149809 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=10.126437
I20260812 06:20:29.200843 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.051s	user 0.028s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":24112,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:29.201444 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:29.216593 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5230,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.217186 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushMRSOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:29.259534 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushMRSOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.042s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":319,"dirs.run_wall_time_us":1475,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1577,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:29.260475 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=3.181125
I20260812 06:20:29.281917 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.021s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4507,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:29.282523 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling LogGCOp(c8b8a2dd486640299a159e47bd9e6d1a): free 108988752 bytes of WAL
I20260812 06:20:29.282847 24146 log_reader.cc:385] T c8b8a2dd486640299a159e47bd9e6d1a: removed 11 log segments from log reader
I20260812 06:20:29.282907 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000028 (ops 133-137)
I20260812 06:20:29.282969 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000029 (ops 138-142)
I20260812 06:20:29.283021 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000030 (ops 143-147)
I20260812 06:20:29.283070 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000031 (ops 148-152)
I20260812 06:20:29.283116 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000032 (ops 153-156)
I20260812 06:20:29.283288 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000033 (ops 157-161)
I20260812 06:20:29.283357 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000034 (ops 162-166)
I20260812 06:20:29.283411 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000035 (ops 167-171)
I20260812 06:20:29.283455 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000036 (ops 172-176)
I20260812 06:20:29.283500 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000037 (ops 177-181)
I20260812 06:20:29.283545 24146 log.cc:1079] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/c8b8a2dd486640299a159e47bd9e6d1a/wal-000000038 (ops 182-186)
I20260812 06:20:29.311554 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: LogGCOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:20:29.312058 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:29.337193 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.025s	user 0.001s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6452,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.337733 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=2.188937
I20260812 06:20:29.347982 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3709,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:29.348453 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:29.601426 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.253s	user 0.158s	sys 0.084s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979857,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1413,"lbm_read_time_us":16279,"lbm_reads_lt_1ms":775,"lbm_write_time_us":43530,"lbm_writes_lt_1ms":743,"mutex_wait_us":47,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15744,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:20:29.602216 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=18.063937
I20260812 06:20:29.658128 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: FlushDeltaMemStoresOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.056s	user 0.036s	sys 0.015s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":24340,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:29.658711 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling UndoDeltaBlockGCOp(c8b8a2dd486640299a159e47bd9e6d1a): 448 bytes on disk
I20260812 06:20:29.659173 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: UndoDeltaBlockGCOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:20:29.659722 24243 maintenance_manager.cc:419] P 62193eb90a8a48d9af656d319008521b: Scheduling MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a): perf score=1.000000
I20260812 06:20:29.675335 23955 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.304s	user 1.915s	sys 0.199s
I20260812 06:20:29.753381 23955 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.077s	user 0.003s	sys 0.000s
I20260812 06:20:29.754191 23955 tablet_server.cc:179] TabletServer@127.23.100.193:0 shutting down...
I20260812 06:20:29.812379 24146 maintenance_manager.cc:643] P 62193eb90a8a48d9af656d319008521b: MajorDeltaCompactionOp(c8b8a2dd486640299a159e47bd9e6d1a) complete. Timing: real 0.152s	user 0.097s	sys 0.055s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774570,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":541,"lbm_read_time_us":11443,"lbm_reads_lt_1ms":563,"lbm_write_time_us":27244,"lbm_writes_lt_1ms":543,"mutex_wait_us":124,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:20:29.813503 23955 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:29.813982 23955 tablet_replica.cc:333] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b: stopping tablet replica
I20260812 06:20:29.814256 23955 raft_consensus.cc:2243] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:29.814577 23955 raft_consensus.cc:2272] T c8b8a2dd486640299a159e47bd9e6d1a P 62193eb90a8a48d9af656d319008521b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:29.831915 23955 tablet_server.cc:196] TabletServer@127.23.100.193:0 shutdown complete.
I20260812 06:20:29.859998 23955 master.cc:562] Master@127.23.100.254:37549 shutting down...
I20260812 06:20:29.863679 23955 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:29.863897 23955 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:29.863992 23955 tablet_replica.cc:333] T 00000000000000000000000000000000 P ad71bed7a545455f978796a20ab73e2b: stopping tablet replica
I20260812 06:20:29.876487 23955 master.cc:584] Master@127.23.100.254:37549 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5957 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:29.995091 23955 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.100.254:32973
I20260812 06:20:29.995678 23955 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:29.998204 24298 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:20:29.998229 24292 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:20:29.998368 23955 server_base.cc:1061] running on GCE node
W20260812 06:20:29.998332 24294 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:20:29.998708 23955 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:29.998769 23955 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:20:29.998801 23955 hybrid_clock.cc:648] HybridClock initialized: now 1786515629998800 us; error 0 us; skew 500 ppm
I20260812 06:20:29.999836 23955 webserver.cc:533] Webserver started at http://127.23.100.254:44425/ using document root <none> and password file <none>
I20260812 06:20:30.000039 23955 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:30.000090 23955 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:30.000176 23955 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:30.000607 23955 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/master-0-root/instance:
uuid: "4555b84f76e0449b9c73c36dfa37094e"
format_stamp: "Formatted at 2026-08-12 06:20:29 on dist-test-slave-twwt"
I20260812 06:20:30.002328 23955 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:30.003480 24304 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:20:30.003794 23955 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:30.003916 23955 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/master-0-root
uuid: "4555b84f76e0449b9c73c36dfa37094e"
format_stamp: "Formatted at 2026-08-12 06:20:29 on dist-test-slave-twwt"
I20260812 06:20:30.004014 23955 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-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:20:30.015447 23955 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:30.015918 23955 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:30.020566 23955 rpc_server.cc:307] RPC server started. Bound to: 127.23.100.254:32973
I20260812 06:20:30.025378 24395 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.100.254:32973 every 8 connection(s)
I20260812 06:20:30.025938 24397 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:20:30.028015 24397 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e: Bootstrap starting.
I20260812 06:20:30.028884 24397 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:30.030022 24397 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e: No bootstrap required, opened a new log
I20260812 06:20:30.030480 24397 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4555b84f76e0449b9c73c36dfa37094e" member_type: VOTER }
I20260812 06:20:30.030572 24397 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:30.030658 24397 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4555b84f76e0449b9c73c36dfa37094e, State: Initialized, Role: FOLLOWER
I20260812 06:20:30.030864 24397 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [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: "4555b84f76e0449b9c73c36dfa37094e" member_type: VOTER }
I20260812 06:20:30.030947 24397 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:30.031006 24397 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:30.031068 24397 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:30.031926 24397 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4555b84f76e0449b9c73c36dfa37094e" member_type: VOTER }
I20260812 06:20:30.032086 24397 leader_election.cc:304] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [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: 4555b84f76e0449b9c73c36dfa37094e; no voters: 
I20260812 06:20:30.032327 24397 leader_election.cc:290] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:30.032474 24400 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:30.032730 24400 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [term 1 LEADER]: Becoming Leader. State: Replica: 4555b84f76e0449b9c73c36dfa37094e, State: Running, Role: LEADER
I20260812 06:20:30.032883 24400 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [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: "4555b84f76e0449b9c73c36dfa37094e" member_type: VOTER }
I20260812 06:20:30.032918 24397 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:30.033363 24402 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4555b84f76e0449b9c73c36dfa37094e. Latest consensus state: current_term: 1 leader_uuid: "4555b84f76e0449b9c73c36dfa37094e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4555b84f76e0449b9c73c36dfa37094e" member_type: VOTER } }
I20260812 06:20:30.033349 24401 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4555b84f76e0449b9c73c36dfa37094e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4555b84f76e0449b9c73c36dfa37094e" member_type: VOTER } }
I20260812 06:20:30.033499 24402 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:30.033563 24401 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:30.034118 24407 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:30.034981 24407 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:30.035209 23955 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:30.037078 24407 catalog_manager.cc:1383] Generated new cluster ID: 0f43f14ddc054285bd0d9a2209e55493
I20260812 06:20:30.037127 24407 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:30.049719 24407 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:30.050261 24407 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:30.055670 24407 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e: Generated new TSK 0
I20260812 06:20:30.055819 24407 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:30.067853 23955 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:30.070084 24424 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:20:30.070154 24425 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:20:30.070159 23955 server_base.cc:1061] running on GCE node
W20260812 06:20:30.070232 24428 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:20:30.070497 23955 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:30.070539 23955 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:20:30.070555 23955 hybrid_clock.cc:648] HybridClock initialized: now 1786515630070556 us; error 0 us; skew 500 ppm
I20260812 06:20:30.071506 23955 webserver.cc:533] Webserver started at http://127.23.100.193:45977/ using document root <none> and password file <none>
I20260812 06:20:30.071648 23955 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:30.071693 23955 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:30.071748 23955 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:30.072118 23955 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/instance:
uuid: "86911771bdf04542abe0557f58d282d1"
format_stamp: "Formatted at 2026-08-12 06:20:30 on dist-test-slave-twwt"
I20260812 06:20:30.073645 23955 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:30.074563 24438 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:20:30.074862 23955 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:30.074956 23955 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root
uuid: "86911771bdf04542abe0557f58d282d1"
format_stamp: "Formatted at 2026-08-12 06:20:30 on dist-test-slave-twwt"
I20260812 06:20:30.075048 23955 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-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:20:30.107394 23955 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:30.107896 23955 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:30.108245 23955 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:30.108762 23955 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:30.108826 23955 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:30.108882 23955 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:30.108942 23955 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:30.113549 23955 rpc_server.cc:307] RPC server started. Bound to: 127.23.100.193:36505
I20260812 06:20:30.113575 24544 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.100.193:36505 every 8 connection(s)
I20260812 06:20:30.123955 24546 heartbeater.cc:344] Connected to a master server at 127.23.100.254:32973
I20260812 06:20:30.124125 24546 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:30.124464 24546 heartbeater.cc:507] Master 127.23.100.254:32973 requested a full tablet report, sending...
I20260812 06:20:30.125253 24336 ts_manager.cc:194] Registered new tserver with Master: 86911771bdf04542abe0557f58d282d1 (127.23.100.193:36505)
I20260812 06:20:30.126017 24336 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49940
I20260812 06:20:30.126214 23955 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012185532s
I20260812 06:20:30.133786 24336 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49944:
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:20:30.142877 24487 tablet_service.cc:1511] Processing CreateTablet for tablet 47d8d71f37384d21a23893afbd9e8ac0 (DEFAULT_TABLE table=heavy-update-compaction-test [id=38c1f01eefa84b65823b610bff2d66e0]), partition=
I20260812 06:20:30.143147 24487 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 47d8d71f37384d21a23893afbd9e8ac0. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:30.145080 24571 tablet_bootstrap.cc:492] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Bootstrap starting.
I20260812 06:20:30.145954 24571 tablet_bootstrap.cc:654] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:30.147048 24571 tablet_bootstrap.cc:492] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: No bootstrap required, opened a new log
I20260812 06:20:30.147130 24571 ts_tablet_manager.cc:1403] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:20:30.147511 24571 raft_consensus.cc:359] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "86911771bdf04542abe0557f58d282d1" member_type: VOTER last_known_addr { host: "127.23.100.193" port: 36505 } }
I20260812 06:20:30.147599 24571 raft_consensus.cc:385] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:30.147621 24571 raft_consensus.cc:740] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 86911771bdf04542abe0557f58d282d1, State: Initialized, Role: FOLLOWER
I20260812 06:20:30.147760 24571 consensus_queue.cc:260] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [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: "86911771bdf04542abe0557f58d282d1" member_type: VOTER last_known_addr { host: "127.23.100.193" port: 36505 } }
I20260812 06:20:30.147852 24571 raft_consensus.cc:399] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:30.147878 24571 raft_consensus.cc:493] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:30.147909 24571 raft_consensus.cc:3060] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:30.148869 24571 raft_consensus.cc:515] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "86911771bdf04542abe0557f58d282d1" member_type: VOTER last_known_addr { host: "127.23.100.193" port: 36505 } }
I20260812 06:20:30.149031 24571 leader_election.cc:304] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [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: 86911771bdf04542abe0557f58d282d1; no voters: 
I20260812 06:20:30.149258 24571 leader_election.cc:290] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:30.149403 24574 raft_consensus.cc:2804] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:30.149610 24571 ts_tablet_manager.cc:1434] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:30.149631 24574 raft_consensus.cc:697] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [term 1 LEADER]: Becoming Leader. State: Replica: 86911771bdf04542abe0557f58d282d1, State: Running, Role: LEADER
I20260812 06:20:30.149646 24546 heartbeater.cc:499] Master 127.23.100.254:32973 was elected leader, sending a full tablet report...
I20260812 06:20:30.149778 24574 consensus_queue.cc:237] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [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: "86911771bdf04542abe0557f58d282d1" member_type: VOTER last_known_addr { host: "127.23.100.193" port: 36505 } }
I20260812 06:20:30.151157 24336 catalog_manager.cc:5719] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 reported cstate change: term changed from 0 to 1, leader changed from <none> to 86911771bdf04542abe0557f58d282d1 (127.23.100.193). New cstate: current_term: 1 leader_uuid: "86911771bdf04542abe0557f58d282d1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "86911771bdf04542abe0557f58d282d1" member_type: VOTER last_known_addr { host: "127.23.100.193" port: 36505 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:30.214931 23955 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.015s	sys 0.008s
I20260812 06:20:30.364555 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushMRSOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=19.054940
I20260812 06:20:30.532992 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushMRSOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.168s	user 0.114s	sys 0.051s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":195,"dirs.run_wall_time_us":927,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39865,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:20:30.533964 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling LogGCOp(47d8d71f37384d21a23893afbd9e8ac0): free 20743831 bytes of WAL
I20260812 06:20:30.534245 24449 log_reader.cc:385] T 47d8d71f37384d21a23893afbd9e8ac0: removed 2 log segments from log reader
I20260812 06:20:30.534350 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000001 (ops 1-6)
I20260812 06:20:30.534439 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000002 (ops 7-11)
I20260812 06:20:30.539039 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: LogGCOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:20:30.539485 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:30.552974 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.553606 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:30.727499 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.174s	user 0.110s	sys 0.059s 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":756,"lbm_read_time_us":11899,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27844,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":330,"threads_started":5,"update_count":2000}
I20260812 06:20:30.728231 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling UndoDeltaBlockGCOp(47d8d71f37384d21a23893afbd9e8ac0): 16411394 bytes on disk
I20260812 06:20:30.729009 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: UndoDeltaBlockGCOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:20:30.729585 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=11.118625
I20260812 06:20:30.765484 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.036s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15224,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:30.766207 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:30.783290 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":5415,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:20:30.783883 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:30.932581 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.148s	user 0.122s	sys 0.023s Metrics: {"cfile_cache_miss":435,"cfile_cache_miss_bytes":20795347,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":614,"lbm_read_time_us":10603,"lbm_reads_lt_1ms":467,"lbm_write_time_us":28696,"lbm_writes_lt_1ms":446,"mutex_wait_us":147,"peak_mem_usage":50812433,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2015}
I20260812 06:20:30.933341 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=11.118625
I20260812 06:20:30.970019 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.036s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12594664,"delete_count":0,"lbm_write_time_us":15930,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1535}
I20260812 06:20:30.970722 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:30.986914 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5916,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:30.987532 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:31.119069 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.131s	user 0.101s	sys 0.028s Metrics: {"cfile_cache_miss":429,"cfile_cache_miss_bytes":20549197,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":291,"lbm_read_time_us":10479,"lbm_reads_lt_1ms":461,"lbm_write_time_us":24440,"lbm_writes_lt_1ms":440,"mutex_wait_us":44,"peak_mem_usage":49525839,"reinsert_count":0,"spinlock_wait_cycles":64640,"update_count":1985}
I20260812 06:20:31.120142 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=10.126437
I20260812 06:20:31.169008 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.049s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17951,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:31.169540 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:31.182337 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4450,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.183156 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:31.341063 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.158s	user 0.109s	sys 0.048s 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":616,"lbm_read_time_us":11019,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32720,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":77952,"update_count":2000}
I20260812 06:20:31.342365 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=10.126437
I20260812 06:20:31.389478 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.047s	user 0.017s	sys 0.027s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15986,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:31.390126 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:31.402777 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.012s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4419,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.403687 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:31.559504 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.156s	user 0.097s	sys 0.058s 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":1065,"lbm_read_time_us":11669,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25208,"lbm_writes_lt_1ms":443,"mutex_wait_us":550,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":944640,"update_count":2000}
I20260812 06:20:31.560386 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=10.126437
I20260812 06:20:31.597311 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.037s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16062,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:31.597888 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:31.609493 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4519,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.610159 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:31.746145 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.136s	user 0.111s	sys 0.024s 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":786,"lbm_read_time_us":10040,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26982,"lbm_writes_lt_1ms":443,"mutex_wait_us":376,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:20:31.746907 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=10.126437
I20260812 06:20:31.788429 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.041s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16653,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:31.788977 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushMRSOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:31.827942 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushMRSOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.039s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":122,"dirs.run_cpu_time_us":333,"dirs.run_wall_time_us":1401,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2181,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":1920}
I20260812 06:20:31.828840 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling UndoDeltaBlockGCOp(47d8d71f37384d21a23893afbd9e8ac0): 447 bytes on disk
I20260812 06:20:31.829267 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: UndoDeltaBlockGCOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:20:31.829743 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=3.181125
I20260812 06:20:31.842948 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4732,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:31.843432 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling LogGCOp(47d8d71f37384d21a23893afbd9e8ac0): free 112692424 bytes of WAL
I20260812 06:20:31.843668 24449 log_reader.cc:385] T 47d8d71f37384d21a23893afbd9e8ac0: removed 11 log segments from log reader
I20260812 06:20:31.843712 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000003 (ops 12-16)
I20260812 06:20:31.843775 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000004 (ops 17-21)
I20260812 06:20:31.843819 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000005 (ops 22-26)
I20260812 06:20:31.843883 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000006 (ops 27-31)
I20260812 06:20:31.843923 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000007 (ops 32-36)
I20260812 06:20:31.843984 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000008 (ops 37-41)
I20260812 06:20:31.844019 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000009 (ops 42-46)
I20260812 06:20:31.844058 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000010 (ops 47-51)
I20260812 06:20:31.844096 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000011 (ops 52-56)
I20260812 06:20:31.844134 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000012 (ops 57-61)
I20260812 06:20:31.844173 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000013 (ops 62-66)
I20260812 06:20:31.870625 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: LogGCOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.027s	user 0.001s	sys 0.022s Metrics: {}
I20260812 06:20:31.871093 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:31.892174 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.021s	user 0.003s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6582,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.892733 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:31.902856 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3735,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:31.903338 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:32.094894 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.191s	user 0.133s	sys 0.055s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":763,"lbm_read_time_us":14232,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36673,"lbm_writes_lt_1ms":643,"mutex_wait_us":359,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:20:32.095728 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=14.095187
I20260812 06:20:32.150203 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.054s	user 0.029s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25228,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.150800 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:32.165247 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.165879 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:32.327395 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.161s	user 0.117s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":326,"lbm_read_time_us":12497,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31264,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:20:32.328052 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=14.095187
I20260812 06:20:32.389391 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.061s	user 0.025s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25458,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.389994 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:32.402657 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.012s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4268,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.403410 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:32.568297 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.165s	user 0.116s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":362,"lbm_read_time_us":10990,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29924,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":92416,"update_count":2500}
I20260812 06:20:32.569061 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=14.095187
I20260812 06:20:32.635967 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.067s	user 0.039s	sys 0.016s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":25272,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.636555 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:32.649778 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4341,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.650476 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:32.828171 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.177s	user 0.132s	sys 0.045s 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":260,"lbm_read_time_us":14630,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29848,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:32.829047 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=14.095187
I20260812 06:20:32.885941 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.057s	user 0.019s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19263,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.886543 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:32.899995 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.013s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.900763 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:33.092178 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.191s	user 0.148s	sys 0.043s 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":313,"lbm_read_time_us":14802,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33660,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2500}
I20260812 06:20:33.092760 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=14.095187
I20260812 06:20:33.159114 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.066s	user 0.030s	sys 0.036s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22537,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.159858 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:33.178870 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.019s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.179558 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:33.378827 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.199s	user 0.112s	sys 0.080s 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":317,"lbm_read_time_us":13483,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34805,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:20:33.379642 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=14.095187
I20260812 06:20:33.424973 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.045s	user 0.032s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18775,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.425619 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushMRSOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:33.472977 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushMRSOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.047s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":246,"dirs.run_wall_time_us":1358,"drs_written":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1777,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:33.473939 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=3.181125
I20260812 06:20:33.488646 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4389828,"delete_count":0,"lbm_write_time_us":4937,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:20:33.489151 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling LogGCOp(47d8d71f37384d21a23893afbd9e8ac0): free 136728183 bytes of WAL
I20260812 06:20:33.489408 24449 log_reader.cc:385] T 47d8d71f37384d21a23893afbd9e8ac0: removed 13 log segments from log reader
I20260812 06:20:33.489454 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000014 (ops 67-71)
I20260812 06:20:33.489485 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000015 (ops 72-76)
I20260812 06:20:33.489552 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000016 (ops 77-81)
I20260812 06:20:33.489622 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000017 (ops 82-86)
I20260812 06:20:33.489684 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000018 (ops 87-91)
I20260812 06:20:33.489723 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000019 (ops 92-96)
I20260812 06:20:33.489766 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000020 (ops 97-101)
I20260812 06:20:33.489804 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000021 (ops 102-106)
I20260812 06:20:33.489842 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000022 (ops 107-111)
I20260812 06:20:33.489887 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000023 (ops 112-116)
I20260812 06:20:33.489928 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000024 (ops 117-121)
I20260812 06:20:33.489966 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000025 (ops 122-126)
I20260812 06:20:33.490005 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000026 (ops 127-131)
I20260812 06:20:33.521287 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: LogGCOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:33.521807 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=3.181125
I20260812 06:20:33.544139 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.022s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4225735,"delete_count":0,"lbm_write_time_us":6956,"lbm_writes_lt_1ms":106,"reinsert_count":0,"update_count":515}
I20260812 06:20:33.544642 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling UndoDeltaBlockGCOp(47d8d71f37384d21a23893afbd9e8ac0): 493 bytes on disk
I20260812 06:20:33.545110 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: UndoDeltaBlockGCOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:20:33.545640 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:33.556402 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:33.557318 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:33.825485 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.268s	user 0.171s	sys 0.085s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":694,"lbm_read_time_us":17991,"lbm_reads_lt_1ms":774,"lbm_write_time_us":45840,"lbm_writes_lt_1ms":743,"mutex_wait_us":55,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12160,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:20:33.826478 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=18.063937
I20260812 06:20:33.900476 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.073s	user 0.029s	sys 0.036s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":28924,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:20:33.901048 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:33.914003 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4397,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.914680 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:34.138389 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.224s	user 0.135s	sys 0.086s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":910,"lbm_read_time_us":15473,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36181,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:20:34.139190 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=16.079562
I20260812 06:20:34.193184 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.054s	user 0.036s	sys 0.015s Metrics: {"bytes_written":17763702,"delete_count":0,"lbm_write_time_us":24020,"lbm_writes_lt_1ms":436,"reinsert_count":0,"update_count":2165}
I20260812 06:20:34.193989 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.196750
I20260812 06:20:34.213716 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.020s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":3453,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:20:34.214205 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:34.225274 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4115,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:34.225809 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:34.449446 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.223s	user 0.157s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877191,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":224,"lbm_read_time_us":15677,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35949,"lbm_writes_lt_1ms":643,"mutex_wait_us":101,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":3000}
I20260812 06:20:34.450321 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=18.063937
I20260812 06:20:34.521844 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.071s	user 0.040s	sys 0.015s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26458,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:34.522492 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:34.539921 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.017s	user 0.010s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6645,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:34.540553 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:34.772219 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.231s	user 0.148s	sys 0.071s 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":1714,"lbm_read_time_us":15358,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37403,"lbm_writes_lt_1ms":643,"mutex_wait_us":486,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":3000}
I20260812 06:20:34.773037 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=18.063937
I20260812 06:20:34.851631 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.078s	user 0.045s	sys 0.031s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":36077,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:20:34.852240 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:34.866120 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5131,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:34.866791 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:35.098557 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.232s	user 0.135s	sys 0.096s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1079,"lbm_read_time_us":16202,"lbm_reads_lt_1ms":672,"lbm_write_time_us":44602,"lbm_writes_lt_1ms":643,"mutex_wait_us":364,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":3000}
I20260812 06:20:35.099447 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=18.063937
I20260812 06:20:35.172314 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.073s	user 0.017s	sys 0.043s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":27778,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:35.172935 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=2.188937
I20260812 06:20:35.185127 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4362,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:35.185771 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushMRSOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:35.216482 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushMRSOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.031s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":102,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1768,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1695,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:35.217185 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling LogGCOp(47d8d71f37384d21a23893afbd9e8ac0): free 132571656 bytes of WAL
I20260812 06:20:35.217447 24449 log_reader.cc:385] T 47d8d71f37384d21a23893afbd9e8ac0: removed 13 log segments from log reader
I20260812 06:20:35.217514 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000027 (ops 132-136)
I20260812 06:20:35.217566 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000028 (ops 137-140)
I20260812 06:20:35.217626 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000029 (ops 141-145)
I20260812 06:20:35.217670 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000030 (ops 146-150)
I20260812 06:20:35.217708 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000031 (ops 151-155)
I20260812 06:20:35.217748 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000032 (ops 156-160)
I20260812 06:20:35.217788 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000033 (ops 161-165)
I20260812 06:20:35.217828 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000034 (ops 166-170)
I20260812 06:20:35.217868 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000035 (ops 171-175)
I20260812 06:20:35.217907 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000036 (ops 176-180)
I20260812 06:20:35.217945 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000037 (ops 181-185)
I20260812 06:20:35.217986 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000038 (ops 186-190)
I20260812 06:20:35.218026 24449 log.cc:1079] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: Deleting log segment in path: /tmp/dist-test-taskL8wV0J/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515624011467-23955-0/minicluster-data/ts-0-root/wals/47d8d71f37384d21a23893afbd9e8ac0/wal-000000039 (ops 191-194)
I20260812 06:20:35.250540 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: LogGCOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.033s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:35.251085 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling UndoDeltaBlockGCOp(47d8d71f37384d21a23893afbd9e8ac0): 493 bytes on disk
I20260812 06:20:35.251550 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: UndoDeltaBlockGCOp(47d8d71f37384d21a23893afbd9e8ac0) 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:20:35.252090 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=5.165500
I20260812 06:20:35.278780 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: FlushDeltaMemStoresOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.027s	user 0.018s	sys 0.007s Metrics: {"bytes_written":7302546,"delete_count":0,"lbm_write_time_us":10206,"lbm_writes_lt_1ms":181,"mutex_wait_us":899,"reinsert_count":0,"update_count":890}
I20260812 06:20:35.279587 24548 maintenance_manager.cc:419] P 86911771bdf04542abe0557f58d282d1: Scheduling MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0): perf score=1.000000
I20260812 06:20:35.354475 23955 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.139s	user 1.887s	sys 0.196s
I20260812 06:20:35.458451 23955 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.103s	user 0.001s	sys 0.000s
I20260812 06:20:35.459064 23955 tablet_server.cc:179] TabletServer@127.23.100.193:0 shutting down...
I20260812 06:20:35.504671 24449 maintenance_manager.cc:643] P 86911771bdf04542abe0557f58d282d1: MajorDeltaCompactionOp(47d8d71f37384d21a23893afbd9e8ac0) complete. Timing: real 0.225s	user 0.140s	sys 0.085s Metrics: {"cfile_cache_miss":811,"cfile_cache_miss_bytes":36179516,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":281,"lbm_read_time_us":17856,"lbm_reads_lt_1ms":843,"lbm_write_time_us":40700,"lbm_writes_lt_1ms":821,"mutex_wait_us":63,"peak_mem_usage":97412078,"reinsert_count":0,"spinlock_wait_cycles":11904,"thread_start_us":84,"threads_started":1,"update_count":3890}
I20260812 06:20:35.506651 23955 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:35.507164 23955 tablet_replica.cc:333] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1: stopping tablet replica
I20260812 06:20:35.507336 23955 raft_consensus.cc:2243] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:35.507540 23955 raft_consensus.cc:2272] T 47d8d71f37384d21a23893afbd9e8ac0 P 86911771bdf04542abe0557f58d282d1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:35.524327 23955 tablet_server.cc:196] TabletServer@127.23.100.193:0 shutdown complete.
I20260812 06:20:35.573447 23955 master.cc:562] Master@127.23.100.254:32973 shutting down...
I20260812 06:20:35.577008 23955 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:35.577221 23955 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:35.577314 23955 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4555b84f76e0449b9c73c36dfa37094e: stopping tablet replica
I20260812 06:20:35.589797 23955 master.cc:584] Master@127.23.100.254:32973 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5702 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11661 ms total)

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