[==========] 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:05.570629 21540 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.9.62:44365
I20260812 06:18:05.571671 21540 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:05.572288 21540 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:05.578918 21551 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:05.579046 21540 server_base.cc:1061] running on GCE node
W20260812 06:18:05.579118 21547 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:05.579182 21548 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:18:05.579784 21540 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:05.579877 21540 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:05.579903 21540 hybrid_clock.cc:648] HybridClock initialized: now 1786515485579901 us; error 0 us; skew 500 ppm
I20260812 06:18:05.584666 21540 webserver.cc:533] Webserver started at http://127.21.9.62:46021/ using document root <none> and password file <none>
I20260812 06:18:05.585165 21540 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:05.585222 21540 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:05.585421 21540 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:05.587097 21540 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/master-0-root/instance:
uuid: "37f266db231e4be3ac781c87bfd206f5"
format_stamp: "Formatted at 2026-08-12 06:18:05 on dist-test-slave-jztv"
I20260812 06:18:05.590487 21540 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:05.592442 21559 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:05.593472 21540 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:05.593603 21540 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/master-0-root
uuid: "37f266db231e4be3ac781c87bfd206f5"
format_stamp: "Formatted at 2026-08-12 06:18:05 on dist-test-slave-jztv"
I20260812 06:18:05.593701 21540 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-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:05.611644 21540 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:05.612303 21540 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:05.612517 21540 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:05.620639 21540 rpc_server.cc:307] RPC server started. Bound to: 127.21.9.62:44365
I20260812 06:18:05.620653 21646 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.9.62:44365 every 8 connection(s)
I20260812 06:18:05.623023 21649 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:05.628487 21649 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5: Bootstrap starting.
I20260812 06:18:05.630967 21649 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:05.631882 21649 log.cc:826] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:05.633669 21649 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5: No bootstrap required, opened a new log
I20260812 06:18:05.636440 21649 raft_consensus.cc:359] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "37f266db231e4be3ac781c87bfd206f5" member_type: VOTER }
I20260812 06:18:05.636608 21649 raft_consensus.cc:385] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:05.636720 21649 raft_consensus.cc:740] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 37f266db231e4be3ac781c87bfd206f5, State: Initialized, Role: FOLLOWER
I20260812 06:18:05.637408 21649 consensus_queue.cc:260] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [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: "37f266db231e4be3ac781c87bfd206f5" member_type: VOTER }
I20260812 06:18:05.637585 21649 raft_consensus.cc:399] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:05.637655 21649 raft_consensus.cc:493] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:05.637809 21649 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:05.638811 21649 raft_consensus.cc:515] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "37f266db231e4be3ac781c87bfd206f5" member_type: VOTER }
I20260812 06:18:05.639266 21649 leader_election.cc:304] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [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: 37f266db231e4be3ac781c87bfd206f5; no voters: 
I20260812 06:18:05.639617 21649 leader_election.cc:290] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:05.639797 21652 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:05.640074 21652 raft_consensus.cc:697] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [term 1 LEADER]: Becoming Leader. State: Replica: 37f266db231e4be3ac781c87bfd206f5, State: Running, Role: LEADER
I20260812 06:18:05.640436 21652 consensus_queue.cc:237] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [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: "37f266db231e4be3ac781c87bfd206f5" member_type: VOTER }
I20260812 06:18:05.640669 21649 sys_catalog.cc:565] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:05.642460 21655 sys_catalog.cc:455] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 37f266db231e4be3ac781c87bfd206f5. Latest consensus state: current_term: 1 leader_uuid: "37f266db231e4be3ac781c87bfd206f5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "37f266db231e4be3ac781c87bfd206f5" member_type: VOTER } }
I20260812 06:18:05.642539 21654 sys_catalog.cc:455] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "37f266db231e4be3ac781c87bfd206f5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "37f266db231e4be3ac781c87bfd206f5" member_type: VOTER } }
I20260812 06:18:05.642601 21655 sys_catalog.cc:458] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:05.642634 21654 sys_catalog.cc:458] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:05.642930 21676 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:05.643369 21540 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:05.645102 21676 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:05.649678 21676 catalog_manager.cc:1383] Generated new cluster ID: 93eeb9e1a19c415fb6692074b8ab0114
I20260812 06:18:05.649746 21676 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:05.664640 21676 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:05.665465 21676 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:05.669612 21676 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5: Generated new TSK 0
I20260812 06:18:05.670164 21676 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:05.676096 21540 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:05.679020 21687 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:05.679029 21688 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:05.679214 21690 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:05.679229 21540 server_base.cc:1061] running on GCE node
I20260812 06:18:05.679455 21540 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:05.679512 21540 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:05.679538 21540 hybrid_clock.cc:648] HybridClock initialized: now 1786515485679536 us; error 0 us; skew 500 ppm
I20260812 06:18:05.680562 21540 webserver.cc:533] Webserver started at http://127.21.9.1:40433/ using document root <none> and password file <none>
I20260812 06:18:05.680742 21540 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:05.680810 21540 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:05.680903 21540 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:05.681288 21540 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/instance:
uuid: "5b87f142c0a74ffabf09e202258591c5"
format_stamp: "Formatted at 2026-08-12 06:18:05 on dist-test-slave-jztv"
I20260812 06:18:05.682878 21540 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:05.683876 21699 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:05.684118 21540 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:05.684188 21540 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root
uuid: "5b87f142c0a74ffabf09e202258591c5"
format_stamp: "Formatted at 2026-08-12 06:18:05 on dist-test-slave-jztv"
I20260812 06:18:05.684269 21540 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-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:05.692591 21540 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:05.693041 21540 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:05.693503 21540 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:05.694357 21540 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:05.694409 21540 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:05.694476 21540 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:05.694509 21540 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:05.701380 21540 rpc_server.cc:307] RPC server started. Bound to: 127.21.9.1:43899
I20260812 06:18:05.701427 21808 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.9.1:43899 every 8 connection(s)
I20260812 06:18:05.714779 21809 heartbeater.cc:344] Connected to a master server at 127.21.9.62:44365
I20260812 06:18:05.715058 21809 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:05.715533 21809 heartbeater.cc:507] Master 127.21.9.62:44365 requested a full tablet report, sending...
I20260812 06:18:05.716897 21590 ts_manager.cc:194] Registered new tserver with Master: 5b87f142c0a74ffabf09e202258591c5 (127.21.9.1:43899)
I20260812 06:18:05.717623 21540 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.0156336s
I20260812 06:18:05.719051 21590 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58228
I20260812 06:18:05.736912 21590 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58242:
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:05.754791 21747 tablet_service.cc:1511] Processing CreateTablet for tablet 584e134c975c4f768e2ea951c718c6c5 (DEFAULT_TABLE table=heavy-update-compaction-test [id=139f6cb2213c48978330e7fa991ec724]), partition=
I20260812 06:18:05.755275 21747 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 584e134c975c4f768e2ea951c718c6c5. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:05.757329 21829 tablet_bootstrap.cc:492] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Bootstrap starting.
I20260812 06:18:05.758874 21829 tablet_bootstrap.cc:654] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:05.760257 21829 tablet_bootstrap.cc:492] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: No bootstrap required, opened a new log
I20260812 06:18:05.760368 21829 ts_tablet_manager.cc:1403] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:05.760984 21829 raft_consensus.cc:359] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b87f142c0a74ffabf09e202258591c5" member_type: VOTER last_known_addr { host: "127.21.9.1" port: 43899 } }
I20260812 06:18:05.761137 21829 raft_consensus.cc:385] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:05.761199 21829 raft_consensus.cc:740] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5b87f142c0a74ffabf09e202258591c5, State: Initialized, Role: FOLLOWER
I20260812 06:18:05.761396 21829 consensus_queue.cc:260] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [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: "5b87f142c0a74ffabf09e202258591c5" member_type: VOTER last_known_addr { host: "127.21.9.1" port: 43899 } }
I20260812 06:18:05.761606 21829 raft_consensus.cc:399] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:05.761721 21829 raft_consensus.cc:493] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:05.761842 21829 raft_consensus.cc:3060] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:05.763235 21829 raft_consensus.cc:515] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b87f142c0a74ffabf09e202258591c5" member_type: VOTER last_known_addr { host: "127.21.9.1" port: 43899 } }
I20260812 06:18:05.763388 21829 leader_election.cc:304] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [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: 5b87f142c0a74ffabf09e202258591c5; no voters: 
I20260812 06:18:05.763621 21829 leader_election.cc:290] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:05.763734 21833 raft_consensus.cc:2804] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:05.763957 21833 raft_consensus.cc:697] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [term 1 LEADER]: Becoming Leader. State: Replica: 5b87f142c0a74ffabf09e202258591c5, State: Running, Role: LEADER
I20260812 06:18:05.763986 21829 ts_tablet_manager.cc:1434] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Time spent starting tablet: real 0.004s	user 0.002s	sys 0.002s
I20260812 06:18:05.764175 21809 heartbeater.cc:499] Master 127.21.9.62:44365 was elected leader, sending a full tablet report...
I20260812 06:18:05.764154 21833 consensus_queue.cc:237] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [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: "5b87f142c0a74ffabf09e202258591c5" member_type: VOTER last_known_addr { host: "127.21.9.1" port: 43899 } }
I20260812 06:18:05.767656 21590 catalog_manager.cc:5719] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5b87f142c0a74ffabf09e202258591c5 (127.21.9.1). New cstate: current_term: 1 leader_uuid: "5b87f142c0a74ffabf09e202258591c5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b87f142c0a74ffabf09e202258591c5" member_type: VOTER last_known_addr { host: "127.21.9.1" port: 43899 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:05.837145 21540 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.027s	sys 0.001s
I20260812 06:18:05.952436 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushMRSOp(584e134c975c4f768e2ea951c718c6c5): perf score=15.086190
I20260812 06:18:06.083971 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushMRSOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.131s	user 0.100s	sys 0.023s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":74,"delete_count":0,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1064,"drs_written":1,"lbm_read_time_us":147,"lbm_reads_lt_1ms":4,"lbm_write_time_us":27952,"lbm_writes_lt_1ms":567,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":151296,"update_count":1050}
I20260812 06:18:06.085068 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling LogGCOp(584e134c975c4f768e2ea951c718c6c5): free 8725963 bytes of WAL
I20260812 06:18:06.085403 21707 log_reader.cc:385] T 584e134c975c4f768e2ea951c718c6c5: removed 1 log segments from log reader
I20260812 06:18:06.085471 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000001 (ops 1-6)
I20260812 06:18:06.087477 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: LogGCOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:06.087774 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling UndoDeltaBlockGCOp(584e134c975c4f768e2ea951c718c6c5): 12308958 bytes on disk
I20260812 06:18:06.088296 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: UndoDeltaBlockGCOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:06.088712 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:06.101611 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.013s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4545,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:06.102177 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:06.218587 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.116s	user 0.100s	sys 0.013s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":815,"lbm_read_time_us":5971,"lbm_reads_lt_1ms":360,"lbm_write_time_us":22381,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":350,"threads_started":5,"update_count":1500}
I20260812 06:18:06.219278 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=7.149875
I20260812 06:18:06.241628 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.022s	user 0.018s	sys 0.004s Metrics: {"bytes_written":8615325,"delete_count":0,"lbm_write_time_us":8717,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:06.242246 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:06.259346 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.017s	user 0.001s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6894,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:18:06.259788 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:06.374502 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.115s	user 0.078s	sys 0.029s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528893,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":552,"lbm_read_time_us":6288,"lbm_reads_lt_1ms":368,"lbm_write_time_us":20084,"lbm_writes_lt_1ms":343,"mutex_wait_us":24,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":104448,"update_count":1500}
I20260812 06:18:06.375002 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:06.420315 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.045s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15264,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.420838 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:06.432394 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.433015 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:06.553210 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.120s	user 0.092s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":723,"lbm_read_time_us":9068,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20844,"lbm_writes_lt_1ms":443,"mutex_wait_us":259,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:06.553764 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:06.602101 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.048s	user 0.017s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13798,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.602656 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:06.615245 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.615733 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:06.735491 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.120s	user 0.095s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":237,"lbm_read_time_us":7469,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25062,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2000}
I20260812 06:18:06.738519 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:06.781744 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.043s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14389,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.782313 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:06.793147 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4017,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.793726 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:06.916028 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.122s	user 0.097s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":229,"lbm_read_time_us":8770,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23558,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:06.916966 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:06.965504 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.048s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17108,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.966173 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:06.982631 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6134,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.983223 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:07.121961 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.139s	user 0.098s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":938,"lbm_read_time_us":10481,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21981,"lbm_writes_lt_1ms":443,"mutex_wait_us":283,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:18:07.122660 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:07.166610 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.044s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14613,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:07.167177 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:07.183179 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5860,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.183873 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:07.309418 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.125s	user 0.106s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":155,"lbm_read_time_us":9709,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23863,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:18:07.310093 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:07.354259 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.044s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15844,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:07.354758 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:07.365662 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.366353 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushMRSOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:07.398826 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushMRSOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.032s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":261,"dirs.run_wall_time_us":1346,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1638,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":896}
I20260812 06:18:07.399606 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling LogGCOp(584e134c975c4f768e2ea951c718c6c5): free 127961101 bytes of WAL
I20260812 06:18:07.399827 21707 log_reader.cc:385] T 584e134c975c4f768e2ea951c718c6c5: removed 12 log segments from log reader
I20260812 06:18:07.399870 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000002 (ops 7-11)
I20260812 06:18:07.399899 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000003 (ops 12-16)
I20260812 06:18:07.399959 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000004 (ops 17-21)
I20260812 06:18:07.399991 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000005 (ops 22-26)
I20260812 06:18:07.400027 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000006 (ops 27-31)
I20260812 06:18:07.400079 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000007 (ops 32-36)
I20260812 06:18:07.400116 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000008 (ops 37-41)
I20260812 06:18:07.400156 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000009 (ops 42-46)
I20260812 06:18:07.400193 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000010 (ops 47-51)
I20260812 06:18:07.400235 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000011 (ops 52-56)
I20260812 06:18:07.400274 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000012 (ops 57-61)
I20260812 06:18:07.400313 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000013 (ops 62-66)
I20260812 06:18:07.426491 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: LogGCOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.027s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:07.427205 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=5.165500
I20260812 06:18:07.443009 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":6358991,"delete_count":0,"lbm_write_time_us":6252,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:18:07.443466 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:07.452349 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.009s	user 0.006s	sys 0.000s Metrics: {"bytes_written":1846277,"delete_count":0,"lbm_write_time_us":2495,"lbm_writes_lt_1ms":48,"reinsert_count":0,"update_count":225}
I20260812 06:18:07.452862 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:07.625236 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.172s	user 0.128s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836321,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":281,"lbm_read_time_us":10026,"lbm_reads_lt_1ms":666,"lbm_write_time_us":35877,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11136,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:18:07.625749 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling UndoDeltaBlockGCOp(584e134c975c4f768e2ea951c718c6c5): 473 bytes on disk
I20260812 06:18:07.626151 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: UndoDeltaBlockGCOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:18:07.626667 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=14.095187
I20260812 06:18:07.686434 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.060s	user 0.031s	sys 0.027s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":28270,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.686902 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:07.700531 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.701081 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:07.861949 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.161s	user 0.124s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1228,"lbm_read_time_us":10489,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29044,"lbm_writes_lt_1ms":543,"mutex_wait_us":357,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":30464,"update_count":2500}
I20260812 06:18:07.862540 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=14.095187
I20260812 06:18:07.920486 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.058s	user 0.020s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25359,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.920975 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:08.057873 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.137s	user 0.104s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631193,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":211,"lbm_read_time_us":8445,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23706,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:18:08.058499 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=11.118625
I20260812 06:18:08.100749 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.042s	user 0.009s	sys 0.029s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21136,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:08.101341 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:08.117259 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.016s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5473,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:08.117892 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:08.238268 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.120s	user 0.100s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":342,"lbm_read_time_us":6941,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22779,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:18:08.238956 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:08.278358 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.039s	user 0.032s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16758,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:08.278854 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:08.292317 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.292774 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:08.433599 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.141s	user 0.108s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":695,"lbm_read_time_us":10034,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27694,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:18:08.434502 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:08.478817 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.044s	user 0.025s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16757,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:08.479287 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:08.489835 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.490684 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:08.615634 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.125s	user 0.085s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":545,"lbm_read_time_us":8866,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22422,"lbm_writes_lt_1ms":443,"mutex_wait_us":283,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:18:08.616330 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:08.660055 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.044s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15199,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:08.660624 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:08.671090 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4143,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.671525 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:08.811486 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.140s	user 0.093s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":326,"lbm_read_time_us":11107,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22154,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:18:08.812083 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:08.860061 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.048s	user 0.035s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17407,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:08.860566 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:08.875597 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5653,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.876132 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushMRSOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:08.920140 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushMRSOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.044s	user 0.038s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":174,"dirs.run_wall_time_us":1382,"drs_written":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2265,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:08.921007 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling LogGCOp(584e134c975c4f768e2ea951c718c6c5): free 133477384 bytes of WAL
I20260812 06:18:08.921314 21707 log_reader.cc:385] T 584e134c975c4f768e2ea951c718c6c5: removed 13 log segments from log reader
I20260812 06:18:08.921396 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000014 (ops 67-71)
I20260812 06:18:08.921454 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000015 (ops 72-76)
I20260812 06:18:08.921502 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000016 (ops 77-81)
I20260812 06:18:08.921548 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000017 (ops 82-86)
I20260812 06:18:08.921592 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000018 (ops 87-91)
I20260812 06:18:08.921638 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000019 (ops 92-96)
I20260812 06:18:08.921681 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000020 (ops 97-101)
I20260812 06:18:08.921725 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000021 (ops 102-106)
I20260812 06:18:08.921769 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000022 (ops 107-111)
I20260812 06:18:08.921810 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000023 (ops 112-116)
I20260812 06:18:08.921854 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000024 (ops 117-121)
I20260812 06:18:08.921895 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000025 (ops 122-126)
I20260812 06:18:08.921939 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000026 (ops 127-131)
I20260812 06:18:08.958734 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: LogGCOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.038s	user 0.002s	sys 0.035s Metrics: {}
I20260812 06:18:08.959168 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=6.157687
I20260812 06:18:09.001235 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.042s	user 0.026s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13837,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:09.001834 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:09.020648 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7048,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.021437 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling UndoDeltaBlockGCOp(584e134c975c4f768e2ea951c718c6c5): 482 bytes on disk
I20260812 06:18:09.022101 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: UndoDeltaBlockGCOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4}
I20260812 06:18:09.024477 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:09.242908 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.218s	user 0.143s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938786,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":594,"lbm_read_time_us":17442,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37593,"lbm_writes_lt_1ms":743,"mutex_wait_us":30,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":96,"threads_started":1,"update_count":3500}
I20260812 06:18:09.243561 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=11.118625
I20260812 06:18:09.290838 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.047s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13069,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:09.291422 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:09.308157 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5988,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:09.308758 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:09.469290 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.160s	user 0.115s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":233,"lbm_read_time_us":11491,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25974,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2000}
I20260812 06:18:09.469929 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:09.511924 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.042s	user 0.014s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17496,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.512471 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:09.631615 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.119s	user 0.090s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528782,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":758,"lbm_read_time_us":7282,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21921,"lbm_writes_lt_1ms":343,"mutex_wait_us":79,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":1500}
I20260812 06:18:09.632126 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:09.669795 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.037s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16713,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.670409 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:09.781399 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.111s	user 0.102s	sys 0.009s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":306,"lbm_read_time_us":6091,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21742,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:18:09.781997 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:09.822207 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.040s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16118,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.822707 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:09.833141 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3929,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.833776 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:09.958472 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.124s	user 0.096s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":893,"lbm_read_time_us":8327,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25578,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:18:09.959177 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:10.002032 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.043s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16309,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.002655 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:10.013976 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4260,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.014659 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:10.144722 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.130s	user 0.105s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":148,"lbm_read_time_us":9482,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24992,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:18:10.145437 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:10.188990 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.043s	user 0.028s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15218,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.189503 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:10.200683 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.201323 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:10.334714 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.133s	user 0.111s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1299,"lbm_read_time_us":9528,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26010,"lbm_writes_lt_1ms":443,"mutex_wait_us":328,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:18:10.335297 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=10.126437
I20260812 06:18:10.380164 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.045s	user 0.015s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15227,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.380765 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=2.188937
I20260812 06:18:10.396430 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6180,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.396926 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushMRSOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:10.428619 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushMRSOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.032s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":1380,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1490,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:10.429874 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling UndoDeltaBlockGCOp(584e134c975c4f768e2ea951c718c6c5): 463 bytes on disk
I20260812 06:18:10.430562 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: UndoDeltaBlockGCOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4}
I20260812 06:18:10.431177 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:10.573161 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.142s	user 0.074s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":581,"lbm_read_time_us":8606,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22872,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:18:10.573709 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling LogGCOp(584e134c975c4f768e2ea951c718c6c5): free 120553636 bytes of WAL
I20260812 06:18:10.573946 21707 log_reader.cc:385] T 584e134c975c4f768e2ea951c718c6c5: removed 12 log segments from log reader
I20260812 06:18:10.574040 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000027 (ops 132-136)
I20260812 06:18:10.574111 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000028 (ops 137-141)
I20260812 06:18:10.574153 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000029 (ops 142-146)
I20260812 06:18:10.574190 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000030 (ops 147-150)
I20260812 06:18:10.574293 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000031 (ops 151-155)
I20260812 06:18:10.574350 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000032 (ops 156-160)
I20260812 06:18:10.574425 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000033 (ops 161-165)
I20260812 06:18:10.574465 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000034 (ops 166-170)
I20260812 06:18:10.574527 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000035 (ops 171-174)
I20260812 06:18:10.574565 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000036 (ops 175-179)
I20260812 06:18:10.574637 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000037 (ops 180-184)
I20260812 06:18:10.574676 21707 log.cc:1079] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/584e134c975c4f768e2ea951c718c6c5/wal-000000038 (ops 185-189)
I20260812 06:18:10.605159 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: LogGCOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.031s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:18:10.605751 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=15.087375
I20260812 06:18:10.659756 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.054s	user 0.028s	sys 0.015s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":19277,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:10.660307 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5): perf score=6.157687
I20260812 06:18:10.685362 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: FlushDeltaMemStoresOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.025s	user 0.018s	sys 0.003s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":7764,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:18:10.685887 21811 maintenance_manager.cc:419] P 5b87f142c0a74ffabf09e202258591c5: Scheduling MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5): perf score=1.000000
I20260812 06:18:10.704402 21540 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.867s	user 1.822s	sys 0.128s
I20260812 06:18:10.792549 21540 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.088s	user 0.001s	sys 0.000s
I20260812 06:18:10.793167 21540 tablet_server.cc:179] TabletServer@127.21.9.1:0 shutting down...
I20260812 06:18:10.854465 21707 maintenance_manager.cc:643] P 5b87f142c0a74ffabf09e202258591c5: MajorDeltaCompactionOp(584e134c975c4f768e2ea951c718c6c5) complete. Timing: real 0.168s	user 0.089s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836135,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3241,"lbm_read_time_us":12894,"lbm_reads_lt_1ms":660,"lbm_write_time_us":30349,"lbm_writes_lt_1ms":643,"mutex_wait_us":2612,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":42112,"update_count":3000}
I20260812 06:18:10.855254 21540 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:10.855681 21540 tablet_replica.cc:333] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5: stopping tablet replica
I20260812 06:18:10.855928 21540 raft_consensus.cc:2243] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:10.856187 21540 raft_consensus.cc:2272] T 584e134c975c4f768e2ea951c718c6c5 P 5b87f142c0a74ffabf09e202258591c5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:10.871688 21540 tablet_server.cc:196] TabletServer@127.21.9.1:0 shutdown complete.
I20260812 06:18:10.905259 21540 master.cc:562] Master@127.21.9.62:44365 shutting down...
I20260812 06:18:10.909534 21540 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:10.909732 21540 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:10.909829 21540 tablet_replica.cc:333] T 00000000000000000000000000000000 P 37f266db231e4be3ac781c87bfd206f5: stopping tablet replica
I20260812 06:18:10.923277 21540 master.cc:584] Master@127.21.9.62:44365 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5439 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:11.021070 21540 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.9.62:44715
I20260812 06:18:11.021499 21540 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:11.024250 21540 server_base.cc:1061] running on GCE node
W20260812 06:18:11.024318 21851 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:11.024371 21852 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:11.024286 21855 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:11.024710 21540 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:11.024753 21540 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:11.024768 21540 hybrid_clock.cc:648] HybridClock initialized: now 1786515491024768 us; error 0 us; skew 500 ppm
I20260812 06:18:11.025642 21540 webserver.cc:533] Webserver started at http://127.21.9.62:40567/ using document root <none> and password file <none>
I20260812 06:18:11.025823 21540 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:11.025892 21540 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:11.026005 21540 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:11.026516 21540 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/master-0-root/instance:
uuid: "d480643990a049cc9955e4baaed5ac43"
format_stamp: "Formatted at 2026-08-12 06:18:11 on dist-test-slave-jztv"
I20260812 06:18:11.028077 21540 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:11.029247 21863 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:11.029506 21540 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:11.029609 21540 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/master-0-root
uuid: "d480643990a049cc9955e4baaed5ac43"
format_stamp: "Formatted at 2026-08-12 06:18:11 on dist-test-slave-jztv"
I20260812 06:18:11.029698 21540 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-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:11.034842 21540 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:11.035198 21540 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:11.039678 21540 rpc_server.cc:307] RPC server started. Bound to: 127.21.9.62:44715
I20260812 06:18:11.041320 21956 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:11.044643 21954 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.9.62:44715 every 8 connection(s)
I20260812 06:18:11.045652 21956 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43: Bootstrap starting.
I20260812 06:18:11.046540 21956 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:11.047643 21956 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43: No bootstrap required, opened a new log
I20260812 06:18:11.048054 21956 raft_consensus.cc:359] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d480643990a049cc9955e4baaed5ac43" member_type: VOTER }
I20260812 06:18:11.048141 21956 raft_consensus.cc:385] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:11.048184 21956 raft_consensus.cc:740] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d480643990a049cc9955e4baaed5ac43, State: Initialized, Role: FOLLOWER
I20260812 06:18:11.048395 21956 consensus_queue.cc:260] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [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: "d480643990a049cc9955e4baaed5ac43" member_type: VOTER }
I20260812 06:18:11.048476 21956 raft_consensus.cc:399] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:11.048535 21956 raft_consensus.cc:493] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:11.048594 21956 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:11.049281 21956 raft_consensus.cc:515] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d480643990a049cc9955e4baaed5ac43" member_type: VOTER }
I20260812 06:18:11.049402 21956 leader_election.cc:304] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [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: d480643990a049cc9955e4baaed5ac43; no voters: 
I20260812 06:18:11.049638 21956 leader_election.cc:290] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:11.049782 21963 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:11.050019 21963 raft_consensus.cc:697] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [term 1 LEADER]: Becoming Leader. State: Replica: d480643990a049cc9955e4baaed5ac43, State: Running, Role: LEADER
I20260812 06:18:11.050074 21956 sys_catalog.cc:565] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:11.050165 21963 consensus_queue.cc:237] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [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: "d480643990a049cc9955e4baaed5ac43" member_type: VOTER }
I20260812 06:18:11.050606 21964 sys_catalog.cc:455] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d480643990a049cc9955e4baaed5ac43" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d480643990a049cc9955e4baaed5ac43" member_type: VOTER } }
I20260812 06:18:11.050719 21964 sys_catalog.cc:458] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:11.050621 21965 sys_catalog.cc:455] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d480643990a049cc9955e4baaed5ac43. Latest consensus state: current_term: 1 leader_uuid: "d480643990a049cc9955e4baaed5ac43" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d480643990a049cc9955e4baaed5ac43" member_type: VOTER } }
I20260812 06:18:11.050786 21965 sys_catalog.cc:458] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:11.052016 21540 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:11.052484 21986 catalog_manager.cc:1594] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:11.052562 21986 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:11.052630 21968 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:11.053236 21968 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:11.055089 21968 catalog_manager.cc:1383] Generated new cluster ID: 1f4ef9c11d3140de98bfc332af1f03ce
I20260812 06:18:11.055179 21968 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:11.084216 21968 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:11.084790 21968 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:11.097203 21968 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43: Generated new TSK 0
I20260812 06:18:11.097404 21968 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:11.116667 21540 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:11.118798 21992 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:11.118819 21991 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:11.118906 21995 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:11.118942 21540 server_base.cc:1061] running on GCE node
I20260812 06:18:11.119223 21540 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:11.119268 21540 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:11.119285 21540 hybrid_clock.cc:648] HybridClock initialized: now 1786515491119285 us; error 0 us; skew 500 ppm
I20260812 06:18:11.120167 21540 webserver.cc:533] Webserver started at http://127.21.9.1:42237/ using document root <none> and password file <none>
I20260812 06:18:11.120340 21540 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:11.120411 21540 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:11.120507 21540 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:11.120908 21540 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/instance:
uuid: "8a07b668cce74f23ab8b40d0cd708c0a"
format_stamp: "Formatted at 2026-08-12 06:18:11 on dist-test-slave-jztv"
I20260812 06:18:11.122489 21540 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:11.123450 22002 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:11.123711 21540 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:11.123777 21540 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root
uuid: "8a07b668cce74f23ab8b40d0cd708c0a"
format_stamp: "Formatted at 2026-08-12 06:18:11 on dist-test-slave-jztv"
I20260812 06:18:11.123859 21540 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-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:11.136911 21540 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:11.137297 21540 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:11.137598 21540 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:11.138057 21540 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:11.138095 21540 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:11.138154 21540 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:11.138188 21540 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:11.142611 21540 rpc_server.cc:307] RPC server started. Bound to: 127.21.9.1:44887
I20260812 06:18:11.143952 22098 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.9.1:44887 every 8 connection(s)
I20260812 06:18:11.154933 22099 heartbeater.cc:344] Connected to a master server at 127.21.9.62:44715
I20260812 06:18:11.155056 22099 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:11.155284 22099 heartbeater.cc:507] Master 127.21.9.62:44715 requested a full tablet report, sending...
I20260812 06:18:11.155967 21888 ts_manager.cc:194] Registered new tserver with Master: 8a07b668cce74f23ab8b40d0cd708c0a (127.21.9.1:44887)
I20260812 06:18:11.156697 21888 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36626
I20260812 06:18:11.156853 21540 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013208304s
I20260812 06:18:11.163945 21888 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36632:
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:11.172550 22046 tablet_service.cc:1511] Processing CreateTablet for tablet 0949485898ee415db8f8a312edb70992 (DEFAULT_TABLE table=heavy-update-compaction-test [id=65445eec51bd43fdbc57e38352d4a5d3]), partition=
I20260812 06:18:11.172832 22046 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0949485898ee415db8f8a312edb70992. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:11.174912 22120 tablet_bootstrap.cc:492] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Bootstrap starting.
I20260812 06:18:11.175747 22120 tablet_bootstrap.cc:654] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:11.176730 22120 tablet_bootstrap.cc:492] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: No bootstrap required, opened a new log
I20260812 06:18:11.176823 22120 ts_tablet_manager.cc:1403] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:11.177193 22120 raft_consensus.cc:359] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8a07b668cce74f23ab8b40d0cd708c0a" member_type: VOTER last_known_addr { host: "127.21.9.1" port: 44887 } }
I20260812 06:18:11.177279 22120 raft_consensus.cc:385] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:11.177335 22120 raft_consensus.cc:740] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8a07b668cce74f23ab8b40d0cd708c0a, State: Initialized, Role: FOLLOWER
I20260812 06:18:11.177495 22120 consensus_queue.cc:260] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [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: "8a07b668cce74f23ab8b40d0cd708c0a" member_type: VOTER last_known_addr { host: "127.21.9.1" port: 44887 } }
I20260812 06:18:11.177583 22120 raft_consensus.cc:399] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:11.177634 22120 raft_consensus.cc:493] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:11.177690 22120 raft_consensus.cc:3060] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:11.178486 22120 raft_consensus.cc:515] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8a07b668cce74f23ab8b40d0cd708c0a" member_type: VOTER last_known_addr { host: "127.21.9.1" port: 44887 } }
I20260812 06:18:11.178625 22120 leader_election.cc:304] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [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: 8a07b668cce74f23ab8b40d0cd708c0a; no voters: 
I20260812 06:18:11.178836 22120 leader_election.cc:290] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:11.178982 22122 raft_consensus.cc:2804] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:11.179149 22120 ts_tablet_manager.cc:1434] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:11.179171 22099 heartbeater.cc:499] Master 127.21.9.62:44715 was elected leader, sending a full tablet report...
I20260812 06:18:11.179196 22122 raft_consensus.cc:697] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [term 1 LEADER]: Becoming Leader. State: Replica: 8a07b668cce74f23ab8b40d0cd708c0a, State: Running, Role: LEADER
I20260812 06:18:11.179342 22122 consensus_queue.cc:237] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [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: "8a07b668cce74f23ab8b40d0cd708c0a" member_type: VOTER last_known_addr { host: "127.21.9.1" port: 44887 } }
I20260812 06:18:11.180538 21888 catalog_manager.cc:5719] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a reported cstate change: term changed from 0 to 1, leader changed from <none> to 8a07b668cce74f23ab8b40d0cd708c0a (127.21.9.1). New cstate: current_term: 1 leader_uuid: "8a07b668cce74f23ab8b40d0cd708c0a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8a07b668cce74f23ab8b40d0cd708c0a" member_type: VOTER last_known_addr { host: "127.21.9.1" port: 44887 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:11.240273 21540 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.014s	sys 0.008s
I20260812 06:18:11.394515 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushMRSOp(0949485898ee415db8f8a312edb70992): perf score=19.054940
I20260812 06:18:11.558792 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushMRSOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.164s	user 0.127s	sys 0.036s Metrics: {"bytes_written":11897249,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1263,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40598,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":1408,"update_count":1450}
I20260812 06:18:11.559500 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling LogGCOp(0949485898ee415db8f8a312edb70992): free 20290830 bytes of WAL
I20260812 06:18:11.559782 22010 log_reader.cc:385] T 0949485898ee415db8f8a312edb70992: removed 2 log segments from log reader
I20260812 06:18:11.559846 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000001 (ops 1-6)
I20260812 06:18:11.559933 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000002 (ops 7-10)
I20260812 06:18:11.564040 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: LogGCOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:11.564385 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling UndoDeltaBlockGCOp(0949485898ee415db8f8a312edb70992): 16821646 bytes on disk
I20260812 06:18:11.564812 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: UndoDeltaBlockGCOp(0949485898ee415db8f8a312edb70992) 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:18:11.565227 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:11.590948 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.026s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4129,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.591459 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:11.602877 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4489,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.603289 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:11.788441 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.185s	user 0.122s	sys 0.056s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405561,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":552,"lbm_read_time_us":12433,"lbm_reads_lt_1ms":559,"lbm_write_time_us":30129,"lbm_writes_lt_1ms":533,"mutex_wait_us":63,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":330,"threads_started":5,"update_count":2450}
I20260812 06:18:11.789042 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=14.095187
I20260812 06:18:11.849037 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.060s	user 0.042s	sys 0.005s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20736,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.849658 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:11.861479 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4628,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.862020 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:12.039031 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.177s	user 0.132s	sys 0.035s 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":293,"lbm_read_time_us":11923,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28552,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:18:12.039690 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=14.095187
I20260812 06:18:12.098805 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.059s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18629,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.099313 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:12.109932 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.110417 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:12.299496 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.189s	user 0.118s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":170,"lbm_read_time_us":11953,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29439,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21632,"update_count":2500}
I20260812 06:18:12.300174 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=14.095187
I20260812 06:18:12.349953 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.050s	user 0.022s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17900,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.350518 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:12.375337 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.025s	user 0.012s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5684,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.375936 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:12.570477 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.194s	user 0.098s	sys 0.085s 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":529,"lbm_read_time_us":11091,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30243,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:18:12.571256 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=14.095187
I20260812 06:18:12.623456 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.052s	user 0.023s	sys 0.025s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24876,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.623924 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:12.635273 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4208,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.635795 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:12.811508 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.175s	user 0.124s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":310,"lbm_read_time_us":9962,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29504,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:18:12.812104 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=14.095187
I20260812 06:18:12.863806 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.052s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19780,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.864315 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:12.877074 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.877630 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushMRSOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:12.907173 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushMRSOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.029s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":1631,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1889,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:12.907766 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling LogGCOp(0949485898ee415db8f8a312edb70992): free 117302562 bytes of WAL
I20260812 06:18:12.907995 22010 log_reader.cc:385] T 0949485898ee415db8f8a312edb70992: removed 12 log segments from log reader
I20260812 06:18:12.908041 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000003 (ops 11-15)
I20260812 06:18:12.908092 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000004 (ops 16-20)
I20260812 06:18:12.908138 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000005 (ops 21-25)
I20260812 06:18:12.908164 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000006 (ops 26-30)
I20260812 06:18:12.908205 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000007 (ops 31-34)
I20260812 06:18:12.908262 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000008 (ops 35-39)
I20260812 06:18:12.908303 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000009 (ops 40-44)
I20260812 06:18:12.908334 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000010 (ops 45-49)
I20260812 06:18:12.908398 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000011 (ops 50-54)
I20260812 06:18:12.908443 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000012 (ops 55-58)
I20260812 06:18:12.908496 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000013 (ops 59-63)
I20260812 06:18:12.908540 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000014 (ops 64-68)
I20260812 06:18:12.934465 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: LogGCOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:12.934859 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=3.181125
I20260812 06:18:12.956506 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.021s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":6873,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:12.957180 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling LogGCOp(0949485898ee415db8f8a312edb70992): free 11564875 bytes of WAL
I20260812 06:18:12.957569 22010 log_reader.cc:385] T 0949485898ee415db8f8a312edb70992: removed 1 log segments from log reader
I20260812 06:18:12.957664 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000015 (ops 69-72)
I20260812 06:18:12.961144 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: LogGCOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:12.961522 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling UndoDeltaBlockGCOp(0949485898ee415db8f8a312edb70992): 462 bytes on disk
I20260812 06:18:12.962000 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: UndoDeltaBlockGCOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:18:12.962533 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:12.976912 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5302,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:12.977588 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:13.219735 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.242s	user 0.136s	sys 0.096s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020736,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1250,"lbm_read_time_us":16297,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38527,"lbm_writes_lt_1ms":743,"mutex_wait_us":535,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14336,"thread_start_us":94,"threads_started":1,"update_count":3500}
I20260812 06:18:13.220310 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=18.063937
I20260812 06:18:13.297079 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.077s	user 0.035s	sys 0.024s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":28407,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:13.297528 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:13.309055 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3787,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.309670 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:13.510952 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.201s	user 0.130s	sys 0.071s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":120,"lbm_read_time_us":14137,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34305,"lbm_writes_lt_1ms":643,"mutex_wait_us":42,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":3000}
I20260812 06:18:13.511631 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=15.087375
I20260812 06:18:13.560446 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.049s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":20744,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:13.561053 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:13.581035 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.020s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4529,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.581477 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:13.590680 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3529,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:13.591130 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:13.788065 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.197s	user 0.149s	sys 0.047s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918202,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":694,"lbm_read_time_us":12755,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33369,"lbm_writes_lt_1ms":643,"mutex_wait_us":315,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":3000}
I20260812 06:18:13.788904 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=14.095187
I20260812 06:18:13.843195 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.054s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23599,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:13.843840 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:13.854836 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4268,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.855285 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:14.027201 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.172s	user 0.131s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":626,"lbm_read_time_us":12612,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28370,"lbm_writes_lt_1ms":543,"mutex_wait_us":224,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":2500}
I20260812 06:18:14.027905 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=14.095187
I20260812 06:18:14.084672 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.057s	user 0.028s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18782,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.085268 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:14.101601 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6125,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.102119 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:14.295570 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.193s	user 0.116s	sys 0.065s 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":1022,"lbm_read_time_us":11822,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32893,"lbm_writes_lt_1ms":543,"mutex_wait_us":474,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":2500}
I20260812 06:18:14.296077 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=14.095187
I20260812 06:18:14.360703 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.064s	user 0.032s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22461,"lbm_writes_lt_1ms":403,"mutex_wait_us":3,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.361232 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:14.372614 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4439,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.373099 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushMRSOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:14.416574 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushMRSOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.043s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":170,"dirs.run_wall_time_us":1269,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1830,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:14.417209 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling LogGCOp(0949485898ee415db8f8a312edb70992): free 112239314 bytes of WAL
I20260812 06:18:14.417421 22010 log_reader.cc:385] T 0949485898ee415db8f8a312edb70992: removed 11 log segments from log reader
I20260812 06:18:14.417466 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000016 (ops 73-77)
I20260812 06:18:14.417492 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000017 (ops 78-82)
I20260812 06:18:14.417553 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000018 (ops 83-87)
I20260812 06:18:14.417608 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000019 (ops 88-92)
I20260812 06:18:14.417649 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000020 (ops 93-97)
I20260812 06:18:14.417687 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000021 (ops 98-102)
I20260812 06:18:14.417728 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000022 (ops 103-106)
I20260812 06:18:14.417769 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000023 (ops 107-111)
I20260812 06:18:14.417806 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000024 (ops 112-116)
I20260812 06:18:14.417845 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000025 (ops 117-121)
I20260812 06:18:14.417882 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000026 (ops 122-126)
I20260812 06:18:14.441939 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: LogGCOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:14.442380 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=3.181125
I20260812 06:18:14.465831 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.023s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6654,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:14.466336 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling UndoDeltaBlockGCOp(0949485898ee415db8f8a312edb70992): 462 bytes on disk
I20260812 06:18:14.466707 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: UndoDeltaBlockGCOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:14.467185 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:14.476372 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3449,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:14.476792 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:14.717293 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.240s	user 0.158s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":367,"lbm_read_time_us":15997,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41019,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11904,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:18:14.718086 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=18.063937
I20260812 06:18:14.773300 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.054s	user 0.031s	sys 0.020s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":24406,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:14.773830 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:14.789451 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.790059 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:14.953568 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.163s	user 0.135s	sys 0.028s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":258,"lbm_read_time_us":13236,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32944,"lbm_writes_lt_1ms":643,"mutex_wait_us":62,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":3000}
I20260812 06:18:14.954334 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=14.095187
I20260812 06:18:15.008522 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.054s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23338,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.009034 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:15.021291 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4988,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.021729 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:15.184998 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.163s	user 0.119s	sys 0.035s 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":329,"lbm_read_time_us":10336,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31354,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":78976,"update_count":2500}
I20260812 06:18:15.185803 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=14.095187
I20260812 06:18:15.231079 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.045s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19310,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.231598 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:15.394680 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.163s	user 0.122s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":362,"lbm_read_time_us":10720,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27641,"lbm_writes_lt_1ms":443,"mutex_wait_us":104,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2000}
I20260812 06:18:15.395411 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=11.118625
I20260812 06:18:15.437184 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.042s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17275,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:15.438014 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:15.455587 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.017s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3954,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.456043 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:15.465638 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3678,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:15.466090 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:15.672617 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.206s	user 0.139s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":991,"lbm_read_time_us":12950,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33859,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":350,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2500}
I20260812 06:18:15.673367 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=14.095187
I20260812 06:18:15.730011 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.056s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24667,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.730624 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:15.751158 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.020s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6030,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.751751 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:15.774787 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.023s	user 0.006s	sys 0.016s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4316,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.775386 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushMRSOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:15.821497 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushMRSOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.046s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":1455,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2026,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:15.822784 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling LogGCOp(0949485898ee415db8f8a312edb70992): free 112692548 bytes of WAL
I20260812 06:18:15.823097 22010 log_reader.cc:385] T 0949485898ee415db8f8a312edb70992: removed 11 log segments from log reader
I20260812 06:18:15.823199 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000027 (ops 127-131)
I20260812 06:18:15.823280 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000028 (ops 132-136)
I20260812 06:18:15.823370 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000029 (ops 137-141)
I20260812 06:18:15.823441 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000030 (ops 142-146)
I20260812 06:18:15.823513 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000031 (ops 147-151)
I20260812 06:18:15.823580 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000032 (ops 152-156)
I20260812 06:18:15.823644 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000033 (ops 157-161)
I20260812 06:18:15.823715 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000034 (ops 162-166)
I20260812 06:18:15.823801 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000035 (ops 167-171)
I20260812 06:18:15.823880 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000036 (ops 172-176)
I20260812 06:18:15.823956 22010 log.cc:1079] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: Deleting log segment in path: /tmp/dist-test-task9oaeIU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515485559183-21540-0/minicluster-data/ts-0-root/wals/0949485898ee415db8f8a312edb70992/wal-000000037 (ops 177-181)
I20260812 06:18:15.855342 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: LogGCOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.032s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:18:15.855796 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:15.881803 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.026s	user 0.004s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7505,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.882432 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling UndoDeltaBlockGCOp(0949485898ee415db8f8a312edb70992): 448 bytes on disk
I20260812 06:18:15.882840 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: UndoDeltaBlockGCOp(0949485898ee415db8f8a312edb70992) 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:15.883368 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:15.895231 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4278,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.895869 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:16.165894 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.270s	user 0.168s	sys 0.099s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":514,"lbm_read_time_us":19926,"lbm_reads_lt_1ms":875,"lbm_write_time_us":44353,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":64000,"thread_start_us":90,"threads_started":1,"update_count":4000}
I20260812 06:18:16.166599 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=18.063937
I20260812 06:18:16.228447 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.062s	user 0.041s	sys 0.018s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":27599,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:16.229179 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992): perf score=2.188937
I20260812 06:18:16.243577 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: FlushDeltaMemStoresOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.244843 22100 maintenance_manager.cc:419] P 8a07b668cce74f23ab8b40d0cd708c0a: Scheduling MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992): perf score=1.000000
I20260812 06:18:16.260689 21540 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.020s	user 1.889s	sys 0.156s
I20260812 06:18:16.341926 21540 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.081s	user 0.001s	sys 0.000s
I20260812 06:18:16.342499 21540 tablet_server.cc:179] TabletServer@127.21.9.1:0 shutting down...
I20260812 06:18:16.418742 22010 maintenance_manager.cc:643] P 8a07b668cce74f23ab8b40d0cd708c0a: MajorDeltaCompactionOp(0949485898ee415db8f8a312edb70992) complete. Timing: real 0.174s	user 0.119s	sys 0.054s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1282,"lbm_read_time_us":16184,"lbm_reads_lt_1ms":660,"lbm_write_time_us":28750,"lbm_writes_lt_1ms":643,"mutex_wait_us":45,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":102784,"update_count":3000}
I20260812 06:18:16.419543 21540 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:16.419795 21540 tablet_replica.cc:333] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a: stopping tablet replica
I20260812 06:18:16.419950 21540 raft_consensus.cc:2243] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:16.420151 21540 raft_consensus.cc:2272] T 0949485898ee415db8f8a312edb70992 P 8a07b668cce74f23ab8b40d0cd708c0a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:16.436416 21540 tablet_server.cc:196] TabletServer@127.21.9.1:0 shutdown complete.
I20260812 06:18:16.471585 21540 master.cc:562] Master@127.21.9.62:44715 shutting down...
I20260812 06:18:16.475178 21540 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:16.475343 21540 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:16.475392 21540 tablet_replica.cc:333] T 00000000000000000000000000000000 P d480643990a049cc9955e4baaed5ac43: stopping tablet replica
I20260812 06:18:16.487785 21540 master.cc:584] Master@127.21.9.62:44715 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5567 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11007 ms total)

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