[==========] 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:56.955283 12144 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.220.62:35083
I20260812 06:19:56.956331 12144 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:56.957047 12144 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:56.963783 12150 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:56.963874 12157 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:56.963958 12144 server_base.cc:1061] running on GCE node
W20260812 06:19:56.964178 12151 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:56.964790 12144 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:56.964929 12144 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:56.964977 12144 hybrid_clock.cc:648] HybridClock initialized: now 1786515596964974 us; error 0 us; skew 500 ppm
I20260812 06:19:56.967366 12144 webserver.cc:533] Webserver started at http://127.11.220.62:34121/ using document root <none> and password file <none>
I20260812 06:19:56.968055 12144 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:56.968161 12144 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:56.968442 12144 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:56.970428 12144 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/master-0-root/instance:
uuid: "fd53b8dbb95642549f42fd49b70d7d3c"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-s11t"
I20260812 06:19:56.974634 12144 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.000s	sys 0.005s
I20260812 06:19:56.977046 12164 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:56.978267 12144 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:19:56.978432 12144 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/master-0-root
uuid: "fd53b8dbb95642549f42fd49b70d7d3c"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-s11t"
I20260812 06:19:56.978556 12144 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-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:57.009397 12144 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:57.010174 12144 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:57.010386 12144 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:57.019126 12144 rpc_server.cc:307] RPC server started. Bound to: 127.11.220.62:35083
I20260812 06:19:57.019174 12234 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.220.62:35083 every 8 connection(s)
I20260812 06:19:57.021698 12236 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:57.027585 12236 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c: Bootstrap starting.
I20260812 06:19:57.030195 12236 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:57.031222 12236 log.cc:826] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:57.033105 12236 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c: No bootstrap required, opened a new log
I20260812 06:19:57.036064 12236 raft_consensus.cc:359] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fd53b8dbb95642549f42fd49b70d7d3c" member_type: VOTER }
I20260812 06:19:57.036489 12236 raft_consensus.cc:385] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:57.036599 12236 raft_consensus.cc:740] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fd53b8dbb95642549f42fd49b70d7d3c, State: Initialized, Role: FOLLOWER
I20260812 06:19:57.037258 12236 consensus_queue.cc:260] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [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: "fd53b8dbb95642549f42fd49b70d7d3c" member_type: VOTER }
I20260812 06:19:57.037456 12236 raft_consensus.cc:399] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:57.037539 12236 raft_consensus.cc:493] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:57.037694 12236 raft_consensus.cc:3060] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:57.038529 12236 raft_consensus.cc:515] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fd53b8dbb95642549f42fd49b70d7d3c" member_type: VOTER }
I20260812 06:19:57.038981 12236 leader_election.cc:304] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [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: fd53b8dbb95642549f42fd49b70d7d3c; no voters: 
I20260812 06:19:57.039352 12236 leader_election.cc:290] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:57.039502 12242 raft_consensus.cc:2804] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:57.039772 12242 raft_consensus.cc:697] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [term 1 LEADER]: Becoming Leader. State: Replica: fd53b8dbb95642549f42fd49b70d7d3c, State: Running, Role: LEADER
I20260812 06:19:57.040222 12242 consensus_queue.cc:237] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [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: "fd53b8dbb95642549f42fd49b70d7d3c" member_type: VOTER }
I20260812 06:19:57.040349 12236 sys_catalog.cc:565] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:57.042148 12245 sys_catalog.cc:455] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [sys.catalog]: SysCatalogTable state changed. Reason: New leader fd53b8dbb95642549f42fd49b70d7d3c. Latest consensus state: current_term: 1 leader_uuid: "fd53b8dbb95642549f42fd49b70d7d3c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fd53b8dbb95642549f42fd49b70d7d3c" member_type: VOTER } }
I20260812 06:19:57.042208 12244 sys_catalog.cc:455] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "fd53b8dbb95642549f42fd49b70d7d3c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fd53b8dbb95642549f42fd49b70d7d3c" member_type: VOTER } }
I20260812 06:19:57.042269 12245 sys_catalog.cc:458] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:57.042317 12244 sys_catalog.cc:458] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:57.042722 12262 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:57.042955 12144 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:57.045076 12262 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:57.050030 12262 catalog_manager.cc:1383] Generated new cluster ID: 104a029fddf74c80a049d48e6c2dff23
I20260812 06:19:57.050113 12262 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:57.069432 12262 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:57.070643 12262 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:57.078125 12262 catalog_manager.cc:6092] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c: Generated new TSK 0
I20260812 06:19:57.078914 12262 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:57.107939 12144 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:57.110985 12275 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:57.111028 12272 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:57.111028 12273 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:57.111393 12144 server_base.cc:1061] running on GCE node
I20260812 06:19:57.111625 12144 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:57.111680 12144 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:57.111697 12144 hybrid_clock.cc:648] HybridClock initialized: now 1786515597111697 us; error 0 us; skew 500 ppm
I20260812 06:19:57.112677 12144 webserver.cc:533] Webserver started at http://127.11.220.1:37987/ using document root <none> and password file <none>
I20260812 06:19:57.112949 12144 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:57.113005 12144 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:57.113125 12144 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:57.113584 12144 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/instance:
uuid: "23c91a38f2d045c2a5a3ad055e2c7295"
format_stamp: "Formatted at 2026-08-12 06:19:57 on dist-test-slave-s11t"
I20260812 06:19:57.115273 12144 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:57.116389 12282 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:57.116672 12144 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:57.116806 12144 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root
uuid: "23c91a38f2d045c2a5a3ad055e2c7295"
format_stamp: "Formatted at 2026-08-12 06:19:57 on dist-test-slave-s11t"
I20260812 06:19:57.116892 12144 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-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:57.137946 12144 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:57.138962 12144 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:57.139532 12144 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:57.140533 12144 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:57.140589 12144 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:57.140674 12144 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:57.140755 12144 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:57.148454 12144 rpc_server.cc:307] RPC server started. Bound to: 127.11.220.1:43721
I20260812 06:19:57.148506 12388 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.220.1:43721 every 8 connection(s)
I20260812 06:19:57.162427 12389 heartbeater.cc:344] Connected to a master server at 127.11.220.62:35083
I20260812 06:19:57.162725 12389 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:57.163254 12389 heartbeater.cc:507] Master 127.11.220.62:35083 requested a full tablet report, sending...
I20260812 06:19:57.164891 12188 ts_manager.cc:194] Registered new tserver with Master: 23c91a38f2d045c2a5a3ad055e2c7295 (127.11.220.1:43721)
I20260812 06:19:57.165196 12144 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01596126s
I20260812 06:19:57.166473 12188 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36146
I20260812 06:19:57.175369 12188 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36160:
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:57.190111 12332 tablet_service.cc:1511] Processing CreateTablet for tablet fa60eff6bb4d436498b6948ac6496fcb (DEFAULT_TABLE table=heavy-update-compaction-test [id=3ee48af7308648c59f62003ea33f5739]), partition=
I20260812 06:19:57.190651 12332 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet fa60eff6bb4d436498b6948ac6496fcb. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:57.193289 12409 tablet_bootstrap.cc:492] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Bootstrap starting.
I20260812 06:19:57.194859 12409 tablet_bootstrap.cc:654] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:57.196326 12409 tablet_bootstrap.cc:492] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: No bootstrap required, opened a new log
I20260812 06:19:57.196455 12409 ts_tablet_manager.cc:1403] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:57.197052 12409 raft_consensus.cc:359] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "23c91a38f2d045c2a5a3ad055e2c7295" member_type: VOTER last_known_addr { host: "127.11.220.1" port: 43721 } }
I20260812 06:19:57.197196 12409 raft_consensus.cc:385] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:57.197288 12409 raft_consensus.cc:740] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 23c91a38f2d045c2a5a3ad055e2c7295, State: Initialized, Role: FOLLOWER
I20260812 06:19:57.197499 12409 consensus_queue.cc:260] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [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: "23c91a38f2d045c2a5a3ad055e2c7295" member_type: VOTER last_known_addr { host: "127.11.220.1" port: 43721 } }
I20260812 06:19:57.197613 12409 raft_consensus.cc:399] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:57.197693 12409 raft_consensus.cc:493] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:57.197764 12409 raft_consensus.cc:3060] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:57.198849 12409 raft_consensus.cc:515] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "23c91a38f2d045c2a5a3ad055e2c7295" member_type: VOTER last_known_addr { host: "127.11.220.1" port: 43721 } }
I20260812 06:19:57.199011 12409 leader_election.cc:304] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [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: 23c91a38f2d045c2a5a3ad055e2c7295; no voters: 
I20260812 06:19:57.199244 12409 leader_election.cc:290] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:57.199447 12411 raft_consensus.cc:2804] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:57.199602 12409 ts_tablet_manager.cc:1434] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:57.199736 12411 raft_consensus.cc:697] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [term 1 LEADER]: Becoming Leader. State: Replica: 23c91a38f2d045c2a5a3ad055e2c7295, State: Running, Role: LEADER
I20260812 06:19:57.199901 12389 heartbeater.cc:499] Master 127.11.220.62:35083 was elected leader, sending a full tablet report...
I20260812 06:19:57.200007 12411 consensus_queue.cc:237] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [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: "23c91a38f2d045c2a5a3ad055e2c7295" member_type: VOTER last_known_addr { host: "127.11.220.1" port: 43721 } }
I20260812 06:19:57.203060 12188 catalog_manager.cc:5719] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 reported cstate change: term changed from 0 to 1, leader changed from <none> to 23c91a38f2d045c2a5a3ad055e2c7295 (127.11.220.1). New cstate: current_term: 1 leader_uuid: "23c91a38f2d045c2a5a3ad055e2c7295" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "23c91a38f2d045c2a5a3ad055e2c7295" member_type: VOTER last_known_addr { host: "127.11.220.1" port: 43721 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:57.267619 12144 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.015s	sys 0.009s
I20260812 06:19:57.400013 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushMRSOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=19.054940
I20260812 06:19:57.581733 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushMRSOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.181s	user 0.162s	sys 0.012s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":654,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":748,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42282,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":165,"threads_started":1,"update_count":1500}
I20260812 06:19:57.582976 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling LogGCOp(fa60eff6bb4d436498b6948ac6496fcb): free 20743831 bytes of WAL
I20260812 06:19:57.583366 12289 log_reader.cc:385] T fa60eff6bb4d436498b6948ac6496fcb: removed 2 log segments from log reader
I20260812 06:19:57.583456 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000001 (ops 1-6)
I20260812 06:19:57.583539 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000002 (ops 7-11)
I20260812 06:19:57.588294 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: LogGCOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:57.588762 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:19:57.606146 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6552,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.606629 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling UndoDeltaBlockGCOp(fa60eff6bb4d436498b6948ac6496fcb): 16411398 bytes on disk
I20260812 06:19:57.607244 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: UndoDeltaBlockGCOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:57.607684 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:19:57.755650 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.148s	user 0.121s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":571,"lbm_read_time_us":7787,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27716,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"thread_start_us":286,"threads_started":5,"update_count":2000}
I20260812 06:19:57.756145 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=10.126437
I20260812 06:19:57.805964 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.050s	user 0.018s	sys 0.028s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":23767,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":299,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.806571 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:19:57.823553 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6232,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.824164 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:19:57.952410 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.128s	user 0.083s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672281,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1216,"lbm_read_time_us":10167,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22387,"lbm_writes_lt_1ms":443,"mutex_wait_us":372,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2000}
I20260812 06:19:57.953091 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=10.126437
I20260812 06:19:57.999409 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.046s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15595,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.000007 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:19:58.012874 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4657,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.013455 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:19:58.149832 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.136s	user 0.116s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":985,"lbm_read_time_us":8315,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28975,"lbm_writes_lt_1ms":443,"mutex_wait_us":310,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":62848,"update_count":2000}
I20260812 06:19:58.150517 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=10.126437
I20260812 06:19:58.202260 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.052s	user 0.022s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16294,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.202813 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:19:58.214581 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4593,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.215042 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:19:58.363301 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.148s	user 0.099s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1228,"lbm_read_time_us":12305,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23250,"lbm_writes_lt_1ms":443,"mutex_wait_us":355,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:58.364013 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=10.126437
I20260812 06:19:58.410452 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.046s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18007,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.411057 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:19:58.422837 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4332,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.423305 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:19:58.551635 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.128s	user 0.095s	sys 0.033s 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":982,"lbm_read_time_us":10225,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24310,"lbm_writes_lt_1ms":443,"mutex_wait_us":321,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.552115 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=10.126437
I20260812 06:19:58.599215 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.047s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17335,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.599655 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:19:58.610658 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4128,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.611485 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:19:58.735520 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.124s	user 0.096s	sys 0.027s 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":542,"lbm_read_time_us":9474,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23334,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:19:58.736299 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=10.126437
I20260812 06:19:58.777544 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.041s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16496,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.778131 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:19:58.793553 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5603,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.794095 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushMRSOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:19:58.826202 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushMRSOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.032s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1668,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1695,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:58.826996 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling LogGCOp(fa60eff6bb4d436498b6948ac6496fcb): free 112239308 bytes of WAL
I20260812 06:19:58.827224 12289 log_reader.cc:385] T fa60eff6bb4d436498b6948ac6496fcb: removed 11 log segments from log reader
I20260812 06:19:58.827267 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000003 (ops 12-16)
I20260812 06:19:58.827296 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000004 (ops 17-21)
I20260812 06:19:58.827363 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000005 (ops 22-26)
I20260812 06:19:58.827420 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000006 (ops 27-30)
I20260812 06:19:58.827462 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000007 (ops 31-35)
I20260812 06:19:58.827641 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000008 (ops 36-40)
I20260812 06:19:58.827754 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000009 (ops 41-45)
I20260812 06:19:58.827817 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000010 (ops 46-50)
I20260812 06:19:58.827859 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000011 (ops 51-55)
I20260812 06:19:58.827901 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000012 (ops 56-60)
I20260812 06:19:58.827942 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000013 (ops 61-65)
I20260812 06:19:58.852428 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: LogGCOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:58.853009 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=3.181125
I20260812 06:19:58.865442 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4744,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:58.865917 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:19:58.875314 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3543,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:58.875748 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:19:59.062011 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.186s	user 0.134s	sys 0.044s 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":132,"lbm_read_time_us":11633,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37531,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11136,"thread_start_us":97,"threads_started":1,"update_count":3000}
I20260812 06:19:59.062723 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=14.095187
I20260812 06:19:59.117700 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.055s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25446,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.118202 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:19:59.150393 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.032s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":17340,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.151113 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:19:59.324616 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.173s	user 0.133s	sys 0.036s 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":1094,"lbm_read_time_us":13711,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32676,"lbm_writes_lt_1ms":543,"mutex_wait_us":374,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23424,"update_count":2500}
I20260812 06:19:59.325387 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling UndoDeltaBlockGCOp(fa60eff6bb4d436498b6948ac6496fcb): 447 bytes on disk
I20260812 06:19:59.326081 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: UndoDeltaBlockGCOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4}
I20260812 06:19:59.326958 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=14.095187
I20260812 06:19:59.388525 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.061s	user 0.027s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24509,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.389108 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:19:59.402158 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.013s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4391,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.402881 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:19:59.586386 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.183s	user 0.110s	sys 0.060s 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":1029,"lbm_read_time_us":12475,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28957,"lbm_writes_lt_1ms":543,"mutex_wait_us":335,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:59.587014 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=14.095187
I20260812 06:19:59.645852 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.059s	user 0.046s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25862,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.646461 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:19:59.659127 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5118,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.659742 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:19:59.841938 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.182s	user 0.098s	sys 0.072s 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":348,"lbm_read_time_us":13018,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32215,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:19:59.842548 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=14.095187
I20260812 06:19:59.910332 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.068s	user 0.031s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25853,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.910910 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:19:59.922938 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4582,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.923395 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:20:00.101946 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.178s	user 0.126s	sys 0.052s 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":40,"lbm_read_time_us":12781,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33608,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:20:00.102722 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=11.118625
I20260812 06:20:00.151877 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.049s	user 0.026s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19728,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:00.152458 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:20:00.187544 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.035s	user 0.012s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5116,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:00.188050 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:20:00.198541 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.198993 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:20:00.378190 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.179s	user 0.132s	sys 0.045s 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":3328,"lbm_read_time_us":13065,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30766,"lbm_writes_lt_1ms":543,"mutex_wait_us":1930,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:00.379099 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=10.126437
I20260812 06:20:00.415330 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.036s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13089,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:00.415944 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:20:00.433530 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.017s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.434141 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushMRSOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:20:00.466341 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushMRSOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.032s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":271,"dirs.run_wall_time_us":1379,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1831,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:00.467262 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling LogGCOp(fa60eff6bb4d436498b6948ac6496fcb): free 124710349 bytes of WAL
I20260812 06:20:00.467527 12289 log_reader.cc:385] T fa60eff6bb4d436498b6948ac6496fcb: removed 12 log segments from log reader
I20260812 06:20:00.467574 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000014 (ops 66-70)
I20260812 06:20:00.467607 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000015 (ops 71-75)
I20260812 06:20:00.467628 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000016 (ops 76-80)
I20260812 06:20:00.467696 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000017 (ops 81-85)
I20260812 06:20:00.467729 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000018 (ops 86-90)
I20260812 06:20:00.467773 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000019 (ops 91-95)
I20260812 06:20:00.467818 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000020 (ops 96-100)
I20260812 06:20:00.467864 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000021 (ops 101-105)
I20260812 06:20:00.467893 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000022 (ops 106-110)
I20260812 06:20:00.467935 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000023 (ops 111-115)
I20260812 06:20:00.467962 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000024 (ops 116-120)
I20260812 06:20:00.468031 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000025 (ops 121-125)
I20260812 06:20:00.497838 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: LogGCOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:00.498346 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=4.173312
I20260812 06:20:00.512482 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":5538515,"delete_count":0,"lbm_write_time_us":5844,"lbm_writes_lt_1ms":138,"reinsert_count":0,"update_count":675}
I20260812 06:20:00.513031 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling LogGCOp(fa60eff6bb4d436498b6948ac6496fcb): free 8767131 bytes of WAL
I20260812 06:20:00.513341 12289 log_reader.cc:385] T fa60eff6bb4d436498b6948ac6496fcb: removed 1 log segments from log reader
I20260812 06:20:00.513414 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000026 (ops 126-130)
I20260812 06:20:00.515161 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: LogGCOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:00.515492 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling UndoDeltaBlockGCOp(fa60eff6bb4d436498b6948ac6496fcb): 491 bytes on disk
I20260812 06:20:00.515904 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: UndoDeltaBlockGCOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:20:00.516428 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.196750
I20260812 06:20:00.525786 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.009s	user 0.006s	sys 0.002s Metrics: {"bytes_written":2666779,"delete_count":0,"lbm_write_time_us":2742,"lbm_writes_lt_1ms":68,"reinsert_count":0,"update_count":325}
I20260812 06:20:00.527962 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:20:00.732107 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.204s	user 0.136s	sys 0.067s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1707,"lbm_read_time_us":15478,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35726,"lbm_writes_lt_1ms":643,"mutex_wait_us":693,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:20:00.733014 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=14.095187
I20260812 06:20:00.792223 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.059s	user 0.021s	sys 0.034s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22653,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.792891 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:20:00.810307 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.810796 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:20:01.003904 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.193s	user 0.147s	sys 0.044s 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":1160,"lbm_read_time_us":15094,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34104,"lbm_writes_lt_1ms":543,"mutex_wait_us":387,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2500}
I20260812 06:20:01.004714 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=11.118625
I20260812 06:20:01.044271 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.039s	user 0.018s	sys 0.018s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16477,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:01.044978 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:20:01.077416 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.032s	user 0.007s	sys 0.019s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6601,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:01.078032 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:20:01.246600 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.168s	user 0.101s	sys 0.067s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":203,"lbm_read_time_us":10205,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29768,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:20:01.249624 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=10.126437
I20260812 06:20:01.287292 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.037s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15071,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.288007 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:20:01.419929 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.132s	user 0.120s	sys 0.008s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":220,"lbm_read_time_us":10524,"lbm_reads_lt_1ms":367,"lbm_write_time_us":23572,"lbm_writes_lt_1ms":343,"mutex_wait_us":47,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":1500}
I20260812 06:20:01.420668 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=10.126437
I20260812 06:20:01.469835 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.049s	user 0.032s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20688,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.470564 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:20:01.487624 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.488075 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:20:01.633680 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.145s	user 0.116s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2394,"lbm_read_time_us":11071,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27493,"lbm_writes_lt_1ms":443,"mutex_wait_us":972,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:20:01.634460 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=10.126437
I20260812 06:20:01.682157 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.048s	user 0.034s	sys 0.011s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16745,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.682749 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:20:01.694895 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4824,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.695402 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:20:01.843539 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.148s	user 0.074s	sys 0.068s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":322,"lbm_read_time_us":11056,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21754,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:20:01.844131 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=10.126437
I20260812 06:20:01.883924 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.040s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16838,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.884404 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:20:01.992242 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.108s	user 0.096s	sys 0.008s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":953,"lbm_read_time_us":5958,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20538,"lbm_writes_lt_1ms":343,"mutex_wait_us":365,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":1500}
I20260812 06:20:01.992933 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=10.126437
I20260812 06:20:02.050834 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.058s	user 0.021s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":23991,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:02.051393 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:20:02.061867 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.062387 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushMRSOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:20:02.094313 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushMRSOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.032s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":294,"dirs.run_wall_time_us":1474,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1670,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:02.095062 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling LogGCOp(fa60eff6bb4d436498b6948ac6496fcb): free 111786500 bytes of WAL
I20260812 06:20:02.095310 12289 log_reader.cc:385] T fa60eff6bb4d436498b6948ac6496fcb: removed 11 log segments from log reader
I20260812 06:20:02.095359 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000027 (ops 131-134)
I20260812 06:20:02.095391 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000028 (ops 135-139)
I20260812 06:20:02.095476 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000029 (ops 140-144)
I20260812 06:20:02.095536 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000030 (ops 145-148)
I20260812 06:20:02.095587 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000031 (ops 149-153)
I20260812 06:20:02.095652 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000032 (ops 154-158)
I20260812 06:20:02.095686 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000033 (ops 159-163)
I20260812 06:20:02.095727 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000034 (ops 164-168)
I20260812 06:20:02.095780 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000035 (ops 169-173)
I20260812 06:20:02.095822 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000036 (ops 174-178)
I20260812 06:20:02.095865 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000037 (ops 179-183)
I20260812 06:20:02.124930 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: LogGCOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:02.125531 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=3.181125
I20260812 06:20:02.139633 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.014s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":5608,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:02.140197 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling LogGCOp(fa60eff6bb4d436498b6948ac6496fcb): free 12017954 bytes of WAL
I20260812 06:20:02.140444 12289 log_reader.cc:385] T fa60eff6bb4d436498b6948ac6496fcb: removed 1 log segments from log reader
I20260812 06:20:02.140508 12289 log.cc:1079] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/fa60eff6bb4d436498b6948ac6496fcb/wal-000000038 (ops 184-188)
I20260812 06:20:02.143731 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: LogGCOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:02.144107 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling UndoDeltaBlockGCOp(fa60eff6bb4d436498b6948ac6496fcb): 447 bytes on disk
I20260812 06:20:02.144634 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: UndoDeltaBlockGCOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:20:02.145318 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:20:02.156183 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.011s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3652,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:02.156778 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:20:02.337843 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.181s	user 0.136s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1201,"lbm_read_time_us":13878,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34610,"lbm_writes_lt_1ms":643,"mutex_wait_us":582,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9984,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:20:02.338505 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=14.095187
I20260812 06:20:02.384927 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.046s	user 0.035s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20396,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.385432 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=2.188937
I20260812 06:20:02.395946 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: FlushDeltaMemStoresOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4309,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.396349 12391 maintenance_manager.cc:419] P 23c91a38f2d045c2a5a3ad055e2c7295: Scheduling MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb): perf score=1.000000
I20260812 06:20:02.429000 12144 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.161s	user 1.948s	sys 0.136s
I20260812 06:20:02.509268 12144 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.080s	user 0.005s	sys 0.000s
I20260812 06:20:02.509999 12144 tablet_server.cc:179] TabletServer@127.11.220.1:0 shutting down...
I20260812 06:20:02.553202 12289 maintenance_manager.cc:643] P 23c91a38f2d045c2a5a3ad055e2c7295: MajorDeltaCompactionOp(fa60eff6bb4d436498b6948ac6496fcb) complete. Timing: real 0.157s	user 0.116s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":896,"lbm_read_time_us":10243,"lbm_reads_lt_1ms":568,"lbm_write_time_us":34290,"lbm_writes_lt_1ms":543,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:20:02.554064 12144 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:02.554553 12144 tablet_replica.cc:333] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295: stopping tablet replica
I20260812 06:20:02.554840 12144 raft_consensus.cc:2243] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:02.555109 12144 raft_consensus.cc:2272] T fa60eff6bb4d436498b6948ac6496fcb P 23c91a38f2d045c2a5a3ad055e2c7295 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:02.582810 12144 tablet_server.cc:196] TabletServer@127.11.220.1:0 shutdown complete.
I20260812 06:20:02.598919 12144 master.cc:562] Master@127.11.220.62:35083 shutting down...
I20260812 06:20:02.603243 12144 raft_consensus.cc:2243] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:02.603461 12144 raft_consensus.cc:2272] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:02.603554 12144 tablet_replica.cc:333] T 00000000000000000000000000000000 P fd53b8dbb95642549f42fd49b70d7d3c: stopping tablet replica
I20260812 06:20:02.617264 12144 master.cc:584] Master@127.11.220.62:35083 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5755 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:02.710928 12144 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.220.62:42137
I20260812 06:20:02.711376 12144 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:02.714066 12437 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:02.714201 12144 server_base.cc:1061] running on GCE node
W20260812 06:20:02.714148 12438 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:02.714130 12441 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:02.714525 12144 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:02.714569 12144 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:02.714584 12144 hybrid_clock.cc:648] HybridClock initialized: now 1786515602714585 us; error 0 us; skew 500 ppm
I20260812 06:20:02.715480 12144 webserver.cc:533] Webserver started at http://127.11.220.62:34787/ using document root <none> and password file <none>
I20260812 06:20:02.715615 12144 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:02.715659 12144 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:02.715711 12144 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:02.716060 12144 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/master-0-root/instance:
uuid: "206465354b7441a4a9955e3da941c588"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-s11t"
I20260812 06:20:02.717674 12144 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:02.718606 12454 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:02.718909 12144 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:02.718977 12144 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/master-0-root
uuid: "206465354b7441a4a9955e3da941c588"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-s11t"
I20260812 06:20:02.719074 12144 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:02.737226 12144 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:02.737671 12144 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:02.742179 12144 rpc_server.cc:307] RPC server started. Bound to: 127.11.220.62:42137
I20260812 06:20:02.747254 12542 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:02.750834 12541 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.220.62:42137 every 8 connection(s)
I20260812 06:20:02.751919 12542 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588: Bootstrap starting.
I20260812 06:20:02.752820 12542 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:02.753942 12542 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588: No bootstrap required, opened a new log
I20260812 06:20:02.754411 12542 raft_consensus.cc:359] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "206465354b7441a4a9955e3da941c588" member_type: VOTER }
I20260812 06:20:02.754508 12542 raft_consensus.cc:385] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:02.754536 12542 raft_consensus.cc:740] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 206465354b7441a4a9955e3da941c588, State: Initialized, Role: FOLLOWER
I20260812 06:20:02.754704 12542 consensus_queue.cc:260] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [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: "206465354b7441a4a9955e3da941c588" member_type: VOTER }
I20260812 06:20:02.754778 12542 raft_consensus.cc:399] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:02.754848 12542 raft_consensus.cc:493] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:02.754891 12542 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:02.755604 12542 raft_consensus.cc:515] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "206465354b7441a4a9955e3da941c588" member_type: VOTER }
I20260812 06:20:02.755720 12542 leader_election.cc:304] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [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: 206465354b7441a4a9955e3da941c588; no voters: 
I20260812 06:20:02.755929 12542 leader_election.cc:290] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:02.756089 12549 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:02.756354 12549 raft_consensus.cc:697] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [term 1 LEADER]: Becoming Leader. State: Replica: 206465354b7441a4a9955e3da941c588, State: Running, Role: LEADER
I20260812 06:20:02.756403 12542 sys_catalog.cc:565] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:02.756495 12549 consensus_queue.cc:237] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [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: "206465354b7441a4a9955e3da941c588" member_type: VOTER }
I20260812 06:20:02.757078 12552 sys_catalog.cc:455] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 206465354b7441a4a9955e3da941c588. Latest consensus state: current_term: 1 leader_uuid: "206465354b7441a4a9955e3da941c588" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "206465354b7441a4a9955e3da941c588" member_type: VOTER } }
I20260812 06:20:02.757174 12552 sys_catalog.cc:458] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:02.757056 12551 sys_catalog.cc:455] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "206465354b7441a4a9955e3da941c588" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "206465354b7441a4a9955e3da941c588" member_type: VOTER } }
I20260812 06:20:02.757268 12551 sys_catalog.cc:458] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:02.757571 12560 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:02.758409 12560 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:02.758677 12144 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:02.760458 12560 catalog_manager.cc:1383] Generated new cluster ID: 5f45b97b0aa44fb2988e9fb06bce66bf
I20260812 06:20:02.760522 12560 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:02.766034 12560 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:02.766601 12560 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:02.771530 12560 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588: Generated new TSK 0
I20260812 06:20:02.771732 12560 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:02.774924 12144 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:02.777154 12575 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:02.777233 12576 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:02.777272 12580 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:02.777395 12144 server_base.cc:1061] running on GCE node
I20260812 06:20:02.777562 12144 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:02.777616 12144 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:02.777652 12144 hybrid_clock.cc:648] HybridClock initialized: now 1786515602777652 us; error 0 us; skew 500 ppm
I20260812 06:20:02.778554 12144 webserver.cc:533] Webserver started at http://127.11.220.1:39127/ using document root <none> and password file <none>
I20260812 06:20:02.778771 12144 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:02.778849 12144 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:02.778934 12144 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:02.779332 12144 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/instance:
uuid: "b2b8db2b12f04c99b2b82a03e71c8321"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-s11t"
I20260812 06:20:02.780941 12144 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:02.781961 12586 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:02.782256 12144 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:02.782346 12144 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root
uuid: "b2b8db2b12f04c99b2b82a03e71c8321"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-s11t"
I20260812 06:20:02.782431 12144 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:02.802925 12144 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:02.803373 12144 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:02.803718 12144 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:02.804214 12144 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:02.804277 12144 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:02.804329 12144 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:02.804380 12144 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:02.808790 12144 rpc_server.cc:307] RPC server started. Bound to: 127.11.220.1:38843
I20260812 06:20:02.810458 12688 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.220.1:38843 every 8 connection(s)
I20260812 06:20:02.820147 12691 heartbeater.cc:344] Connected to a master server at 127.11.220.62:42137
I20260812 06:20:02.820310 12691 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:02.820580 12691 heartbeater.cc:507] Master 127.11.220.62:42137 requested a full tablet report, sending...
I20260812 06:20:02.821358 12476 ts_manager.cc:194] Registered new tserver with Master: b2b8db2b12f04c99b2b82a03e71c8321 (127.11.220.1:38843)
I20260812 06:20:02.822118 12476 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55238
I20260812 06:20:02.822122 12144 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012470875s
I20260812 06:20:02.829770 12476 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55248:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:02.838579 12632 tablet_service.cc:1511] Processing CreateTablet for tablet ed605559b3144884a80aa8b2938568ce (DEFAULT_TABLE table=heavy-update-compaction-test [id=8b6b39eba7d649a39ae5100fd1def700]), partition=
I20260812 06:20:02.838894 12632 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ed605559b3144884a80aa8b2938568ce. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:02.840878 12713 tablet_bootstrap.cc:492] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Bootstrap starting.
I20260812 06:20:02.841862 12713 tablet_bootstrap.cc:654] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:02.843029 12713 tablet_bootstrap.cc:492] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: No bootstrap required, opened a new log
I20260812 06:20:02.843148 12713 ts_tablet_manager.cc:1403] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:02.843585 12713 raft_consensus.cc:359] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b2b8db2b12f04c99b2b82a03e71c8321" member_type: VOTER last_known_addr { host: "127.11.220.1" port: 38843 } }
I20260812 06:20:02.843700 12713 raft_consensus.cc:385] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:02.843762 12713 raft_consensus.cc:740] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b2b8db2b12f04c99b2b82a03e71c8321, State: Initialized, Role: FOLLOWER
I20260812 06:20:02.843935 12713 consensus_queue.cc:260] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [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: "b2b8db2b12f04c99b2b82a03e71c8321" member_type: VOTER last_known_addr { host: "127.11.220.1" port: 38843 } }
I20260812 06:20:02.844044 12713 raft_consensus.cc:399] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:02.844091 12713 raft_consensus.cc:493] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:02.844146 12713 raft_consensus.cc:3060] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:02.845016 12713 raft_consensus.cc:515] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b2b8db2b12f04c99b2b82a03e71c8321" member_type: VOTER last_known_addr { host: "127.11.220.1" port: 38843 } }
I20260812 06:20:02.845175 12713 leader_election.cc:304] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [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: b2b8db2b12f04c99b2b82a03e71c8321; no voters: 
I20260812 06:20:02.845386 12713 leader_election.cc:290] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:02.845597 12717 raft_consensus.cc:2804] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:02.845778 12713 ts_tablet_manager.cc:1434] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:20:02.845784 12691 heartbeater.cc:499] Master 127.11.220.62:42137 was elected leader, sending a full tablet report...
I20260812 06:20:02.845921 12717 raft_consensus.cc:697] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [term 1 LEADER]: Becoming Leader. State: Replica: b2b8db2b12f04c99b2b82a03e71c8321, State: Running, Role: LEADER
I20260812 06:20:02.846097 12717 consensus_queue.cc:237] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [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: "b2b8db2b12f04c99b2b82a03e71c8321" member_type: VOTER last_known_addr { host: "127.11.220.1" port: 38843 } }
I20260812 06:20:02.847489 12476 catalog_manager.cc:5719] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 reported cstate change: term changed from 0 to 1, leader changed from <none> to b2b8db2b12f04c99b2b82a03e71c8321 (127.11.220.1). New cstate: current_term: 1 leader_uuid: "b2b8db2b12f04c99b2b82a03e71c8321" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b2b8db2b12f04c99b2b82a03e71c8321" member_type: VOTER last_known_addr { host: "127.11.220.1" port: 38843 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:02.911782 12144 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.020s	sys 0.006s
I20260812 06:20:03.060974 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushMRSOp(ed605559b3144884a80aa8b2938568ce): perf score=19.054940
I20260812 06:20:03.217090 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushMRSOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.156s	user 0.115s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":793,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37434,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:03.217728 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling LogGCOp(ed605559b3144884a80aa8b2938568ce): free 20743831 bytes of WAL
I20260812 06:20:03.217962 12591 log_reader.cc:385] T ed605559b3144884a80aa8b2938568ce: removed 2 log segments from log reader
I20260812 06:20:03.218024 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000001 (ops 1-6)
I20260812 06:20:03.218079 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000002 (ops 7-11)
I20260812 06:20:03.223724 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: LogGCOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:20:03.224263 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:03.237810 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.238250 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling UndoDeltaBlockGCOp(ed605559b3144884a80aa8b2938568ce): 16411396 bytes on disk
I20260812 06:20:03.238687 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: UndoDeltaBlockGCOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:20:03.239224 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:03.388715 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.149s	user 0.102s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":489,"lbm_read_time_us":9662,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26318,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":335,"threads_started":5,"update_count":2000}
I20260812 06:20:03.389374 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=11.118625
I20260812 06:20:03.433347 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.044s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18136,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:03.433841 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:03.456183 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.022s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4271,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:03.456697 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:03.467414 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4093,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.467841 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:03.654896 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.187s	user 0.125s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":805,"lbm_read_time_us":14037,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31524,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:20:03.655503 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=14.095187
I20260812 06:20:03.717794 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.062s	user 0.028s	sys 0.026s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20170,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.718326 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:03.729259 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.729658 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:03.914259 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.184s	user 0.127s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":565,"lbm_read_time_us":13049,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28905,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:20:03.914995 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=14.095187
I20260812 06:20:03.981052 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.066s	user 0.035s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23422,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.981630 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:03.992889 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4395,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.993320 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:04.185994 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.193s	user 0.108s	sys 0.073s 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":192,"lbm_read_time_us":13115,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30310,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":31744,"update_count":2500}
I20260812 06:20:04.186510 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=14.095187
I20260812 06:20:04.232393 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.046s	user 0.016s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19252,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:20:04.232990 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:04.256210 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.023s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.256765 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:04.441704 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.185s	user 0.115s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":275,"lbm_read_time_us":14360,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27817,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:20:04.442348 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=14.095187
I20260812 06:20:04.499759 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.057s	user 0.020s	sys 0.025s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21259,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.500277 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:04.517134 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.017s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6344,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.517832 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushMRSOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:04.563059 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushMRSOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.045s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1151,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2352,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:04.563694 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling LogGCOp(ed605559b3144884a80aa8b2938568ce): free 112239305 bytes of WAL
I20260812 06:20:04.563943 12591 log_reader.cc:385] T ed605559b3144884a80aa8b2938568ce: removed 11 log segments from log reader
I20260812 06:20:04.563992 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000003 (ops 12-16)
I20260812 06:20:04.564054 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000004 (ops 17-21)
I20260812 06:20:04.564106 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000005 (ops 22-26)
I20260812 06:20:04.564154 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000006 (ops 27-31)
I20260812 06:20:04.564200 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000007 (ops 32-36)
I20260812 06:20:04.564267 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000008 (ops 37-41)
I20260812 06:20:04.564311 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000009 (ops 42-46)
I20260812 06:20:04.564356 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000010 (ops 47-50)
I20260812 06:20:04.564401 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000011 (ops 51-55)
I20260812 06:20:04.564445 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000012 (ops 56-60)
I20260812 06:20:04.564489 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000013 (ops 61-65)
I20260812 06:20:04.593609 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: LogGCOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.030s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:20:04.594051 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling UndoDeltaBlockGCOp(ed605559b3144884a80aa8b2938568ce): 461 bytes on disk
I20260812 06:20:04.594600 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: UndoDeltaBlockGCOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:20:04.595091 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=3.181125
I20260812 06:20:04.608259 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4594951,"delete_count":0,"lbm_write_time_us":4966,"lbm_writes_lt_1ms":115,"reinsert_count":0,"update_count":560}
I20260812 06:20:04.608791 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:04.623193 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":5416,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:20:04.623728 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:04.883671 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.260s	user 0.156s	sys 0.103s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":818,"lbm_read_time_us":18017,"lbm_reads_lt_1ms":774,"lbm_write_time_us":44058,"lbm_writes_lt_1ms":743,"mutex_wait_us":93,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":91,"threads_started":1,"update_count":3500}
I20260812 06:20:04.884442 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=18.063937
I20260812 06:20:04.946091 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.061s	user 0.048s	sys 0.012s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":26832,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:04.946823 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:04.963688 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.017s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5691,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.964344 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:05.184010 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.219s	user 0.122s	sys 0.091s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":235,"lbm_read_time_us":14833,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34772,"lbm_writes_lt_1ms":643,"mutex_wait_us":62,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:20:05.184808 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=18.063937
I20260812 06:20:05.240339 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.055s	user 0.031s	sys 0.017s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":24072,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:05.240913 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:05.427542 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.186s	user 0.121s	sys 0.061s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774574,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":326,"lbm_read_time_us":13512,"lbm_reads_lt_1ms":563,"lbm_write_time_us":31800,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:20:05.428092 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=15.087375
I20260812 06:20:05.506458 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.078s	user 0.034s	sys 0.035s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":27699,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:20:05.506986 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=6.157687
I20260812 06:20:05.526975 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.020s	user 0.013s	sys 0.004s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8303,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:20:05.527750 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:05.744093 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.216s	user 0.148s	sys 0.067s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1353,"lbm_read_time_us":14431,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37586,"lbm_writes_lt_1ms":643,"mutex_wait_us":516,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":3000}
I20260812 06:20:05.744850 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=14.095187
I20260812 06:20:05.806162 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.061s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21020,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.806691 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:05.818369 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.818869 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:05.995937 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.177s	user 0.113s	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":313,"lbm_read_time_us":12935,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28623,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:20:05.996451 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=14.095187
I20260812 06:20:06.066090 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.069s	user 0.041s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28360,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:06.066598 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:06.083714 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.017s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6517,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.084331 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushMRSOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:06.124421 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushMRSOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.040s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1239,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1630,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:06.125167 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling LogGCOp(ed605559b3144884a80aa8b2938568ce): free 124257306 bytes of WAL
I20260812 06:20:06.125438 12591 log_reader.cc:385] T ed605559b3144884a80aa8b2938568ce: removed 12 log segments from log reader
I20260812 06:20:06.125511 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000014 (ops 66-70)
I20260812 06:20:06.125571 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000015 (ops 71-74)
I20260812 06:20:06.125612 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000016 (ops 75-79)
I20260812 06:20:06.125654 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000017 (ops 80-84)
I20260812 06:20:06.125694 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000018 (ops 85-89)
I20260812 06:20:06.125737 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000019 (ops 90-94)
I20260812 06:20:06.125777 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000020 (ops 95-99)
I20260812 06:20:06.125819 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000021 (ops 100-104)
I20260812 06:20:06.125860 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000022 (ops 105-109)
I20260812 06:20:06.125901 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000023 (ops 110-114)
I20260812 06:20:06.125942 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000024 (ops 115-119)
I20260812 06:20:06.125983 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000025 (ops 120-124)
I20260812 06:20:06.157253 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: LogGCOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.032s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:20:06.157727 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=3.181125
I20260812 06:20:06.180999 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.023s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7789,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:06.181514 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling UndoDeltaBlockGCOp(ed605559b3144884a80aa8b2938568ce): 463 bytes on disk
I20260812 06:20:06.181983 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: UndoDeltaBlockGCOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:20:06.182588 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:06.192478 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3644,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:06.193051 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:06.409549 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.216s	user 0.134s	sys 0.077s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2586,"lbm_read_time_us":15834,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39322,"lbm_writes_lt_1ms":743,"mutex_wait_us":1831,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10368,"thread_start_us":111,"threads_started":1,"update_count":3500}
I20260812 06:20:06.410195 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=18.063937
I20260812 06:20:06.466517 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.056s	user 0.030s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25860,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:06.467099 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:06.479768 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4329,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.480242 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:06.649726 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.169s	user 0.117s	sys 0.052s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":360,"lbm_read_time_us":12703,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35433,"lbm_writes_lt_1ms":643,"mutex_wait_us":78,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":3000}
I20260812 06:20:06.650516 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=14.095187
I20260812 06:20:06.709028 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.058s	user 0.033s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24943,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:06.709640 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:06.725344 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.015s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.725860 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:06.896927 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.171s	user 0.101s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2396,"lbm_read_time_us":11551,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28929,"lbm_writes_lt_1ms":543,"mutex_wait_us":1483,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:20:06.897647 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=14.095187
I20260812 06:20:06.961864 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.064s	user 0.023s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23001,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:06.962440 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:06.974125 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4369,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.974931 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:07.155000 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.180s	user 0.124s	sys 0.052s 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":752,"lbm_read_time_us":12073,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33621,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:20:07.155681 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=14.095187
I20260812 06:20:07.217440 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.062s	user 0.035s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23719,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:07.218094 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:07.230569 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4503,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.231216 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:07.403590 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.172s	user 0.112s	sys 0.055s 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":12987,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26916,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:20:07.404294 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=14.095187
I20260812 06:20:07.467131 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.063s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19218,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:07.467742 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:07.478839 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.479338 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushMRSOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:07.525693 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushMRSOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.046s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":111,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1223,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2299,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:07.526428 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling LogGCOp(ed605559b3144884a80aa8b2938568ce): free 121006622 bytes of WAL
I20260812 06:20:07.526664 12591 log_reader.cc:385] T ed605559b3144884a80aa8b2938568ce: removed 12 log segments from log reader
I20260812 06:20:07.526726 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000026 (ops 125-129)
I20260812 06:20:07.526778 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000027 (ops 130-134)
I20260812 06:20:07.526835 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000028 (ops 135-139)
I20260812 06:20:07.526881 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000029 (ops 140-144)
I20260812 06:20:07.526917 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000030 (ops 145-149)
I20260812 06:20:07.526959 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000031 (ops 150-154)
I20260812 06:20:07.526994 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000032 (ops 155-159)
I20260812 06:20:07.527030 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000033 (ops 160-164)
I20260812 06:20:07.527068 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000034 (ops 165-169)
I20260812 06:20:07.527103 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000035 (ops 170-174)
I20260812 06:20:07.527139 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000036 (ops 175-178)
I20260812 06:20:07.527177 12591 log.cc:1079] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: Deleting log segment in path: /tmp/dist-test-task2V2sX_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596944164-12144-0/minicluster-data/ts-0-root/wals/ed605559b3144884a80aa8b2938568ce/wal-000000037 (ops 179-183)
I20260812 06:20:07.554592 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: LogGCOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:07.555609 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling UndoDeltaBlockGCOp(ed605559b3144884a80aa8b2938568ce): 447 bytes on disk
I20260812 06:20:07.556207 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: UndoDeltaBlockGCOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4}
I20260812 06:20:07.556840 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=3.181125
I20260812 06:20:07.570482 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4570,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:07.570932 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:07.580967 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3628,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:07.581468 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:07.815440 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.234s	user 0.144s	sys 0.083s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1054,"lbm_read_time_us":15460,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40752,"lbm_writes_lt_1ms":743,"mutex_wait_us":331,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11392,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:20:07.816059 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=18.063937
I20260812 06:20:07.870661 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.054s	user 0.033s	sys 0.019s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":24478,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:07.871219 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce): perf score=2.188937
I20260812 06:20:07.882810 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: FlushDeltaMemStoresOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4093,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.883342 12693 maintenance_manager.cc:419] P b2b8db2b12f04c99b2b82a03e71c8321: Scheduling MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce): perf score=1.000000
I20260812 06:20:07.957590 12144 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.046s	user 1.877s	sys 0.197s
I20260812 06:20:08.022064 12144 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.064s	user 0.001s	sys 0.000s
I20260812 06:20:08.022559 12144 tablet_server.cc:179] TabletServer@127.11.220.1:0 shutting down...
I20260812 06:20:08.048643 12591 maintenance_manager.cc:643] P b2b8db2b12f04c99b2b82a03e71c8321: MajorDeltaCompactionOp(ed605559b3144884a80aa8b2938568ce) complete. Timing: real 0.165s	user 0.141s	sys 0.024s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":934,"lbm_read_time_us":11718,"lbm_reads_lt_1ms":668,"lbm_write_time_us":36119,"lbm_writes_lt_1ms":643,"mutex_wait_us":303,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":3000}
I20260812 06:20:08.049346 12144 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:08.049602 12144 tablet_replica.cc:333] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321: stopping tablet replica
I20260812 06:20:08.049798 12144 raft_consensus.cc:2243] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:08.049989 12144 raft_consensus.cc:2272] T ed605559b3144884a80aa8b2938568ce P b2b8db2b12f04c99b2b82a03e71c8321 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:08.065703 12144 tablet_server.cc:196] TabletServer@127.11.220.1:0 shutdown complete.
I20260812 06:20:08.101240 12144 master.cc:562] Master@127.11.220.62:42137 shutting down...
I20260812 06:20:08.104635 12144 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:08.104883 12144 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:08.104982 12144 tablet_replica.cc:333] T 00000000000000000000000000000000 P 206465354b7441a4a9955e3da941c588: stopping tablet replica
I20260812 06:20:08.117506 12144 master.cc:584] Master@127.11.220.62:42137 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5498 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11254 ms total)

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