[==========] 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:18:54.918044 15610 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.62.190:43337
I20260812 06:18:54.918990 15610 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:18:54.919549 15610 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:54.925520 15619 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:18:54.925532 15622 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:18:54.925761 15618 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:18:54.925693 15610 server_base.cc:1061] running on GCE node
I20260812 06:18:54.926215 15610 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:54.926339 15610 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:18:54.926388 15610 hybrid_clock.cc:648] HybridClock initialized: now 1786515534926384 us; error 0 us; skew 500 ppm
I20260812 06:18:54.928056 15610 webserver.cc:533] Webserver started at http://127.15.62.190:37427/ using document root <none> and password file <none>
I20260812 06:18:54.928558 15610 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:54.928617 15610 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:54.928830 15610 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:54.930382 15610 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/master-0-root/instance:
uuid: "d6c722af3c3a40ff88ef3e288567fce8"
format_stamp: "Formatted at 2026-08-12 06:18:54 on dist-test-slave-k5rr"
I20260812 06:18:54.933563 15610 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:18:54.935477 15631 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:18:54.936405 15610 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:54.936507 15610 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/master-0-root
uuid: "d6c722af3c3a40ff88ef3e288567fce8"
format_stamp: "Formatted at 2026-08-12 06:18:54 on dist-test-slave-k5rr"
I20260812 06:18:54.936589 15610 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-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:18:54.958360 15610 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:54.958956 15610 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:18:54.959108 15610 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:54.966297 15610 rpc_server.cc:307] RPC server started. Bound to: 127.15.62.190:43337
I20260812 06:18:54.966301 15716 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.62.190:43337 every 8 connection(s)
I20260812 06:18:54.968415 15717 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:18:54.974041 15717 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8: Bootstrap starting.
I20260812 06:18:54.976296 15717 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:54.977202 15717 log.cc:826] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:54.978807 15717 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8: No bootstrap required, opened a new log
I20260812 06:18:54.981544 15717 raft_consensus.cc:359] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d6c722af3c3a40ff88ef3e288567fce8" member_type: VOTER }
I20260812 06:18:54.981703 15717 raft_consensus.cc:385] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:54.981750 15717 raft_consensus.cc:740] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d6c722af3c3a40ff88ef3e288567fce8, State: Initialized, Role: FOLLOWER
I20260812 06:18:54.982317 15717 consensus_queue.cc:260] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [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: "d6c722af3c3a40ff88ef3e288567fce8" member_type: VOTER }
I20260812 06:18:54.982452 15717 raft_consensus.cc:399] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:54.982515 15717 raft_consensus.cc:493] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:54.982628 15717 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:54.983348 15717 raft_consensus.cc:515] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d6c722af3c3a40ff88ef3e288567fce8" member_type: VOTER }
I20260812 06:18:54.983754 15717 leader_election.cc:304] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [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: d6c722af3c3a40ff88ef3e288567fce8; no voters: 
I20260812 06:18:54.984041 15717 leader_election.cc:290] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:54.984167 15723 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:54.984390 15723 raft_consensus.cc:697] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [term 1 LEADER]: Becoming Leader. State: Replica: d6c722af3c3a40ff88ef3e288567fce8, State: Running, Role: LEADER
I20260812 06:18:54.984776 15723 consensus_queue.cc:237] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [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: "d6c722af3c3a40ff88ef3e288567fce8" member_type: VOTER }
I20260812 06:18:54.984972 15717 sys_catalog.cc:565] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:54.986675 15727 sys_catalog.cc:455] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d6c722af3c3a40ff88ef3e288567fce8. Latest consensus state: current_term: 1 leader_uuid: "d6c722af3c3a40ff88ef3e288567fce8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d6c722af3c3a40ff88ef3e288567fce8" member_type: VOTER } }
I20260812 06:18:54.986708 15725 sys_catalog.cc:455] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d6c722af3c3a40ff88ef3e288567fce8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d6c722af3c3a40ff88ef3e288567fce8" member_type: VOTER } }
I20260812 06:18:54.986811 15727 sys_catalog.cc:458] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:54.986814 15725 sys_catalog.cc:458] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:54.987185 15740 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:54.987354 15610 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:54.989435 15740 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:54.994050 15740 catalog_manager.cc:1383] Generated new cluster ID: 8359225686c64245876c8cc80ba1feeb
I20260812 06:18:54.994107 15740 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:55.006796 15740 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:55.007911 15740 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:55.015355 15740 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8: Generated new TSK 0
I20260812 06:18:55.016055 15740 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:55.019783 15610 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:55.022202 15754 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:18:55.022411 15755 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:18:55.022436 15757 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:18:55.022578 15610 server_base.cc:1061] running on GCE node
I20260812 06:18:55.022830 15610 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:55.022886 15610 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:18:55.022907 15610 hybrid_clock.cc:648] HybridClock initialized: now 1786515535022907 us; error 0 us; skew 500 ppm
I20260812 06:18:55.023782 15610 webserver.cc:533] Webserver started at http://127.15.62.129:32925/ using document root <none> and password file <none>
I20260812 06:18:55.023943 15610 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:55.024001 15610 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:55.024075 15610 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:55.024498 15610 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/instance:
uuid: "5b0da5fb2ae944e8aa792aa477f16169"
format_stamp: "Formatted at 2026-08-12 06:18:55 on dist-test-slave-k5rr"
I20260812 06:18:55.026283 15610 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:55.027364 15764 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:18:55.027634 15610 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:55.027701 15610 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root
uuid: "5b0da5fb2ae944e8aa792aa477f16169"
format_stamp: "Formatted at 2026-08-12 06:18:55 on dist-test-slave-k5rr"
I20260812 06:18:55.027768 15610 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-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:18:55.044711 15610 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:55.045158 15610 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:55.045598 15610 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:55.046505 15610 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:55.046561 15610 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:55.046605 15610 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:55.046633 15610 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:55.052826 15610 rpc_server.cc:307] RPC server started. Bound to: 127.15.62.129:39211
I20260812 06:18:55.052861 15879 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.62.129:39211 every 8 connection(s)
I20260812 06:18:55.065044 15885 heartbeater.cc:344] Connected to a master server at 127.15.62.190:43337
I20260812 06:18:55.065269 15885 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:55.065722 15885 heartbeater.cc:507] Master 127.15.62.190:43337 requested a full tablet report, sending...
I20260812 06:18:55.067191 15659 ts_manager.cc:194] Registered new tserver with Master: 5b0da5fb2ae944e8aa792aa477f16169 (127.15.62.129:39211)
I20260812 06:18:55.067852 15610 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014415134s
I20260812 06:18:55.068768 15659 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58536
I20260812 06:18:55.077024 15659 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58548:
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:18:55.091675 15811 tablet_service.cc:1511] Processing CreateTablet for tablet e576c0b180d046ddb566af8db7dc2946 (DEFAULT_TABLE table=heavy-update-compaction-test [id=129edca603e443fc9e96be61c4cd8720]), partition=
I20260812 06:18:55.092132 15811 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e576c0b180d046ddb566af8db7dc2946. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:55.094537 15918 tablet_bootstrap.cc:492] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Bootstrap starting.
I20260812 06:18:55.095633 15918 tablet_bootstrap.cc:654] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:55.096771 15918 tablet_bootstrap.cc:492] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: No bootstrap required, opened a new log
I20260812 06:18:55.096866 15918 ts_tablet_manager.cc:1403] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:55.097366 15918 raft_consensus.cc:359] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b0da5fb2ae944e8aa792aa477f16169" member_type: VOTER last_known_addr { host: "127.15.62.129" port: 39211 } }
I20260812 06:18:55.097472 15918 raft_consensus.cc:385] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:55.097498 15918 raft_consensus.cc:740] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5b0da5fb2ae944e8aa792aa477f16169, State: Initialized, Role: FOLLOWER
I20260812 06:18:55.097635 15918 consensus_queue.cc:260] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [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: "5b0da5fb2ae944e8aa792aa477f16169" member_type: VOTER last_known_addr { host: "127.15.62.129" port: 39211 } }
I20260812 06:18:55.097720 15918 raft_consensus.cc:399] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:55.097769 15918 raft_consensus.cc:493] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:55.097824 15918 raft_consensus.cc:3060] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:55.098676 15918 raft_consensus.cc:515] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b0da5fb2ae944e8aa792aa477f16169" member_type: VOTER last_known_addr { host: "127.15.62.129" port: 39211 } }
I20260812 06:18:55.098869 15918 leader_election.cc:304] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [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: 5b0da5fb2ae944e8aa792aa477f16169; no voters: 
I20260812 06:18:55.099116 15918 leader_election.cc:290] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:55.099236 15920 raft_consensus.cc:2804] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:55.099424 15920 raft_consensus.cc:697] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [term 1 LEADER]: Becoming Leader. State: Replica: 5b0da5fb2ae944e8aa792aa477f16169, State: Running, Role: LEADER
I20260812 06:18:55.099505 15918 ts_tablet_manager.cc:1434] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:55.099848 15885 heartbeater.cc:499] Master 127.15.62.190:43337 was elected leader, sending a full tablet report...
I20260812 06:18:55.099800 15920 consensus_queue.cc:237] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [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: "5b0da5fb2ae944e8aa792aa477f16169" member_type: VOTER last_known_addr { host: "127.15.62.129" port: 39211 } }
I20260812 06:18:55.102445 15659 catalog_manager.cc:5719] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5b0da5fb2ae944e8aa792aa477f16169 (127.15.62.129). New cstate: current_term: 1 leader_uuid: "5b0da5fb2ae944e8aa792aa477f16169" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b0da5fb2ae944e8aa792aa477f16169" member_type: VOTER last_known_addr { host: "127.15.62.129" port: 39211 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:55.172251 15610 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.029s	sys 0.004s
I20260812 06:18:55.303846 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushMRSOp(e576c0b180d046ddb566af8db7dc2946): perf score=19.054940
I20260812 06:18:55.449862 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushMRSOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.146s	user 0.113s	sys 0.029s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":201,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":169,"dirs.run_wall_time_us":863,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36354,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":110,"threads_started":1,"update_count":1500}
I20260812 06:18:55.451097 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling UndoDeltaBlockGCOp(e576c0b180d046ddb566af8db7dc2946): 16411392 bytes on disk
I20260812 06:18:55.451689 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: UndoDeltaBlockGCOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:18:55.452136 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:55.462634 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.010s	user 0.002s	sys 0.004s Metrics: {"bytes_written":1682181,"delete_count":0,"lbm_write_time_us":2589,"lbm_writes_lt_1ms":44,"mutex_wait_us":2,"reinsert_count":0,"update_count":205}
I20260812 06:18:55.463148 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling LogGCOp(e576c0b180d046ddb566af8db7dc2946): free 20743880 bytes of WAL
I20260812 06:18:55.463483 15770 log_reader.cc:385] T e576c0b180d046ddb566af8db7dc2946: removed 2 log segments from log reader
I20260812 06:18:55.463609 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000001 (ops 1-6)
I20260812 06:18:55.463743 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000002 (ops 7-11)
I20260812 06:18:55.468690 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: LogGCOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:55.468993 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.196750
I20260812 06:18:55.478942 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2420629,"delete_count":0,"lbm_write_time_us":3388,"lbm_writes_lt_1ms":62,"reinsert_count":0,"update_count":295}
I20260812 06:18:55.479406 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:55.612488 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.133s	user 0.092s	sys 0.032s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672301,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":772,"lbm_read_time_us":8859,"lbm_reads_lt_1ms":469,"lbm_write_time_us":22186,"lbm_writes_lt_1ms":443,"mutex_wait_us":175,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":296,"threads_started":5,"update_count":2000}
I20260812 06:18:55.612949 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=10.126437
I20260812 06:18:55.656610 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.044s	user 0.027s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14968,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.657121 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:55.668242 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.668835 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:55.781054 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.112s	user 0.096s	sys 0.016s 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":288,"lbm_read_time_us":8694,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20520,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:55.781546 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=10.126437
I20260812 06:18:55.827060 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.045s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13812,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.827579 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:55.842558 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.843115 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:55.962072 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.119s	user 0.107s	sys 0.012s 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":554,"lbm_read_time_us":7826,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23015,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:18:55.962581 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=10.126437
I20260812 06:18:56.010056 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.047s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14879,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.010603 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:56.020864 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3752,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.021296 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:56.158890 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.137s	user 0.093s	sys 0.044s 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":212,"lbm_read_time_us":10066,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21765,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":44160,"update_count":2000}
I20260812 06:18:56.159350 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=10.126437
I20260812 06:18:56.203055 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.044s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14374,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.203503 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:56.213359 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3669,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.213830 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:56.334554 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.121s	user 0.078s	sys 0.042s 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":288,"lbm_read_time_us":8211,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23754,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:56.335065 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=10.126437
I20260812 06:18:56.381342 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.046s	user 0.031s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22032,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.381855 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:56.394145 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4079,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.394835 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:56.527350 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.132s	user 0.099s	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":1186,"lbm_read_time_us":11022,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25603,"lbm_writes_lt_1ms":443,"mutex_wait_us":390,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:18:56.528009 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=10.126437
I20260812 06:18:56.561977 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.034s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14454,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.562417 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:56.572781 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3751,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.573513 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushMRSOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:56.602829 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushMRSOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.029s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1746,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1900,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:56.603587 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling LogGCOp(e576c0b180d046ddb566af8db7dc2946): free 108535454 bytes of WAL
I20260812 06:18:56.603807 15770 log_reader.cc:385] T e576c0b180d046ddb566af8db7dc2946: removed 11 log segments from log reader
I20260812 06:18:56.603853 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000003 (ops 12-16)
I20260812 06:18:56.603883 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000004 (ops 17-20)
I20260812 06:18:56.603919 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000005 (ops 21-25)
I20260812 06:18:56.603945 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000006 (ops 26-30)
I20260812 06:18:56.603977 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000007 (ops 31-34)
I20260812 06:18:56.604010 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000008 (ops 35-39)
I20260812 06:18:56.604043 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000009 (ops 40-44)
I20260812 06:18:56.604074 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000010 (ops 45-49)
I20260812 06:18:56.604107 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000011 (ops 50-54)
I20260812 06:18:56.604139 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000012 (ops 55-59)
I20260812 06:18:56.604171 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000013 (ops 60-64)
I20260812 06:18:56.623602 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: LogGCOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.020s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:18:56.624135 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling UndoDeltaBlockGCOp(e576c0b180d046ddb566af8db7dc2946): 448 bytes on disk
I20260812 06:18:56.624699 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: UndoDeltaBlockGCOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:18:56.625258 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:56.641072 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.015s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3726,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.641531 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling LogGCOp(e576c0b180d046ddb566af8db7dc2946): free 11564875 bytes of WAL
I20260812 06:18:56.641795 15770 log_reader.cc:385] T e576c0b180d046ddb566af8db7dc2946: removed 1 log segments from log reader
I20260812 06:18:56.641851 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000014 (ops 65-68)
I20260812 06:18:56.643788 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: LogGCOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:56.644079 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:56.660352 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5852,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.660938 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:56.827641 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.167s	user 0.119s	sys 0.037s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1282,"lbm_read_time_us":10927,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30129,"lbm_writes_lt_1ms":643,"mutex_wait_us":540,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":1487,"threads_started":1,"update_count":3000}
I20260812 06:18:56.828132 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=14.095187
I20260812 06:18:56.873090 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.045s	user 0.016s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19474,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.873608 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:56.888819 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5839,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.889317 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:57.033325 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.144s	user 0.121s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":948,"lbm_read_time_us":9070,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28321,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:18:57.033941 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=14.095187
I20260812 06:18:57.089784 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.056s	user 0.021s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20633,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:57.090361 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:57.103727 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.104220 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:57.271536 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.167s	user 0.105s	sys 0.053s 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":283,"lbm_read_time_us":10336,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29708,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:57.272096 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=14.095187
I20260812 06:18:57.327903 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.056s	user 0.029s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23521,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:57.328464 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:57.468288 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.140s	user 0.078s	sys 0.061s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":129,"lbm_read_time_us":10031,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22833,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:57.469089 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=11.118625
I20260812 06:18:57.504916 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.036s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15605,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:57.505573 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:57.519028 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4947,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:57.519588 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:57.645151 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.125s	user 0.101s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":212,"lbm_read_time_us":8333,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24898,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2000}
I20260812 06:18:57.645696 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=10.126437
I20260812 06:18:57.681900 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.036s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":13855,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.682431 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:57.693549 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.694172 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:57.820976 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.127s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672282,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":931,"lbm_read_time_us":10028,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23208,"lbm_writes_lt_1ms":443,"mutex_wait_us":316,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:18:57.821504 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=10.126437
I20260812 06:18:57.860700 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.039s	user 0.014s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13659,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.861307 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:57.876312 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5455,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.876852 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushMRSOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:57.904085 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushMRSOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.027s	user 0.019s	sys 0.005s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1263,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1337,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:57.904762 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling LogGCOp(e576c0b180d046ddb566af8db7dc2946): free 108988507 bytes of WAL
I20260812 06:18:57.904963 15770 log_reader.cc:385] T e576c0b180d046ddb566af8db7dc2946: removed 11 log segments from log reader
I20260812 06:18:57.905038 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000015 (ops 69-73)
I20260812 06:18:57.905079 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000016 (ops 74-78)
I20260812 06:18:57.905112 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000017 (ops 79-83)
I20260812 06:18:57.905146 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000018 (ops 84-88)
I20260812 06:18:57.905170 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000019 (ops 89-92)
I20260812 06:18:57.905203 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000020 (ops 93-97)
I20260812 06:18:57.905243 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000021 (ops 98-102)
I20260812 06:18:57.905277 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000022 (ops 103-107)
I20260812 06:18:57.905308 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000023 (ops 108-112)
I20260812 06:18:57.905339 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000024 (ops 113-117)
I20260812 06:18:57.905370 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000025 (ops 118-122)
I20260812 06:18:57.924144 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: LogGCOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.019s	user 0.000s	sys 0.016s Metrics: {}
I20260812 06:18:57.924530 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling UndoDeltaBlockGCOp(e576c0b180d046ddb566af8db7dc2946): 449 bytes on disk
I20260812 06:18:57.924963 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: UndoDeltaBlockGCOp(e576c0b180d046ddb566af8db7dc2946) 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:18:57.925493 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:57.944337 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.019s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.944796 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:57.954493 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3489,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.954905 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:58.109767 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.155s	user 0.114s	sys 0.038s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":343,"lbm_read_time_us":13019,"lbm_reads_lt_1ms":674,"lbm_write_time_us":28229,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:18:58.110342 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=14.095187
I20260812 06:18:58.161340 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.050s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":19634,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.161906 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:58.173862 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4301,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.174386 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:58.323609 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.149s	user 0.105s	sys 0.038s 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":691,"lbm_read_time_us":9611,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30321,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":290,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:18:58.324270 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=14.095187
I20260812 06:18:58.365096 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.041s	user 0.032s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18567,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.365698 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:58.519429 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.153s	user 0.106s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":237,"lbm_read_time_us":10717,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26410,"lbm_writes_lt_1ms":443,"mutex_wait_us":176,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:18:58.520411 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=11.118625
I20260812 06:18:58.562722 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.042s	user 0.037s	sys 0.003s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18132,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:58.563194 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:58.583046 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.020s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5147,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:58.583494 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:58.593595 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3654,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.594018 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:58.760157 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.166s	user 0.091s	sys 0.067s 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":138,"lbm_read_time_us":9215,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28199,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:18:58.760895 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=14.095187
I20260812 06:18:58.808892 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.048s	user 0.037s	sys 0.000s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18241,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.809494 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:58.825186 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.016s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.825615 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:58.983047 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.157s	user 0.114s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":271,"lbm_read_time_us":9158,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26352,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:58.983608 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=14.095187
I20260812 06:18:59.027348 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.044s	user 0.032s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18075,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.027925 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:59.038260 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3625,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.038885 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:59.192025 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.153s	user 0.122s	sys 0.026s 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":116,"lbm_read_time_us":10975,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28977,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:18:59.192572 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=14.095187
I20260812 06:18:59.240057 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.047s	user 0.031s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17943,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.240585 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=2.188937
I20260812 06:18:59.250586 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3662,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.251111 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushMRSOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:59.286571 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushMRSOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.035s	user 0.033s	sys 0.001s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1327,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1905,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:59.287388 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling LogGCOp(e576c0b180d046ddb566af8db7dc2946): free 132118501 bytes of WAL
I20260812 06:18:59.287626 15770 log_reader.cc:385] T e576c0b180d046ddb566af8db7dc2946: removed 13 log segments from log reader
I20260812 06:18:59.287676 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000026 (ops 123-126)
I20260812 06:18:59.287724 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000027 (ops 127-131)
I20260812 06:18:59.287766 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000028 (ops 132-136)
I20260812 06:18:59.287806 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000029 (ops 137-140)
I20260812 06:18:59.287845 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000030 (ops 141-145)
I20260812 06:18:59.287884 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000031 (ops 146-150)
I20260812 06:18:59.287923 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000032 (ops 151-155)
I20260812 06:18:59.287961 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000033 (ops 156-160)
I20260812 06:18:59.288000 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000034 (ops 161-165)
I20260812 06:18:59.288039 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000035 (ops 166-170)
I20260812 06:18:59.288077 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000036 (ops 171-175)
I20260812 06:18:59.288123 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000037 (ops 176-180)
I20260812 06:18:59.288161 15770 log.cc:1079] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/e576c0b180d046ddb566af8db7dc2946/wal-000000038 (ops 181-184)
I20260812 06:18:59.311929 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: LogGCOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:59.312387 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling UndoDeltaBlockGCOp(e576c0b180d046ddb566af8db7dc2946): 482 bytes on disk
I20260812 06:18:59.312930 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: UndoDeltaBlockGCOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:59.313675 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=5.165500
I20260812 06:18:59.330300 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":7097423,"delete_count":0,"lbm_write_time_us":6603,"lbm_writes_lt_1ms":176,"reinsert_count":0,"update_count":865}
I20260812 06:18:59.331003 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:59.560842 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.230s	user 0.136s	sys 0.080s Metrics: {"cfile_cache_miss":706,"cfile_cache_miss_bytes":31871977,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":3409,"lbm_read_time_us":15156,"lbm_reads_lt_1ms":742,"lbm_write_time_us":36997,"lbm_writes_lt_1ms":716,"mutex_wait_us":3068,"peak_mem_usage":83739947,"reinsert_count":0,"spinlock_wait_cycles":5504,"thread_start_us":78,"threads_started":1,"update_count":3365}
I20260812 06:18:59.561743 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=16.079562
I20260812 06:18:59.623701 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.062s	user 0.043s	sys 0.014s Metrics: {"bytes_written":18543163,"delete_count":0,"lbm_write_time_us":22610,"lbm_writes_lt_1ms":455,"reinsert_count":0,"update_count":2260}
I20260812 06:18:59.624209 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=4.173312
I20260812 06:18:59.642272 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.018s	user 0.009s	sys 0.008s Metrics: {"bytes_written":5907726,"delete_count":0,"lbm_write_time_us":7116,"lbm_writes_lt_1ms":147,"reinsert_count":0,"update_count":720}
I20260812 06:18:59.642848 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:59.649526 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: FlushDeltaMemStoresOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.006s	user 0.002s	sys 0.004s Metrics: {"bytes_written":1271927,"delete_count":0,"lbm_write_time_us":1804,"lbm_writes_lt_1ms":34,"reinsert_count":0,"update_count":155}
I20260812 06:18:59.650028 15886 maintenance_manager.cc:419] P 5b0da5fb2ae944e8aa792aa477f16169: Scheduling MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946): perf score=1.000000
I20260812 06:18:59.688130 15610 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.516s	user 1.658s	sys 0.152s
I20260812 06:18:59.763535 15610 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.075s	user 0.001s	sys 0.000s
I20260812 06:18:59.764158 15610 tablet_server.cc:179] TabletServer@127.15.62.129:0 shutting down...
I20260812 06:18:59.820655 15770 maintenance_manager.cc:643] P 5b0da5fb2ae944e8aa792aa477f16169: MajorDeltaCompactionOp(e576c0b180d046ddb566af8db7dc2946) complete. Timing: real 0.170s	user 0.109s	sys 0.060s Metrics: {"cfile_cache_miss":660,"cfile_cache_miss_bytes":29984811,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":799,"lbm_read_time_us":14444,"lbm_reads_lt_1ms":696,"lbm_write_time_us":28506,"lbm_writes_lt_1ms":670,"mutex_wait_us":83,"peak_mem_usage":78731185,"reinsert_count":0,"update_count":3135}
I20260812 06:18:59.821269 15610 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:59.821712 15610 tablet_replica.cc:333] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169: stopping tablet replica
I20260812 06:18:59.821954 15610 raft_consensus.cc:2243] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:59.822190 15610 raft_consensus.cc:2272] T e576c0b180d046ddb566af8db7dc2946 P 5b0da5fb2ae944e8aa792aa477f16169 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:59.838195 15610 tablet_server.cc:196] TabletServer@127.15.62.129:0 shutdown complete.
I20260812 06:18:59.874682 15610 master.cc:562] Master@127.15.62.190:43337 shutting down...
I20260812 06:18:59.877851 15610 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:59.878032 15610 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:59.878104 15610 tablet_replica.cc:333] T 00000000000000000000000000000000 P d6c722af3c3a40ff88ef3e288567fce8: stopping tablet replica
I20260812 06:18:59.890244 15610 master.cc:584] Master@127.15.62.190:43337 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5049 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:59.977716 15610 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.62.190:34259
I20260812 06:18:59.978132 15610 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:59.980020 15952 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:18:59.980141 15953 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:18:59.980208 15956 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:18:59.980274 15610 server_base.cc:1061] running on GCE node
I20260812 06:18:59.980429 15610 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:59.980465 15610 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:18:59.980479 15610 hybrid_clock.cc:648] HybridClock initialized: now 1786515539980479 us; error 0 us; skew 500 ppm
I20260812 06:18:59.981289 15610 webserver.cc:533] Webserver started at http://127.15.62.190:43153/ using document root <none> and password file <none>
I20260812 06:18:59.981441 15610 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:59.981480 15610 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:59.981536 15610 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:59.981875 15610 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/master-0-root/instance:
uuid: "e81a8d7968874458a519789d42d9fbc8"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-k5rr"
I20260812 06:18:59.983251 15610 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:59.984201 15966 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:18:59.984532 15610 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:59.984607 15610 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/master-0-root
uuid: "e81a8d7968874458a519789d42d9fbc8"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-k5rr"
I20260812 06:18:59.984676 15610 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:00.000093 15610 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:00.000486 15610 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:00.004652 15610 rpc_server.cc:307] RPC server started. Bound to: 127.15.62.190:34259
I20260812 06:19:00.010061 16059 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:00.010079 16056 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.62.190:34259 every 8 connection(s)
I20260812 06:19:00.011914 16059 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8: Bootstrap starting.
I20260812 06:19:00.012696 16059 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:00.013726 16059 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8: No bootstrap required, opened a new log
I20260812 06:19:00.014117 16059 raft_consensus.cc:359] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e81a8d7968874458a519789d42d9fbc8" member_type: VOTER }
I20260812 06:19:00.014207 16059 raft_consensus.cc:385] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:00.014238 16059 raft_consensus.cc:740] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e81a8d7968874458a519789d42d9fbc8, State: Initialized, Role: FOLLOWER
I20260812 06:19:00.014376 16059 consensus_queue.cc:260] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [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: "e81a8d7968874458a519789d42d9fbc8" member_type: VOTER }
I20260812 06:19:00.014459 16059 raft_consensus.cc:399] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:00.014496 16059 raft_consensus.cc:493] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:00.014544 16059 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:00.015197 16059 raft_consensus.cc:515] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e81a8d7968874458a519789d42d9fbc8" member_type: VOTER }
I20260812 06:19:00.015328 16059 leader_election.cc:304] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [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: e81a8d7968874458a519789d42d9fbc8; no voters: 
I20260812 06:19:00.015539 16059 leader_election.cc:290] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:00.015646 16066 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:00.015888 16066 raft_consensus.cc:697] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [term 1 LEADER]: Becoming Leader. State: Replica: e81a8d7968874458a519789d42d9fbc8, State: Running, Role: LEADER
I20260812 06:19:00.015937 16059 sys_catalog.cc:565] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:00.016031 16066 consensus_queue.cc:237] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [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: "e81a8d7968874458a519789d42d9fbc8" member_type: VOTER }
I20260812 06:19:00.016472 16067 sys_catalog.cc:455] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e81a8d7968874458a519789d42d9fbc8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e81a8d7968874458a519789d42d9fbc8" member_type: VOTER } }
I20260812 06:19:00.016500 16069 sys_catalog.cc:455] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e81a8d7968874458a519789d42d9fbc8. Latest consensus state: current_term: 1 leader_uuid: "e81a8d7968874458a519789d42d9fbc8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e81a8d7968874458a519789d42d9fbc8" member_type: VOTER } }
I20260812 06:19:00.016644 16069 sys_catalog.cc:458] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:00.016877 16067 sys_catalog.cc:458] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:00.017175 16079 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:00.017839 16079 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:00.018008 15610 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:00.019572 16079 catalog_manager.cc:1383] Generated new cluster ID: a471783cf84a40ac94e86ce16d11e8f1
I20260812 06:19:00.019627 16079 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:00.023779 16079 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:00.024268 16079 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:00.032544 16079 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8: Generated new TSK 0
I20260812 06:19:00.032687 16079 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:00.034030 15610 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:00.036037 16097 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:00.036113 16101 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:00.036160 16099 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:00.036300 15610 server_base.cc:1061] running on GCE node
I20260812 06:19:00.036549 15610 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:00.036597 15610 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:00.036612 15610 hybrid_clock.cc:648] HybridClock initialized: now 1786515540036611 us; error 0 us; skew 500 ppm
I20260812 06:19:00.037457 15610 webserver.cc:533] Webserver started at http://127.15.62.129:35481/ using document root <none> and password file <none>
I20260812 06:19:00.037609 15610 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:00.037658 15610 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:00.037734 15610 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:00.038085 15610 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/instance:
uuid: "5f1112ba9bba4dc2ab8b0a0d9eb4a1aa"
format_stamp: "Formatted at 2026-08-12 06:19:00 on dist-test-slave-k5rr"
I20260812 06:19:00.039498 15610 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:00.040338 16107 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:00.040552 15610 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:00.040618 15610 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root
uuid: "5f1112ba9bba4dc2ab8b0a0d9eb4a1aa"
format_stamp: "Formatted at 2026-08-12 06:19:00 on dist-test-slave-k5rr"
I20260812 06:19:00.040681 15610 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:00.056025 15610 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:00.056392 15610 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:00.056681 15610 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:00.057164 15610 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:00.057204 15610 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:00.057247 15610 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:00.057276 15610 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:00.061282 15610 rpc_server.cc:307] RPC server started. Bound to: 127.15.62.129:40231
I20260812 06:19:00.061599 16215 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.62.129:40231 every 8 connection(s)
I20260812 06:19:00.068248 16216 heartbeater.cc:344] Connected to a master server at 127.15.62.190:34259
I20260812 06:19:00.068352 16216 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:00.068539 16216 heartbeater.cc:507] Master 127.15.62.190:34259 requested a full tablet report, sending...
I20260812 06:19:00.069132 15994 ts_manager.cc:194] Registered new tserver with Master: 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa (127.15.62.129:40231)
I20260812 06:19:00.069386 15610 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007597407s
I20260812 06:19:00.069864 15994 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59454
I20260812 06:19:00.075585 15994 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59460:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:00.083678 16150 tablet_service.cc:1511] Processing CreateTablet for tablet 5c0e52efd8d44bb8a1669bb8592cb332 (DEFAULT_TABLE table=heavy-update-compaction-test [id=df2a8a3dde224330990cb9b583b83ad7]), partition=
I20260812 06:19:00.083926 16150 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5c0e52efd8d44bb8a1669bb8592cb332. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:00.085968 16239 tablet_bootstrap.cc:492] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Bootstrap starting.
I20260812 06:19:00.086843 16239 tablet_bootstrap.cc:654] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:00.087826 16239 tablet_bootstrap.cc:492] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: No bootstrap required, opened a new log
I20260812 06:19:00.087925 16239 ts_tablet_manager.cc:1403] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:00.088316 16239 raft_consensus.cc:359] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5f1112ba9bba4dc2ab8b0a0d9eb4a1aa" member_type: VOTER last_known_addr { host: "127.15.62.129" port: 40231 } }
I20260812 06:19:00.088405 16239 raft_consensus.cc:385] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:00.088436 16239 raft_consensus.cc:740] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa, State: Initialized, Role: FOLLOWER
I20260812 06:19:00.088562 16239 consensus_queue.cc:260] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [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: "5f1112ba9bba4dc2ab8b0a0d9eb4a1aa" member_type: VOTER last_known_addr { host: "127.15.62.129" port: 40231 } }
I20260812 06:19:00.088634 16239 raft_consensus.cc:399] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:00.088673 16239 raft_consensus.cc:493] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:00.088721 16239 raft_consensus.cc:3060] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:00.089596 16239 raft_consensus.cc:515] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5f1112ba9bba4dc2ab8b0a0d9eb4a1aa" member_type: VOTER last_known_addr { host: "127.15.62.129" port: 40231 } }
I20260812 06:19:00.089730 16239 leader_election.cc:304] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [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: 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa; no voters: 
I20260812 06:19:00.089910 16239 leader_election.cc:290] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:00.089993 16242 raft_consensus.cc:2804] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:00.090193 16239 ts_tablet_manager.cc:1434] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:00.090241 16242 raft_consensus.cc:697] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [term 1 LEADER]: Becoming Leader. State: Replica: 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa, State: Running, Role: LEADER
I20260812 06:19:00.090258 16216 heartbeater.cc:499] Master 127.15.62.190:34259 was elected leader, sending a full tablet report...
I20260812 06:19:00.090397 16242 consensus_queue.cc:237] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [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: "5f1112ba9bba4dc2ab8b0a0d9eb4a1aa" member_type: VOTER last_known_addr { host: "127.15.62.129" port: 40231 } }
I20260812 06:19:00.091679 15994 catalog_manager.cc:5719] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa reported cstate change: term changed from 0 to 1, leader changed from <none> to 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa (127.15.62.129). New cstate: current_term: 1 leader_uuid: "5f1112ba9bba4dc2ab8b0a0d9eb4a1aa" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5f1112ba9bba4dc2ab8b0a0d9eb4a1aa" member_type: VOTER last_known_addr { host: "127.15.62.129" port: 40231 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:00.149063 15610 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.010s	sys 0.012s
I20260812 06:19:00.312300 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushMRSOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=23.023690
I20260812 06:19:00.476823 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushMRSOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.164s	user 0.121s	sys 0.039s Metrics: {"bytes_written":12512610,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":726,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40413,"lbm_writes_lt_1ms":862,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":10496,"update_count":1525}
I20260812 06:19:00.477623 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling LogGCOp(5c0e52efd8d44bb8a1669bb8592cb332): free 20743880 bytes of WAL
I20260812 06:19:00.477882 16117 log_reader.cc:385] T 5c0e52efd8d44bb8a1669bb8592cb332: removed 2 log segments from log reader
I20260812 06:19:00.477934 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000001 (ops 1-6)
I20260812 06:19:00.477969 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000002 (ops 7-11)
I20260812 06:19:00.481446 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: LogGCOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:00.481802 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling UndoDeltaBlockGCOp(5c0e52efd8d44bb8a1669bb8592cb332): 20513814 bytes on disk
I20260812 06:19:00.482231 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: UndoDeltaBlockGCOp(5c0e52efd8d44bb8a1669bb8592cb332) 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:19:00.482640 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:00.496353 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.014s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":4707,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:19:00.496752 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:00.644811 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.148s	user 0.096s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":749,"lbm_read_time_us":10888,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23844,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":102912,"thread_start_us":336,"threads_started":5,"update_count":2000}
I20260812 06:19:00.645360 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=11.118625
I20260812 06:19:00.691368 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.044s	user 0.023s	sys 0.018s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15123,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:00.691956 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:00.717453 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.025s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":5386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.717868 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:00.726713 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3199,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:00.727100 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:00.897786 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.171s	user 0.106s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":290,"lbm_read_time_us":12221,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26252,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:19:00.898335 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=14.095187
I20260812 06:19:00.953459 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.055s	user 0.030s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19316,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.953992 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:00.963979 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.964375 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:01.136838 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.172s	user 0.096s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":250,"lbm_read_time_us":12103,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26695,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:19:01.137362 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=14.095187
I20260812 06:19:01.195568 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.058s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20119,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.196165 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:01.206413 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.206930 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:01.385910 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.179s	user 0.130s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1501,"lbm_read_time_us":12364,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27163,"lbm_writes_lt_1ms":543,"mutex_wait_us":542,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:19:01.386510 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=14.095187
I20260812 06:19:01.440312 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.054s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23219,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.440868 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:01.458783 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.018s	user 0.004s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3610,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.459277 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:01.644502 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.185s	user 0.102s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":637,"lbm_read_time_us":13538,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28493,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:19:01.644965 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=14.095187
I20260812 06:19:01.694114 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.049s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21915,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.694648 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:01.705276 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3679,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.705706 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushMRSOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:01.739187 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushMRSOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.033s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":47,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1418,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1690,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":1792}
I20260812 06:19:01.739876 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling LogGCOp(5c0e52efd8d44bb8a1669bb8592cb332): free 120553377 bytes of WAL
I20260812 06:19:01.740141 16117 log_reader.cc:385] T 5c0e52efd8d44bb8a1669bb8592cb332: removed 12 log segments from log reader
I20260812 06:19:01.740200 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000003 (ops 12-16)
I20260812 06:19:01.740240 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000004 (ops 17-21)
I20260812 06:19:01.740273 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000005 (ops 22-26)
I20260812 06:19:01.740307 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000006 (ops 27-31)
I20260812 06:19:01.740338 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000007 (ops 32-36)
I20260812 06:19:01.740368 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000008 (ops 37-41)
I20260812 06:19:01.740399 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000009 (ops 42-46)
I20260812 06:19:01.740429 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000010 (ops 47-50)
I20260812 06:19:01.740459 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000011 (ops 51-55)
I20260812 06:19:01.740490 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000012 (ops 56-60)
I20260812 06:19:01.740520 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000013 (ops 61-64)
I20260812 06:19:01.740550 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000014 (ops 65-69)
I20260812 06:19:01.763795 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: LogGCOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:01.764216 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling UndoDeltaBlockGCOp(5c0e52efd8d44bb8a1669bb8592cb332): 462 bytes on disk
I20260812 06:19:01.764715 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: UndoDeltaBlockGCOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:19:01.765259 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=3.181125
I20260812 06:19:01.780988 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.016s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4037,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:01.781405 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:01.794184 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4684,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:01.794628 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:02.014652 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.220s	user 0.127s	sys 0.089s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020733,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":538,"lbm_read_time_us":13618,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35193,"lbm_writes_lt_1ms":743,"mutex_wait_us":43,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":94,"threads_started":1,"update_count":3500}
I20260812 06:19:02.015163 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=18.063937
I20260812 06:19:02.081131 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.066s	user 0.032s	sys 0.020s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":23216,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":20352,"update_count":2500}
I20260812 06:19:02.081605 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:02.092101 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3534,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.092546 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:02.289059 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.196s	user 0.158s	sys 0.038s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1194,"lbm_read_time_us":13555,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31240,"lbm_writes_lt_1ms":643,"mutex_wait_us":303,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":3000}
I20260812 06:19:02.289647 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=14.095187
I20260812 06:19:02.334937 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.045s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19276,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.335476 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:02.350576 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.015s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5581,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.351145 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:02.528545 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.177s	user 0.117s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":572,"lbm_read_time_us":11006,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29941,"lbm_writes_lt_1ms":543,"mutex_wait_us":275,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:19:02.529235 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=14.095187
I20260812 06:19:02.581730 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.052s	user 0.018s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17964,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.582247 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:02.593434 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.593876 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:02.763180 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.169s	user 0.116s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":596,"lbm_read_time_us":13115,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28056,"lbm_writes_lt_1ms":543,"mutex_wait_us":294,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":39168,"update_count":2500}
I20260812 06:19:02.763726 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=14.095187
I20260812 06:19:02.827461 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.064s	user 0.034s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23396,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.828043 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:02.840328 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4541,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":500}
I20260812 06:19:02.840853 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:02.995167 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.154s	user 0.125s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":911,"lbm_read_time_us":10454,"lbm_reads_lt_1ms":568,"lbm_write_time_us":24471,"lbm_writes_lt_1ms":543,"mutex_wait_us":274,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:02.995728 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=14.095187
I20260812 06:19:03.045528 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.050s	user 0.027s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17959,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:03.046103 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:03.056329 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3914,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.056751 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushMRSOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:03.083756 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushMRSOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.027s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1219,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1237,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:03.084460 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling UndoDeltaBlockGCOp(5c0e52efd8d44bb8a1669bb8592cb332): 448 bytes on disk
I20260812 06:19:03.084884 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: UndoDeltaBlockGCOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.085443 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:03.251443 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.166s	user 0.097s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1044,"lbm_read_time_us":10971,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29054,"lbm_writes_lt_1ms":543,"mutex_wait_us":83,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:19:03.252079 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling LogGCOp(5c0e52efd8d44bb8a1669bb8592cb332): free 120553380 bytes of WAL
I20260812 06:19:03.252682 16117 log_reader.cc:385] T 5c0e52efd8d44bb8a1669bb8592cb332: removed 12 log segments from log reader
I20260812 06:19:03.252866 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000015 (ops 70-74)
I20260812 06:19:03.253044 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000016 (ops 75-78)
I20260812 06:19:03.253165 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000017 (ops 79-83)
I20260812 06:19:03.253669 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000018 (ops 84-88)
I20260812 06:19:03.253811 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000019 (ops 89-93)
I20260812 06:19:03.253921 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000020 (ops 94-98)
I20260812 06:19:03.254022 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000021 (ops 99-103)
I20260812 06:19:03.254065 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000022 (ops 104-108)
I20260812 06:19:03.254091 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000023 (ops 109-113)
I20260812 06:19:03.254142 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000024 (ops 114-118)
I20260812 06:19:03.254189 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000025 (ops 119-122)
I20260812 06:19:03.254215 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000026 (ops 123-127)
I20260812 06:19:03.295892 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: LogGCOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.043s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:03.296396 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=18.063937
I20260812 06:19:03.358202 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.062s	user 0.046s	sys 0.015s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":24250,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:03.358875 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=3.181125
I20260812 06:19:03.370519 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4077,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:03.370927 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:03.384449 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4947,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.384949 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:03.625186 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.240s	user 0.129s	sys 0.097s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020616,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":401,"lbm_read_time_us":16834,"lbm_reads_lt_1ms":773,"lbm_write_time_us":37575,"lbm_writes_lt_1ms":743,"mutex_wait_us":79,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":763392,"update_count":3500}
I20260812 06:19:03.625871 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=18.063937
I20260812 06:19:03.695714 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.070s	user 0.031s	sys 0.029s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28118,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:03.696355 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:03.708313 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4065,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.709079 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:03.903231 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.194s	user 0.123s	sys 0.070s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1042,"lbm_read_time_us":12968,"lbm_reads_lt_1ms":672,"lbm_write_time_us":30694,"lbm_writes_lt_1ms":643,"mutex_wait_us":426,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":37760,"update_count":3000}
I20260812 06:19:03.903879 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=16.079562
I20260812 06:19:03.970611 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.067s	user 0.030s	sys 0.024s Metrics: {"bytes_written":18214962,"delete_count":0,"lbm_write_time_us":25426,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":446,"reinsert_count":0,"update_count":2220}
I20260812 06:19:03.971125 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=5.165500
I20260812 06:19:03.995030 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.024s	user 0.016s	sys 0.000s Metrics: {"bytes_written":6400018,"delete_count":0,"lbm_write_time_us":6893,"lbm_writes_lt_1ms":159,"reinsert_count":0,"update_count":780}
I20260812 06:19:03.995600 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:04.199335 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.204s	user 0.119s	sys 0.078s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":216,"lbm_read_time_us":15599,"lbm_reads_lt_1ms":664,"lbm_write_time_us":31638,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:04.199913 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=18.063937
I20260812 06:19:04.256822 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.057s	user 0.028s	sys 0.024s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25281,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:04.257290 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:04.419621 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.162s	user 0.123s	sys 0.039s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24815567,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":238,"lbm_read_time_us":11761,"lbm_reads_lt_1ms":563,"lbm_write_time_us":26600,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2500}
I20260812 06:19:04.420308 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=14.095187
I20260812 06:19:04.470167 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.048s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17236,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.470731 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:04.481314 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3928,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.481774 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushMRSOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:04.521198 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushMRSOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.039s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1268,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1421,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:04.521929 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling LogGCOp(5c0e52efd8d44bb8a1669bb8592cb332): free 120100584 bytes of WAL
I20260812 06:19:04.522146 16117 log_reader.cc:385] T 5c0e52efd8d44bb8a1669bb8592cb332: removed 12 log segments from log reader
I20260812 06:19:04.522193 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000027 (ops 128-132)
I20260812 06:19:04.522221 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000028 (ops 133-137)
I20260812 06:19:04.522253 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000029 (ops 138-142)
I20260812 06:19:04.522303 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000030 (ops 143-147)
I20260812 06:19:04.522339 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000031 (ops 148-152)
I20260812 06:19:04.522372 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000032 (ops 153-156)
I20260812 06:19:04.522401 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000033 (ops 157-161)
I20260812 06:19:04.522439 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000034 (ops 162-166)
I20260812 06:19:04.522470 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000035 (ops 167-170)
I20260812 06:19:04.522502 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000036 (ops 171-175)
I20260812 06:19:04.522533 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000037 (ops 176-180)
I20260812 06:19:04.522567 16117 log.cc:1079] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Deleting log segment in path: /tmp/dist-test-taskev7aSE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515534907474-15610-0/minicluster-data/ts-0-root/wals/5c0e52efd8d44bb8a1669bb8592cb332/wal-000000038 (ops 181-184)
I20260812 06:19:04.546343 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: LogGCOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:04.546777 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling UndoDeltaBlockGCOp(5c0e52efd8d44bb8a1669bb8592cb332): 462 bytes on disk
I20260812 06:19:04.547240 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: UndoDeltaBlockGCOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:19:04.547878 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=3.181125
I20260812 06:19:04.565162 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.017s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4593,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:04.565531 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:04.574347 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3315,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.574790 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:04.793562 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.219s	user 0.143s	sys 0.063s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020733,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":141,"lbm_read_time_us":14261,"lbm_reads_lt_1ms":774,"lbm_write_time_us":34538,"lbm_writes_lt_1ms":743,"mutex_wait_us":48,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:19:04.794437 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=18.063937
I20260812 06:19:04.854630 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.060s	user 0.025s	sys 0.030s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25108,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:04.855176 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=2.188937
I20260812 06:19:04.866695 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: FlushDeltaMemStoresOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4392,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.867206 16217 maintenance_manager.cc:419] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: Scheduling MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332): perf score=1.000000
I20260812 06:19:04.883574 15610 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.734s	user 1.665s	sys 0.207s
I20260812 06:19:04.946393 15610 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.062s	user 0.003s	sys 0.000s
I20260812 06:19:04.947007 15610 tablet_server.cc:179] TabletServer@127.15.62.129:0 shutting down...
I20260812 06:19:05.020834 16117 maintenance_manager.cc:643] P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: MajorDeltaCompactionOp(5c0e52efd8d44bb8a1669bb8592cb332) complete. Timing: real 0.153s	user 0.101s	sys 0.052s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":277,"lbm_read_time_us":10952,"lbm_reads_lt_1ms":668,"lbm_write_time_us":27293,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":50176,"update_count":3000}
I20260812 06:19:05.021478 15610 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:05.021749 15610 tablet_replica.cc:333] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa: stopping tablet replica
I20260812 06:19:05.021890 15610 raft_consensus.cc:2243] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:05.022049 15610 raft_consensus.cc:2272] T 5c0e52efd8d44bb8a1669bb8592cb332 P 5f1112ba9bba4dc2ab8b0a0d9eb4a1aa [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:05.038014 15610 tablet_server.cc:196] TabletServer@127.15.62.129:0 shutdown complete.
I20260812 06:19:05.073318 15610 master.cc:562] Master@127.15.62.190:34259 shutting down...
I20260812 06:19:05.076432 15610 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:05.076622 15610 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:05.076689 15610 tablet_replica.cc:333] T 00000000000000000000000000000000 P e81a8d7968874458a519789d42d9fbc8: stopping tablet replica
I20260812 06:19:05.088865 15610 master.cc:584] Master@127.15.62.190:34259 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5196 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10246 ms total)

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