[==========] 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:16:58.978119 26867 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.60.254:44001
I20260812 06:16:58.979116 26867 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:16:58.979727 26867 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:58.985993 26875 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:16:58.986009 26872 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:16:58.986122 26867 server_base.cc:1061] running on GCE node
W20260812 06:16:58.986400 26873 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:16:58.986891 26867 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:58.987013 26867 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:16:58.987048 26867 hybrid_clock.cc:648] HybridClock initialized: now 1786515418987047 us; error 0 us; skew 500 ppm
I20260812 06:16:58.988781 26867 webserver.cc:533] Webserver started at http://127.26.60.254:37143/ using document root <none> and password file <none>
I20260812 06:16:58.989267 26867 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:58.989322 26867 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:58.989504 26867 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:58.991091 26867 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/master-0-root/instance:
uuid: "f3c1140079d84ed1963aa6ee2887e911"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-zkpd"
I20260812 06:16:58.994465 26867 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:16:58.996517 26880 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:16:58.997524 26867 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:58.997656 26867 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/master-0-root
uuid: "f3c1140079d84ed1963aa6ee2887e911"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-zkpd"
I20260812 06:16:58.997756 26867 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-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:16:59.021396 26867 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:59.022115 26867 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:16:59.022305 26867 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:59.030191 26867 rpc_server.cc:307] RPC server started. Bound to: 127.26.60.254:44001
I20260812 06:16:59.030205 26936 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.60.254:44001 every 8 connection(s)
I20260812 06:16:59.032547 26937 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:16:59.038014 26937 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911: Bootstrap starting.
I20260812 06:16:59.040432 26937 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:59.041438 26937 log.cc:826] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:59.043205 26937 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911: No bootstrap required, opened a new log
I20260812 06:16:59.046283 26937 raft_consensus.cc:359] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f3c1140079d84ed1963aa6ee2887e911" member_type: VOTER }
I20260812 06:16:59.046450 26937 raft_consensus.cc:385] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:59.046547 26937 raft_consensus.cc:740] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f3c1140079d84ed1963aa6ee2887e911, State: Initialized, Role: FOLLOWER
I20260812 06:16:59.047250 26937 consensus_queue.cc:260] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [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: "f3c1140079d84ed1963aa6ee2887e911" member_type: VOTER }
I20260812 06:16:59.047435 26937 raft_consensus.cc:399] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:59.047513 26937 raft_consensus.cc:493] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:59.047711 26937 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:59.048681 26937 raft_consensus.cc:515] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f3c1140079d84ed1963aa6ee2887e911" member_type: VOTER }
I20260812 06:16:59.049127 26937 leader_election.cc:304] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [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: f3c1140079d84ed1963aa6ee2887e911; no voters: 
I20260812 06:16:59.049463 26937 leader_election.cc:290] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:59.049589 26940 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:59.049856 26940 raft_consensus.cc:697] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [term 1 LEADER]: Becoming Leader. State: Replica: f3c1140079d84ed1963aa6ee2887e911, State: Running, Role: LEADER
I20260812 06:16:59.050248 26940 consensus_queue.cc:237] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [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: "f3c1140079d84ed1963aa6ee2887e911" member_type: VOTER }
I20260812 06:16:59.050514 26937 sys_catalog.cc:565] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:59.052228 26942 sys_catalog.cc:455] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [sys.catalog]: SysCatalogTable state changed. Reason: New leader f3c1140079d84ed1963aa6ee2887e911. Latest consensus state: current_term: 1 leader_uuid: "f3c1140079d84ed1963aa6ee2887e911" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f3c1140079d84ed1963aa6ee2887e911" member_type: VOTER } }
I20260812 06:16:59.052254 26941 sys_catalog.cc:455] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f3c1140079d84ed1963aa6ee2887e911" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f3c1140079d84ed1963aa6ee2887e911" member_type: VOTER } }
I20260812 06:16:59.052359 26941 sys_catalog.cc:458] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:59.052358 26942 sys_catalog.cc:458] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:59.053412 26950 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:59.053553 26867 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:59.055583 26950 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:59.060186 26950 catalog_manager.cc:1383] Generated new cluster ID: 5edfd881074340b0a825741ca9aaa424
I20260812 06:16:59.060251 26950 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:59.072742 26950 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:59.073585 26950 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:59.079231 26950 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911: Generated new TSK 0
I20260812 06:16:59.079833 26950 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:59.086019 26867 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:59.088618 26964 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:16:59.088644 26962 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:16:59.088665 26961 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:16:59.089023 26867 server_base.cc:1061] running on GCE node
I20260812 06:16:59.089215 26867 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:59.089277 26867 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:16:59.089305 26867 hybrid_clock.cc:648] HybridClock initialized: now 1786515419089304 us; error 0 us; skew 500 ppm
I20260812 06:16:59.090260 26867 webserver.cc:533] Webserver started at http://127.26.60.193:46247/ using document root <none> and password file <none>
I20260812 06:16:59.090464 26867 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:59.090543 26867 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:59.090626 26867 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:59.091020 26867 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/instance:
uuid: "4b359c4d9e3343b59c96eed5fc1b2b7e"
format_stamp: "Formatted at 2026-08-12 06:16:59 on dist-test-slave-zkpd"
I20260812 06:16:59.092785 26867 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:59.093837 26969 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:16:59.094098 26867 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:59.094193 26867 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root
uuid: "4b359c4d9e3343b59c96eed5fc1b2b7e"
format_stamp: "Formatted at 2026-08-12 06:16:59 on dist-test-slave-zkpd"
I20260812 06:16:59.094286 26867 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-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:16:59.100944 26867 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:59.101424 26867 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:59.101948 26867 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:59.103099 26867 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:59.103179 26867 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:59.103251 26867 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:59.103286 26867 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:59.109831 26867 rpc_server.cc:307] RPC server started. Bound to: 127.26.60.193:46055
I20260812 06:16:59.109891 27036 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.60.193:46055 every 8 connection(s)
I20260812 06:16:59.124699 27037 heartbeater.cc:344] Connected to a master server at 127.26.60.254:44001
I20260812 06:16:59.124962 27037 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:59.125458 27037 heartbeater.cc:507] Master 127.26.60.254:44001 requested a full tablet report, sending...
I20260812 06:16:59.126982 26897 ts_manager.cc:194] Registered new tserver with Master: 4b359c4d9e3343b59c96eed5fc1b2b7e (127.26.60.193:46055)
I20260812 06:16:59.127342 26867 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016859641s
I20260812 06:16:59.128357 26897 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53350
I20260812 06:16:59.137347 26897 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53354:
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:16:59.152958 27000 tablet_service.cc:1511] Processing CreateTablet for tablet 4130fb8d4f3644e3be49a5125ad78bf0 (DEFAULT_TABLE table=heavy-update-compaction-test [id=36a8b2d6377b46f68f1a855e45da5b59]), partition=
I20260812 06:16:59.153499 27000 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4130fb8d4f3644e3be49a5125ad78bf0. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:59.156453 27049 tablet_bootstrap.cc:492] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Bootstrap starting.
I20260812 06:16:59.157516 27049 tablet_bootstrap.cc:654] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:59.158926 27049 tablet_bootstrap.cc:492] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: No bootstrap required, opened a new log
I20260812 06:16:59.159045 27049 ts_tablet_manager.cc:1403] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:59.159605 27049 raft_consensus.cc:359] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b359c4d9e3343b59c96eed5fc1b2b7e" member_type: VOTER last_known_addr { host: "127.26.60.193" port: 46055 } }
I20260812 06:16:59.159704 27049 raft_consensus.cc:385] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:59.159726 27049 raft_consensus.cc:740] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4b359c4d9e3343b59c96eed5fc1b2b7e, State: Initialized, Role: FOLLOWER
I20260812 06:16:59.159940 27049 consensus_queue.cc:260] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [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: "4b359c4d9e3343b59c96eed5fc1b2b7e" member_type: VOTER last_known_addr { host: "127.26.60.193" port: 46055 } }
I20260812 06:16:59.160048 27049 raft_consensus.cc:399] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:59.160118 27049 raft_consensus.cc:493] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:59.160178 27049 raft_consensus.cc:3060] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:59.160925 27049 raft_consensus.cc:515] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b359c4d9e3343b59c96eed5fc1b2b7e" member_type: VOTER last_known_addr { host: "127.26.60.193" port: 46055 } }
I20260812 06:16:59.161080 27049 leader_election.cc:304] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [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: 4b359c4d9e3343b59c96eed5fc1b2b7e; no voters: 
I20260812 06:16:59.161324 27049 leader_election.cc:290] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:59.161451 27051 raft_consensus.cc:2804] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:59.161638 27051 raft_consensus.cc:697] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [term 1 LEADER]: Becoming Leader. State: Replica: 4b359c4d9e3343b59c96eed5fc1b2b7e, State: Running, Role: LEADER
I20260812 06:16:59.161743 27049 ts_tablet_manager.cc:1434] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:16:59.161839 27051 consensus_queue.cc:237] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [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: "4b359c4d9e3343b59c96eed5fc1b2b7e" member_type: VOTER last_known_addr { host: "127.26.60.193" port: 46055 } }
I20260812 06:16:59.162052 27037 heartbeater.cc:499] Master 127.26.60.254:44001 was elected leader, sending a full tablet report...
I20260812 06:16:59.165045 26896 catalog_manager.cc:5719] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e reported cstate change: term changed from 0 to 1, leader changed from <none> to 4b359c4d9e3343b59c96eed5fc1b2b7e (127.26.60.193). New cstate: current_term: 1 leader_uuid: "4b359c4d9e3343b59c96eed5fc1b2b7e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b359c4d9e3343b59c96eed5fc1b2b7e" member_type: VOTER last_known_addr { host: "127.26.60.193" port: 46055 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:59.248435 26867 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.076s	user 0.025s	sys 0.007s
I20260812 06:16:59.360976 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushMRSOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=15.086190
I20260812 06:16:59.541011 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushMRSOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.180s	user 0.135s	sys 0.035s Metrics: {"bytes_written":10461405,"cfile_init":1,"compiler_manager_pool.queue_time_us":241,"delete_count":0,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1315,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":49866,"lbm_writes_lt_1ms":612,"mutex_wait_us":1272,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":113536,"thread_start_us":172,"threads_started":1,"update_count":1275}
I20260812 06:16:59.542655 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling UndoDeltaBlockGCOp(4130fb8d4f3644e3be49a5125ad78bf0): 12308955 bytes on disk
I20260812 06:16:59.543176 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: UndoDeltaBlockGCOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:16:59.543624 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:16:59.558316 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3651388,"delete_count":0,"lbm_write_time_us":6446,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:16:59.558802 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling LogGCOp(4130fb8d4f3644e3be49a5125ad78bf0): free 8725963 bytes of WAL
I20260812 06:16:59.559126 26975 log_reader.cc:385] T 4130fb8d4f3644e3be49a5125ad78bf0: removed 1 log segments from log reader
I20260812 06:16:59.559228 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000001 (ops 1-6)
I20260812 06:16:59.561993 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: LogGCOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:59.562330 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.196750
I20260812 06:16:59.572096 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2297554,"delete_count":0,"lbm_write_time_us":3463,"lbm_writes_lt_1ms":59,"reinsert_count":0,"update_count":280}
I20260812 06:16:59.572635 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:16:59.719606 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.147s	user 0.113s	sys 0.033s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20631382,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":566,"lbm_read_time_us":11074,"lbm_reads_lt_1ms":469,"lbm_write_time_us":27748,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"thread_start_us":354,"threads_started":5,"update_count":2000}
I20260812 06:16:59.720212 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=10.126437
I20260812 06:16:59.763247 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.043s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20465,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.763698 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:16:59.783645 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.020s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7440,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.784148 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:16:59.909855 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.126s	user 0.094s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":328,"lbm_read_time_us":7199,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24607,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":76800,"update_count":2000}
I20260812 06:16:59.911500 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=10.126437
I20260812 06:16:59.958560 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.047s	user 0.016s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16513,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.959233 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:16:59.979043 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.020s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6408,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.979591 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:00.130098 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.150s	user 0.106s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":258,"lbm_read_time_us":8592,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23687,"lbm_writes_lt_1ms":443,"mutex_wait_us":4,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:00.130774 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=14.095187
I20260812 06:17:00.186084 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.055s	user 0.029s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26365,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:00.186584 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:00.197686 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.198153 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:00.358215 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.160s	user 0.110s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":759,"lbm_read_time_us":11619,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28599,"lbm_writes_lt_1ms":543,"mutex_wait_us":248,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:00.358948 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=11.118625
I20260812 06:17:00.405040 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.046s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18641,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:00.405620 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:00.422214 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.016s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3965,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.422680 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:00.432646 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3754,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:00.433048 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:00.575675 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.142s	user 0.103s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":71,"lbm_read_time_us":10376,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28512,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:00.576596 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=10.126437
I20260812 06:17:00.609200 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.032s	user 0.012s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14503,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.609681 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:00.620280 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4113,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.620723 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:00.749476 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.129s	user 0.107s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":264,"lbm_read_time_us":7790,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26562,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:17:00.749955 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=10.126437
I20260812 06:17:00.781581 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.031s	user 0.021s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13648,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.782064 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushMRSOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:00.837714 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushMRSOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.055s	user 0.031s	sys 0.004s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":132,"dirs.run_cpu_time_us":172,"dirs.run_wall_time_us":1325,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2015,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:00.838517 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling LogGCOp(4130fb8d4f3644e3be49a5125ad78bf0): free 127961117 bytes of WAL
I20260812 06:17:00.838779 26975 log_reader.cc:385] T 4130fb8d4f3644e3be49a5125ad78bf0: removed 12 log segments from log reader
I20260812 06:17:00.838850 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000002 (ops 7-11)
I20260812 06:17:00.838891 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000003 (ops 12-16)
I20260812 06:17:00.838927 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000004 (ops 17-21)
I20260812 06:17:00.838956 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000005 (ops 22-26)
I20260812 06:17:00.838979 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000006 (ops 27-31)
I20260812 06:17:00.839005 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000007 (ops 32-36)
I20260812 06:17:00.839038 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000008 (ops 37-41)
I20260812 06:17:00.839073 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000009 (ops 42-46)
I20260812 06:17:00.839104 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000010 (ops 47-51)
I20260812 06:17:00.839133 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000011 (ops 52-56)
I20260812 06:17:00.839162 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000012 (ops 57-61)
I20260812 06:17:00.839190 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000013 (ops 62-66)
I20260812 06:17:00.871228 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: LogGCOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.033s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:17:00.871630 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling UndoDeltaBlockGCOp(4130fb8d4f3644e3be49a5125ad78bf0): 472 bytes on disk
I20260812 06:17:00.872119 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: UndoDeltaBlockGCOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4}
I20260812 06:17:00.872575 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=7.149875
I20260812 06:17:00.892536 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.020s	user 0.016s	sys 0.003s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":8639,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:00.892980 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:00.903664 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3962,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:00.904114 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:01.070905 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.167s	user 0.128s	sys 0.038s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836247,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":368,"lbm_read_time_us":12120,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34830,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8960,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:17:01.071554 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=14.095187
I20260812 06:17:01.126995 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.055s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21467,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.127456 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:01.139254 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4466,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.139765 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:01.299070 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.159s	user 0.115s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1005,"lbm_read_time_us":11290,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27815,"lbm_writes_lt_1ms":543,"mutex_wait_us":324,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27136,"update_count":2500}
I20260812 06:17:01.299700 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=14.095187
I20260812 06:17:01.354115 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.054s	user 0.028s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24700,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.354666 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:01.509384 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.154s	user 0.099s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631194,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":978,"lbm_read_time_us":10327,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26654,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:01.510234 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=11.118625
I20260812 06:17:01.543371 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.033s	user 0.012s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13682,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:01.543851 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:01.557453 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5267,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":450}
I20260812 06:17:01.557919 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:01.691119 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.133s	user 0.092s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":695,"lbm_read_time_us":8292,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25635,"lbm_writes_lt_1ms":443,"mutex_wait_us":515,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.691870 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=10.126437
I20260812 06:17:01.721773 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.030s	user 0.019s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13295,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.722223 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:01.737080 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.015s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4935,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.737512 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:01.865774 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.128s	user 0.075s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":9524,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23689,"lbm_writes_lt_1ms":443,"mutex_wait_us":18,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:17:01.866459 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=10.126437
I20260812 06:17:01.909585 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.043s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15724,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.910113 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:01.920718 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3983,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.921304 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:02.054265 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.133s	user 0.109s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":152,"lbm_read_time_us":8463,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28006,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2000}
I20260812 06:17:02.055284 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=10.126437
I20260812 06:17:02.105839 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.050s	user 0.033s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16983,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.106395 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:02.117017 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.117667 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:02.282426 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.165s	user 0.108s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1891,"lbm_read_time_us":11966,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27589,"lbm_writes_lt_1ms":443,"mutex_wait_us":800,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:17:02.282968 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=10.126437
I20260812 06:17:02.321923 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.039s	user 0.028s	sys 0.003s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14511,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.322407 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:02.334316 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4241,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.335070 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushMRSOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:02.364032 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushMRSOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.029s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1491,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1921,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:02.364764 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling LogGCOp(4130fb8d4f3644e3be49a5125ad78bf0): free 133024372 bytes of WAL
I20260812 06:17:02.365037 26975 log_reader.cc:385] T 4130fb8d4f3644e3be49a5125ad78bf0: removed 13 log segments from log reader
I20260812 06:17:02.365099 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000014 (ops 67-71)
I20260812 06:17:02.365140 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000015 (ops 72-76)
I20260812 06:17:02.365170 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000016 (ops 77-81)
I20260812 06:17:02.365199 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000017 (ops 82-86)
I20260812 06:17:02.365229 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000018 (ops 87-90)
I20260812 06:17:02.365258 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000019 (ops 91-95)
I20260812 06:17:02.365294 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000020 (ops 96-100)
I20260812 06:17:02.365327 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000021 (ops 101-105)
I20260812 06:17:02.365356 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000022 (ops 106-110)
I20260812 06:17:02.365384 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000023 (ops 111-115)
I20260812 06:17:02.365410 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000024 (ops 116-120)
I20260812 06:17:02.365438 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000025 (ops 121-125)
I20260812 06:17:02.365473 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000026 (ops 126-130)
I20260812 06:17:02.399495 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: LogGCOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.035s	user 0.001s	sys 0.030s Metrics: {}
I20260812 06:17:02.399960 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling UndoDeltaBlockGCOp(4130fb8d4f3644e3be49a5125ad78bf0): 483 bytes on disk
I20260812 06:17:02.400400 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: UndoDeltaBlockGCOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:02.400976 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:02.430613 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.029s	user 0.011s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6404,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.431069 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:02.443614 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.444149 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:02.649107 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.205s	user 0.135s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836376,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":433,"lbm_read_time_us":14882,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34428,"lbm_writes_lt_1ms":643,"mutex_wait_us":67,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:17:02.649884 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=14.095187
I20260812 06:17:02.718585 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.068s	user 0.031s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23518,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.719182 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:02.730896 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4562,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.731364 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:02.913280 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.182s	user 0.126s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":13435,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28856,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:17:02.913986 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=14.095187
I20260812 06:17:02.965791 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.052s	user 0.018s	sys 0.021s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18427,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.966291 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:02.985807 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.019s	user 0.007s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4157,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.986277 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:03.160172 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.174s	user 0.124s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733721,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":605,"lbm_read_time_us":12183,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27110,"lbm_writes_lt_1ms":543,"mutex_wait_us":286,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:17:03.160815 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=14.095187
I20260812 06:17:03.216408 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.055s	user 0.033s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22402,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.216876 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:03.229022 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.229835 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:03.416787 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.187s	user 0.127s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":641,"lbm_read_time_us":11639,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30334,"lbm_writes_lt_1ms":543,"mutex_wait_us":271,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:17:03.417515 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=14.095187
I20260812 06:17:03.471576 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.054s	user 0.024s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23131,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.472183 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:03.482893 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3973,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.483561 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:03.637722 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.154s	user 0.104s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733721,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":842,"lbm_read_time_us":10725,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29422,"lbm_writes_lt_1ms":543,"mutex_wait_us":253,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:17:03.638382 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=14.095187
I20260812 06:17:03.687474 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.049s	user 0.030s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18747,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.688081 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:03.703783 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5812,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.704360 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:03.849664 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.145s	user 0.099s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":118,"lbm_read_time_us":11366,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29284,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:17:03.850422 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=10.126437
I20260812 06:17:03.881820 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.031s	user 0.012s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13952,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.882277 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:03.892582 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4170,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.893010 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushMRSOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:03.926417 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushMRSOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1330,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3000,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":38,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:03.927068 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling LogGCOp(4130fb8d4f3644e3be49a5125ad78bf0): free 129320776 bytes of WAL
I20260812 06:17:03.927286 26975 log_reader.cc:385] T 4130fb8d4f3644e3be49a5125ad78bf0: removed 13 log segments from log reader
I20260812 06:17:03.927351 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000027 (ops 131-135)
I20260812 06:17:03.927405 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000028 (ops 136-140)
I20260812 06:17:03.927465 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000029 (ops 141-145)
I20260812 06:17:03.927510 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000030 (ops 146-150)
I20260812 06:17:03.927548 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000031 (ops 151-154)
I20260812 06:17:03.927587 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000032 (ops 155-159)
I20260812 06:17:03.927625 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000033 (ops 160-164)
I20260812 06:17:03.927663 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000034 (ops 165-169)
I20260812 06:17:03.927702 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000035 (ops 170-174)
I20260812 06:17:03.927740 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000036 (ops 175-179)
I20260812 06:17:03.927779 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000037 (ops 180-184)
I20260812 06:17:03.927824 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000038 (ops 185-188)
I20260812 06:17:03.927863 26975 log.cc:1079] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/4130fb8d4f3644e3be49a5125ad78bf0/wal-000000039 (ops 189-193)
I20260812 06:17:03.956568 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: LogGCOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:03.957085 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=3.181125
I20260812 06:17:03.974568 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4553933,"delete_count":0,"lbm_write_time_us":7039,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:17:03.975033 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling UndoDeltaBlockGCOp(4130fb8d4f3644e3be49a5125ad78bf0): 482 bytes on disk
I20260812 06:17:03.975461 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: UndoDeltaBlockGCOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:17:03.976118 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=2.188937
I20260812 06:17:03.986497 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":3779,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:17:03.986951 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=1.000000
I20260812 06:17:04.099496 26867 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.851s	user 1.791s	sys 0.116s
I20260812 06:17:04.150405 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: MajorDeltaCompactionOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.163s	user 0.138s	sys 0.023s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836369,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":12696,"lbm_reads_lt_1ms":670,"lbm_write_time_us":31655,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":3000}
I20260812 06:17:04.150902 27038 maintenance_manager.cc:419] P 4b359c4d9e3343b59c96eed5fc1b2b7e: Scheduling FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0): perf score=10.126437
I20260812 06:17:04.179982 26867 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.080s	user 0.004s	sys 0.000s
I20260812 06:17:04.180711 26867 tablet_server.cc:179] TabletServer@127.26.60.193:0 shutting down...
I20260812 06:17:04.189458 26975 maintenance_manager.cc:643] P 4b359c4d9e3343b59c96eed5fc1b2b7e: FlushDeltaMemStoresOp(4130fb8d4f3644e3be49a5125ad78bf0) complete. Timing: real 0.038s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16783,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:04.190003 26867 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:04.191166 26867 tablet_replica.cc:333] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e: stopping tablet replica
I20260812 06:17:04.191354 26867 raft_consensus.cc:2243] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:04.191530 26867 raft_consensus.cc:2272] T 4130fb8d4f3644e3be49a5125ad78bf0 P 4b359c4d9e3343b59c96eed5fc1b2b7e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:04.206396 26867 tablet_server.cc:196] TabletServer@127.26.60.193:0 shutdown complete.
I20260812 06:17:04.214250 26867 master.cc:562] Master@127.26.60.254:44001 shutting down...
I20260812 06:17:04.218008 26867 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:04.218185 26867 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:04.218281 26867 tablet_replica.cc:333] T 00000000000000000000000000000000 P f3c1140079d84ed1963aa6ee2887e911: stopping tablet replica
I20260812 06:17:04.230327 26867 master.cc:584] Master@127.26.60.254:44001 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5338 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:04.316679 26867 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.60.254:44207
I20260812 06:17:04.317085 26867 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:04.319334 27074 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:04.319375 26867 server_base.cc:1061] running on GCE node
W20260812 06:17:04.319428 27072 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:04.319428 27071 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:04.319748 26867 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:04.319795 26867 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:04.319810 26867 hybrid_clock.cc:648] HybridClock initialized: now 1786515424319811 us; error 0 us; skew 500 ppm
I20260812 06:17:04.320688 26867 webserver.cc:533] Webserver started at http://127.26.60.254:44341/ using document root <none> and password file <none>
I20260812 06:17:04.320863 26867 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:04.320907 26867 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:04.321013 26867 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:04.321424 26867 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/master-0-root/instance:
uuid: "a43be4dd970e4017b61f87ab49c50b22"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-zkpd"
I20260812 06:17:04.322984 26867 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:04.324040 27080 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:04.324343 26867 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:04.324447 26867 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/master-0-root
uuid: "a43be4dd970e4017b61f87ab49c50b22"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-zkpd"
I20260812 06:17:04.324530 26867 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:04.338328 26867 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:04.338706 26867 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:04.342988 26867 rpc_server.cc:307] RPC server started. Bound to: 127.26.60.254:44207
I20260812 06:17:04.347941 27135 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:04.362452 27134 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.60.254:44207 every 8 connection(s)
I20260812 06:17:04.362743 27135 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22: Bootstrap starting.
I20260812 06:17:04.363570 27135 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:04.364688 27135 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22: No bootstrap required, opened a new log
I20260812 06:17:04.365121 27135 raft_consensus.cc:359] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a43be4dd970e4017b61f87ab49c50b22" member_type: VOTER }
I20260812 06:17:04.365213 27135 raft_consensus.cc:385] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:04.365235 27135 raft_consensus.cc:740] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a43be4dd970e4017b61f87ab49c50b22, State: Initialized, Role: FOLLOWER
I20260812 06:17:04.365442 27135 consensus_queue.cc:260] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [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: "a43be4dd970e4017b61f87ab49c50b22" member_type: VOTER }
I20260812 06:17:04.365535 27135 raft_consensus.cc:399] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:04.365602 27135 raft_consensus.cc:493] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:04.365662 27135 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:04.366361 27135 raft_consensus.cc:515] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a43be4dd970e4017b61f87ab49c50b22" member_type: VOTER }
I20260812 06:17:04.366515 27135 leader_election.cc:304] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [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: a43be4dd970e4017b61f87ab49c50b22; no voters: 
I20260812 06:17:04.366743 27135 leader_election.cc:290] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:04.366912 27139 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:04.367100 27139 raft_consensus.cc:697] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [term 1 LEADER]: Becoming Leader. State: Replica: a43be4dd970e4017b61f87ab49c50b22, State: Running, Role: LEADER
I20260812 06:17:04.367225 27135 sys_catalog.cc:565] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:04.367269 27139 consensus_queue.cc:237] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [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: "a43be4dd970e4017b61f87ab49c50b22" member_type: VOTER }
I20260812 06:17:04.367733 27142 sys_catalog.cc:455] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a43be4dd970e4017b61f87ab49c50b22. Latest consensus state: current_term: 1 leader_uuid: "a43be4dd970e4017b61f87ab49c50b22" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a43be4dd970e4017b61f87ab49c50b22" member_type: VOTER } }
I20260812 06:17:04.367686 27141 sys_catalog.cc:455] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a43be4dd970e4017b61f87ab49c50b22" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a43be4dd970e4017b61f87ab49c50b22" member_type: VOTER } }
I20260812 06:17:04.367812 27142 sys_catalog.cc:458] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:04.367822 27141 sys_catalog.cc:458] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:04.368161 27145 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:04.368902 27145 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:04.369254 26867 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:04.370719 27145 catalog_manager.cc:1383] Generated new cluster ID: 923d5ff4179d4cb4ab77f36a0375f5ec
I20260812 06:17:04.370782 27145 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:04.391654 27145 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:04.392282 27145 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:04.399214 27145 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22: Generated new TSK 0
I20260812 06:17:04.399410 27145 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:04.401404 26867 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:04.403262 27160 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:04.403306 27161 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:04.403379 27163 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:04.403446 26867 server_base.cc:1061] running on GCE node
I20260812 06:17:04.403772 26867 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:04.403824 26867 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:04.403839 26867 hybrid_clock.cc:648] HybridClock initialized: now 1786515424403839 us; error 0 us; skew 500 ppm
I20260812 06:17:04.404703 26867 webserver.cc:533] Webserver started at http://127.26.60.193:33751/ using document root <none> and password file <none>
I20260812 06:17:04.404887 26867 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:04.404960 26867 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:04.405035 26867 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:04.405398 26867 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/instance:
uuid: "abd32a1cf81b4ab5915be2a69e839bf1"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-zkpd"
I20260812 06:17:04.406895 26867 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:04.407833 27170 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:04.408114 26867 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:04.408187 26867 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root
uuid: "abd32a1cf81b4ab5915be2a69e839bf1"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-zkpd"
I20260812 06:17:04.408242 26867 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:04.413334 26867 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:04.413596 26867 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:04.413843 26867 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:04.414289 26867 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:04.414326 26867 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:04.414387 26867 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:04.414433 26867 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:04.418522 26867 rpc_server.cc:307] RPC server started. Bound to: 127.26.60.193:38063
I20260812 06:17:04.418545 27240 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.60.193:38063 every 8 connection(s)
I20260812 06:17:04.427445 27241 heartbeater.cc:344] Connected to a master server at 127.26.60.254:44207
I20260812 06:17:04.427553 27241 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:04.427819 27241 heartbeater.cc:507] Master 127.26.60.254:44207 requested a full tablet report, sending...
I20260812 06:17:04.428508 27098 ts_manager.cc:194] Registered new tserver with Master: abd32a1cf81b4ab5915be2a69e839bf1 (127.26.60.193:38063)
I20260812 06:17:04.428939 26867 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009986445s
I20260812 06:17:04.429287 27098 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40298
I20260812 06:17:04.435804 27098 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40310:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:04.444675 27200 tablet_service.cc:1511] Processing CreateTablet for tablet 3798f150c5094f5d955876bbe1ecdb0a (DEFAULT_TABLE table=heavy-update-compaction-test [id=71e81935000645e9bfade89cf792f232]), partition=
I20260812 06:17:04.444969 27200 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3798f150c5094f5d955876bbe1ecdb0a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:04.447021 27254 tablet_bootstrap.cc:492] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Bootstrap starting.
I20260812 06:17:04.447942 27254 tablet_bootstrap.cc:654] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:04.448974 27254 tablet_bootstrap.cc:492] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: No bootstrap required, opened a new log
I20260812 06:17:04.449044 27254 ts_tablet_manager.cc:1403] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:04.449383 27254 raft_consensus.cc:359] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "abd32a1cf81b4ab5915be2a69e839bf1" member_type: VOTER last_known_addr { host: "127.26.60.193" port: 38063 } }
I20260812 06:17:04.449463 27254 raft_consensus.cc:385] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:04.449486 27254 raft_consensus.cc:740] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: abd32a1cf81b4ab5915be2a69e839bf1, State: Initialized, Role: FOLLOWER
I20260812 06:17:04.449580 27254 consensus_queue.cc:260] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [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: "abd32a1cf81b4ab5915be2a69e839bf1" member_type: VOTER last_known_addr { host: "127.26.60.193" port: 38063 } }
I20260812 06:17:04.449638 27254 raft_consensus.cc:399] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:04.449661 27254 raft_consensus.cc:493] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:04.449689 27254 raft_consensus.cc:3060] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:04.450589 27254 raft_consensus.cc:515] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "abd32a1cf81b4ab5915be2a69e839bf1" member_type: VOTER last_known_addr { host: "127.26.60.193" port: 38063 } }
I20260812 06:17:04.450721 27254 leader_election.cc:304] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [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: abd32a1cf81b4ab5915be2a69e839bf1; no voters: 
I20260812 06:17:04.450862 27254 leader_election.cc:290] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:04.451006 27256 raft_consensus.cc:2804] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:04.451179 27254 ts_tablet_manager.cc:1434] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:04.451232 27256 raft_consensus.cc:697] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [term 1 LEADER]: Becoming Leader. State: Replica: abd32a1cf81b4ab5915be2a69e839bf1, State: Running, Role: LEADER
I20260812 06:17:04.451217 27241 heartbeater.cc:499] Master 127.26.60.254:44207 was elected leader, sending a full tablet report...
I20260812 06:17:04.451439 27256 consensus_queue.cc:237] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [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: "abd32a1cf81b4ab5915be2a69e839bf1" member_type: VOTER last_known_addr { host: "127.26.60.193" port: 38063 } }
I20260812 06:17:04.452723 27098 catalog_manager.cc:5719] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 reported cstate change: term changed from 0 to 1, leader changed from <none> to abd32a1cf81b4ab5915be2a69e839bf1 (127.26.60.193). New cstate: current_term: 1 leader_uuid: "abd32a1cf81b4ab5915be2a69e839bf1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "abd32a1cf81b4ab5915be2a69e839bf1" member_type: VOTER last_known_addr { host: "127.26.60.193" port: 38063 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:04.509326 26867 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.006s	sys 0.016s
I20260812 06:17:04.669521 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushMRSOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=19.054940
I20260812 06:17:04.826599 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushMRSOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.157s	user 0.118s	sys 0.036s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":864,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39126,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:04.827234 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling LogGCOp(3798f150c5094f5d955876bbe1ecdb0a): free 20290830 bytes of WAL
I20260812 06:17:04.827513 27176 log_reader.cc:385] T 3798f150c5094f5d955876bbe1ecdb0a: removed 2 log segments from log reader
I20260812 06:17:04.827574 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000001 (ops 1-6)
I20260812 06:17:04.827612 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000002 (ops 7-10)
I20260812 06:17:04.833410 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: LogGCOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:04.833791 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:04.852664 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.019s	user 0.004s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6205,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.853137 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling UndoDeltaBlockGCOp(3798f150c5094f5d955876bbe1ecdb0a): 16411392 bytes on disk
I20260812 06:17:04.853523 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: UndoDeltaBlockGCOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4}
I20260812 06:17:04.853924 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:04.982980 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.129s	user 0.087s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":835,"lbm_read_time_us":10024,"lbm_reads_lt_1ms":460,"lbm_write_time_us":21905,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":336,"threads_started":5,"update_count":2000}
I20260812 06:17:04.983644 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=11.118625
I20260812 06:17:05.020430 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.036s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15662,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:05.021016 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:05.035455 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5424,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:05.036073 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:05.167800 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.132s	user 0.098s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":862,"lbm_read_time_us":10042,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25278,"lbm_writes_lt_1ms":443,"mutex_wait_us":375,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21376,"update_count":2000}
I20260812 06:17:05.168642 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=10.126437
I20260812 06:17:05.223278 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.054s	user 0.025s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18829,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.223879 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:05.234864 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.235301 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:05.389009 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.154s	user 0.085s	sys 0.068s 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":293,"lbm_read_time_us":11875,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22856,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2000}
I20260812 06:17:05.389649 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=10.126437
I20260812 06:17:05.435614 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.046s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18083,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.436152 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:05.447054 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4153,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.447713 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:05.577440 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.130s	user 0.099s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":656,"lbm_read_time_us":11080,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22174,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27776,"update_count":2000}
I20260812 06:17:05.578135 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=10.126437
I20260812 06:17:05.625286 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.047s	user 0.025s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17050,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.625788 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:05.636466 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.637146 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:05.757118 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.120s	user 0.087s	sys 0.032s 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":150,"lbm_read_time_us":7779,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24720,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:17:05.757639 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=10.126437
I20260812 06:17:05.821102 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.063s	user 0.028s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17826,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.821669 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:05.839043 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6643,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.839577 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:05.982443 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.143s	user 0.101s	sys 0.041s 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":958,"lbm_read_time_us":11310,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22415,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22016,"update_count":2000}
I20260812 06:17:05.983029 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=10.126437
I20260812 06:17:06.026614 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.043s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18278,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:06.027094 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:06.038455 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4157,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.039148 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushMRSOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:06.068125 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushMRSOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.029s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1449,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1685,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:06.068792 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling LogGCOp(3798f150c5094f5d955876bbe1ecdb0a): free 108535391 bytes of WAL
I20260812 06:17:06.069005 27176 log_reader.cc:385] T 3798f150c5094f5d955876bbe1ecdb0a: removed 11 log segments from log reader
I20260812 06:17:06.069048 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000003 (ops 11-15)
I20260812 06:17:06.069077 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000004 (ops 16-20)
I20260812 06:17:06.069130 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000005 (ops 21-25)
I20260812 06:17:06.069164 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000006 (ops 26-30)
I20260812 06:17:06.069198 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000007 (ops 31-35)
I20260812 06:17:06.069254 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000008 (ops 36-40)
I20260812 06:17:06.069293 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000009 (ops 41-44)
I20260812 06:17:06.069330 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000010 (ops 45-49)
I20260812 06:17:06.069366 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000011 (ops 50-54)
I20260812 06:17:06.069402 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000012 (ops 55-58)
I20260812 06:17:06.069439 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000013 (ops 59-63)
I20260812 06:17:06.093693 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: LogGCOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.025s	user 0.001s	sys 0.022s Metrics: {}
I20260812 06:17:06.094240 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling UndoDeltaBlockGCOp(3798f150c5094f5d955876bbe1ecdb0a): 447 bytes on disk
I20260812 06:17:06.094725 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: UndoDeltaBlockGCOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:17:06.095217 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=3.181125
I20260812 06:17:06.127174 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.032s	user 0.011s	sys 0.014s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7269,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:06.127642 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling LogGCOp(3798f150c5094f5d955876bbe1ecdb0a): free 12017983 bytes of WAL
I20260812 06:17:06.127861 27176 log_reader.cc:385] T 3798f150c5094f5d955876bbe1ecdb0a: removed 1 log segments from log reader
I20260812 06:17:06.127956 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000014 (ops 64-68)
I20260812 06:17:06.130324 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: LogGCOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:06.130613 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:06.140395 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3710,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:06.140762 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:06.357609 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.217s	user 0.129s	sys 0.080s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":453,"lbm_read_time_us":16160,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30453,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:17:06.358337 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=15.087375
I20260812 06:17:06.412106 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.054s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":18994,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:06.412721 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:06.424311 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4225736,"delete_count":0,"lbm_write_time_us":4362,"lbm_writes_lt_1ms":106,"mutex_wait_us":104,"reinsert_count":0,"update_count":515}
I20260812 06:17:06.424805 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:06.438047 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3569330,"delete_count":0,"lbm_write_time_us":5178,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:17:06.438517 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:06.654481 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.216s	user 0.144s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877208,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":663,"lbm_read_time_us":16394,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35668,"lbm_writes_lt_1ms":643,"mutex_wait_us":248,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":3000}
I20260812 06:17:06.655205 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=14.095187
I20260812 06:17:06.710623 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.055s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23554,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.711211 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:06.723743 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.724344 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:06.894186 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.170s	user 0.117s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":198,"lbm_read_time_us":12129,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27026,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:17:06.894940 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=14.095187
I20260812 06:17:06.955843 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.061s	user 0.042s	sys 0.015s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22646,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.956490 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:06.967270 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4342,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.967724 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:07.147970 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.180s	user 0.116s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":610,"lbm_read_time_us":13320,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28308,"lbm_writes_lt_1ms":543,"mutex_wait_us":332,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:17:07.148548 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=11.118625
I20260812 06:17:07.191946 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.043s	user 0.023s	sys 0.021s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19940,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:17:07.192608 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:07.221696 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.029s	user 0.013s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5970,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:07.222230 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:07.233868 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4656,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.234375 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:07.416029 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.181s	user 0.133s	sys 0.048s 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":944,"lbm_read_time_us":12130,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29236,"lbm_writes_lt_1ms":543,"mutex_wait_us":404,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:17:07.416745 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=14.095187
I20260812 06:17:07.481922 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.065s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":40553,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:07.482517 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:07.502818 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.020s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4039,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.503263 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushMRSOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:07.536628 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushMRSOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.033s	user 0.028s	sys 0.005s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1441,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1599,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:07.537283 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling LogGCOp(3798f150c5094f5d955876bbe1ecdb0a): free 108988515 bytes of WAL
I20260812 06:17:07.537505 27176 log_reader.cc:385] T 3798f150c5094f5d955876bbe1ecdb0a: removed 11 log segments from log reader
I20260812 06:17:07.537547 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000015 (ops 69-73)
I20260812 06:17:07.537577 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000016 (ops 74-78)
I20260812 06:17:07.537640 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000017 (ops 79-83)
I20260812 06:17:07.537674 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000018 (ops 84-88)
I20260812 06:17:07.537714 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000019 (ops 89-93)
I20260812 06:17:07.537750 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000020 (ops 94-98)
I20260812 06:17:07.537791 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000021 (ops 99-103)
I20260812 06:17:07.537822 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000022 (ops 104-108)
I20260812 06:17:07.537865 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000023 (ops 109-112)
I20260812 06:17:07.537906 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000024 (ops 113-117)
I20260812 06:17:07.537945 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000025 (ops 118-122)
I20260812 06:17:07.562022 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: LogGCOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.025s	user 0.002s	sys 0.021s Metrics: {}
I20260812 06:17:07.562409 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:07.579330 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.017s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5410,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.579782 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:07.590432 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.590883 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling LogGCOp(3798f150c5094f5d955876bbe1ecdb0a): free 11564873 bytes of WAL
I20260812 06:17:07.591097 27176 log_reader.cc:385] T 3798f150c5094f5d955876bbe1ecdb0a: removed 1 log segments from log reader
I20260812 06:17:07.591140 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000026 (ops 123-126)
I20260812 06:17:07.594936 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: LogGCOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:07.595655 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:07.837333 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.241s	user 0.130s	sys 0.111s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979748,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":989,"lbm_read_time_us":16948,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40322,"lbm_writes_lt_1ms":743,"mutex_wait_us":436,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4352,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:17:07.838127 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=18.063937
I20260812 06:17:07.902144 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.064s	user 0.029s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25475,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:07.902680 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:07.914880 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4154,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.915503 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling UndoDeltaBlockGCOp(3798f150c5094f5d955876bbe1ecdb0a): 463 bytes on disk
I20260812 06:17:07.916043 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: UndoDeltaBlockGCOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4}
I20260812 06:17:07.916549 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:08.127067 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.210s	user 0.135s	sys 0.075s 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":663,"lbm_read_time_us":13896,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34397,"lbm_writes_lt_1ms":643,"mutex_wait_us":305,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":3000}
I20260812 06:17:08.127725 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=14.095187
I20260812 06:17:08.184851 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.057s	user 0.016s	sys 0.038s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":27639,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.185686 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:08.201329 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4940,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.201777 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:08.374825 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.173s	user 0.129s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":336,"lbm_read_time_us":13208,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26467,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:17:08.375566 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=14.095187
I20260812 06:17:08.424165 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.048s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21514,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.424737 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:08.442619 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.018s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6842,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.443303 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:08.624454 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.181s	user 0.114s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":697,"lbm_read_time_us":12432,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29986,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2500}
I20260812 06:17:08.625172 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=14.095187
I20260812 06:17:08.684113 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.059s	user 0.035s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19756,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.684675 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:08.695645 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4166,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.696173 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:08.886368 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.190s	user 0.116s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":727,"lbm_read_time_us":13423,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28654,"lbm_writes_lt_1ms":543,"mutex_wait_us":335,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2500}
I20260812 06:17:08.887161 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=14.095187
I20260812 06:17:08.954560 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.067s	user 0.036s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22690,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.955103 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:08.965993 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4400,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.966424 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:09.156229 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.190s	user 0.126s	sys 0.057s 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":1167,"lbm_read_time_us":12696,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31185,"lbm_writes_lt_1ms":543,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2500}
I20260812 06:17:09.156916 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=14.095187
I20260812 06:17:09.208712 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.052s	user 0.037s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22246,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:09.209259 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:09.221663 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4373,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.222355 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushMRSOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:09.261293 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushMRSOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.038s	user 0.033s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":163,"dirs.run_wall_time_us":1173,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2459,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:09.262029 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling LogGCOp(3798f150c5094f5d955876bbe1ecdb0a): free 121006684 bytes of WAL
I20260812 06:17:09.262269 27176 log_reader.cc:385] T 3798f150c5094f5d955876bbe1ecdb0a: removed 12 log segments from log reader
I20260812 06:17:09.262317 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000027 (ops 127-131)
I20260812 06:17:09.262347 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000028 (ops 132-136)
I20260812 06:17:09.262414 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000029 (ops 137-141)
I20260812 06:17:09.262449 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000030 (ops 142-146)
I20260812 06:17:09.262483 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000031 (ops 147-150)
I20260812 06:17:09.262545 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000032 (ops 151-155)
I20260812 06:17:09.262580 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000033 (ops 156-160)
I20260812 06:17:09.262619 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000034 (ops 161-165)
I20260812 06:17:09.262657 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000035 (ops 166-170)
I20260812 06:17:09.262697 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000036 (ops 171-175)
I20260812 06:17:09.262740 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000037 (ops 176-180)
I20260812 06:17:09.262780 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000038 (ops 181-185)
I20260812 06:17:09.288735 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: LogGCOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:09.289183 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling UndoDeltaBlockGCOp(3798f150c5094f5d955876bbe1ecdb0a): 492 bytes on disk
I20260812 06:17:09.289659 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: UndoDeltaBlockGCOp(3798f150c5094f5d955876bbe1ecdb0a) 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:17:09.290231 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:09.313436 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.023s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5592,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.313930 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling LogGCOp(3798f150c5094f5d955876bbe1ecdb0a): free 12017952 bytes of WAL
I20260812 06:17:09.314136 27176 log_reader.cc:385] T 3798f150c5094f5d955876bbe1ecdb0a: removed 1 log segments from log reader
I20260812 06:17:09.314199 27176 log.cc:1079] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: Deleting log segment in path: /tmp/dist-test-taskOIyQ4K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418967576-26867-0/minicluster-data/ts-0-root/wals/3798f150c5094f5d955876bbe1ecdb0a/wal-000000039 (ops 186-190)
I20260812 06:17:09.316426 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: LogGCOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:09.316690 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=2.188937
I20260812 06:17:09.329139 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.329813 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=1.000000
I20260812 06:17:09.566947 26867 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.057s	user 1.816s	sys 0.195s
I20260812 06:17:09.582372 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: MajorDeltaCompactionOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.252s	user 0.168s	sys 0.080s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":543,"lbm_read_time_us":17284,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40437,"lbm_writes_lt_1ms":743,"mutex_wait_us":328,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17280,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:17:09.583142 27242 maintenance_manager.cc:419] P abd32a1cf81b4ab5915be2a69e839bf1: Scheduling FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a): perf score=18.063937
I20260812 06:17:09.631821 26867 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.064s	user 0.001s	sys 0.000s
I20260812 06:17:09.632427 26867 tablet_server.cc:179] TabletServer@127.26.60.193:0 shutting down...
I20260812 06:17:09.653923 27176 maintenance_manager.cc:643] P abd32a1cf81b4ab5915be2a69e839bf1: FlushDeltaMemStoresOp(3798f150c5094f5d955876bbe1ecdb0a) complete. Timing: real 0.071s	user 0.041s	sys 0.027s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":32272,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:09.654430 26867 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:09.654660 26867 tablet_replica.cc:333] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1: stopping tablet replica
I20260812 06:17:09.654803 26867 raft_consensus.cc:2243] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:09.654989 26867 raft_consensus.cc:2272] T 3798f150c5094f5d955876bbe1ecdb0a P abd32a1cf81b4ab5915be2a69e839bf1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:09.658227 26867 tablet_server.cc:196] TabletServer@127.26.60.193:0 shutdown complete.
I20260812 06:17:09.661147 26867 master.cc:562] Master@127.26.60.254:44207 shutting down...
I20260812 06:17:09.664705 26867 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:09.664876 26867 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:09.664947 26867 tablet_replica.cc:333] T 00000000000000000000000000000000 P a43be4dd970e4017b61f87ab49c50b22: stopping tablet replica
I20260812 06:17:09.677034 26867 master.cc:584] Master@127.26.60.254:44207 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5455 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10795 ms total)

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