[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:40.634670  9911 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.173.254:43441
I20260812 06:19:40.635668  9911 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:40.636333  9911 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:40.642892  9918 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:40.642985  9920 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:40.643177  9917 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:40.642966  9911 server_base.cc:1061] running on GCE node
I20260812 06:19:40.643702  9911 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:40.643833  9911 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:40.643888  9911 hybrid_clock.cc:648] HybridClock initialized: now 1786515580643886 us; error 0 us; skew 500 ppm
I20260812 06:19:40.645782  9911 webserver.cc:533] Webserver started at http://127.9.173.254:33151/ using document root <none> and password file <none>
I20260812 06:19:40.646382  9911 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:40.646476  9911 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:40.646734  9911 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:40.648517  9911 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/master-0-root/instance:
uuid: "888027b75d22417a86cd678010b06db0"
format_stamp: "Formatted at 2026-08-12 06:19:40 on dist-test-slave-0b58"
I20260812 06:19:40.651876  9911 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:40.654563  9927 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:40.658280  9911 fs_manager.cc:730] Time spent opening block manager: real 0.005s	user 0.002s	sys 0.003s
I20260812 06:19:40.658432  9911 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/master-0-root
uuid: "888027b75d22417a86cd678010b06db0"
format_stamp: "Formatted at 2026-08-12 06:19:40 on dist-test-slave-0b58"
I20260812 06:19:40.658548  9911 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:40.676388  9911 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:40.677074  9911 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:40.677310  9911 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:40.685120  9911 rpc_server.cc:307] RPC server started. Bound to: 127.9.173.254:43441
I20260812 06:19:40.685134  9986 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.173.254:43441 every 8 connection(s)
I20260812 06:19:40.687387  9987 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:40.692804  9987 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0: Bootstrap starting.
I20260812 06:19:40.695120  9987 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:40.696045  9987 log.cc:826] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:40.697794  9987 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0: No bootstrap required, opened a new log
I20260812 06:19:40.700543  9987 raft_consensus.cc:359] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "888027b75d22417a86cd678010b06db0" member_type: VOTER }
I20260812 06:19:40.700700  9987 raft_consensus.cc:385] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:40.700829  9987 raft_consensus.cc:740] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 888027b75d22417a86cd678010b06db0, State: Initialized, Role: FOLLOWER
I20260812 06:19:40.701427  9987 consensus_queue.cc:260] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [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: "888027b75d22417a86cd678010b06db0" member_type: VOTER }
I20260812 06:19:40.701589  9987 raft_consensus.cc:399] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:40.701663  9987 raft_consensus.cc:493] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:40.701834  9987 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:40.702641  9987 raft_consensus.cc:515] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "888027b75d22417a86cd678010b06db0" member_type: VOTER }
I20260812 06:19:40.703083  9987 leader_election.cc:304] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [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: 888027b75d22417a86cd678010b06db0; no voters: 
I20260812 06:19:40.703439  9987 leader_election.cc:290] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:40.703563  9991 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:40.703873  9991 raft_consensus.cc:697] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [term 1 LEADER]: Becoming Leader. State: Replica: 888027b75d22417a86cd678010b06db0, State: Running, Role: LEADER
I20260812 06:19:40.704346  9991 consensus_queue.cc:237] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [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: "888027b75d22417a86cd678010b06db0" member_type: VOTER }
I20260812 06:19:40.704532  9987 sys_catalog.cc:565] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:40.706395  9993 sys_catalog.cc:455] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 888027b75d22417a86cd678010b06db0. Latest consensus state: current_term: 1 leader_uuid: "888027b75d22417a86cd678010b06db0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "888027b75d22417a86cd678010b06db0" member_type: VOTER } }
I20260812 06:19:40.706421  9992 sys_catalog.cc:455] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "888027b75d22417a86cd678010b06db0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "888027b75d22417a86cd678010b06db0" member_type: VOTER } }
I20260812 06:19:40.706537  9992 sys_catalog.cc:458] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:40.706537  9993 sys_catalog.cc:458] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:40.706933  9911 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:40.709059 10007 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:40.709146 10007 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:40.709206 10006 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:40.709904 10006 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:40.714397 10006 catalog_manager.cc:1383] Generated new cluster ID: ebfc0bd2259d4bbb867a6e4f3198f7c7
I20260812 06:19:40.714459 10006 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:40.724752 10006 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:40.725554 10006 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:40.731801 10006 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0: Generated new TSK 0
I20260812 06:19:40.732506 10006 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:40.739636  9911 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:40.742658 10014 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:40.742846 10011 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:40.743054  9911 server_base.cc:1061] running on GCE node
W20260812 06:19:40.742903 10012 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:40.743374  9911 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:40.743448  9911 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:40.743479  9911 hybrid_clock.cc:648] HybridClock initialized: now 1786515580743477 us; error 0 us; skew 500 ppm
I20260812 06:19:40.744627  9911 webserver.cc:533] Webserver started at http://127.9.173.193:42743/ using document root <none> and password file <none>
I20260812 06:19:40.744827  9911 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:40.744908  9911 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:40.744997  9911 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:40.745486  9911 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/instance:
uuid: "9ae7cf88bb4c497893e9faf912cb9c92"
format_stamp: "Formatted at 2026-08-12 06:19:40 on dist-test-slave-0b58"
I20260812 06:19:40.747180  9911 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:40.748426 10019 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:40.748718  9911 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:40.748802  9911 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root
uuid: "9ae7cf88bb4c497893e9faf912cb9c92"
format_stamp: "Formatted at 2026-08-12 06:19:40 on dist-test-slave-0b58"
I20260812 06:19:40.748916  9911 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:40.769030  9911 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:40.769587  9911 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:40.770171  9911 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:40.771095  9911 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:40.771148  9911 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:40.771225  9911 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:40.771275  9911 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:40.778997  9911 rpc_server.cc:307] RPC server started. Bound to: 127.9.173.193:36579
I20260812 06:19:40.779032 10089 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.173.193:36579 every 8 connection(s)
I20260812 06:19:40.790704 10090 heartbeater.cc:344] Connected to a master server at 127.9.173.254:43441
I20260812 06:19:40.791007 10090 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:40.791517 10090 heartbeater.cc:507] Master 127.9.173.254:43441 requested a full tablet report, sending...
I20260812 06:19:40.793197  9944 ts_manager.cc:194] Registered new tserver with Master: 9ae7cf88bb4c497893e9faf912cb9c92 (127.9.173.193:36579)
I20260812 06:19:40.793331  9911 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013583319s
I20260812 06:19:40.794762  9944 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46450
I20260812 06:19:40.803434  9944 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46454:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:40.818418 10053 tablet_service.cc:1511] Processing CreateTablet for tablet 194a9b99c9874a4c80914142af4cca13 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ea7f9fa3dbc943f783a07aa70678cbf9]), partition=
I20260812 06:19:40.818907 10053 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 194a9b99c9874a4c80914142af4cca13. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:40.821820 10106 tablet_bootstrap.cc:492] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Bootstrap starting.
I20260812 06:19:40.822722 10106 tablet_bootstrap.cc:654] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:40.823874 10106 tablet_bootstrap.cc:492] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: No bootstrap required, opened a new log
I20260812 06:19:40.824002 10106 ts_tablet_manager.cc:1403] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:40.824582 10106 raft_consensus.cc:359] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ae7cf88bb4c497893e9faf912cb9c92" member_type: VOTER last_known_addr { host: "127.9.173.193" port: 36579 } }
I20260812 06:19:40.824707 10106 raft_consensus.cc:385] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:40.824754 10106 raft_consensus.cc:740] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9ae7cf88bb4c497893e9faf912cb9c92, State: Initialized, Role: FOLLOWER
I20260812 06:19:40.824920 10106 consensus_queue.cc:260] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [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: "9ae7cf88bb4c497893e9faf912cb9c92" member_type: VOTER last_known_addr { host: "127.9.173.193" port: 36579 } }
I20260812 06:19:40.825035 10106 raft_consensus.cc:399] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:40.825081 10106 raft_consensus.cc:493] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:40.825150 10106 raft_consensus.cc:3060] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:40.826069 10106 raft_consensus.cc:515] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ae7cf88bb4c497893e9faf912cb9c92" member_type: VOTER last_known_addr { host: "127.9.173.193" port: 36579 } }
I20260812 06:19:40.826233 10106 leader_election.cc:304] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [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: 9ae7cf88bb4c497893e9faf912cb9c92; no voters: 
I20260812 06:19:40.826505 10106 leader_election.cc:290] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:40.826606 10108 raft_consensus.cc:2804] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:40.826865 10106 ts_tablet_manager.cc:1434] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:40.826907 10108 raft_consensus.cc:697] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [term 1 LEADER]: Becoming Leader. State: Replica: 9ae7cf88bb4c497893e9faf912cb9c92, State: Running, Role: LEADER
I20260812 06:19:40.827121 10090 heartbeater.cc:499] Master 127.9.173.254:43441 was elected leader, sending a full tablet report...
I20260812 06:19:40.827292 10108 consensus_queue.cc:237] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [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: "9ae7cf88bb4c497893e9faf912cb9c92" member_type: VOTER last_known_addr { host: "127.9.173.193" port: 36579 } }
I20260812 06:19:40.830186  9944 catalog_manager.cc:5719] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 reported cstate change: term changed from 0 to 1, leader changed from <none> to 9ae7cf88bb4c497893e9faf912cb9c92 (127.9.173.193). New cstate: current_term: 1 leader_uuid: "9ae7cf88bb4c497893e9faf912cb9c92" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ae7cf88bb4c497893e9faf912cb9c92" member_type: VOTER last_known_addr { host: "127.9.173.193" port: 36579 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:40.904224  9911 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.066s	user 0.017s	sys 0.016s
I20260812 06:19:41.030228 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushMRSOp(194a9b99c9874a4c80914142af4cca13): perf score=15.086190
I20260812 06:19:41.191294 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushMRSOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.161s	user 0.130s	sys 0.025s Metrics: {"bytes_written":12307493,"cfile_init":1,"compiler_manager_pool.queue_time_us":181,"delete_count":0,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":1112,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42251,"lbm_writes_lt_1ms":667,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":115,"threads_started":1,"update_count":1500}
I20260812 06:19:41.192529 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling LogGCOp(194a9b99c9874a4c80914142af4cca13): free 20743880 bytes of WAL
I20260812 06:19:41.192881 10027 log_reader.cc:385] T 194a9b99c9874a4c80914142af4cca13: removed 2 log segments from log reader
I20260812 06:19:41.192999 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000001 (ops 1-6)
I20260812 06:19:41.193106 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000002 (ops 7-11)
I20260812 06:19:41.198958 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: LogGCOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:41.199381 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:41.215570 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.016s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5525,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.216017 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling UndoDeltaBlockGCOp(194a9b99c9874a4c80914142af4cca13): 12719216 bytes on disk
I20260812 06:19:41.216694 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: UndoDeltaBlockGCOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:19:41.217119 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:41.232178 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5493,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:41.232803 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:41.395951 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.163s	user 0.123s	sys 0.035s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364557,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1124,"lbm_read_time_us":10777,"lbm_reads_lt_1ms":559,"lbm_write_time_us":27644,"lbm_writes_lt_1ms":533,"mutex_wait_us":315,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":289,"threads_started":5,"update_count":2450}
I20260812 06:19:41.396517 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=10.126437
I20260812 06:19:41.437701 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.041s	user 0.019s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14570,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.438170 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:41.453517 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5707,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.454092 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:41.578768 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.124s	user 0.105s	sys 0.020s 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":300,"lbm_read_time_us":8428,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24868,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24960,"update_count":2000}
I20260812 06:19:41.579347 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=10.126437
I20260812 06:19:41.619174 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.040s	user 0.031s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14725,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.619654 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:41.634917 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5678,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.635452 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:41.770504 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.135s	user 0.112s	sys 0.022s 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":939,"lbm_read_time_us":8703,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28769,"lbm_writes_lt_1ms":443,"mutex_wait_us":298,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:19:41.770967 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=10.126437
I20260812 06:19:41.824597 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.053s	user 0.030s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17250,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.825171 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:41.836484 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4235,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.836915 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:41.992017 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.155s	user 0.094s	sys 0.057s 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":387,"lbm_read_time_us":11625,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24646,"lbm_writes_lt_1ms":443,"mutex_wait_us":104,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:19:41.992681 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=10.126437
I20260812 06:19:42.038928 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.045s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15006,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:19:42.039415 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:42.050184 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.050942 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:42.176594 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.125s	user 0.102s	sys 0.023s 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":345,"lbm_read_time_us":8787,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24637,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2000}
I20260812 06:19:42.177479 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=10.126437
I20260812 06:19:42.213061 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.035s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15262,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.213596 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:42.229820 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6266,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.230444 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:42.352890 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.122s	user 0.102s	sys 0.020s 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":360,"lbm_read_time_us":9183,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23450,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:42.353649 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=10.126437
I20260812 06:19:42.390473 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.037s	user 0.013s	sys 0.021s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":15647,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.391211 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:42.403084 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.012s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4009,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.403668 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushMRSOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:42.430205 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushMRSOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.026s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1372,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1731,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:42.431038 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling LogGCOp(194a9b99c9874a4c80914142af4cca13): free 111786258 bytes of WAL
I20260812 06:19:42.431257 10027 log_reader.cc:385] T 194a9b99c9874a4c80914142af4cca13: removed 11 log segments from log reader
I20260812 06:19:42.431301 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000003 (ops 12-16)
I20260812 06:19:42.431329 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000004 (ops 17-20)
I20260812 06:19:42.431391 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000005 (ops 21-25)
I20260812 06:19:42.431432 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000006 (ops 26-30)
I20260812 06:19:42.431474 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000007 (ops 31-34)
I20260812 06:19:42.431509 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000008 (ops 35-39)
I20260812 06:19:42.431545 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000009 (ops 40-44)
I20260812 06:19:42.431583 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000010 (ops 45-49)
I20260812 06:19:42.431620 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000011 (ops 50-54)
I20260812 06:19:42.431665 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000012 (ops 55-59)
I20260812 06:19:42.431706 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000013 (ops 60-64)
I20260812 06:19:42.456825 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: LogGCOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:42.457221 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling UndoDeltaBlockGCOp(194a9b99c9874a4c80914142af4cca13): 447 bytes on disk
I20260812 06:19:42.457635 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: UndoDeltaBlockGCOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:42.458230 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=3.181125
I20260812 06:19:42.471045 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":5087238,"delete_count":0,"lbm_write_time_us":5163,"lbm_writes_lt_1ms":127,"reinsert_count":0,"update_count":620}
I20260812 06:19:42.471541 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=1.196750
I20260812 06:19:42.481547 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":3046,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:19:42.482148 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:42.656854 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.174s	user 0.118s	sys 0.051s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877319,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1736,"lbm_read_time_us":10340,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36762,"lbm_writes_lt_1ms":643,"mutex_wait_us":1133,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12800,"thread_start_us":94,"threads_started":1,"update_count":3000}
I20260812 06:19:42.657647 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=14.095187
I20260812 06:19:42.706802 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.049s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18932,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.707271 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:42.717950 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4017,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.718616 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:42.875777 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.157s	user 0.105s	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":450,"lbm_read_time_us":9119,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28119,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:19:42.876535 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=14.095187
I20260812 06:19:42.926895 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.050s	user 0.030s	sys 0.014s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20837,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.927383 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:43.082141 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.155s	user 0.109s	sys 0.035s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":613,"lbm_read_time_us":9675,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26233,"lbm_writes_lt_1ms":443,"mutex_wait_us":297,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2000}
I20260812 06:19:43.082901 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=14.095187
I20260812 06:19:43.130079 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.047s	user 0.025s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20395,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.130618 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:43.142936 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4954,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.143617 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:43.332381 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.188s	user 0.100s	sys 0.077s 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":775,"lbm_read_time_us":11439,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30413,"lbm_writes_lt_1ms":543,"mutex_wait_us":338,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:19:43.333122 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=14.095187
I20260812 06:19:43.378880 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.046s	user 0.018s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20274,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.379406 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:43.396557 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6406,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.397105 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:43.559995 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.163s	user 0.114s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":225,"lbm_read_time_us":9879,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30426,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:19:43.560627 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=14.095187
I20260812 06:19:43.609716 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.049s	user 0.022s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19296,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.610160 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:43.621517 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4203,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.622064 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:43.771227 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.149s	user 0.096s	sys 0.045s 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":612,"lbm_read_time_us":10113,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30186,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:19:43.771922 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=14.095187
I20260812 06:19:43.826522 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.054s	user 0.040s	sys 0.007s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":21835,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.827171 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:43.839455 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.840034 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushMRSOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:43.870455 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushMRSOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.030s	user 0.025s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1101,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2091,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:43.871234 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling LogGCOp(194a9b99c9874a4c80914142af4cca13): free 133024374 bytes of WAL
I20260812 06:19:43.871523 10027 log_reader.cc:385] T 194a9b99c9874a4c80914142af4cca13: removed 13 log segments from log reader
I20260812 06:19:43.871585 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000014 (ops 65-69)
I20260812 06:19:43.871626 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000015 (ops 70-74)
I20260812 06:19:43.871657 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000016 (ops 75-79)
I20260812 06:19:43.871686 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000017 (ops 80-84)
I20260812 06:19:43.871713 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000018 (ops 85-89)
I20260812 06:19:43.871743 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000019 (ops 90-94)
I20260812 06:19:43.871776 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000020 (ops 95-99)
I20260812 06:19:43.871804 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000021 (ops 100-104)
I20260812 06:19:43.871830 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000022 (ops 105-108)
I20260812 06:19:43.871858 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000023 (ops 109-113)
I20260812 06:19:43.871886 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000024 (ops 114-118)
I20260812 06:19:43.871915 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000025 (ops 119-123)
I20260812 06:19:43.871948 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000026 (ops 124-128)
I20260812 06:19:43.905100 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: LogGCOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.034s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:19:43.905519 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=3.181125
I20260812 06:19:43.924441 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.019s	user 0.013s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7419,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:43.924888 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling UndoDeltaBlockGCOp(194a9b99c9874a4c80914142af4cca13): 483 bytes on disk
I20260812 06:19:43.925288 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: UndoDeltaBlockGCOp(194a9b99c9874a4c80914142af4cca13) 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:19:43.925796 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:43.935295 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3639,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.935757 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:44.160770 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.225s	user 0.141s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979743,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1658,"lbm_read_time_us":14014,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39706,"lbm_writes_lt_1ms":743,"mutex_wait_us":804,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":97,"threads_started":1,"update_count":3500}
I20260812 06:19:44.161751 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=15.087375
I20260812 06:19:44.227109 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.065s	user 0.028s	sys 0.030s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23228,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:19:44.227615 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=3.181125
I20260812 06:19:44.244438 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4553926,"delete_count":0,"lbm_write_time_us":6999,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:19:44.244863 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:44.253634 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":3351,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:19:44.254102 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:44.442798 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.189s	user 0.126s	sys 0.062s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877198,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":296,"lbm_read_time_us":13797,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33164,"lbm_writes_lt_1ms":643,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":3000}
I20260812 06:19:44.443434 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=14.095187
I20260812 06:19:44.501308 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.058s	user 0.034s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20931,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.501828 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:44.512820 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.513255 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:44.687047 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.174s	user 0.118s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":250,"lbm_read_time_us":12592,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27134,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29056,"update_count":2500}
I20260812 06:19:44.687732 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=14.095187
I20260812 06:19:44.746032 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.058s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20808,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.746735 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:44.758427 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4394,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.758978 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:44.948537 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.189s	user 0.120s	sys 0.060s 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":269,"lbm_read_time_us":14413,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31326,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":68096,"update_count":2500}
I20260812 06:19:44.949301 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=14.095187
I20260812 06:19:45.009039 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.059s	user 0.030s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22022,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.009614 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:45.020383 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4119,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.020891 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:45.186618 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.166s	user 0.103s	sys 0.061s 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":163,"lbm_read_time_us":12372,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27288,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:45.187388 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=11.118625
I20260812 06:19:45.225382 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.038s	user 0.036s	sys 0.000s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15911,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:45.225994 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:45.245446 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.019s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4788,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:45.245944 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:45.264488 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.018s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.267517 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushMRSOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:45.305259 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushMRSOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.038s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":176,"dirs.run_wall_time_us":1054,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1729,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:45.306017 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling LogGCOp(194a9b99c9874a4c80914142af4cca13): free 108988751 bytes of WAL
I20260812 06:19:45.306275 10027 log_reader.cc:385] T 194a9b99c9874a4c80914142af4cca13: removed 11 log segments from log reader
I20260812 06:19:45.306404 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000027 (ops 129-133)
I20260812 06:19:45.306468 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000028 (ops 134-138)
I20260812 06:19:45.306488 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000029 (ops 139-143)
I20260812 06:19:45.306547 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000030 (ops 144-148)
I20260812 06:19:45.306578 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000031 (ops 149-153)
I20260812 06:19:45.306617 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000032 (ops 154-158)
I20260812 06:19:45.306654 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000033 (ops 159-163)
I20260812 06:19:45.306692 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000034 (ops 164-168)
I20260812 06:19:45.306730 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000035 (ops 169-172)
I20260812 06:19:45.306768 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000036 (ops 173-177)
I20260812 06:19:45.306818 10027 log.cc:1079] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/194a9b99c9874a4c80914142af4cca13/wal-000000037 (ops 178-182)
I20260812 06:19:45.329954 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: LogGCOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:45.330489 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling UndoDeltaBlockGCOp(194a9b99c9874a4c80914142af4cca13): 447 bytes on disk
I20260812 06:19:45.331058 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: UndoDeltaBlockGCOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":104,"lbm_reads_lt_1ms":4}
I20260812 06:19:45.331864 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=3.181125
I20260812 06:19:45.354426 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.022s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5383,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:45.354879 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:45.364174 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3512,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:45.364677 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:45.586058 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.221s	user 0.132s	sys 0.073s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979852,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":333,"lbm_read_time_us":14659,"lbm_reads_lt_1ms":775,"lbm_write_time_us":34962,"lbm_writes_lt_1ms":743,"mutex_wait_us":21,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":71680,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:19:45.588716 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=18.063937
I20260812 06:19:45.664951 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.076s	user 0.053s	sys 0.021s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":34285,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:19:45.665496 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13): perf score=2.188937
I20260812 06:19:45.675714 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: FlushDeltaMemStoresOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.676175 10092 maintenance_manager.cc:419] P 9ae7cf88bb4c497893e9faf912cb9c92: Scheduling MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13): perf score=1.000000
I20260812 06:19:45.708411  9911 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.804s	user 1.752s	sys 0.141s
I20260812 06:19:45.788430  9911 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.079s	user 0.003s	sys 0.000s
I20260812 06:19:45.789055  9911 tablet_server.cc:179] TabletServer@127.9.173.193:0 shutting down...
I20260812 06:19:45.849550 10027 maintenance_manager.cc:643] P 9ae7cf88bb4c497893e9faf912cb9c92: MajorDeltaCompactionOp(194a9b99c9874a4c80914142af4cca13) complete. Timing: real 0.173s	user 0.092s	sys 0.081s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":274,"lbm_read_time_us":14750,"lbm_reads_lt_1ms":668,"lbm_write_time_us":29733,"lbm_writes_lt_1ms":643,"mutex_wait_us":80,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":22912,"update_count":3000}
I20260812 06:19:45.850411  9911 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:45.850819  9911 tablet_replica.cc:333] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92: stopping tablet replica
I20260812 06:19:45.851086  9911 raft_consensus.cc:2243] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:45.851387  9911 raft_consensus.cc:2272] T 194a9b99c9874a4c80914142af4cca13 P 9ae7cf88bb4c497893e9faf912cb9c92 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:45.867792  9911 tablet_server.cc:196] TabletServer@127.9.173.193:0 shutdown complete.
I20260812 06:19:45.903030  9911 master.cc:562] Master@127.9.173.254:43441 shutting down...
I20260812 06:19:45.907058  9911 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:45.907265  9911 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:45.907366  9911 tablet_replica.cc:333] T 00000000000000000000000000000000 P 888027b75d22417a86cd678010b06db0: stopping tablet replica
I20260812 06:19:45.919785  9911 master.cc:584] Master@127.9.173.254:43441 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5382 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:46.028023  9911 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.173.254:35075
I20260812 06:19:46.028514  9911 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:46.030977 10130 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:46.031046 10132 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:46.031085 10129 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:46.031056  9911 server_base.cc:1061] running on GCE node
I20260812 06:19:46.031383  9911 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:46.031423  9911 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:46.031438  9911 hybrid_clock.cc:648] HybridClock initialized: now 1786515586031438 us; error 0 us; skew 500 ppm
I20260812 06:19:46.032480  9911 webserver.cc:533] Webserver started at http://127.9.173.254:35289/ using document root <none> and password file <none>
I20260812 06:19:46.032660  9911 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:46.032734  9911 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:46.032840  9911 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:46.033250  9911 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/master-0-root/instance:
uuid: "77ac2fe52cd643929ed229f0c8048a2f"
format_stamp: "Formatted at 2026-08-12 06:19:46 on dist-test-slave-0b58"
I20260812 06:19:46.034726  9911 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:46.035630 10138 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:46.035876  9911 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:46.035950  9911 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/master-0-root
uuid: "77ac2fe52cd643929ed229f0c8048a2f"
format_stamp: "Formatted at 2026-08-12 06:19:46 on dist-test-slave-0b58"
I20260812 06:19:46.036005  9911 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:46.047334  9911 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:46.047689  9911 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:46.052085  9911 rpc_server.cc:307] RPC server started. Bound to: 127.9.173.254:35075
I20260812 06:19:46.059613 10195 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.173.254:35075 every 8 connection(s)
I20260812 06:19:46.060128 10197 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:46.061952 10197 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f: Bootstrap starting.
I20260812 06:19:46.062811 10197 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:46.063768 10197 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f: No bootstrap required, opened a new log
I20260812 06:19:46.064136 10197 raft_consensus.cc:359] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "77ac2fe52cd643929ed229f0c8048a2f" member_type: VOTER }
I20260812 06:19:46.064215 10197 raft_consensus.cc:385] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:46.064237 10197 raft_consensus.cc:740] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 77ac2fe52cd643929ed229f0c8048a2f, State: Initialized, Role: FOLLOWER
I20260812 06:19:46.064451 10197 consensus_queue.cc:260] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [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: "77ac2fe52cd643929ed229f0c8048a2f" member_type: VOTER }
I20260812 06:19:46.064544 10197 raft_consensus.cc:399] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:46.064569 10197 raft_consensus.cc:493] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:46.064604 10197 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:46.065227 10197 raft_consensus.cc:515] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "77ac2fe52cd643929ed229f0c8048a2f" member_type: VOTER }
I20260812 06:19:46.065337 10197 leader_election.cc:304] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [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: 77ac2fe52cd643929ed229f0c8048a2f; no voters: 
I20260812 06:19:46.065472 10197 leader_election.cc:290] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:46.065634 10200 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:46.065834 10200 raft_consensus.cc:697] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [term 1 LEADER]: Becoming Leader. State: Replica: 77ac2fe52cd643929ed229f0c8048a2f, State: Running, Role: LEADER
I20260812 06:19:46.065948 10197 sys_catalog.cc:565] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:46.065994 10200 consensus_queue.cc:237] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [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: "77ac2fe52cd643929ed229f0c8048a2f" member_type: VOTER }
I20260812 06:19:46.066427 10201 sys_catalog.cc:455] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "77ac2fe52cd643929ed229f0c8048a2f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "77ac2fe52cd643929ed229f0c8048a2f" member_type: VOTER } }
I20260812 06:19:46.066444 10202 sys_catalog.cc:455] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 77ac2fe52cd643929ed229f0c8048a2f. Latest consensus state: current_term: 1 leader_uuid: "77ac2fe52cd643929ed229f0c8048a2f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "77ac2fe52cd643929ed229f0c8048a2f" member_type: VOTER } }
I20260812 06:19:46.066538 10202 sys_catalog.cc:458] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:46.066761 10201 sys_catalog.cc:458] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:46.067112 10205 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:46.068054 10205 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:46.068284  9911 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:46.069994 10205 catalog_manager.cc:1383] Generated new cluster ID: e2882c8491af4212a97bc7d9ad4b8d23
I20260812 06:19:46.070066 10205 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:46.091405 10205 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:46.092000 10205 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:46.107052 10205 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f: Generated new TSK 0
I20260812 06:19:46.107264 10205 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:46.132967  9911 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:46.134979 10220 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:46.135046 10222 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:46.135142 10219 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:46.135447  9911 server_base.cc:1061] running on GCE node
I20260812 06:19:46.135602  9911 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:46.135638  9911 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:46.135667  9911 hybrid_clock.cc:648] HybridClock initialized: now 1786515586135668 us; error 0 us; skew 500 ppm
I20260812 06:19:46.136507  9911 webserver.cc:533] Webserver started at http://127.9.173.193:39171/ using document root <none> and password file <none>
I20260812 06:19:46.136684  9911 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:46.136741  9911 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:46.136806  9911 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:46.137216  9911 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/instance:
uuid: "d670023bedd449f59807885409e6c8ee"
format_stamp: "Formatted at 2026-08-12 06:19:46 on dist-test-slave-0b58"
I20260812 06:19:46.138609  9911 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:46.139441 10227 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:46.139714  9911 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:46.139778  9911 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root
uuid: "d670023bedd449f59807885409e6c8ee"
format_stamp: "Formatted at 2026-08-12 06:19:46 on dist-test-slave-0b58"
I20260812 06:19:46.139866  9911 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:46.162241  9911 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:46.162663  9911 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:46.162995  9911 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:46.163493  9911 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:46.163532  9911 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:46.163565  9911 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:46.163614  9911 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:46.168169  9911 rpc_server.cc:307] RPC server started. Bound to: 127.9.173.193:36217
I20260812 06:19:46.168723 10295 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.173.193:36217 every 8 connection(s)
I20260812 06:19:46.179709 10296 heartbeater.cc:344] Connected to a master server at 127.9.173.254:35075
I20260812 06:19:46.179833 10296 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:46.180043 10296 heartbeater.cc:507] Master 127.9.173.254:35075 requested a full tablet report, sending...
I20260812 06:19:46.180691 10157 ts_manager.cc:194] Registered new tserver with Master: d670023bedd449f59807885409e6c8ee (127.9.173.193:36217)
I20260812 06:19:46.181121  9911 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012218693s
I20260812 06:19:46.181530 10157 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33482
I20260812 06:19:46.188179 10157 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33484:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:46.196625 10256 tablet_service.cc:1511] Processing CreateTablet for tablet 6d1b1f148f824a8c9e2bfcc892915e84 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b20f49674ee04cd0b083557bfedab823]), partition=
I20260812 06:19:46.196905 10256 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6d1b1f148f824a8c9e2bfcc892915e84. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:46.199209 10310 tablet_bootstrap.cc:492] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Bootstrap starting.
I20260812 06:19:46.200080 10310 tablet_bootstrap.cc:654] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:46.201148 10310 tablet_bootstrap.cc:492] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: No bootstrap required, opened a new log
I20260812 06:19:46.201220 10310 ts_tablet_manager.cc:1403] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:46.201709 10310 raft_consensus.cc:359] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d670023bedd449f59807885409e6c8ee" member_type: VOTER last_known_addr { host: "127.9.173.193" port: 36217 } }
I20260812 06:19:46.201818 10310 raft_consensus.cc:385] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:46.201843 10310 raft_consensus.cc:740] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d670023bedd449f59807885409e6c8ee, State: Initialized, Role: FOLLOWER
I20260812 06:19:46.201982 10310 consensus_queue.cc:260] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [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: "d670023bedd449f59807885409e6c8ee" member_type: VOTER last_known_addr { host: "127.9.173.193" port: 36217 } }
I20260812 06:19:46.202078 10310 raft_consensus.cc:399] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:46.202138 10310 raft_consensus.cc:493] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:46.202201 10310 raft_consensus.cc:3060] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:46.202898 10310 raft_consensus.cc:515] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d670023bedd449f59807885409e6c8ee" member_type: VOTER last_known_addr { host: "127.9.173.193" port: 36217 } }
I20260812 06:19:46.203065 10310 leader_election.cc:304] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [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: d670023bedd449f59807885409e6c8ee; no voters: 
I20260812 06:19:46.203313 10310 leader_election.cc:290] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:46.203481 10313 raft_consensus.cc:2804] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:46.203720 10310 ts_tablet_manager.cc:1434] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:46.203703 10296 heartbeater.cc:499] Master 127.9.173.254:35075 was elected leader, sending a full tablet report...
I20260812 06:19:46.203703 10313 raft_consensus.cc:697] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [term 1 LEADER]: Becoming Leader. State: Replica: d670023bedd449f59807885409e6c8ee, State: Running, Role: LEADER
I20260812 06:19:46.203970 10313 consensus_queue.cc:237] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [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: "d670023bedd449f59807885409e6c8ee" member_type: VOTER last_known_addr { host: "127.9.173.193" port: 36217 } }
I20260812 06:19:46.205226 10157 catalog_manager.cc:5719] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee reported cstate change: term changed from 0 to 1, leader changed from <none> to d670023bedd449f59807885409e6c8ee (127.9.173.193). New cstate: current_term: 1 leader_uuid: "d670023bedd449f59807885409e6c8ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d670023bedd449f59807885409e6c8ee" member_type: VOTER last_known_addr { host: "127.9.173.193" port: 36217 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:46.267980  9911 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.021s	sys 0.003s
I20260812 06:19:46.419576 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushMRSOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=19.054940
I20260812 06:19:46.573133 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushMRSOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.153s	user 0.125s	sys 0.027s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":898,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37965,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:19:46.574137 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling LogGCOp(6d1b1f148f824a8c9e2bfcc892915e84): free 20743880 bytes of WAL
I20260812 06:19:46.574396 10232 log_reader.cc:385] T 6d1b1f148f824a8c9e2bfcc892915e84: removed 2 log segments from log reader
I20260812 06:19:46.574456 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000001 (ops 1-6)
I20260812 06:19:46.574512 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000002 (ops 7-11)
I20260812 06:19:46.579965 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: LogGCOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:46.580497 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:46.595346 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.595822 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:46.743649 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.148s	user 0.111s	sys 0.036s 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":885,"lbm_read_time_us":10860,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24780,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"thread_start_us":384,"threads_started":5,"update_count":2000}
I20260812 06:19:46.744402 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling UndoDeltaBlockGCOp(6d1b1f148f824a8c9e2bfcc892915e84): 16411393 bytes on disk
I20260812 06:19:46.744930 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: UndoDeltaBlockGCOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:19:46.745538 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=10.126437
I20260812 06:19:46.792308 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.047s	user 0.019s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15342,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.792840 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:46.803347 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.803781 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:46.965678 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.162s	user 0.108s	sys 0.054s 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":275,"lbm_read_time_us":11705,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25217,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:19:46.966279 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=10.126437
I20260812 06:19:47.010288 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.044s	user 0.022s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16601,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.010878 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:47.022854 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4347,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.023571 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:47.153012 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.129s	user 0.106s	sys 0.022s 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":701,"lbm_read_time_us":9384,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25810,"lbm_writes_lt_1ms":443,"mutex_wait_us":83,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:19:47.153818 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=10.126437
I20260812 06:19:47.198081 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.044s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16607,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.198614 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:47.209853 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4157,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.210616 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:47.340018 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.129s	user 0.113s	sys 0.016s 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":263,"lbm_read_time_us":8839,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24753,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21120,"update_count":2000}
I20260812 06:19:47.340623 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=10.126437
I20260812 06:19:47.399394 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.059s	user 0.027s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15959,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.399989 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:47.416940 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.417567 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:47.576719 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.159s	user 0.099s	sys 0.060s 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":74,"lbm_read_time_us":12108,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26003,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2000}
I20260812 06:19:47.577565 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=10.126437
I20260812 06:19:47.619626 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.042s	user 0.033s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17054,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.620234 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:47.630618 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4087,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.631287 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:47.757685 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.126s	user 0.086s	sys 0.040s 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":465,"lbm_read_time_us":10051,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22508,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2000}
I20260812 06:19:47.758365 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=10.126437
I20260812 06:19:47.799126 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.040s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16082,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.799650 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:47.810304 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4058,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.811086 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushMRSOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:47.840235 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushMRSOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.029s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1391,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1681,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:47.841107 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling LogGCOp(6d1b1f148f824a8c9e2bfcc892915e84): free 111786258 bytes of WAL
I20260812 06:19:47.841341 10232 log_reader.cc:385] T 6d1b1f148f824a8c9e2bfcc892915e84: removed 11 log segments from log reader
I20260812 06:19:47.841384 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000003 (ops 12-16)
I20260812 06:19:47.841436 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000004 (ops 17-21)
I20260812 06:19:47.841482 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000005 (ops 22-26)
I20260812 06:19:47.841526 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000006 (ops 27-31)
I20260812 06:19:47.841565 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000007 (ops 32-36)
I20260812 06:19:47.841626 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000008 (ops 37-41)
I20260812 06:19:47.841668 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000009 (ops 42-46)
I20260812 06:19:47.841711 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000010 (ops 47-50)
I20260812 06:19:47.841753 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000011 (ops 51-55)
I20260812 06:19:47.841792 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000012 (ops 56-60)
I20260812 06:19:47.841832 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000013 (ops 61-64)
I20260812 06:19:47.867624 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: LogGCOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:47.868135 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=3.181125
I20260812 06:19:47.879730 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4511,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:47.880172 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling UndoDeltaBlockGCOp(6d1b1f148f824a8c9e2bfcc892915e84): 447 bytes on disk
I20260812 06:19:47.880800 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: UndoDeltaBlockGCOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:47.881238 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:47.892009 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3728,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:47.893826 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:48.069561 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.176s	user 0.123s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":238,"lbm_read_time_us":13021,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33905,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21888,"thread_start_us":108,"threads_started":1,"update_count":3000}
I20260812 06:19:48.070362 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=14.095187
I20260812 06:19:48.127058 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.056s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22908,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.127543 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:48.139567 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4452,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.140098 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:48.328331 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.188s	user 0.131s	sys 0.049s 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":812,"lbm_read_time_us":11604,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33177,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:19:48.329165 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=14.095187
I20260812 06:19:48.390883 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.061s	user 0.027s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25813,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.391598 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:48.558401 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.167s	user 0.115s	sys 0.047s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1005,"lbm_read_time_us":11108,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25759,"lbm_writes_lt_1ms":443,"mutex_wait_us":303,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:48.559216 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=11.118625
I20260812 06:19:48.599601 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.040s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17190,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:48.600207 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:48.623350 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.023s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4204,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:48.623884 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:48.634490 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4109,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.635052 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:48.830910 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.196s	user 0.104s	sys 0.079s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":868,"lbm_read_time_us":12725,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29393,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:19:48.831518 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=14.095187
I20260812 06:19:48.882589 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.051s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22785,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.883162 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:48.897148 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.014s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5358,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.897689 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:49.063299 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.165s	user 0.121s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":10053,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30073,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:19:49.064009 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=14.095187
I20260812 06:19:49.112846 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.049s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21538,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.113404 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:49.125942 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4550,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.126446 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:49.275839 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.149s	user 0.121s	sys 0.028s 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":144,"lbm_read_time_us":9609,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32332,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":38784,"update_count":2500}
I20260812 06:19:49.276715 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=11.118625
I20260812 06:19:49.317783 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.041s	user 0.032s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17921,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:49.318572 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:49.335963 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6242,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:49.336624 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushMRSOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:49.369499 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushMRSOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":41,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":1279,"drs_written":1,"lbm_read_time_us":116,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2279,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:49.370167 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling LogGCOp(6d1b1f148f824a8c9e2bfcc892915e84): free 121006383 bytes of WAL
I20260812 06:19:49.370406 10232 log_reader.cc:385] T 6d1b1f148f824a8c9e2bfcc892915e84: removed 12 log segments from log reader
I20260812 06:19:49.370466 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000014 (ops 65-69)
I20260812 06:19:49.370520 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000015 (ops 70-74)
I20260812 06:19:49.370579 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000016 (ops 75-79)
I20260812 06:19:49.370617 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000017 (ops 80-84)
I20260812 06:19:49.370654 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000018 (ops 85-89)
I20260812 06:19:49.370692 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000019 (ops 90-94)
I20260812 06:19:49.370728 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000020 (ops 95-99)
I20260812 06:19:49.370764 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000021 (ops 100-104)
I20260812 06:19:49.370795 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000022 (ops 105-109)
I20260812 06:19:49.370842 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000023 (ops 110-114)
I20260812 06:19:49.370872 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000024 (ops 115-118)
I20260812 06:19:49.370908 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000025 (ops 119-123)
I20260812 06:19:49.396636 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: LogGCOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.026s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:19:49.397030 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=5.165500
I20260812 06:19:49.415962 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.019s	user 0.011s	sys 0.004s Metrics: {"bytes_written":7261522,"delete_count":0,"lbm_write_time_us":7455,"lbm_writes_lt_1ms":180,"reinsert_count":0,"update_count":885}
I20260812 06:19:49.416538 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling LogGCOp(6d1b1f148f824a8c9e2bfcc892915e84): free 12017983 bytes of WAL
I20260812 06:19:49.416800 10232 log_reader.cc:385] T 6d1b1f148f824a8c9e2bfcc892915e84: removed 1 log segments from log reader
I20260812 06:19:49.416877 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000026 (ops 124-128)
I20260812 06:19:49.420130 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: LogGCOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:49.420596 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:49.428623 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.008s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1353981,"delete_count":0,"lbm_write_time_us":1562,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:19:49.429061 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling UndoDeltaBlockGCOp(6d1b1f148f824a8c9e2bfcc892915e84): 473 bytes on disk
I20260812 06:19:49.429431 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: UndoDeltaBlockGCOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:19:49.429877 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:49.629602 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.200s	user 0.115s	sys 0.069s Metrics: {"cfile_cache_miss":644,"cfile_cache_miss_bytes":29287511,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":544,"lbm_read_time_us":11881,"lbm_reads_lt_1ms":676,"lbm_write_time_us":34251,"lbm_writes_lt_1ms":653,"mutex_wait_us":93,"peak_mem_usage":75952822,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":76,"threads_started":1,"update_count":3050}
I20260812 06:19:49.630424 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=18.063937
I20260812 06:19:49.698668 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.067s	user 0.050s	sys 0.015s Metrics: {"bytes_written":20102071,"delete_count":0,"lbm_write_time_us":25459,"lbm_writes_lt_1ms":493,"reinsert_count":0,"update_count":2450}
I20260812 06:19:49.699297 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:49.710722 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4262,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.711388 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:49.895279 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.184s	user 0.128s	sys 0.056s Metrics: {"cfile_cache_miss":622,"cfile_cache_miss_bytes":28466858,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":605,"lbm_read_time_us":14326,"lbm_reads_lt_1ms":662,"lbm_write_time_us":29316,"lbm_writes_lt_1ms":633,"mutex_wait_us":271,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2950}
I20260812 06:19:49.895958 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=14.095187
I20260812 06:19:49.960728 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.065s	user 0.041s	sys 0.022s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24328,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.961508 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:49.979046 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6029,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.979584 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:50.148456 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.169s	user 0.106s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":331,"lbm_read_time_us":11692,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27954,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:19:50.149152 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=14.095187
I20260812 06:19:50.195982 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.047s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22000,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.196568 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:50.225859 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.029s	user 0.014s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6501,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.226504 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:50.395139 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.168s	user 0.127s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":775,"lbm_read_time_us":12766,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28613,"lbm_writes_lt_1ms":543,"mutex_wait_us":271,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:19:50.395915 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=14.095187
I20260812 06:19:50.445089 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.049s	user 0.033s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22073,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.445672 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:50.457890 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4792,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.458357 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:50.631209 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.173s	user 0.120s	sys 0.042s 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":3613,"lbm_read_time_us":10737,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28500,"lbm_writes_lt_1ms":543,"mutex_wait_us":3142,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:19:50.631912 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=14.095187
I20260812 06:19:50.678443 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.046s	user 0.020s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18589,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.679050 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:50.694885 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5886,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.695498 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushMRSOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:50.722829 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushMRSOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":302,"dirs.run_wall_time_us":1433,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1462,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:50.723563 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling LogGCOp(6d1b1f148f824a8c9e2bfcc892915e84): free 112692564 bytes of WAL
I20260812 06:19:50.723773 10232 log_reader.cc:385] T 6d1b1f148f824a8c9e2bfcc892915e84: removed 11 log segments from log reader
I20260812 06:19:50.723821 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000027 (ops 129-133)
I20260812 06:19:50.723858 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000028 (ops 134-138)
I20260812 06:19:50.723888 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000029 (ops 139-143)
I20260812 06:19:50.723922 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000030 (ops 144-148)
I20260812 06:19:50.723955 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000031 (ops 149-153)
I20260812 06:19:50.723992 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000032 (ops 154-158)
I20260812 06:19:50.724020 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000033 (ops 159-163)
I20260812 06:19:50.724049 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000034 (ops 164-168)
I20260812 06:19:50.724083 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000035 (ops 169-173)
I20260812 06:19:50.724115 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000036 (ops 174-178)
I20260812 06:19:50.724141 10232 log.cc:1079] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: Deleting log segment in path: /tmp/dist-test-taskV5dRh5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515580623914-9911-0/minicluster-data/ts-0-root/wals/6d1b1f148f824a8c9e2bfcc892915e84/wal-000000037 (ops 179-183)
I20260812 06:19:50.753607 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: LogGCOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:50.754020 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:50.787727 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.034s	user 0.011s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.788357 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling UndoDeltaBlockGCOp(6d1b1f148f824a8c9e2bfcc892915e84): 447 bytes on disk
I20260812 06:19:50.788843 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: UndoDeltaBlockGCOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:19:50.789376 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:50.800087 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4105,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.800666 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:51.035181 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.234s	user 0.164s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":980,"lbm_read_time_us":17889,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37844,"lbm_writes_lt_1ms":743,"mutex_wait_us":375,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11776,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:19:51.035887 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=15.087375
I20260812 06:19:51.093997 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.058s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":26137,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:51.094604 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:51.118845 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.024s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4894,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:51.119336 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=2.188937
I20260812 06:19:51.131179 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: FlushDeltaMemStoresOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4001,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.131816 10297 maintenance_manager.cc:419] P d670023bedd449f59807885409e6c8ee: Scheduling MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84): perf score=1.000000
I20260812 06:19:51.211926  9911 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.944s	user 1.837s	sys 0.154s
I20260812 06:19:51.279858  9911 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.001s	sys 0.000s
I20260812 06:19:51.280435  9911 tablet_server.cc:179] TabletServer@127.9.173.193:0 shutting down...
I20260812 06:19:51.307802 10232 maintenance_manager.cc:643] P d670023bedd449f59807885409e6c8ee: MajorDeltaCompactionOp(6d1b1f148f824a8c9e2bfcc892915e84) complete. Timing: real 0.176s	user 0.135s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877208,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":364,"lbm_read_time_us":13626,"lbm_reads_lt_1ms":669,"lbm_write_time_us":29791,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":3000}
I20260812 06:19:51.309382  9911 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:51.309666  9911 tablet_replica.cc:333] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee: stopping tablet replica
I20260812 06:19:51.309854  9911 raft_consensus.cc:2243] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:51.310041  9911 raft_consensus.cc:2272] T 6d1b1f148f824a8c9e2bfcc892915e84 P d670023bedd449f59807885409e6c8ee [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:51.328433  9911 tablet_server.cc:196] TabletServer@127.9.173.193:0 shutdown complete.
I20260812 06:19:51.362994  9911 master.cc:562] Master@127.9.173.254:35075 shutting down...
I20260812 06:19:51.366407  9911 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:51.366624  9911 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:51.366688  9911 tablet_replica.cc:333] T 00000000000000000000000000000000 P 77ac2fe52cd643929ed229f0c8048a2f: stopping tablet replica
I20260812 06:19:51.379112  9911 master.cc:584] Master@127.9.173.254:35075 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5455 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10838 ms total)

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