[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:22.803982 30683 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.29.246.254:46015
I20260812 06:16:22.804975 30683 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:22.805536 30683 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:22.812621 30683 server_base.cc:1061] running on GCE node
W20260812 06:16:22.812548 30688 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:16:22.812521 30689 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:22.812956 30691 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:16:22.813643 30683 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:22.813761 30683 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:22.813841 30683 hybrid_clock.cc:648] HybridClock initialized: now 1786515382813838 us; error 0 us; skew 500 ppm
I20260812 06:16:22.816094 30683 webserver.cc:533] Webserver started at http://127.29.246.254:44349/ using document root <none> and password file <none>
I20260812 06:16:22.816740 30683 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:22.816843 30683 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:22.817132 30683 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:22.819027 30683 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/master-0-root/instance:
uuid: "7466b902626f4c24b651a1b8b3d1c68c"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-zpfg"
I20260812 06:16:22.822928 30683 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:16:22.825345 30698 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:22.826730 30683 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:22.826846 30683 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/master-0-root
uuid: "7466b902626f4c24b651a1b8b3d1c68c"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-zpfg"
I20260812 06:16:22.826998 30683 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:22.851027 30683 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:22.851874 30683 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:22.852102 30683 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:22.860775 30751 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.246.254:46015 every 8 connection(s)
I20260812 06:16:22.860783 30683 rpc_server.cc:307] RPC server started. Bound to: 127.29.246.254:46015
I20260812 06:16:22.863544 30752 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:22.869221 30752 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c: Bootstrap starting.
I20260812 06:16:22.871778 30752 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:22.872742 30752 log.cc:826] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:22.875438 30752 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c: No bootstrap required, opened a new log
I20260812 06:16:22.880334 30752 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7466b902626f4c24b651a1b8b3d1c68c" member_type: VOTER }
I20260812 06:16:22.880673 30752 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:22.880785 30752 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7466b902626f4c24b651a1b8b3d1c68c, State: Initialized, Role: FOLLOWER
I20260812 06:16:22.881533 30752 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [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: "7466b902626f4c24b651a1b8b3d1c68c" member_type: VOTER }
I20260812 06:16:22.881690 30752 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:22.881803 30752 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:22.881940 30752 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:22.883332 30752 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7466b902626f4c24b651a1b8b3d1c68c" member_type: VOTER }
I20260812 06:16:22.884024 30752 leader_election.cc:304] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [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: 7466b902626f4c24b651a1b8b3d1c68c; no voters: 
I20260812 06:16:22.884560 30752 leader_election.cc:290] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:22.884717 30755 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:22.885056 30755 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [term 1 LEADER]: Becoming Leader. State: Replica: 7466b902626f4c24b651a1b8b3d1c68c, State: Running, Role: LEADER
I20260812 06:16:22.885592 30755 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [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: "7466b902626f4c24b651a1b8b3d1c68c" member_type: VOTER }
I20260812 06:16:22.885744 30752 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:22.888475 30683 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:22.888424 30756 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7466b902626f4c24b651a1b8b3d1c68c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7466b902626f4c24b651a1b8b3d1c68c" member_type: VOTER } }
I20260812 06:16:22.888594 30756 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:22.889027 30772 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:22.890846 30757 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7466b902626f4c24b651a1b8b3d1c68c. Latest consensus state: current_term: 1 leader_uuid: "7466b902626f4c24b651a1b8b3d1c68c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7466b902626f4c24b651a1b8b3d1c68c" member_type: VOTER } }
I20260812 06:16:22.891037 30757 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:22.891903 30772 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:22.898141 30772 catalog_manager.cc:1383] Generated new cluster ID: be51887b748f487480a6b4dacf0d831b
I20260812 06:16:22.898295 30772 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:22.921986 30772 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:22.923381 30772 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:22.944725 30772 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c: Generated new TSK 0
I20260812 06:16:22.945505 30772 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:22.953871 30683 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:22.957011 30779 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:22.957006 30776 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:22.957064 30683 server_base.cc:1061] running on GCE node
W20260812 06:16:22.957227 30777 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:22.957558 30683 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:22.957607 30683 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:22.957623 30683 hybrid_clock.cc:648] HybridClock initialized: now 1786515382957623 us; error 0 us; skew 500 ppm
I20260812 06:16:22.958686 30683 webserver.cc:533] Webserver started at http://127.29.246.193:37713/ using document root <none> and password file <none>
I20260812 06:16:22.958920 30683 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:22.958976 30683 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:22.959091 30683 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:22.959501 30683 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/instance:
uuid: "cb1358931ed94f7aa3cbffffaeee922e"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-zpfg"
I20260812 06:16:22.961077 30683 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:22.962172 30784 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:22.962509 30683 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:22.962603 30683 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root
uuid: "cb1358931ed94f7aa3cbffffaeee922e"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-zpfg"
I20260812 06:16:22.962697 30683 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:22.988252 30683 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:22.988919 30683 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:22.989504 30683 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:22.990487 30683 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:22.990568 30683 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:22.990644 30683 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:22.990694 30683 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:23.004874 30683 rpc_server.cc:307] RPC server started. Bound to: 127.29.246.193:38211
I20260812 06:16:23.005267 30852 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.246.193:38211 every 8 connection(s)
I20260812 06:16:23.025619 30853 heartbeater.cc:344] Connected to a master server at 127.29.246.254:46015
I20260812 06:16:23.025916 30853 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:23.026508 30853 heartbeater.cc:507] Master 127.29.246.254:46015 requested a full tablet report, sending...
I20260812 06:16:23.028241 30715 ts_manager.cc:194] Registered new tserver with Master: cb1358931ed94f7aa3cbffffaeee922e (127.29.246.193:38211)
I20260812 06:16:23.028788 30683 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.022803301s
I20260812 06:16:23.029826 30715 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56108
I20260812 06:16:23.042598 30715 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56124:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:23.060205 30813 tablet_service.cc:1511] Processing CreateTablet for tablet 064620a0d6014eec822c2d2a8f943e90 (DEFAULT_TABLE table=heavy-update-compaction-test [id=62d2ad998b5d494396014989a611efb5]), partition=
I20260812 06:16:23.060761 30813 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 064620a0d6014eec822c2d2a8f943e90. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:23.064348 30867 tablet_bootstrap.cc:492] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Bootstrap starting.
I20260812 06:16:23.066203 30867 tablet_bootstrap.cc:654] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:23.068650 30867 tablet_bootstrap.cc:492] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: No bootstrap required, opened a new log
I20260812 06:16:23.068750 30867 ts_tablet_manager.cc:1403] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Time spent bootstrapping tablet: real 0.005s	user 0.000s	sys 0.004s
I20260812 06:16:23.069365 30867 raft_consensus.cc:359] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cb1358931ed94f7aa3cbffffaeee922e" member_type: VOTER last_known_addr { host: "127.29.246.193" port: 38211 } }
I20260812 06:16:23.069475 30867 raft_consensus.cc:385] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:23.069499 30867 raft_consensus.cc:740] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cb1358931ed94f7aa3cbffffaeee922e, State: Initialized, Role: FOLLOWER
I20260812 06:16:23.069659 30867 consensus_queue.cc:260] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [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: "cb1358931ed94f7aa3cbffffaeee922e" member_type: VOTER last_known_addr { host: "127.29.246.193" port: 38211 } }
I20260812 06:16:23.069787 30867 raft_consensus.cc:399] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:23.069840 30867 raft_consensus.cc:493] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:23.069926 30867 raft_consensus.cc:3060] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:23.071131 30867 raft_consensus.cc:515] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cb1358931ed94f7aa3cbffffaeee922e" member_type: VOTER last_known_addr { host: "127.29.246.193" port: 38211 } }
I20260812 06:16:23.071303 30867 leader_election.cc:304] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [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: cb1358931ed94f7aa3cbffffaeee922e; no voters: 
I20260812 06:16:23.071584 30867 leader_election.cc:290] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:23.071695 30869 raft_consensus.cc:2804] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:23.071930 30869 raft_consensus.cc:697] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [term 1 LEADER]: Becoming Leader. State: Replica: cb1358931ed94f7aa3cbffffaeee922e, State: Running, Role: LEADER
I20260812 06:16:23.072077 30867 ts_tablet_manager.cc:1434] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.004s
I20260812 06:16:23.072122 30869 consensus_queue.cc:237] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [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: "cb1358931ed94f7aa3cbffffaeee922e" member_type: VOTER last_known_addr { host: "127.29.246.193" port: 38211 } }
I20260812 06:16:23.072537 30853 heartbeater.cc:499] Master 127.29.246.254:46015 was elected leader, sending a full tablet report...
I20260812 06:16:23.075766 30715 catalog_manager.cc:5719] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e reported cstate change: term changed from 0 to 1, leader changed from <none> to cb1358931ed94f7aa3cbffffaeee922e (127.29.246.193). New cstate: current_term: 1 leader_uuid: "cb1358931ed94f7aa3cbffffaeee922e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cb1358931ed94f7aa3cbffffaeee922e" member_type: VOTER last_known_addr { host: "127.29.246.193" port: 38211 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:23.236295 30683 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.147s	user 0.028s	sys 0.041s
I20260812 06:16:23.256512 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushMRSOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.187753
I20260812 06:16:23.380090 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushMRSOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.123s	user 0.089s	sys 0.024s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":255,"delete_count":0,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1150,"drs_written":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4,"lbm_write_time_us":24323,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":253,"peak_mem_usage":0,"reinsert_count":0,"rows_written":100,"thread_start_us":182,"threads_started":1,"update_count":1000}
I20260812 06:16:23.381425 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling UndoDeltaBlockGCOp(064620a0d6014eec822c2d2a8f943e90): 766 bytes on disk
I20260812 06:16:23.382056 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: UndoDeltaBlockGCOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:16:23.382490 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:23.398837 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.399355 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:23.542845 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.143s	user 0.119s	sys 0.024s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16405980,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":62,"lbm_read_time_us":7288,"lbm_reads_lt_1ms":364,"lbm_write_time_us":28731,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":343,"threads_started":5,"update_count":1500}
I20260812 06:16:23.543581 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=10.126437
I20260812 06:16:23.589445 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.046s	user 0.028s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18359,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:23.590049 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:23.602247 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4781,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.602857 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:23.760171 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.157s	user 0.099s	sys 0.055s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20508392,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":823,"lbm_read_time_us":11280,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30252,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2000}
I20260812 06:16:23.760758 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=10.126437
I20260812 06:16:23.805495 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.045s	user 0.010s	sys 0.028s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19619,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:23.806048 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:23.818106 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4400,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.818894 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:23.954739 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.135s	user 0.102s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20508393,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":182,"lbm_read_time_us":9706,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27631,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23808,"update_count":2000}
I20260812 06:16:23.955657 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=10.126437
I20260812 06:16:24.012241 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.056s	user 0.023s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":25656,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.012704 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:24.024312 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.025080 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:24.170545 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.145s	user 0.111s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20508392,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1432,"lbm_read_time_us":10071,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31378,"lbm_writes_lt_1ms":443,"mutex_wait_us":420,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2000}
I20260812 06:16:24.171164 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=10.126437
I20260812 06:16:24.219192 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.048s	user 0.027s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22419,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.219748 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:24.233839 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5092,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.234493 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:24.396278 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.162s	user 0.125s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20508392,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":474,"lbm_read_time_us":9561,"lbm_reads_lt_1ms":472,"lbm_write_time_us":42829,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:16:24.396858 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=11.118625
I20260812 06:16:24.456133 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.059s	user 0.025s	sys 0.028s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":24967,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:24.456676 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=3.181125
I20260812 06:16:24.473834 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":5046216,"delete_count":0,"lbm_write_time_us":6968,"lbm_writes_lt_1ms":126,"reinsert_count":0,"update_count":615}
I20260812 06:16:24.474448 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.196750
I20260812 06:16:24.488445 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":4799,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:16:24.489159 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:24.695086 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.206s	user 0.149s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24610896,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":219,"lbm_read_time_us":15996,"lbm_reads_lt_1ms":573,"lbm_write_time_us":45930,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:24.695955 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=14.095187
I20260812 06:16:24.765781 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.069s	user 0.039s	sys 0.027s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":31255,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:24.766325 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:24.799659 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.033s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5531,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.800230 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:24.811726 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4294,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.812296 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushMRSOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:24.847462 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushMRSOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":141,"dirs.run_cpu_time_us":298,"dirs.run_wall_time_us":1648,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1517,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:24.848268 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling LogGCOp(064620a0d6014eec822c2d2a8f943e90): free 128373247 bytes of WAL
I20260812 06:16:24.848563 30790 log_reader.cc:385] T 064620a0d6014eec822c2d2a8f943e90: removed 13 log segments from log reader
I20260812 06:16:24.848623 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000001 (ops 1-6)
I20260812 06:16:24.848691 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000002 (ops 7-10)
I20260812 06:16:24.848738 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000003 (ops 11-15)
I20260812 06:16:24.848758 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000004 (ops 16-20)
I20260812 06:16:24.848810 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000005 (ops 21-25)
I20260812 06:16:24.848850 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000006 (ops 26-30)
I20260812 06:16:24.848907 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000007 (ops 31-34)
I20260812 06:16:24.848946 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000008 (ops 35-39)
I20260812 06:16:24.848984 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000009 (ops 40-44)
I20260812 06:16:24.849022 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000010 (ops 45-48)
I20260812 06:16:24.849066 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000011 (ops 49-53)
I20260812 06:16:24.849108 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000012 (ops 54-58)
I20260812 06:16:24.849148 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000013 (ops 59-62)
I20260812 06:16:24.874835 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: LogGCOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:24.875319 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:24.891767 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4225734,"delete_count":0,"lbm_write_time_us":4197,"lbm_writes_lt_1ms":106,"mutex_wait_us":192,"reinsert_count":0,"update_count":515}
I20260812 06:16:24.892215 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling UndoDeltaBlockGCOp(064620a0d6014eec822c2d2a8f943e90): 471 bytes on disk
I20260812 06:16:24.892632 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: UndoDeltaBlockGCOp(064620a0d6014eec822c2d2a8f943e90) 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:16:24.893124 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:24.903961 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":3902,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:16:24.904487 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:25.152997 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.248s	user 0.178s	sys 0.068s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":36918393,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":209,"lbm_read_time_us":17773,"lbm_reads_lt_1ms":875,"lbm_write_time_us":44250,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":78,"threads_started":1,"update_count":4000}
I20260812 06:16:25.153625 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=15.087375
I20260812 06:16:25.204339 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.051s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":20199,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:25.204905 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:25.223670 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.019s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6453,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.224195 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:25.239812 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5628,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:25.240582 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:25.450045 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.209s	user 0.165s	sys 0.043s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28713323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1820,"lbm_read_time_us":12767,"lbm_reads_lt_1ms":673,"lbm_write_time_us":52913,"lbm_writes_lt_1ms":643,"mutex_wait_us":615,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":3000}
I20260812 06:16:25.450798 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=15.087375
I20260812 06:16:25.491103 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.040s	user 0.016s	sys 0.024s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":18175,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:25.491674 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:25.511286 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.019s	user 0.013s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6202,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:25.511969 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:25.683589 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.171s	user 0.110s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24610790,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":350,"lbm_read_time_us":10348,"lbm_reads_lt_1ms":564,"lbm_write_time_us":37973,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:16:25.684259 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=14.095187
I20260812 06:16:25.729849 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.045s	user 0.025s	sys 0.017s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":21022,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:25.730625 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:25.745112 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5358,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.745741 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:25.941110 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.195s	user 0.099s	sys 0.096s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24610800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":668,"lbm_read_time_us":10259,"lbm_reads_lt_1ms":572,"lbm_write_time_us":45075,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21376,"update_count":2500}
I20260812 06:16:25.942864 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=14.095187
I20260812 06:16:26.012590 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.069s	user 0.035s	sys 0.032s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":31140,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.013629 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:26.029404 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5763,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.029999 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:26.226884 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.197s	user 0.133s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24610806,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":11910,"lbm_reads_lt_1ms":564,"lbm_write_time_us":39780,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:16:26.227819 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=14.095187
I20260812 06:16:26.287189 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.059s	user 0.035s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22388,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.287892 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:26.299521 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.300009 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushMRSOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:26.335187 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushMRSOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.035s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1244,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1352,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:26.336043 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:26.521929 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.186s	user 0.117s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24610803,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1136,"lbm_read_time_us":12391,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32810,"lbm_writes_lt_1ms":543,"mutex_wait_us":351,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:16:26.522892 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling LogGCOp(064620a0d6014eec822c2d2a8f943e90): free 116849473 bytes of WAL
I20260812 06:16:26.523231 30790 log_reader.cc:385] T 064620a0d6014eec822c2d2a8f943e90: removed 12 log segments from log reader
I20260812 06:16:26.523320 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000014 (ops 63-67)
I20260812 06:16:26.523414 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000015 (ops 68-72)
I20260812 06:16:26.523479 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000016 (ops 73-76)
I20260812 06:16:26.523551 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000017 (ops 77-81)
I20260812 06:16:26.523595 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000018 (ops 82-86)
I20260812 06:16:26.523649 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000019 (ops 87-91)
I20260812 06:16:26.523689 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000020 (ops 92-96)
I20260812 06:16:26.523770 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000021 (ops 97-100)
I20260812 06:16:26.523808 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000022 (ops 101-105)
I20260812 06:16:26.523873 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000023 (ops 106-110)
I20260812 06:16:26.523911 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000024 (ops 111-114)
I20260812 06:16:26.523957 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000025 (ops 115-119)
I20260812 06:16:26.552667 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: LogGCOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:26.553193 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling UndoDeltaBlockGCOp(064620a0d6014eec822c2d2a8f943e90): 447 bytes on disk
I20260812 06:16:26.553872 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: UndoDeltaBlockGCOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:16:26.554530 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=15.087375
I20260812 06:16:26.617506 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.063s	user 0.043s	sys 0.012s Metrics: {"bytes_written":16820191,"delete_count":0,"lbm_write_time_us":22608,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:26.618213 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=3.181125
I20260812 06:16:26.637006 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.019s	user 0.007s	sys 0.009s Metrics: {"bytes_written":5415437,"delete_count":0,"lbm_write_time_us":7572,"lbm_writes_lt_1ms":135,"reinsert_count":0,"update_count":660}
I20260812 06:16:26.637560 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.196750
I20260812 06:16:26.650043 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":2379604,"delete_count":0,"lbm_write_time_us":3868,"lbm_writes_lt_1ms":61,"reinsert_count":0,"update_count":290}
I20260812 06:16:26.650756 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:26.866554 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.216s	user 0.162s	sys 0.053s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28713341,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":329,"lbm_read_time_us":15545,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38084,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20736,"update_count":3000}
I20260812 06:16:26.867228 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=14.095187
I20260812 06:16:26.919788 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.052s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23084,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.920377 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:26.936875 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6188,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.937376 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:27.094619 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.157s	user 0.082s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24610804,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":768,"lbm_read_time_us":10722,"lbm_reads_lt_1ms":568,"lbm_write_time_us":25393,"lbm_writes_lt_1ms":543,"mutex_wait_us":341,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:16:27.095167 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=14.095187
I20260812 06:16:27.157186 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.062s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21344,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:27.157835 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:27.168982 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4414,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.169466 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:27.362630 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.193s	user 0.134s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24610804,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":341,"lbm_read_time_us":12659,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33944,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:16:27.363459 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=11.118625
I20260812 06:16:27.406659 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.043s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21644,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:27.407397 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:27.423861 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5445,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:27.424453 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:27.605772 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.181s	user 0.125s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20508383,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":294,"lbm_read_time_us":9118,"lbm_reads_lt_1ms":464,"lbm_write_time_us":32071,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:16:27.606503 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=10.126437
I20260812 06:16:27.652483 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.046s	user 0.027s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":22753,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:27.653152 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:27.672525 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.019s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6020,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.673050 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:27.816867 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.144s	user 0.094s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20508390,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":222,"lbm_read_time_us":8050,"lbm_reads_lt_1ms":464,"lbm_write_time_us":33123,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:16:27.817557 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=14.095187
I20260812 06:16:27.875077 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.057s	user 0.019s	sys 0.035s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26678,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:27.875784 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:27.888537 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4363,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.889070 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushMRSOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:27.924664 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushMRSOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.035s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1193506,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1628,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1649,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:27.925447 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling LogGCOp(064620a0d6014eec822c2d2a8f943e90): free 112239518 bytes of WAL
I20260812 06:16:27.925712 30790 log_reader.cc:385] T 064620a0d6014eec822c2d2a8f943e90: removed 11 log segments from log reader
I20260812 06:16:27.925781 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000026 (ops 120-124)
I20260812 06:16:27.925844 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000027 (ops 125-129)
I20260812 06:16:27.925908 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000028 (ops 130-134)
I20260812 06:16:27.925956 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000029 (ops 135-139)
I20260812 06:16:27.926000 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000030 (ops 140-144)
I20260812 06:16:27.926046 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000031 (ops 145-149)
I20260812 06:16:27.926091 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000032 (ops 150-154)
I20260812 06:16:27.926136 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000033 (ops 155-159)
I20260812 06:16:27.926180 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000034 (ops 160-164)
I20260812 06:16:27.926224 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000035 (ops 165-168)
I20260812 06:16:27.926270 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000036 (ops 169-173)
I20260812 06:16:27.955018 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: LogGCOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.029s	user 0.002s	sys 0.026s Metrics: {}
I20260812 06:16:27.955530 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=3.181125
I20260812 06:16:27.974952 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.019s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7489,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:27.975484 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling LogGCOp(064620a0d6014eec822c2d2a8f943e90): free 12018006 bytes of WAL
I20260812 06:16:27.975735 30790 log_reader.cc:385] T 064620a0d6014eec822c2d2a8f943e90: removed 1 log segments from log reader
I20260812 06:16:27.975808 30790 log.cc:1079] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/064620a0d6014eec822c2d2a8f943e90/wal-000000037 (ops 174-178)
I20260812 06:16:27.978070 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: LogGCOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:27.978502 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling UndoDeltaBlockGCOp(064620a0d6014eec822c2d2a8f943e90): 463 bytes on disk
I20260812 06:16:27.978929 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: UndoDeltaBlockGCOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:27.979468 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:27.991353 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4000,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:27.991887 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:28.182116 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.190s	user 0.124s	sys 0.065s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32815853,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1100,"lbm_read_time_us":13879,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39808,"lbm_writes_lt_1ms":743,"mutex_wait_us":198,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:16:28.182986 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=14.095187
I20260812 06:16:28.237130 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.054s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23665,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:28.237872 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=2.188937
I20260812 06:16:28.252569 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5682,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.253108 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:28.409796 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.156s	user 0.127s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24610804,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":933,"lbm_read_time_us":9831,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29676,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2500}
I20260812 06:16:28.410621 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=12.110812
I20260812 06:16:28.449589 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.039s	user 0.027s	sys 0.009s Metrics: {"bytes_written":14399712,"delete_count":0,"lbm_write_time_us":16880,"lbm_writes_lt_1ms":354,"reinsert_count":0,"update_count":1755}
I20260812 06:16:28.450165 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:28.459540 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: FlushDeltaMemStoresOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2010377,"delete_count":0,"lbm_write_time_us":2771,"lbm_writes_lt_1ms":52,"reinsert_count":0,"update_count":245}
I20260812 06:16:28.460047 30854 maintenance_manager.cc:419] P cb1358931ed94f7aa3cbffffaeee922e: Scheduling MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90): perf score=1.000000
I20260812 06:16:28.526636 30683 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.290s	user 1.872s	sys 0.169s
I20260812 06:16:28.608798 30683 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.082s	user 0.001s	sys 0.000s
I20260812 06:16:28.609505 30683 tablet_server.cc:179] TabletServer@127.29.246.193:0 shutting down...
I20260812 06:16:28.617398 30790 maintenance_manager.cc:643] P cb1358931ed94f7aa3cbffffaeee922e: MajorDeltaCompactionOp(064620a0d6014eec822c2d2a8f943e90) complete. Timing: real 0.157s	user 0.112s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20508333,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":118,"lbm_read_time_us":9590,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28876,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29440,"update_count":2000}
I20260812 06:16:28.618211 30683 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:28.618695 30683 tablet_replica.cc:333] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e: stopping tablet replica
I20260812 06:16:28.618947 30683 raft_consensus.cc:2243] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:28.619195 30683 raft_consensus.cc:2272] T 064620a0d6014eec822c2d2a8f943e90 P cb1358931ed94f7aa3cbffffaeee922e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:28.637555 30683 tablet_server.cc:196] TabletServer@127.29.246.193:0 shutdown complete.
I20260812 06:16:28.655884 30683 master.cc:562] Master@127.29.246.254:46015 shutting down...
I20260812 06:16:28.660059 30683 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:28.660234 30683 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:28.660290 30683 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7466b902626f4c24b651a1b8b3d1c68c: stopping tablet replica
I20260812 06:16:28.672804 30683 master.cc:584] Master@127.29.246.254:46015 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5959 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:28.777295 30683 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.29.246.254:39007
I20260812 06:16:28.777837 30683 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:28.781076 30887 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:16:28.781178 30888 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:28.781304 30890 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:16:28.781697 30683 server_base.cc:1061] running on GCE node
I20260812 06:16:28.781934 30683 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:28.781983 30683 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:28.782021 30683 hybrid_clock.cc:648] HybridClock initialized: now 1786515388782020 us; error 0 us; skew 500 ppm
I20260812 06:16:28.783121 30683 webserver.cc:533] Webserver started at http://127.29.246.254:39631/ using document root <none> and password file <none>
I20260812 06:16:28.783304 30683 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:28.783372 30683 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:28.783458 30683 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:28.784003 30683 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/master-0-root/instance:
uuid: "e1c87cc188d047ff8af0f1d8bbd9a2ac"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-zpfg"
I20260812 06:16:28.785722 30683 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:28.786756 30898 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.787047 30683 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:28.787122 30683 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/master-0-root
uuid: "e1c87cc188d047ff8af0f1d8bbd9a2ac"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-zpfg"
I20260812 06:16:28.787225 30683 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:28.824581 30683 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:28.825124 30683 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:28.830317 30683 rpc_server.cc:307] RPC server started. Bound to: 127.29.246.254:39007
I20260812 06:16:28.835160 30954 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.246.254:39007 every 8 connection(s)
I20260812 06:16:28.835731 30955 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:28.837814 30955 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac: Bootstrap starting.
I20260812 06:16:28.838744 30955 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:28.839943 30955 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac: No bootstrap required, opened a new log
I20260812 06:16:28.840520 30955 raft_consensus.cc:359] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1c87cc188d047ff8af0f1d8bbd9a2ac" member_type: VOTER }
I20260812 06:16:28.840647 30955 raft_consensus.cc:385] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:28.840731 30955 raft_consensus.cc:740] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e1c87cc188d047ff8af0f1d8bbd9a2ac, State: Initialized, Role: FOLLOWER
I20260812 06:16:28.840957 30955 consensus_queue.cc:260] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [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: "e1c87cc188d047ff8af0f1d8bbd9a2ac" member_type: VOTER }
I20260812 06:16:28.841084 30955 raft_consensus.cc:399] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:28.841133 30955 raft_consensus.cc:493] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:28.841197 30955 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:28.842027 30955 raft_consensus.cc:515] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1c87cc188d047ff8af0f1d8bbd9a2ac" member_type: VOTER }
I20260812 06:16:28.842192 30955 leader_election.cc:304] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [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: e1c87cc188d047ff8af0f1d8bbd9a2ac; no voters: 
I20260812 06:16:28.842470 30955 leader_election.cc:290] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:28.842625 30958 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:28.842854 30958 raft_consensus.cc:697] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [term 1 LEADER]: Becoming Leader. State: Replica: e1c87cc188d047ff8af0f1d8bbd9a2ac, State: Running, Role: LEADER
I20260812 06:16:28.843008 30958 consensus_queue.cc:237] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [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: "e1c87cc188d047ff8af0f1d8bbd9a2ac" member_type: VOTER }
I20260812 06:16:28.843051 30955 sys_catalog.cc:565] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:28.843614 30959 sys_catalog.cc:455] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e1c87cc188d047ff8af0f1d8bbd9a2ac" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1c87cc188d047ff8af0f1d8bbd9a2ac" member_type: VOTER } }
I20260812 06:16:28.843640 30960 sys_catalog.cc:455] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [sys.catalog]: SysCatalogTable state changed. Reason: New leader e1c87cc188d047ff8af0f1d8bbd9a2ac. Latest consensus state: current_term: 1 leader_uuid: "e1c87cc188d047ff8af0f1d8bbd9a2ac" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1c87cc188d047ff8af0f1d8bbd9a2ac" member_type: VOTER } }
I20260812 06:16:28.843803 30959 sys_catalog.cc:458] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:28.843880 30960 sys_catalog.cc:458] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:28.844470 30965 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:28.845329 30965 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:28.845571 30683 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:28.847486 30965 catalog_manager.cc:1383] Generated new cluster ID: 423b19ba71c04a00a138005d32b3ae03
I20260812 06:16:28.847560 30965 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:28.874275 30965 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:28.874918 30965 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:28.887595 30965 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac: Generated new TSK 0
I20260812 06:16:28.887827 30965 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:28.910730 30683 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:28.913452 30977 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:28.913498 30683 server_base.cc:1061] running on GCE node
W20260812 06:16:28.913452 30979 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:28.913506 30976 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:28.913951 30683 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:28.914002 30683 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:28.914019 30683 hybrid_clock.cc:648] HybridClock initialized: now 1786515388914020 us; error 0 us; skew 500 ppm
I20260812 06:16:28.915011 30683 webserver.cc:533] Webserver started at http://127.29.246.193:34817/ using document root <none> and password file <none>
I20260812 06:16:28.915166 30683 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:28.915212 30683 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:28.915297 30683 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:28.915692 30683 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/instance:
uuid: "28d4a1299e654f17ab216f6f4e5ffcbc"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-zpfg"
I20260812 06:16:28.917382 30683 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:28.918448 30985 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.918730 30683 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:28.918808 30683 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root
uuid: "28d4a1299e654f17ab216f6f4e5ffcbc"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-zpfg"
I20260812 06:16:28.918876 30683 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:28.929769 30683 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:28.930168 30683 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:28.930514 30683 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:28.931021 30683 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:28.931084 30683 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.931144 30683 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:28.931177 30683 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.935824 30683 rpc_server.cc:307] RPC server started. Bound to: 127.29.246.193:43147
I20260812 06:16:28.935873 31054 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.246.193:43147 every 8 connection(s)
I20260812 06:16:28.946079 31055 heartbeater.cc:344] Connected to a master server at 127.29.246.254:39007
I20260812 06:16:28.946209 31055 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:28.946547 31055 heartbeater.cc:507] Master 127.29.246.254:39007 requested a full tablet report, sending...
I20260812 06:16:28.947413 30916 ts_manager.cc:194] Registered new tserver with Master: 28d4a1299e654f17ab216f6f4e5ffcbc (127.29.246.193:43147)
I20260812 06:16:28.947547 30683 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011261074s
I20260812 06:16:28.948347 30916 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40402
I20260812 06:16:28.955790 30916 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40412:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:28.965237 31015 tablet_service.cc:1511] Processing CreateTablet for tablet 550c3819f7944c5d9d8ef6545df14747 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b11f04cde1544657976c139c9e61c5ba]), partition=
I20260812 06:16:28.965535 31015 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 550c3819f7944c5d9d8ef6545df14747. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:28.967900 31067 tablet_bootstrap.cc:492] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Bootstrap starting.
I20260812 06:16:28.968861 31067 tablet_bootstrap.cc:654] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:28.970042 31067 tablet_bootstrap.cc:492] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: No bootstrap required, opened a new log
I20260812 06:16:28.970160 31067 ts_tablet_manager.cc:1403] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:28.970814 31067 raft_consensus.cc:359] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28d4a1299e654f17ab216f6f4e5ffcbc" member_type: VOTER last_known_addr { host: "127.29.246.193" port: 43147 } }
I20260812 06:16:28.970908 31067 raft_consensus.cc:385] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:28.970969 31067 raft_consensus.cc:740] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 28d4a1299e654f17ab216f6f4e5ffcbc, State: Initialized, Role: FOLLOWER
I20260812 06:16:28.971102 31067 consensus_queue.cc:260] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [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: "28d4a1299e654f17ab216f6f4e5ffcbc" member_type: VOTER last_known_addr { host: "127.29.246.193" port: 43147 } }
I20260812 06:16:28.971182 31067 raft_consensus.cc:399] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:28.971206 31067 raft_consensus.cc:493] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:28.971241 31067 raft_consensus.cc:3060] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:28.972092 31067 raft_consensus.cc:515] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28d4a1299e654f17ab216f6f4e5ffcbc" member_type: VOTER last_known_addr { host: "127.29.246.193" port: 43147 } }
I20260812 06:16:28.972230 31067 leader_election.cc:304] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [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: 28d4a1299e654f17ab216f6f4e5ffcbc; no voters: 
I20260812 06:16:28.972405 31067 leader_election.cc:290] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:28.972543 31069 raft_consensus.cc:2804] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:28.972739 31067 ts_tablet_manager.cc:1434] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:28.972774 31069 raft_consensus.cc:697] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [term 1 LEADER]: Becoming Leader. State: Replica: 28d4a1299e654f17ab216f6f4e5ffcbc, State: Running, Role: LEADER
I20260812 06:16:28.972783 31055 heartbeater.cc:499] Master 127.29.246.254:39007 was elected leader, sending a full tablet report...
I20260812 06:16:28.972990 31069 consensus_queue.cc:237] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [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: "28d4a1299e654f17ab216f6f4e5ffcbc" member_type: VOTER last_known_addr { host: "127.29.246.193" port: 43147 } }
I20260812 06:16:28.974515 30916 catalog_manager.cc:5719] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc reported cstate change: term changed from 0 to 1, leader changed from <none> to 28d4a1299e654f17ab216f6f4e5ffcbc (127.29.246.193). New cstate: current_term: 1 leader_uuid: "28d4a1299e654f17ab216f6f4e5ffcbc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28d4a1299e654f17ab216f6f4e5ffcbc" member_type: VOTER last_known_addr { host: "127.29.246.193" port: 43147 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:29.037438 30683 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.019s	sys 0.004s
I20260812 06:16:29.186956 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushMRSOp(550c3819f7944c5d9d8ef6545df14747): perf score=19.054940
I20260812 06:16:29.359076 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushMRSOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.172s	user 0.135s	sys 0.036s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1023,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41038,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:16:29.359835 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling LogGCOp(550c3819f7944c5d9d8ef6545df14747): free 20743880 bytes of WAL
I20260812 06:16:29.360090 30990 log_reader.cc:385] T 550c3819f7944c5d9d8ef6545df14747: removed 2 log segments from log reader
I20260812 06:16:29.360139 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000001 (ops 1-6)
I20260812 06:16:29.360172 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000002 (ops 7-11)
I20260812 06:16:29.364966 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: LogGCOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:29.365437 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling UndoDeltaBlockGCOp(550c3819f7944c5d9d8ef6545df14747): 16411392 bytes on disk
I20260812 06:16:29.365919 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: UndoDeltaBlockGCOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:16:29.366480 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:29.379472 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5111,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.379963 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:29.553838 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.174s	user 0.095s	sys 0.073s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1056,"lbm_read_time_us":11229,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27120,"lbm_writes_lt_1ms":443,"mutex_wait_us":332,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"thread_start_us":389,"threads_started":5,"update_count":2000}
I20260812 06:16:29.554587 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=11.118625
I20260812 06:16:29.595799 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.041s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17210,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:29.596463 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:29.617511 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.021s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4791,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:29.617946 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:29.628572 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3973,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.629081 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:29.793133 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.164s	user 0.134s	sys 0.024s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":339,"lbm_read_time_us":12039,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30286,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24192,"update_count":2500}
I20260812 06:16:29.793821 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=11.118625
I20260812 06:16:29.833420 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.039s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":17212,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:29.834107 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:29.851961 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.018s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5858,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:29.852445 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:29.973327 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.121s	user 0.088s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":696,"lbm_read_time_us":7464,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24166,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":105088,"update_count":2000}
I20260812 06:16:29.974466 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=10.126437
I20260812 06:16:30.009964 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.035s	user 0.009s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13941,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.010598 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:30.027395 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6290,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.028019 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:30.156594 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.128s	user 0.096s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":370,"lbm_read_time_us":8962,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24631,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:16:30.157212 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=10.126437
I20260812 06:16:30.208385 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.051s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16884,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.208915 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:30.220896 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4654,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.221396 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:30.382548 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.161s	user 0.110s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":899,"lbm_read_time_us":11763,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23458,"lbm_writes_lt_1ms":443,"mutex_wait_us":251,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:16:30.383201 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=10.126437
I20260812 06:16:30.421911 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.038s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15699,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.422459 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:30.433404 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.434234 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:30.563702 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.129s	user 0.104s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":808,"lbm_read_time_us":10313,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22831,"lbm_writes_lt_1ms":443,"mutex_wait_us":313,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:16:30.564267 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=10.126437
I20260812 06:16:30.604810 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.040s	user 0.032s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14489,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.605387 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:30.616753 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.617357 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushMRSOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:30.644752 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushMRSOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.027s	user 0.021s	sys 0.003s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1426,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1584,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:30.645452 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling LogGCOp(550c3819f7944c5d9d8ef6545df14747): free 112239257 bytes of WAL
I20260812 06:16:30.645720 30990 log_reader.cc:385] T 550c3819f7944c5d9d8ef6545df14747: removed 11 log segments from log reader
I20260812 06:16:30.645767 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000003 (ops 12-16)
I20260812 06:16:30.645849 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000004 (ops 17-21)
I20260812 06:16:30.645903 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000005 (ops 22-26)
I20260812 06:16:30.645946 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000006 (ops 27-31)
I20260812 06:16:30.645990 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000007 (ops 32-36)
I20260812 06:16:30.646051 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000008 (ops 37-41)
I20260812 06:16:30.646088 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000009 (ops 42-46)
I20260812 06:16:30.646131 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000010 (ops 47-50)
I20260812 06:16:30.646166 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000011 (ops 51-55)
I20260812 06:16:30.646202 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000012 (ops 56-60)
I20260812 06:16:30.646242 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000013 (ops 61-65)
I20260812 06:16:30.670977 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: LogGCOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.025s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:16:30.671406 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:30.693512 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.022s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5820,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.693974 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling LogGCOp(550c3819f7944c5d9d8ef6545df14747): free 12017983 bytes of WAL
I20260812 06:16:30.694187 30990 log_reader.cc:385] T 550c3819f7944c5d9d8ef6545df14747: removed 1 log segments from log reader
I20260812 06:16:30.694232 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000014 (ops 66-70)
I20260812 06:16:30.696743 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: LogGCOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:30.697089 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling UndoDeltaBlockGCOp(550c3819f7944c5d9d8ef6545df14747): 462 bytes on disk
I20260812 06:16:30.697507 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: UndoDeltaBlockGCOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:16:30.697955 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:30.709956 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4310,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.710984 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:30.885649 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.174s	user 0.126s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1542,"lbm_read_time_us":11760,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34790,"lbm_writes_lt_1ms":643,"mutex_wait_us":513,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:16:30.886368 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=14.095187
I20260812 06:16:30.939183 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.051s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22225,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.939823 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:30.958626 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6720,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.959096 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:31.139401 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.180s	user 0.138s	sys 0.034s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":453,"lbm_read_time_us":12211,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30472,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22656,"update_count":2500}
I20260812 06:16:31.140044 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=14.095187
I20260812 06:16:31.200923 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.061s	user 0.029s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26147,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.201417 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:31.371371 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.170s	user 0.104s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1041,"lbm_read_time_us":9551,"lbm_reads_lt_1ms":463,"lbm_write_time_us":28961,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:16:31.372056 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=14.095187
I20260812 06:16:31.431437 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.059s	user 0.030s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27766,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.431989 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:31.444619 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.012s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4490,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.445374 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:31.630771 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.185s	user 0.141s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":183,"lbm_read_time_us":12229,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27255,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2500}
I20260812 06:16:31.631531 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=14.095187
I20260812 06:16:31.684903 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.053s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":24120,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.685612 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:31.699159 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.013s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5440,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.699885 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:31.870443 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.170s	user 0.123s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":772,"lbm_read_time_us":11322,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30951,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:16:31.871348 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=11.118625
I20260812 06:16:31.909207 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.038s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15778,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:31.909916 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:31.926851 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6012,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:31.927407 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:32.063030 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.135s	user 0.095s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":557,"lbm_read_time_us":8140,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27149,"lbm_writes_lt_1ms":443,"mutex_wait_us":267,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:32.063889 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=11.118625
I20260812 06:16:32.098596 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.035s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14159,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1550}
I20260812 06:16:32.099349 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:32.112712 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4955,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:32.113317 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushMRSOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:32.147356 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushMRSOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.034s	user 0.030s	sys 0.002s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":138,"dirs.run_cpu_time_us":195,"dirs.run_wall_time_us":1516,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2052,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:32.148197 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling LogGCOp(550c3819f7944c5d9d8ef6545df14747): free 108988505 bytes of WAL
I20260812 06:16:32.148474 30990 log_reader.cc:385] T 550c3819f7944c5d9d8ef6545df14747: removed 11 log segments from log reader
I20260812 06:16:32.148547 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000015 (ops 71-75)
I20260812 06:16:32.148623 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000016 (ops 76-80)
I20260812 06:16:32.148700 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000017 (ops 81-85)
I20260812 06:16:32.148744 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000018 (ops 86-90)
I20260812 06:16:32.148783 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000019 (ops 91-95)
I20260812 06:16:32.148811 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000020 (ops 96-100)
I20260812 06:16:32.148847 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000021 (ops 101-105)
I20260812 06:16:32.148885 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000022 (ops 106-110)
I20260812 06:16:32.148921 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000023 (ops 111-114)
I20260812 06:16:32.148962 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000024 (ops 115-119)
I20260812 06:16:32.148998 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000025 (ops 120-124)
I20260812 06:16:32.173738 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: LogGCOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:32.174150 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling UndoDeltaBlockGCOp(550c3819f7944c5d9d8ef6545df14747): 473 bytes on disk
I20260812 06:16:32.174808 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: UndoDeltaBlockGCOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:16:32.175423 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=4.173312
I20260812 06:16:32.191753 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":6153870,"delete_count":0,"lbm_write_time_us":6803,"lbm_writes_lt_1ms":153,"reinsert_count":0,"update_count":750}
I20260812 06:16:32.192230 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling LogGCOp(550c3819f7944c5d9d8ef6545df14747): free 12017931 bytes of WAL
I20260812 06:16:32.192441 30990 log_reader.cc:385] T 550c3819f7944c5d9d8ef6545df14747: removed 1 log segments from log reader
I20260812 06:16:32.192487 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000026 (ops 125-129)
I20260812 06:16:32.194896 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: LogGCOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:32.195415 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:32.206323 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.011s	user 0.001s	sys 0.005s Metrics: {"bytes_written":2051402,"delete_count":0,"lbm_write_time_us":2697,"lbm_writes_lt_1ms":53,"reinsert_count":0,"update_count":250}
I20260812 06:16:32.206835 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:32.380300 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.173s	user 0.129s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877279,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":865,"lbm_read_time_us":12979,"lbm_reads_lt_1ms":670,"lbm_write_time_us":32452,"lbm_writes_lt_1ms":643,"mutex_wait_us":308,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":54144,"thread_start_us":92,"threads_started":1,"update_count":3000}
I20260812 06:16:32.381093 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=14.095187
I20260812 06:16:32.421626 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.040s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17887,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.422194 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:32.443874 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.021s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6450,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.444344 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:32.608984 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.164s	user 0.111s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1124,"lbm_read_time_us":9347,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32923,"lbm_writes_lt_1ms":543,"mutex_wait_us":306,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:16:32.609760 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=14.095187
I20260812 06:16:32.656631 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.047s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19733,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.657349 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:32.843765 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.186s	user 0.123s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":527,"lbm_read_time_us":12529,"lbm_reads_lt_1ms":463,"lbm_write_time_us":30866,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:16:32.844461 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=14.095187
I20260812 06:16:32.898617 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.054s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21808,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.899220 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:32.911116 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4195,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.911640 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:33.112119 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.200s	user 0.120s	sys 0.070s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":600,"lbm_read_time_us":11747,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31290,"lbm_writes_lt_1ms":543,"mutex_wait_us":275,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:16:33.112874 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=14.095187
I20260812 06:16:33.167826 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.055s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21733,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.168375 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:33.180382 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4358,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.181397 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:33.340273 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.159s	user 0.111s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":336,"lbm_read_time_us":10322,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30530,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:16:33.341063 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=14.095187
I20260812 06:16:33.395008 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.054s	user 0.023s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21695,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.395597 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:33.409379 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.409869 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:33.588670 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.178s	user 0.132s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":306,"lbm_read_time_us":11810,"lbm_reads_lt_1ms":564,"lbm_write_time_us":41869,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2500}
I20260812 06:16:33.589298 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=14.095187
I20260812 06:16:33.648995 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.060s	user 0.029s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":29816,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.649577 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:33.665283 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.666006 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushMRSOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:33.702080 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushMRSOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.036s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":111,"dirs.run_cpu_time_us":287,"dirs.run_wall_time_us":1634,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1682,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:33.703181 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling LogGCOp(550c3819f7944c5d9d8ef6545df14747): free 121006705 bytes of WAL
I20260812 06:16:33.703529 30990 log_reader.cc:385] T 550c3819f7944c5d9d8ef6545df14747: removed 12 log segments from log reader
I20260812 06:16:33.703608 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000027 (ops 130-134)
I20260812 06:16:33.703711 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000028 (ops 135-138)
I20260812 06:16:33.703760 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000029 (ops 139-143)
I20260812 06:16:33.703811 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000030 (ops 144-148)
I20260812 06:16:33.703859 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000031 (ops 149-153)
I20260812 06:16:33.703907 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000032 (ops 154-158)
I20260812 06:16:33.703953 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000033 (ops 159-163)
I20260812 06:16:33.704000 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000034 (ops 164-168)
I20260812 06:16:33.704047 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000035 (ops 169-173)
I20260812 06:16:33.704093 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000036 (ops 174-178)
I20260812 06:16:33.704170 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000037 (ops 179-183)
I20260812 06:16:33.704223 30990 log.cc:1079] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: Deleting log segment in path: /tmp/dist-test-taskMWkHyn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382792775-30683-0/minicluster-data/ts-0-root/wals/550c3819f7944c5d9d8ef6545df14747/wal-000000038 (ops 184-188)
I20260812 06:16:33.734390 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: LogGCOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.031s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:33.734990 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling UndoDeltaBlockGCOp(550c3819f7944c5d9d8ef6545df14747): 472 bytes on disk
I20260812 06:16:33.735562 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: UndoDeltaBlockGCOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:16:33.736219 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=5.165500
I20260812 06:16:33.754204 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.018s	user 0.004s	sys 0.012s Metrics: {"bytes_written":6892305,"delete_count":0,"lbm_write_time_us":7707,"lbm_writes_lt_1ms":171,"reinsert_count":0,"update_count":840}
I20260812 06:16:33.754968 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:33.761966 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1312952,"delete_count":0,"lbm_write_time_us":1653,"lbm_writes_lt_1ms":35,"reinsert_count":0,"update_count":160}
I20260812 06:16:33.762589 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747): perf score=1.000000
I20260812 06:16:33.984747 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: MajorDeltaCompactionOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.222s	user 0.151s	sys 0.070s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":330,"lbm_read_time_us":15121,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38143,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11776,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:16:33.985683 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=15.087375
I20260812 06:16:34.012858 30683 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.975s	user 1.813s	sys 0.174s
I20260812 06:16:34.049620 30683 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.036s	user 0.005s	sys 0.001s
I20260812 06:16:34.050226 30683 tablet_server.cc:179] TabletServer@127.29.246.193:0 shutting down...
I20260812 06:16:34.050633 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.065s	user 0.028s	sys 0.036s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":23315,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:34.051373 31056 maintenance_manager.cc:419] P 28d4a1299e654f17ab216f6f4e5ffcbc: Scheduling FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747): perf score=2.188937
I20260812 06:16:34.064433 30990 maintenance_manager.cc:643] P 28d4a1299e654f17ab216f6f4e5ffcbc: FlushDeltaMemStoresOp(550c3819f7944c5d9d8ef6545df14747) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4919,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:34.065063 30683 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:34.065320 30683 tablet_replica.cc:333] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc: stopping tablet replica
I20260812 06:16:34.065456 30683 raft_consensus.cc:2243] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.065639 30683 raft_consensus.cc:2272] T 550c3819f7944c5d9d8ef6545df14747 P 28d4a1299e654f17ab216f6f4e5ffcbc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.079535 30683 tablet_server.cc:196] TabletServer@127.29.246.193:0 shutdown complete.
I20260812 06:16:34.082818 30683 master.cc:562] Master@127.29.246.254:39007 shutting down...
I20260812 06:16:34.086829 30683 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.086995 30683 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.087045 30683 tablet_replica.cc:333] T 00000000000000000000000000000000 P e1c87cc188d047ff8af0f1d8bbd9a2ac: stopping tablet replica
I20260812 06:16:34.099684 30683 master.cc:584] Master@127.29.246.254:39007 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5427 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11388 ms total)

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